[Spacewalk-list] OSAD Communication Issue (Was: Provisioning Virtual Machines (KVM/Centos Fails))
Nicolas Antonio Corrarello
ncorrare at gmail.com
Mon Nov 22 20:59:01 UTC 2010
I think I found that the issue, might be related to osad. Apparently,
Spacewalk is not able to ping the client. I collected the
osa-dispatcher and osad logs
<OSA-DISPATCHER LOGS>
RHN 22396 2010/11/22 14:42:28 -05:00: ('Error caught:',)
RHN 22396 2010/11/22 14:42:28 -05:00: ('Traceback (most recent call
last):\n File "/usr/share/rhn/osad/jabber_lib.py", line 120, in
main\n c = self.setup_connection(no_fork=no_fork)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection\n
resource=self._resource)\n File
"/usr/share/rhn/osad/dispatcher_client.py", line 33, in start\n
self.auth(username, password, resource)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 886, in auth\n
self.SendAndWaitForResponse(auth_set_iq)\n File
"/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401, in
SendAndWaitForResponse\n return self.waitForResponse(ID,timeout)\n
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in
waitForResponse\n raise TimeoutError()\nTimeoutError\n',)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(0.043658971786499023,)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
0.043657064437866211)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.get_one_stanza('timed out', 1290458548.558686,
1290458248.5576761, 299.99998092651367)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('after get_one_stanza',)
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('ERROR', 'Error caught:')
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('ERROR', 'Traceback (most recent call last):\n
File "/usr/share/rhn/osad/jabber_lib.py", line 120, in main\n c =
self.setup_connection(no_fork=no_fork)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection\n
resource=self._resource)\n File
"/usr/share/rhn/osad/dispatcher_client.py", line 33, in start\n
self.auth(username, password, resource)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 886, in auth\n
self.SendAndWaitForResponse(auth_set_iq)\n File
"/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401, in
SendAndWaitForResponse\n return self.waitForResponse(ID,timeout)\n
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in
waitForResponse\n raise TimeoutError()\nTimeoutError\n')
2010/11/22 14:42:28 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('Sleeping', 10, 'seconds')
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
<-- <features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>
<-- <proceed />
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
<-- <features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><mechanisms xmlns =
'urn:ietf:params:xml:ns:xmpp-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>
--> <iq type='get' id='auth-get-a25eff-2'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username></query></iq>
<-- <iq type='result' id='auth-get-a25eff-2'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username><resource
/><password /><digest /></query></iq>
--> <iq type='set' id='auth-set-a25eff-3'><query xmlns =
'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource>superclient</resource><digest>f79fa02c1b01ff9756c017146d4b483ebb2861b7</digest></query></iq>
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.check_cert('Loading cert', <X509Name object
'/C=US/ST=IL/L=Chicago/O=Orbitz/OU=wmspacewalk01p.prod.orbitz.net/CN=wmspacewalk01p.prod.orbitz.net'>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
rhnSQL/driver_cx_Oracle._execute_wrapper('Executing SQL: "select 1
from dual" with bind params: {}',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.setup_connection('Connecting to',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib._get_jabber_client
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._get_jabber_client('Connecting to',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.__init__
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.__init__
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.check_cert('Loading cert', <X509Name object
'/C=US/ST=IL/L=Chicago/O=Orbitz/OU=wmspacewalk01p.prod.orbitz.net/CN=wmspacewalk01p.prod.orbitz.net'>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.connect
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Attempting to connect',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.process(300,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
299.99999809265137)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fa5f0>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.connect('Connected',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Expecting features stanza, got:',
<features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('starttls node', <jabber.xmlstream.Node
instance at 0x2b3b1f4fa8c0>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4faa70>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Expecting proceed stanza, got:', <proceed />)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Preparing for TLS handshake',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 264 bytes',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 422 bytes',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fae60>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('connect returning',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.setup_connection('Connected to jabber server',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/dispatcher_client.start
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('rhn-dispatcher-sat', 'rhn-dispatcher-m66818',
'superclient', 1)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('Sending auth request', <iq type='get'
id='auth-get-a25eff-2'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username></query></iq>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('auth-get-a25eff-2', 60)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('before get_one_stanza',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(59.999976873397827,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
59.999974727630615)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 176 bytes',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._orig_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fb5f0>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.dispatch(<iq
type='result' id='auth-get-a25eff-2'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.cleanup_expired_callbacks
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._get_callbacks(<iq type='result'
id='auth-get-a25eff-2'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.dispatch('Unhandled stanza', <iq type='result'
id='auth-get-a25eff-2'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('after get_one_stanza',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0: osad/jabber_lib.auth('Auth
response', <iq type='result' id='auth-get-a25eff-2'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username><resource
/><password /><digest /></query></iq>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('Sending auth info', <iq type='set'
id='auth-set-a25eff-3'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource>superclient</resource><digest>f79fa02c1b01ff9756c017146d4b483ebb2861b7</digest></query></iq>)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse(u'auth-set-a25eff-3', 300)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('before get_one_stanza',)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(299.99998092651367,)
2010/11/22 14:42:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
299.99997901916504)
RHN 22396 2010/11/22 14:47:38 -05:00: ('Error caught:',)
RHN 22396 2010/11/22 14:47:38 -05:00: ('Traceback (most recent call
last):\n File "/usr/share/rhn/osad/jabber_lib.py", line 120, in
main\n c = self.setup_connection(no_fork=no_fork)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection\n
resource=self._resource)\n File
"/usr/share/rhn/osad/dispatcher_client.py", line 33, in start\n
self.auth(username, password, resource)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 886, in auth\n
self.SendAndWaitForResponse(auth_set_iq)\n File
"/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401, in
SendAndWaitForResponse\n return self.waitForResponse(ID,timeout)\n
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in
waitForResponse\n raise TimeoutError()\nTimeoutError\n',)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(0.044722795486450195,)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
0.044721841812133789)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.get_one_stanza('timed out', 1290458858.6312251,
1290458558.6303151, 299.99998378753662)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('after get_one_stanza',)
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('ERROR', 'Error caught:')
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('ERROR', 'Traceback (most recent call last):\n
File "/usr/share/rhn/osad/jabber_lib.py", line 120, in main\n c =
self.setup_connection(no_fork=no_fork)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection\n
resource=self._resource)\n File
"/usr/share/rhn/osad/dispatcher_client.py", line 33, in start\n
self.auth(username, password, resource)\n File
"/usr/share/rhn/osad/jabber_lib.py", line 886, in auth\n
self.SendAndWaitForResponse(auth_set_iq)\n File
"/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401, in
SendAndWaitForResponse\n return self.waitForResponse(ID,timeout)\n
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in
waitForResponse\n raise TimeoutError()\nTimeoutError\n')
2010/11/22 14:47:38 -05:00 22396 0.0.0.0:
osad/jabber_lib.main('Sleeping', 10, 'seconds')
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
<-- <features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>
<-- <proceed />
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
<-- <features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><mechanisms xmlns =
'urn:ietf:params:xml:ns:xmpp-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>
--> <iq type='get' id='auth-get-5d0f40-4'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username></query></iq>
<-- <iq type='result' id='auth-get-5d0f40-4'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username><resource
/><password /><digest /></query></iq>
--> <iq type='set' id='auth-set-5d0f40-5'><query xmlns =
'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource>superclient</resource><digest>14f77d708dd3336e6296952a193ed21b2361878d</digest></query></iq>
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.check_cert('Loading cert', <X509Name object
'/C=US/ST=IL/L=Chicago/O=Orbitz/OU=wmspacewalk01p.prod.orbitz.net/CN=wmspacewalk01p.prod.orbitz.net'>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
rhnSQL/driver_cx_Oracle._execute_wrapper('Executing SQL: "select 1
from dual" with bind params: {}',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.setup_connection('Connecting to',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib._get_jabber_client
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._get_jabber_client('Connecting to',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.__init__
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.__init__
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.check_cert('Loading cert', <X509Name object
'/C=US/ST=IL/L=Chicago/O=Orbitz/OU=wmspacewalk01p.prod.orbitz.net/CN=wmspacewalk01p.prod.orbitz.net'>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.connect
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Attempting to connect',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.process(300,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
299.99999904632568)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fd560>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.connect('Connected',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Expecting features stanza, got:',
<features><address xmlns = 'http://affinix.com/jabber/address'
>10.50.174.31</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('starttls node', <jabber.xmlstream.Node
instance at 0x2b3b1f4fd830>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fd9e0>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Expecting proceed stanza, got:', <proceed />)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('Preparing for TLS handshake',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 264 bytes',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.process(None,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout', None)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 422 bytes',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._auth_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4fddd0>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.connect('connect returning',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.setup_connection('Connected to jabber server',
'wmspacewalk01p.prod.orbitz.net')
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/dispatcher_client.start
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('rhn-dispatcher-sat', 'rhn-dispatcher-m66818',
'superclient', 1)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('Sending auth request', <iq type='get'
id='auth-get-5d0f40-4'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username></query></iq>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('auth-get-5d0f40-4', 60)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('before get_one_stanza',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(59.999979734420776,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
59.999977827072144)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('select() returned',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Reading 1024 bytes from ssl socket',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('Read 176 bytes',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._orig_dispatch(<jabber.xmlstream.Node instance at
0x2b3b1f4ff560>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.dispatch(<iq
type='result' id='auth-get-5d0f40-4'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.cleanup_expired_callbacks
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._get_callbacks(<iq type='result'
id='auth-get-5d0f40-4'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.dispatch('Unhandled stanza', <iq type='result'
id='auth-get-5d0f40-4'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource /><password
/><digest /></query></iq>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('after get_one_stanza',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0: osad/jabber_lib.auth('Auth
response', <iq type='result' id='auth-get-5d0f40-4'><query xmlns =
'jabber:iq:auth' ><username>rhn-dispatcher-sat</username><resource
/><password /><digest /></query></iq>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.auth('Sending auth info', <iq type='set'
id='auth-set-5d0f40-5'><query xmlns = 'jabber:iq:auth'
><username>rhn-dispatcher-sat</username><resource>superclient</resource><digest>14f77d708dd3336e6296952a193ed21b2361878d</digest></query></iq>)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse(u'auth-set-5d0f40-5', 300)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib._waitForResponse('before get_one_stanza',)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process(299.99997925758362,)
2010/11/22 14:47:48 -05:00 22396 0.0.0.0:
osad/jabber_lib.process('before select(); timeout',
299.99997711181641)
<OSAD LOGS>
2010-11-22 14:42:28 jabber_lib.process: select() returned
2010-11-22 14:42:28 jabber_lib.get_one_stanza: timed out 1290458548.63
1290458248.63 299.999988794
2010-11-22 14:42:28 jabber_lib._waitForResponse: after get_one_stanza
Error caught:
Traceback (most recent call last):
File "/usr/share/rhn/osad/jabber_lib.py", line 120, in main
c = self.setup_connection(no_fork=no_fork)
File "/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection
resource=self._resource)
File "/usr/share/rhn/osad/osad_client.py", line 47, in start
self.auth(username, password, resource)
File "/usr/share/rhn/osad/jabber_lib.py", line 886, in auth
self.SendAndWaitForResponse(auth_set_iq)
File "/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401,
in SendAndWaitForResponse
return self.waitForResponse(ID,timeout)
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in waitForResponse
raise TimeoutError()
TimeoutError
2010-11-22 14:42:28 jabber_lib.main: Sleeping 111 seconds
2010-11-22 14:44:19 osad.setup_config: Skipping config setup;
counter=1; interval=71
2010-11-22 14:44:19 jabber_lib.setup_connection: Connecting to
wmspacewalk01p.prod.orbitz.net
2010-11-22 14:44:19 jabber_lib._get_jabber_client:
2010-11-22 14:44:19 jabber_lib._get_jabber_client: Connecting to
wmspacewalk01p.prod.orbitz.net
2010-11-22 14:44:19 jabber_lib.__init__:
2010-11-22 14:44:19 jabber_lib.__init__:
2010-11-22 14:44:19 jabber_lib.check_cert: Loading cert <X509Name
object '/C=US/ST=IL/L=Chicago/O=Orbitz/OU=wmspacewalk01p.prod.orbitz.net/CN=wmspacewalk01p.prod.orbitz.net'>
2010-11-22 14:44:19 jabber_lib.connect:
2010-11-22 14:44:19 jabber_lib.connect: Attempting to connect
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
2010-11-22 14:44:19 jabber_lib.process: 300
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout 300.0
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout 299.998706102
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib._auth_dispatch: <features><address
xmlns = 'http://affinix.com/jabber/address'
>10.229.126.44</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>
<-- <features><address xmlns = 'http://affinix.com/jabber/address'
>10.229.126.44</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>
2010-11-22 14:44:19 jabber_lib.connect: Connected
2010-11-22 14:44:19 jabber_lib.connect: Expecting features stanza,
got: <features><address xmlns = 'http://affinix.com/jabber/address'
>10.229.126.44</address><auth xmlns =
'http://jabber.org/features/iq-auth' /><register xmlns =
'http://jabber.org/features/iq-register' /><starttls xmlns =
'urn:ietf:params:xml:ns:xmpp-tls' ><required /></starttls></features>
2010-11-22 14:44:19 jabber_lib.connect: starttls node
<starttls><required /></starttls>
2010-11-22 14:44:19 jabber_lib.process: None
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout None
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib._auth_dispatch: <proceed />
<-- <proceed />
2010-11-22 14:44:19 jabber_lib.connect: Expecting proceed stanza, got:
<proceed />
2010-11-22 14:44:19 jabber_lib.connect: Preparing for TLS handshake
--> <?xml version='1.0' encoding='UTF-8'?><stream:stream
to='wmspacewalk01p.prod.orbitz.net' xmlns='jabber:client'
xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
2010-11-22 14:44:19 jabber_lib.process: None
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout None
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib.process: Reading 1024 bytes from ssl socket
2010-11-22 14:44:19 jabber_lib.process: Read 264 bytes
2010-11-22 14:44:19 jabber_lib.process: None
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout None
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib.process: Reading 1024 bytes from ssl socket
2010-11-22 14:44:19 jabber_lib.process: Read 423 bytes
2010-11-22 14:44:19 jabber_lib._auth_dispatch: <features><address
xmlns = 'http://affinix.com/jabber/address'
>10.229.126.44</address><mechanisms xmlns =
'urn:ietf:params:xml:ns:xmpp-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'
>10.229.126.44</address><mechanisms xmlns =
'urn:ietf:params:xml:ns:xmpp-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>
2010-11-22 14:44:19 jabber_lib.connect: connect returning
2010-11-22 14:44:19 jabber_lib.setup_connection: Connected to jabber
server wmspacewalk01p.prod.orbitz.net
2010-11-22 14:44:19 osad_client.start: osad-7b6e446344 24a95c79c601dd4cfb03 osad
2010-11-22 14:44:19 jabber_lib.auth: osad-7b6e446344 24a95c79c601dd4cfb03 osad 1
--> <iq type='get' id='auth-get-363dac-2'><query xmlns =
'jabber:iq:auth' ><username>osad-7b6e446344</username></query></iq>
2010-11-22 14:44:19 jabber_lib.auth: Sending auth request <iq
type='get' id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username></query></iq>
2010-11-22 14:44:19 jabber_lib._waitForResponse: auth-get-363dac-2 60
2010-11-22 14:44:19 jabber_lib._waitForResponse: before get_one_stanza
2010-11-22 14:44:19 jabber_lib.process: 59.9999890327
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout 59.9999890327
2010-11-22 14:44:19 jabber_lib.process: select() returned
2010-11-22 14:44:19 jabber_lib.process: Reading 1024 bytes from ssl socket
2010-11-22 14:44:19 jabber_lib.process: Read 173 bytes
2010-11-22 14:44:19 jabber_lib._orig_dispatch: <iq type='result'
id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource /><password /><digest
/></query></iq>
<-- <iq type='result' id='auth-get-363dac-2'><query xmlns =
'jabber:iq:auth' ><username>osad-7b6e446344</username><resource
/><password /><digest /></query></iq>
2010-11-22 14:44:19 jabber_lib.dispatch: <iq type='result'
id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource /><password /><digest
/></query></iq>
2010-11-22 14:44:19 jabber_lib.cleanup_expired_callbacks:
2010-11-22 14:44:19 jabber_lib._get_callbacks: <iq type='result'
id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource /><password /><digest
/></query></iq>
2010-11-22 14:44:19 jabber_lib.dispatch: Unhandled stanza <iq
type='result' id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource /><password /><digest
/></query></iq>
2010-11-22 14:44:19 jabber_lib._waitForResponse: after get_one_stanza
2010-11-22 14:44:19 jabber_lib.auth: Auth response <iq type='result'
id='auth-get-363dac-2'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource /><password /><digest
/></query></iq>
2010-11-22 14:44:19 jabber_lib.auth: Sending auth info <iq type='set'
id='auth-set-363dac-3'><query xmlns = 'jabber:iq:auth'
><username>osad-7b6e446344</username><resource>osad</resource><digest>5bb1a564fd55b2d9741899893119375f8daf32d7</digest></query></iq>
--> <iq type='set' id='auth-set-363dac-3'><query xmlns =
'jabber:iq:auth'
><username>osad-7b6e446344</username><resource>osad</resource><digest>5bb1a564fd55b2d9741899893119375f8daf32d7</digest></query></iq>
2010-11-22 14:44:19 jabber_lib._waitForResponse: auth-set-363dac-3 300
2010-11-22 14:44:19 jabber_lib._waitForResponse: before get_one_stanza
2010-11-22 14:44:19 jabber_lib.process: 299.999986887
2010-11-22 14:44:19 jabber_lib.process: before select(); timeout 299.999985933
2010-11-22 14:49:19 jabber_lib.process: select() returned
2010-11-22 14:49:19 jabber_lib.get_one_stanza: timed out 1290458959.7
1290458659.7 299.999987841
2010-11-22 14:49:19 jabber_lib._waitForResponse: after get_one_stanza
Error caught:
Traceback (most recent call last):
File "/usr/share/rhn/osad/jabber_lib.py", line 120, in main
c = self.setup_connection(no_fork=no_fork)
File "/usr/share/rhn/osad/jabber_lib.py", line 288, in setup_connection
resource=self._resource)
File "/usr/share/rhn/osad/osad_client.py", line 47, in start
self.auth(username, password, resource)
File "/usr/share/rhn/osad/jabber_lib.py", line 886, in auth
self.SendAndWaitForResponse(auth_set_iq)
File "/usr/lib/python2.4/site-packages/jabber/jabber.py", line 401,
in SendAndWaitForResponse
return self.waitForResponse(ID,timeout)
File "/usr/share/rhn/osad/jabber_lib.py", line 1154, in waitForResponse
raise TimeoutError()
TimeoutError
2010-11-22 14:49:19 jabber_lib.main: Sleeping 116 seconds
2010/11/15 Nicolas Antonio Corrarello <ncorrare at gmail.com>:
> Hi guys,
> I've been running into this issue. Apparently, every time I try to
> provision a VM, it fails with:
> Client execution returned "Fatal error in Python code occured [[6]]" (code -1).
>
> I've checked the rhn_check -vvvvvvvv output, but I've found nothing.
> Can you help me to troubleshoot this issue?
>
More information about the Spacewalk-list
mailing list