Autoinstrumentation not working #1109

sta-szek · 2022-08-03T15:25:28Z

Help required 🙏

What version of OpenTelemetry are you using?

    "@opentelemetry/auto-instrumentations-node": "^0.31.0",
    "@opentelemetry/core": "^1.5.0",
    "@opentelemetry/exporter-jaeger": "^1.5.0",
    "@opentelemetry/propagator-b3": "^1.5.0",
    "@opentelemetry/resources": "^1.5.0",
    "@opentelemetry/sdk-node": "^0.31.0",
    "@opentelemetry/sdk-trace-base": "^1.5.0",
    "@opentelemetry/sdk-trace-node": "^1.5.0",
    "@opentelemetry/semantic-conventions": "^1.5.0",

What version of Node are you using?

node --version
v17.8.0

Hi,
I have implemented and tested locally the tracing, using ⬆️ libraries.
It was working properly - i saw spans reported, they were autoinstrumented on libraries like express or networking.

After that, I cannot fully recall, but I went through some nodeJS courses (possibly invoking tsc in my project). After 2 days i wanted to run example again, and since then its not working anymore.
I was trying to play around and revert all modules (i refactored to modules), then reimplemented from scratch, and again, autoinstrumentation does not work.

What works is the manual test:

  trace.getTracerProvider().getTracer('debug').startSpan('test manual from main app').end();
  setInterval(()=> {
    trace.getTracerProvider().getTracer('debug').startSpan('test manual span each 10 second').end();
  }, 10000);

I tried all of https://opentelemetry.io/blog/2022/troubleshooting-nodejs/ and without result.
i added debug logger and can see in logs:

@opentelemetry/api: Registered a global for diag v1.1.0.

Applying patch for [email protected]

which indicates that it is still autoregistering some components.

my full code added to app:

import {trace} from "@opentelemetry/api";
import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
import {JaegerExporter} from "@opentelemetry/exporter-jaeger";
import {AlwaysOnSampler} from "@opentelemetry/core";
import {Resource} from "@opentelemetry/resources";
import {SemanticResourceAttributes} from "@opentelemetry/semantic-conventions";
import {B3InjectEncoding, B3Propagator} from "@opentelemetry/propagator-b3";
import {getNodeAutoInstrumentations} from "@opentelemetry/auto-instrumentations-node";
import opentelemetry = require('@opentelemetry/sdk-node');
import {BatchSpanProcessor} from "@opentelemetry/sdk-trace-base";


  const traceExporter = new JaegerExporter({endpoint: 'http://localhost:14268/api/traces'});
  console.log(traceExporter)
  const sampler = new AlwaysOnSampler();
  const resource = Resource.default().merge(new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: "optimization-reporting-jopi-localhost",
    [SemanticResourceAttributes.SERVICE_VERSION]: "0.75.0"
  }));

  const textMapPropagator = new B3Propagator({injectEncoding: B3InjectEncoding.MULTI_HEADER});

  const sdk = new opentelemetry.NodeSDK({
    autoDetectResources: true,
    contextManager: undefined,
    defaultAttributes: undefined,
    textMapPropagator: textMapPropagator,
    metricReader: undefined,
    instrumentations: [getNodeAutoInstrumentations()],
    resource: resource,
    sampler: sampler,
    serviceName: "optimization-reporting-jopi-localhost",
    spanProcessor: new BatchSpanProcessor(traceExporter, {}),
    traceExporter: traceExporter,
    spanLimits: undefined,
  })

  process.on('SIGTERM', () => sdk.shutdown().finally(() => process.exit(0)));

  await sdk.start();
  diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

  trace.getTracerProvider().getTracer('debug').startSpan('test manual from main app').end();
  setInterval(()=> {
    trace.getTracerProvider().getTracer('debug').startSpan('test manual span each 10 second').end();
  }, 10000);

what else can i try?

The text was updated successfully, but these errors were encountered:

Flarna · 2022-08-03T15:55:18Z

Could you explain what is not working? Above description just tells that manual creation of spans works as expected.

Also your sample code doesn't use express or similar. Therefore it's hard to understand the problem.

sta-szek · 2022-08-03T17:27:03Z

Could you explain what is not working? Above description just tells that manual creation of spans works as expected.

Also your sample code doesn't use express or similar. Therefore it's hard to understand the problem.

Hi,
so basically my app is using NestJS (with express under the hood).
Previously, the autoinstrumentation worked, so i could see spans for all requests coming from web.

