SE WebSocket partially broken: WebSocket repeatedly disconnects after about 100 seconds, prior to server sending normal heartbeat

Question

Shortly after 05:00 UTC this morning, the Stack Exchange WebSocket started misbehaving. It (assumed) initially restarted at 05:01 UTC. Then, starting at 05:10 UTC, the server has been closing the WebSocket connection every couple of minutes. The closure happens 100 seconds after the most recent data is sent by the server.

Normal operation

Normal operation for the WebSocket is that once opened and subscribed the server sends a "hb" every 5 minutes and then closes the connection if it doesn't receive a "hb" message back. As long as these "heartbeat" messages are replied to, the WebSocket can, normally, be kept open indefinitely.

Testing

The following code opens a WebSocket connection to monitor activity on this question. If a "hb" is sent by the server (usually every 5 minutes), then it will reply with a "hb". Under normal conditions, this would keep the connection open indefinitely. Unfortunately, at the moment, the server will close the connection without sending a "hb".

As currently written, the following test will open 10 WebSockets to Stack Exchange all of which will monitor this question. A record is kept of the total number of heartbeat messages received, which should be 1 every 5 minutes for each of the WebSockets, and the total number of times that the WebSockets are closed (by Stack Exchange or other network disruption). Unfortunately, the code doesn't currently track the distribution of how long the WebSockets remain open, as that would be a much more interesting number, both for the performance of Stack Exchange pages, but also for SmokeDetector and other consumers of the WebSocket data.

(() => {
  'use strict';

  const NUMBER_OF_WEBSOCKETS = 10;
  const webSockets = Array(NUMBER_OF_WEBSOCKETS);
  webSockets.fill(null);
  let closing = false;
  let startTime = 0;
  const passEl = document.getElementById('pass');
  const failEl = document.getElementById('fail');
  const failPercentEl = document.getElementById('failPercent');
  const startTimeEl = document.getElementById('startTime');
  const elapsedTimeEl = document.getElementById('elapsedTime');
  const diffLabel = {
      days: 'd',
      hours: 'h',
      minutes: 'm',
      seconds: 's',
  };
  const diffOrder = [
      'days',
      'hours',
      'minutes',
      'seconds',
  ];

  function incrementAndShowPercent(addPass, addFail, noAdd) {
    if (noAdd || closing) {
      return;
    }
    const pass = +passEl.textContent + addPass;
    passEl.textContent = pass;
    const fail = +failEl.textContent + addFail;
    failEl.textContent = fail;
    const failPercent = Math.round((10000 * fail) / (pass + fail))/100
    failPercentEl.textContent = failPercent;
    if (fail) {
      failEl.classList.add('isFailing');
      failPercentEl.classList.add('isFailing');
    }
    /* The elapsed time code was copied, then significantly modified, from
     * https://codereview.stackexchange.com/a/160240/53535 by Przemek
     * https://codereview.stackexchange.com/users/97934/przemek */
    const elapsed = (Date.now() - startTime) / 1000;
    const diff = {
      days: Math.floor(elapsed / 86400),
      hours: Math.floor((elapsed / 3600) % 24),
      minutes: Math.floor((elapsed / 60) % 60),
      seconds: Math.floor(elapsed % 60),
    };
    const elapsedText = diffOrder.reduce((sum, key) => {
      if (sum || diff[key] || key === 'seconds') {
          sum += ` ${diff[key]}${diffLabel[key]}`;
      }
      return sum;
    }, '').trim();
    elapsedTimeEl.textContent = elapsedText;
  }

  function startAWebSocket(entry, socketIndex) {
    let webSocket = null;
    let noAdd = true;

    function registerWebSocket() { // eslint-disable-line no-unused-vars
      if (webSocket) {
        if (typeof webSocket.removeEventListener === 'function') {
            //There can be additional events that mess up the count.
            webSocket.removeEventListener('message', socketOnMessage);
        }
        if (typeof webSocket.close === 'function') {
            // Close any existing WebSocket.
            webSocket.close();
        }
      }
      webSocket = new WebSocket('wss://qa.sockets.stackexchange.com');
      webSockets[socketIndex] = webSocket;
      webSocket.addEventListener('message', socketOnMessage);
      webSocket.addEventListener('open', () => {
        webSocket.send('4-question-400186');
        console.info(`WS[${socketIndex}]: Open & Subscribed to this question`);
        noAdd = false;
      });
      webSocket.addEventListener('close', event => {
        if (!noAdd && !closing) {
          console.error(`WS[${socketIndex}]: Closed: event.code`, event.code, '::  event:', event);
          incrementAndShowPercent(0, 1, noAdd);
          noAdd = true;
          registerWebSocket();
        } else {
          if (event.wasClean !== true || event.reason !== 'ok' || event.code !== 1000) {
            console.error(`WS[${socketIndex}]: Closed: event.code`, event.code, '::  event:', event);
          } else {
            console.info(`WS[${socketIndex}]: Closed: normal closure`);
          }
        }
      });
      webSocket.addEventListener('error', event => {
        console.error(`WS[${socketIndex}]: Error:`);
        console.log(`WS[${socketIndex}]: Error: event`, event);
      });
    }

    function socketOnMessage(event) {
      const messageObject = JSON.parse(event.data);
      const data = messageObject.data;
      let dataObject = data;
      try {
        dataObject = JSON.parse(data);
      } catch(error) {
        // Ignore any errors
      }
      messageObject.data = dataObject;
      if (messageObject.action === 'hb') {
        //The hb is every 5 minutes.
        incrementAndShowPercent(1, 0, noAdd);
        webSocket.send(data);
        console.info(`WS[${socketIndex}]: heartbeat received & responded to`);
      } else {
        console.log(`WS[${socketIndex}]: non-heartbeat: messageObject:`, messageObject);
      }
    }

    registerWebSocket();
  }

  function startAllWebSockets() {
    console.log(`vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv Start test with ${NUMBER_OF_WEBSOCKETS} WebSockets`);
    webSockets.forEach(startAWebSocket);
  }

  function stopAllWebSockets() {
    closing = true;
    Promise.all(webSockets.map((webSocket) => new Promise((resolve) => {
      webSocket.addEventListener('close', resolve);
      webSocket.close();
    })))
      .then(() => {
        console.log('WS: All WebSockets closed at end of test');
        console.log('^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ End test');
        webSockets.fill(null);
        closing = false;
      });
  }

  document.getElementById('start').addEventListener('click', () => {
    passEl.textContent = 0;
    failEl.textContent = 0;
    failEl.classList.remove('isFailing');
    failPercentEl.textContent = 0;
    failPercentEl.classList.remove('isFailing');
    startTime = Date.now();
    startTimeEl.textContent = (new Date(startTime)).toISOString();
    closing = false;
    startAllWebSockets();
  });

  document.getElementById('stop').addEventListener('click', stopAllWebSockets);
})();

