Recommand · October 22, 2021 0

StompJS: Random reconnection-loop after a while

Context

  • 12 (testing) React Native devices are connected to our server through WebSockets.
  • Randomly some devices stop receiving any server activity anymore during the day.
  • These devices will be stuck in a reconnection-loop.
    • The following actions will get the devices out of the loop:
      • Restarting the client application on the devices.
      • Calling stompSocket.deactivate() followed by stompSocket.activate().
  • While looping, our server registers every time a client tries to connect to the server.
    • After diving into our server logs, we can conclude the following:
      • The client’s CONNECT message is received by the server.
      • The server indicates that the client is CONNECTED.
      • After around 35 seconds the server indicates that the client is DISCONNECTED
  • Heartbeats on the server, as well on the client are set at 10000, 10000
  • Client uses @stomp/stompjs@6.1.2
  • In this issue I’ll be zooming into the logs of one of the devices. The logs of the issue are similar across all of the devices.

Attachments

Table of contents

  1. StompJS Client configuration
  2. Client-side logs of the reconnection-loop
  3. Client-side logs of a successful reconnection after we restarted our server-application

1. StompJS Client configuration

const stompSocket: Client = new Client({
    brokerURL: WS_URL,
    appendMissingNULLonIncoming: true,
    forceBinaryWSFrames: true,
    reconnectDelay: 5000,
    connectionTimeout: 10000,
});

