#1474 smacks/websockets: abruptly closed sockets are disconnected with a 20s delay for resumed sessions

Reporter marc0s
Owner MattJ
Created
Updated
Stars ★★ (2)
Tags
  • Type-Defect
  • Status-Fixed
  • Priority-Medium
  • Milestone-0.11
  1. marc0s on

    When the websocket of a SM-resumed session is broken, the closing of the c2s connection is not actually happening unit 20 seconds after, and because of a `read error`. What steps will reproduce the problem? 1. Establish a 198-enabled session 2. Have its socket closed (using stanza I'im issuing a `client.transport.conn.close()`) 3. Resume the session 4. Have its socket closed by the same method above 5. Wait 20s 6. Actually notice the disconnection What is the expected output? Receive the disconnection event right after breaking the socket, no matter if a session is resumed or not. What do you see instead? A 20 seconds delay. What version of the product are you using? On what operating system? hg clone of 0.11 at: 9735:97c0f5fe5f41, Debian buster. These are the captured logs (first ones with nginx proxying, latter ones without it). Please don't hesitate asking for more information if needed. -- fresh session Dec 08 00:37:24 mod_websocket debug Websocket received frame: opcode=8, 0 bytes Dec 08 00:37:24 c2s556583042240 info Client disconnected: connection closed Dec 08 00:37:24 c2s556583042240 debug Destroying session for dummy1@test.domain/ZqxcxuaM (dummy1@test.domain) Dec 08 00:37:24 c2s556583042240 debug mod_smacks hibernating session for up to 300 seconds Dec 08 00:37:24 socket debug server.lua: closed client handler and removed socket from list -- resumed session Dec 08 00:37:42 mod_websocket debug Websocket received frame: opcode=8, 0 bytes Dec 08 00:38:02 socket debug server.lua: client 127.0.0.1:46274 read error: closed Dec 08 00:38:02 c2s556583042240 info Client disconnected: closed -- fresh, straight (no nginx proxying nor TLS-offloading) connection Dec 08 00:52:46 c2s55e8a9272270 debug Destroying session for dummy1@test.domain/7WJiuv3R (dummy1@test.domain) Dec 08 00:52:46 c2s55e8a9272270 debug mod_smacks hibernating session for up to 300 seconds Dec 08 00:52:46 socket debug server.lua: closed client handler and removed socket from list -- resumed, straight (no nginx proxying nor TLS-offloading) connection Dec 08 00:53:28 mod_websocket debug Websocket received frame: opcode=8, 0 bytes Dec 08 00:53:48 socket debug server.lua: client <redacted>:57232 read error: closed Dec 08 00:53:48 c2s55e8a9272270 info Client disconnected: closed Dec 08 00:53:48 c2s55e8a9272270 debug Destroying session for dummy1@test.domain/7WJiuv3R (dummy1@test.domain): closed Dec 08 00:53:48 c2s55e8a9272270 debug mod_smacks hibernating session for up to 300 seconds Dec 08 00:53:48 socket debug server.lua: closed client handler and removed socket from list

  2. marc0s on

    Using libevent made no difference: -- resumed session, no nginx proxied connection Dec 08 01:32:09 mod_websocket debug Websocket received frame: opcode=8, 0 bytes Dec 08 01:32:29 socket debug connection failed in read event: closed Dec 08 01:32:29 socket debug closing client with id: 5617a1f11b00 closed Dec 08 01:32:29 c2s5617a1ea3ab0 info Client disconnected: closed Dec 08 01:32:29 c2s5617a1ea3ab0 debug Destroying session for dummy1@test.domain/6zp5DR4z (dummy1@test.domain): closed Dec 08 01:32:29 c2s5617a1ea3ab0 debug mod_smacks hibernating session for up to 300 seconds

  3. MattJ on

    Just noticed that this appears to be a duplicate of #1234 (but I don't blame you for not finding it, I only just realised).

  4. MattJ on

    Fixed in 0.11.7: https://hg.prosody.im/trunk/rev/55d8612ac357

    Changes
    • owner MattJ
    • tags Status-Fixed
  5. MattJ on

    Changes
    • tags Milestone-0.11
  6. marc0s on

    Looks like 0.11.7 is reproducing the same behavior: ```xmpp_1 | 2020-10-21T11:04:29.108496916Z mod_websocket debug Websocket received frame: opcode=8, 0 bytes xmpp_1 | 2020-10-21T11:04:49.108575258Z socket debug connection failed in read event: closed xmpp_1 | 2020-10-21T11:04:49.108627132Z socket debug closing client with id: 55d4509c50f0 closed xmpp_1 | 2020-10-21T11:04:49.108633616Z c2s55d4509543e0 info Client disconnected: closed``

  7. jmarty on

    I see the same behavior marc0s describes in 0.11.7 as well. I've noticed that when the resumed session's close frame is trying to write to the connection the call fails because there is no handler. But my knowledge ends there.

New comment

Not published. Used for spam prevention and optional update notifications.