Fix emitting logs when Logger propagation is disabled for a logger

[oldium]

trafficstars

Description

The logs are emited via LoggingHandler as a handler of the root logger. Unfortunatelly when there is a Logger instance with disabled propagation with logger.propagate=False, the root logger handler does not get called. Fix this by instrumenting Logger.propagate as a property attribute, so when the value changes to False, install the LoggingHandler to the logger automatically, and when the value changes to True, uninstall it.

Type of change

Please delete options that are not relevant.

• [x] Bug fix (non-breaking change which fixes an issue)

How Has This Been Tested?

Tested with unit tests. Tested with real project using gunicorn with uvicorn workers (uvicorn.workers.UvicornWorker) and celery task executor. Previously there were logs missing (i.e. not forwarded) from gunicorn, uvicorn and celery task loggers, now they are forwarded to OpenTelemetry collector.

Does This PR Require a Core Repo Change?

• [x] No.

Checklist:

See contributing.md for styleguide, changelog guidelines, and more.

• [x] Followed the style guidelines of this project
• [x] Changelogs have been updated
• [x] Unit tests have been added

[linux-foundation-easycla[bot]]

The committers listed above are authorized under a signed CLA.

• :white_check_mark: login: oldium / name: Oldřich Jedlička (8a86358008c95ae86777c34979029a4d0ed85a55, 033284b90a36dba7c60c79ea2d66be03d242ac9c)

[oldium]

Added few more tests for user-added LoggingHandler - they are not touched by instrumentation.

[oldium]

Updated changelog to refer to this pull request.

[oldium]

I have added a Proof-of-Concept commit to prove that LoggingHandler can be moved out of SDK:

1. Root logger instrumentation is done in the logging instrumentation, not in the SDK. Previously it was done in SDK, which I think is conceptually wrong.
2. Logger instrumentation uses only opentelemetry-api package, nothing from the SDK.

There are several things that need to be checked/finished:

1. Ensure that resource attribute is added to LogRecord by SDK, when we are not able to do so in LoggingHandler/OpenTelemetry API. This attribute is missing in LogRecord API, but present in SDK.
2. If there is any other LogRecord modification in SDK, ensure it is applied.
3. Fix SDK startup with OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED enabled for compatibility - run instrumentation manually (as the env var name suggests)?

Please suggest how to handle the logging instrumentation situation. I will be happy to do some implementation if necessary or to finish the POC.

[lzchen]

@oldium

A couple of questions as I seem to be confused about the issue and the proposed solution.

1. Can you provide sample code in the description to show a logger that is configured in such a way that this bug is prevalent?
2. Why do we have to move the LoggingHandler out of the SDK? How does this address the original problem?
3. What does this issue have to do with the logging instrumentation? I though we were discussing the LoggingHandler?

[oldium]

@lzchen

A couple of questions as I seem to be confused about the issue and the proposed solution.

1. Can you provide sample code in the description to show a logger that is configured in such a way that this bug is prevalent?

Try my example repo: https://github.com/oldium/gunicorn-opentelemetry-test

The Dockerfile there simulates exactly the same instrumentation steps that are done via K8s Operator for Python auto-instrumentation, i.e. puts /opentelemetry/opentelemetry/instrumentation/auto_instrumentation on the PYTHONPATH and lets the auto-instrumentation hook itself.

Steps to reproduce:

1. docker build . -t gunicorn-test
2. docker run -it --rm -e OTEL_TRACES_EXPORTER=none -e OTEL_METRICS_EXPORTER=none -p 8080:8080 gunicorn-test
3. curl localhost:8080 (run from different console)

Now observe that the docker console contains only OTEL log from app.py read_root(), but nothing from gunicorn.

2. Why do we have to move the LoggingHandler out of the SDK? How does this address the original problem?
3. What does this issue have to do with the logging instrumentation? I though we were discussing the LoggingHandler?

From the repro steps it can be seen that the opentelemetry-instrumentation-logging library actually does not do the auto-instrumentation of the logging subsystem in the way that all the logs would be automatically sent via OTEL. By further investigating this I have found out that it is the SDK (!), who is actually auto-instrumenting the root logger to send the logs via OTEL by adding LoggingHandler to the root logger. With hypothetical different Python OTEL SDK you would not see any logs in OTEL.

So my goal is to fix the opentelemetry-instrumentation-logging to actually auto-instrument the logging subsystem in a way that all the logs, which are sent via the standard Python logging subsystem, are also sent via OTEL.

Here are the key-points for the final implementation:

1. Implementing logging auto-instrumentation in opentelemetry-instrumentation-logging in a SDK-independent way requires similar approach, which is implemented in the SDK actually. That means to create something like LoggingHandler and install it into a root logger.
2. Instrumenting a root logger is not enough, because there might be other loggers with logger.propagate=False, which means that the log record is not propagated upwards in the logger hierarchy. This is exactly why the logs from gunicorn, uvicorn and celery are not forwarded via OTEL, they are setting logger.propagate=False for their loggers, so the log records are simply not forwarded to the root logger and its handlers, so the installed LoggingHandler does not see them and cannot forward them further to OTEL collector.
3. The LoggingHandler is actually a good start to implement logging instrumentation in a SDK-independent way, but it resides in SDK. Having it both in SDK and in opentelemetry-instrumentation-logging does not make much sense to me, so I chose to move it from SDK.

So it is not strictly necessary to remove LoggingHandler from SDK, but in order to implement logging subsystem instrumentation inside opentelemetry-instrumentation-logging, something like a LoggingHandler is necessary.

[oldium]

Any update, please? I can finish the PoC - just let me know if that is acceptable, I can prepare it. 😊