moleculerjs / moleculer

:rocket: Progressive microservices framework for Node.js
https://moleculer.services/
MIT License
6.15k stars 583 forks source link

Active span not correctly set in dd-trace #690

Closed ngraef closed 1 year ago

ngraef commented 4 years ago

Prerequisites

Current Behavior

Using the approach documented in Datadog's docs for injecting trace and span IDs into JSON logs does not work. The logs do not contain a trace and span ID.

Expected Behavior

Because moleculer is using dd-trace, I expect to be able to use dd-trace's documented functionality and have moleculer-reported traces available for log injection.

Failure Information

Steps to Reproduce

  1. Create a project with the moleculer.config.js below.
    • Datadog tracing exporter
    • Custom console log formatter that injects trace IDs into JSON logs.
  2. Start the broker and make a request to a service.
  3. Observe the logs.

Reproduce code snippet

// moleculer.config.js
const ddTracer = require("dd-trace").default;
const ddTracerFormats = require("dd-trace/ext/formats");

const tracer = ddTracer.init({
  url: "http://localhost:8126",
  plugins: false,
});

module.exports = {
  logger: {
    type: "Console",
    options: {
      colors: false,
      formatter(level, args, bindings, { printArgs }) {
        const record = {
          ts: Date.now(),
          level,
          msg: printArgs(args).join(" "),
          ...bindings
        };

        const span = tracer.scope().active();
        if (span) {
          tracer.inject(span.context(), ddTracerFormats.LOG, record);
        }

        return [JSON.stringify(record)];
      }
    }
  },
  tracing: {
    enabled: true,
    exporter: {
      type: "Datadog",
      options: {
        tracer
      }
    },
    actions: true,
    events: true,
    stackTrace: true,
    sampling: {
      rate: 1
    }
  }
};

I also tried getting this.broker.tracer.getCurrentTraceID() and this.broker.tracer.getActiveSpanID() to inject the logs manually instead of tracer.scope().active(), but that ultimately gets the same underlying data from dd-trace.

Context

Notes

After looking through the moleculer and dd-trace code, I believe moleculer is not properly setting the active span in dd-trace. I'm currently experimenting with calling this.ddScope._before(asyncId) after this.ddScope._spans[asyncId] = ddSpan in DatadogTraceExporter.spanStarted and this.ddScope._after() after ddSpan.finish(span.finishTime) in DatadogTraceExporter.spanFinished.

This report uses manual trace ID injection with the moleculer logger. dd-trace also supports auto injection for bunyan, pino, and winston loggers. I have not tried using those loggers in moleculer.config.js, but I imagine the same issue will exist.

icebob commented 1 year ago

I'm closing this issue, because we will remove the built-in tracing solution in future versions.