After some time, when i run it again it does not work, which means i cannot see autoinstrumented spans - express, otel-networking etc... but i still see manually created spans - which confirms that span exporting works properly.

Not sure why the autoinstrumentation does not work anymore, as it used to be. I check it in different PC, redeveloped from scratch, copy-pasted from tutorials, and still... Smth either changed or i dont know, but its not working anymore. i also ran out of ideas what to check.

Any clues would be appreciated.

When it was working i saw spans like this:

now i cant see spans, except the one created manually...

Flarna · 2022-08-03T20:32:01Z

Without your code it's hard to tell. I recommend to post working and non working code to allow comparison.
if you lost the working code or you are sure that there is no diff between working/non working I guess some changes in the dependencies caused this.

do you ensure that OTel is fully initalised before you require express/nest-js/http?

sta-szek · 2022-08-04T10:02:42Z

unfortunatelly cannot share application and the code i shared above is called in app.ts in first lines. i can also see in logs

@opentelemetry/api: Registered a global for diag v1.1.0.
Applying patch for [email protected]
@opentelemetry/api: Registered a global for trace v1.1.0.
@opentelemetry/api: Registered a global for context v1.1.0.
@opentelemetry/api: Registered a global for propagation v1.1.0.
Jaeger exporter export
successful append for : 1
successful flush for 1 spans

but the autoinstrumentation still does not work.

the code did not change, i am pretty sure about it. the libraries was version 1.4.0 but now its 1.5.0. anyway, it stopped working with 1.4.0 already.
i am blind what to check next

do you ensure that OTel is fully initalised before you require express/nest-js/http?

how to ensure that?

Flarna · 2022-08-04T11:41:57Z

how to ensure that?

It's about the sequence of require. It's important that instrumentations are loaded/initialized before the corresponding module is loaded.
e.g.:

const express =require("express"); // wont be instrumented
// register instrumentations
const nestjs = require("nestjs"); // should be instrumented

You use NodeSDK which registers instrumentations at the end of the start() call. So it should be safe to require other compoents after await sdk.start().

Side note: While writing this I notice that this is actually quite a bad choice in NodeSDK as the first thing start() does is to await this.detectResources(); which might already need http....

You could easily workaround this by remving instrumentations: [getNodeAutoInstrumentations()], and instead add

const { registerInstrumentations } = require('@opentelemetry/instrumentation');
registerInstrumentations({
  instrumentations: getNodeAutoInstrumentations()
});

at the very beginning of your main/tracesetup script, e.g. even before require/initializing JaegerExporter.

Another potential problem is module duplication because of non matching ranges.
@opentelemetry/[email protected] depends on "@opentelemetry/instrumentation": "^0.29.2".
@opentelemetry/[email protected] depends on "@opentelemetry/instrumentation": "0.31.0"

^0.29.2 and 0.31.0 do not overlap therefore you get two instances of @opentelemetry/instrumentation. There might be more similar issues.
You could step back to 0.29.1/1.3.0 for packages hosted on opentelemetry-js repo.

sta-szek · 2022-08-04T14:04:21Z

So.
Firs try: move all tracing related code to the end of app.ts bootstrap() method. The method looks like:

import * as path from 'path';
import { NestFactory } from '@nestjs/core';
import helmet = require('helmet');
import errorHandler = require('errorhandler');
// other custom imports
import { NestApplicationOptions, ValidationPipe } from '@nestjs/common';

// telemetry imports
import {trace} from "@opentelemetry/api";
import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
import {JaegerExporter} from "@opentelemetry/exporter-jaeger";
import {AlwaysOnSampler} from "@opentelemetry/core";
import {Resource} from "@opentelemetry/resources";
import {SemanticResourceAttributes} from "@opentelemetry/semantic-conventions";
import {B3InjectEncoding, B3Propagator} from "@opentelemetry/propagator-b3";
import {getNodeAutoInstrumentations} from "@opentelemetry/auto-instrumentations-node";
import opentelemetry = require('@opentelemetry/sdk-node');
import {BatchSpanProcessor} from "@opentelemetry/sdk-trace-base";

const BASE_PATH = '/portal';
const TRANSLATION_PREFIX = `OR_`;