stompSocket.onConnect = async (): Promise<void> => {
    stompSocket.subscribe(`/topic/${topic}/messages`, async (message: IMessage): Promise<void> => {
        // Handle messages
        ...
    }
}

stompSocket.onChangeState = async (state) => {
    logDebug(`onChangeState ${JSON.stringify(state)}`, 'WS');
};

stompSocket.onWebSocketError = async (error: any) => {
    logError(`onWebSocketError ${JSON.stringify(error)}`, 'WS');
};

stompSocket.onStompError = async (error: any) => {
    logError(`onStompError ${JSON.stringify(error)}`, 'WS');
};

stompSocket.onWebSocketClose = async (evt: any) => {
    logWarn(`onWebSocketClose(): ${JSON.stringify(evt)}`, 'WS');
};

stompSocket.onDisconnect = async (receipt: any) => {
    logWarn(`onDisconnect ${JSON.stringify(receipt)}`, 'WS');
};
    

2. Logs of the reconnecting loop (client-side)

  • One of the client stops receiving activity from the server, even though the server receives all the CONNECT messages from the client.
  • I can’t figure out why the CONNECT message is send after the 10000ms timeout is triggered and the connection is trying to close.
// No previous logs in the past couple hours.
09:14:33 STOMP did not receive server activity for the last 26911ms
09:14:33 STOMP Issuing close on the websocket
09:14:43 STOMP did not receive server activity for the last 36919ms
09:14:43 STOMP Issuing close on the websocket
09:14:53 STOMP did not receive server activity for the last 46919ms
09:14:53 STOMP Issuing close on the websocket
09:15:03 STOMP did not receive server activity for the last 56923ms
09:15:03 STOMP Issuing close on the websocket
09:15:13 STOMP did not receive server activity for the last 66927ms
09:15:13 STOMP Issuing close on the websocket
09:15:23 STOMP did not receive server activity for the last 76931ms
09:15:23 STOMP Issuing close on the websocket
09:15:33 STOMP did not receive server activity for the last 86934ms
09:15:33 STOMP Issuing close on the websocket
09:15:33 WS onWebSocketError {"isTrusted":false,"message":"Socket closed"}
09:15:33 STOMP Connection closed to wss://example.com/websocket
09:15:33 WS onWebSocketClose {"isTrusted":false,"message":"Socket closed"}
09:15:33 STOMP STOMP: scheduling reconnection in 5000ms
09:15:38 STOMP Opening Web Socket...
09:15:48 STOMP Connection not established in 10000ms, closing socket
09:15:48 STOMP Issuing close on the websocket
09:15:49 STOMP Web Socket Opened...
09:15:49 STOMP
    >>> CONNECT
    accept-version:1.0,1.1,1.2
    heart-beat:10000,10000

09:16:26 STOMP Connection closed to wss://example.com/websocket
09:16:26 WS onWebSocketClose {"isTrusted":false,"code":1002,"reason":""}
09:16:26 STOMP STOMP: scheduling reconnection in 5000ms
09:16:31 STOMP Opening Web Socket...
09:16:41 STOMP Connection not established in 10000ms, closing socket
09:16:41 STOMP Issuing close on the websocket
09:16:41 STOMP Web Socket Opened...
09:16:41 STOMP
    >>> CONNECT
    accept-version:1.0,1.1,1.2
    heart-beat:10000,10000

09:17:16 STOMP Connection closed to wss://example.com/websocket
09:17:16 WS onWebSocketClose {"isTrusted":false,"code":1002,"reason":""}
09:17:16 STOMP STOMP: scheduling reconnection in 5000ms
09:17:21 STOMP Opening Web Socket...
09:17:31 STOMP Connection not established in 10000ms, closing socket
09:17:31 STOMP Issuing close on the websocket
09:17:31 STOMP Web Socket Opened...
09:17:31 STOMP
    >>> CONNECT
    accept-version:1.0,1.1,1.2
    heart-beat:10000,10000

09:18:06 STOMP Connection closed to wss://example.com/websocket
09:18:06 WS onWebSocketClose {"isTrusted":false,"code":1002,"reason":""}
09:18:06 STOMP STOMP: scheduling reconnection in 5000ms
09:18:11 STOMP Opening Web Socket...
09:18:21 STOMP Connection not established in 10000ms, closing socket
09:18:21 STOMP Issuing close on the websocket
09:18:21 STOMP Web Socket Opened...
09:18:21 STOMP
    >>> CONNECT
    accept-version:1.0,1.1,1.2
    heart-beat:10000,10000
// This keeps going for ever, until manual intervention.

3. Client-side logs of a successful reconnection after we restarted our server-application

  • These logs show what we should expect when the client tries to reconnect when the server is down.
  • The server application was restarting between 07:04:11 and 07:05:15.
  • It is expected that our apache server returns 503 while restarting.
  • When the server application was back, the client tried to reconnect at 07:05:20. In the same second the connection was established and the server returned a CONNECTED back.
// No previous logs in the past couple hours.
07:04:11 STOMP Connection closed to wss://example.com/websocket
07:04:11 WS onWebSocketClose {"isTrusted":false,"code":1001,"reason":""}
07:04:11 STOMP STOMP: scheduling reconnection in 5000ms
07:04:16 STOMP Opening Web Socket...
07:04:16 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:17 STOMP Connection closed to wss://example.com/websocket
07:04:17 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:17 STOMP STOMP: scheduling reconnection in 5000ms
07:04:22 STOMP Opening Web Socket...
07:04:22 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:22 STOMP Connection closed to wss://example.com/websocket
07:04:22 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:22 STOMP STOMP: scheduling reconnection in 5000ms
07:04:27 STOMP Opening Web Socket...
07:04:27 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:27 STOMP Connection closed to wss://example.com/websocket
07:04:27 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:27 STOMP STOMP: scheduling reconnection in 5000ms
07:04:32 STOMP Opening Web Socket...
07:04:32 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:32 STOMP Connection closed to wss://example.com/websocket
07:04:32 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:32 STOMP STOMP: scheduling reconnection in 5000ms
07:04:37 STOMP Opening Web Socket...
07:04:38 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:38 STOMP Connection closed to wss://example.com/websocket
07:04:38 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:38 STOMP STOMP: scheduling reconnection in 5000ms
07:04:43 STOMP Opening Web Socket...
07:04:43 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:43 STOMP Connection closed to wss://example.com/websocket
07:04:43 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:43 STOMP STOMP: scheduling reconnection in 5000ms
07:04:48 STOMP Opening Web Socket...
07:04:48 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:48 STOMP Connection closed to wss://example.com/websocket
07:04:48 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:48 STOMP STOMP: scheduling reconnection in 5000ms
07:04:53 STOMP Opening Web Socket...
07:04:54 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:54 STOMP Connection closed to wss://example.com/websocket
07:04:54 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:54 STOMP STOMP: scheduling reconnection in 5000ms
07:04:59 STOMP Opening Web Socket...
07:04:59 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:59 STOMP Connection closed to wss://example.com/websocket
07:04:59 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:04:59 STOMP STOMP: scheduling reconnection in 5000ms
07:05:04 STOMP Opening Web Socket...
07:05:04 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:04 STOMP Connection closed to wss://example.com/websocket
07:05:04 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:04 STOMP STOMP: scheduling reconnection in 5000ms
07:05:09 STOMP Opening Web Socket...
07:05:09 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:09 STOMP Connection closed to wss://example.com/websocket
07:05:09 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:09 STOMP STOMP: scheduling reconnection in 5000ms
07:05:14 STOMP Opening Web Socket...
07:05:15 WS onWebSocketError {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:15 STOMP Connection closed to wss://example.com/websocket
07:05:15 WS onWebSocketClose {"isTrusted":false,"message":"Expected HTTP 101 response but was '503 Service Unavailable'"}
07:05:15 STOMP STOMP: scheduling reconnection in 5000ms
07:05:20 STOMP Opening Web Socket...
07:05:20 STOMP Web Socket Opened...
07:05:20 STOMP
    >>> CONNECT
    accept-version:1.0,1.1,1.2
    heart-beat:10000,10000

07:05:20 STOMP
    <<< CONNECTED
    heart-beat:10000,10000
    version:1.2
    content-length:0

07:05:20 STOMP connected to server undefined 
07:05:20 TRACE ws.service.ts: stompSocket.onConnect() was called
// ...