On node versions higher than 10.19.0, a socket disconnect can permanently break the internal command_queue state

Issue

The node-redis client has a race condition in the handling of write error events from the TCP socket if the TCP socket disconnects during the execution of the internal_send_command() function, specifically on versions of Node.js >= 10.23.2.

The issue stems from the way error events are emitted from net sockets between 10.19.0 and 10.23.2. Whereas socket EPIPE error events are emitted asynchronously on 10.19.0, they are emitted synchronously higher versions, which means the internal_send_command function may wind up executing the this.flush_and_error() function within connection_gone before the this.command_queue.push() call here. This means the command queue gets polluted with a stray command that throws off the synchronization between the command queue and the commands sent to redis once redis reconnects.

To be a bit more concrete, here is an example of the same socket disconnect in the same part of the code being handled on 10.19.0 (where the .flush_and_error() is called after .command_queue.push()) vs 10.23.2, where the .flush_and_error happens midway through the code in internal_send_command sending the write to redis.

On 10.19.0:

On node 10.23.2:

I was not able to pinpoint the exact change in libuv that is causing the problem, but it was definitely introduced in libuv between versions 1.25.0 and 1.34.2, since that is the difference between node 10.19.0 and 10.23.2. Without in-depth knowledge, I believe https://github.com/libuv/libuv/pull/2425 may have something to do with it.

Reproducing

This issue is inherently difficult to reproduce, since the perfect conditions need to be aligned for a write to be happening at the same time as a disconnect. When trying to trigger the event by terminating an active redis-server process, it usually takes me 10-20 tries before I can get an error case. For small writes, this probability is even lower.

I wrote a small script to reproduce this issue:

'use strict';

const redis = require('.');
const assert = require('assert');

let onestring = '', twostring = '', threestring = '';
for (let i = 0; i < 30002; i++) {
  onestring += 'one';
  twostring += 'two';
  threestring += 'three';
}


const client = redis.createClient(6379, 'localhost', {
  ttl: 86400,
  return_buffers: true,
  timeout: 200,
  retry_strategy: function(options) {
    console.log('Redis retry #', options.attempt);
    // Try to reconnect every 5 seconds
    if (options.error && options.error.code === 'ECONNREFUSED') {
      console.log('Redis server refused the connection');
      return 5000;
    } // If there's some other error, log it and retry
    if (options.error) {
      console.log(options.error);
      return 2000;
      // otherwise, try reconnecting every 2 seconds
    } else return 2000;
  }
})
  .on('error', console.log)
  .on('ready', function() {
    console.log('Redis connection established.');
  });
client.command_queue_high_water = 2000;

setInterval(() => {
  client.set('one', onestring, (err, res) => {
    console.log(`set one err: ${err}`);
    console.log(`set one res: ${res}`);
    if (res) assert.equal(res, 'OK');
    client.set('two', twostring, (err, res) => {
      console.log(`set two err: ${err}`);
      console.log(`set two res: ${res}`);
      if (res) assert.equal(res, 'OK');
      client.set('three', threestring, (err, res) => {
        console.log(`set three err: ${err}`);
        console.log(`set three res: ${res}`);
        if (res) assert.equal(res, 'OK');
        client.get('one', (err, res) => {
          console.log(`get one err: ${err}`);
          console.log(`get one res: ${res && res.slice(0, 10)}`);
          if (res) assert.equal(res.slice(0,10).toString(), 'oneoneoneo');
          client.get('two', (err, res) => {
            console.log(`get two err: ${err}`);
            console.log(`get two res: ${res && res.slice(0, 10)}`);
            if (res) assert.equal(res.slice(0,10).toString(), 'twotwotwot');
            client.get('three', (err, res) => {
              console.log(`get three err: ${err}`);
              console.log(`get three res: ${res && res.slice(0, 10)}`);
              if (res) assert.equal(res.slice(0,10).toString(), 'threethree');
            });
          });
        });
      });
    });
  });
}, process.env.INTERVAL || 100);

(sorry for such a pyramid of doom shape to this test).

By running redis-server in one terminal and this script in another, with NODE_DEBUG=redis INTERVAL=10 node script.js, then terminating and restarting redis-server in the other terminal, I eventually trigger an error on the assert that says:

assert.js:84
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: <Buffer 23 20 53 65 72 76 65 72 0d 0a 72 65 64 69 73 5f 76 65 72 73 69 6f 6e 3a 34 2e 30 2e 39 0d 0a 72 65 64 69 73 5f 67 69 ... == 'OK'
    at Command.client.set [as callback] (/Users/jake/Projects/node-redis/script.js:43:21)

Since this issue is so difficult to trigger, I usually need to retry the connection severing several times.

Potential solutions

This problem can be solved by adding a setImmediate() or process.nextTick() into the stream.on('error') event handling. I do not know where it would be best to add this, but it seems like there are a few candidates:

• At the highest level, right when on('error') is fired
• Wrapping around the call to connection_gone()
• Around the flush_and_error() call that clears the command queue in connection_gone()
• Within flush_and_error()

My own moral compass points toward putting it inside the flush_and_error handler so that flushing is guaranteed to happen on the next tick, and the command queue would not grow after getting flushed. This would also be the least intrusive and most targeted approach. I could also see the case for putting it at the highest level, since that would effectively make the behavior on node >10.23.2 and 10.19.0 equivalent.

Environment

• Node.js Version: I can reproduce this on 10.23.2, node 12, and node 14. I do not see this issue on node 10.19.0. The key component seems to be a change in libuv to the way sockets emit events.

• Redis Version: Able to reproduce with 4.0.9 and 6.0.5
• node-redis Version: Originally detected on 2.8.0, able to reproduce on 3.x as well.

• Platform: Mac and Linux

Start with index.js, especially the stream error handler, connection_gone(), flush_and_error(), and internal_send_command(), then run the supplied reproduction script against Redis while restarting redis-server. Done means a socket disconnect during a write no longer leaves a stray command in command_queue, and commands receive correct replies after reconnection.