async function bootstrap() {
  const { vaultService } = readConfig();

  const config: NestApplicationOptions = {};

  const app = await NestFactory.create(AppModule, config);

// custom code to setup logger, globalPipes, CORS, etc...


  try {
    await app.listen(NODE_LISTEN_PORT);
    logger.info(`Server listening on port ${NODE_LISTEN_PORT} in ${env} mode`);

  } catch (error) {
    logger.error('Cannot launch server', error);
    process.exit(1);
  }


// tracing code
  const traceExporter = new JaegerExporter({endpoint: 'http://localhost:14268/api/traces'});
  console.log(traceExporter)
  const sampler = new AlwaysOnSampler();
  const resource = Resource.default().merge(new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: "optimization-reporting-jopi-localhost",
    [SemanticResourceAttributes.SERVICE_VERSION]: "0.75.0"
  }));

  const textMapPropagator = new B3Propagator({injectEncoding: B3InjectEncoding.MULTI_HEADER});

  const sdk = new opentelemetry.NodeSDK({
    autoDetectResources: true,
    contextManager: undefined,
    defaultAttributes: undefined,
    textMapPropagator: textMapPropagator,
    metricReader: undefined,
    instrumentations: [getNodeAutoInstrumentations()],
    resource: resource,
    sampler: sampler,
    serviceName: "optimization-reporting-jopi-localhost",
    spanProcessor: new BatchSpanProcessor(traceExporter, {}),
    traceExporter: traceExporter,
    spanLimits: undefined,
  })

  process.on('SIGTERM', () => sdk.shutdown().finally(() => process.exit(0)));

  sdk.start();
  diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

  trace.getTracerProvider().getTracer('debug').startSpan('test manual from main app').end();
  setInterval(()=> {
    trace.getTracerProvider().getTracer('debug').startSpan('test manual span. uptime: ' + process.uptime()).end();
  }, 10000);

}

bootstrap();

result: the same - manual span creation works, autoinstrumentation does not work

2nd attempt: remove instrumentations: [getNodeAutoInstrumentations()], and try adding instrumentations before JaegerExport:

  const { registerInstrumentations } = require('@opentelemetry/instrumentation');
  registerInstrumentations({
    instrumentations: getNodeAutoInstrumentations()
  });

  const traceExporter = new JaegerExporter({endpoint: 'http://localhost:14268/api/traces'});
  console.log(traceExporter)
  const sampler = new AlwaysOnSampler();
  const resource = Resource.default().merge(new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: "optimization-reporting-jopi-localhost",
    [SemanticResourceAttributes.SERVICE_VERSION]: "0.75.0"
  }));

  const textMapPropagator = new B3Propagator({injectEncoding: B3InjectEncoding.MULTI_HEADER});

  const sdk = new opentelemetry.NodeSDK({
    autoDetectResources: true,
    contextManager: undefined,
    defaultAttributes: undefined,
    textMapPropagator: textMapPropagator,
    metricReader: undefined,
    // instrumentations: [getNodeAutoInstrumentations()],
    resource: resource,
    sampler: sampler,
    serviceName: "optimization-reporting-jopi-localhost",
    spanProcessor: new BatchSpanProcessor(traceExporter, {}),
    traceExporter: traceExporter,
    spanLimits: undefined,
  })

  process.on('SIGTERM', () => sdk.shutdown().finally(() => process.exit(0)));

  sdk.start();
  diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

  trace.getTracerProvider().getTracer('debug').startSpan('test manual from main app').end();
  setInterval(()=> {
    trace.getTracerProvider().getTracer('debug').startSpan('test manual span. uptime: ' + process.uptime()).end();
  }, 10000);
}

bootstrap();

logs:

@opentelemetry/api: Registered a global for diag v1.1.0.
EnvDetector found resource. Resource { attributes: {} }
ProcessDetector found resource. Resource {
  attributes: {
    'process.pid': 94417,
    'process.executable.name': 'node',
    'process.command': 'xxxx/optimization-reporting/backend/src/app.ts',
    'process.command_line': 'xxxx/optimization-reporting/backend/src/app.ts ./config/env-local-qt.json',
    'process.runtime.version': '17.8.0',
    'process.runtime.name': 'nodejs',
    'process.runtime.description': 'Node.js'
  }
}
@opentelemetry/api: Registered a global for trace v1.1.0.
@opentelemetry/api: Registered a global for context v1.1.0.
@opentelemetry/api: Registered a global for propagation v1.1.0.
(node:94417) [DEP0152] DeprecationWarning: Custom PerformanceEntry accessors are deprecated. Please use the detail property.

but autoinstrumentation still does not work.

attempt 3:
i moved the code:

  const { registerInstrumentations } = require('@opentelemetry/instrumentation');
  registerInstrumentations({
    instrumentations: getNodeAutoInstrumentations()
  });

