search

open-telemetry / opentelemetry-js-contrib

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

auto-instrumentation with winston doesn't seem to report logs to open collector #2090

Open li-dennis opened 7 months ago

li-dennis commented 7 months ago

Hi,

I'm trying to setup opentelemetry to automatically instrument my project, and while traces work, I cannot seem to get the winston instrumentation to report logs back to opentelemetry collector.

both via the CLI approach of

export OTEL_TRACES_EXPORTER="otlp"
export OTEL_EXPORTER_OTLP_ENDPOINT="http://otelcol:4317"
export OTEL_SERVICE_NAME="your-service-name"
export NODE_OPTIONS="--require @opentelemetry/auto-instrumentations-node/register"
node app.js

and the SDK approach of

import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-grpc";
import { Resource } from "@opentelemetry/resources";
import { NodeSDK } from "@opentelemetry/sdk-node";

import { diag, DiagConsoleLogger, DiagLogLevel } from "@opentelemetry/api";
import { SEMRESATTRS_SERVICE_NAME } from "@opentelemetry/semantic-conventions";
import { WinstonInstrumentation } from "@opentelemetry/instrumentation-winston";

diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);
const traceExporter = new OTLPTraceExporter();

const sdk = new NodeSDK({
    resource: new Resource({
        [SEMRESATTRS_SERVICE_NAME]: process.env.OTEL_SERVICE_NAME
    }),
    traceExporter,
    instrumentations: [
        getNodeAutoInstrumentations({
            "@opentelemetry/instrumentation-fs": { enabled: false },
            "@opentelemetry/instrumentation-winston": { enabled: true }
        }),
        new WinstonInstrumentation({
            logHook: (_span, record) => {
                record["resource.service.name"] = process.env.OTEL_SERVICE_NAME;
            }
        })
    ]
});

sdk.start();

Later on, I have this snippet:

const winstonLogger = winston.createLogger({
    level: "info",
    format: winston.format.json(),
    transports: [new winston.transports.Console({})]
});

winstonLogger.info("Hello, Winston!");

My Logs I've opted for the first approach since it seems like the second approach requires the instrumentation to initialize prior to winston being imported (?), but in either case, I run into the same issue in both. I don't see my messages even getting logged when I set OTEL_LOG_LEVEL=debug

My console logs

HostDetectorSync found resource. Resource {
...
}
...
@opentelemetry/instrumentation-winston Applying patch for winston@3.13.0
{"level":"info","message":"Hello, Winston!"}
...

Winston is getting patched, and my message of "Hello, Winston!" is getting sent to my console, but not to my opentelemetry-collector.

In contrast, with the automatic instrumentation in python, I can see my logs getting reported to opencollector (and opensearch) just fine. I can't tell if I'm doing something wrong here. I can also manually instrument it successfully by adding a opentelemetry log handler to my node logger, but I'd prefer not to do that, and instead just let the autoinstrumentation work.

DivyaNayaka commented 7 months ago

Even I have the same question. So, I went through the code base, and based on this, I will ask if someone can answer or the contributors @hectorhdzg

After setting up Winston auto instrumentation (incl. Winston transport), do we need to configure a loggerProvider from Logs SDK to forward those to the otel-collector?

mhennoch commented 7 months ago

I think you need to specify logRecordProcessor in your configuration for provider to be registered.

architgarg95 commented 7 months ago

Even after providing the logRecordProcessor it doesn't send the logs to otel collector, right now I have patched the winston logger to emit logs to otel-collector every time something gets logged. It would be better if the logs could get exported by providing the logRecordProcessor

mhennoch commented 7 months ago

If you configure it to use console exporter does that work? Can you share your final configuration?

DivyaNayaka commented 7 months ago

For me, Winston's auto instrumentation is not working and needs fixing.

What worked for me was the execution order below.

falsyvalues commented 6 months ago

@DivyaNayaka can you share some snippets with "working" example?

I have similar experience @li-dennis with auto instrumentation, versions:

    "@opentelemetry/api": "^1.8.0",
    "@opentelemetry/auto-instrumentations-node": "^0.43.0",
    "@opentelemetry/api-logs": "^0.50.0",
    "@opentelemetry/winston-transport": "^0.2.0",

env:

OTEL_EXPORTER_OTLP_ENDPOINT="http://localhost:4317"
OTEL_EXPORTER_OTLP_PROTOCOL="http/protobuf"
OTEL_SERVICE_NAME="otel-test-api"
OTEL_LOGS_EXPORTER="otlp"
OTEL_METRICS_EXPORTER="otlp"
OTEL_TRACES_EXPORTER="otlp"
OTEL_NODE_RESOURCE_DETECTORS="env,host,os"
OTEL_NODE_ENABLED_INSTRUMENTATIONS="http,express,winston"

