Duplicate end() and span API calls after Redis timeout

[tyio]

What happened?

When a Redis command times out, the ioredis instrumentation tries to use the same span after it has already been ended. This leads to two OpenTelemetry errors: You can only call end() on a span once and Cannot execute the operation on ended Span. It looks like both end() and other span methods are called more than once due to how the error is handled internally.

Steps to Reproduce

This minimal Node.js app uses ioredis with @opentelemetry/instrumentation-ioredis. It sets a very short commandTimeout to simulate a Redis timeout. This leads to multiple errors from OpenTelemetry due to unsafe usage of already-ended spans.

Redis must be running locally (e.g. via Docker: docker run --rm -p 6379:6379 redis).

index.js

// index.js

const sdk = require('./tracing');

const Redis = require('ioredis');

const redis = new Redis({
  host: '127.0.0.1',
  port: 6379,
  connectTimeout: 1000,
  commandTimeout: 5, // Configure small timeout
});

async function run() {
  try {
    await redis.get('foo');
  } catch (err) {
    console.error('Redis error:', err);
  } finally {
    redis.disconnect();

    sdk.shutdown();
  }
}

run();

Expected Result

• The span for the Redis command should be ended exactly once.
• OpenTelemetry API methods (e.g. recordException, setStatus) should only be called while the span is active.
• No internal OpenTelemetry errors should occur.

Actual Result

Two OpenTelemetry errors are logged when the Redis command times out:

• You can only call end() on a span once

Can not execute the operation on ended Span {traceId: ..., spanId: ...} - You can only call end() on a span once

• Cannot execute the operation on ended Span
  This happens when the plugin tries to call recordException() or setStatus() on a span that was already ended.

Additional Details

• Node.js version: v20.12.2
• Module system: CommonJS
• Run with: node index.js
• Package versions:
  • ioredis: 5.3.2
  • @opentelemetry/sdk-node: 0.50.0
  • @opentelemetry/api: 1.18.0
  • @opentelemetry/instrumentation-ioredis: 0.50.0
  • @opentelemetry/sdk-trace-base: 1.18.0

OpenTelemetry Setup Code

const { NodeSDK } = require("@opentelemetry/sdk-node");
const {
  IORedisInstrumentation,
} = require("@opentelemetry/instrumentation-ioredis");

const { diag, DiagConsoleLogger, DiagLogLevel } = require("@opentelemetry/api");

diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ALL);

const sdk = new NodeSDK({
  instrumentations: [new IORedisInstrumentation({ requireParentSpan: false})],
});

sdk.start();

module.exports = sdk;

package.json

{
  "name": "test",
  "version": "1.0.0",
  "scripts": {
    "start": "node index.js"
  },
  "author": "",
  "license": "ISC",
  "description": "",
  "dependencies": {
    "@opentelemetry/api": "^1.9.0",
    "@opentelemetry/instrumentation-ioredis": "^0.50.0",
    "@opentelemetry/sdk-node": "^0.202.0",
    "ioredis": "^5.6.1"
  }
}

Relevant log output

Redis error: Error: Command timed out
    at Timeout._onTimeout (/sandbox/test-redis/node_modules/ioredis/built/Command.js:192:33)
    at listOnTimeout (node:internal/timers:588:17)
    at process.processTimers (node:internal/timers:523:7)
OTLPExportDelegate shutdown started
Cannot execute the operation on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9} Error: Operation attempted on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9}
    at SpanImpl._isSpanEnded (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:265:27)
    at SpanImpl.addEvent (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:118:18)
    at SpanImpl.recordException (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:242:18)
    at endSpan (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/utils.js:22:14)
    at cmd.reject (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:128:41)
    at EventEmitter.flushQueue (/sandbox/test-redis/node_modules/ioredis/built/Redis.js:632:30)
    at close (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:189:14)
    at Socket.<anonymous> (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:156:20)
    at Object.onceWrapper (node:events:633:26)
    at Socket.emit (node:events:530:35)
Cannot execute the operation on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9} Error: Operation attempted on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9}
    at SpanImpl._isSpanEnded (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:265:27)
    at SpanImpl.setStatus (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:158:18)
    at endSpan (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/utils.js:23:14)
    at cmd.reject (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:128:41)
    at EventEmitter.flushQueue (/sandbox/test-redis/node_modules/ioredis/built/Redis.js:632:30)
    at close (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:189:14)
    at Socket.<anonymous> (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:156:20)
    at Object.onceWrapper (node:events:633:26)
    at Socket.emit (node:events:530:35)
    at TCP.<anonymous> (node:net:351:12)
Cannot execute the operation on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9} Error: Operation attempted on ended Span {traceId: 3b1fc4577478d07c3a221eea1310e6ba, spanId: 61dd2b1c7127fdf9}
    at SpanImpl._isSpanEnded (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:265:27)
    at SpanImpl.end (/sandbox/test-redis/node_modules/@opentelemetry/sdk-trace-base/build/src/Span.js:178:18)
    at endSpan (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/utils.js:28:10)
    at cmd.reject (/sandbox/test-redis/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:128:41)
    at EventEmitter.flushQueue (/sandbox/test-redis/node_modules/ioredis/built/Redis.js:632:30)
    at close (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:189:14)
    at Socket.<anonymous> (/sandbox/test-redis/node_modules/ioredis/built/redis/event_handler.js:156:20)
    at Object.onceWrapper (node:events:633:26)
    at Socket.emit (node:events:530:35)
    at TCP.<anonymous> (node:net:351:12)
get 3b1fc4577478d07c3a221eea1310e6ba-61dd2b1c7127fdf9 - You can only call end() on a span once.

Operating System and Version

Ubuntu 24.04

Runtime and Version

NodeJS v22.15.0, npm 10.9.2

[pichlermarc]

@tyio thanks for reporting this - to add some info to this: the logs that you're seeing are warning logs but it seems that the exported telemetry is correct since the correct handler runs first. This is something that we definitely need to address in the instrumentation, but the logs should be safe to ignore for now.