Bug 707468

Summary: ValueError: while checking sync status after rhui upgrade
Product: Red Hat Update Infrastructure for Cloud Providers Reporter: Sachin Ghai <sghai>
Component: ToolsAssignee: Jason Connor <jconnor>
Status: CLOSED CURRENTRELEASE QA Contact: wes hayutin <whayutin>
Severity: high Docs Contact:
Priority: unspecified    
Version: 2.0CC: mmccune, 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:54:47 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-25 07:44:41 UTC
Description of problem:
Upgraded the RHUI setup from follwing builds:

RHUI tools: 2.0.22 to 2.0.25
Pulp: 0.171 to 0.179

After upgrading the rhui build and pulp rpms. I executed following two commands:
service pulp-server init ( took some time to complete)
service pulp-server restart

Then check the repos by:

pulp-admin -u admin -p admin repo list 

The ouput of repo list was perfect; but got some errors in pulp.log related to repo_sync_task

pulp.log:
============
2011-05-25 12:50:33,496 [WARNING][Dummy-2] schedule() @ task.py:270 - Task 7a8ad40a-869f-11e0-bbd7-525400da69d0: RepoApi._sync(rhui-1.1-5Server-x86_64, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7f1aa50d6590>) missed 289 scheduled runs
2011-05-25 12:50:33,498 [WARNING][Dummy-2] __init__() @ scheduler.py:124 - IntervalScheduler created with start time more than one interval in the past: 2011-05-13 12:32:00+05:30, 1:00:00
2011-05-25 12:50:33,498 [ERROR][Dummy-2] set_synchronizer() @ repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task


Finally I checked the sync status with "dr" and got unexpected error on stdout and following error in rhui.log:

rhui.log:
=========

ValueError: need more than 1 value to unpack


Version-Release number of selected component (if applicable):
Upgrade from:

RHUI tools: 2.0.22 to 2.0.25
Pulp: 0.171 to 0.179

How reproducible:
I'm hitting with same error even after restarting the "pulp-server" service.

Steps to Reproduce:
1. Upgrade the rhui-tools on rhui-manager with all pulp rpms
2. upgrade rhua server with all pulp rpms
3. service pulp-server init
4. service pulp-server restart
  
Actual results:
See the complete logs in the "Additional info" section.

Expected results:
Should not be any error in pulp.log and sync status should be dispalyed with out any error

Additional info:

[root@dhcp193-157 ~]# service pulp-server init
database migration to version 14 complete


Complete logs:
[root@dhcp193-157 ~]# service pulp-server restart
Stopping httpd:                                            [  OK  ]
Stopping Qpid AMQP daemon:                                 [  OK  ]
Stopping mongod:                                           [  OK  ]
Starting mongod:                                           [  OK  ]
Starting Qpid AMQP daemon:                                 [  OK  ]
Starting httpd:                                            [  OK  ]
[root@dhcp193-157 ~]# 

[root@dhcp193-157 ~]# pulp-admin -u admin -p admin repo list
+------------------------------------------+
       List of Available Repositories
+------------------------------------------+

Id                 	rhui-1.2-5Server-x86_64  
Name               	Red Hat Update Infrastructure 1.2 (RPMs) (5Server-x86_64)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server/5Server/x86_64/rhui/1.2/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-05T06:06:00/PT6H 
Packages           	13                       
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       


Id                 	rhui-1.2-5Server-i386    
Name               	Red Hat Update Infrastructure 1.2 (RPMs) (5Server-i386)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server/5Server/i386/rhui/1.2/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-05T06:06:00/PT6H 
Packages           	13                       
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       


Id                 	repo157                  
Name               	repo157                  
Feed URL           	None                     
Feed Type          	None                     
Feed Certs         	CA:No   Cert:No   Key:No
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	None                     
Packages           	112                      
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'custom']              
Filters            	[]                       
Notes              	{u'entitlement-path': u'/protected/157/$basearch'}


Id                 	rhui-1.1-5Server-x86_64  
Name               	Red Hat Update Infrastructure 1.1 (RPMs) (5Server-x86_64)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server/5Server/x86_64/rhui/1.1/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-13T12:32:00/PT1H 
Packages           	10                       
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       


Id                 	rhui-1.1-5Server-i386    
Name               	Red Hat Update Infrastructure 1.1 (RPMs) (5Server-i386)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server/5Server/i386/rhui/1.1/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-13T12:32:00/PT1H 
Packages           	10                       
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       


Id                 	rhel-server-6-updates-6Server-x86_64
Name               	Red Hat Enterprise Linux Server 6 Updates (RPMs) (6Server-x86_64)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server-6/updates/6Server/x86_64/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-13T12:26:00/PT1H 
Packages           	4964                     
Files              	0                        
Distributions      	None                     
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       


