Quick-Start to Integrating OpenTelemetry with FastAPI (Part 2)

The Otel Python SDK is still a work-in-progress piece of technology. These are gaps which I discovered during my journey and how I managed to work around them.

HTTPException Logging — Missing details!?

The first one was where I couldn’t get Otel to log the error details when I raised a HTTPException (see https://fastapi.tiangolo.com/tutorial/handling-errors/#use-httpexception). We use NewRelic (and DataDog) for our Otel needs, and in NewRelic, our FastAPI traces would merely show up as a generic HTTP error when HTTPException was raised.

No details!

See the otel.status_description and otel.status_code fields? Nothing useful for me!! Ok, to be fair, you *could* click on the text below that says There was 1 span event exception to see the details, but it’s a bit of work and I’m lazy. Here’s what that click will show you:

Still not very useful

Still not very useful. I want to see what’s inside HTTPException because that is what gets returned to the browser / API caller.

The workaround turned out to be simple. I ended up overriding the default HTTPException handler and you can read about it here https://fastapi.tiangolo.com/tutorial/handling-errors/#override-the-httpexception-error-handler. Here’s the code for it:

from starlette.exceptions import HTTPException as StarletteHTTPException

# For otel compatibility. It seems HTTPException is only trapped by Otel with otel.status_description
# set to the string "HTTPException:", which is not very informative for us. Here, we implement a custom
# error handler for HTTPException class.
@app.exception_handler(StarletteHTTPException)
async def http_exception_handler(request, exc):
    current_span = trace.get_current_span()
    if (current_span is not None) and (current_span.is_recording()):
        current_span.set_attributes(
            {
                "http.status_text": str(exc.detail),
                "otel.status_description": f"{exc.status_code} / {str(exc.detail)}",
                "otel.status_code": "ERROR"
            }
        )
    return PlainTextResponse(json.dumps({ "detail" : str(exc.detail) }), status_code=exc.status_code)

Note the extra code to check if there is a current Otel span recording. This is because the FastAPI production code I wrote can be configured to turn Otel tracing on / off (for debugging purposes).

And now I can see this!! Yay to lazy people!

Much better!

Just in case you are wondering, otel.status_description takes the value directly from HTTPException.detail in FastAPI. So code like this:

From https://fastapi.tiangolo.com/tutorial/handling-errors/#use-httpexception

Will end up having “Item not found” inside otel.status_description.

Log formatting ignored!

The venerable Pypi module called logging has nice integration with the OpenTelemetry SDK.

With logging, you can specify Formatter objects (see https://docs.python.org/3/library/logging.html#formatter-objects) which allows you to control what fields end up in your output log text. If you look at https://opentelemetry-python-contrib.readthedocs.io/en/latest/instrumentation/logging/logging.html#envvar-OTEL_PYTHON_LOG_FORMAT, it says you can change the format to whatever you desire. Well, that didn’t work for me!

OTEL_PYTHON_LOG_CORRELATION=true
OTEL_PYTHON_LOG_FORMAT=%(pathname)s:%(funcName)s:%(lineno)d:%(levelname)s:%(message)s
OTEL_PYTHON_LOG_LEVEL=info

If you have specify OTEL_PYTHON_LOG_FORMAT like above, I would expect my otel logs to have the full pathname to my Python file, the function name where the log was generated, the line no that generated the log, etc. In my testing, OTEL_PYTHON_LOG_FORMAT was ignored.

So if I do this in my code:

 logging.info("Hi there, Mr. Pineapple!")

I get this otel JSON being spit out:

{
    "body": "Hi there, Mr. Pineapple!",
    "severity_number": "<SeverityNumber.INFO: 9>",
    "severity_text": "INFO",
    "attributes": {
        "otelSpanID": "2e94f2400eb2f2c9",
        "otelTraceID": "1b63d84a5a4faec3b1dd77477d1d52df",
        "otelTraceSampled": true,
        "otelServiceName": "my-fruit-service"
    },
    "timestamp": "2023-06-19T06:48:28.605903Z",
    "trace_id": "0x1b63d84a5a4faec3b1dd77477d1d52df",
    "span_id": "0x2e94f2400eb2f2c9",
    "trace_flags": 1,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.18.0', 'service.instance.id': 'dev', 'service.name': 'my-fruit-service'}, maxlen=None)"
}

Do you see what’s in body????? It’s just plain text! Arrrrgggggh.

The solution was to create a new class that inherits from LoggingHandler that respects Formatter objects. You can read about the solution from the post I made at Github: https://github.com/open-telemetry/opentelemetry-python/issues/3353

Turn console logging on and off for debugging

You could set up your own otel backend for debugging purposes, but hey, I’m lazy and that’s extra work and resources on my laptop. I could also export the data to a SaaS provider like NewRelic or DataDog but the ingest takes a few minutes to show up on the dashboard, and I’d have to open another account (oh gawd, those extra mouse clicks and key clicks!!).

So you might want to consider turning on console output for your otel JSON payloads (these are the ones that get shipped to your otel backend). In Python, that’s easy to do:

from opentelemetry.sdk.trace.export import SimpleSpanProcessor, BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor, SimpleLogRecordProcessor, ConsoleLogExporter

def otel_trace_init():
    trace.set_tracer_provider(
       TracerProvider(
           resource=Resource.create({}),
       ),
    )
    if DEBUG_LOG_OTEL_TO_PROVIDER:
        otel_endpoint_url, otel_http_headers = otel_get_env_vars()
        otlp_span_exporter = OTLPSpanExporter(endpoint=otel_endpoint_url,headers=otel_http_headers)
        trace.get_tracer_provider().add_span_processor(BatchSpanProcessor(otlp_span_exporter))
    if DEBUG_LOG_OTEL_TO_CONSOLE:
        trace.get_tracer_provider().add_span_processor(SimpleSpanProcessor(ConsoleSpanExporter()))

The code snippet above shows how 2 variables — DEBUG_LOG_OTEL_TO_PROVIDER and DEBUG_LOG_OTEL_TO_CONSOLE control whether to send those JSONs to the SaaS provider or to the console. You can define these are environment variables and initialize them in Python like so:

DEBUG_LOG_OTEL_TO_CONSOLE = os.getenv("DEBUG_LOG_OTEL_TO_CONSOLE", 'False').lower() == 'true'
DEBUG_LOG_OTEL_TO_PROVIDER = os.getenv("DEBUG_LOG_OTEL_TO_PROVIDER", 'False').lower() == 'true'

I also highly recommend you set these environment variables and use them in your Python code:

OTEL_ENDPOINT_HTTP_HEADERS=api-key=(really? You'd think I'd leave this here????!)
OTEL_ENDPOINT_URL=https://otlp.eu01.nr-data.net:4317
OTEL_PYTHON_LOG_CORRELATION=true
OTEL_PYTHON_LOG_FORMAT=%(pathname)s:%(funcName)s:%(lineno)d:%(levelname)s:%(message)s
OTEL_PYTHON_LOG_LEVEL=debug
OTEL_RESOURCE_ATTRIBUTES=service.instance.id=production,service.name=api.invicta.io,telemetry.sdk.name=opentelemetry,telemetry.sdk.language=python,telemetry.sdk.version=1.18.0
DEBUG_LOG_OTEL_TO_CONSOLE=true
DEBUG_LOG_OTEL_TO_PROVIDER=true

You can read more about the OTEL_PYTHON_* variables here (https://opentelemetry-python-contrib.readthedocs.io/en/latest/instrumentation/logging/logging.html).

Oh, please note you can have the = symbol in environment variables like in OTEL_ENDPOINT_HTTP_HEADERS above. It works just fine and as you’d expect it. :)

Don’t forget to read part 3!