[Spacewalk-list] Client updates failing
Dimitri Yioulos
dyioulos at netatlantic.com
Thu Feb 18 20:19:17 UTC 2016
-----Original Message-----
From: Jan Hutař [mailto:jhutar at redhat.com]
Sent: Thursday, February 18, 2016 3:04 PM
To: Dimitri Yioulos <dyioulos at netatlantic.com>
Cc: spacewalk-list at redhat.com
Subject: Re: [Spacewalk-list] Client updates failing
On 2016-02-18 13:38 +0000, Dimitri Yioulos wrote:
>-----Original Message-----
>From: Jan Hutař [mailto:jhutar at redhat.com]
>Sent: Thursday, February 18, 2016 12:00 AM
>To: Dimitri Yioulos <dyioulos at netatlantic.com>
>Cc: spacewalk-list at redhat.com
>Subject: Re: [Spacewalk-list] Client updates failing
>
>On 2016-02-17 13:59 +0000, Dimitri Yioulos wrote:
>>-----Original Message-----
>>From: Jan Hutař [mailto:jhutar at redhat.com]
>>Sent: Wednesday, February 17, 2016 1:15 AM
>>To: Dimitri Yioulos <dyioulos at netatlantic.com>
>>Cc: spacewalk-list at redhat.com
>>Subject: Re: [Spacewalk-list] Client updates failing
>>
>>On 2016-02-16 21:40 +0000, Dimitri Yioulos wrote:
>>[...]
>>>>Jan,
>>>>
>>>>After backing up/modifying packages.py as follows:
>>>>
>>>> found = False
>>>> for pkg in pkgs:
>>>> print "Current:", current.epoch, current.version, current.release
>>>> print "Candidate:", evr.epoch, evr.version, evr.release
>>>> print "Comparasion:", current.compare(evr)
>>>> if pkg.returnEVR().compare(evr) == 0:
>>>> log.log_debug('Package %s already installed' \
>>>> % _yum_package_tup(package))
>>>> ~
>>>>
>>>>I ran rhn_check, with the following output:
>>>>
>>>>[root at server actions]# /usr/sbin/rhn_check -vv
>>>>D: check_action{'action': "<?xml
>>>>version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodNa
>>>>m
>>>>e
>>>>>
>>>>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<va
>>>>l
>>>>u
>>>>e
>>>>><string>tzdata</string></value>\n<value><string>2016a</string></val
>>>>>u
>>>>>e
>>>>>>
>>>>\n<value><string>1.el5</string></value>\n<value><string></string></v
>>>>a
>>>>l
>>>>u
>>>>e>\n<value><string>x86_64</string></value>\n</data></array></value>\
>>>>e>n
>>>>e><
>>>>e>/
>>>>data></array></value>\n</param>\n</params>\n</methodCall>\n",
>>>>'version': 2, 'id': 2739}
>>>>updateLoginInfo() login info
>>>>D: login(forceUpdate=True) invoked
>>>>logging into up2date server
>>>>D: rpcServer: Calling XMLRPC up2date.login
>>>>D: writeCachedLogin() invoked
>>>>D: Wrote pickled loginInfo at 1455646702.53 with expiration of 1455650302.53 seconds.
>>>>successfully retrieved authentication token from up2date server
>>>>D: logininfo:{'X-RHN-Server-Id': 1000010162, 'X-RHN-Auth-Server-Time':
>>>>'1455646703.57', 'X-RHN-Auth':
>>>>'sZm51YnvCfQzwXsCTshBPfpBxhhT9xkRb9NubPX098Q=', 'X-RHN-Auth-Channels':
>>>>[['centos5-x86_64', '20150219163429', '1', '1'],
>>>>['centos5-base-x86_64', '20160215172513', '0', '1'],
>>>>['centos5-updates-x86_64', '20160215181106', '0', '1'],
>>>>['epel5-x86_64', '20160215181856', '0', '1'], ['puppet-el5-x86_64',
>>>>'20160213002732', '0', '1'], ['rpmforge-el5-x86_64',
>>>>'20160215131156', '0', '1'], ['spacewalk-client-el5-x86_64',
>>>>'20160215175220', '0', '1']], 'X-RHN-Auth-User-Id': '',
>>>>'X-RHN-Auth-Expire-Offset': '3600.0'}
>>>>D: handle_action{'action': "<?xml
>>>>version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodNa
>>>>m
>>>>e
>>>>>
>>>>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<va
>>>>l
>>>>u
>>>>e
>>>>><string>tzdata</string></value>\n<value><string>2016a</string></val
>>>>>u
>>>>>e
>>>>>>
>>>>\n<value><string>1.el5</string></value>\n<value><string></string></v
>>>>a
>>>>l
>>>>u
>>>>e>\n<value><string>x86_64</string></value>\n</data></array></value>\
>>>>e>n
>>>>e><
>>>>e>/
>>>>data></array></value>\n</param>\n</params>\n</methodCall>\n",
>>>>'version': 2, 'id': 2739}
>>>>D: handle_action actionid = 2739, version = 2
>>>>D: do_call packages.update([['tzdata', '2016a', '1.el5', '',
>>>>'x86_64']],){'cache_only': None} Loaded plugins: fastestmirror,
>>>>rhnplugin
>>>>D: rpcServer: Calling XMLRPC up2date.listChannels This system is receiving updates from RHN Classic or Red Hat Satellite.
>>>>Loading mirror speeds from cached hostfile
>>>> * base: mirror.atlanticmetro.net
>>>> * epel: mirror.vcu.edu
>>>> * extras: mirror.trouble-free.net
>>>> * updates: mirror.netdepot.com
>>>>Reducing Extra Packages for Enterprise Linux 5 - x86_64 to included
>>>>packages only Finished Checking for new repos for mirrors
>>>>D: Called update[['tzdata', '2016a', '1.el5', '', 'x86_64']]
>>>>Current: D: Sending back response((6,), 'Fatal error in Python code
>>>>occurred', {})
>>>>D: do_call packages.checkNeedUpdate('rhnsd=1',){}
>>>>D: local action status: (0, 'rpm database not modified since last
>>>>update (or package list recently updated)', {})
>>>>D: rpcServer: Calling XMLRPC registration.welcome_message
>>>>
>>>>Dimitri
>>>>
>>>>
>>>>Since adding the lines in packages.py, I see the following in the Spacewalk UI:
>>>>
>>>>Details: This action will be executed after 2/16/16 1:13:00 PM EST
>>>>This action's status is: Failed.
>>>>The client picked up this action on 2/16/16 1:18 PM The client
>>>>completed this action on 2/16/16 1:18 PM Client execution returned
>>>>"Fatal error in Python code occurred [[6]]" (code -1)
>>>>
>>>>Packages Scheduled:
>>>>tzdata-2016a-1.el5.x86_64
>>>>
>>>>Dimitri
>>>
>>>Hello.
>>>
>>>Details about his "Fatal error in Python code occurred" should be logged on client in /var/log/up2date.
>>>
>>>Also please restart your Spacewalk after this change in the code (but you have probably already done that).
>>>
>>>Regards,
>>>Jan
>>>
>>>
>>>
>>>--
>>>Jan Hutar Systems Management QA
>>>jhutar at redhat.com Red Hat, Inc.
>>>
>>>
>>>Oops, I actually hadn't restarted the Spacewalk server after changing the code in the client. After doing so, I stopped osad on the client, and ran rhn_check:
>>>
>>>[root at server ~]# /usr/sbin/rhn_check -vv
>>>D: do_call packages.checkNeedUpdate('rhnsd=1',){}
>>>Loaded plugins: fastestmirror, rhnplugin
>>>D: login(forceUpdate=False) invoked
>>>D: readCachedLogin invoked
>>>D: Checking pickled loginInfo, currentTime=1455657841.6,
>>>createTime=1455646702.53, expire-offset=3600.0
>>>D: Pickled loginInfo has expired, created = 1455646702.53, expire = 1455650302.53.
>>>logging into up2date server
>>>D: rpcServer: Calling XMLRPC up2date.login
>>>D: writeCachedLogin() invoked
>>>D: Wrote pickled loginInfo at 1455657841.63 with expiration of 1455661441.63 seconds.
>>>successfully retrieved authentication token from up2date server
>>>D: logininfo:{'X-RHN-Server-Id': 1000010162, 'X-RHN-Auth-Server-Time':
>>>'1455657842.92', 'X-RHN-Auth':
>>>'x8Ca4i9/NXvPC+OuoInP44M1JGiuyr2aYiks1BKbQhY=', 'X-RHN-Auth-Channels':
>>>[['centos5-x86_64', '20150219163429', '1', '1'],
>>>['centos5-base-x86_64', '20160215172513', '0', '1'],
>>>['centos5-updates-x86_64', '20160215181106', '0', '1'],
>>>['epel5-x86_64', '20160215181856', '0', '1'], ['puppet-el5-x86_64',
>>>'20160213002732', '0', '1'], ['rpmforge-el5-x86_64',
>>>'20160215131156', '0', '1'], ['spacewalk-client-el5-x86_64',
>>>'20160215175220', '0', '1']], 'X-RHN-Auth-User-Id': '',
>>>'X-RHN-Auth-Expire-Offset': '3600.0'}
>>>D: rpcServer: Calling XMLRPC up2date.listChannels This system is
>>>receiving updates from RHN Classic or Red Hat Satellite.
>>>Loading mirror speeds from cached hostfile
>>> * base: mirror.atlanticmetro.net
>>> * epel: mirrors.mit.edu
>>> * extras: mirror.trouble-free.net
>>> * updates: mirrors.seas.harvard.edu
>>>Reducing Extra Packages for Enterprise Linux 5 - x86_64 to included
>>>packages only Finished Checking for new repos for mirrors
>>>D: local action status: (0, 'rpm database not modified since last
>>>update (or package list recently updated)', {})
>>>D: rpcServer: Calling XMLRPC registration.welcome_message
>>>[root at bluefield ~]# tail -f /var/log/up2date [Tue Feb 16 16:24:01
>>>2016] up2date D: Pickled loginInfo has expired, created = 1455646702.53, expire = 1455650302.53.
>>>[Tue Feb 16 16:24:01 2016] up2date logging into up2date server [Tue
>>>Feb
>>>16 16:24:01 2016] up2date D: rpcServer: Calling XMLRPC up2date.login
>>>[Tue Feb 16 16:24:01 2016] up2date D: writeCachedLogin() invoked [Tue
>>>Feb 16 16:24:01 2016] up2date D: Wrote pickled loginInfo at 1455657841.63 with expiration of 1455661441.63 seconds.
>>>[Tue Feb 16 16:24:01 2016] up2date successfully retrieved
>>>authentication token from up2date server [Tue Feb 16 16:24:01 2016]
>>>up2date D: logininfo:{'X-RHN-Server-Id': 1000010162,
>>>'X-RHN-Auth-Server-Time': '1455657842.92', 'X-RHN-Auth':
>>>'x8Ca4i9/NXvPC+OuoInP44M1JGiuyr2aYiks1BKbQhY=', 'X-RHN-Auth-Channels':
>>>[['centos5-x86_64', '20150219163429', '1', '1'],
>>>['centos5-base-x86_64', '20160215172513', '0', '1'],
>>>['centos5-updates-x86_64', '20160215181106', '0', '1'],
>>>['epel5-x86_64', '20160215181856', '0', '1'], ['puppet-el5-x86_64',
>>>'20160213002732', '0', '1'], ['rpmforge-el5-x86_64',
>>>'20160215131156', '0', '1'], ['spacewalk-client-el5-x86_64',
>>>'20160215175220', '0', '1']], 'X-RHN-Auth-User-Id': '',
>>>'X-RHN-Auth-Expire-Offset': '3600.0'} [Tue Feb 16 16:24:01 2016]
>>>up2date D: rpcServer: Calling XMLRPC up2date.listChannels [Tue Feb 16
>>>16:24:06 2016] up2date D: local action
>>>status: (0, 'rpm database not modified since last update (or package
>>>list recently updated)', {}) [Tue Feb 16 16:24:06 2016] up2date D:
>>>rpcServer: Calling XMLRPC registration.welcome_message
>>>
>>>I restarted osad on the client, then tried to do an update from the Spacewalk server. I watched the output of top, and saw rhn_check try to run three or four times, but always go to "rhn_check <defunct>"
>>>
>>>Dimitri
>>
>>Hello,
>>looks like this time package update was not scheduled (or was picked up by rhn_check started by osad) before you ran `rhn_check -vv` manually. I suggest to do the testing with osad turned off on the client so it is not picking events before you.
>>
>>And I woul not worry too much about these "<defunct>"s:
>>
>>
>> http://askubuntu.com/questions/201303/what-is-defunct-for-a-process-a
>> n
>> d-why-it-doesnt-get-killed#answer-427222
>>
>>I believe you might want to do something like this:
>>
>> 1. schedule problematic package update for client on the spacewalk
>> webUI
>> 2. client# service osad stop
>> 3. client# tail -f /var/log/up2date & 4. client# rhn_check -vv
>>
>>Regards,
>>Jan
>>
>>
>>
>>--
>>Jan Hutar Systems Management QA
>>jhutar at redhat.com Red Hat, Inc.
>>
>>Jan,
>>
>>I did as you suggested. Here's the output of tailing /var/log/up2date:
>>
>>[Wed Feb 17 08:55:28 2016] up2date D: do_call
>>packages.checkNeedUpdate('rhnsd=1',){}
>>[Wed Feb 17 08:55:28 2016] up2date D: login(forceUpdate=False) invoked
>>[Wed Feb 17 08:55:28 2016] up2date D: readCachedLogin invoked [Wed Feb
>>17 08:55:28 2016] up2date D: Checking pickled loginInfo,
>>currentTime=1455717328.73, createTime=1455716395.31,
>>expire-offset=3600.0 [Wed Feb 17 08:55:28 2016] up2date D:
>>readCachedLogin(): using pickled loginInfo set to expire at
>>1455719995.31 [Wed Feb 17 08:55:28 2016] up2date D: rpcServer: Calling
>>XMLRPC up2date.listChannels [Wed Feb 17 08:55:29 2016] up2date D:
>>local action status: (0, 'rpm database not modified since last update
>>(or package list recently updated)', {}) [Wed Feb 17 08:55:29 2016]
>>up2date
>>D: rpcServer: Calling XMLRPC registration.welcome_message
>>
>>The package was not updated.
>>
>>Dimitri
>
>Hello,
>I'm more interested in `rhn_check -vv` output, because these lines you have added do not log into /var/log/up2date. /var/log/up2date would be interesting in case you would see "Fatal error in Python code occurred". Also the output you have just sent doesn't look like you have scheduled package update before running the rhn_check. Ensure you have osad turned off so it does not pick the action you schedule in Spacewalk webUI before rhn_check you run manually.
>
>Regards,
>Jan
>
>
>
>--
>Jan Hutar Systems Management QA
>jhutar at redhat.com Red Hat, Inc.
>
>Jan,
>
>I'm pretty sure I did that. But, here it is, again:
>
>[root at bluefield ~]# /sbin/service osad stop
>Shutting down osad: [OK]
>
>[root at bluefield ~]# /usr/sbin/rhn_check -vv
>D: do_call packages.checkNeedUpdate('rhnsd=1',){}
>Loaded plugins: fastestmirror, rhnplugin
>D: login(forceUpdate=False) invoked
>D: readCachedLogin invoked
>D: Checking pickled loginInfo, currentTime=1455802542.52,
>createTime=1455801724.57, expire-offset=3600.0
>D: readCachedLogin(): using pickled loginInfo set to expire at
>1455805324.57
>D: rpcServer: Calling XMLRPC up2date.listChannels This system is
>receiving updates from RHN Classic or Red Hat Satellite.
>Loading mirror speeds from cached hostfile
> * base: centos.mirror.constant.com
> * epel: mirrors.mit.edu
> * extras: mirror.metrocast.net
> * updates: mirrors.adams.net
>Reducing Extra Packages for Enterprise Linux 5 - x86_64 to included
>packages only Finished Checking for new repos for mirrors
>D: local action status: (0, 'rpm database not modified since last
>update (or package list recently updated)', {})
>D: rpcServer: Calling XMLRPC registration.welcome_message
>
>Dimitri
Hmm, again, looks like rhn_check did not picked any action. The output have to contain line like this:
D: do_call packages.update([['rhnpush', '5.5.91', '1.el7', '', 'noarch']],){'cache_only': None}
Please ensure you keep order of steps (1. stop osad; 2. schedule update; 3. run rhn_check). Also this might be caused by time difference on Spacewalk and client, or you are accidentaly scheduling for different system or for time too much in the future?
Regards,
Jan
--
Jan Hutar Systems Management QA
jhutar at redhat.com Red Hat, Inc.
Jan,
Thanks for sticking with this!
My apologies on getting the steps right. This time I following them explicitly:
1. stopped osad
2. scheduled update
3. ran "rhn_chceck -vv"
[root at bluefield ~]# /usr/sbin/rhn_check -vv
D: check_action{'action': "<?xml version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodName>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<value><string>tzdata</string></value>\n<value><string>2016a</string></value>\n<value><string>1.el5</string></value>\n<value><string></string></value>\n<value><string>x86_64</string></value>\n</data></array></value>\n</data></array></value>\n</param>\n</params>\n</methodCall>\n", 'version': 2, 'id': 2743}
updateLoginInfo() login info
D: login(forceUpdate=True) invoked
logging into up2date server
D: rpcServer: Calling XMLRPC up2date.login
D: writeCachedLogin() invoked
D: Wrote pickled loginInfo at 1455826274.2 with expiration of 1455829874.2 seconds.
successfully retrieved authentication token from up2date server
D: logininfo:{'X-RHN-Server-Id': 1000010162, 'X-RHN-Auth-Server-Time': '1455826275.39', 'X-RHN-Auth': 'l75aqjtpQW2aRJdb/2JuyI6B2EMQpfIpHtL35tinznI=', 'X-RHN-Auth-Channels': [['centos5-x86_64', '20150219163429', '1', '1'], ['centos5-base-x86_64', '20160218040000', '0', '1'], ['centos5-updates-x86_64', '20160218070000', '0', '1'], ['epel5-x86_64', '20160218000000', '0', '1'], ['puppet-el5-x86_64', '20160218100000', '0', '1'], ['rpmforge-el5-x86_64', '20160218020000', '0', '1'], ['spacewalk-client-el5-x86_64', '20160218110000', '0', '1']], 'X-RHN-Auth-User-Id': '', 'X-RHN-Auth-Expire-Offset': '3600.0'}
D: handle_action{'action': "<?xml version='1.0'?>\n<methodCall>\n<methodName>packages.update</methodName>\n<params>\n<param>\n<value><array><data>\n<value><array><data>\n<value><string>tzdata</string></value>\n<value><string>2016a</string></value>\n<value><string>1.el5</string></value>\n<value><string></string></value>\n<value><string>x86_64</string></value>\n</data></array></value>\n</data></array></value>\n</param>\n</params>\n</methodCall>\n", 'version': 2, 'id': 2743}
D: handle_action actionid = 2743, version = 2
D: do_call packages.update([['tzdata', '2016a', '1.el5', '', 'x86_64']],){'cache_only': None}
Loaded plugins: fastestmirror, rhnplugin
D: rpcServer: Calling XMLRPC up2date.listChannels
This system is receiving updates from RHN Classic or Red Hat Satellite.
Loading mirror speeds from cached hostfile
* base: centos.mia.host-engine.com
* epel: mirror.steadfast.net
* extras: mirrors.seas.harvard.edu
* updates: mirror.cs.pitt.edu
Reducing Extra Packages for Enterprise Linux 5 - x86_64 to included packages only
Finished
Checking for new repos for mirrors
D: Called update[['tzdata', '2016a', '1.el5', '', 'x86_64']]
Current: D: Sending back response((6,), 'Fatal error in Python code occurred', {})
D: do_call packages.checkNeedUpdate('rhnsd=1',){}
D: local action status: (0, 'rpm database not modified since last update (or package list recently updated)', {})
D: rpcServer: Calling XMLRPC registration.welcome_message
Afterward, I saw this in the Event History of the node I was trying to update:
Summary: Package Install scheduled by admin
Details: This action will be executed after 2/18/16 3:11:00 PM EST
This action's status is: Failed.
The client picked up this action on 2/18/16 3:11 PM
The client completed this action on 2/18/16 3:11 PM
Client execution returned "Fatal error in Python code occurred [[6]]" (code -1)
Packages Scheduled:
tzdata-2016a-1.el5.x86_64
What the heck is going on here?
Dimitri
More information about the Spacewalk-list
mailing list