logger:

 import * as api from '@opentelemetry/api-logs';

import {
    LoggerProvider,
    SimpleLogRecordProcessor,
    ConsoleLogRecordExporter,
} from '@opentelemetry/sdk-logs';
import { OpenTelemetryTransportV3 } from '@opentelemetry/winston-transport';
import * as winston from 'winston';

const loggerProvider = new LoggerProvider();

loggerProvider.addLogRecordProcessor(
    new SimpleLogRecordProcessor(new ConsoleLogRecordExporter())
);
api.logs.setGlobalLoggerProvider(loggerProvider);

export const logger = winston.createLogger({
  level: 'info',
  transports: [
    new winston.transports.Console(),
    new OpenTelemetryTransportV3()
  ]
});

Random route handler:

  logger.log({
    level: 'info',
    message: 'Hello world'
  });

While logging to console clearly works fine, logs enrichment works, spans data is visible. But nothing is being sent to collector, no error or anything like that.

 {"level":"info","message":"Hello world","span_id":"4804419b864406b3","trace_flags":"01","trace_id":"d98b802f171a92919b24c0aba5480252"}
{
  timestamp: 1715685247060000,
  traceId: 'd98b802f171a92919b24c0aba5480252',
  spanId: '4804419b864406b3',
  traceFlags: 1,
  severityText: 'info',
  severityNumber: 9,
  body: 'Hello world',
  attributes: {
    trace_id: 'd98b802f171a92919b24c0aba5480252',
    span_id: '4804419b864406b3',
    trace_flags: '01'
  }
}
DivyaNayaka commented 6 months ago

Instead of ConsoleLogRecordExporter(), use OTLPLogExporter from @opentelemetry/exporter-logs-otlp-http to ship logs to collector

falsyvalues commented 6 months ago

@DivyaNayaka that was also my guess, thanks for confirmation.

I would like to ask author @dyladan, can you confirm or what was your approach while testing?

dyladan commented 6 months ago

I'm not the author of the winston package or of this issue so i'm not sure what you're asking exactly

falsyvalues commented 6 months ago

@dyladan Ahh I apologize, highlighted you wrongly due to this release.

dyladan commented 6 months ago

No worries. At some level i'm responsible for everything here so it's basically never wrong to highlight me. I just wasn't sure what you were asking me.

falsyvalues commented 6 months ago

In case someone else is looking for solution with additions like resource augmentation for logs.

import * as api from "@opentelemetry/api-logs";
// It might be one of http, proto, grpc depending on preferred transport
import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-http";
import {
  detectResourcesSync,
  envDetectorSync,
  hostDetectorSync,
  processDetectorSync,
} from "@opentelemetry/resources";
import {
  BatchLogRecordProcessor,
  LoggerProvider
} from "@opentelemetry/sdk-logs";
import { OpenTelemetryTransportV3 } from "@opentelemetry/winston-transport";

import * as winston from "winston";

const logExporter = new OTLPLogExporter();
const loggerProvider = new LoggerProvider({
// without resource we don't have proper service.name, service.version correlated with logs
  resource: detectResourcesSync({
// this have to be manually adjusted to match SDK OTEL_NODE_RESOURCE_DETECTORS
    detectors: [envDetectorSync, processDetectorSync, hostDetectorSync],
  }),
});

loggerProvider.addLogRecordProcessor(
  new BatchLogRecordProcessor(logExporter)
  // new SimpleLogRecordProcessor(new ConsoleLogRecordExporter())
);
api.logs.setGlobalLoggerProvider(loggerProvider);

export const logger = winston.createLogger({
  level: "info",
  transports: [
    new winston.transports.Console(),
    new OpenTelemetryTransportV3(),
  ],
});

logger.info('Hello world');
c0j0s commented 6 months ago

I was experiencing the same issue when using auto-instrumentation with winston. My setup is similar to @li-dennis and finally managed to get it working after some trial and error.

Here are my findings in case anyone needs it:

Thus, my initial conclusion is that winston-transport was somehow excluded in the dependency chain from upstream modules (my guess is instrumentation-winston ).

Finally, thanks everyone for your input here, if not I would hv been a headless fly.

jbresciani commented 5 months ago

https://github.com/open-telemetry/opentelemetry-js-contrib/blob/main/plugins/node/opentelemetry-instrumentation-winston/package.json#L51 it's listed as a devDependencies and not a dependancy, which explains it and confirms your theory @c0j0s

trentm commented 5 months ago

I commented on #2283 as well. winston-transport is currently intentionally not a dep of @opentelemetry/instrumentation-winston.

