Skip to content

Instantly share code, notes, and snippets.

@haizaar

haizaar/asyncio-client-debug-log.txt

Created January 14, 2019 23:37
Show Gist options

  • Select an option

    Learn more about clone URLs
  • Save haizaar/d9033b531759ee73807cc8b3f035b742 to your computer and use it in GitHub Desktop.

Select an option

Learn more about clone URLs
Save haizaar/d9033b531759ee73807cc8b3f035b742 to your computer and use it in GitHub Desktop.
Download ZIP

Revisions

  1. haizaar created this gist Jan 14, 2019.
    226 changes: 226 additions & 0 deletions asyncio-client-debug-log.txt
    View file
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,226 @@
    $ python bug-subscribe-and-do-nothing.py
    2019-01-15T00:14:01 Entering re-connect loop
    2019-01-15T00:14:01 trying transport 0 using connect delay 0
    2019-01-15T00:14:01 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-15T00:14:02
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f0d402bed08>,
    'WampWebSocketClientFactory')]
    2019-01-15T00:14:02 connection to tcp:ip.is.hidden:443 established
    2019-01-15T00:14:02 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: 6XEuZ+nMZHlhWxZyFQPWDw==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-15T00:14:02 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 13:14:02 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: uNXF94uw0ORosE7XTmZ1k0X//Co=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-15T00:14:02 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-15T00:14:02 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 13:14:02 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': 'uNXF94uw0ORosE7XTmZ1k0X//Co=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-15T00:14:02 openHandshakeTimeoutCall.cancel
    2019-01-15T00:14:03 Entering on_join
    2019-01-15T00:14:03 Subscribed
    2019-01-15T00:14:03 Sleeping
    2019-01-15T00:14:12 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:14:22 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:14:32 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:14:32 _connectionLost: None
    2019-01-15T00:14:32 WAMP-over-WebSocket transport lost: wasClean=False, code=1006, reason="connection was closed uncleanly (peer dropped the TCP connection without previous WebSocket closing handshake)"
    2019-01-15T00:14:32 session leaving 'wamp.close.transport_lost'
    2019-01-15T00:14:32 session on_disconnect: was_clean=False
    2019-01-15T00:14:32 component failed: TransportLost: failed to complete connection
    2019-01-15T00:14:32 Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    autobahn.wamp.exception.TransportLost: failed to complete connection

    2019-01-15T00:14:32 Connection failed: TransportLost: failed to complete connection
    2019-01-15T00:14:32 Entering re-connect loop
    2019-01-15T00:14:32 trying transport 0 using connect delay 2.467634918279256
    2019-01-15T00:14:35 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-15T00:14:35
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f0d3f9c3730>,
    'WampWebSocketClientFactory')]
    2019-01-15T00:14:35 connection to tcp:ip.is.hidden:443 established
    2019-01-15T00:14:35 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: Kmppg69rgqkofQ1tH5lTTQ==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-15T00:14:35 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 13:14:35 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: oiRSHHieALKlb3+9wVmRsbKdpdE=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-15T00:14:35 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-15T00:14:35 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 13:14:35 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': 'oiRSHHieALKlb3+9wVmRsbKdpdE=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-15T00:14:35 openHandshakeTimeoutCall.cancel
    2019-01-15T00:14:35 Entering on_join
    2019-01-15T00:14:35 Subscribed
    2019-01-15T00:14:35 Sleeping
    2019-01-15T00:14:45 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:14:55 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:15:03 Publishing
    2019-01-15T00:15:03 While notifying 'join': Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "bug-subscribe-and-do-nothing.py", line 34, in on_join
    await session.publish("news", "Fake news", options=options)
    File "/home/.../lib/python3.7/site-packages/autobahn/wamp/protocol.py", line 1278, in publish
    raise exception.TransportLost()
    autobahn.wamp.exception.TransportLost

    2019-01-15T00:15:03 While firing onJoin: Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "bug-subscribe-and-do-nothing.py", line 34, in on_join
    await session.publish("news", "Fake news", options=options)
    File "/home/.../lib/python3.7/site-packages/autobahn/wamp/protocol.py", line 1278, in publish
    raise exception.TransportLost()
    autobahn.wamp.exception.TransportLost

    2019-01-15T00:15:03 While notifying 'ready': Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    [Previous line repeated 2 more times]
    File "bug-subscribe-and-do-nothing.py", line 34, in on_join
    await session.publish("news", "Fake news", options=options)
    File "/home/.../lib/python3.7/site-packages/autobahn/wamp/protocol.py", line 1278, in publish
    raise exception.TransportLost()
    autobahn.wamp.exception.TransportLost

    2019-01-15T00:15:05 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-15T00:15:05 _connectionLost: None
    2019-01-15T00:15:05 WAMP-over-WebSocket transport lost: wasClean=False, code=1006, reason="connection was closed uncleanly (peer dropped the TCP connection without previous WebSocket closing handshake)"
    2019-01-15T00:15:05 session leaving 'wamp.close.transport_lost'
    2019-01-15T00:15:05 session on_disconnect: was_clean=False
    2019-01-15T00:15:05 component failed: TransportLost: failed to complete connection
    2019-01-15T00:15:05 Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    File "/home/.../lib/python3.7/site-packages/txaio/aio.py", line 514, in done
    res = f.result()
    autobahn.wamp.exception.TransportLost: failed to complete connection

    2019-01-15T00:15:05 Connection failed: TransportLost: failed to complete connection
    2019-01-15T00:15:05 Entering re-connect loop
    2019-01-15T00:15:05 trying transport 0 using connect delay 3.8440721281200982
    2019-01-15T00:15:09 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-15T00:15:09
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f0d3df42488>,
    'WampWebSocketClientFactory')]
    2019-01-15T00:15:09 connection to tcp:ip.is.hidden:443 established
    2019-01-15T00:15:09 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: EcUtuahCv8sNwn9ZIEkqgA==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-15T00:15:09 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 13:15:09 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: hN2N9K7+ntnlw/yN8iL0xsT+D3E=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-15T00:15:09 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-15T00:15:09 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 13:15:09 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': 'hN2N9K7+ntnlw/yN8iL0xsT+D3E=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-15T00:15:09 openHandshakeTimeoutCall.cancel
    2019-01-15T00:15:10 Entering on_join
    2019-01-15T00:15:10 Subscribed
    2019-01-15T00:15:10 Sleeping
    38 changes: 38 additions & 0 deletions client-asyncio-component.py
    View file
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,38 @@
    import asyncio
    from autobahn.asyncio.component import Component, run
    from autobahn.wamp.types import PublishOptions
    import txaio

    txaio.start_logging(level='debug')
    logger = txaio.make_logger()


    component = Component(
    transports="wss://example.com",
    authentication={
    "ticket": {
    "ticket": "secret",
    }
    }
    )


    def printer(ev):
    print("Got event", ev)


    @component.on_join
    async def on_join(session, details):
    logger.info("Entering on_join")
    options = PublishOptions(exclude_me=False, acknowledge=True)
    logger.info("Subscribed")
    await session.subscribe(printer, "news")
    while True:
    logger.info("Sleeping")
    await asyncio.sleep(60)
    logger.info("Publishing")
    await session.publish("news", "Fake news", options=options)


    if __name__ == "__main__":
    run([component])
    41 changes: 41 additions & 0 deletions client-twisted-component.py
    View file
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,41 @@
    from autobahn.twisted.component import Component
    from autobahn.twisted.component import run
    from autobahn.wamp.types import PublishOptions
    from twisted.internet.defer import inlineCallbacks
    from twisted.internet.task import deferLater
    from twisted.internet import reactor

    import txaio
    txaio.start_logging(level='debug')
    logger = txaio.make_logger()

    component = Component(
    transports="wss://example.com",
    authentication={
    "ticket": {
    "ticket": "secret",
    }
    }
    )


    def printer(ev):
    print("Got event", ev)


    @component.on_join
    @inlineCallbacks
    def on_join(session, details):
    logger.info("Entering on_join")
    options = PublishOptions(exclude_me=False, acknowledge=True)
    logger.info("Subscribed")
    yield session.subscribe(printer, "news")
    while True:
    logger.info("Sleeping")
    yield deferLater(reactor, 60, lambda: None)
    logger.info("Publishing")
    yield session.publish("news", "Fake news", options=options)


    if __name__ == "__main__":
    run([component])
    52 changes: 52 additions & 0 deletions crossbar-reconnect-log.txt
    View file
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,52 @@
    2019-01-14T12:25:04+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Expecting ping in 5.0 seconds for auto-ping/pong
    2019-01-14T12:25:04+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Auto ping/pong: received pending pong for auto-ping/pong
    2019-01-14T12:25:04+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] WebSocketProtocol.onPong(payload=<4 bytes>)
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Auto ping/pong: sending ping auto-ping/pong
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Expecting ping in 5.0 seconds for auto-ping/pong
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Auto ping/pong: received pending pong for auto-ping/pong
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] WebSocketProtocol.onPong(payload=<4 bytes>)
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Connection to/from tcp4:10.200.22.24:57952 was closed cleanly
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] _connectionLost: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
    ]
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] Auto ping/pong: canceling autoPingPendingCall upon lost connection
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol] WAMP-over-WebSocket transport lost: wasClean=False, code=1006, reason="connection was closed uncleanly (peer dropped the TCP connection without previous WebSocket closing handshake)"
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.router.Router] session "5535107469550354" left realm "myrealm"
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.router.Router] {'session': 5535107469550354, 'authid': 'aad:kaminario.com:2c5289ff-e0ea-4171-9aae-9c3199dc2481', 'authrole': 'peers', 'authmethod': 'ticket', 'authextra': None, 'authprovider': 'dynamic', 'transport': {'type': 'websocket', 'protocol': 'wamp.2.cbor', 'peer': 'tcp4:10.200.22.24:57952', 'http_headers_received': {'upgrade': 'WebSocket', 'connection': 'upgrade', 'host': 'channeler.default.svc.cluster.local:5555', 'user-agent': 'AutobahnPython/19.1.1', 'pragma': 'no-cache', 'cache-control': 'no-cache', 'sec-websocket-key': 'pZrLvQ1kv3mWdd8bFshM0Q==', 'sec-websocket-protocol': 'wamp.2.cbor,wamp.2.json', 'sec-websocket-version': '13', 'x-cloud-trace-context': '9b6af66910977186e69b02a884a60551/14036055621129395511', 'via': '1.1 google', 'x-forwarded-for': 'another.ip.is.hidden, ip.is.hidden', 'x-forwarded-proto': 'https'}, 'http_headers_sent': {}, 'websocket_extensions_in_use': [], 'cbtid': None}}
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.service.RouterServiceAgent] RouterServiceAgent.publish("wamp.session.on_leave") -> "wamp.session.on_leave" on "myrealm"
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.service.RouterServiceAgent] RouterServiceAgent.publish("wamp.subscription.on_unsubscribe") -> "wamp.subscription.on_unsubscribe" on "myrealm"
    2019-01-14T12:25:14+0000 [Router 14 crossbar.router.service.RouterServiceAgent] RouterServiceAgent.publish("wamp.subscription.on_delete") -> "wamp.subscription.on_delete" on "myrealm"
    2019-01-14T12:25:17+0000 [Router 14 crossbar.router.protocol.WampWebSocketServerProtocol]
    [('logOctets', False, 'WampWebSocketServerFactory'),
    ('logFrames', False, 'WampWebSocketServerFactory'),
    ('trackTimings', False, 'WampWebSocketServerFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketServerFactory'),
    ('applyMask', True, 'WampWebSocketServerFactory'),
    ('maxFramePayloadSize', 1048576, 'WampWebSocketServerFactory'),
    ('maxMessagePayloadSize', 2097152, 'WampWebSocketServerFactory'),
    ('autoFragmentSize', 65536, 'WampWebSocketServerFactory'),
    ('failByDrop', True, 'WampWebSocketServerFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketServerFactory'),
    ('openHandshakeTimeout', 2.5, 'WampWebSocketServerFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketServerFactory'),
    ('tcpNoDelay', True, 'WampWebSocketServerFactory'),
    ('autoPingInterval', 10.0, 'WampWebSocketServerFactory'),
    ('autoPingTimeout', 5.0, 'WampWebSocketServerFactory'),
    ('autoPingSize', 4, 'WampWebSocketServerFactory'),
    ('versions', [8, 13], 'WampWebSocketServerFactory'),
    ('webStatus', False, 'WampWebSocketServerFactory'),
    ('requireMaskedClientFrames', True, 'WampWebSocketServerFactory'),
    ('maskServerFrames', False, 'WampWebSocketServerFactory'),
    ('perMessageCompressionAccept',
    <function set_websocket_options.<locals>.<lambda> at 0x00007fc82829b740>,
    'WampWebSocketServerFactory'),
    ('serveFlashSocketPolicy', False, 'WampWebSocketServerFactory'),
    ('flashSocketPolicy',
    '<cross-domain-policy>\n'
    ' <allow-access-from domain="*" to-ports="*" />\n'
    '</cross-domain-policy>\x00',
    'WampWebSocketServerFactory'),
    ('allowedOrigins', ['*'], 'WampWebSocketServerFactory'),
    ('allowedOriginsPatterns', [re.compile('^.*$')], 'WampWebSocketServerFactory'),
    ('allowNullOrigin', True, 'WampWebSocketServerFactory'),
    ('maxConnections', 0, 'WampWebSocketServerFactory'),
    ('trustXForwardedFor', 0, 'WampWebSocketServerFactory')]
    251 changes: 251 additions & 0 deletions twisted-client-debug-log.txt
    View file
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,251 @@
    $ python bug-twisted-subscribe-and-do-nothing.py
    :0: UserWarning: You do not have a working installation of the service_identity module: 'No module named 'service_identity''. Please install it from <https://pypi.python.org/pypi/service_identity> and make sure all of its dependencies are satisfied. Without the service_identity module, Twisted can perform only rudimentary TLS client hostname verification. Many valid certificate/hostname mappings may be rejected.
    2019-01-14T23:52:35+1100 Entering re-connect loop
    2019-01-14T23:52:35+1100 trying transport 0 using connect delay 0
    2019-01-14T23:52:35+1100 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-14T23:52:35+1100 Starting factory <autobahn.twisted.websocket.WampWebSocketClientFactory object at 0x7f77224e09b0>
    2019-01-14T23:52:35+1100
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f77224ec1e0>,
    'WampWebSocketClientFactory')]
    2019-01-14T23:52:35+1100 connection to tcp4:ip.is.hidden:443 established
    2019-01-14T23:52:35+1100 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: 4D44jxWYouf4FDJ7KcB/iw==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-14T23:52:35+1100 Connection made to tcp4:ip.is.hidden:443
    2019-01-14T23:52:35+1100 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 12:52:35 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: 0y8ufxARaaQJzewLvjRG2ZwbCG8=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-14T23:52:35+1100 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-14T23:52:35+1100 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 12:52:35 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': '0y8ufxARaaQJzewLvjRG2ZwbCG8=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-14T23:52:35+1100 openHandshakeTimeoutCall.cancel
    2019-01-14T23:52:36+1100 Entering on_join
    2019-01-14T23:52:36+1100 Subscribed
    2019-01-14T23:52:36+1100 Sleeping
    2019-01-14T23:52:45+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:52:55+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:53:05+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:53:05+1100 Connection to/from tcp4:ip.is.hidden:443 was lost in a non-clean fashion: Connection to the other side was lost in a non-clean fashion: Connection lost.
    2019-01-14T23:53:05+1100 _connectionLost: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.
    ]
    2019-01-14T23:53:05+1100 WAMP-over-WebSocket transport lost: wasClean=False, code=1006, reason="connection was closed uncleanly (peer dropped the TCP connection without previous WebSocket closing handshake)"
    2019-01-14T23:53:05+1100 session leaving 'wamp.close.transport_lost'
    2019-01-14T23:53:05+1100 component failed: ApplicationError: ApplicationError(error=<wamp.close.transport_lost>, args=[], kwargs={}, enc_algo=None)
    2019-01-14T23:53:05+1100 Traceback (most recent call last):
    Failure: autobahn.wamp.exception.ApplicationError: ApplicationError(error=<wamp.close.transport_lost>, args=[], kwargs={}, enc_algo=None)

    2019-01-14T23:53:05+1100 wamp.close.transport_lost:
    2019-01-14T23:53:05+1100 session on_disconnect: was_clean=False
    2019-01-14T23:53:05+1100 Stopping factory <autobahn.twisted.websocket.WampWebSocketClientFactory object at 0x7f77224e09b0>
    2019-01-14T23:53:05+1100 Entering re-connect loop
    2019-01-14T23:53:05+1100 trying transport 0 using connect delay 2.3187428648299617
    2019-01-14T23:53:07+1100 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-14T23:53:07+1100 Starting factory <autobahn.twisted.websocket.WampWebSocketClientFactory object at 0x7f77224f20b8>
    2019-01-14T23:53:08+1100
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f772140e400>,
    'WampWebSocketClientFactory')]
    2019-01-14T23:53:08+1100 connection to tcp4:ip.is.hidden:443 established
    2019-01-14T23:53:08+1100 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: 2UMgYUlkqE6QtCj7KPbClw==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-14T23:53:08+1100 Connection made to tcp4:ip.is.hidden:443
    2019-01-14T23:53:08+1100 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 12:53:08 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: yKlxFCQtg+GVkjCV+YQ10X/+F9g=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-14T23:53:08+1100 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-14T23:53:08+1100 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 12:53:08 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': 'yKlxFCQtg+GVkjCV+YQ10X/+F9g=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-14T23:53:08+1100 openHandshakeTimeoutCall.cancel
    2019-01-14T23:53:08+1100 Entering on_join
    2019-01-14T23:53:08+1100 Subscribed
    2019-01-14T23:53:09+1100 Sleeping
    2019-01-14T23:53:18+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:53:28+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:53:36+1100 Publishing
    2019-01-14T23:53:36+1100 While notifying 'join': Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 1116, in _cbDeferred
    self.callback(self.resultList)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
    --- <exception caught here> ---
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
    File "/home/.../lib/python3.7/site-packages/txaio/tx.py", line 515, in completed
    value.raiseException()
    File "/home/.../lib/python3.7/site-packages/twisted/python/failure.py", line 467, in raiseException
    raise self.value.with_traceback(self.tb)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
    File "/home/.../lib/python3.7/site-packages/txaio/tx.py", line 515, in completed
    value.raiseException()
    File "/home/.../lib/python3.7/site-packages/twisted/python/failure.py", line 467, in raiseException
    raise self.value.with_traceback(self.tb)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
    File "bug-twisted-subscribe-and-do-nothing.py", line 37, in on_join
    yield session.publish("news", "Fake news", options=options)
    File "/home/.../lib/python3.7/site-packages/autobahn/wamp/protocol.py", line 1278, in publish
    raise exception.TransportLost()
    autobahn.wamp.exception.TransportLost:

    2019-01-14T23:53:36+1100 Unhandled error in Deferred:
    2019-01-14T23:53:36+1100 Traceback (most recent call last):
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 1116, in _cbDeferred
    self.callback(self.resultList)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
    --- <exception caught here> ---
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
    File "/home/.../lib/python3.7/site-packages/txaio/tx.py", line 515, in completed
    value.raiseException()
    File "/home/.../lib/python3.7/site-packages/twisted/python/failure.py", line 467, in raiseException
    raise self.value.with_traceback(self.tb)
    File "/home/.../lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
    File "bug-twisted-subscribe-and-do-nothing.py", line 37, in on_join
    yield session.publish("news", "Fake news", options=options)
    File "/home/.../lib/python3.7/site-packages/autobahn/wamp/protocol.py", line 1278, in publish
    raise exception.TransportLost()
    autobahn.wamp.exception.TransportLost:

    2019-01-14T23:53:38+1100 WebSocketProtocol.onPing(payload=<4 bytes>)
    2019-01-14T23:53:38+1100 Connection to/from tcp4:ip.is.hidden:443 was lost in a non-clean fashion: Connection to the other side was lost in a non-clean fashion: Connection lost.
    2019-01-14T23:53:38+1100 _connectionLost: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.
    ]
    2019-01-14T23:53:38+1100 WAMP-over-WebSocket transport lost: wasClean=False, code=1006, reason="connection was closed uncleanly (peer dropped the TCP connection without previous WebSocket closing handshake)"
    2019-01-14T23:53:38+1100 session leaving 'wamp.close.transport_lost'
    2019-01-14T23:53:38+1100 component failed: ApplicationError: ApplicationError(error=<wamp.close.transport_lost>, args=[], kwargs={}, enc_algo=None)
    2019-01-14T23:53:38+1100 Traceback (most recent call last):
    Failure: autobahn.wamp.exception.ApplicationError: ApplicationError(error=<wamp.close.transport_lost>, args=[], kwargs={}, enc_algo=None)

    2019-01-14T23:53:38+1100 wamp.close.transport_lost:
    2019-01-14T23:53:38+1100 session on_disconnect: was_clean=False
    2019-01-14T23:53:38+1100 Stopping factory <autobahn.twisted.websocket.WampWebSocketClientFactory object at 0x7f77224f20b8>
    2019-01-14T23:53:38+1100 Entering re-connect loop
    2019-01-14T23:53:38+1100 trying transport 0 using connect delay 3.0991769490630414
    2019-01-14T23:53:41+1100 connecting once using transport type "websocket" over endpoint "tcp"
    2019-01-14T23:53:41+1100 Starting factory <autobahn.twisted.websocket.WampWebSocketClientFactory object at 0x7f7721418f60>
    2019-01-14T23:53:41+1100
    [('logOctets', False, 'WampWebSocketClientFactory'),
    ('logFrames', False, 'WampWebSocketClientFactory'),
    ('trackTimings', False, 'WampWebSocketClientFactory'),
    ('utf8validateIncoming', True, 'WampWebSocketClientFactory'),
    ('applyMask', True, 'WampWebSocketClientFactory'),
    ('maxFramePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('maxMessagePayloadSize', 0, 'WampWebSocketClientFactory'),
    ('autoFragmentSize', 0, 'WampWebSocketClientFactory'),
    ('failByDrop', True, 'WampWebSocketClientFactory'),
    ('echoCloseCodeReason', False, 'WampWebSocketClientFactory'),
    ('openHandshakeTimeout', 5, 'WampWebSocketClientFactory'),
    ('closeHandshakeTimeout', 1, 'WampWebSocketClientFactory'),
    ('tcpNoDelay', True, 'WampWebSocketClientFactory'),
    ('autoPingInterval', 0, 'WampWebSocketClientFactory'),
    ('autoPingTimeout', 0, 'WampWebSocketClientFactory'),
    ('autoPingSize', 4, 'WampWebSocketClientFactory'),
    ('version', 18, 'WampWebSocketClientFactory'),
    ('acceptMaskedServerFrames', False, 'WampWebSocketClientFactory'),
    ('maskClientFrames', True, 'WampWebSocketClientFactory'),
    ('serverConnectionDropTimeout', 1, 'WampWebSocketClientFactory'),
    ('perMessageCompressionOffers', [], 'WampWebSocketClientFactory'),
    ('perMessageCompressionAccept',
    <function WebSocketClientFactory.resetProtocolOptions.<locals>.<lambda> at 0x7f77224a5d08>,
    'WampWebSocketClientFactory')]
    2019-01-14T23:53:41+1100 connection to tcp4:ip.is.hidden:443 established
    2019-01-14T23:53:41+1100 GET /link HTTP/1.1
    User-Agent: AutobahnPython/19.1.1
    Host: example.com:443
    Upgrade: WebSocket
    Connection: Upgrade
    Pragma: no-cache
    Cache-Control: no-cache
    Sec-WebSocket-Key: yuksG/xd3Fvl3Yx8XvqIqQ==
    Sec-WebSocket-Protocol: wamp.2.cbor,wamp.2.json
    Sec-WebSocket-Version: 13


    2019-01-14T23:53:41+1100 Connection made to tcp4:ip.is.hidden:443
    2019-01-14T23:53:41+1100 received HTTP response:

    b'HTTP/1.1 101 Switching Protocols\r\nServer: nginx\r\nDate: Mon, 14 Jan 2019 12:53:41 GMT\r\nConnection: upgrade\r\nUpgrade: WebSocket\r\nSec-WebSocket-Protocol: wamp.2.cbor\r\nSec-WebSocket-Accept: WI2kE5UD1zaD31Sh5WEqz/EjNiI=\r\nVia: 1.1 google\r\nAlt-Svc: clear\r\n\r\n'


    2019-01-14T23:53:41+1100 received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
    2019-01-14T23:53:41+1100 received HTTP headers in opening handshake : {'server': 'nginx', 'date': 'Mon, 14 Jan 2019 12:53:41 GMT', 'connection': 'upgrade', 'upgrade': 'WebSocket', 'sec-websocket-protocol': 'wamp.2.cbor', 'sec-websocket-accept': 'WI2kE5UD1zaD31Sh5WEqz/EjNiI=', 'via': '1.1 google', 'alt-svc': 'clear'}
    2019-01-14T23:53:41+1100 openHandshakeTimeoutCall.cancel
    2019-01-14T23:53:42+1100 Entering on_join
    2019-01-14T23:53:42+1100 Subscribed
    2019-01-14T23:53:42+1100 Sleeping