search

crossbario / crossbar

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

Attempt to send on a closed protocol #1717

Closed oberstet closed 2 years ago

oberstet commented 4 years ago

when router workers are stopped dynamically (that is in CrossbarFX with edge and master nodes), the following happens - this is not actually doing any harm, but nevertheless wrong and annoying;)

from https://travis-ci.com/crossbario/crossbarfx/jobs/291278202#L2192

2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Stopping router worker with ID 'worker0'
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Router      21255] Native worker received SIGTERM - shutting down ..
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Router      21255] Shutdown of worker requested!
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Router      21255] Connection to node controller closed cleanly
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Unhandled error in Deferred:
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Traceback (most recent call last):
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/crossbar/router/router.py", line 317, in process
2020-02-26T12:05:17+0100     self._broker.processPublish(session, msg)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/crossbar/router/broker.py", line 733, in processPublish
2020-02-26T12:05:17+0100     txaio.add_callbacks(d, on_authorize_success, on_authorize_error)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/txaio/tx.py", line 443, in add_callbacks
2020-02-26T12:05:17+0100     future.addCallbacks(callback, errback)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/twisted/internet/defer.py", line 311, in addCallbacks
2020-02-26T12:05:17+0100     self._runCallbacks()
2020-02-26T12:05:17+0100 --- <exception caught here> ---
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-02-26T12:05:17+0100     current.result = callback(current.result, *args, **kw)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/crossbar/router/broker.py", line 531, in on_authorize_success
2020-02-26T12:05:17+0100     self._router.send(session, reply)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/crossbar/router/router.py", line 293, in send
2020-02-26T12:05:17+0100     session._transport.send(msg)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/autobahn/wamp/websocket.py", line 125, in send
2020-02-26T12:05:17+0100     self.sendMessage(payload, isBinary)
2020-02-26T12:05:17+0100   File "/home/oberstet/scm/crossbario/crossbarfx/.tox/functests-cfc/lib/python3.8/site-packages/autobahn/websocket/protocol.py", line 2190, in sendMessage
2020-02-26T12:05:17+0100     raise Disconnected("Attempt to send on a closed protocol")
2020-02-26T12:05:17+0100 autobahn.exception.Disconnected: Attempt to send on a closed protocol
2020-02-26T12:05:17+0100 
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Router      21255] (TCP Port 8080 Closed)
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Native worker connection closed cleanly.
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Router.detach(session=1306754022279804)
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Router.detach(session=1306754022279804): detached sessions [1306754022279804] from router realm "crossbar"
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Node worker worker0 ended successfully
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Checking for node shutdown: worker_exit_success=True, shutdown_requested=False, node_shutdown_triggers=['shutdown_on_shutdown_requested']
2020-02-26T12:05:17+0100 2020-02-26T12:05:17+0100 [Controller  21122] Node will continue to run!
2020-02-26T12:05:17+0100 {'id': 'worker0', 'type': 'router', 'kill': False, 'who': 4923781879069267, 'when': '2020-02-26T11:05:17.383Z'}
tomatoishealthy commented 4 years ago

same problem, anyone here?

oberstet commented 2 years ago

fixed on 22.4.1, everything is closed properly (there is a guard in the code now that prevents sending close on closed session). here is an example node shutdown of a now with multiple workers

