search

crossbario / crossbar

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

ERROR sent after GOODBYE when caller leaves in middle of progressive call results #2068

Open ecorm opened 1 year ago

ecorm commented 1 year ago

While using Crossbar to test the CppWAMP client implementation, I've come across some strange behavior on the part of Crossbar. When the caller leaves before a call with progressive results completes, Crossbar sends the GOODBYE response before sending the ERROR response with wamp.error.canceled. Here's a trace I've captured from the point of view of a CppWAMP client:

2023-03-16T02:57:46.306Z ["TX","CALL",[48,1,{"receive_progress":true},"com.myapp.foo",["invitation"]]]
2023-03-16T02:57:46.306Z ["RX","RESULT",[50,1,{"progress":true},["rsvp"]]]
2023-03-16T02:57:46.331Z ["RX","RESULT",[50,1,{"progress":true},[9]]]
2023-03-16T02:57:46.357Z ["RX","RESULT",[50,1,{"progress":true},[3]]]
2023-03-16T02:57:46.382Z ["RX","RESULT",[50,1,{"progress":true},[7]]]
2023-03-16T02:57:46.407Z ["RX","RESULT",[50,1,{"progress":true},[5]]]
2023-03-16T02:57:46.407Z ["TX","GOODBYE",[6,{},"wamp.close.close_realm"]]
2023-03-16T02:57:46.407Z ["RX","GOODBYE",[6,{},"wamp.close.normal"]]
2023-03-16T02:57:46.407Z ["RX","ERROR",[8,48,1,{},"wamp.error.canceled"]]

One would expect the router to send the ERROR message before the GOODBYE message, or not even bother sending the ERROR message at all.

The version of Crossbar I have installed on my desktop is pretty old at v18.9.2. I checked to see if this bug was reported before, but can't find anything.

I'll try to install a more recent version of Crossbar when I get the chance, and will check if the bug is still there. In the meantime, I've reported the bug here so that it's not forgotten.

oberstet commented 1 year ago

thanks for reporting! this sounds like a bug in crossbar ..

ecorm commented 1 year ago

I can confirm this bug still occurs after upgrading to the latest master. What's happening is that the callee sends an ERROR in response to the INTERRUPT, which Crossbar forwards back to the caller despite leaving the session.

Here's a trace that includes both caller and callee (with HELLO/GOODBYE options stripped for brevity).

Caller: 2023-04-20T04:33:29.461Z ["TX","HELLO",[1,"cppwamp.test",{}]]
Caller: 2023-04-20T04:33:29.462Z ["RX","WELCOME",[2,7644867858740542,{}]]
Callee: 2023-04-20T04:33:29.463Z ["TX","HELLO",[1,"cppwamp.test",{}]]
Callee: 2023-04-20T04:33:29.464Z ["RX","WELCOME",[2,7522971938995879,{}]]
Callee: 2023-04-20T04:33:29.464Z ["TX","REGISTER",[64,1,{},"com.myapp.foo"]]
Callee: 2023-04-20T04:33:29.465Z ["RX","REGISTERED",[65,1,1936973253605048]]
Caller: 2023-04-20T04:33:29.465Z ["TX","CALL",[48,1,{"receive_progress":true},"com.myapp.foo",["invitation"],{}]]
Callee: 2023-04-20T04:33:29.465Z ["RX","INVOCATION",[68,22,1936973253605048,{"caller":7644867858740542,"caller_authid":"F9LJ-LWWF-G6K5-KH6C-3EEP-XNQF","caller_authrole":"anonymous","receive_progress":true},["invitation"]]]
Callee: 2023-04-20T04:33:29.465Z ["TX","YIELD",[70,22,{"progress":true},["rsvp"],{}]]
Caller: 2023-04-20T04:33:29.465Z ["RX","RESULT",[50,1,{"callee":7522971938995879,"callee_authid":"PQ6S-PLSV-XCNP-5PWK-QLJA-5QF5","callee_authrole":"anonymous","progress":true},["rsvp"]]]
Callee: 2023-04-20T04:33:29.490Z ["TX","YIELD",[70,22,{"progress":true},[9],{}]]
Caller: 2023-04-20T04:33:29.491Z ["RX","RESULT",[50,1,{"callee":7522971938995879,"callee_authid":"PQ6S-PLSV-XCNP-5PWK-QLJA-5QF5","callee_authrole":"anonymous","progress":true},[9]]]
Callee: 2023-04-20T04:33:29.515Z ["TX","YIELD",[70,22,{"progress":true},[3],{}]]
Caller: 2023-04-20T04:33:29.516Z ["RX","RESULT",[50,1,{"callee":7522971938995879,"callee_authid":"PQ6S-PLSV-XCNP-5PWK-QLJA-5QF5","callee_authrole":"anonymous","progress":true},[3]]]
Callee: 2023-04-20T04:33:29.541Z ["TX","YIELD",[70,22,{"progress":true},[7],{}]]
Caller: 2023-04-20T04:33:29.541Z ["RX","RESULT",[50,1,{"callee":7522971938995879,"callee_authid":"PQ6S-PLSV-XCNP-5PWK-QLJA-5QF5","callee_authrole":"anonymous","progress":true},[7]]]
Callee: 2023-04-20T04:33:29.566Z ["TX","YIELD",[70,22,{"progress":true},[5],{}]]
Caller: 2023-04-20T04:33:29.566Z ["RX","RESULT",[50,1,{"callee":7522971938995879,"callee_authid":"PQ6S-PLSV-XCNP-5PWK-QLJA-5QF5","callee_authrole":"anonymous","progress":true},[5]]]
Caller: 2023-04-20T04:33:29.566Z ["TX","GOODBYE",[6,{},"wamp.close.close_realm"]]
Caller: 2023-04-20T04:33:29.567Z ["RX","GOODBYE",[6,{},"wamp.close.normal"]]
Callee: 2023-04-20T04:33:29.567Z ["RX","INTERRUPT",[69,22,{"mode":"killnowait"}]]
Callee: 2023-04-20T04:33:29.567Z ["TX","ERROR",[8,68,22,{},"wamp.error.canceled",[],{}]]
Caller: 2023-04-20T04:33:29.567Z ["TX","HELLO",[1,"cppwamp.test",{}]]
Caller: 2023-04-20T04:33:29.567Z ["RX","ERROR",[8,48,1,{},"wamp.error.canceled"]]
Caller: 2023-04-20T04:33:29.567Z ["RX","WELCOME",[2,2117473671002045,{}]]