instrumentation-redis-4 tests fail with redis@4.6.12

[trentm]

"test-all-versions" (TAV) tests are failing for @opentelemetry/instrumentation-redis-4 on redis@4.6.12. E.g. https://github.com/open-telemetry/opentelemetry-js-contrib/actions/runs/7263854755/job/19790084068#step:9:36052

-- required packages ["redis@4.6.12"]
-- installing ["redis@4.6.12"]
-- running test "npm run test" with redis (env: {})
...
     multi (transactions) commands
      ✓ multi commands
      ✓ multi command with generic command
      1) multi command with error
      ✓ multi command that rejects
...
  1 failing

  1) redis@^4.0.0
       multi (transactions) commands
         multi command with error:
     1 commands failed, see .replies and .errorIndexes for more information

The tests pass with redis@4.6.11.

repro

This is using the current latest "main" (commit e35e370).

cd plugins/node/opentelemetry-instrumentation-redis-4
npm install --no-save redis@4.6.12
npm run test:local

Full output run

% npm run test:local

> @opentelemetry/instrumentation-redis-4@0.35.5 test:local
> cross-env RUN_REDIS_TESTS_LOCAL=true npm run test


> @opentelemetry/instrumentation-redis-4@0.35.5 test
> nyc ts-mocha -p tsconfig.json --require '@opentelemetry/contrib-test-utils' 'test/redis.test.ts'



  redis@^4.0.0
    redis commands
      ✓ simple set and get
      ✓ send general command
      ✓ command with error
    client connect
      ✓ produces a span
      ✓ sets error status on connection failure
      ✓ omits basic auth from DB_CONNECTION_STRING span attribute
      ✓ omits user_pwd query parameter from DB_CONNECTION_STRING span attribute
    multi (transactions) commands
      ✓ multi commands
      ✓ multi command with generic command
      1) multi command with error
      ✓ multi command that rejects
      ✓ duration covers create until server response
      ✓ response hook for multi commands
    config
      dbStatementSerializer
        ✓ custom dbStatementSerializer
        ✓ dbStatementSerializer throws
      responseHook
        ✓ valid response hook
        ✓ responseHook throws
      requireParentSpan
        ✓ set to true


  17 passing (694ms)
  1 failing

  1) redis@^4.0.0
       multi (transactions) commands
         multi command with error:
     1 commands failed, see .replies and .errorIndexes for more information




--------------------|---------|----------|---------|---------|--------------------------------------------------------------------------
File                | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s
--------------------|---------|----------|---------|---------|--------------------------------------------------------------------------
All files           |   79.14 |    50.93 |   90.69 |   78.91 |
 instrumentation.ts |   79.31 |    48.43 |   90.24 |   79.06 | ...6,130,139,150-157,175-178,186,196,213-222,237,283-286,293,298,306,328
 utils.ts           |   76.92 |    72.72 |     100 |   76.92 | 44,54-56
--------------------|---------|----------|---------|---------|--------------------------------------------------------------------------
npm ERR! Lifecycle script `test` failed with error:
npm ERR! Error: command failed
npm ERR!   in workspace: @opentelemetry/instrumentation-redis-4@0.35.5
npm ERR!   at location: /Users/trentm/tm/opentelemetry-js-contrib4/plugins/node/opentelemetry-instrumentation-redis-4
npm ERR! Lifecycle script `test:local` failed with error:
npm ERR! Error: command failed
npm ERR!   in workspace: @opentelemetry/instrumentation-redis-4@0.35.5
npm ERR!   at location: /Users/trentm/tm/opentelemetry-js-contrib4/plugins/node/opentelemetry-instrumentation-redis-4

the cause

redis@4.6.12 includes an update to @redis/client@1.5.13, which includes a change to handling of runtime errors in client.multi()... such that it will throw. See redis/node-redis#2665

details

Save this to "use-redis.js" in the "plugins/node/opentelemetry-instrumentation-redis-4" dir:

const { RedisInstrumentation } = require('./');
const { NodeSDK, tracing } = require('@opentelemetry/sdk-node');
const sdk = new NodeSDK({
  serviceName: 'use-redis',
  spanProcessor: new tracing.SimpleSpanProcessor(new tracing.ConsoleSpanExporter()),
  instrumentations: [
    new RedisInstrumentation()
  ]
});
sdk.start();