The intent (for better or worse) of instrumentation-winston is that when it is going to add a transport to a created Winston logger, it attempts to lazily import @opentelemetry/winston-transport ... which does have a dep on winston-transport. That indirection design was to conservatively decouple @opentelemetry/instrumentation-winston from an incompatible change in winston-transport. Discussed in comments and reviews leading up to this comment: https://github.com/open-telemetry/opentelemetry-js-contrib/pull/1837#issuecomment-1920249244

auto-instrumentation in SDK (not working) instrumentation-winston in SDK (not working)

Sorry, I haven't worked through all the comments and examples above, but my guess is that the (not working) cases may be because of other issues.

For example, in the OP issue description it looks to me like the "CLI approach" may be failing because @opentelemetry/auto-instrumentations-node/register doesn't currently add a LoggerProvider to the created SDK:

both via the CLI approach of

...
export NODE_OPTIONS="--require @opentelemetry/auto-instrumentations-node/register"
node app.js

and the "SDK approach" also isn't adding a logger provider: (It is also adding two instances of WinstonInstrumentation: one from getNodeAutoInstrumentations and an explicit new WinstonInstrumentation. I don't know if that will cause surprises.)

const sdk = new NodeSDK({
    resource: new Resource({
        [SEMRESATTRS_SERVICE_NAME]: process.env.OTEL_SERVICE_NAME
    }),
    traceExporter,
    instrumentations: [
        getNodeAutoInstrumentations({
            "@opentelemetry/instrumentation-fs": { enabled: false },
            "@opentelemetry/instrumentation-winston": { enabled: true }
        }),
        new WinstonInstrumentation({
            logHook: (_span, record) => {
                record["resource.service.name"] = process.env.OTEL_SERVICE_NAME;
            }
        })
    ]
});
mithun-shaji-dts commented 3 months ago

Hi @falsyvalues, @DivyaNayaka

I'm having trouble with Pino instrumentation in my OpenTelemetry setup. Despite configuring everything, the logs are still not being exported to the collector. Here’s a summary of my setup:

package.json

{
  "dependencies": {
    "@opentelemetry/exporter-logs-otlp-http": "^0.52.1",
    "@opentelemetry/instrumentation-pino": "^0.41.0",
    "@opentelemetry/sdk-node": "^0.52.1",
    "pino": "^8.21.0"
  }
}

app.js

const express = require('express');
const { NodeSDK, tracing, logs, api } = require('@opentelemetry/sdk-node');
const { PinoInstrumentation } = require('@opentelemetry/instrumentation-pino');
const { OTLPLogExporter } = require("@opentelemetry/exporter-logs-otlp-http");

const sdk = new NodeSDK({
  spanProcessor: new tracing.SimpleSpanProcessor(new tracing.ConsoleSpanExporter()),
  logRecordProcessor: new logs.SimpleLogRecordProcessor(new OTLPLogExporter()),
  instrumentations: [
    new PinoInstrumentation({
      disableLogSending: false, 
      disableLogCorrelation: false,
      logKeys: {
        traceId: 'trace_id',
        spanId: 'span_id',
        traceFlags: 'trace_flags',
      },
      logHook: (span, record) => {
        if (span) {
          record['trace_id'] = span.spanContext().traceId;
          record['span_id'] = span.spanContext().spanId;
          record['trace_flags'] = span.spanContext().traceFlags;
        }
        record['resource.service.name'] = 'my-service-name';
        record['custom_field'] = 'custom_value';
      },
    })
  ],
});

sdk.start();

const pino = require('pino');
const logger = pino();

const app = express();
const port = 4001;

app.use((req, res, next) => {
  const tracer = api.trace.getTracer('example');
  const span = tracer.startSpan(`HTTP ${req.method} ${req.url}`);
  req.span = span;
  res.on('finish', () => {
    span.end();
  });
  next();
});

app.get('/', (req, res) => {
  logger.info('Received a GET request on /');
  res.send('Hello World!');
});

app.get('/data', (req, res) => {
  logger.info('Received a GET request on /data'); 
  res.send({'name': 'Hello', 'age': 12});
});

app.listen(port, () => {
  logger.info(`Server running at http://localhost:${port}`);
});

Environment Variables

export OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317
export OTEL_EXPORTER_OTLP_PROTOCOL=grpc
export OTEL_TRACES_EXPORTER=otlp
export OTEL_LOGS_EXPORTER=otlp

Logs I see in the application terminal: {"level":30,"time":1723797972641,"pid":1,"hostname":"local-node-app-fdf76f856-kq2sp","trace_id":"173b489323bca5e254ed1cc0a9b7c3bd","span_id":"9b571216c5976aa1","trace_flags":"01","resource.service.name":"my-service-name","custom_field":"custom_value","msg":"Received a GET request on /data"}

