open-telemetry / opentelemetry-js-contrib

OpenTelemetry instrumentation for JavaScript modules
https://opentelemetry.io
Apache License 2.0
709 stars 531 forks source link

Instrumentation not working #2390

Closed rubencosta13 closed 1 week ago

rubencosta13 commented 3 months ago

What version of OpenTelemetry are you using?

"@opentelemetry/api": "^1.9.0",
"@opentelemetry/auto-instrumentations-node": "^0.49.1",
"@opentelemetry/exporter-logs-otlp-proto": "^0.52.1",
"@opentelemetry/exporter-metrics-otlp-proto": "^0.52.1",
"@opentelemetry/host-metrics": "^0.35.3",
"@opentelemetry/instrumentation-express": "^0.41.1",
"@opentelemetry/instrumentation-http": "^0.52.1",
"@opentelemetry/node": "^0.24.0",
"@opentelemetry/sdk-trace-node": "^1.25.1",

What version of Node are you using?

 node -v          
v20.16.0

What did you do?

I've put together a simple implementation of a class to consume opentelemetry with some custom stuff:

import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto';
import { OTLPMetricExporter } from '@opentelemetry/exporter-metrics-otlp-proto';
import { Tracer, Meter } from '@opentelemetry/api';
import {
  NodeTracerProvider, ParentBasedSampler, SimpleSpanProcessor,
  TraceIdRatioBasedSampler
} from '@opentelemetry/sdk-trace-node';
import { Resource } from '@opentelemetry/resources';
import {
  MeterProvider, PeriodicExportingMetricReader
} from '@opentelemetry/sdk-metrics';
import {
  SemanticResourceAttributes
} from '@opentelemetry/semantic-conventions';
import * as opentelemetry from '@opentelemetry/api';
import { registerInstrumentations } from '@opentelemetry/instrumentation';
import {
  MongooseInstrumentation
} from '@opentelemetry/instrumentation-mongoose';
import { HostMetrics } from '@opentelemetry/host-metrics';
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';
import { MongoDBInstrumentation } from '@opentelemetry/instrumentation-mongodb';
import { RedisInstrumentation } from '@opentelemetry/instrumentation-redis-4';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { logger } from '../utils/logger';

interface ISetupAnalytics {
  url: string;
  serviceName: string;
  metricsUrl: string;
}

class Analytics {
  private _tracer?: Tracer;
  private _meter?: Meter;
  private _meterProvider?: MeterProvider;
  private _provider?: NodeTracerProvider;

  get tracer() {
    if (!this._tracer && process.env.NODE_ENV !== 'test') {
      throw new Error('Cannot access tracer before initialization');
    }
    return this._tracer!;
  }

  get meter() {
    if (!this._meter && process.env.NODE_ENV !== 'test') {
      throw new Error('Cannot access meter before initialization');
    }
    return this._meter!;
  }

  get spanId() {
    return opentelemetry.trace.getActiveSpan();
  }

  private setupTraceExporter(url: string) {
    return new OTLPTraceExporter({ url });
  }

  private setupMetricExporter(url: string) {
    return new OTLPMetricExporter({ url });
  }

  private setupInstrumentation() {
    registerInstrumentations({
      instrumentations: [
        new MongooseInstrumentation({
          suppressInternalInstrumentation: true,
        }),
        new HttpInstrumentation(),
        new ExpressInstrumentation(),
        new MongoDBInstrumentation(),
        new RedisInstrumentation(),
      ],
      meterProvider: this._meterProvider,
      tracerProvider: this._provider
    });
  }

  private setupMetrics(serviceName: string) {
    new HostMetrics({
      meterProvider: this._meterProvider,
      name: serviceName,
    }).start();
  }

