search

crossbario / crossbar

Crossbar.io - WAMP application router
https://crossbar.io/
Other
2.05k stars 274 forks source link

Can't establish TCP RawSocket connection #856

Closed chiefmc closed 7 years ago

chiefmc commented 8 years ago

I'm facing trouble while trying to connect clients (PHP Thruway and AutobahnJS on nodejs) via tcp RawSocket. Meanwhile WebSocket works well.

Crossbar v0.13.2 installed on FreeBSD 10.1

Here's what i see in Crossbar's output:

2016-08-09T09:27:19+0000 [Router      15174] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/opt/crossbar/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/opt/crossbar/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/opt/crossbar/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/crossbar/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/opt/crossbar/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/opt/crossbar/site-packages/twisted/internet/tcp.py", line 209, in doRead
    return self._dataReceived(data)
  File "/opt/crossbar/site-packages/twisted/internet/tcp.py", line 215, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/opt/crossbar/site-packages/autobahn/twisted/rawsocket.py", line 191, in dataReceived
    self.abort()
  File "/opt/crossbar/site-packages/autobahn/twisted/rawsocket.py", line 169, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-08-09T09:27:19+0000 [Router      15174] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/opt/crossbar/site-packages/twisted/python/log.py:101:callWithLogger
/opt/crossbar/site-packages/twisted/python/log.py:84:callWithContext
/opt/crossbar/site-packages/twisted/python/context.py:118:callWithContext
/opt/crossbar/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/opt/crossbar/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/opt/crossbar/site-packages/twisted/internet/tcp.py:209:doRead
/opt/crossbar/site-packages/twisted/internet/tcp.py:215:_dataReceived
/opt/crossbar/site-packages/autobahn/twisted/rawsocket.py:191:dataReceived
/opt/crossbar/site-packages/autobahn/twisted/rawsocket.py:169:abort
]'
2016-08-09T09:27:19+0000 [Router      15174] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
hawkowl commented 8 years ago

@chiefmc From reading the source, it appears this is because an invalid magic octet is being sent -- could you try running with debug logging (--loglevel=debug) and seeing what it says? It might have "WampRawSocketProtocol: invalid magic byte" in it which might give us more clues...

chiefmc commented 8 years ago

@hawkowl will do and get back to you with details

chiefmc commented 7 years ago

Here's the debug output I'm having:

/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:17+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:19+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:19+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:19+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:19+0300 [Router      78590 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:19+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:19+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:20+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:20+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:20+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:20+0300 [Router      78590 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:20+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:20+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:22+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:22+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:22+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:22+0300 [Router      78590 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:22+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:22+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:22+0300 [Controller  78585 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 245, 'bytes': 347313}, 3: {'count': 13, 'bytes': 3687}}
2016-09-20T18:26:23+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:23+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:23+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:23+0300 [Router      78590 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:23+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:23+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:25+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:25+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:25+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:25+0300 [Router      78590 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:25+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:25+0300 [Router      78590 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
^C2016-09-20T18:26:26+0300 [Controller  78585 log_legacy] Received SIGINT, shutting down.
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process._cleanup_worker] sending TERM to subprocess 78590
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process._cleanup_worker] waiting for 78590 to exit...
2016-09-20T18:26:26+0300 [Router      78590 __main__.run] Ignoring SIGINT in worker.
2016-09-20T18:26:26+0300 [Router      78590 crossbar.worker.worker.NativeWorkerSession] Native worker received SIGTERM - shutting down ..
2016-09-20T18:26:26+0300 [Router      78590 crossbar.worker.worker.NativeWorkerSession] Shutdown of worker requested!
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.router.Router] Validate 'event' for 'crossbar.node.cb_node1.worker.cb_router1.on_shutdown_requested'
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.on_shutdown_requested publish
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.router.Router] Authorized action 'publish' for URI 'crossbar.node.cb_node1.worker.cb_router1.on_shutdown_requested' by session 1231245295912902 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:26+0300 [Router      78590 crossbar.worker.worker.NativeWorkerSession] Worker-to-controller session detached
2016-09-20T18:26:26+0300 [Router      78590 autobahn.twisted.websocket.WebSocketAdapterProtocol] connection closed properly: canceling closing handshake timeout
2016-09-20T18:26:26+0300 [Router      78590 autobahn.twisted.websocket.WebSocketAdapterProtocol] dropping connection: None
2016-09-20T18:26:26+0300 [Router      78590 __main__.run] Connection to node controller closed cleanly
2016-09-20T18:26:26+0300 [Router      78590 autobahn.twisted.websocket.WebSocketAdapterProtocol] Connection to/from <pipe> was closed cleanly
2016-09-20T18:26:26+0300 [Router      78590 autobahn.twisted.websocket.WebSocketAdapterProtocol] _connectionLost: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
]
2016-09-20T18:26:26+0300 [Router      78590 autobahn.twisted.websocket.WebSocketAdapterProtocol] WAMP-over-WebSocket transport lost: wasClean=True, code=1000, reason="None"
2016-09-20T18:26:26+0300 [Router      78590 crossbar.worker.worker.NativeWorkerSession] Worker-to-controller session disconnected
2016-09-20T18:26:26+0300 [Router      78590 log_legacy] (TCP Port 8080 Closed)
2016-09-20T18:26:26+0300 [Router      78590 log_legacy] (TCP Port 8000 Closed)
2016-09-20T18:26:26+0300 [Router      78590 log_legacy] (TCP Port 8001 Closed)
2016-09-20T18:26:26+0300 [Router      78590 log_legacy] (TCP Port 8081 Closed)
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.native.NativeWorkerClientProtocol] Native worker connection closed cleanly.
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.native.NativeWorkerClientProtocol] Connection to/from process:78590 was closed cleanly
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.native.NativeWorkerClientProtocol] _connectionLost: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.
]
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.native.NativeWorkerClientProtocol] WAMP-over-WebSocket transport lost: wasClean=True, code=1000, reason="None"
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process.NodeControllerSession] Node worker cb_router1 ended successfully
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process.NodeControllerSession] Node worker ended, and trigger 'shutdown_on_worker_exit' active
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process.NodeControllerSession] Node shutting down ..
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process.NodeControllerSession] Shutting down node...
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.router.Router] Validate 'event' for 'crossbar.node.cb_node1.on_shutdown'
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.on_shutdown publish
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.router.router.Router] Authorized action 'publish' for URI 'crossbar.node.cb_node1.on_shutdown' by session 3369421854390448 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:26+0300 [Controller  78585 crossbar.controller.process._cleanup_worker] 78590 exited
root@testenv:/home/crossbar/authentication-service# clear
root@testenv:/home/crossbar/authentication-service# crossbar start --loglevel=debug
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start] Node key already exists (public key: af4d3c04e75ef29cba066fc724f649b5317fd7aad7d06775c1724fe886bda414)
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]      __  __  __  __  __  __      __     __
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]     /  `|__)/  \/__`/__`|__) /\ |__)  |/  \
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]     \__,|  \\__/.__/.__/|__)/~~\|  \. |\__/
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]     Crossbar.io Version: 0.15.0
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]     Node Public Key: af4d3c04e75ef29cba066fc724f649b5317fd7aad7d06775c1724fe886bda414
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start]
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start] Running from node directory '/usr/home/crossbar/authentication-service/.crossbar'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.cli.run_command_start] Controller process starting (PyPy-KQueueReactor) ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.node.Node] Loading node configuration from '/usr/home/crossbar/authentication-service/.crossbar/config.json' ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking controller item ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking worker item 0 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking realm item 0 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking transport item 0 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking transport item 1 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking transport item 2 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.common.checkconfig] Checking transport item 3 ..
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.node.Node] Node configuration loaded from 'config.json'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.node.Node] Node ID 'cb_node1' set from config
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.node.Node] Using default node shutdown triggers [u'shutdown_on_worker_exit']
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.RouterFactory] CrossbarRouterFactory.start_realm(realm = <crossbar.worker.router.RouterRealm object at 0x000000080b7d3a28>)
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.RouterFactory] Router created for realm 'crossbar'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] attaching non-client session <crossbar.router.service.RouterServiceSession object at 0x000000080b7d3a60>
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.service.RouterServiceSession] Router service session attached: SessionDetails(realm=<crossbar>, session=7919599894691866, authid=<None>, authrole=<trusted>, authmethod=None, authprovider=None, authextra=None)
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.count_callees register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.count_callees' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.get register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.get' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.list register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.list' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.list_callees register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.list_callees' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.lookup register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.lookup' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.match register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.match' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.remove_callee register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.remove_callee' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.schema.define register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.schema.define' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.schema.describe register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.schema.describe' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.count register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.count' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.get register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.get' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.kill register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.kill' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.list register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.list' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.count_subscribers register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.count_subscribers' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.get register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.get' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.get_events register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.get_events' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.list register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.list' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.list_subscribers register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.list_subscribers' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.lookup register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.lookup' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.match register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.match' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.remove_subscriber register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.remove_subscriber' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.test.exception register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.test.exception' by session 7919599894691866 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.service.RouterServiceSession] Registered 22 procedures
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Connected to node management router
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] attaching non-client session <crossbar.controller.process.NodeControllerSession object at 0x0000000809703e88>
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Joined realm 'crossbar' on node management router
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.on_worker_ready subscribe
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'subscribe' for URI 'crossbar.node.cb_node1.on_worker_ready' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.start_manhole'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_manhole register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_manhole' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.stop_manhole'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_manhole register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_manhole' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.get_manhole'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_manhole register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_manhole' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.start_connection'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_connection register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_connection' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.stop_connection'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_connection register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_connection' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.get_connections'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_connections register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_connections' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.trigger_gc'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.trigger_gc register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.trigger_gc' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.utcnow'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.utcnow register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.utcnow' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.started'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.started register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.started' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.uptime'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.uptime register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.uptime' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.get_process_info'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_process_info register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_process_info' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.get_process_stats'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_process_stats register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_process_stats' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering procedure 'crossbar.node.cb_node1.set_process_stats_monitoring'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.set_process_stats_monitoring register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.set_process_stats_monitoring' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registered 13 procedures
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.get_info
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_info register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_info' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.shutdown
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.shutdown register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.shutdown' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.get_workers
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_workers register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_workers' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.get_worker_log
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.get_worker_log register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.get_worker_log' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.start_router
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_router register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_router' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.stop_router
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_router register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_router' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.start_container
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_container register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_container' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.stop_container
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_container register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_container' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.start_guest
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_guest register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_guest' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.stop_guest
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_guest register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_guest' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.start_websocket_testee
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.start_websocket_testee register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.start_websocket_testee' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registering management API procedure crossbar.node.cb_node1.stop_websocket_testee
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.stop_websocket_testee register
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.stop_websocket_testee' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Registered 12 management API procedures
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Node controller ready
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.node.Node] No WAMPlets detected in enviroment.
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] NodeControllerSession.start_router(cb_router1, options=OrderedDict([(u'title', u'crossbar-worker [router]')]))
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Starting Router with ID 'cb_router1'...
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Router 'cb_router1' command line is '/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/bin/pypy -u -m crossbar.worker.process --cbdir /usr/home/crossbar/authentication-service/.crossbar --node cb_node1 --worker cb_router1 --realm crossbar --type router --loglevel debug --title crossbar-worker [router]'
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol]
[('logOctets', False, 'NativeWorkerClientFactory'),
 ('logFrames', False, 'NativeWorkerClientFactory'),
 ('trackTimings', False, 'NativeWorkerClientFactory'),
 ('utf8validateIncoming', True, 'NativeWorkerClientFactory'),
 ('applyMask', True, 'NativeWorkerClientFactory'),
 ('maxFramePayloadSize', 0, 'NativeWorkerClientFactory'),
 ('maxMessagePayloadSize', 0, 'NativeWorkerClientFactory'),
 ('autoFragmentSize', 0, 'NativeWorkerClientFactory'),
 ('failByDrop', False, 'NativeWorkerClientFactory'),
 ('echoCloseCodeReason', False, 'NativeWorkerClientFactory'),
 ('openHandshakeTimeout', 60, 'NativeWorkerClientFactory'),
 ('closeHandshakeTimeout', 5, 'NativeWorkerClientFactory'),
 ('tcpNoDelay', True, 'NativeWorkerClientFactory'),
 ('autoPingInterval', 0, 'NativeWorkerClientFactory'),
 ('autoPingTimeout', 0, 'NativeWorkerClientFactory'),
 ('autoPingSize', 4, 'NativeWorkerClientFactory'),
 ('version', 18, 'NativeWorkerClientFactory'),
 ('acceptMaskedServerFrames', False, 'NativeWorkerClientFactory'),
 ('maskClientFrames', True, 'NativeWorkerClientFactory'),
 ('serverConnectionDropTimeout', 1, 'NativeWorkerClientFactory'),
 ('perMessageCompressionOffers', [], 'NativeWorkerClientFactory'),
 ('perMessageCompressionAccept',
  <function <lambda> at 0x0000000807b7f880>,
  'NativeWorkerClientFactory')]
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] connection to process:78603 established
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] GET / HTTP/1.1
User-Agent: AutobahnPython/0.16.0
Host: localhost:80
Upgrade: WebSocket
Connection: Upgrade
Pragma: no-cache
Cache-Control: no-cache
Sec-WebSocket-Key: VGh4CCx00bNoJuHI2yQdAA==
Sec-WebSocket-Protocol: wamp.2.cbor.batched,wamp.2.cbor,wamp.2.msgpack.batched,wamp.2.msgpack,wamp.2.ubjson.batched,wamp.2.ubjson,wamp.2.json.batched,wamp.2.json
Sec-WebSocket-Version: 13

2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] Connection made to process:78603
2016-09-20T18:26:34+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Native worker process connected with PID 78603
2016-09-20T18:26:35+0300 [Router      78603 autobahn.twisted.choosereactor.install_reactor] Automatically choosing optimal Twisted reactor
2016-09-20T18:26:36+0300 [Router      78603 autobahn.twisted.choosereactor.install_optimal_reactor] Running on *BSD or MacOSX and optimal reactor (kqueue) was installed.
2016-09-20T18:26:36+0300 [Router      78603 __main__.run] Worker process starting (PyPy-KQueueReactor) ..
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol]
[('logOctets', False, 'WampWebSocketServerFactory'),
 ('logFrames', False, 'WampWebSocketServerFactory'),
 ('trackTimings', False, 'WampWebSocketServerFactory'),
 ('utf8validateIncoming', True, 'WampWebSocketServerFactory'),
 ('applyMask', True, 'WampWebSocketServerFactory'),
 ('maxFramePayloadSize', 0, 'WampWebSocketServerFactory'),
 ('maxMessagePayloadSize', 0, 'WampWebSocketServerFactory'),
 ('autoFragmentSize', 0, 'WampWebSocketServerFactory'),
 ('failByDrop', False, 'WampWebSocketServerFactory'),
 ('echoCloseCodeReason', False, 'WampWebSocketServerFactory'),
 ('openHandshakeTimeout', 5, 'WampWebSocketServerFactory'),
 ('closeHandshakeTimeout', 1, 'WampWebSocketServerFactory'),
 ('tcpNoDelay', True, 'WampWebSocketServerFactory'),
 ('autoPingInterval', 0, 'WampWebSocketServerFactory'),
 ('autoPingTimeout', 0, 'WampWebSocketServerFactory'),
 ('autoPingSize', 4, 'WampWebSocketServerFactory'),
 ('versions', [8, 13], 'WampWebSocketServerFactory'),
 ('webStatus', True, 'WampWebSocketServerFactory'),
 ('requireMaskedClientFrames', True, 'WampWebSocketServerFactory'),
 ('maskServerFrames', False, 'WampWebSocketServerFactory'),
 ('perMessageCompressionAccept',
  <function <lambda> at 0x000000080a611010>,
  'WampWebSocketServerFactory'),
 ('serveFlashSocketPolicy', False, 'WampWebSocketServerFactory'),
 ('flashSocketPolicy',
  u'<cross-domain-policy>\n     <allow-access-from domain="*" to-ports="*" />\n</cross-domain-policy>\x00',
  'WampWebSocketServerFactory'),
 ('allowedOrigins', ['*'], 'WampWebSocketServerFactory'),
 ('allowedOriginsPatterns',
  [<SRE_Pattern object at 0x0000000808c16ca0>],
  'WampWebSocketServerFactory'),
 ('allowNullOrigin', False, 'WampWebSocketServerFactory'),
 ('maxConnections', 0, 'WampWebSocketServerFactory')]
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] connection accepted from peer <pipe>
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] Connection made to <pipe>
2016-09-20T18:26:37+0300 [Router      78603 __main__.run] Entering event loop...
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] received HTTP request:

GET / HTTP/1.1
User-Agent: AutobahnPython/0.16.0
Host: localhost:80
Upgrade: WebSocket
Connection: Upgrade
Pragma: no-cache
Cache-Control: no-cache
Sec-WebSocket-Key: VGh4CCx00bNoJuHI2yQdAA==
Sec-WebSocket-Protocol: wamp.2.cbor.batched,wamp.2.cbor,wamp.2.msgpack.batched,wamp.2.msgpack,wamp.2.ubjson.batched,wamp.2.ubjson,wamp.2.json.batched,wamp.2.json
Sec-WebSocket-Version: 13

2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] received HTTP status line in opening handshake : GET / HTTP/1.1
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] received HTTP headers in opening handshake : {u'user-agent': u'AutobahnPython/0.16.0', u'host': u'localhost:80', u'upgrade': u'WebSocket', u'connection': u'Upgrade', u'pragma': u'no-cache', u'cache-control': u'no-cache', u'sec-websocket-key': u'VGh4CCx00bNoJuHI2yQdAA==', u'sec-websocket-protocol': u'wamp.2.cbor.batched,wamp.2.cbor,wamp.2.msgpack.batched,wamp.2.msgpack,wamp.2.ubjson.batched,wamp.2.ubjson,wamp.2.json.batched,wamp.2.json', u'sec-websocket-version': u'13'}
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] Hybi protocol detected
2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] sending HTTP response:

HTTP/1.1 101 Switching Protocols
Server: AutobahnPython/0.16.0
Upgrade: WebSocket
Connection: Upgrade
Sec-WebSocket-Protocol: wamp.2.cbor.batched
Sec-WebSocket-Accept: NbCxaZJZf6SfD/Upa69a1d+ly1E=

2016-09-20T18:26:37+0300 [Router      78603 autobahn.twisted.websocket.WebSocketAdapterProtocol] openHandshakeTimeoutCall.cancel
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Using Web templates from /root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/crossbar/web/templates
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] received HTTP response:

HTTP/1.1 101 Switching Protocols
Server: AutobahnPython/0.16.0
Upgrade: WebSocket
Connection: Upgrade
Sec-WebSocket-Protocol: wamp.2.cbor.batched
Sec-WebSocket-Accept: NbCxaZJZf6SfD/Upa69a1d+ly1E=

2016-09-20T18:26:37+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] received HTTP headers in opening handshake : {u'server': u'AutobahnPython/0.16.0', u'upgrade': u'WebSocket', u'connection': u'Upgrade', u'sec-websocket-protocol': u'wamp.2.cbor.batched', u'sec-websocket-accept': u'NbCxaZJZf6SfD/Upa69a1d+ly1E='}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.controller.native.NativeWorkerClientProtocol] openHandshakeTimeoutCall.cancel
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.session.RouterSession] Client session connected - transport: None
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.start_manhole'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.stop_manhole'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.get_manhole'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.start_connection'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.stop_connection'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.get_connections'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.trigger_gc'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.utcnow'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.started'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.uptime'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.get_process_info'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.get_process_stats'
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering procedure 'crossbar.node.cb_node1.worker.cb_router1.set_process_stats_monitoring'
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_manhole register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_manhole' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_manhole register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_manhole' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_manhole register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_manhole' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_connection register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_connection' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_connection register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_connection' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_connections register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_connections' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.trigger_gc register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.trigger_gc' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.utcnow register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.utcnow' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.started register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.started' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.uptime register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.uptime' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_process_info register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_process_info' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_process_stats register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_process_stats' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.set_process_stats_monitoring register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.set_process_stats_monitoring' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registered 13 procedures
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.shutdown
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_cpu_count
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_cpu_affinity
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.set_cpu_affinity
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_pythonpath
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.add_pythonpath
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_profilers
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_profiler
2016-09-20T18:26:37+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_profile
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.shutdown register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.shutdown' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_cpu_count register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_cpu_count' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_cpu_affinity register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_cpu_affinity' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.set_cpu_affinity register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.set_cpu_affinity' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_pythonpath register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_pythonpath' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.add_pythonpath register
2016-09-20T18:26:37+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.add_pythonpath' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_profilers register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_profilers' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_profiler register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_profiler' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_profile register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_profile' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registered 9 management API procedures
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_router_realms
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_router_realm
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.stop_router_realm
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_router_realm_roles
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_role
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_router_realm_uplinks
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_router_realm_uplink
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_uplink
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_router_components
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_router_component
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.stop_router_component
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.get_router_transports
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.start_router_transport
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registering management API procedure crossbar.node.cb_node1.worker.cb_router1.stop_router_transport
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_router_realms register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_router_realms' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_router_realm register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_router_realm' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_router_realm_roles register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_router_realm_roles' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_role register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_role' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_router_realm_uplinks register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_router_realm_uplinks' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm_uplink register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_uplink' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_uplink register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_router_realm_uplink' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_router_components register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_router_components' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_component register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_component' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_router_component register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_router_component' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.get_router_transports register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.get_router_transports' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_transport register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.stop_router_transport register
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'register' for URI 'crossbar.node.cb_node1.worker.cb_router1.stop_router_transport' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Registered 15 management API procedures
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'event' for 'crossbar.node.cb_node1.on_worker_ready'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.on_worker_ready publish
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'publish' for URI 'crossbar.node.cb_node1.on_worker_ready' by session 1950699134625541 with authid 'dummy' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.process.NodeControllerSession] Router with ID 'cb_router1' and PID 78603 started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 20, 'bytes': 19167}, 3: {'count': 5, 'bytes': 3583}}
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Worker 'cb_node1' running as PID 78603
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_realm
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.RouterFactory] CrossbarRouterFactory.start_realm(realm = <crossbar.worker.router.RouterRealm object at 0x000000080ad4f5c8>)
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.RouterFactory] Router created for realm 'vticket'
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] attaching non-client session <crossbar.router.service.RouterServiceSession object at 0x000000080ad4f600>
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.service.RouterServiceSession] Router service session attached: SessionDetails(realm=<vticket>, session=8513450335703741, authid=<None>, authrole=<trusted>, authmethod=None, authprovider=None, authextra=None)
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.count_callees register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.count_callees' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.get register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.get' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.list register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.list' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.list_callees register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.list_callees' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.lookup register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.lookup' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.match register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.match' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.registration.remove_callee register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.registration.remove_callee' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.schema.define register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.schema.define' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.schema.describe register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.schema.describe' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.count register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.count' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.get register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.get' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.kill register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.kill' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.session.list register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.session.list' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.count_subscribers register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.count_subscribers' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.get register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.get' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.get_events register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.get_events' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.list register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.list' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.list_subscribers register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.list_subscribers' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.lookup register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.lookup' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.match register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.match' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.subscription.remove_subscriber register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.subscription.remove_subscriber' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted wamp.test.exception register
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] Authorized action 'register' for URI 'wamp.test.exception' by session 8513450335703741 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.service.RouterServiceSession] Registered 22 procedures
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Realm 'vticket' started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': realm 'realm-001' (named 'vticket') started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_realm_role
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.RouterFactory] CrossbarRouterFactory.add_role(realm = vticket, config = {u'name': u'anonymous', u'permissions': [{u'uri': u'*', u'allow': {u'call': True, u'register': True, u'publish': True, u'subscribe': True}, u'disclose': {u'caller': True, u'publisher': True}, u'cache': True}]})
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] CrossbarRouter.add_role(<crossbar.router.role.RouterRoleStaticAuth object at 0x000000080adf9018>)
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': role 'role-001' (named 'anonymous') started on realm 'realm-001'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_realm_role
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.RouterFactory] CrossbarRouterFactory.add_role(realm = vticket, config = {u'name': u'user-admin', u'permissions': [{u'uri': u'*', u'allow': {u'call': True, u'register': False, u'publish': False, u'subscribe': True}, u'disclose': {u'caller': True, u'publisher': False}, u'cache': True}]})
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] CrossbarRouter.add_role(<crossbar.router.role.RouterRoleStaticAuth object at 0x000000080adf9050>)
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': role 'role-002' (named 'user-admin') started on realm 'realm-001'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_realm_role
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.RouterFactory] CrossbarRouterFactory.add_role(realm = vticket, config = {u'name': u'authenticator', u'permissions': [{u'uri': u'com.vticket.authenticate', u'match': u'exact', u'allow': {u'call': False, u'register': True, u'publish': False, u'subscribe': False}, u'disclose': {u'caller': False, u'publisher': False}, u'cache': True}]})
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.router.Router] CrossbarRouter.add_role(<crossbar.router.role.RouterRoleStaticAuth object at 0x000000080ae163d8>)
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_realm_role'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': role 'role-003' (named 'authenticator') started on realm 'realm-001'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_transport call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_transport
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Starting websocket-transport on router.
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.cookiestore.CookieStore] Cookie stored created with config {u'name': u'cbtid', u'length': 24, u'max_age': 86400, u'store': {u'type': u'file', u'filename': u'cookies.dat'}}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.cookiestore.CookieStore] File-backed cookie store already exists
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.cookiestore.CookieStore] Loaded 2 cookie records from file. Cookie store has 1 entries.
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.protocol.WampWebSocketServerFactory] File-backed cookie store active /usr/home/crossbar/authentication-service/.crossbar/cookies.dat
2016-09-20T18:26:38+0300 [Router      78603 log_legacy] WampWebSocketServerFactory starting on 8080
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Router transport 'transport-001'' started and listening
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': transport 'transport-001' started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_transport call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_transport
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Starting websocket-transport on router.
2016-09-20T18:26:38+0300 [Router      78603 log_legacy] WampWebSocketServerFactory starting on 8000
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Router transport 'transport-002'' started and listening
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': transport 'transport-002' started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_transport call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_transport
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Starting rawsocket-transport on router.
2016-09-20T18:26:38+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerFactory] RawSocket transport factory created using [<autobahn.wamp.serializer.MsgPackSerializer object at 0x000000080af60d78>, <autobahn.wamp.serializer.JsonSerializer object at 0x000000080af60db0>] serializers, max. message size 131072
2016-09-20T18:26:38+0300 [Router      78603 log_legacy] WampRawSocketServerFactory starting on 8001
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Router transport 'transport-003'' started and listening
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': transport 'transport-003' started
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.role.RouterRole] CrossbarRouterTrustedRole.authorize trusted crossbar.node.cb_node1.worker.cb_router1.start_router_transport call
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Authorized action 'call' for URI 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport' by session 6137071485341417 with authid 'None' and authrole 'trusted' -> authorization: {u'allow': True, u'cache': False, u'disclose': False}
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] RouterWorkerSession.start_router_transport
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Starting web-transport on router.
2016-09-20T18:26:38+0300 [Router      78603 crossbar.twisted.resource.WampLongPollResource] WampLongPollResource initialized
2016-09-20T18:26:38+0300 [Router      78603 log_legacy] Site starting on 8081
2016-09-20T18:26:38+0300 [Router      78603 crossbar.worker.worker.NativeWorkerSession] Router transport 'transport-004'' started and listening
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.router.router.Router] Validate 'call_result' for 'crossbar.node.cb_node1.worker.cb_router1.start_router_transport'
2016-09-20T18:26:38+0300 [Controller  78598 crossbar.controller.node.Node] Router 'cb_router1': transport 'transport-004' started

2016-09-20T18:26:43+0300 [Controller  78598 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 56, 'bytes': 47827}, 3: {'count': 13, 'bytes': 3687}}
^[^[2016-09-20T18:26:48+0300 [Controller  78598 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 56, 'bytes': 47827}, 3: {'count': 13, 'bytes': 3687}}
2016-09-20T18:26:52+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:52+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:52+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:52+0300 [Router      78603 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:52+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:52+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:53+0300 [Controller  78598 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 61, 'bytes': 53938}, 3: {'count': 13, 'bytes': 3687}}
2016-09-20T18:26:53+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:53+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:53+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:53+0300 [Router      78603 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:53+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:53+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:55+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-20T18:26:55+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 00000161
2016-09-20T18:26:55+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x00, but expected 0x7f
2016-09-20T18:26:55+0300 [Router      78603 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-20T18:26:55+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-20T18:26:55+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-20T18:26:56+0300 [Router      78603 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
chiefmc commented 7 years ago

must mention that last output is from v0.15

oberstet commented 7 years ago

@chiefmc what client library?

chiefmc commented 7 years ago

Sorry, it is the PHP-Thruway

oberstet commented 7 years ago

Likely a bug in Thruway - pls report there. You can try AutobahnPython or AutobahnC++ ..

chiefmc commented 7 years ago

I don't think so, as the error is still there while trying to connect from AutobahnJS 0.10 on NodeJS.

Here's the debug output from crossbar:

2016-09-21T14:51:22+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-21T14:51:22+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 47455420
2016-09-21T14:51:22+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x47, but expected 0x7f
2016-09-21T14:51:22+0300 [Router      89177 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-21T14:51:22+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-21T14:51:22+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-21T14:51:23+0300 [Controller  89172 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 84, 'bytes': 122060}, 3: {'count': 13, 'bytes': 3687}}
2016-09-21T14:51:24+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-21T14:51:24+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 47455420
2016-09-21T14:51:24+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x47, but expected 0x7f
2016-09-21T14:51:24+0300 [Router      89177 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-21T14:51:24+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-21T14:51:24+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-21T14:51:28+0300 [Controller  89172 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 89, 'bytes': 128168}, 3: {'count': 13, 'bytes': 3687}}
2016-09-21T14:51:29+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection made
2016-09-21T14:51:29+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: opening handshake received - 47455420
2016-09-21T14:51:29+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: invalid magic byte (octet 1) in opening handshake: was 0x47, but expected 0x7f
2016-09-21T14:51:29+0300 [Router      89177 log_legacy] An exception was raised from application code while processing a reactor selectable
Traceback (most recent call last):
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 101, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py", line 84, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py", line 293, in _doWriteOrRead
    why = selectable.doRead()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 208, in doRead
    return self._dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py", line 214, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 200, in dataReceived
    self.abort()
  File "/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py", line 171, in abort
    raise TransportLost()
autobahn.wamp.exception.TransportLost:

2016-09-21T14:51:29+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: connection lost: reason = '[Failure instance: Traceback: <class 'autobahn.wamp.exception.TransportLost'>:
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:101:callWithLogger
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/log.py:84:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:118:callWithContext
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/python/context.py:81:callWithContext
--- <exception caught here> ---
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/kqreactor.py:293:_doWriteOrRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:208:doRead
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/twisted/internet/tcp.py:214:_dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:200:dataReceived
/root/pypy-c-jit-79841-9c3d2bdbb1fa-freebsd64/site-packages/autobahn/twisted/rawsocket.py:171:abort
]'
2016-09-21T14:51:29+0300 [Router      89177 crossbar.router.protocol.WampRawSocketServerProtocol] WampRawSocketProtocol: ApplicationSession.onClose raised ('NoneType' object has no attribute 'onClose')
2016-09-21T14:51:33+0300 [Controller  89172 crossbar.controller.processtypes.RouterWorkerProcess] Worker cb_router1 -> Controller traffic: {2: {'count': 91, 'bytes': 134276}, 3: {'count': 13, 'bytes': 3687}}
oberstet commented 7 years ago

As said, try AutobahnPython or AutobahnC++