opentelemetry-js-contrib icon indicating copy to clipboard operation
opentelemetry-js-contrib copied to clipboard

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

Open li-dennis opened this issue 10 months ago • 25 comments

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 [email protected]
{"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.

  • [x] This only affects the JavaScript OpenTelemetry library
  • [ ] This may affect other libraries, but I would like to get opinions here first

li-dennis avatar Apr 11 '24 03:04 li-dennis

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?

DivyaNayaka avatar Apr 14 '24 09:04 DivyaNayaka

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

mhennoch avatar Apr 15 '24 13:04 mhennoch

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

architgarg95 avatar Apr 17 '24 12:04 architgarg95

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

mhennoch avatar Apr 17 '24 12:04 mhennoch

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

What worked for me was the execution order below.

  • Set a global logger provider that will export the logs to the Otel collector
  • Register Winston instrumentation as auto instrumentation is not registering it
  • Create Winston logger with console output

DivyaNayaka avatar Apr 17 '24 19:04 DivyaNayaka

@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'
 }
}

falsyvalues avatar May 14 '24 11:05 falsyvalues

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

DivyaNayaka avatar May 14 '24 13:05 DivyaNayaka

@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?

falsyvalues avatar May 14 '24 13:05 falsyvalues

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

dyladan avatar May 14 '24 13:05 dyladan

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

falsyvalues avatar May 14 '24 14:05 falsyvalues

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.

dyladan avatar May 14 '24 14:05 dyladan

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');

falsyvalues avatar May 15 '24 11:05 falsyvalues

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:

  • auto-instrumentation in SDK (not working)
  • instrumentation-winston in SDK (not working)
  • instrumentation-winston in SDK + winston-transport in logger transports (working)
  • auto-instrumentation in SDK + winston-transport in logger transports (working)
  • auto-instrumentation in SDK + winston-transport installed only (working)

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.

c0j0s avatar May 17 '24 03:05 c0j0s

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

jbresciani avatar Jun 05 '24 23:06 jbresciani

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;
            }
        })
    ]
});

trentm avatar Jun 19 '24 22:06 trentm

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?

mithun-shaji-dts avatar Aug 16 '24 09:08 mithun-shaji-dts

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

mhennoch avatar Aug 16 '24 09:08 mhennoch

@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.

mithun-shaji-dts avatar Aug 16 '24 09:08 mithun-shaji-dts

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

mhennoch avatar Aug 16 '24 09:08 mhennoch

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?

mithun-shaji-dts avatar Aug 16 '24 10:08 mithun-shaji-dts

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

mhennoch avatar Aug 16 '24 10:08 mhennoch

@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.

mithun-shaji-dts avatar Aug 16 '24 10:08 mithun-shaji-dts

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]

mhennoch avatar Aug 16 '24 11:08 mhennoch

Does anyone successfully created a Pino Logger using the SDK?

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

MikeMoldawsky avatar Aug 16 '24 19:08 MikeMoldawsky

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

mithun-shaji-dts avatar Aug 17 '24 01:08 mithun-shaji-dts