Getting OpenTelemetry Logging working in Python

I’ve just spent a few hours tracking through the source code of OpenTelemetry and Python’s logging packages to try to get a better understanding of how this works in order to implement OpenTelemetry logging in python. As it’s not trivial I thought I’d document the process for others (and my future self) to better understand.

Firstly, the OpenTelemetry docs about OTEL_PYTHON_LOG_LEVEL seem to be incorrect – there’s no reference to this (yet) in the code, only in an open PR.

Secondly, it doesn’t actually matter what that is set to even if it works, if the level of your root logger is higher than what you want to log via OTEL it simply won’t ever receive those messages.

If you are doing logging.basicConfig(level=...) then that level is set on the root logger in your program, and any logs of a lesser level will be dropped. So if you’re saying logging.basicConfig(level=logging.WARNING) then INFO/DEBUG will never be sent to OTEL or anywhere else for that matter, even if you create handlers with their levels as lower than this.

So, firstly you need to configure the root logger correctly, ie rather than:

logging.basicConfig(
  level=logging.WARNING,
  format="%(asctime)s %(name)-12s %(levelname)-8s %(message)s",
  ...
)

you need to say:

default_handler = logging.StreamHandler()                                                                                                                                        
default_handler.setLevel(logging.getLevelName(log_settings.log_level))                                                                                                           
default_handler.setFormatter(logging.Formatter("%(asctime)s %(name)-12s %(levelname)-8s %(message)s"))                                                                           
                                                                                                                                                                                 
# Ensure that the root logger gets all messages, as we may want another log handler (eg opentelemetry) to be able                                                                
# to fetch messages of lower level than we output to the console.                                                                                                                
logging.basicConfig(                                                                                                                                                             
    level=logging.NOTSET,                                                                                                                                                        
    handlers=[default_handler],    
    ...                                                                                                                                              
)                                                                                                                                                                                

It’s more verbose (and basically what the basicConfig defaults are doing under the hood), but it will give you more ability to configure logs in the future.

Anyway, now we’ve got the basic logging configured correctly we can initialize the OpenTelemetry logging.

I’m going to assume that you have OpenTelemetry already working eg via opentelemetry-instrument -a python ...; you can set the following environment variables to enable the logging:

OTEL_PYTHON_LOG_CORRELATION=true  # Add trace information
OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true  # Enable logging
OTEL_LOGS_EXPORTER=console  # Obviously set this to something else in the real-world, but useful for testing
OTEL_PYTHON_LOG_LEVEL=info

This should dump OTEL log events to your console when you trigger them. However a logging.debug(...) will also be dumped because as I said at the beginning, OTEL_PYTHON_LOG_LEVEL is not yet implemented in Python in spite of what the docs say (see https://github.com/open-telemetry/opentelemetry-python/pull/4203 for a proposed PR which hopefully will be merged soon).

A quick hack to set the OTEL log level is as follows:

from opentelemetry.sdk._logs._internal import LoggingHandler

# Patch the newly created log handler so that OTEL_PYTHON_LOG_LEVEL is honoured. Can be removed once            
# https://github.com/open-telemetry/opentelemetry-python/pull/4203 is merged.            
otel_logger = next(filter(lambda n: isinstance(n, LoggingHandler), logging.getLogger().handlers), None)            
if otel_logger:            
    otel_logger.setLevel(logging.getLevelName(os.environ.get("OTEL_PYTHON_LOG_LEVEL", "WARNING").upper()))            

And you’re done.

As a side-note, I recently found a really simple way to make OpenTelemetry auto-instrumentation work correctly with forking servers such as uvicorn or gunicorn. For FastAPI in particular (but it should be easy to modify for other frameworks) simply create a lifespan hook which imports opentelemetry.instrumentation.auto_instrumentation.sitecustomize:

@asynccontextmanager
async def otel_lifespan(app: FastAPI) -> t.AsyncIterator[None]:
    if "OTEL_SERVICE_NAME" in os.environ:  # Only enable OTEL if this is set    
        if "PYTHONPATH" not in os.environ:    
            os.environ["PYTHONPATH"] = ":".join(sys.path)

        # This import will trigger auto-instrumentation for this process, which is needed for anything with multiple    
        # worker processes (e.g. gunicorn, uvicorn)    
        import opentelemetry.instrumentation.auto_instrumentation.sitecustomize  # noqa
    yield

app = FastAPI(lifespan=otel_lifespan, ...)

This basically is the same as running opentelemetry-instrument on each worker process that is forked by the process manager. This hack should work with gunicorn, uvicorn etc.