Issue Despite the configuration, the logs are not being exported to the collector. The logs are visible in the console but not reaching the OTLP endpoint.

Do you have any insights or suggestions on what might be going wrong with this setup?

mhennoch commented 3 months ago

Pino instrumentation doesn't currently send logs it only adds span context to log record.

mithun-shaji-dts commented 3 months ago

@mhennoch, Is that sill in development? I noticed in the README that the Pino instrumentation module does more than just add span context to log records. It also sends logs to the OpenTelemetry Logs SDK.

mhennoch commented 3 months ago

@mithun-shaji-dts my bad, it has been indeed added recently.

mithun-shaji-dts commented 3 months ago

No problem @mhennoch, I have a try with Winston as well, still the logs are not getting exported to the OTel SDK.

app.js


const express = require('express');
const winston = require('winston');
const { OpenTelemetryTransportV3 } = require('@opentelemetry/winston-transport');
const { LoggerProvider, SimpleLogRecordProcessor, ConsoleLogRecordExporter } = require('@opentelemetry/sdk-logs');
const api = require('@opentelemetry/api-logs');
const { OTLPLogExporter } = require("@opentelemetry/exporter-logs-otlp-http")

console.log('EnvVar: ' +  `${process.env.OTEL_EXPORTER_OTLP_ENDPOINT}/v1/logs`)
const collectorOptions = {
    url: `${process.env.OTEL_EXPORTER_OTLP_ENDPOINT}/v1/logs`, // http://opentelemetry-instrumentation-collector.default.svc.cluster.local:4317/v1/logs
    headers: {}, 
    concurrencyLimit: 1,
};

console.log(collectorOptions);

const loggerProvider = new LoggerProvider();
loggerProvider.addLogRecordProcessor(
  new SimpleLogRecordProcessor(new OTLPLogExporter(collectorOptions))
);
api.logs.setGlobalLoggerProvider(loggerProvider);

const logger = winston.createLogger({
  level: 'info',
  transports: [
    new winston.transports.Console(),
    new OpenTelemetryTransportV3()
  ]
});

const app = express();
const port = 4004;

app.get('/', (req, res) => {
  logger.info('Handling request to root endpoint');
  res.send('Hello World!');
});

app.get('/data', (req, res) => {
    logger.log({ level: 'info', message: 'Request Received'})
    logger.info('Received a GET request on /data'); 
    res.send({'name': 'hello', 'age': 23});
});

app.get('/user/:id', (req, res) => {
    logger.info(`Fetching user with ID ${req.params.id}`);
    res.send(`User ID: ${req.params.id}`);
});

app.listen(port, () => {
  logger.info(`Server listening at http://localhost:${port}`);
});

Env:

export OTEL_EXPORTER_OTLP_ENDPOINT="http://{{ include "opentelemetry-collector.fullname" . }}.{{ template "opentelemetry-collector.namespace" . }}.svc.cluster.local:4317"
export OTEL_EXPORTER_OTLP_PROTOCOL="http/protobuf"
export OTEL_NODE_RESOURCE_DETECTORS="env,host,os"
export OTEL_TRACES_EXPORTER="otlp"
export OTEL_LOGS_EXPORTER="otlp"
export OTEL_METRICS_EXPORTER="otlp"
export OTEL_NODE_ENABLED_INSTRUMENTATIONS="http,express,pino,winston,bunyan"

Any Insights on this?

mhennoch commented 3 months ago

Your configuration seems correct. Tried with your pino example and it works fine. Probably issue with the collector

mithun-shaji-dts commented 3 months ago

@mhennoch, oh ok Thanks.

I was wondering if you could share your Collector configuration. It would be helpful to see how you’ve set up your collector for logging.

Update: I tried in my local system and it is fetching the logs. Probably some issue with the collector in k8s.!

Update2: Got it fixed in the k8s as well.

mhennoch commented 3 months ago

Running latest contrib

.\otelcol-contrib.exe --config .\otel-collector-config.yaml --feature-gates=-component.UseLocalHostAsDefaultHost

receivers:
  otlp:
    protocols:
      grpc:
      http:
        cors:
          allowed_origins:
            - http://*
            - https://*

exporters:
  debug:
    verbosity: detailed

processors:
  batch:

service:
  pipelines:
    logs:
      receivers: [otlp]
      exporters: [debug]
      processors: [batch]
MikeMoldawsky commented 3 months ago

Does anyone successfully created a Pino Logger using the SDK?

I couldn't make it work (didn't work either through env variables).

mithun-shaji-dts commented 3 months ago

@MikeMoldawsky, Yes I was able to create it using the configuration I shared above.