into very first lines of my app.ts code and it started to work!
now i see more logs:

Instrumentation suppressed, returning Noop Span
@opentelemetry/instrumentation-http http instrumentation outgoingRequest
@opentelemetry/instrumentation-http http.ClientRequest return request
@opentelemetry/instrumentation-http outgoingRequest on response()
successful flush for 1 spans
@opentelemetry/instrumentation-http outgoingRequest on end()
@opentelemetry/instrumentation-http outgoingRequest on request close()
Jaeger exporter export
successful append for : 1
Instrumentation suppressed, returning Noop Span
@opentelemetry/instrumentation-http http instrumentation outgoingRequest
@opentelemetry/instrumentation-http http.ClientRequest return request
@opentelemetry/instrumentation-http outgoingRequest on response()
successful flush for 1 spans
@opentelemetry/instrumentation-http outgoingRequest on end()
@opentelemetry/instrumentation-http outgoingRequest on request close()

not sure why it worked this t ime... will try few more refactorings to get more understanding. thanks a lot!

--- edit

the code:

  const { registerInstrumentations } = require('@opentelemetry/instrumentation');
  registerInstrumentations({
    instrumentations: getNodeAutoInstrumentations()
  });

MUST BE before:

  const app = await NestFactory.create(AppModule, config);

otherwise it will not work. would be good to mention somewhere in docs, if you use NestJS you should initialize before NestFactory

Flarna · 2022-08-04T14:29:57Z

That is what I said, do not import/require anything before the instrumenations are in place.

Flarna · 2022-08-05T12:01:13Z

It's documented e.g. here or here.

But I agree that it might be better to mention this more visible.
Feel free to create a PR to improve the doc regarding this. As one familiar with OTelJs and more or less never reading the doc it's not so easy to find the best place/wording. So people new to OTel tend to have a better view on this and we need volunteers in this area.

I will close this issue as it seems your problem is solved. Feel free to reopen.

albertteoh · 2024-02-09T18:12:48Z

You could easily workaround this by remving instrumentations: [getNodeAutoInstrumentations()], and instead add
const { registerInstrumentations } = require('@opentelemetry/instrumentation');
registerInstrumentations({
  instrumentations: getNodeAutoInstrumentations()
});
at the very beginning of your main/tracesetup script, e.g. even before require/initializing JaegerExporter.

@Flarna this was super helpful!

I'd spent days trying to figure out why the trace context wasn't getting inserted into the outbound request, and this simple suggestion fixed it!

Thank you very much! 🙏🏼

P.S. we should update the documentation here: https://opentelemetry.io/docs/languages/js/getting-started/nodejs/

sta-szek added the bug Something isn't working label Aug 3, 2022

Flarna closed this as completed Aug 5, 2022

Flarna mentioned this issue Aug 5, 2022

NodeSDK should register instrumentations earlier open-telemetry/opentelemetry-js#3146

Closed

ringerc mentioned this issue Sep 5, 2022

Confusing documentation mixes different packages and entrypoints open-telemetry/opentelemetry-js#3230

Closed

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Autoinstrumentation not working #1109

Autoinstrumentation not working #1109

sta-szek commented Aug 3, 2022 •

edited

Loading

Flarna commented Aug 3, 2022

sta-szek commented Aug 3, 2022 •

edited

Loading

Flarna commented Aug 3, 2022

sta-szek commented Aug 4, 2022

Flarna commented Aug 4, 2022

sta-szek commented Aug 4, 2022 •

edited

Loading

Flarna commented Aug 4, 2022

Flarna commented Aug 5, 2022

albertteoh commented Feb 9, 2024 •

edited

Loading

Autoinstrumentation not working #1109

Autoinstrumentation not working #1109

Comments

sta-szek commented Aug 3, 2022 • edited Loading

What version of OpenTelemetry are you using?

What version of Node are you using?

Flarna commented Aug 3, 2022

sta-szek commented Aug 3, 2022 • edited Loading

Flarna commented Aug 3, 2022

sta-szek commented Aug 4, 2022

Flarna commented Aug 4, 2022

sta-szek commented Aug 4, 2022 • edited Loading

Flarna commented Aug 4, 2022

Flarna commented Aug 5, 2022

albertteoh commented Feb 9, 2024 • edited Loading

sta-szek commented Aug 3, 2022 •

edited

Loading

sta-szek commented Aug 3, 2022 •

edited

Loading

sta-szek commented Aug 4, 2022 •

edited

Loading

albertteoh commented Feb 9, 2024 •

edited

Loading