Bug 1222868 - OSA-Dispatcher and OSAD are not executing remote commands after upgrading from 2.2 to 2.3
Summary: OSA-Dispatcher and OSAD are not executing remote commands after upgrading fro...
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Spacewalk
Classification: Community
Component: Server
Version: 2.3
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Gennadii Altukhov
QA Contact: Red Hat Satellite QA List
URL:
Whiteboard:
Depends On:
Blocks: spacewalk-review space27
TreeView+ depends on / blocked
 
Reported: 2015-05-19 10:31 UTC by Ahmad Al-Masry
Modified: 2023-09-14 02:59 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-05-09 12:33:50 UTC
Embargoed:


Attachments (Terms of Use)

Description Ahmad Al-Masry 2015-05-19 10:31:08 UTC
Description of problem:
OSA status are all offline after I updated from 2.2 to 2.3

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

Steps to Reproduce:
1. I followed https://fedorahosted.org/spacewalk/wiki/HowToUpgrade
2. in the step spacewalk-setup --disconnected --upgrade the setup showed me an error for the database credentials, the system asked for user and password and I provided the correct ones.

Actual results:
All servers appears as OSA status offline

Expected results:
All servers appears as OSA status online

Additional info:
I applied the following:
/sbin/service osa-dispatcher stop
/sbin/service jabberd stop
rm /var/satellite/jabberd/db/*
/sbin/service jabberd start
/sbin/service osa-dispatcher start
But no change

Enable OSAD Debugging:
vi /etc/sysconfig/rhn/osad.conf
 # increase for debugging output
 #debug_level = 0
 debug_level = 6
then restart osad, and check with osad -N -v -v -v
I got the following:
2015-05-13 14:32:02 osad._setup_config: Updating configuration
2015-05-13 14:32:12 osad._setup_config: Time drift 8
2015-05-13 14:32:12 osad._setup_config: Client name 9591e3bd9baaf597
2015-05-13 14:32:12 osad._setup_config: Shared key d913645d24a2b55c4c48b29ae9b4227a47f43bff
2015-05-13 14:32:12 jabber_lib.setup_connection: Connecting to spacewalk.hadara.ps
2015-05-13 14:32:12 jabber_lib._get_jabber_client:
2015-05-13 14:32:12 jabber_lib._get_jabber_client: Connecting to spacewalk.hadara.ps
2015-05-13 14:32:12 jabber_lib.__init__:
2015-05-13 14:32:12 jabber_lib.__init__:
2015-05-13 14:32:12 jabber_lib.connect:
2015-05-13 14:32:12 jabber_lib.process: 300
2015-05-13 14:32:12 jabber_lib.process: None
2015-05-13 14:32:12 jabber_lib.process: None
2015-05-13 14:32:12 jabber_lib.process: None
2015-05-13 14:32:12 jabber_lib.setup_connection: Connected to jabber server spacewalk.hadara.ps
2015-05-13 14:32:12 osad_client.start: osad-31f6710f80 78d044909c96f4a97407 osad
2015-05-13 14:32:12 jabber_lib.auth: osad-31f6710f80 78d044909c96f4a97407 osad 1
2015-05-13 14:32:12 jabber_lib.process: 59.9999866486
2015-05-13 14:32:12 jabber_lib.process: 299.999986887
2015-05-13 14:32:12 jabber_lib.register_callback: <bound method Client._roster_callback of <osad.osad_client.Client instance at 0x2690908>> iq None None None None
2015-05-13 14:32:12 jabber_lib.process: None
2015-05-13 14:32:12 jabber_lib._roster_callback: Updating the roster <iq type='result' id='iq-request-7a2f51-2'><query xmlns = 'jabber:iq:roster' ><item jid='rhn-dispatcher-sat.ps' subscription='to' /></query></iq>
2015-05-13 14:32:12 jabber_lib.register_callback: <bound method Client._presence_callback of <osad.osad_client.Client instance at 0x2690908>> presence None None None None
2015-05-13 14:32:12 jabber_lib.register_callback: <bound method Client._message_callback of <osad.osad_client.Client instance at 0x2690908>> message None None None None
2015-05-13 14:32:18 jabber_lib.send_presence: None None
2015-05-13 14:32:18 jabber_lib.process_forever:
2015-05-13 14:32:18 jabber_lib.process: 180
2015-05-13 14:32:18 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:32:24 jabber_lib.process: 180
2015-05-13 14:32:24 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:32:32 jabber_lib.process: 180
2015-05-13 14:32:32 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:32:40 jabber_lib.process: 180
2015-05-13 14:32:40 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:32:48 jabber_lib.process: 180
2015-05-13 14:32:48 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:32:55 jabber_lib.process: 180
2015-05-13 14:32:55 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:02 jabber_lib.process: 180
2015-05-13 14:33:02 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:10 jabber_lib.process: 180
2015-05-13 14:33:10 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:16 jabber_lib.process: 180
2015-05-13 14:33:19 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:29 jabber_lib.process: 180
2015-05-13 14:33:29 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:35 jabber_lib.process: 180
2015-05-13 14:33:35 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:43 jabber_lib.process: 180
2015-05-13 14:33:43 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:33:51 jabber_lib.process: 180
2015-05-13 14:33:53 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None
2015-05-13 14:34:03 jabber_lib.process: 180
2015-05-13 14:34:03 jabber_lib._presence_callback: osad-31f6710f80.ps/osad rhn-dispatcher-sat.ps/superclient None



I also tried this:
/etc/init.d/osad start
Starting osad: 2015-05-13 14:35:13 osad._setup_config: Updating configuration
2015-05-13 14:35:18 osad._setup_config: Time drift 8
2015-05-13 14:35:18 osad._setup_config: Client name 14f8e3b955f3d3be
2015-05-13 14:35:18 osad._setup_config: Shared key bfb75d36751fc0d80baea02646a417d7d17ac91f
2015-05-13 14:35:18 jabber_lib.setup_connection: Connecting to spacewalk.hadara.ps
2015-05-13 14:35:18 jabber_lib._get_jabber_client:
2015-05-13 14:35:18 jabber_lib._get_jabber_client: Connecting to spacewalk.hadara.ps
2015-05-13 14:35:18 jabber_lib.__init__:
2015-05-13 14:35:18 jabber_lib.__init__:
2015-05-13 14:35:18 jabber_lib.check_cert: Loading cert <X509Name object '/C=IL/ST=WestBank/L=Ramallah/O=Hadara Technologies/OU=Systems/CN=spacewalk.hadara.ps'>
2015-05-13 14:35:18 jabber_lib.connect:
2015-05-13 14:35:18 jabber_lib.connect: Attempting to connect
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream to='spacewalk.hadara.ps' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>

2015-05-13 14:35:18 jabber_lib.process: 300
2015-05-13 14:35:18 jabber_lib.process: before select(); timeout 299.999999046
2015-05-13 14:35:18 jabber_lib.process: select() returned
2015-05-13 14:35:18 jabber_lib._auth_dispatch: <features><address xmlns = 'http://affinix.com/jabber/address' >217.66.226.69</address><auth xmlns = 'http://jabber.org/features/iq-auth'  /><register xmlns = 'http://jabber.org/features/iq-register'  /><starttls xmlns = 'urn:ietfaramsml:nsmpp-tls' ><required /></starttls></features>
<-- <features><address xmlns = 'http://affinix.com/jabber/address' >217.66.226.69</address><auth xmlns = 'http://jabber.org/features/iq-auth'  /><register xmlns = 'http://jabber.org/features/iq-register'  /><starttls xmlns = 'urn:ietfaramsml:nsmpp-tls' ><required /></starttls></features>

2015-05-13 14:35:18 jabber_lib.connect: Connected
2015-05-13 14:35:18 jabber_lib.connect: Expecting features stanza, got: <features><address xmlns = 'http://affinix.com/jabber/address' >217.66.226.69</address><auth xmlns = 'http://jabber.org/features/iq-auth'  /><register xmlns = 'http://jabber.org/features/iq-register'  /><starttls xmlns = 'urn:ietfaramsml:nsmpp-tls' ><required /></starttls></features>
2015-05-13 14:35:18 jabber_lib.connect: starttls node <starttls><required /></starttls>
2015-05-13 14:35:18 jabber_lib.process: None
2015-05-13 14:35:18 jabber_lib.process: before select(); timeout None
2015-05-13 14:35:18 jabber_lib.process: select() returned
2015-05-13 14:35:18 jabber_lib._auth_dispatch: <proceed />
<-- <proceed />

2015-05-13 14:35:18 jabber_lib.connect: Expecting proceed stanza, got: <proceed />
2015-05-13 14:35:18 jabber_lib.connect: Preparing for TLS handshake
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream to='spacewalk.hadara.ps' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>

2015-05-13 14:35:18 jabber_lib.process: None
2015-05-13 14:35:18 jabber_lib.process: before select(); timeout None
2015-05-13 14:35:18 jabber_lib.process: select() returned
2015-05-13 14:35:18 jabber_lib.process: Reading 1024 bytes from ssl socket
2015-05-13 14:35:18 jabber_lib.process: Read 253 bytes
2015-05-13 14:35:18 jabber_lib.process: None
2015-05-13 14:35:18 jabber_lib.process: before select(); timeout None
2015-05-13 14:35:18 jabber_lib.process: select() returned
2015-05-13 14:35:18 jabber_lib.process: Reading 1024 bytes from ssl socket
2015-05-13 14:35:18 jabber_lib.process: Read 423 bytes
2015-05-13 14:35:18 jabber_lib._auth_dispatch: <features><address xmlns = 'http://affinix.com/jabber/address' >217.66.226.69</address><mechanisms xmlns = 'urn:ietfaramsml:nsmpp-sasl' ><mechanism>EXTERNAL</mechanism><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism></mechanisms><auth xmlns = 'http://jabber.org/features/iq-auth'  /><register xmlns = 'http://jabber.org/features/iq-register'  /></features>
<-- <features><address xmlns = 'http://affinix.com/jabber/address' >217.66.226.69</address><mechanisms xmlns = 'urn:ietfaramsml:nsmpp-sasl' ><mechanism>EXTERNAL</mechanism><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism></mechanisms><auth xmlns = 'http://jabber.org/features/iq-auth'  /><register xmlns = 'http://jabber.org/features/iq-register'  /></features>

2015-05-13 14:35:18 jabber_lib.connect: connect returning
2015-05-13 14:35:18 jabber_lib.setup_connection: Connected to jabber server spacewalk.hadara.ps
2015-05-13 14:35:18 jabber_lib.push_to_background: Pushing process into background
                                                           [  OK  ]

And no error found

On the server I sometimes when I tried to restart osad I got error on sm, and /var/log/rhn/osa-dispatcher.log displays some error "Please see below" I don't know if these are related.

# service jabberd stop
Terminating jabberd processes ...
Stopping s2s:                                              [  OK  ]
Stopping c2s:                                              [  OK  ]
Stopping sm:                                               [FAILED]
Stopping router:                                           [  OK  ]
You have mail in /var/spool/mail/root
[root@spacewalk ~]# service osa-dispatcher stop
Shutting down osa-dispatcher:                              [  OK  ]
[root@spacewalk ~]# rm -rf /var/lib/jabberd/db/*
[root@spacewalk ~]# service jabberd start
Initializing jabberd processes ...
Starting router:                                           [  OK  ]
Starting sm:                                               [  OK  ]
Starting c2s:                                              [  OK  ]
Starting s2s:                                              [  OK  ]
[root@spacewalk ~]# service osa-dispatcher start
Starting osa-dispatcher:                                   [  OK  ]

For the logs:
tail -f /var/log/rhn/osa-dispatcher.log
2015/05/13 12:55:12 +03:00 29497 0.0.0.0: osad/jabber_lib.__init__
2015/05/13 12:55:13 +03:00 29497 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/13 12:55:13 +03:00 29497 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/13 12:55:15 +03:00 29497 0.0.0.0: osad/jabber_lib.process_forever

I noticed something old, in the logs, I don't know if it is related or not:
[root@spacewalk ~]# tail -100 /var/log/rhn/osa-dispatcher.log
2015/05/06 08:05:14 +03:00 11677 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 08:05:14 +03:00 11677 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 08:05:14 +03:00 11677 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 08:08:05 +03:00 14450 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 08:08:05 +03:00 14450 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 08:08:05 +03:00 14450 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 08:08:05 +03:00 14450 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 08:19:58 +03:00 15833 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 08:19:58 +03:00 15833 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 08:19:58 +03:00 15833 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 08:19:59 +03:00 15833 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 09:01:48 +03:00 15833 0.0.0.0: osad/jabber_lib.main('ERROR', 'Error caught:')
2015/05/06 09:01:48 +03:00 15833 0.0.0.0: osad/jabber_lib.main('ERROR', 'Traceback (most recent call last):\n  File "/usr/share/rhn/osad/jabber_lib.py", line 121, in main\n    self.process_forever(c)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 179, in process_forever\n    self.process_once(client)\n  File "/usr/share/rhn/osad/osa_dispatcher.py", line 187, in process_once\n    client.retrieve_roster()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 729, in retrieve_roster\n    stanza = self.get_one_stanza()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 801, in get_one_stanza\n    self.process(timeout=tm)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 1055, in process\n    data = self._read(self.BLOCK_SIZE)\nSSLError: (\'OpenSSL error; will retry\', "(-1, \'Unexpected EOF\')")\n')
2015/05/06 09:01:58 +03:00 15833 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 09:01:58 +03:00 15833 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 09:01:59 +03:00 15833 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 09:01:59 +03:00 15833 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 09:03:16 +03:00 19166 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 09:03:16 +03:00 19166 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 09:03:16 +03:00 19166 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 09:03:16 +03:00 19166 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 09:18:14 +03:00 20756 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 09:18:14 +03:00 20756 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 09:18:14 +03:00 20756 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 09:18:17 +03:00 20756 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 09:29:16 +03:00 22149 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 09:29:16 +03:00 22149 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 09:29:17 +03:00 22149 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 09:29:19 +03:00 22149 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 09:30:28 +03:00 22149 0.0.0.0: osad/dispatcher_client._message_callback('Ping response',)
2015/05/06 10:17:56 +03:00 1864 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 10:17:56 +03:00 1864 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 10:17:56 +03:00 1864 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 10:18:16 +03:00 1864 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 11:28:14 +03:00 1864 0.0.0.0: osad/jabber_lib.main('ERROR', 'Error caught:')
2015/05/06 11:28:14 +03:00 1864 0.0.0.0: osad/jabber_lib.main('ERROR', 'Traceback (most recent call last):\n  File "/usr/share/rhn/osad/jabber_lib.py", line 121, in main\n    self.process_forever(c)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 179, in process_forever\n    self.process_once(client)\n  File "/usr/share/rhn/osad/osa_dispatcher.py", line 187, in process_once\n    client.retrieve_roster()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 729, in retrieve_roster\n    stanza = self.get_one_stanza()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 801, in get_one_stanza\n    self.process(timeout=tm)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 1063, in process\n    self._parser.Parse(data)\n  File "/usr/lib/python2.6/site-packages/jabber/xmlstream.py", line 269, in unknown_endtag\n    self.dispatch(self._mini_dom)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 829, in _orig_dispatch\n    jabber.Client.dispatch(self, stanza)\n  File "/usr/lib/python2.6/site-packages/jabber/jabber.py", line 290, in dispatch\n    else: handler[\'func\'](self,stanza)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 380, in dispatch\n    callback(client, stanza)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 1250, in _presence_callback\n    self.subscribe_to_presence([jid])\n  File "/usr/share/rhn/osad/jabber_lib.py", line 986, in subscribe_to_presence\n    self._subscribe_to_presence(jid)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 1268, in _subscribe_to_presence\n    sig = self._create_signature(full_jid, NS_RHN_PRESENCE_SUBSCRIBE)\n  File "/usr/share/rhn/osad/dispatcher_client.py", line 108, in _create_signature\n    row = lookup_client_by_jid(jid)\n  File "/usr/share/rhn/osad/dispatcher_client.py", line 228, in lookup_client_by_jid\n    raise InvalidClientError(jid)\nInvalidClientError: osad-02ea277b24.ps/osad\n')
2015/05/06 11:28:24 +03:00 1864 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 11:28:24 +03:00 1864 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 11:28:25 +03:00 1864 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 11:28:25 +03:00 1864 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 11:35:30 +03:00 5806 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 11:35:30 +03:00 5806 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 11:35:30 +03:00 5806 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 11:35:32 +03:00 5806 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 11:41:30 +03:00 5806 0.0.0.0: osad/dispatcher_client._message_callback('Ping response',)
2015/05/06 11:42:34 +03:00 5806 0.0.0.0: osad/dispatcher_client._message_callback('Ping response',)
2015/05/06 11:43:08 +03:00 5806 0.0.0.0: osad/dispatcher_client._message_callback('Ping response',)
2015/05/06 11:49:14 +03:00 7228 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 11:49:14 +03:00 7228 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 11:49:14 +03:00 7228 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 11:49:16 +03:00 7228 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 12:01:48 +03:00 7228 0.0.0.0: osad/dispatcher_client._message_callback('Ping response',)
2015/05/06 15:18:54 +03:00 1868 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 15:18:54 +03:00 1868 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 15:18:55 +03:00 1868 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 15:19:27 +03:00 1868 0.0.0.0: osad/jabber_lib.process_forever
2015/05/06 15:34:11 +03:00 3759 0.0.0.0: osad/jabber_lib.__init__
2015/05/06 15:34:11 +03:00 3759 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/06 15:34:11 +03:00 3759 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/06 15:34:12 +03:00 3759 0.0.0.0: osad/jabber_lib.process_forever
2015/05/07 04:00:09 +03:00 27930 0.0.0.0: osad/jabber_lib.__init__
2015/05/07 04:00:09 +03:00 27930 0.0.0.0: osad/jabber_lib.connect('Server did not return a <features /> stanza, reconnecting',)
2015/05/07 04:00:10 +03:00 27930 0.0.0.0: osad/jabber_lib.connect('Server did not return a <features /> stanza, reconnecting',)
2015/05/07 04:00:11 +03:00 27930 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/07 04:00:12 +03:00 27930 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/07 04:00:14 +03:00 27930 0.0.0.0: osad/jabber_lib.process_forever
2015/05/08 04:00:09 +03:00 2046 0.0.0.0: osad/jabber_lib.__init__
2015/05/08 04:00:09 +03:00 2046 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/08 04:00:09 +03:00 2046 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/08 04:00:11 +03:00 2046 0.0.0.0: osad/jabber_lib.process_forever
2015/05/09 04:00:07 +03:00 8724 0.0.0.0: osad/jabber_lib.__init__
2015/05/09 04:00:07 +03:00 8724 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/09 04:00:08 +03:00 8724 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/09 04:00:10 +03:00 8724 0.0.0.0: osad/jabber_lib.process_forever
2015/05/10 04:00:11 +03:00 15686 0.0.0.0: osad/jabber_lib.__init__
2015/05/10 04:00:11 +03:00 15686 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/10 04:00:11 +03:00 15686 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/10 04:00:14 +03:00 15686 0.0.0.0: osad/jabber_lib.process_forever
2015/05/11 04:00:09 +03:00 20065 0.0.0.0: osad/jabber_lib.__init__
2015/05/11 04:00:09 +03:00 20065 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/11 04:00:09 +03:00 20065 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/11 04:00:11 +03:00 20065 0.0.0.0: osad/jabber_lib.process_forever
2015/05/11 12:36:48 +03:00 1870 0.0.0.0: osad/jabber_lib.__init__
2015/05/11 12:36:48 +03:00 1870 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/11 12:36:48 +03:00 1870 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/11 12:37:16 +03:00 1870 0.0.0.0: osad/jabber_lib.process_forever
2015/05/12 04:00:06 +03:00 1870 0.0.0.0: osad/jabber_lib.main('ERROR', 'Error caught:')
2015/05/12 04:00:06 +03:00 1870 0.0.0.0: osad/jabber_lib.main('ERROR', 'Traceback (most recent call last):\n  File "/usr/share/rhn/osad/jabber_lib.py", line 121, in main\n    self.process_forever(c)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 179, in process_forever\n    self.process_once(client)\n  File "/usr/share/rhn/osad/osa_dispatcher.py", line 187, in process_once\n    client.retrieve_roster()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 729, in retrieve_roster\n    stanza = self.get_one_stanza()\n  File "/usr/share/rhn/osad/jabber_lib.py", line 801, in get_one_stanza\n    self.process(timeout=tm)\n  File "/usr/share/rhn/osad/jabber_lib.py", line 1055, in process\n    data = self._read(self.BLOCK_SIZE)\nSSLError: (\'OpenSSL error; will retry\', "(-1, \'Unexpected EOF\')")\n')
2015/05/12 04:00:15 +03:00 31354 0.0.0.0: osad/jabber_lib.__init__
2015/05/12 04:00:15 +03:00 31354 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/12 04:00:16 +03:00 31354 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/12 04:00:18 +03:00 31354 0.0.0.0: osad/jabber_lib.process_forever
2015/05/13 04:00:12 +03:00 12768 0.0.0.0: osad/jabber_lib.__init__
2015/05/13 04:00:12 +03:00 12768 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/13 04:00:14 +03:00 12768 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/13 04:00:16 +03:00 12768 0.0.0.0: osad/jabber_lib.process_forever
2015/05/13 12:55:12 +03:00 29497 0.0.0.0: osad/jabber_lib.__init__
2015/05/13 12:55:13 +03:00 29497 0.0.0.0: osad/jabber_lib.setup_connection('Connected to jabber server', 'spacewalk.hadara.ps')
2015/05/13 12:55:13 +03:00 29497 0.0.0.0: osad/osa_dispatcher.fix_connection('Upstream notification server started on port', 1290)
2015/05/13 12:55:15 +03:00 29497 0.0.0.0: osad/jabber_lib.process_forever

I also noticed that the log file does not change when I try to issue OSA ping from the web so I can know the status of the ping.
Please your help.
BR

Comment 1 bernhard.lichtinger 2015-07-22 15:57:39 UTC
I had the same problem, only about 40 of my 195 systems had an OSAD status of online.

Comparing the verbose logs of osad on an online system and an offline system I think the problem lies in the roster management of osa-dispatcher. 

osad on online system shows:

2015-07-22 15:27:01 jabber_lib._roster_callback: Updating the roster <iq type='result' id='iq-request-c92a47-2'><query xmlns = 'jabber:iq:roster' ><item ask='subscribe' jid='rhn-dispatcher-sat@SPACEWALK_SERVER' subscription='from' /></query></iq>
2015-07-22 15:27:01 jabber_lib.send_presence: rhn-dispatcher-sat@SPACEWALK_SERVER subscribed
2015-07-22 15:27:01 jabber_lib.register_callback: <bound method Client._presence_callback of <osad.osad_client.Client instance at 0x8d8e18>> presence None None None None
2015-07-22 15:27:01 jabber_lib.register_callback: <bound method Client._message_callback of <osad.osad_client.Client instance at 0x8d8e18>> message None None None None
2015-07-22 15:27:01 jabber_lib.subscribe_to_presence: Subscribed to {}
2015-07-22 15:27:01 jabber_lib.subscribe_to_presence: Subscribed both {}
2015-07-22 15:27:01 jabber_lib.subscribe_to_presence: Subscribed none {}
2015-07-22 15:27:01 jabber_lib.subscribe_to_presence: Subscribed from {'rhn-dispatcher-sat@SPACEWALK_SERVER': {'ask': u'subscribe', 'jid': 'rhn-dispatcher-sat@SPACEWALK_SERVER', 'subscription': u'from'}}
2015-07-22 15:27:01 jabber_lib.subscribe_to_presence: Subscribed from + ask=subscribe
2015-07-22 15:27:01 jabber_lib.send_presence: None None
2015-07-22 15:27:01 jabber_lib.process_forever: 
2015-07-22 15:27:01 jabber_lib.process: 180
2015-07-22 15:27:01 jabber_lib._roster_callback: Updating the roster <iq to='osad-a914df551c@SPACEWALK_SERVER/osad' type='set' id='lyfo3fy3ep0w7dtziloywuifbaudde8ydnmg3lkh'><query xmlns = 'jabber:iq:roster' ><item ask='subscribe' jid='rhn-dispatcher-sat@SPACEWALK_SERVER' subscription='from' /></query></iq>
2015-07-22 15:27:09 jabber_lib.process: 180

osad on offline system shows:

2015-07-22 15:03:20 jabber_lib.register_callback: <bound method Client._roster_callback of <osad.osad_client.Client instance at 0x9d8e18>> iq None None None None
2015-07-22 15:03:20 jabber_lib.process: None
2015-07-22 15:03:20 jabber_lib._roster_callback: Updating the roster <iq type='result' id='iq-request-0381de-2'><query xmlns = 'jabber:iq:roster' ><item jid='rhn-dispatcher-sat@SPACEWALK_SERVER' subscription='to' /></query></iq>
2015-07-22 15:03:20 jabber_lib.register_callback: <bound method Client._presence_callback of <osad.osad_client.Client instance at 0x9d8e18>> presence None None None None
2015-07-22 15:03:20 jabber_lib.register_callback: <bound method Client._message_callback of <osad.osad_client.Client instance at 0x9d8e18>> message None None None None
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed to {'rhn-dispatcher-sat@SPACEWALK_SERVER': {'jid': 'rhn-dispatcher-sat@SPACEWALK_SERVER', 'subscription': u'to'}}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed both {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed none {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed from {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed to
2015-07-22 15:03:20 jabber_lib.send_presence: None None
2015-07-22 15:03:20 jabber_lib.process_forever: 
2015-07-22 15:03:20 jabber_lib.process: 180
2015-07-22 15:03:20 jabber_lib._presence_callback: osad-46ac861523@SPACEWALK_SERVER/osad rhn-dispatcher-sat@SPACEWALK_SERVER/superclient None
2015-07-22 15:03:20 jabber_lib._presence_callback: Node is available rhn-dispatcher-sat@SPACEWALK_SERVER/superclient None
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed to {'rhn-dispatcher-sat@SPACEWALK_SERVER': {'jid': 'rhn-dispatcher-sat@SPACEWALK_SERVER', 'subscription': u'to'}}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed both {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed none {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed from {}
2015-07-22 15:03:20 jabber_lib.subscribe_to_presence: Subscribed to
2015-07-22 15:03:26 jabber_lib.process: 180

The logs between the "jabber_lib.process: 180" lines repeat every few seconds forever.

In my conclusion the offline systems fail to get a proper roster subscription with osa-dispatcher and therefore osa-dispatcher regards them as offline. And then osa-dispatcher doesn't even try to send ping requests or notify the system to run rhn_check.

My workaround is:
1. stop osa-dispatcher
2. stop jabberd
3. delete everything in /var/lib/jabberd/db
4. start jabberd
5. wait for all osad to reconnect to jabberd
6. start osa-dispatcher
7. All systems are online again (according to table rhnPushClient)

Comment 2 Mihai Petracovici 2016-01-25 15:24:42 UTC
I am seeing in this Spacewalk 2.4 as well and can confirm that the workaround above works. 

Disabling the roster module in jabberd (commenting it out in /etc/jabberd/sm.xml) also prevents this issue from appearing and I could still ping and schedule actions.

Comment 3 Thomas Mueller 2016-02-26 09:56:33 UTC
Deleting /var/lib/jabberd/db will cause you troubles when spacewalk-proxies are connected. 

By deleting /var/lib/jabberd/db you loose all subscriptions of clients connected to spacewalk-proxy. They won't notice the problem until the osad service is restarted on the affected clients.

Comment 4 bernhard.lichtinger 2016-02-26 10:31:47 UTC
This already merged pull request might resolve the problem:
https://github.com/spacewalkproject/spacewalk/pull/287

Comment 5 Gennadii Altukhov 2016-03-01 17:03:35 UTC
Taking...

Comment 6 Gennadii Altukhov 2016-03-02 14:58:27 UTC
Looks like it works well now. I cannot reproduce the bug after upgrade from SW 2.2 to 2.3. OSAD status is online, can execute remote commands.

My steps:
1) Install SW 2.2
2) Register client, try to execute remote command. Result - OK
3) Upgrade SW from 2.2 to 2.3 ttps://fedorahosted.org/spacewalk/wiki/HowToUpgrade
4) Status for osad of registered client is online, can execute remote command as well.

Comment 7 Tomas Lestach 2016-05-09 12:33:50 UTC
No information provided for 2 months. The scenario as described works for us. I am closing this BZ with INSUFFICIENT_DATA.

Comment 8 Eric Herget 2017-09-28 18:05:59 UTC
This BZ closed some time during 2.5, 2.6 or 2.7.  Adding to 2.7 tracking bug.

Comment 9 Red Hat Bugzilla 2023-09-14 02:59:20 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days


Note You need to log in before you can comment on or make changes to this bug.