  async setup({ url, serviceName, metricsUrl }: ISetupAnalytics): Promise<void> {
    try {
      if (process.env.NODE_ENV === 'test') {
        return;
      }

      const traceExporter = this.setupTraceExporter(`${url}/v1/traces`);
      const metricExporter = this.setupMetricExporter(`${url}/metrics`);

      this._provider = new NodeTracerProvider({
        resource: new Resource({
          [SemanticResourceAttributes.SERVICE_NAME]: serviceName,
          [SemanticResourceAttributes.SERVICE_VERSION]: '0.1.0',
        }),
        sampler: new ParentBasedSampler({
          root: new TraceIdRatioBasedSampler(1.0),
        }),
      });

      this._meterProvider = new MeterProvider({
        readers: [
          new PeriodicExportingMetricReader({
            exporter: metricExporter,
            exportTimeoutMillis: 60000,
          }),
        ],
        resource: new Resource({
          [SemanticResourceAttributes.SERVICE_NAME]: serviceName,
        }),
      });

      this.setupMetrics(serviceName);
      this._provider.addSpanProcessor(new SimpleSpanProcessor(traceExporter));
      this.setupInstrumentation();

      this._provider.register();
      this._tracer = opentelemetry.trace.getTracer(`TRACER_${serviceName}`);
      this._meter = this._meterProvider.getMeter(`METER_${serviceName}`);

      logger.info('Telemetry Collection started');
    } catch (err) {
      logger.error('Error initializing OpenTelemetry', err);
      throw err;
    }
  }

  async shutdown() {
    if (this._provider) {
      await this._provider.shutdown();
      logger.info('Telemetry shutdown completed');
    }
  }
}

const analytics = new Analytics();
export { analytics, Analytics, opentelemetry };

However no matter what I try, autoinstrumentations are never working...

What did you expect to see?

Would love to see and test auto instrumentations

What did you see instead?

No instrumentation, only spans on jagger (see below)

Additional context

here is my collector:

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

exporters:
  jaeger:
    endpoint: jaeger:14250
    tls:
      insecure: true

  prometheus:
    endpoint: 0.0.0.0:8888

processors:
  batch:

extensions:
  health_check:

service:
  extensions: [health_check]
  pipelines:
    traces:
      receivers: [otlp]
      processors: [batch]
      exporters: [jaeger]
    metrics:
      receivers: [otlp]
      processors: [batch]
      exporters: [prometheus]

Thank you in advance!

trentm commented 3 months ago

@rubencosta13 Can you please show a (possibly small) script that is using that setup TypeScript file above and how you are calling it? Also, ideally, if you could show the compiled JavaScript resulting from this TypeScript. Showing the small repro and the compiled JavaScript can help to clarify some things that can cause surprises with instrumentation:

rubencosta13 commented 3 months ago

Here is the compiled version (from TS to JS) using tsc: This project is using ESM

