test: fix race in redis-4 tests

[trentm]

The beforeEach() hook was not awaited, so afterEach() could run before it completed, resulting in a client.disconnect() that rejects, and a mocha hook that calls done() twice.

Refs: #1860

details

The redis-4 tests are sometimes failing as follows. There is a timing race in the test.

  1) redis@^4.0.0
       "after each" hook in "redis@^4.0.0":
     Error: done() called multiple times in hook <redis@^4.0.0 "after each" hook> of file /Users/trentm/tm/opentelemetry-js-contrib2/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts; in addition, done() received error: TypeError: Cannot read properties of undefined (reading 'destroy')
...

With this patch to add some debug prints:

diff --git a/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts b/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts
@@ -71,12 +71,15 @@
   beforeEach(async () => {
     client = createClient({
       url: redisTestUrl,
     });
     context.with(suppressTracing(context.active()), async () => {
       await client.connect();
+      console.log('XXX beforeEach: client connected');
     });
   });

   afterEach(async () => {
+    console.log('XXX afterEach: client disconnecting');
     await client?.disconnect();
   });

the relevant section of the test output of a failing run looks like this:

...
    client connect
XXX beforeEach: client connected
      ✓ produces a span
XXX afterEach: client disconnecting
      ✓ sets error status on connection failure
XXX afterEach: client disconnecting             <-- HERE, client.disconnect() called before connected
      1) "after each" hook in "redis@^4.0.0"
      ✓ omits basic auth from DB_CONNECTION_STRING span attribute
XXX beforeEach: client connected
XXX afterEach: client disconnecting
      ✓ omits user_pwd query parameter from DB_CONNECTION_STRING span attribute
XXX beforeEach: client connected
XXX afterEach: client disconnecting
...

  1) redis@^4.0.0
       "after each" hook in "redis@^4.0.0":
     Error: done() called multiple times in hook <redis@^4.0.0 "after each" hook> of file /Users/trentm/tm/opentelemetry-js-contrib2/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts; in addition, done() received error: TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/@redis/client/dist/lib/client/socket.js:154:71)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at Commander.connect (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/@redis/client/dist/lib/client/index.js:185:9)
    at /Users/trentm/tm/opentelemetry-js-contrib2/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts:75:7 {
  uncaught: true
}
      at process.emit (node:events:513:28)
      at processEmit (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/signal-exit/index.js:199:34)
      at process.emit (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/source-map-support/source-map-support.js:516:21)
      at process._fatalException (node:internal/process/execution:149:25)
      at processPromiseRejections (node:internal/process/promises:279:13)
      at processTicksAndRejections (node:internal/process/task_queues:97:32)

The issue is that in one of the test cases that runs quickly, the client.disconnect() in the afterEach() hook is running before the client.connect() in the beforeEach() has completed, and that results in client.disconnect() rejecting:

% node
Welcome to Node.js v16.20.2.
Type ".help" for more information.
> const { createClient } = require('redis')
undefined
> let client = createClient(); client.disconnect()
Promise {
  <rejected> ClientClosedError: The client is closed
      at RedisSocket.disconnect (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/@redis/client/dist/lib/client/socket.js:63:19)
      at Commander.disconnect (/Users/trentm/tm/opentelemetry-js-contrib2/node_modules/@redis/client/dist/lib/client/index.js:343:64)
      at REPL13:1:37
      at Script.runInThisContext (node:vm:129:12)
      at REPLServer.defaultEval (node:repl:572:29)
      at bound (node:domain:433:15)
      at REPLServer.runBound [as eval] (node:domain:444:12)
      at REPLServer.onLine (node:repl:902:10)
      at REPLServer.emit (node:events:525:35)
      at REPLServer.emit (node:domain:489:12),
  [Symbol(async_id_symbol)]: 489,
  [Symbol(trigger_async_id_symbol)]: 5
}

This race can happen because the beforeEach() hook is not awaited. This changed by accident in a change to the beforeEach() hook in #1125.

@@ -71,7 +71,9 @@ describe('redis@^4.0.0', () => {
     client = createClient({
       url: redisTestUrl,
     });
-    await client.connect();
+    context.with(suppressTracing(context.active()), async () => {
+      await client.connect();
+    });
   });

That change also added a test case -- sets error status on connection failure -- that runs fast enough to sometimes trigger this.

[codecov]

Codecov Report

Merging #1863 (96e24b2) into main (4f98916) will not change coverage.
The diff coverage is n/a.

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #1863   +/-   ##
=======================================
  Coverage   91.45%   91.45%           
=======================================
  Files         144      144           
  Lines        7406     7406           
  Branches     1483     1483           
=======================================
  Hits         6773     6773           
  Misses        633      633           

[trentm]

Note: the TAV test for Node.js 14 fails for a different reason that will be fixed by #1862

[pichlermarc]

tests for redis-4 are all green, thanks for tracking this down @trentm 🙂