^C2022-05-06T01:23:03+0200 [Controller 148376] Controller received SIGINT [signal=2]: shutting down node [shutdown_was_clean=True] ..
2022-05-06T01:23:03+0200 [Controller 148376] Node shutdown requested (restart=False, mode=None, reactor.running=True) ..
2022-05-06T01:23:03+0200 [Controller 148376] FabricNodeControllerSession._shutdown(restart=False, mode=None)
2022-05-06T01:23:03+0200 [Controller 148376] Stopping management uplink ..
2022-05-06T01:23:03+0200 [Controller 148376] NodeManagementBridgeSession.detach_manager: manager detached for node "None" on management realm "None")
2022-05-06T01:23:03+0200 [Controller 148376] <autobahn.twisted.websocket.WebSocketAdapterProtocol.connectionLost> connection lost for peer="tcp4:127.0.0.1:9000", closed cleanly
2022-05-06T01:23:03+0200 [Controller 148376] sending TERM to subprocess 149368
2022-05-06T01:23:03+0200 [Controller 148376] waiting for 149368 to exit...
2022-05-06T01:23:03+0200 [Controller 148376] sending TERM to subprocess 149393
2022-05-06T01:23:03+0200 [Controller 148376] waiting for 149393 to exit...
2022-05-06T01:23:03+0200 [Controller 148376] sending TERM to subprocess 149420
2022-05-06T01:23:03+0200 [Controller 148376] waiting for 149420 to exit...
2022-05-06T01:23:03+0200 [Proxy      149368] Native worker received SIGTERM - shutting down ..
2022-05-06T01:23:03+0200 [Proxy      149368] Shutdown of worker requested!
2022-05-06T01:23:03+0200 [Proxy      149393] Native worker received SIGTERM - shutting down ..
2022-05-06T01:23:03+0200 [Proxy      149393] Shutdown of worker requested!
2022-05-06T01:23:03+0200 [Router     149420] Native worker received SIGTERM - shutting down ..
2022-05-06T01:23:03+0200 [Router     149420] Shutdown of worker requested!
2022-05-06T01:23:03+0200 [Controller 148376] Router detached session from realm "crossbar" (session=2882582614785130, detached_session_ids=1, authid="crossbar.process.149420", authrole="crossbar.worker.group1_1", authmethod="trusted", authprovider="programcode") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Controller 148376] Router detached session from realm "crossbar" (session=2224187054298566, detached_session_ids=1, authid="crossbar.process.149393", authrole="crossbar.worker.cpw-a44ea2c4-1", authmethod="trusted", authprovider="programcode") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Controller 148376] Router detached session from realm "crossbar" (session=8014745874523120, detached_session_ids=1, authid="crossbar.process.149368", authrole="crossbar.worker.cpw-a44ea2c4-0", authmethod="trusted", authprovider="programcode") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] Connection to node controller closed cleanly
2022-05-06T01:23:03+0200 [Router     149420] <__main__._run_command_exec_worker.<locals>.WorkerServerProtocol.connectionLost> connection lost for peer="process:148376", closed cleanly
2022-05-06T01:23:03+0200 [Proxy      149393] Connection to node controller closed cleanly
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=428745176987490, detached_session_ids=1, authid="proxy-GTWP-JHSM-HNX5-F3Y7-WG95-6QMU", authrole="system", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Proxy      149393] <__main__._run_command_exec_worker.<locals>.WorkerServerProtocol.connectionLost> connection lost for peer="process:148376", closed cleanly
2022-05-06T01:23:03+0200 [Proxy      149393] (TCP Port 8080 Closed)
2022-05-06T01:23:03+0200 [Proxy      149368] session leaving 'wamp.close.transport_lost'
2022-05-06T01:23:03+0200 [Proxy      149368] wamp.close.transport_lost: WAMP transport was lost without closing the session 428745176987490 before
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=1910240218225269, detached_session_ids=1, authid="proxy-GVH7-A9X4-WSJK-VETS-ARN5-5E49", authrole="anonymous", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=4398574535513761, detached_session_ids=1, authid="proxy-4FPL-QTRS-HXYL-XWN5-GSJV-ERXV", authrole="anonymous", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] (TCP Port 10000 Closed)
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=6286950387169889, detached_session_ids=1, authid="system", authrole="system", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Proxy      149393] session leaving 'wamp.close.transport_lost'
2022-05-06T01:23:03+0200 [Proxy      149393] wamp.close.transport_lost: WAMP transport was lost without closing the session 5477534397562130 before
2022-05-06T01:23:03+0200 [Proxy      149368] session leaving 'wamp.close.transport_lost'
2022-05-06T01:23:03+0200 [Proxy      149368] wamp.close.transport_lost: WAMP transport was lost without closing the session 1910240218225269 before
2022-05-06T01:23:03+0200 [Proxy      149368] Connection to node controller closed cleanly
2022-05-06T01:23:03+0200 [Proxy      149368] <__main__._run_command_exec_worker.<locals>.WorkerServerProtocol.connectionLost> connection lost for peer="process:148376", closed cleanly
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=5477534397562130, detached_session_ids=1, authid="proxy-6SQ5-PL3R-KLMY-6EP4-SVUV-WS5S", authrole="anonymous", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=549718107621911, detached_session_ids=1, authid="proxy-594N-7KRL-P9PV-NQP7-FSXL-TEN7", authrole="anonymous", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=2826241284423658, detached_session_ids=1, authid="proxy-UNSK-VG5L-46MQ-JCCM-G9W9-MFJN", authrole="system", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Router     149420] Router detached session from realm "realm1" (session=3390065810551789, detached_session_ids=1, authid="proxy-5VJY-W559-CVMG-9FNR-KN99-V6R6", authrole="system", authmethod="cryptosign-proxy", authprovider="static") <crossbar.router.router.Router.detach>
2022-05-06T01:23:03+0200 [Proxy      149393] session leaving 'wamp.close.transport_lost'
2022-05-06T01:23:03+0200 [Proxy      149393] wamp.close.transport_lost: WAMP transport was lost without closing the session 3390065810551789 before
2022-05-06T01:23:03+0200 [Proxy      149368] (TCP Port 8080 Closed)
2022-05-06T01:23:03+0200 [Controller 148376] Native worker connection closed cleanly.
2022-05-06T01:23:03+0200 [Controller 148376] <crossbar.node.native.NativeWorkerClientProtocol.connectionLost> connection lost for peer="process:149420", closed cleanly
2022-05-06T01:23:03+0200 [Controller 148376] Node worker group1_1 ended successfully
2022-05-06T01:23:03+0200 [Controller 148376] Checking for node shutdown: worker_exit_success=True, shutdown_requested=True, node_shutdown_triggers=['shutdown_on_shutdown_requested']
2022-05-06T01:23:03+0200 [Controller 148376] Native worker connection closed cleanly.
2022-05-06T01:23:03+0200 [Controller 148376] <crossbar.node.native.NativeWorkerClientProtocol.connectionLost> connection lost for peer="process:149368", closed cleanly
2022-05-06T01:23:03+0200 [Controller 148376] Node worker cpw-a44ea2c4-0 ended successfully
2022-05-06T01:23:03+0200 [Controller 148376] Checking for node shutdown: worker_exit_success=True, shutdown_requested=True, node_shutdown_triggers=['shutdown_on_shutdown_requested']
2022-05-06T01:23:03+0200 [Controller 148376] Native worker connection closed cleanly.
2022-05-06T01:23:03+0200 [Controller 148376] <crossbar.node.native.NativeWorkerClientProtocol.connectionLost> connection lost for peer="process:149393", closed cleanly
2022-05-06T01:23:03+0200 [Controller 148376] Node worker cpw-a44ea2c4-1 ended successfully
2022-05-06T01:23:03+0200 [Controller 148376] Checking for node shutdown: worker_exit_success=True, shutdown_requested=True, node_shutdown_triggers=['shutdown_on_shutdown_requested']

(cpy39_1) (base) oberstet@intel-nuci7:~/scm/typedefint/crossbar-cluster$