Id                 	rhel-server-6-releases-6Server-x86_64
Name               	Red Hat Enterprise Linux Server 6 Releases (RPMs) (6Server-x86_64)
Feed URL           	https://cdn.redhat.com/content/dist/rhel/rhui/server-6/releases/6Server/x86_64/os
Feed Type          	remote                   
Feed Certs         	CA:Yes   Cert:Yes   Key:Yes
Consumer Certs     	CA:Yes   Cert:Yes   Key:Yes
Architecture       	noarch                   
Sync Schedule      	2011-05-13T12:24:00/PT1H 
Packages           	3391                     
Files              	0                        
Distributions      	ks-rhel-server-6-releases-6Server-x86_64-noarch
Publish            	True                     
Clones             	[]                       
Groups             	[u'redhat']              
Filters            	[]                       
Notes              	{}                       



[root@dhcp193-157 ~]#tail -f /var/log/pulp/pulp.log
===============================
2011-05-25 12:50:33,490 [WARNING][Dummy-2] __init__() @ scheduler.py:124 - IntervalScheduler created with start time more than one interval in the past: 2011-05-05 06:06:00+05:30, 6:00:00
2011-05-25 12:50:33,490 [ERROR][Dummy-2] set_synchronizer() @ repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task
2011-05-25 12:50:33,490 [WARNING][Dummy-2] schedule() @ task.py:270 - Task 7a87fc75-869f-11e0-bbc4-525400da69d0: RepoApi._sync(rhui-1.2-5Server-x86_64, synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at 0x7f1aa50d6250>) missed 82 scheduled runs
2011-05-25 12:50:33,492 [WARNING][Dummy-2] __init__() @ scheduler.py:124 - IntervalScheduler created with start time more than one interval in the past: 2011-05-05 06:06:00+05:30, 6:00:00
2011-05-25 12:50:33,492 [ERROR][Dummy-2] set_synchronizer() @ repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task

[root@dhcp193-136 ~]# tail -f /root/.rhui/rhui.log 
============================
    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/render.py", line 157, in format_date
    datetime_obj = dateutils.parse_iso8601_datetime(date_str)
  File "/usr/lib/python2.6/site-packages/pulp/common/dateutils.py", line 126, in parse_iso8601_datetime
    return isodate.parse_datetime(datetime_str)
  File "/usr/lib/python2.6/site-packages/isodate/isodatetime.py", line 48, in parse_datetime
    datestring, timestring = datetimestring.split('T')
ValueError: need more than 1 value to unpack

Comment 1 Jay Dobies 2011-05-25 12:53:39 UTC
Jason - Can you provide any input? Take a look at the last traceback, it's bombing trying to format last_sync.

Here's the body of the RHUI format_date method. It's checking for None, so it's not the case that last_sync isn't set.


def format_date(date_str):
    if date_str is None:
        return 'Never'
    else:
        datetime_obj = dateutils.parse_iso8601_datetime(date_str)
        return datetime_obj.strftime('%m-%d-%Y %H:%M')

Comment 2 Sachin Ghai 2011-05-26 15:19:49 UTC
Getting following logs very frequently;  Its reproducible with following steps:

1. Restart the pulp-server (service pulp-server restart)
2. then login using rhui-manager, once you login with rhui-manager; check the
pulp.logs.

2011-05-26 20:06:38,466 [WARNING][Dummy-2] __init__() @ scheduler.py:124 -
IntervalScheduler created with start time more than one interval in the past:
2011-05-26 15:49:28+05:30, 1:00:00
2011-05-26 20:06:38,503 [ERROR][Dummy-2] set_synchronizer() @
repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task
2011-05-26 20:06:38,504 [WARNING][Dummy-2] schedule() @ task.py:289 - Task
907e36c5-87a5-11e0-96c1-525400ff61a5:
RepoApi._sync(rhel-server-6-updates-6Server-x86_64,
synchronizer=<pulp.server.api.repo_sync.YumSynchronizer object at
0x7f16c85ecd90>) missed 5 scheduled runs
2011-05-26 20:06:38,506 [WARNING][Dummy-2] __init__() @ scheduler.py:124 -
IntervalScheduler created with start time more than one interval in the past:
2011-05-26 18:46:24+05:30, 1:00:00
2011-05-26 20:06:38,506 [ERROR][Dummy-2] set_synchronizer() @
repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task

Comment 3 wes hayutin 2011-06-06 21:15:47 UTC
added to rhui-20 tracker

Comment 4 Jay Dobies 2011-06-22 14:05:16 UTC
Bulk moving a bunch of sync related bugs to ON_QA to test with version 2.0.32.

Comment 5 Sachin Ghai 2011-06-24 06:29:46 UTC
The following "ValueError" is not reproducble with new build ( pulp 0.197 and rh-rhui-tools 2.0.33).

I checked sync status couple of times are verifed the pulp.log. None of these errors are reproducible.

>>ValueError: need more than 1 value to unpack

>>2011-05-26 20:06:38,506 [ERROR][Dummy-2] set_synchronizer() @
repo_sync_task.py:32 - __name__ = pulp.server.api.repo_sync_task

So moving this verified state.

Comment 6 wes hayutin 2011-08-01 21:39:42 UTC
moving to release pending

Comment 7 wes hayutin 2012-05-31 12:54:47 UTC
closing out, product released