OTEL_PYTHON_LOG_CORRELATION is mentioned in doc, but does not seem to work.

[howardyoo]

trafficstars

Problem Statement As mentioned in https://opentelemetry.io/docs/languages/python/automatic/configuration/, there is a mention of OTEL_PYTHON_LOG_CORRELATION which when set to true, will automatically inject trace id and span id in context to python's logs:

export OTEL_PYTHON_LOG_CORRELATION=true
export OTEL_PYTHON_LOG_FORMAT="%(msg)s [span_id=%(span_id)s]"
export OTEL_PYTHON_LOG_LEVEL=debug
export OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true

However, setting the environment does NOT inject the trace_id and span_id, and the generated span has 0x0 as their values. In fact, when I tried to find the OTEL_PYTHON_LOG_CORRELATION in Otel python repo in github, I couldn't find any mention of it in the codebase.

Steps to reproduce Describe exactly how to reproduce the error. Include a code sample if applicable.

1. Write a simple python app (e.g. flask application), and use python's logging and generate a log.
2. define the following env:

...
- OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
- OTEL_LOGS_EXPORTER=console,otlp_proto_http
- OTEL_PYTHON_LOG_CORRELATION=true
- OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true
...

3. run the application, with

What is the expected behavior? OTEL log payload should have trace_id and span_id correctly populated

What is the actual behavior? The console output has 0x00.. values for trace_id and span_id.

"timestamp": "2024-03-13T04:25:59.888144Z",
"observed_timestamp": "2024-03-13T04:25:59.889081Z",
"trace_id": "0x00000000000000000000000000000000",
"span_id": "0x0000000000000000",
"trace_flags": 0,

Additional context The following dependencies were added to requirements.txt:

• opentelemetry-distro
• opentelemetry-exporter-otlp

[howardyoo]

On further investigation, the LOG CORRELATION does seem to work, but OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true is not picking up the trace_id and span_id correctly, and seems to set the value to 0x00.. when sending to the collector.

[howardyoo]

Looks like when the auto instrumentation is enabled, only the logs having trace_id=0 and span_id=0 are getting exported, and I am not seeing any logs for the legal trace_id and span_id. Not sure why this is happening, or what kind of logic logging auto instrumentation is imposing to not send those. From the log lines,

2024-03-13 05:33:46,503 INFO [werkzeug] [_internal.py:96] [trace_id=0 span_id=0 resource.service.name=tier1-service trace_sampled=False] - WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.

and

2024-03-13 05:33:59,213 INFO [app] [app.py:21] [trace_id=762e64369f53b9bd7b5fd2ad95dc597a span_id=8261bce18a83b72f resource.service.name=tier2-service trace_sampled=True] - this is some important log that is used to udpate product owners that a event was successful

do not seem to be different at all, but the second log entry that should be sent does not get exported. I also wonder what the trace_sampled=True means. I have set the formatting so the entry would have trace_sampled=False, but the results were the same.

[howardyoo]

This issue is related to https://github.com/open-telemetry/opentelemetry-python/issues/3473 . Very strange. INFO level log is NOT exported. When I switched the logging to log.warning(..), I could now see the log messages getting exported. Very strange and should be considered as a bug.

[dhofstetter]

Hello, I discovered the same

Very strange. INFO level log is NOT exported. When I switched the logging to log.warning(..), I could now see the log messages getting exported. Very strange and should be considered as a bug.

I don't fully understand the reasons yet

Anyone an idea?

[howardyoo]

It's definitely a bug. I hope someone would pick it up and fix it.

[dhofstetter]

There is a pull request here addressing this issue (only indirect, but it would resolve the problem)