Bug 704960

Summary: RepoError: while running multiple repo sync for different repo's
Product: Red Hat Update Infrastructure for Cloud Providers Reporter: Sachin Ghai <sghai>
Component: UpstreamAssignee: Jay Dobies <jason.dobies>
Status: CLOSED CURRENTRELEASE QA Contact: wes hayutin <whayutin>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 2.0CC: jmatthew, tsanders
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-05-31 12:57:50 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 711223    

Description Sachin Ghai 2011-05-16 07:33:29 UTC 
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
Comment 1 Sachin Ghai 2011-05-16 07:39:46 UTC 
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
Comment 2 wes hayutin 2011-06-06 21:15:37 UTC 
added to rhui-20 tracker
Comment 3 Jay Dobies 2011-06-16 14:29:46 UTC 
Refiled upstream as 713775
Comment 4 John Matthews 2011-07-14 19:13:34 UTC 
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.
Comment 5 Sachin Ghai 2011-07-15 13:18:38 UTC 
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.
Comment 6 Jay Dobies 2011-07-26 16:03:30 UTC 
Looks like Sachin is already QE-ing this, so changing the status.
Comment 7 Sachin Ghai 2011-07-27 05:34:37 UTC 
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.
Comment 8 wes hayutin 2011-08-01 21:40:50 UTC 
moving to release pending
Comment 9 wes hayutin 2012-05-31 12:57:50 UTC 
closing out, product released