LoggingInstrumentation: Set Handler Format Explictly If basicConfig Has Already Been Called

[rjduffner]

Description

We are using open telemetry with Gunicorn. Due to the forking model of Gunicorn (https://opentelemetry-python.readthedocs.io/en/latest/examples/fork-process-model/README.html), we are unable to do automatic instrumentation.

Since Gunicorn sets up logging very early, setting the logFormat via OTEL_PYTHON_LOG_CORRELATION and OTEL_PYTHON_LOG_FORMAT doesn't do anything. This causes us to have to set the log format to include the trace_id/span_id in the generic formatter. This means that the LoggingInstrumention always has to be instrumented even locally.

This is a first draft of a potential way to fix it. I am looking for some feedback.

The Fix:

• Since the handler is created the first time one of the configs is called, we need to update the handler's format in place to use the instrumented logger.

The Open Questions:

• Most example code where people update the formatter in place assumes there is only one handler defined. While this is ok for most things, there might be cases where multiple handlers are defined. I chose to iterate over them all and change each formatter. This could have some unintended consequences though. Beyond, specifying which handler to use (or which format to override specifically), I am not sure of a better method.

The Annoying:

• Since the instrumentations are instrumented in alphabetical order, only logs produced after the logging instrumentation is instrumented get the new format. This means that the format changes during startup which is not ideal.

2023-09-06 11:44:40,943 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented boto3
2023-09-06 11:44:40,946 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented botocore
2023-09-06 11:44:40,955 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented confluent_kafka
2023-09-06 11:44:40,958 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented grpc_aio_client
2023-09-06 11:44:40,959 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented grpc_aio_server
2023-09-06 11:44:40,959 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented grpc_client
2023-09-06 11:44:40,960 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented grpc_server
2023-09-06 11:44:40,974 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented jinja2
2023-09-06 11:44:40,997 DEBUG [o11y.tracing:118][pid=19962][MainThread] Instrumented kafka
2023-09-06 11:44:40,999 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented logging
2023-09-06 11:44:41,009 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented pymemcache
2023-09-06 11:44:41,042 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented pyramid
2023-09-06 11:44:41,060 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented redis
2023-09-06 11:44:41,076 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented requests
2023-09-06 11:44:41,083 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented sqlite3
2023-09-06 11:44:41,085 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented urllib
2023-09-06 11:44:41,087 DEBUG [o11y.tracing] [tracing.py:118] [trace_id=0 span_id=0 resource.service.name=starfish_local trace_sampled=False] - Instrumented urllib3

Type of change

• [X] New feature (non-breaking change which adds functionality)

How Has This Been Tested?

• [X] Tested locally with a sample Gunicorn app until I get some guidance on final functionality.

Does This PR Require a Core Repo Change?

• [X] No.

Checklist:

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

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

[dhofstetter]

There are two open issues within the opentelemetry-python repository that are affected by this pr.

• 1
• 2

What can we do helping to get this pr reviewed and merged?

[howardyoo]

There are two open issues within the opentelemetry-python repository that are affected by this pr.

• 1
• 2

What can we do helping to get this pr reviewed and merged?

Add this issue on top of those two: https://github.com/open-telemetry/opentelemetry-python-contrib/issues/2346

[rjduffner]

going to close this pr. @dhofstetter has a more complete implementation. thanks @dhofstetter and @ocelotl