Can not execute the operation on ended Span / tls.connect .. You can only call end() on a span once.

[stdedos]

What happened?

Steps to Reproduce

Run a private repo using nodemon

Expected Result

Actual Result

logs

Additional Details

Seems related to:

• the Can not execute the operation on ended Span opentelemetry-instrumentation-http #2575 issue - but 0.41.0 is not fixing it 😕
• the express plugin: multiple .end() call & .setStatus after .end() of span #908
• the plugin-express: end() called more than once on async handlers opentelemetry-js-contrib#107

OpenTelemetry Setup Code

/* eslint-disable no-console -- this file cannot use the proper logger
 */

import { createAzureSdkInstrumentation } from '@azure/opentelemetry-instrumentation-azure-sdk'
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto'
import { registerInstrumentations } from '@opentelemetry/instrumentation'
import { DnsInstrumentation } from '@opentelemetry/instrumentation-dns'
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express'
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http'
import { NetInstrumentation } from '@opentelemetry/instrumentation-net'
import { WinstonInstrumentation } from '@opentelemetry/instrumentation-winston'
import { Resource } from '@opentelemetry/resources'
import {
  BatchSpanProcessor,
  NoopSpanProcessor,
} from '@opentelemetry/sdk-trace-base'
import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'
import { getCurrentLoggerMetadata } from './common/logger-metadata-context'
import { getVersionString } from './common/version-string'
import type { SpanExporter, SpanProcessor } from '@opentelemetry/sdk-trace-base'

/*
 * This file is responsible for initializing OpenTelemetry. It is preloaded by
 * Node.js, so it can be used to initialize OpenTelemetry before any other code
 * is executed.
 *
 * It's important that this file does not import any other non-essential modules,
 * because those modules may be instrumented by OpenTelemetry and importing them
 * here would break the instrumentation.
 */

main()

function main() {
  const resource = createResource()

  const provider = new NodeTracerProvider({
    resource,
  })

  const exporter = createExporter()

  const spanProcessor = createSpanProcessor(exporter)

  provider.addSpanProcessor(spanProcessor)
  provider.register()

  registerInstrumentations({
    instrumentations: [
      new HttpInstrumentation({
        ignoreIncomingPaths: ['/health'],
      }),
      new WinstonInstrumentation({
        logHook: (_, record) => {
          const currentLoggerMetadata = getCurrentLoggerMetadata()
          if (currentLoggerMetadata !== undefined) {
            Object.assign(record, currentLoggerMetadata)
          }
        },
      }),
      new ExpressInstrumentation(),
      new DnsInstrumentation(),
      new NetInstrumentation(),
      createAzureSdkInstrumentation(),
    ],
    tracerProvider: provider,
  })

  const exitHandler = () => {
    console.log('Shutting down OpenTelemetry...')
    // Schedule the shutdown to happen after the current event loop iteration
    // completes. This is necessary because we want to give the exporter a
    // chance to send any remaining spans.
    provider
      .shutdown()
      .then(() => console.log('OpenTelemetry shutdown complete'))
      .catch((ex) => console.error('OpenTelemetry shutdown failed', ex))
  }

  process.on('SIGINT', exitHandler)
  process.on('SIGTERM', exitHandler)
}

function createResource(): Resource {
  const serviceName = process.env['NAME_SERVICE']
  const envName = process.env['ENVIRONMENT_NAME']

  return Resource.default().merge(
    new Resource({
      [SemanticResourceAttributes.SERVICE_NAME]: serviceName,
      service_name: serviceName,
      [SemanticResourceAttributes.SERVICE_NAMESPACE]: 'Namespace name',
      [SemanticResourceAttributes.SERVICE_VERSION]: getVersionString(),
      [SemanticResourceAttributes.DEPLOYMENT_ENVIRONMENT]: envName,
    }),
  )
}

function createExporter() {
  const exporterNameEnvVar = 'OTEL_TRACES_EXPORTER'
  const exporterName = process.env[exporterNameEnvVar]
  const isProduction = process.env['NODE_ENV'] === 'production'

  switch (exporterName) {
    case undefined:
    case '':
      if (isProduction) {
        console.error(
          'Opentelemetry span exporting has not been configured, and defaulted to off. This is probably a mistake in production.',
        )
      }
      return undefined
    case 'none':
      if (isProduction) {
        console.warn(
          'Opentelemetry span exporting has been explicitly disabled. This is probably a mistake in production.',
        )
      }
      return undefined
    case 'otlp':
      return new OTLPTraceExporter()
    default:
      throw new Error(
        `Unknown value received for the environment variable '${exporterNameEnvVar}'`,
      )
  }
}

