stream bind timeout - receiving bind with jid from server fails

[Morten Bjoernsvik]

Almost all the time I get bind failure, (I do not have pyasn1 installed because it says my cert has expired and refuse to authenticate Although it has not)
Any ideas how to debug this?

sleekxmpp==1.3.3
Python 3.6.3

Correct, then all is green

DEBUG    Event triggered: auth_success
DEBUG    SEND (IMMED): <stream:stream to='xmpp.local' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
DEBUG    RECV: <stream:stream version="1.0" from="xmpp.local" id="82d20984-aa62-449b-ae93-2461f3362f19">
DEBUG    RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></stream:features>
DEBUG    Requesting resource:
DEBUG    SEND (IMMED): <iq id="bbdd8713-79d7-45c8-ba66-bf2d567ebe88-1" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq>
DEBUG    RECV: <iq id="bbdd8713-79d7-45c8-ba66-bf2d567ebe88-1" type="result"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>deadbeef0002@xmpp.local</jid></bind></iq>
DEBUG    Event triggered: session_bind
ERROR    Error reading from XML stream.
INFO     JID set to: deadbeef0002@xmpp.local
DEBUG    Event triggered: session_end
DEBUG    Established Session
DEBUG    SEND (IMMED): </stream:stream>

But most of the time I get the following:

DEBUG    Event triggered: auth_success
DEBUG    SEND (IMMED): <stream:stream to='xmpp.local' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'>
DEBUG    RECV: <stream:stream version="1.0" from="xmpp.local" id="00f600eb-bd21-4067-9f90-a100ec0920cd">
DEBUG    RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></stream:features>
DEBUG    Requesting resource:
DEBUG    SEND (IMMED): <iq id="489035d8-cbda-420f-a913-d9f14ce2865f-1" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq>
ERROR    Error reading from XML stream.
DEBUG    Event triggered: session_end
DEBUG    SEND (IMMED): </stream:stream>
INFO     Waiting for </stream:stream> from server

The xmppserver I connect to is a minimalist xmppserver written in .NET using matrixxmpp https://www.ag-software.net/matrix-xmpp-sdk/ mainly for connection to android devices. no error and no source.

debuglog sucessfull:

2017-12-13 09:48:28 - Debug {<b class="match">21a10666-3c9c-48d4-b4d4-33c1f27d5fbc</b>} XMPP (deadbeef0002) << <iq id="bbdd8713-79d7-45c8-ba66-bf2d567ebe88-1" type="set" xmlns="jabber:client">\n <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" />\n</iq> 2017-12-13 09:48:28 - Debug {<b class="match">21a10666-3c9c-48d4-b4d4-33c1f27d5fbc</b>} TCP disconnect from 80.241.95.122:2021 2017-12-13 09:48:28 - Debug {<b class="match">21a10666-3c9c-48d4-b4d4-33c1f27d5fbc</b>} XMPP (deadbeef0002) >> <iq id="bbdd8713-79d7-45c8-ba66-bf2d567ebe88-1" type="result" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>deadbe...@xmpp.local</jid></bind></iq> Failed is same, the last bind do not return to me:

2017-12-13 09:49:21 - Debug {<b class="match">4d325291-0e66-4725-b07f-85c26a54bfc4</b>} XMPP (deadbeef0002) << <iq id="489035d8-cbda-420f-a913-d9f14ce2865f-1" type="set" xmlns="jabber:client">\n <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" />\n</iq> 2017-12-13 09:49:21 - Debug {<b class="match">4d325291-0e66-4725-b07f-85c26a54bfc4</b>} TCP disconnect from 80.241.95.122:53110 2017-12-13 09:49:21 - Debug {<b class="match">4d325291-0e66-4725-b07f-85c26a54bfc4</b>} XMPP (deadbeef0002) >> <iq id="489035d8-cbda-420f-a913-d9f14ce2865f-1" type="result" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>deadbe...@xmpp.local</jid></bind></iq>