span:not([id]) {
  margin-left: 10px;
}
span.extraSpace {
  margin-left: 20px;
}
#fail.isFailing,
#failPercent.isFailing {
  color: red;
  font-weight: bold;
}
#pass,
#failPercent {
  color: #00d000;
  font-weight: bold;
}

<button id="start">Start/Restart</button>
<button id="stop">Stop</button>
<span> heartbeats: <span id="pass">0</span></span>
<span> Closures: <span id="fail">0</span></span>
<span>Closures %: <span id="failPercent">0</span> %</span>
<span class="extraSpace">Started: <span id="startTime"></span></span>
<span class="extraSpace">Elapsed: <spam id="elapsedTime"></span></span>
</br>You may want to open the Web Console (F12), as it's easier to read the output there.</br>

Monitoring trace

The following is the console output of monitoring the question activity for question #400179 for an hour or so, and shows that the WebSocket wasn't closed until 100 seconds after the most recent activity.

14:39:47.796 Monitor WS: initialized.                                                                                                                                                                           SE:-Monitor-WebSocket.user.js:679:19
14:39:48.854 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:39:48.856 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:41:28.703 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:41:28.705 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:41:30.232 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:41:30.234 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:43:10.147 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:43:10.147 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:43:11.771 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:43:11.772 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:44:37.512 Monitor WS: messageObject: 
                Object { action: "4-question-400179", data: {…} }
                 ::  data: 
                Object { a: "score", id: 400179, score: 6 }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:718:13
14:45:20.412 Monitor WS: messageObject: 
                Object { action: "4-question-400179", data: {…} }
                 ::  data: 
                Object { a: "score", id: 400179, score: 5 }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:718:13