function createSpanProcessor(
  exporter: SpanExporter | undefined,
): SpanProcessor {
  return exporter === undefined
    ? new NoopSpanProcessor()
    : new BatchSpanProcessor(exporter)
}

/* eslint-enable no-console */

package.json

"dependencies": {
    "@azure/opentelemetry-instrumentation-azure-sdk": "^1.0.0-beta.2",
    "@opentelemetry/api": "^1.3.0",
    "@opentelemetry/exporter-trace-otlp-proto": "^0.38.0",
    "@opentelemetry/instrumentation": "^0.38.0",
    "@opentelemetry/instrumentation-dns": "^0.31.0",
    "@opentelemetry/instrumentation-express": "^0.32.0",
    "@opentelemetry/instrumentation-http": "^0.41.0",
    "@opentelemetry/instrumentation-net": "^0.31.0",
    "@opentelemetry/instrumentation-winston": "^0.31.0",
    "@opentelemetry/resources": "^1.8.0",
    "@opentelemetry/sdk-trace-base": "^1.8.0",
    "@opentelemetry/sdk-trace-node": "^1.8.0",
    "@opentelemetry/semantic-conventions": "^1.8.0",
...
    "express": "^4.18.2",
    "express-basic-auth": "^1.2.1",
    "express-jwt": "^8.4.1",

Relevant log output

[WebServer] {
  "level": "warn",
  "message": "Can not execute the operation on ended Span {traceId: b77b886664c95c5e7e937f5a6200fcf0, spanId: 6a4d3ced1105c832}",
  "span_id": "78d5aca7fc8ac3c2",
  "timestamp": "2023-07-17T07:27:02.300Z",
  "trace_flags": "01",
  "trace_id": "b77b886664c95c5e7e937f5a6200fcf0"
}
{
  "level": "warn",
  "message": "Can not execute the operation on ended Span {traceId: b77b886664c95c5e7e937f5a6200fcf0, spanId: 6a4d3ced1105c832}",
  "span_id": "78d5aca7fc8ac3c2",
  "timestamp": "2023-07-17T07:27:02.301Z",
  "trace_flags": "01",
  "trace_id": "b77b886664c95c5e7e937f5a6200fcf0"
}
[WebServer] {
  "level": "error",
  "message": "tls.connect b77b886664c95c5e7e937f5a6200fcf0-6a4d3ced1105c832 - You can only call end() on a span once.",
  "span_id": "78d5aca7fc8ac3c2",
  "timestamp": "2023-07-17T07:27:02.301Z",
  "trace_flags": "01",
  "trace_id": "b77b886664c95c5e7e937f5a6200fcf0"
}

[dyladan]

This seems like it might be a bug in one of the instrumentations. Is the telemetry incorrect or are you just seeing unexpected logs?

[stdedos]

Those 3 messages are most definitely unexpected. And very predictable - "just start and wait 2 minutes" (or so).

All other telemetry looks correct - despite the above 3 log messages.

[cameron-ross-bluecore]

We are seeing the same issue when using @opentelemetry/instrumentation-net

[zmilonas]

@stdedos What version of Node.js are you running? Since I cannot see this information in your original post.

I am also experiencing this on Node.js 20 similarly when using @opentelemetry/auto-instrumentation-node which also uses @opentelemetry/instrumentation-net under the hood.

[googol]

Answering for my teammate @stdedos, we are seeing this on node 18

[zmilonas]

@googol Ok so I guess it's not neccessarily node version related.

Doing a little digging i found a change in @opentelemetry/instrumentation-net that could be related - this commit: open-telemetry/opentelemetry-js-contrib@1ee197e

This has landed in 0.31.1 of @opentelemetry/instrumentation-net

Maybe if you have time you can try and install exactly @opentelemetry/instrumentation-net@0.31.0 to see if this was a regression?

[stdedos]

No luck:

u@h:prj$ npm i @opentelemetry/instrumentation-net@0.31.0

added 1 package, changed 2 packages, and audited 1113 packages in 15s
u@h:prj$ npm run dev

> prj@1.0.0 dev
> nodemon

[nodemon] 2.0.22
[nodemon] to restart at any time, enter `rs`
[nodemon] watching path(s): src/**/*
[nodemon] watching extensions: ts
[nodemon] starting `ts-node -r ./src/initialize-telemetry.ts --transpile-only ./src/index.ts`
...
{
  "level": "info",
  "message": "Server listening for connections on 0.0.0.0:4900",
  "timestamp": "2023-08-09T15:02:46.259Z"
}
{
  "level": "warn",
  "message": "Can not execute the operation on ended Span {traceId: b67fc07d0cf9496fe8dad2a49c0dc4f0, spanId: cac5b97cca3baf39}",
  "span_id": "8581abcc0d119d2f",
  "timestamp": "2023-08-09T15:05:50.430Z",
  "trace_flags": "01",
  "trace_id": "b67fc07d0cf9496fe8dad2a49c0dc4f0"
}
{
  "level": "warn",
  "message": "Can not execute the operation on ended Span {traceId: b67fc07d0cf9496fe8dad2a49c0dc4f0, spanId: cac5b97cca3baf39}",
  "span_id": "8581abcc0d119d2f",
  "timestamp": "2023-08-09T15:05:50.430Z",
  "trace_flags": "01",
  "trace_id": "b67fc07d0cf9496fe8dad2a49c0dc4f0"
}
{
  "level": "error",
  "message": "tls.connect b67fc07d0cf9496fe8dad2a49c0dc4f0-cac5b97cca3baf39 - You can only call end() on a span once.",
  "span_id": "8581abcc0d119d2f",
  "timestamp": "2023-08-09T15:05:50.431Z",
  "trace_flags": "01",
  "trace_id": "b67fc07d0cf9496fe8dad2a49c0dc4f0"
}

[stdedos]

Hello everyone! Any progress? 🙃

[seemk]

@stdedos Do you have an example of such a span? Would be interesting to see whether it had any relevant attributes (e.g. errors).

[stdedos]

@seemk, unfortunately, I cannot provide a direct example of such a span due to the private nature of the project.
I also don't have any data (that I am aware of), apart from what is already on my comment (in the warning logs).

Doesn't my example replicate locally?

[stdedos]

We are also seeing them on every 400 request to our API

[seemk]

I haven't managed to reproduce it yet, but my hunch is that a TLS socket error is emitted after a successful tls.connect.

[seemk]

If possible, what's the library you are doing the outgoing requests with? And which HTTP server are you using? Trying to replicate it as close as possible.

[stdedos]

Server is express (as visible in package.json above)

Client is axios

    "axios": "^1.4.0",

[stdedos]

It seems that

import { NetInstrumentation } from '@opentelemetry/instrumentation-net'

Is the culprit in our situation.

[stdedos]

Registered via:

function main() {
  const resource = createResource()

  const provider = new NodeTracerProvider({
    resource,
  })

  const exporter = createExporter()

  const spanProcessor = createSpanProcessor(exporter)

  provider.addSpanProcessor(spanProcessor)
  provider.register()

  registerInstrumentations({
    instrumentations: [
      // new ...({
      //   ...
      // }),
      // new ...({
      //   ...
      // }),
      // new ...(),
      // new ...(),
      new NetInstrumentation(),
      // ...(),
    ],
    tracerProvider: provider,
  })

  const exitHandler = () => {
    console.log('Shutting down OpenTelemetry...')
    // Schedule the shutdown to happen after the current event loop iteration
    // completes. This is necessary because we want to give the exporter a
    // chance to send any remaining spans.
    provider
      .shutdown()
      .then(() => console.log('OpenTelemetry shutdown complete'))
      .catch((ex) => console.error('OpenTelemetry shutdown failed', ex))
  }

  process.on('SIGINT', exitHandler)
  process.on('SIGTERM', exitHandler)
}

[pichlermarc]

Hi all, looks like this is caused by the net instrumentation, which is part of the contrib repo. There's an issue there for the same problem. I'll close this issue here as a duplicate but you can follow the progress over at open-telemetry/opentelemetry-js-contrib#1775

If you think that's not correct, please feel free to reach out and I'll re-open this issue and transfer it to the contrib repo.