I've set up a minimalistic simplified xmppclient: #!/usr/bin/env python3 import argparse import logging import socket import json import uuid from sleekxmpp import ClientXMPP, Message from sleekxmpp.exceptions import IqError, IqTimeout logging.basicConfig(level=logging.DEBUG, format='%(levelname)-8s %(message)s') parser = argparse.ArgumentParser(description='simple xmpp unity tester') parser.add_argument('--jid', help="jabberid name@site/service: %(default)s)", default='DEADBE...@xmpp.local') parser.add_argument('--pw', help="password for xmpp service, can be anything: %(default)s)", default='test1234test1234') parser.add_argument('--tojid', help="to jid in unity: %(default)s)", default='mas...@xmpp.local') parser.add_argument('--server', help="xmpp server hostname: %(default)s)", default='welfare-vm-23.sensio.no') parser.add_argument('--port', help="xmpp server port: %(default)s)", default='843') parser.add_argument('--message', help="message to send: %(default)s)", default="just a stupid message") args = parser.parse_args() class TestBot(ClientXMPP): def __init__(self, jid, password, recipient): ClientXMPP.__init__(self, jid, password, sasl_mech="PLAIN") self.auto_reconnect = False self.recipient = recipient if __name__ == '__main__': xmpp = TestBot(args.jid, args.pw, args.tojid) if xmpp.connect((args.server, int(args.port)), use_tls=True, use_ssl=False, reattempt=False): msg = Message() msg['type'] = "chat" msg['to'] = args.tojid msg['body'] = args.message msg['id'] = "panel00000002" xmpp.send(msg) xmpp.process(block=True)