"use strict";
var __createBinding = (this && this.__createBinding) || (Object.create ? (function(o, m, k, k2) {
    if (k2 === undefined) k2 = k;
    var desc = Object.getOwnPropertyDescriptor(m, k);
    if (!desc || ("get" in desc ? !m.__esModule : desc.writable || desc.configurable)) {
      desc = { enumerable: true, get: function() { return m[k]; } };
    }
    Object.defineProperty(o, k2, desc);
}) : (function(o, m, k, k2) {
    if (k2 === undefined) k2 = k;
    o[k2] = m[k];
}));
var __setModuleDefault = (this && this.__setModuleDefault) || (Object.create ? (function(o, v) {
    Object.defineProperty(o, "default", { enumerable: true, value: v });
}) : function(o, v) {
    o["default"] = v;
});
var __importStar = (this && this.__importStar) || function (mod) {
    if (mod && mod.__esModule) return mod;
    var result = {};
    if (mod != null) for (var k in mod) if (k !== "default" && Object.prototype.hasOwnProperty.call(mod, k)) __createBinding(result, mod, k);
    __setModuleDefault(result, mod);
    return result;
};
Object.defineProperty(exports, "__esModule", { value: true });
exports.opentelemetry = exports.Analytics = exports.analytics = void 0;
const exporter_trace_otlp_proto_1 = require("@opentelemetry/exporter-trace-otlp-proto");
const exporter_metrics_otlp_proto_1 = require("@opentelemetry/exporter-metrics-otlp-proto");
const sdk_trace_node_1 = require("@opentelemetry/sdk-trace-node");
const resources_1 = require("@opentelemetry/resources");
const sdk_metrics_1 = require("@opentelemetry/sdk-metrics");
const semantic_conventions_1 = require("@opentelemetry/semantic-conventions");
const opentelemetry = __importStar(require("@opentelemetry/api"));
exports.opentelemetry = opentelemetry;
const instrumentation_1 = require("@opentelemetry/instrumentation");
const instrumentation_mongoose_1 = require("@opentelemetry/instrumentation-mongoose");
const host_metrics_1 = require("@opentelemetry/host-metrics");
const instrumentation_express_1 = require("@opentelemetry/instrumentation-express");
const instrumentation_mongodb_1 = require("@opentelemetry/instrumentation-mongodb");
const instrumentation_redis_4_1 = require("@opentelemetry/instrumentation-redis-4");
const instrumentation_http_1 = require("@opentelemetry/instrumentation-http");
const logger_1 = require("../utils/logger");
class Analytics {
    _tracer;
    _meter;
    _meterProvider;
    _provider;
    get tracer() {
        if (!this._tracer && process.env.NODE_ENV !== 'test') {
            throw new Error('Cannot access tracer before initialization');
        }
        return this._tracer;
    }
    get meter() {
        if (!this._meter && process.env.NODE_ENV !== 'test') {
            throw new Error('Cannot access meter before initialization');
        }
        return this._meter;
    }
    get spanId() {
        return opentelemetry.trace.getActiveSpan();
    }
    setupTraceExporter(url) {
        return new exporter_trace_otlp_proto_1.OTLPTraceExporter({ url });
    }
    setupMetricExporter(url) {
        return new exporter_metrics_otlp_proto_1.OTLPMetricExporter({ url });
    }
    setupInstrumentation() {
        (0, instrumentation_1.registerInstrumentations)({
            instrumentations: [
                new instrumentation_mongoose_1.MongooseInstrumentation({
                    suppressInternalInstrumentation: true,
                }),
                new instrumentation_http_1.HttpInstrumentation(),
                new instrumentation_express_1.ExpressInstrumentation(),
                new instrumentation_mongodb_1.MongoDBInstrumentation(),
                new instrumentation_redis_4_1.RedisInstrumentation(),
            ],
            meterProvider: this._meterProvider,
            tracerProvider: this._provider
        });
    }
    setupMetrics(serviceName) {
        new host_metrics_1.HostMetrics({
            meterProvider: this._meterProvider,
            name: serviceName,
        }).start();
    }
    async setup({ url, serviceName, metricsUrl }) {
        try {
            if (process.env.NODE_ENV === 'test') {
                return;
            }
            const traceExporter = this.setupTraceExporter(`${url}/v1/traces`);
            const metricExporter = this.setupMetricExporter(`${url}/metrics`);
            this._provider = new sdk_trace_node_1.NodeTracerProvider({
                resource: new resources_1.Resource({
                    [semantic_conventions_1.SemanticResourceAttributes.SERVICE_NAME]: serviceName,
                    [semantic_conventions_1.SemanticResourceAttributes.SERVICE_VERSION]: '0.1.0',
                }),
                sampler: new sdk_trace_node_1.ParentBasedSampler({
                    root: new sdk_trace_node_1.TraceIdRatioBasedSampler(1.0),
                }),
            });
            this._meterProvider = new sdk_metrics_1.MeterProvider({
                readers: [
                    new sdk_metrics_1.PeriodicExportingMetricReader({
                        exporter: metricExporter,
                        exportTimeoutMillis: 60000,
                    }),
                ],
                resource: new resources_1.Resource({
                    [semantic_conventions_1.SemanticResourceAttributes.SERVICE_NAME]: serviceName,
                }),
            });
            this.setupMetrics(serviceName);
            this._provider.addSpanProcessor(new sdk_trace_node_1.SimpleSpanProcessor(traceExporter));
            this.setupInstrumentation();
            this._provider.register();
            this._tracer = opentelemetry.trace.getTracer(`TRACER_${serviceName}`);
            this._meter = this._meterProvider.getMeter(`METER_${serviceName}`);
            logger_1.logger.info('Telemetry Collection started');
        }
        catch (err) {
            logger_1.logger.error('Error initializing OpenTelemetry', err);
            throw err;
        }
    }
    async shutdown() {
        if (this._provider) {
            await this._provider.shutdown();
            logger_1.logger.info('Telemetry shutdown completed');
        }
    }
}
exports.Analytics = Analytics;
const analytics = new Analytics();
exports.analytics = analytics;

