Span/Trace ID is always zero in log files when running with Django

[proffalken]

Describe your environment
Running github.com/makemonmouth/mventory either via manage.py or uwsgi does not produce correct trace/span ID's.

Steps to reproduce

1. Clone the project and install via pip install -r requirements.txt
2. Run ./manage.py runserver
3. Browse to http://localhost:8000

What is the expected behavior?
Trace and Span ID's showing up in the logs

What is the actual behavior?

03-12-2021 05:07:47 INFO [django.server] [basehttp.py:161] [trace_id=0 span_id=0 resource.service.name=mventory] - "GET /rest/ HTTP/1.1" 200 6145
03-12-2021 05:07:47 INFO [django.server] [basehttp.py:161] [trace_id=0 span_id=0 resource.service.name=mventory] - "GET /rest/ HTTP/1.1" 200 6145

Additional context
I'm trying to get OpenTelemetry traces to be sent to Tempo, with the trace/span ID's being logged in Loki so I can lookup and compare the values.

If I add the following code to manage.py, then the Span/Trace ID's are printed to STDOUT but do not appear in the logs:

def request_hook(span, request):
    print(f"Request: {span}")

def response_hook(span, request, response):
    print(f"Response: {span}")

DjangoInstrumentor().instrument(request_hook=request_hook, response_hook=response_hook)

Setup code is at https://github.com/MakeMonmouth/mventory/blob/feature/opentelemetry/manage.py#L6-L41 but may be in the wrong place, I wasn't sure from the docs

Logging settings are at https://github.com/MakeMonmouth/mventory/blob/feature/opentelemetry/mventory/settings.py#L161-L198

[proffalken]

I've made some progress by moving the initialisation code out of manage.py and into https://github.com/MakeMonmouth/mventory/blob/feature/opentelemetry/mventory/wsgi.py

This gets me the traceID's into the logs and they are showing up in Loki, however it only seems to be for errors and warnings, not for successful responses:

# Successful response shows trace_id in context, but log format is ignored
Request: SpanContext(trace_id=0x007b6f228ed91601c6c2e3f721529f14, span_id=0x35625def90a025b8, trace_flags=0x01, trace_state=[], is_remote=False)
Response: SpanContext(trace_id=0x007b6f228ed91601c6c2e3f721529f14, span_id=0x35625def90a025b8, trace_flags=0x01, trace_state=[], is_remote=False)
[pid: 77797|app: 0|req: 1/1] 127.0.0.1 () {48 vars in 890 bytes} [Fri Dec  3 06:07:32 2021] GET /rest/ => generated 6073 bytes in 63 msecs (HTTP/1.1 200) 8 headers in 383 bytes (1 switches on core 0)

# Warning event (404) generates appropriate log lines:
Request: SpanContext(trace_id=0xa344cffd717c38ee65bb3c8965a6f221, span_id=0xd53fdfdbd7d3c7b4, trace_flags=0x01, trace_state=[], is_remote=False)
Response: SpanContext(trace_id=0xa344cffd717c38ee65bb3c8965a6f221, span_id=0xd53fdfdbd7d3c7b4, trace_flags=0x01, trace_state=[], is_remote=False)
03-12-2021 06:08:37 WARNING [django.request] [log.py:224] [trace_id=a6f76446c1507712ecb1461959370a73 span_id=c4388578b0cf1834 resource.service.name=mventory] - Not Found: /api
03-12-2021 06:08:37 WARNING [django.request] [log.py:224] [trace_id=a6f76446c1507712ecb1461959370a73 span_id=c4388578b0cf1834 resource.service.name=mventory] - Not Found: /api
[pid: 77797|app: 0|req: 2/2] 127.0.0.1 () {44 vars in 823 bytes} [Fri Dec  3 06:08:37 2021] GET /api => generated 2586 bytes in 67 msecs (HTTP/1.1 404) 5 headers in 158 bytes (1 switches on core 0)

[lzchen]

How are you setting up your tracing pipeline? I can't seem to find it in your sample.

[proffalken]

How are you setting up your tracing pipeline? I can't seem to find it in your sample.

This could well be where I'm going wrong then! 🤣

I'm using the OTLP HTTP exporter sending directly to Grafana's Tempo over a TLS Connection for the traces, and using the Django Loki Logging module to send the logs directly to Grafana's Loki.

I'm then trying to stitch it all together in Grafana, but because the traceID in the log is 0, Tempo can't see the trace IDs.

As an example, I have this in the logs for a 404:

but that trace doesn't exist in Tempo even though it exists in the Context.

