Bug 804188

Resulting traceback:

    [Fri Mar 16 14:35:35 2012] [notice] Apache/2.2.15 (Unix) DAV/2 mod_ssl/2.2.15 OpenSSL/1.0.0-fips mod_wsgi/3.3 Python/2.6.6 mod_perl/2.0.4 Perl/v5.10.1 configured -- resuming normal operations
    [Fri Mar 16 14:35:36 2012] [error] mod_wsgi (pid=3804): Target WSGI script '/srv/pulp/webservices.wsgi' cannot be loaded as Python module.
    [Fri Mar 16 14:35:36 2012] [error] mod_wsgi (pid=3804): Exception occurred processing WSGI script '/srv/pulp/webservices.wsgi'.
    [Fri Mar 16 14:35:36 2012] [error] Traceback (most recent call last):
    [Fri Mar 16 14:35:36 2012] [error]   File "/srv/pulp/webservices.wsgi", line 19, in <module>
    [Fri Mar 16 14:35:36 2012] [error]     application = wsgi_application()
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 247, in wsgi_application
    [Fri Mar 16 14:35:36 2012] [error]     _initialize_pulp()
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 221, in _initialize_pulp
    [Fri Mar 16 14:35:36 2012] [error]     async.initialize()
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/async.py", line 179, in initialize
    [Fri Mar 16 14:35:36 2012] [error]     _load_persisted_tasks()
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/async.py", line 150, in _load_persisted_tasks
    [Fri Mar 16 14:35:36 2012] [error]     task = TaskSnapshot(snapshot).to_task()
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/db/model/persistence.py", line 64, in to_task
    [Fri Mar 16 14:35:36 2012] [error]     return cls.from_snapshot(self)
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync_task.py", line 77, in from_snapshot
    [Fri Mar 16 14:35:36 2012] [error]     task = super(RepoSyncTask, cls).from_snapshot(snapshot)
    [Fri Mar 16 14:35:36 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/tasking/task.py", line 335, in from_snapshot
    [Fri Mar 16 14:35:36 2012] [error]     setattr(task, field, pickle.loads(snapshot[field]))
    [Fri Mar 16 14:35:36 2012] [error] KeyError: 'timeout_delta'

There is a workaround for this:

Make sure mongod is started:
$ service mongod start

Log into the mongo shell:
$ mongo pulp_database

Drop task snapshots:
> db.task_snapshots.drop()
> exit

Restart pulp-server:
$ service pulp-server restart

Any tasks there were running before the update will start again on their next scheduled time.

snapshot fields are not controlled by a db model, so they are note really "migratable". I've add a call in the migrate script to drop the persisted tasks as part of the standard workflow to avoid these problems in the future.

fix pushed in:
82a4def58ab08dd57677c566df385b9d252b6fe9

QA:
Attempt an update to 2.0.3 while a repo sync is running and in progress.  After you complete the step where you restart the pulp-server service, you should not see this traceback

Tested: the error reported in Comment 2 isn't present any more as far as the upgrade from 2.0.1 to 2.0.3, while repository sync in progress, is concerned. However, other error entries can be seen in '/var/log/httpd/error_log'. Even though this IMHO could be OK (due to a service restart during the repository synchronisation), Dev info is required to confirm.

Version: RHEL-6.2-RHUI-2.0.3-20120322.0-Server-x86_64-DVD1.iso

### Screen log (error details: /var/log/httpd/error_log)
[Tue Mar 27 11:33:58 2012] [error] /usr/lib/python2.6/site-packages/oauth2/__init__.py:29: DeprecationWarning: the sha module is deprecated; use the hashlib module instead
[Tue Mar 27 11:33:58 2012] [error]   import sha
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:49 2012] [error] Exception KeyError: KeyError(139955329161184,) in <module 'threading' from '/usr/lib64/python2.6/threading.pyc'> ignored
[Tue Mar 27 12:47:50 2012] [notice] caught SIGTERM, shutting down
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()
IOError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()
IOError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()
IOError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()
IOError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()
IOError: [Errno 32] Broken pipe
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 490, in <module>
    main()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 487, in main
    process()
  File "/usr/lib/python2.6/site-packages/grinder/activeobject.py", line 436, in process
    sys.stdout.flush()

Created attachment 573023 [details]
deployment and upgrade screen logs

Screen logs from the deployment and upgrade process

the errors from comment 5 are fine, it's just grinder being noisy on shutdown.

The logs being fine (Comment 6) moving to verified status...

Answered in Comment 5

    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
C: One of the pickle fields for tasks was changed from timeout to timeout_delta.  
C: If an update was attempted while a repository synchronisation was in progress, a traceback was recorded.
F: A call was added to drop persistent tasks during the update.
R: The update completed successfully without displaying a traceback, and non-critical errors are recorded in the /var/log/httpd/error_log logfile.

    Technical note updated. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    Diffed Contents:
@@ -1,4 +1,7 @@
 C: One of the pickle fields for tasks was changed from timeout to timeout_delta.  
 C: If an update was attempted while a repository synchronisation was in progress, a traceback was recorded.
 F: A call was added to drop persistent tasks during the update.
-R: The update completed successfully without displaying a traceback, and non-critical errors are recorded in the /var/log/httpd/error_log logfile.+R: The update completed successfully without displaying a traceback, and non-critical errors are recorded in the /var/log/httpd/error_log logfile.
+
+Final:
+* The 'timeout' field for tasks was changed to 'timeout_delta', which meant that if an update was attempted while a repository synchronisation was in progress, a traceback was recorded. A call was added to drop persistent tasks during the update, and updates now complete successfully without displaying a traceback. Some non-critical errors are recorded in the /var/log/httpd/error_log logfile. (BZ#804188)

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2012-0539.html