14:46:12.296 Monitor WS: messageObject: 
                Object { action: "4-question-400179", data: {…} }
                 ::  data: 
                Object { a: "score", id: 400179, score: 6 }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:718:13
14:46:27.434 Monitor WS: messageObject: 
                Object { action: "4-question-400179", data: {…} }
                 ::  data: 
                Object { a: "score", id: 400179, score: 5 }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:718:13
14:48:07.440 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:48:07.443 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:48:11.470 Monitor WS: Error:                                                                                                                                                                                 SE:-Monitor-WebSocket.user.js:664:19
14:48:11.471 Monitor WS: Error: event 
                error { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:665:19
14:48:13.552 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:48:13.553 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:49:53.472 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:49:53.473 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:49:55.163 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:49:55.164 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:51:35.083 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:51:35.085 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:51:37.594 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:51:37.595 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:53:17.507 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:53:17.507 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:53:19.868 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:53:19.871 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:54:32.212 Monitor WS: messageObject: 
                Object { action: "4-question-400179", data: {…} }
                 ::  data: 
                Object { a: "score", id: 400179, score: 6 }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:718:13
14:56:12.217 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:56:12.218 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:56:14.772 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:56:14.773 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:57:54.678 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:57:54.679 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:57:56.247 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:57:56.248 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
14:59:36.161 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
14:59:36.162 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
14:59:37.978 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
14:59:37.979 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:01:17.908 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:01:17.910 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:01:20.124 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:01:20.126 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:03:00.026 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:03:00.027 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:03:01.684 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:03:01.685 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:04:41.604 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:04:41.605 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:04:44.258 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:04:44.259 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:06:24.184 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:06:24.185 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:06:25.734 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:06:25.735 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:08:05.655 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:08:05.656 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:08:07.139 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:08:07.140 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:09:47.058 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:09:47.058 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:09:49.131 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:09:49.132 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:11:29.063 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:11:29.064 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:11:31.885 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:11:31.886 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:13:11.801 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:13:11.802 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:13:13.411 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:13:13.412 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:14:53.314 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:14:53.321 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:14:54.847 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:14:54.848 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:16:34.751 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:16:34.752 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:16:37.640 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:16:37.641 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:18:17.552 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:18:17.553 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:18:20.141 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:18:20.142 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:20:00.063 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:20:00.065 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:20:02.329 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:20:02.329 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:21:42.404 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:21:42.405 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:21:44.253 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:21:44.254 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:23:24.172 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:23:24.174 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:23:26.296 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:23:26.297 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:25:06.181 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:25:06.181 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:25:08.551 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:25:08.552 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:26:48.436 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:26:48.436 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:26:50.452 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:26:50.453 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:28:30.372 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:28:30.373 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19
15:28:32.285 Monitor WS: Open:                                                                                                                                                                                  SE:-Monitor-WebSocket.user.js:634:19
15:28:32.286 Monitor WS: Subscribed to site: 4 :: question: 400179                                                                                                                                              SE:-Monitor-WebSocket.user.js:770:13
15:30:12.191 Monitor WS: Closed:                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:657:19
15:30:12.192 Monitor WS: Closed: event.code undefined ::  event: 
                close { target: div, isTrusted: false, srcElement: div, currentTarget: div, eventPhase: 2, bubbles: false, cancelable: false, returnValue: true, defaultPrevented: false, composed: false, … }
                                                                                                                                                                                                                SE:-Monitor-WebSocket.user.js:658:19

they go through cloudflare as of last night. (That's about chat, but likely they moved all web sockets). — Shadow Wizard, Commented May 23 at 17:06
For the sites, I made a userscript that tries to induce activity on the the websockets so it isn't killed. It's not a solution for anything that's not a browser (bots, most notably) but might at least users might find it helpful. — VLAZ, Commented May 23 at 17:13
We've deployed a patch to fix configs on our side. Are you still seeing this problem? — Slate, Commented May 23 at 17:21
@Slate Preliminary is that it's resolved. Still running tests, but definitely changed and looking good. — Makyen, Commented May 23 at 17:32

This_is_NOT_a_forum · Accepted Answer · 2024-05-28 10:28:07Z

31

My bad. The keepalive timeout I set was appropriate for Chat, but not WebSockets. I missed this when testing in Dev, and now the timeouts are set appropriately for each app.

edited May 28 at 10:28

This_is_NOT_a_forum

6,6754 gold badges37 silver badges55 bronze badges

answered May 23 at 17:43

Josh ZhangStaffMod

10k9 gold badges31 silver badges41 bronze badges

Thank you for making this change. Unfortunately, while it greatly improved the situation, it didn't resolve it. In the 24 hours after you posted this answer, SmokeDetector experienced the WebSocket disconnecting/closing 14 times. While that's dramatically better than the WebSocket closing every couple/few minutes, it's still substantially above what it used to be, which was that it basically never happened. It might have happened before, but it was sufficiently few (i.e., one or two per year), such that it wasn't noticed as anything other than an intermittent glitch.
– Makyen
Commented May 26 at 2:17
4

@Makyen I've increased the timeout window to 15 minutes, let me know if that helped.
– Josh Zhang StaffMod
Commented May 28 at 15:51
1

Thanks for making the additional change. I'll keep an eye on it. It may take a while (potentially days) to test. In all three of two different SmokeDetector instances on two different compute instances and on my local machine using JavaScript running in the browser, the issues appear to be dependent on external factors, potentially the load which SE experiences. Notably, there were few, if any, issues recorded over Saturday or Sunday, but they then ramped up on Monday and Tuesday.
– Makyen
Commented May 28 at 23:24
Unfortunately, the issue hasn't fully resolved. I believe it's something other than the timeout window. We're still seeing a substantial number of dropped connections. In the time between your most recent comment here and now, SmokeDetector experienced 41 drops of the SE WebSockets.In that time, using the code in the question here to continually run tests, the WebSockets were dropped 128 times. The question's code uses 10 WebSockets, so that's about 13 times per WebSocket connection in that time, which is consistent with the 13.67 times which SD experienced in that time (using 3 WebSockets).
– Makyen
Commented May 30 at 16:27
It's also happening in SE pages, as most of the tabs I keep open for extended times have ended up dropping at least one of their WebSocket connections (e.g. topbar, active questions, question updates). Chat is probably also affected, but that's not as clear, given that chat also communicates such info cross-tab through localStorage. I've definitely seen some unusual anomalies there, but it's not as easy to track down.
– Makyen
Commented May 30 at 16:27
Looking at the logs from this question's code, the closures happen anywhere from seconds to a couple/few minutes after a heartbeat is received and responded to (i.e., don't appear to be close to approaching the 15 minute timeout). The closures tend to be clustered, often with two or three, of ten, WebSockets closing at the same time, or nearly the same time. The closures, in the testing using the code in this question and on the two separate SmokeDetector instances, tend to happen more often during times of the day, and days of the week, when SE, or just the internet overall, is busier.
– Makyen
Commented May 30 at 16:27
3

BTW (separate topic): We'd appreciate it if you'd turn off Cloudflare's Email Address Obfuscation for chat. We've encountered issues with it running some SmokeDetector commands, as email addresses are something we deal with routinely. Unfortunately, without an actual API for chat, scraping is needed in some cases. While we can work around it, doing so will require making changes to the ChatExchange library. It's also likely to be affecting other chat libraries. I can write up a new MSE question, if you'd prefer.
– Makyen
Commented May 30 at 16:28
I know this week we've deployed SocketServer, that would disconnect any active sessions as the app is deployed. We were updating the CI/CD pipeline, no app code changed.
– Josh Zhang StaffMod
Commented May 30 at 20:11
If the timeouts are within a few minutes of connection I'm not sure it's the CDN at that point. Cloudflare might have a maximum session time a socket can stay active but that should be a long duration.
– Josh Zhang StaffMod
Commented May 30 at 20:14
2

As for email obfuscation, please create a new question so the CM team can raise for us to track the request internally.
– Josh Zhang StaffMod
Commented May 30 at 20:15

Add a comment |

Stack Exchange Network

SE WebSocket partially broken: WebSocket repeatedly disconnects after about 100 seconds, prior to server sending normal heartbeat

Normal operation

Testing

Monitoring trace

1 Answer 1

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged
bug
status-completed
web-sockets
.

Hot Network Questions

SE WebSocket partially broken: WebSocket repeatedly disconnects after about 100 seconds, prior to server sending normal heartbeat

Normal operation

Testing

Monitoring trace

1 Answer 1

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged bugstatus-completedweb-sockets.

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
bug
status-completed
web-sockets
.