Injected traces data into Logs is not showing on Loki-Grafana

Question

SETUP: i'm using the python-logging-loki library to manually instrument my code for logs. I have a single running instance of Loki (promtail not used, i'm pushing directly to loki). On Grafana i have Jaeger and Loki up and running as data sources. For Traces i'm using opentelemetry python library (also manually instrumented the code).

I'm trying to use the Opentelemetry Logging Instrumentation library to automatically inject trace data into my logs before they are sent to Loki. My problem is, i can see the injected data printed out on my console when i run my test app but on grafana the injected data does not show up.

i configured Loki for derived fields to extract the trace_id with a regex and an internal link is pointing to jaeger.

    # auto inject trace data into logs (Opentelemetry Logging Instrumentation library)
    LoggingInstrumentor().instrument(set_logging_format=True, log_level=logging.DEBUG)

    # manual instrumentation of traces 
    with tracer.start_as_current_span(name="random-name") as span:

        # using python-logging-loki library to construct the logs
        logger.info(msg="testing loki logger", extra={"tags": {"product_number": "ABCD123"}})

On Grafana, the logs are exported successfully but the trace data does not appear, despite setting the derived fields values in Loki on Grafana

on my console however when i run my test app, i can see a printout of the log msg with the trace data injected into though

2022-04-08 15:17:15,476 DEBUG [urllib3.connectionpool] [connectionpool.py:228] [trace_id=e4fb8555337a28cc639955a36d994ed1 span_id=86425d0bc3cc088c resource.service.name=] - Starting new HTTP connection (1): localhost:3100
2022-04-08 15:17:15,498 DEBUG [urllib3.connectionpool] [connectionpool.py:456] [trace_id=e4fb8555337a28cc639955a36d994ed1 span_id=86425d0bc3cc088c resource.service.name=] - http://localhost:3100 "POST /loki/api/v1/push HTTP/1.1" 204 0
2022-04-08 15:17:15,469 INFO [otlp_handler] [main.py:39] [trace_id=e4fb8555337a28cc639955a36d994ed1 span_id=86425d0bc3cc088c resource.service.name=] - testing loki logger

i'm not sure what i'm doing wrong here ! Only when i explicitly write down the trace_id into the log message, grafana is deriving those values. So if i write the log like this:

logger.info(msg="[ trace_id=d4ea420b4fa4e20e7fbb579c80fa4e88 span_id=856ca68d4b52bbd4 ] - testing loki logger", extra={"tags": {"product_number": "ABCD123"}})

then on grafana loki, i can see the derived fields in the records and it links correctly to the trace on jaeger

What am i doing wrong? .. is this the correct way to use this Logging Instrumentation by otel? ..

Answer 1

Could it be that you need to put a space between [ and trace_id? When parsing, fields are separated by a space, so in your log the field name might end up as [trace_id.

Answer 2

If I had to guess I'd say the log entry you're seeing in Grafana was created while there wasn't actually an active Span.

Not sure how things work with Python but with JS you'd use instrumentation-winston. You can put a breakpoint in the logHook callback function to make sure there is actually a Span running.

You could also try manually getting the tracer and wrapping the log.info() call in a tracer.startActiveSpan. Here's how it works in Typescript:

import { WinstonInstrumentation } from '@opentelemetry/instrumentation-winston';
import { Span } from '@opentelemetry/api';

// initTracer does all the otel tracer setup stuff and takes an optional param InstrumentationOption[]
initTracer([
  new WinstonInstrumentation({
    logHook: (span: Span) => {
      console.log(span) // <---- Put breakpoint here.
    },
  }),
]);

// manually start a span
trace
  .getTracer('my-service')
  .startActiveSpan('seedRootUser', async (span: Span) => {
    logger.info('This will have the Span\'s span_id and trace_id attached to the log data');
    span.end(); // make sure to call or I won't work!
  });