const { createClient } = require('redis');
console.log('Use redis@%s', require('redis/package.json').version);
const client = createClient();

async function main() {
  await client.connect();

  let replies = await client.multi().set('key', 'value').incr('key').exec(); // ['OK', 'ReplyError']
  console.log('replies:', replies);

  await client.quit();
}

main()

Start a temporary redis server:

docker run --rm -d --name tmp-redis -p 6379:6379 redis:alpine

Then run use-redis.js with redis@4.6.11 and 4.6.12:

use-redis.js with 4.6.11

% npm install --no-save redis@4.6.11
% node use-redis.js
Use redis@4.6.11
{
  traceId: 'fc0104bfa216f189643ce8741cdc31b5',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-connect',
  id: '3956ba119ab5de30',
  kind: 2,
  timestamp: 1703111117333000,
  duration: 7778.773,
  attributes: { 'db.system': 'redis' },
  status: { code: 0 },
  events: [],
  links: []
}
{
  traceId: 'e765425c2703c3f9153743aadb3a8dd2',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-SET',
  id: 'f59c371a3ccba1ab',
  kind: 2,
  timestamp: 1703111117343000,
  duration: 1928.125,
  attributes: {
    'db.system': 'redis',
    'db.statement': 'SET key [1 other arguments]'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  traceId: '7a8aae2b4e0a715b656668a35912c4e4',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-INCR',
  id: 'f6379c7099669368',
  kind: 2,
  timestamp: 1703111117343000,
  duration: 1785.214,
  attributes: { 'db.system': 'redis', 'db.statement': 'INCR key' },
  status: { code: 2, message: 'ERR value is not an integer or out of range' },
  events: [
    {
      name: 'exception',
      attributes: {
        'exception.type': 'Error',
        'exception.message': 'ERR value is not an integer or out of range'
      },
      time: [ 1703111117, 344759161 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
replies: [ 'OK', [ErrorReply: ERR value is not an integer or out of range] ]

use-redis.js with 4.6.12

% npm install --no-save redis@4.6.12
% node use-redis.js
Use redis@4.6.12
{
  traceId: '3469f889c3df3af3c281f66a9667c12e',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-connect',
  id: 'fefa13498e2fe2ec',
  kind: 2,
  timestamp: 1703111003465000,
  duration: 8308.435,
  attributes: { 'db.system': 'redis' },
  status: { code: 0 },
  events: [],
  links: []
}
{
  traceId: 'b945a55978698646a9ccd4d12cbc77fa',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-SET',
  id: 'f788e346e22e5507',
  kind: 2,
  timestamp: 1703111003475000,
  duration: 2227.607,
  attributes: {
    'db.system': 'redis',
    'db.statement': 'SET key [1 other arguments]'
  },
  status: {
    code: 2,
    message: '1 commands failed, see .replies and .errorIndexes for more information'
  },
  events: [
    {
      name: 'exception',
      attributes: {
        'exception.type': 'Error',
        'exception.message': '1 commands failed, see .replies and .errorIndexes for more information'
      },
      time: [ 1703111003, 477204433 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
{
  traceId: '47287d300cb423bc9e5259abaeeb3678',
  parentId: undefined,
  traceState: undefined,
  name: 'redis-INCR',
  id: '4a99d39f958a8be7',
  kind: 2,
  timestamp: 1703111003476000,
  duration: 2115.322,
  attributes: { 'db.system': 'redis', 'db.statement': 'INCR key' },
  status: {
    code: 2,
    message: '1 commands failed, see .replies and .errorIndexes for more information'
  },
  events: [
    {
      name: 'exception',
      attributes: {
        'exception.type': 'Error',
        'exception.message': '1 commands failed, see .replies and .errorIndexes for more information'
      },
      time: [ 1703111003, 478103972 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
node:internal/process/promises:279
            triggerUncaughtException(err, true /* fromPromise */);
            ^

[MultiErrorReply: 1 commands failed, see .replies and .errorIndexes for more information] {
  replies: [ 'OK', [ErrorReply: ERR value is not an integer or out of range] ],
  errorIndexes: [ 1 ]
}

The main difference is that now client.multi()... throws with a MultiErrorReply. The error does include enough information to set span.status on each span as before, but the instrumentation will need to adjust for that (using err.replies and possibly err.errorIndexes).