I've got be honest, whilst I'm pretty aufait with Python, I'm not a pro by any means when it comes to Django, so I may well be holding this upside down and back to front!

[proffalken]

FWIW, I've gone back to flask and stripped everything back to a single file just to understand where I might be going wrong.

The app, env vars, and requirements.txt are all available in this Gist, and the result is exactly the same - the Trace and Span ID are 0 in the logs, so I'm guessing I'm doing something wrong with my logging config?

[proffalken]

OK, I've stripped this down even further, based it on the Getting Started Guide and I'm still not getting trace ID's in the logs:

# flask_example.py
import flask
import requests

from opentelemetry import trace
from opentelemetry.instrumentation.flask import FlaskInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    BatchSpanProcessor,
    ConsoleSpanExporter,
)
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter

trace.set_tracer_provider(TracerProvider())
span_processor = BatchSpanProcessor(OTLPSpanExporter(endpoint="https://otlphttp.service.wallace.network/v1/traces"))
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)
trace.get_tracer_provider().add_span_processor(
    span_processor
)

app = flask.Flask(__name__)
LoggingInstrumentor().instrument(set_logging_format=True)
FlaskInstrumentor().instrument_app(app)
RequestsInstrumentor().instrument()

tracer = trace.get_tracer(__name__)


@app.route("/")
def hello():
    with tracer.start_as_current_span("example-request"):
        requests.get("http://www.example.com")
    return "hello"


app.run(port=5000)

The trace ID's are echoed to the console but are not in the application logs:

(otel-test) [mmw@rincewind otel-test]$ python newapp.py 
 * Serving Flask app 'newapp' (lazy loading)
 * Environment: dev
 * Debug mode: off
2021-12-07 17:36:03,874 INFO [werkzeug] [_internal.py:225] [trace_id=0 span_id=0 resource.service.name=unknown_service] -  * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
2021-12-07 17:36:13,514 INFO [werkzeug] [_internal.py:225] [trace_id=0 span_id=0 resource.service.name=unknown_service] - 127.0.0.1 - - [07/Dec/2021 17:36:13] "GET / HTTP/1.1" 200 -
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0xfc221152991c56a4c9c8cd08bc6526c3",
        "span_id": "0x13b69c2d3be73e43",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": "0x7cde6ec7ec31f68f",
    "start_time": "2021-12-07T17:36:13.338285Z",
    "end_time": "2021-12-07T17:36:13.513855Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.example.com",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.7.1",
        "service.name": "unknown_service"
    }
}
{
    "name": "example-request",
    "context": {
        "trace_id": "0xfc221152991c56a4c9c8cd08bc6526c3",
        "span_id": "0x7cde6ec7ec31f68f",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": "0x44df0ee87aedd45e",
    "start_time": "2021-12-07T17:36:13.338130Z",
    "end_time": "2021-12-07T17:36:13.514149Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {},
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.7.1",
        "service.name": "unknown_service"
    }
}
{
    "name": "/",
    "context": {
        "trace_id": "0xfc221152991c56a4c9c8cd08bc6526c3",
        "span_id": "0x44df0ee87aedd45e",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2021-12-07T17:36:13.337428Z",
    "end_time": "2021-12-07T17:36:13.514632Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "127.0.0.1",
        "http.scheme": "http",
        "net.host.port": 5000,
        "http.host": "localhost:5000",
        "http.target": "/",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36",
        "net.peer.port": 50356,
        "http.flavor": "1.1",
        "http.route": "/",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.7.1",
        "service.name": "unknown_service"
    }
}

and yet the traces are being sent correctly to Tempo:

[lzchen]

Taking a look at your most recent sample code, it looks like the log messages produced are originating from the werkzeug library (which is what Flask uses), which defaults logging messages to INFO, which is why you see initial launch messages such as * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit). The LoggingInstrumentor will modify the root logger format to include trace_id and span_id if you specify set_logging_format=True, which is why you are seeing the highlighted logs formatted like this (in this case, trace_id and span_id are 0 because there is no trace, these are init logs not from your own application).

The logging you actually want is to be done in actual spans in your code. So if you modify your code like this:

@app.route("/")
def hello():
    with tracer.start_as_current_span("example-request"):
        requests.get("http://www.example.com")
        logging.warning("Log message in span")
    return "hello"

You should be able to get a log message with trace_id/span_id corresponding to the current span context (the one generated from with tracer.start_as_current_span("example-request"):.

[proffalken]

Yup, this works perfectly, thanks @lzchen!