logs for a subscribe-subscribed interaction

gistfile1.txt

DEBUG:asyncio:Using selector: KqueueSelector
DEBUG:aioxmpp.callbacks:connecting <bound method SimpleMessageDispatcher._feed of <aioxmpp.dispatcher.SimpleMessageDispatcher object at 0x10e564278>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method SimplePresenceDispatcher._feed of <aioxmpp.dispatcher.SimplePresenceDispatcher object at 0x10e564358>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceServer._before_stream_established of <aioxmpp.presence.service.PresenceServer object at 0x10e564470>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManagedClient._update_presence of <aioxmpp.node.PresenceManagedClient object at 0x10df4e2e8>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent1.on_stream_established:connecting <bound method PresenceManagedClient._handle_stream_established of <aioxmpp.node.PresenceManagedClient object at 0x10df4e2e8>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent1.on_stream_established:connecting <Future pending created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/node.py:1378> with mode <bound method AdHocSignal.AUTO_FUTURE of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent1.on_failure:connecting <Future pending created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/node.py:1378> with mode <bound method AdHocSignal.AUTO_FUTURE of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method Client._stream_failure of <aioxmpp.node.PresenceManagedClient object at 0x10df4e2e8>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method Client._stream_destroyed of <aioxmpp.node.PresenceManagedClient object at 0x10df4e2e8>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:asyncio:poll took 5.273 ms: 1 events
DEBUG:asyncio:poll took 1.740 ms: 1 events
DEBUG:agent1:no SRV records found for localhost, falling back
DEBUG:agent1:domain localhost: trying to connect to 'localhost':5222 using <aioxmpp.connector.STARTTLSConnector object at 0x10dbc7e10>
DEBUG:asyncio:Get address info localhost:5222, type=<SocketKind.SOCK_STREAM: 1>
DEBUG:asyncio:Getting address info localhost:5222, type=<SocketKind.SOCK_STREAM: 1> took 1.751 ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('158.42.184.105', 5222))]
DEBUG:asyncio:poll took 0.836 ms: 1 events
DEBUG:asyncio:poll took 2.172 ms: 1 events
DEBUG:agent1.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.453 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='9e38e3df-c99d-499c-b760-f5dc2ed6b81c' xml:lang='en' xmlns='jabber:client'><stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><register xmlns='http://jabber.org/features/iq-register'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>"
DEBUG:agent1.XMLStream:SENT b'<starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>'
DEBUG:asyncio:poll took 0.010 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.124 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>"
DEBUG:aioopenssl.trace.fd=7:_initiate_tls called
DEBUG:aioopenssl.trace.fd=7:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=7:registering reader for _tls_do_handshake
DEBUG:asyncio:poll took 2.632 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=7:registering reader for _tls_do_handshake
DEBUG:asyncio:poll took 1.591 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=7:clearing readers/writers
DEBUG:aioopenssl.trace.fd=7:handshake complete
DEBUG:aioopenssl.trace.fd=7:post handshake scheduled via callback
DEBUG:aioopenssl.trace.fd=7:_tls_post_handshake called
DEBUG:aioopenssl.trace.fd=7:_waiter future done (<Future finished result=None created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioopenssl/__init__.py:632>)
DEBUG:agent1.XMLStream:SENT b''
DEBUG:agent1.XMLStream:SENT b''
DEBUG:agent1.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:asyncio:poll 59999.819 ms took 0.026 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 59999.579 ms took 1.133 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='4809fc40-9218-4bbf-914e-84f6dc7b8f77' xml:lang='en' xmlns='jabber:client'><stream:features><register xmlns='http://jabber.org/features/iq-register'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features>"
DEBUG:agent1:domain localhost: connection succeeded using <aioxmpp.connector.STARTTLSConnector object at 0x10dbc7e10>
INFO:aiosasl:attempting SCRAM-SHA-1 mechanism (using sha1 hashfun)
DEBUG:agent1.XMLStream:SENT b'<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1">biwsbj1hZ2VudDEscj1ZbWVCdzZSL21NQm5BSDNYSS9aMg==</auth>'
DEBUG:asyncio:poll took 0.009 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.157 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1ZbWVCdzZSL21NQm5BSDNYSS9aMjNlZjZlYTMxLTYxMDQtNGIyMS1iZDQ3LTNiMzA0YWY2ZWQxMixzPU5tTTFaV0V5WlRrdFpUUTRNeTAwTjJNeExXSmxaV1V0TnpJeU56RmlZbVZpWVRFMixpPTQwOTY=</challenge>"
DEBUG:aiosasl:pbkdf2 timing: 0.003183 seconds
DEBUG:aiosasl:response generation time: 0.003415 seconds
DEBUG:agent1.XMLStream:SENT b'<response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1iaXdzLHI9WW1lQnc2Ui9tTUJuQUgzWEkvWjIzZWY2ZWEzMS02MTA0LTRiMjEtYmQ0Ny0zYjMwNGFmNmVkMTIscD1iSURZelAvZW1saVZVMHM5L2FVbURPaU13a1U9</response>'
DEBUG:asyncio:poll took 0.009 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.074 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1aVXVpNm5rRU93RUtTSi9VcWhuYmJqM3E5UWs9</success>"
DEBUG:agent1.XMLStream:SENT b''
DEBUG:agent1.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:asyncio:poll 59999.823 ms took 0.010 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 59999.603 ms took 1.137 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='bbd605ea-bab5-40db-99fd-b1db56f10935' xml:lang='en' xmlns='jabber:client'><stream:features><c hash='sha-1' ver='ZBWApSGFMsTZkuVThHtyU5xv1Mk=' node='http://prosody.im' xmlns='http://jabber.org/protocol/caps'/><ver xmlns='urn:xmpp:features:rosterver'/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><required/></bind><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session></stream:features>"
DEBUG:agent1:negotiating stream (server_can_do_sm=False)
DEBUG:aioxmpp.callbacks:connecting <bound method StanzaStream._xmlstream_failed of <aioxmpp.stream.StanzaStream object at 0x10ea25f28>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent1.StanzaStream:broker task started as <Task pending coro=<StanzaStream._run() running at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/stream.py:1805> cb=[StanzaStream._done_handler()] created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/asyncio/tasks.py:499>
DEBUG:agent1:binding to resource
DEBUG:agent1.StanzaStream:sending <iq from=None to=None id='xtuU/3tWHiXQGwWwqwwdR' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e22c208>> and waiting for it to be sent
DEBUG:agent1.StanzaStream:iq response future registered: from=None, id='xtuU/3tWHiXQGwWwqwwdR'
DEBUG:agent1.StanzaStream:enqueued stanza <iq from=None to=None id='xtuU/3tWHiXQGwWwqwwdR' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e22c208>> with token <StanzaToken id=0x000000010e2ce098>
DEBUG:agent1.StanzaStream:forwarding stanza to xmlstream: <iq from=None to=None id='xtuU/3tWHiXQGwWwqwwdR' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e22c208>>
DEBUG:agent1.XMLStream:SENT b'<iq id="xtuU/3tWHiXQGwWwqwwdR" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/></iq>'
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 14995.108 ms took 1.179 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<iq id='xtuU/3tWHiXQGwWwqwwdR' type='result'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b</jid></bind></iq>"
DEBUG:agent1.StanzaStream:incoming iq: <iq from=None to=None id='xtuU/3tWHiXQGwWwqwwdR' type=<IQType.RESULT: 'result'> data=<aioxmpp.rfc6120.Bind object at 0x10e22cc18>>
DEBUG:agent1.StanzaStream:iq is response
DEBUG:agent1.StanzaStream:iq response delivered to key (None, 'xtuU/3tWHiXQGwWwqwwdR')
INFO:agent1:bound to jid: agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b
DEBUG:agent1:remote server announces support for legacy sessions
DEBUG:agent1.StanzaStream:sending <iq from=None to=None id='xZyjyHdBknnXcSAWY+3jk' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e1676d8>> and waiting for it to be sent
DEBUG:agent1.StanzaStream:iq response future registered: from=None, id='xZyjyHdBknnXcSAWY+3jk'
DEBUG:agent1.StanzaStream:enqueued stanza <iq from=None to=None id='xZyjyHdBknnXcSAWY+3jk' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e1676d8>> with token <StanzaToken id=0x000000010e2d2728>
DEBUG:agent1.StanzaStream:forwarding stanza to xmlstream: <iq from=None to=None id='xZyjyHdBknnXcSAWY+3jk' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e1676d8>>
DEBUG:agent1.XMLStream:SENT b'<iq id="xZyjyHdBknnXcSAWY+3jk" type="set"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq>'
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 14988.169 ms took 0.900 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<iq id='xZyjyHdBknnXcSAWY+3jk' type='result' to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b'/>"
DEBUG:agent1.StanzaStream:incoming iq: <iq from=None to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' id='xZyjyHdBknnXcSAWY+3jk' type=<IQType.RESULT: 'result'>>
DEBUG:agent1.StanzaStream:iq is response
DEBUG:agent1.StanzaStream:iq response delivered to key (None, 'xZyjyHdBknnXcSAWY+3jk')
DEBUG:agent1:legacy session negotiated (upgrade your server!)
DEBUG:agent1.StanzaStream:sending <presence from=None to=None id='xC5aq3ygS9E68G5woHjFN' type=<PresenceType.AVAILABLE: None>> and waiting for it to be sent
DEBUG:agent1.StanzaStream:enqueued stanza <presence from=None to=None id='xC5aq3ygS9E68G5woHjFN' type=<PresenceType.AVAILABLE: None>> with token <StanzaToken id=0x000000010e2617c8>
DEBUG:agent1.StanzaStream:forwarding stanza to xmlstream: <presence from=None to=None id='xC5aq3ygS9E68G5woHjFN' type=<PresenceType.AVAILABLE: None>>
DEBUG:agent1.XMLStream:SENT b'<presence id="xC5aq3ygS9E68G5woHjFN"/>'
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:agent1.StanzaStream:iq request coroutine registered: type=<IQType.SET: 'set'>, payload=<class 'aioxmpp.roster.xso.Query'>
DEBUG:aioxmpp.callbacks:connecting <bound method RosterClient._request_initial_roster of <aioxmpp.roster.service.RosterClient object at 0x10cc74a58>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_subscribe of <spade.presence.PresenceManager object at 0x10e167f98>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_subscribed of <spade.presence.PresenceManager object at 0x10e167f98>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_unsubscribe of <spade.presence.PresenceManager object at 0x10e167f98>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_unsubscribed of <spade.presence.PresenceManager object at 0x10e167f98>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:asyncio:poll 14981.055 ms took 0.703 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<presence id='xC5aq3ygS9E68G5woHjFN' from='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b'/><presence to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' from='agent1@localhost/bb2623e4-b7a7-45f7-9bda-ae2f46b6c435'><status/><x xmlns='vcard-temp:x:update'><photo>4a4d229aa03967b73af6fde0f0f6afc3123fff2f</photo></x><c hash='sha-1' ver='3ScHZH4hKmksks0e7RG8B4cjaT8=' node='http://swift.im' xmlns='http://jabber.org/protocol/caps'/><delay from='localhost' stamp='2017-11-02T17:34:49Z' xmlns='urn:xmpp:delay'/></presence><presence to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' from='agent1@localhost/Mac-Pro-de-Javi'><c hash='sha-1' ver='DdnydQG7RGhP9E3k9Sf+b+bF0zo=' node='http://pidgin.im/' xmlns='http://jabber.org/protocol/caps'/><x xmlns='vcard-temp:x:update'><photo>4a4d229aa03967b73af6fde0f0f6afc3123fff2f</photo></x><delay from='localhost' stamp='2017-11-02T16:22:29Z' xmlns='urn:xmpp:delay'/></presence>"
DEBUG:asyncio:Using selector: KqueueSelector
DEBUG:aioxmpp.callbacks:connecting <bound method SimpleMessageDispatcher._feed of <aioxmpp.dispatcher.SimpleMessageDispatcher object at 0x10e32d0b8>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method SimplePresenceDispatcher._feed of <aioxmpp.dispatcher.SimplePresenceDispatcher object at 0x10e32d1d0>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceServer._before_stream_established of <aioxmpp.presence.service.PresenceServer object at 0x10e32d358>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManagedClient._update_presence of <aioxmpp.node.PresenceManagedClient object at 0x10e2d4a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent2.on_stream_established:connecting <bound method PresenceManagedClient._handle_stream_established of <aioxmpp.node.PresenceManagedClient object at 0x10e2d4a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent2.on_stream_established:connecting <Future pending created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/node.py:1378> with mode <bound method AdHocSignal.AUTO_FUTURE of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent2.on_failure:connecting <Future pending created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/node.py:1378> with mode <bound method AdHocSignal.AUTO_FUTURE of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method Client._stream_failure of <aioxmpp.node.PresenceManagedClient object at 0x10e2d4a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method Client._stream_destroyed of <aioxmpp.node.PresenceManagedClient object at 0x10e2d4a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:asyncio:poll took 2.546 ms: 1 events
DEBUG:agent1.StanzaStream:enqueued stanza <presence from=None to='agent2@localhost' id='xev5ARZb9BmSrkZS/F/5i' type=<PresenceType.SUBSCRIBE: 'subscribe'>> with token <StanzaToken id=0x000000010e333048>
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' to=None id='xC5aq3ygS9E68G5woHjFN' type=<PresenceType.AVAILABLE: None>>
DEBUG:asyncio:poll took 1.472 ms: 1 events
DEBUG:agent1.StanzaStream:forwarding stanza to xmlstream: <presence from=None to='agent2@localhost' id='xev5ARZb9BmSrkZS/F/5i' type=<PresenceType.SUBSCRIBE: 'subscribe'>>
DEBUG:agent2:no SRV records found for localhost, falling back
DEBUG:agent2:domain localhost: trying to connect to 'localhost':5222 using <aioxmpp.connector.STARTTLSConnector object at 0x10e32de48>
DEBUG:agent1.XMLStream:SENT b'<presence to="agent2@localhost" id="xev5ARZb9BmSrkZS/F/5i" type="subscribe"/>'
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent1@localhost/bb2623e4-b7a7-45f7-9bda-ae2f46b6c435' to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' id=None type=<PresenceType.AVAILABLE: None>>
DEBUG:asyncio:Get address info localhost:5222, type=<SocketKind.SOCK_STREAM: 1>
DEBUG:asyncio:Getting address info localhost:5222, type=<SocketKind.SOCK_STREAM: 1> took 0.919 ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('158.42.184.105', 5222))]
DEBUG:asyncio:poll took 0.295 ms: 1 events
DEBUG:aioopenssl.trace.fd=7:_write_ready: nothing more to write, removing writer
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent1@localhost/Mac-Pro-de-Javi' to='agent1@localhost/09607050-edb9-4b86-9672-341cff55b26b' id=None type=<PresenceType.AVAILABLE: None>>
DEBUG:asyncio:poll 14958.866 ms took 0.815 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<presence type='unavailable' to='agent1@localhost' from='agent2@localhost'/>"
DEBUG:asyncio:poll took 1.808 ms: 1 events
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent2@localhost' to='agent1@localhost' id=None type=<PresenceType.UNAVAILABLE: 'unavailable'>>
DEBUG:agent2.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.248 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='0fb2c84d-fbdb-4582-bdd1-0fadea7761bf' xml:lang='en' xmlns='jabber:client'><stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><register xmlns='http://jabber.org/features/iq-register'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-1</mechanism></mechanisms></stream:features>"
DEBUG:agent2.XMLStream:SENT b'<starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>'
DEBUG:asyncio:poll took 0.009 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 0.927 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>"
DEBUG:aioopenssl.trace.fd=13:_initiate_tls called
DEBUG:aioopenssl.trace.fd=13:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=13:registering reader for _tls_do_handshake
DEBUG:asyncio:poll took 2.668 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=13:registering reader for _tls_do_handshake
DEBUG:asyncio:poll took 1.332 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_tls_do_handshake called
DEBUG:aioopenssl.trace.fd=13:clearing readers/writers
DEBUG:aioopenssl.trace.fd=13:handshake complete
DEBUG:aioopenssl.trace.fd=13:post handshake scheduled via callback
DEBUG:aioopenssl.trace.fd=13:_tls_post_handshake called
DEBUG:aioopenssl.trace.fd=13:_waiter future done (<Future finished result=None created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioopenssl/__init__.py:632>)
DEBUG:agent2.XMLStream:SENT b''
DEBUG:agent2.XMLStream:SENT b''
DEBUG:agent2.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:asyncio:poll 59999.808 ms took 0.010 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 59999.595 ms took 1.159 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='0c629c07-14a5-4c6e-929a-c930d426f372' xml:lang='en' xmlns='jabber:client'><stream:features><register xmlns='http://jabber.org/features/iq-register'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism></mechanisms></stream:features>"
DEBUG:agent2:domain localhost: connection succeeded using <aioxmpp.connector.STARTTLSConnector object at 0x10e32de48>
INFO:aiosasl:attempting SCRAM-SHA-1 mechanism (using sha1 hashfun)
DEBUG:agent2.XMLStream:SENT b'<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1">biwsbj1hZ2VudDIscj1qU1RVU08xU1RBQ05nNDVUYk9aaw==</auth>'
DEBUG:asyncio:poll took 0.009 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 0.997 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1qU1RVU08xU1RBQ05nNDVUYk9aazUxYjI3M2U0LTI2N2MtNDQ4ZS04YmZiLWE3M2FmYzU5YTBhMSxzPVltVmhNVGhpTXpFdE1EbGlPQzAwT0RnMkxUbGlZamd0T1dRd016aGxOV0U1WkRsayxpPTQwOTY=</challenge>"
DEBUG:aiosasl:pbkdf2 timing: 0.003001 seconds
DEBUG:aiosasl:response generation time: 0.003111 seconds
DEBUG:agent2.XMLStream:SENT b'<response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1iaXdzLHI9alNUVVNPMVNUQUNOZzQ1VGJPWms1MWIyNzNlNC0yNjdjLTQ0OGUtOGJmYi1hNzNhZmM1OWEwYTEscD0yZU5TbXhBWEJBK3JYWjN1ZHBYamVRSEFRdGM9</response>'
DEBUG:asyncio:poll took 0.009 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll took 1.134 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1LMHhQb2xycy90bDdxMXUxMjM2WGJUbmNha3M9</success>"
DEBUG:agent2.XMLStream:SENT b''
DEBUG:agent2.XMLStream:SENT b'<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" version="1.0">'
DEBUG:asyncio:poll 59999.815 ms took 0.022 ms: 1 events
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 59999.591 ms took 1.182 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='localhost' id='706026e1-3748-4d78-b392-868ee93c58c9' xml:lang='en' xmlns='jabber:client'><stream:features><c hash='sha-1' ver='ZBWApSGFMsTZkuVThHtyU5xv1Mk=' node='http://prosody.im' xmlns='http://jabber.org/protocol/caps'/><ver xmlns='urn:xmpp:features:rosterver'/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><required/></bind><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session></stream:features>"
DEBUG:agent2:negotiating stream (server_can_do_sm=False)
DEBUG:aioxmpp.callbacks:connecting <bound method StanzaStream._xmlstream_failed of <aioxmpp.stream.StanzaStream object at 0x10e2d4d68>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:agent2.StanzaStream:broker task started as <Task pending coro=<StanzaStream._run() running at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/site-packages/aioxmpp/stream.py:1805> cb=[StanzaStream._done_handler()] created at /Users/jpalanca/anaconda/envs/spade-dev/lib/python3.6/asyncio/tasks.py:499>
DEBUG:agent2:binding to resource
DEBUG:agent2.StanzaStream:sending <iq from=None to=None id='xefQpiCAG6AqdP+2im82y' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e343908>> and waiting for it to be sent
DEBUG:agent2.StanzaStream:iq response future registered: from=None, id='xefQpiCAG6AqdP+2im82y'
DEBUG:agent2.StanzaStream:enqueued stanza <iq from=None to=None id='xefQpiCAG6AqdP+2im82y' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e343908>> with token <StanzaToken id=0x000000010e3425e8>
DEBUG:agent2.StanzaStream:forwarding stanza to xmlstream: <iq from=None to=None id='xefQpiCAG6AqdP+2im82y' type=<IQType.SET: 'set'> data=<aioxmpp.rfc6120.Bind object at 0x10e343908>>
DEBUG:agent2.XMLStream:SENT b'<iq id="xefQpiCAG6AqdP+2im82y" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/></iq>'
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 14996.390 ms took 1.105 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<iq id='xefQpiCAG6AqdP+2im82y' type='result'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4</jid></bind></iq>"
DEBUG:agent2.StanzaStream:incoming iq: <iq from=None to=None id='xefQpiCAG6AqdP+2im82y' type=<IQType.RESULT: 'result'> data=<aioxmpp.rfc6120.Bind object at 0x10e343518>>
DEBUG:agent2.StanzaStream:iq is response
DEBUG:agent2.StanzaStream:iq response delivered to key (None, 'xefQpiCAG6AqdP+2im82y')
INFO:agent2:bound to jid: agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4
DEBUG:agent2:remote server announces support for legacy sessions
DEBUG:agent2.StanzaStream:sending <iq from=None to=None id='xTCthTcqkDZcONjbBsgL5' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e3437f0>> and waiting for it to be sent
DEBUG:agent2.StanzaStream:iq response future registered: from=None, id='xTCthTcqkDZcONjbBsgL5'
DEBUG:agent2.StanzaStream:enqueued stanza <iq from=None to=None id='xTCthTcqkDZcONjbBsgL5' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e3437f0>> with token <StanzaToken id=0x000000010e3a8d68>
DEBUG:agent2.StanzaStream:forwarding stanza to xmlstream: <iq from=None to=None id='xTCthTcqkDZcONjbBsgL5' type=<IQType.SET: 'set'> data=<aioxmpp.rfc3921.Session object at 0x10e3437f0>>
DEBUG:agent2.XMLStream:SENT b'<iq id="xTCthTcqkDZcONjbBsgL5" type="set"><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></iq>'
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:asyncio:poll 14989.761 ms took 0.984 ms: 1 events
DEBUG:agent2.XMLStream:RECV b"<iq id='xTCthTcqkDZcONjbBsgL5' type='result' to='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4'/>"
DEBUG:agent2.StanzaStream:incoming iq: <iq from=None to='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4' id='xTCthTcqkDZcONjbBsgL5' type=<IQType.RESULT: 'result'>>
DEBUG:agent2.StanzaStream:iq is response
DEBUG:agent2.StanzaStream:iq response delivered to key (None, 'xTCthTcqkDZcONjbBsgL5')
DEBUG:agent2:legacy session negotiated (upgrade your server!)
DEBUG:agent2.StanzaStream:sending <presence from=None to=None id='xUOlGochGsdPTWNQK3GBr' type=<PresenceType.AVAILABLE: None>> and waiting for it to be sent
DEBUG:agent2.StanzaStream:enqueued stanza <presence from=None to=None id='xUOlGochGsdPTWNQK3GBr' type=<PresenceType.AVAILABLE: None>> with token <StanzaToken id=0x000000010e345f98>
DEBUG:agent2.StanzaStream:forwarding stanza to xmlstream: <presence from=None to=None id='xUOlGochGsdPTWNQK3GBr' type=<PresenceType.AVAILABLE: None>>
DEBUG:agent2.XMLStream:SENT b'<presence id="xUOlGochGsdPTWNQK3GBr"/>'
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
DEBUG:agent2.StanzaStream:iq request coroutine registered: type=<IQType.SET: 'set'>, payload=<class 'aioxmpp.roster.xso.Query'>
DEBUG:aioxmpp.callbacks:connecting <bound method RosterClient._request_initial_roster of <aioxmpp.roster.service.RosterClient object at 0x10e343940>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_subscribe of <spade.presence.PresenceManager object at 0x10e343a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_subscribed of <spade.presence.PresenceManager object at 0x10e343a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_unsubscribe of <spade.presence.PresenceManager object at 0x10e343a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:aioxmpp.callbacks:connecting <bound method PresenceManager._on_unsubscribed of <spade.presence.PresenceManager object at 0x10e343a58>> with mode <bound method AdHocSignal.STRONG of <class 'aioxmpp.callbacks.AdHocSignal'>>
DEBUG:asyncio:poll 14982.603 ms took 0.828 ms: 2 events
DEBUG:agent2.XMLStream:RECV b"<presence id='xUOlGochGsdPTWNQK3GBr' from='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4'/><presence to='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4' from='agent2@localhost/Mac-Pro-de-Javi'><c hash='sha-1' ver='DdnydQG7RGhP9E3k9Sf+b+bF0zo=' node='http://pidgin.im/' xmlns='http://jabber.org/protocol/caps'/><x xmlns='vcard-temp:x:update'><photo>4a4d229aa03967b73af6fde0f0f6afc3123fff2f</photo></x><delay from='localhost' stamp='2017-11-02T16:22:29Z' xmlns='urn:xmpp:delay'/></presence><presence from='agent1@localhost' type='subscribe'/>"
DEBUG:agent2.StanzaStream:incoming presence: <presence from='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4' to=None id='xUOlGochGsdPTWNQK3GBr' type=<PresenceType.AVAILABLE: None>>
DEBUG:agent2.StanzaStream:incoming presence: <presence from='agent2@localhost/Mac-Pro-de-Javi' to='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4' id=None type=<PresenceType.AVAILABLE: None>>
DEBUG:agent2.StanzaStream:incoming presence: <presence from='agent1@localhost' to=None id=None type=<PresenceType.SUBSCRIBE: 'subscribe'>>
DEBUG:agent2.StanzaStream:enqueued stanza <presence from=None to='agent1@localhost' id='xLIED4L99e9YbuGPwlP4K' type=<PresenceType.SUBSCRIBED: 'subscribed'>> with token <StanzaToken id=0x000000010e39c7c8>
DEBUG:agent2.StanzaStream:forwarding stanza to xmlstream: <presence from=None to='agent1@localhost' id='xLIED4L99e9YbuGPwlP4K' type=<PresenceType.SUBSCRIBED: 'subscribed'>>
DEBUG:agent2.XMLStream:SENT b'<presence to="agent1@localhost" id="xLIED4L99e9YbuGPwlP4K" type="subscribed"/>'
DEBUG:aioopenssl.trace.fd=13:_write_ready: nothing more to write, removing writer
INFO:asyncio:poll 14953.378 ms took 1171.919 ms: 1 events
DEBUG:agent1.XMLStream:RECV b"<presence id='xUOlGochGsdPTWNQK3GBr' to='agent1@localhost' from='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4'><delay from='localhost' stamp='2017-11-02T17:35:07Z' xmlns='urn:xmpp:delay'/></presence><presence to='agent1@localhost' from='agent2@localhost/Mac-Pro-de-Javi'><c hash='sha-1' ver='DdnydQG7RGhP9E3k9Sf+b+bF0zo=' node='http://pidgin.im/' xmlns='http://jabber.org/protocol/caps'/><x xmlns='vcard-temp:x:update'><photo>4a4d229aa03967b73af6fde0f0f6afc3123fff2f</photo></x><delay from='localhost' stamp='2017-11-02T16:22:29Z' xmlns='urn:xmpp:delay'/></presence>"
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent2@localhost/ef3391fb-b985-471f-aba9-45e2bcd0ccb4' to='agent1@localhost' id='xUOlGochGsdPTWNQK3GBr' type=<PresenceType.AVAILABLE: None>>
DEBUG:agent1.StanzaStream:incoming presence: <presence from='agent2@localhost/Mac-Pro-de-Javi' to='agent1@localhost' id=None type=<PresenceType.AVAILABLE: None>>