./xmpp-clienttest.py DEBUG    Loaded Plugin: RFC 6120: Stream Feature: STARTTLS DEBUG    Loaded Plugin: RFC 6120: Stream Feature: Resource Binding DEBUG    Loaded Plugin: RFC 3920: Stream Feature: Start Session DEBUG    Loaded Plugin: RFC 6121: Stream Feature: Roster Versioning DEBUG    Loaded Plugin: RFC 6121: Stream Feature: Subscription Pre-Approval DEBUG    Loaded Plugin: RFC 6120: Stream Feature: SASL DEBUG    DNS: Querying welfare-dev.sensio.no for AAAA records. DEBUG    DNS: Error retreiving AAAA address info for welfare-dev.sensio.no. DEBUG    DNS: Querying welfare-dev.sensio.no for A records. DEBUG    Connecting to XXXXXXXXXXXXX:843 DEBUG    Event triggered: connected DEBUG     ==== TRANSITION disconnected -> connected DEBUG    Starting HANDLER THREAD DEBUG    Loading event runner DEBUG    SEND (IMMED): <stream:stream to='xmpp.local' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'> DEBUG    RECV: <stream:stream version="1.0" from="xmpp.local" id="2c23e102-4c23-41ef-bd78-8ba8a9285101"> DEBUG    RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" /><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features> DEBUG    SEND (IMMED): <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" /> DEBUG    RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" /> DEBUG    Starting TLS INFO     Negotiating TLS INFO     Using SSL version: TLSv1 DEBUG    CERT: -----BEGIN CERTIFICATE----- MIIG4DCCBcigAwIBAgIQPoKy3vw04yC1kwQXsQgJvDANBgkqhkiG9w0BAQsFADBC MQswCQYDVQQGEwJVUzEWMBQGA1UEChMNR2VvVHJ1c3QgSW5jLjEbMBkGA1UEAxMS UmFwaWRTU0wgU0hBMjU2IENBMB4XDTE2MTEyNDAwMDAwMFoXDTE4MDIyMzIzNTk1 OVowFjEUMBIGA1UEAwwLKi5zZW5zaW8ubm8wggIiMA0GCSqGSIb3DQEBAQUAA4IC DwAwggIKAoICAQCdVTojYAQ4a+K+czarxkb+XjBsa/oMG02zvS0HrFDJAsgUFhtT 0y9gHLR1PnGtelLHFNAMjVwS+lDFCL4MonV0NJjEgSHheTC6yW5J30RiZfxiKIm6 rpqGC6K6bjQLkMQ748Au0eInQjfQLLvg+bmW8uNojVsYqqsKTORuxgC0LPCikvYg bltyFKCIkvI4kdA8VQlnMy6GQgdOOLHqi6dBc8GAuUPHgXHk65AlVe9qH/2Ibx7L 6jQxq7Kr5knwq2JTmVfqS/YflxQuzKO6+sk/uDYUXQOom+3vT3auEAh5cYsMBDwG mlQ5T5JdhUnDqVSbo/mwwWPgEylYaf9u+cRmYufOFdXyG5jbbxAsdfjTEpELaDWE PEq32RXHBf+D7DhXCWQ/cKHSzNaL1vurQ4nfOVuOTPPIN3q2F7Rv8AqD91jE5pDX saX5l0C9VDBOzCekSuSXxSSVqKThV+Wa02ro1vyrYv1jCD6JAdzbA8Le6MsispME Jep9iClNENnqlnOPk7vfJRpfSUS8WEJLd2Cimsco5uSWdqxne6VBmaOqyURK6QO7 bMrYK03OcK3eiNXBmFrSKng8m7U7/p+tXZZG30JxUXpTAs2WAf1MiHLlZ8D2lZtK 8v4HEr24FuId0JbLbXAgDMTlHzo2b0dYvLKozw86qEtPqUdnD8IAFkmeZQIDAQAB o4IC/DCCAvgwIQYDVR0RBBowGIILKi5zZW5zaW8ubm+CCXNlbnNpby5ubzAJBgNV HRMEAjAAMCsGA1UdHwQkMCIwIKAeoByGGmh0dHA6Ly9ncC5zeW1jYi5jb20vZ3Au Y3JsMG8GA1UdIARoMGYwZAYGZ4EMAQIBMFowKgYIKwYBBQUHAgEWHmh0dHBzOi8v d3d3LnJhcGlkc3NsLmNvbS9sZWdhbDAsBggrBgEFBQcCAjAgDB5odHRwczovL3d3 dy5yYXBpZHNzbC5jb20vbGVnYWwwHwYDVR0jBBgwFoAUl8InUJ7CyewMiDLIfK3i pgFP2m8wDgYDVR0PAQH/BAQDAgWgMB0GA1UdJQQWMBQGCCsGAQUFBwMBBggrBgEF BQcDAjBXBggrBgEFBQcBAQRLMEkwHwYIKwYBBQUHMAGGE2h0dHA6Ly9ncC5zeW1j ZC5jb20wJgYIKwYBBQUHMAKGGmh0dHA6Ly9ncC5zeW1jYi5jb20vZ3AuY3J0MIIB fwYKKwYBBAHWeQIEAgSCAW8EggFrAWkAdwDd6x0reg1PpiCLga2BaHB+Lo6dAdVc iI09EcTNtuy+zAAAAViVw5miAAAEAwBIMEYCIQCZcpOY1CEW8cjPlyystOgJDO40 QM8m3NJy/536PPpvngIhAOrUMWpHljQI2oJfHOHJfxGaYr9b2tQjysZZQrNes8sV AHYA7ku9t3XOYLrhQmkfq+GeZqMPfl+wctiDAMR7iXqo/csAAAFYlcOZ5QAABAMA RzBFAiBisSspT1fOn9NmwzNf07dryovgyQpSJedmpaml+mHx7gIhAM3gRLZADJ7S 4ybg1E5TgwavScpIoipNEnndQtxJpO/RAHYAvHjh38X2PGhGSTNNoQ+hXwl5aSAJ wIG08/aRfz7ZuKUAAAFYlcOakAAABAMARzBFAiAIL6PIOJVjBF+r+owiWbjJ2JOw rmdt1eTdP6DyrfxIjgIhAJfoN03NLl0Un1uMDqQGqejUWnXc7TvRiVR8VzOXE8W6 MA0GCSqGSIb3DQEBCwUAA4IBAQAMETmQ+q/QzM7n0Hnc7Y51FFEMUMijOc+xsdJB 8jevfgNjswSxWs1Hs8BQMiM3756iXYm3t1U9fJfe67az0dno1T/ltHc+yRVAF7HM CLxusN+KtAWOI3+vAb49g4pe3ZRga3VJ9RNyIYsP7/IX4zteKy/yeiPqyJ4Wnjvy G0shw7okFxR4IW/uCtPKSgeKC5oCtVadEpGV8F4CbQ97334XhiFy4j1BSmMW6Kzr wj9HJgjbddvKWZd5FfOFqbaKc6jMNckPVGVKN9IUb8PhAtxuwoEN/DlmMyjsYs3b 5ac8vgnS/vdQNv57i25v3XFPBiVVE4e6skGO8ZChJ53Cs0Pe -----END CERTIFICATE----- DEBUG    Event triggered: ssl_cert WARNING  Could not find pyasn1 and pyasn1_modules. SSL certificate COULD NOT BE VERIFIED. DEBUG    SEND (IMMED): <stream:stream to='xmpp.local' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'> DEBUG    RECV: <stream:stream version="1.0" from="xmpp.local" id="ff605170-efff-4c9e-ba6c-a3973f68be08"> DEBUG    RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features> DEBUG    SEND (IMMED): <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">AGRlYWRiZWVmMDAwMgB0ZXN0MTIzNHRlc3QxMjM0</auth> DEBUG    RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl" /> DEBUG    Event triggered: auth_success DEBUG    SEND (IMMED): <stream:stream to='xmpp.local' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en' version='1.0'> DEBUG    RECV: <stream:stream version="1.0" from="xmpp.local" id="d2e6b484-dbd3-4604-be4c-60c1359eaef8"> DEBUG    RECV: <stream:features xmlns="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></stream:features> DEBUG    Requesting resource: DEBUG    SEND (IMMED): <iq id="f4033c0f-981b-48fa-b992-744c9d9e8359-1" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq> ERROR    Error reading from XML stream. DEBUG    Event triggered: session_end DEBUG    SEND (IMMED): </stream:stream> INFO     Waiting for </stream:stream> from server DEBUG    Waiting for 3 threads to exit. ### this message is not sent, it is just because I put it in the main loop and not in session_start ### DEBUG    SEND: <message type="chat" to="master@xmpp.local" id="panel00000002"><body>just a stupid message</body></message> DEBUG    Stopped send thread. 2 threads remain. DEBUG    Quitting Scheduler thread DEBUG    Stopped scheduler thread. 1 threads remain. ERROR    Error processing stream handler: Stream Features Traceback (most recent call last):   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/xmlstream/xmlstream.py", line 1686, in _event_runner     handler.run(args[0])   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/xmlstream/handler/callback.py", line 76, in run     self._pointer(payload)   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/clientxmpp.py", line 285, in _handle_stream_features     if handler(features) and restart:   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/features/feature_bind/bind.py", line 50, in _handle_bind_resource     response = iq.send(now=True)   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/stanza/iq.py", line 233, in send     raise IqTimeout(self) sleekxmpp.exceptions.IqTimeout: <iq id="f4033c0f-981b-48fa-b992-744c9d9e8359-1" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq> ERROR    Error handling {jabber:client}features stanza Traceback (most recent call last):   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/xmlstream/xmlstream.py", line 1686, in _event_runner     handler.run(args[0])   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/xmlstream/handler/callback.py", line 76, in run     self._pointer(payload)   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/clientxmpp.py", line 285, in _handle_stream_features     if handler(features) and restart:   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/features/feature_bind/bind.py", line 50, in _handle_bind_resource     response = iq.send(now=True)   File "/home/mortenb/.pyenv/versions/xmpp/lib/python3.6/site-packages/sleekxmpp/stanza/iq.py", line 233, in send     raise IqTimeout(self) sleekxmpp.exceptions.IqTimeout: <iq id="f4033c0f-981b-48fa-b992-744c9d9e8359-1" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" /></iq> DEBUG    Stopped event runner thread. 0 threads remain. DEBUG    Event triggered: disconnected DEBUG     ==== TRANSITION connected -> disconnected Thanks ---

Morten Bjoernsvik, Sensio AS, Oslo Norway

[Alexandre Marques]

Hi Morten,

I'm having the same issue,

did you find a solution for this?

Thanks