As for how I import it and setup: Let me know if this is enough...

import { analytics } from './analytics/analytics';
import mongoose from 'mongoose';
import { httpServer } from './app';

const setupAnalytics = async () => {
    await analytics.setup({
    url: process.env.TELEMETRY_URL,
    serviceName: process.env.OTEL_SERVICE_NAME,
    metricsUrl: process.env.METRICS_URL
  });
}

const startFunction = () => {
   await setupAnalytics();
   await mongoose.connect(SOME_URL);
   httpServer.listen(3000);
}

startFunction();

I always make sure that analytics is the first thing to be imported, and call setup the very first thing

Thank you for your help!

trentm commented 3 months ago

@rubencosta13 My guess at the issue you are hitting is that your setupAnalytics() work (the code path that creates the Instrumentation class instances and calls registerInstrumentations) is too late. It is happening after the modules that you want instrumented have been imported. For example, the load of the 'mongoose' package happens before setupAnalytics runs.

The way OTel JS instruments packages (in most cases) is to setup a hook into Node.js's require and import mechanisms. Then when the package is loaded (by require(...) or from ... import '...', the OTel instrumentation tweaks the loaded package before the application code gets access to it.

If the application loads the package before those hooks are setup, then it is possible that the instrumentation hook never runs... or that it runs later, but too late because the application already had access to the uninstrumented package exports. I say "possible", because sometimes one can get "lucky" and instrumentation works even if the order is wrong.

To be sure, you want to setup OTel in a way that ensures its setup is complete before the application code runs. The recommended way (at least the way I recommend) is to (a) put your OTel setup code in a separate file (e.g. called "instrumentation.js" or "telemetry.js" -- or using ".ts" works if you are running via ts-node or compiling it) and then (b) call that setup file via one of Node.js's "preload" mechanisms: --require or --import. E.g.:

node --require ./telemetry.js my-app.js

or this is supported in more recent versions of Node.js:

node --import ./telemetry.js my-app.js

There are some possibly subtle differences between --require and --import that hopefully you don't need to worry about now.

Alternatively, you can put the OTel setup code at the top of your main file. However, you need to make sure it all sets up before any of your application code even does its imports. With TypeScript compilation and/or other transpilers there can be surprises that re-order imports to the top of a file.

surprises / subtleties

I mentioned CommonJS vs ESM above. The compiled .js code you posted is using require(...), so that is CommonJS code. That should mean you are fine using the node --require ./telemetry.js my-app.js above. If you are running ESM code (code using import ...) directly from Node.js, then the OpenTelemetry JS support for hooking and instrumenting with ESM is experimental and in flux of late.

Separately, it doesn't sound like you are using a bundler. If you do use a bundler, then there are more surprises there.

dyladan commented 3 months ago

@trentm can you please apply a priority label to this issue so it doesn't show up in the triage filter? If this isn't a bug you can remove the bug label

pichlermarc commented 2 months ago

@rubencosta13 were you able to try @trentm's recommendation? :slightly_smiling_face:

github-actions[bot] commented 3 weeks ago

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

github-actions[bot] commented 1 week ago

This issue was closed because it has been stale for 14 days with no activity.