-----Original Message----- From: Jan Hutař [mailto:[email protected]] Sent: Thursday, February 18, 2016 3:04 PM To: Dimitri Yioulos <[email protected]> Cc: [email protected] Subject: Re: [Spacewalk-list] Client updates failing
On 2016-02-18 13:38 +0000, Dimitri Yioulos wrote: >-----Original Message----- >From: Jan Hutař [mailto:[email protected]] >Sent: Thursday, February 18, 2016 12:00 AM >To: Dimitri Yioulos <[email protected]> >Cc: [email protected] >Subject: Re: [Spacewalk-list] Client updates failing > >On 2016-02-17 13:59 +0000, Dimitri Yioulos wrote: >>-----Original Message----- >>From: Jan Hutař [mailto:[email protected]] >>Sent: Wednesday, February 17, 2016 1:15 AM >>To: Dimitri Yioulos <[email protected]> >>Cc: [email protected] >>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@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 >>>[email protected] 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@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@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 >>[email protected] 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 >[email protected] Red Hat, Inc. > >Jan, > >I'm pretty sure I did that. But, here it is, again: > >[root@bluefield ~]# /sbin/service osad stop >Shutting down osad: [OK] > >[root@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 [email protected] 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@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 _______________________________________________ Spacewalk-list mailing list [email protected] https://www.redhat.com/mailman/listinfo/spacewalk-list
