Description of problem: Multiple repos were scheduled to sync and in the time gap of few minutes. When scheduled sync starts for more than one repo, it throws an RepoError: 2011-05-16 12:32:06,631 [ERROR][Thread-72] failed() @ task.py:310 - Task id:06910602-7f81-11e0-9b07-525400da69d0, method_name:_sync: Traceback (most recent call last): File "/usr/lib/python2.6/site-packages/pulp/server/tasking/task.py", line 258, in run result = self.callable(*self.args, **self.kwargs) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo.py", line 1499, in _sync threads) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 146, in sync progress_callback, max_speed, threads) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 460, in sync report = self.yum_repo_grinder.fetchYumRepo(store_path, callback=progress_callback) File "/usr/lib/python2.6/site-packages/grinder/RepoFetch.py", line 366, in fetchYumRepo self.prepareRPMS() File "/usr/lib/python2.6/site-packages/grinder/RepoFetch.py", line 244, in prepareRPMS info['downloadurl'] = self.yumFetch.repourl + '/' + pkg.relativepath File "/usr/lib/python2.6/site-packages/yum/sqlitesack.py", line 268, in __getattr__ (self.pkgId,)).fetchone() File "/usr/lib/python2.6/site-packages/yum/sqlitesack.py", line 55, in newFunc raise Errors.RepoError, str(e) RepoError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 140370933417744 and this is thread id 140370964887312 Version-Release number of selected component (if applicable): pulp 0.171 rhui-tools 2.0.22 How reproducible: Observe this only in case of mutiple syncs. Steps to Reproduce: 1. 2. 3. Actual results: Got above traceback with following error: RepoError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 140370933417744 and this is thread id 140370964887312 Expected results: sync should be successfull for all repos. Additional info: Here is the scheduled sync status ( Output of "dr") -= Repository Synchronization Status =- Last Refreshed: 11:25:35 (updated every 50 seconds, ctrl+c to exit) Next Sync Last Sync Last Result ------------------------------------------------------------------------------ Red Hat Enterprise Linux Server 6 Releases (RPMs) (6Server-x86_64) 05-16-2011 12:24 05-13-2011 18:31 scheduled Red Hat Enterprise Linux Server 6 Updates (RPMs) (6Server-x86_64) 05-16-2011 12:26 05-13-2011 18:08 scheduled Red Hat Update Infrastructure 1.1 (RPMs) (5Server-i386) 05-16-2011 12:32 05-13-2011 19:06 scheduled Red Hat Update Infrastructure 1.1 (RPMs) (5Server-x86_64) 05-16-2011 12:32 05-13-2011 14:02 scheduled Red Hat Update Infrastructure 1.2 (RPMs) (5Server-i386) 05-16-2011 12:6 05-13-2011 18:36 scheduled Red Hat Update Infrastructure 1.2 (RPMs) (5Server-x86_64) 05-16-2011 12:6 05-13-2011 18:36 scheduled Logs when sync starts at 12:6 (Success ) ================================ 2011-05-16 12:06:00,395 [INFO][Thread-6] _sync() @ repo.py:1489 - Sync of rhui-1.2-5Server-x86_64 starting, skip_dict = {} 2011-05-16 12:06:00,397 [INFO][Thread-6] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:06:00,399 [INFO][Thread-7] _sync() @ repo.py:1489 - Sync of rhui-1.2-5Server-i386 starting, skip_dict = {} 2011-05-16 12:06:00,400 [INFO][Thread-7] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:06:22,304 [INFO][Thread-7] sync() @ repo_sync.py:463 - YumSynchronizer reported 13 successes, 0 downloads, 0 errors 2011-05-16 12:06:22,728 [INFO][Thread-6] sync() @ repo_sync.py:463 - YumSynchronizer reported 13 successes, 0 downloads, 0 errors 2011-05-16 12:06:23,772 [INFO][Thread-7] _process_repo_images() @ repo_sync.py:260 - No image files to import to repo.. 2011-05-16 12:06:23,774 [INFO][Thread-7] add_packages_from_dir() @ repo_sync.py:233 - Loaded group info from /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/i386/rhui/1.2/os/repodata/comps-rhel5-server-rhui.xml 2011-05-16 12:06:23,775 [INFO][Thread-6] _process_repo_images() @ repo_sync.py:260 - No image files to import to repo.. 2011-05-16 12:06:23,776 [INFO][Thread-6] add_packages_from_dir() @ repo_sync.py:233 - Loaded group info from /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/x86_64/rhui/1.2/os/repodata/comps-rhel5-server-rhui.xml 2011-05-16 12:06:23,777 [INFO][Thread-6] add_packages_from_dir() @ repo_sync.py:253 - Skipping errata imports from sync process 2011-05-16 12:06:23,777 [INFO][Thread-6] _sync() @ repo.py:1502 - Sync returned 13 packages, 0 errata in 23.3808839321 seconds 2011-05-16 12:06:23,777 [INFO][Thread-7] add_packages_from_dir() @ repo_sync.py:253 - Skipping errata imports from sync process 2011-05-16 12:06:23,779 [INFO][Thread-7] _sync() @ repo.py:1502 - Sync returned 13 packages, 0 errata in 23.3797521591 seconds 2011-05-16 12:06:23,794 [INFO][Thread-7] _sync() @ repo.py:1513 - 0 old packages to process, 0 new packages to process 2011-05-16 12:06:23,795 [INFO][Thread-6] _sync() @ repo.py:1513 - 0 old packages to process, 0 new packages to process 2011-05-16 12:06:23,802 [INFO][Thread-7] _sync() @ repo.py:1527 - Examining 0 errata from repo rhui-1.2-5Server-i386 2011-05-16 12:06:23,804 [INFO][Thread-6] _sync() @ repo.py:1527 - Examining 0 errata from repo rhui-1.2-5Server-x86_64 2011-05-16 12:06:23,807 [INFO][Thread-6] _sync() @ repo.py:1531 - Removing 0 old errata from repo rhui-1.2-5Server-x86_64 2011-05-16 12:06:23,805 [INFO][Thread-7] _sync() @ repo.py:1531 - Removing 0 old errata from repo rhui-1.2-5Server-i386 2011-05-16 12:06:23,817 [INFO][Thread-6] _sync() @ repo.py:1535 - Adding 0 new errata to repo rhui-1.2-5Server-x86_64 2011-05-16 12:06:23,818 [INFO][Thread-7] _sync() @ repo.py:1535 - Adding 0 new errata to repo rhui-1.2-5Server-i386 2011-05-16 12:06:23,823 [WARNING][Thread-6] schedule() @ task.py:192 - Task 06905ec7-7f81-11e0-9b02-525400da69d0: RepoApi._sync(rhui-1.2-5Server-x86_64, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7faac45d1ed0>) missed 1 scheduled runs 2011-05-16 12:06:23,823 [WARNING][Thread-7] schedule() @ task.py:192 - Task 0690ab8a-7f81-11e0-9b04-525400da69d0: RepoApi._sync(rhui-1.2-5Server-i386, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7faac45d1ed0>) missed 1 scheduled runs Logs when sync starts at 12:24, 12:26 and 12:32 (Traceback) ===================================================== 2011-05-16 12:24:00,623 [INFO][Thread-39] _sync() @ repo.py:1489 - Sync of rhel-server-6-releases-6Server-x86_64 starting, skip_dict = {} 2011-05-16 12:24:00,623 [INFO][Thread-39] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:26:00,932 [INFO][Thread-55] _sync() @ repo.py:1489 - Sync of rhel-server-6-updates-6Server-x86_64 starting, skip_dict = {} 2011-05-16 12:26:00,932 [INFO][Thread-55] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:30:48,804 [INFO][Thread-55] sync() @ repo_sync.py:463 - YumSynchronizer reported 3994 successes, 0 downloads, 0 errors 2011-05-16 12:31:03,776 [INFO][Thread-55] _process_repo_images() @ repo_sync.py:260 - No image files to import to repo.. 2011-05-16 12:31:04,012 [INFO][Thread-55] add_packages_from_dir() @ repo_sync.py:233 - Loaded group info from /var/lib/pulp//repos/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os/repodata/comps-rhel-x86_64-server-6.xml 2011-05-16 12:31:04,014 [INFO][Thread-55] add_packages_from_dir() @ repo_sync.py:248 - updateinfo is found in repomd.xml, it's path is /var/lib/pulp//repos/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os/repodata/713850e8a4ffefc82e6b6842cede0bc0c6bb04576ae0ff08b6ba4728edf9426f-updateinfo.xml.gz 2011-05-16 12:31:04,319 [INFO][Thread-55] _sync() @ repo.py:1502 - Sync returned 3994 packages, 143 errata in 303.386878967 seconds 2011-05-16 12:31:04,664 [INFO][Thread-55] _sync() @ repo.py:1513 - 0 old packages to process, 0 new packages to process 2011-05-16 12:31:05,356 [INFO][Thread-55] _sync() @ repo.py:1527 - Examining 143 errata from repo rhel-server-6-updates-6Server-x86_64 2011-05-16 12:31:05,563 [INFO][Thread-55] _sync() @ repo.py:1531 - Removing 0 old errata from repo rhel-server-6-updates-6Server-x86_64 2011-05-16 12:31:06,582 [INFO][Thread-55] generate_updateinfo() @ updateinfo.py:157 - updateinfo.xml generated and written to file /var/lib/pulp//repos/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os//updateinfo.xml 2011-05-16 12:31:08,484 [INFO][Thread-55] modify_repo() @ util.py:378 - modifyrepo with /var/lib/pulp//repos/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os//updateinfo.xml on /var/lib/pulp//repos/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os/repodata finished 2011-05-16 12:31:08,690 [INFO][Thread-55] _sync() @ repo.py:1535 - Adding 0 new errata to repo rhel-server-6-updates-6Server-x86_64 2011-05-16 12:31:08,967 [WARNING][Thread-55] schedule() @ task.py:192 - Task 06aea838-7f81-11e0-9bc9-525400da69d0: RepoApi._sync(rhel-server-6-updates-6Server-x86_64, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7faac45d1ed0>) missed 1 scheduled runs 2011-05-16 12:32:00,540 [INFO][Thread-71] _sync() @ repo.py:1489 - Sync of rhui-1.1-5Server-i386 starting, skip_dict = {} 2011-05-16 12:32:00,540 [INFO][Thread-71] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:32:00,549 [INFO][Thread-72] _sync() @ repo.py:1489 - Sync of rhui-1.1-5Server-x86_64 starting, skip_dict = {} 2011-05-16 12:32:00,550 [INFO][Thread-72] sync() @ repo_sync.py:447 - Limiting download speed to 0 KB/sec per thread. [15] threads will be used 2011-05-16 12:32:06,631 [ERROR][Thread-72] failed() @ task.py:310 - Task id:06910602-7f81-11e0-9b07-525400da69d0, method_name:_sync: Traceback (most recent call last): File "/usr/lib/python2.6/site-packages/pulp/server/tasking/task.py", line 258, in run result = self.callable(*self.args, **self.kwargs) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo.py", line 1499, in _sync threads) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 146, in sync progress_callback, max_speed, threads) File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 460, in sync report = self.yum_repo_grinder.fetchYumRepo(store_path, callback=progress_callback) File "/usr/lib/python2.6/site-packages/grinder/RepoFetch.py", line 366, in fetchYumRepo self.prepareRPMS() File "/usr/lib/python2.6/site-packages/grinder/RepoFetch.py", line 244, in prepareRPMS info['downloadurl'] = self.yumFetch.repourl + '/' + pkg.relativepath File "/usr/lib/python2.6/site-packages/yum/sqlitesack.py", line 268, in __getattr__ (self.pkgId,)).fetchone() File "/usr/lib/python2.6/site-packages/yum/sqlitesack.py", line 55, in newFunc raise Errors.RepoError, str(e) RepoError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 140370933417744 and this is thread id 140370964887312 2011-05-16 12:32:06,631 [WARNING][Thread-72] schedule() @ task.py:192 - Task 06910602-7f81-11e0-9b07-525400da69d0: RepoApi._sync(rhui-1.1-5Server-x86_64, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7faac45d1ed0>) missed 1 scheduled runs 2011-05-16 12:32:17,287 [INFO][Thread-71] sync() @ repo_sync.py:463 - YumSynchronizer reported 10 successes, 0 downloads, 0 errors 2011-05-16 12:32:18,027 [INFO][Thread-71] _process_repo_images() @ repo_sync.py:260 - No image files to import to repo.. 2011-05-16 12:32:18,029 [INFO][Thread-71] add_packages_from_dir() @ repo_sync.py:233 - Loaded group info from /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/i386/rhui/1.1/os/repodata/comps-rhel5-server-rhui.xml 2011-05-16 12:32:18,029 [INFO][Thread-71] add_packages_from_dir() @ repo_sync.py:253 - Skipping errata imports from sync process 2011-05-16 12:32:18,030 [INFO][Thread-71] _sync() @ repo.py:1502 - Sync returned 10 packages, 0 errata in 17.4895288944 seconds 2011-05-16 12:32:18,049 [INFO][Thread-71] _sync() @ repo.py:1513 - 6 old packages to process, 6 new packages to process 2011-05-16 12:32:18,063 [INFO][Thread-71] create_repo() @ util.py:357 - Checking what metadata types are available: ['filelists', 'other', 'group', 'primary', 'group_gz'] 2011-05-16 12:32:18,620 [INFO][Thread-71] create_repo() @ util.py:369 - [createrepo --checksum sha256 -g /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/i386/rhui/1.1/os/repodata/comps-rhel5-server-rhui.xml --update /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/i386/rhui/1.1/os] on /var/lib/pulp//repos/content/dist/rhel/rhui/server/5Server/i386/rhui/1.1/os finished
After aboce traceback, when I tried to check the sync state using rhui-manager, got unexpected error with following error in rhui.log ------------------------------------------------------------------------------ ^Crhui (sync) => dr ------------------------------------------------------------------------------ -= Red Hat Update Infrastructure Management Tool =- -= Repository Synchronization Status =- Last Refreshed: 12:37:02 (updated every 50 seconds, ctrl+c to exit) Next Sync Last Sync Last Result ------------------------------------------------------------------------------ Red Hat Enterprise Linux Server 6 Releases (RPMs) (6Server-x86_64) 05-16-2011 12:24 05-13-2011 18:31 running Red Hat Enterprise Linux Server 6 Updates (RPMs) (6Server-x86_64) 05-16-2011 13:26 05-16-2011 07:01 finished Red Hat Update Infrastructure 1.1 (RPMs) (5Server-i386) An unexpected error has occurred during the last operation. More information can be found in /root/.rhui/rhui.log. [root@dhcp193-136 rhui]# tail -f /root/.rhui/rhui.log Shell.listen(self) File "/usr/lib/python2.6/site-packages/rhui/common/shell.py", line 191, in listen item.func(*args, **item.kwargs) File "/usr/lib/python2.6/site-packages/rhui/tools/screens/sync.py", line 63, in repo_display self._sync_display('-= Repository Synchronization Status =-', self.pulp.repos_with_sync_status, False) File "/usr/lib/python2.6/site-packages/rhui/tools/screens/sync.py", line 241, in _sync_display self.prompt.write(SYNC_STATUS_LINE % (next_sync, render.format_date(data['last_sync']), self._color_sync_state(data))) File "/usr/lib/python2.6/site-packages/rhui/tools/screens/sync.py", line 259, in _color_sync_state return self.prompt.color(data['sync_state'], STATE_COLORS[data['sync_state']]) KeyError: None
added to rhui-20 tracker
Refiled upstream as 713775
Saichin are you able to reproduce the error in comment 0? We added a class level lock in grinder which serializes the yum metadata fetch calls a month or two ago, I am wondering if you saw the error in comment #0 prior to our change. I've done multiple syncs in pulp and I haven't been able to duplicate this.
This issue is not reproducible with new build pulp 0.208 and rhui-tools 2.0.38. I tried to sync multiple repos but its not reproducible. ------------------------------------------------------------------------------ -= Red Hat Update Infrastructure Management Tool =- -= Repository Synchronization Status =- Last Refreshed: 18:34:34 (updated every 5 seconds, ctrl+c to exit) Next Sync Last Sync Last Result ------------------------------------------------------------------------------ Red Hat Enterprise Linux Server 6 Optional Updates (RPMs) (6Server-x86_64) 07-15-2011 20:02 07-15-2011 18:30 Success Red Hat Enterprise Linux Server 6 Updates (RPMs) (6Server-x86_64) 07-15-2011 20:02 07-15-2011 18:30 Success Red Hat Update Infrastructure 1.1 (RPMs) (5Server-i386) 07-15-2011 20:06 07-15-2011 18:24 Success Red Hat Update Infrastructure 1.1 (RPMs) (5Server-x86_64) 07-15-2011 20:06 07-15-2011 18:24 Success Red Hat Update Infrastructure 1.2 (RPMs) (5Server-i386) 07-15-2011 20:06 07-15-2011 18:33 Success Red Hat Update Infrastructure 1.2 (RPMs) (5Server-x86_64) 07-15-2011 20:06 07-15-2011 18:33 Success Connected: dhcp201-141.englab.pnq.redhat.com ------------------------------------------------------------------------------ ^Crhui (sync) => From the above sync status, seems that it is fixed in new builds.
Looks like Sachin is already QE-ing this, so changing the status.
This has already been fixed in pulp 0.208 as per comment 5. However to ensure I verified this in pulp 0.211. This issue is no longer reproducible. -= Repository Synchronization Status =- Last Refreshed: 10:24:28 (updated every 5 seconds, ctrl+c to exit) Next Sync Last Sync Last Result ------------------------------------------------------------------------------ Red Hat Enterprise Linux Server (RPMs) (5Server-x86_64) 07-27-2011 12:35 07-27-2011 09:25 Success Red Hat Enterprise Linux Server 6 Optional Updates (RPMs) (6Server-x86_64) 07-27-2011 12:12 07-27-2011 06:43 Success Red Hat Enterprise Linux Server 6 Releases (RPMs) (6Server-x86_64) 07-27-2011 12:12 07-27-2011 09:19 Success Red Hat Enterprise Linux Server 6 Updates (RPMs) (6Server-x86_64) 07-27-2011 12:13 07-27-2011 06:44 Success Red Hat Update Infrastructure 1.2 (RPMs) (5Server-i386) 07-27-2011 10:48 07-27-2011 04:48 Success Red Hat Update Infrastructure 1.2 (RPMs) (5Server-x86_64) 07-27-2011 10:48 07-27-2011 04:48 Success Connected: dhcp201-127.englab.pnq.redhat.com ------------------------------------------------------------------------------ ^Crhui (sync) => ^ Moving this to verified.
moving to release pending
closing out, product released