Auto-instrumented Flask access logs doesn't includes a valid trace_id

Flask access logs doesn't includes trace_id, while exception/error log messages does.

Describe your environment

$ python -V
Python 3.10.7

$ pip freeze
blinker==1.7.0
certifi==2024.2.2
charset-normalizer==3.3.2
click==8.1.7
Deprecated==1.2.14
Flask==2.3.3
idna==3.6
importlib-metadata==6.11.0
itsdangerous==2.1.2
Jinja2==3.1.3
MarkupSafe==2.1.5
opentelemetry-api==1.23.0
opentelemetry-distro==0.44b0
opentelemetry-instrumentation==0.44b0
opentelemetry-instrumentation-flask==0.44b0
opentelemetry-instrumentation-logging==0.44b0
opentelemetry-instrumentation-wsgi==0.44b0
opentelemetry-sdk==1.23.0
opentelemetry-semantic-conventions==0.44b0
opentelemetry-util-http==0.44b0
packaging==24.0
requests==2.31.0
typing_extensions==4.10.0
urllib3==2.2.1
Werkzeug==2.3.8
wrapt==1.16.0
zipp==3.18.1

Steps to reproduce

Create a simple Flask app.py:

import requests
from flask import Flask

app = Flask(__name__)

@app.route("/")
def success():
    res = requests.get("https://google.com")
    return f"got status: {res.status_code}\n"

@app.route("/fail")
def fail():
    x = 1/0
    return 'ERROR'

if __name__ == "__main__":
    app.run(host="0.0.0.0", port=8080)

Execute with:

$ virtualenv .env
$ . .env/bin/activate
$ pip install \
    'werkzeug<3' \
    'flask<3' \
    requests \
    opentelemetry-api \
    opentelemetry-sdk \
    opentelemetry-distro \
    opentelemetry-instrumentation-flask \
    opentelemetry-instrumentation-logging

$ export OTEL_PYTHON_LOG_CORRELATION=true
$ export OTEL_PYTHON_LOG_FORMAT='[trace_id=%(otelTraceID)s] %(message)s'
$ opentelemetry-instrument --traces_exporter console --metrics_exporter none --logs_exporter console python ./app.py
 * Serving Flask app 'app'
 * Debug mode: off
[trace_id=0] WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.
 * Running on all addresses (0.0.0.0)
 * Running on http://127.0.0.1:8080
 * Running on http://192.168.1.70:8080
[trace_id=0] Press CTRL+C to quit
[trace_id=0] 127.0.0.1 - - [20/Mar/2024 22:13:18] "GET / HTTP/1.1" 200 -
{
    "name": "/",
    "context": {
        "trace_id": "0x123a5aad57dff632ab06eedea663f6a1",
        "span_id": "0xed070ba1984fab03",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2024-03-20T22:13:18.095985Z",
    "end_time": "2024-03-20T22:13:18.652112Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "0.0.0.0",
        "http.scheme": "http",
        "net.host.port": 8080,
        "http.host": "127.0.0.1:8080",
        "http.target": "/",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "curl/7.82.0",
        "net.peer.port": 35116,
        "http.flavor": "1.1",
        "http.route": "/",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.23.0",
            "telemetry.auto.version": "0.44b0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}
[trace_id=53240561043d889ee636f768405a0cc9] Exception on /fail [GET]
Traceback (most recent call last):
  File "/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py", line 2190, in wsgi_app
    response = self.full_dispatch_request()
  File "/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py", line 1486, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py", line 1484, in full_dispatch_request
    rv = self.dispatch_request()
  File "/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py", line 1469, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/tmp/flask/./app.py", line 14, in fail
    x = 1/0
ZeroDivisionError: division by zero
[trace_id=0] 127.0.0.1 - - [20/Mar/2024 22:13:22] "GET /fail HTTP/1.1" 500 -
{
    "name": "/fail",
    "context": {
        "trace_id": "0x53240561043d889ee636f768405a0cc9",
        "span_id": "0xddd8dbf3f24273cf",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2024-03-20T22:13:22.518221Z",
    "end_time": "2024-03-20T22:13:22.523594Z",
    "status": {
        "status_code": "ERROR",
        "description": "ZeroDivisionError: division by zero"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "0.0.0.0",
        "http.scheme": "http",
        "net.host.port": 8080,
        "http.host": "127.0.0.1:8080",
        "http.target": "/fail",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "curl/7.82.0",
        "net.peer.port": 35132,
        "http.flavor": "1.1",
        "http.route": "/fail",
        "http.status_code": 500
    },
    "events": [
        {
            "name": "exception",
            "timestamp": "2024-03-20T22:13:22.523579Z",
            "attributes": {
                "exception.type": "ZeroDivisionError",
                "exception.message": "division by zero",
                "exception.stacktrace": "Traceback (most recent call last):\n  File \"/tmp/flask/.env/lib/python3.10/site-packages/opentelemetry/trace/__init__.py\", line 573, in use_span\n    yield span\n  File \"/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py\", line 2190, in wsgi_app\n    response = self.full_dispatch_request()\n  File \"/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py\", line 1486, in full_dispatch_request\n    rv = self.handle_user_exception(e)\n  File \"/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py\", line 1484, in full_dispatch_request\n    rv = self.dispatch_request()\n  File \"/tmp/flask/.env/lib/python3.10/site-packages/flask/app.py\", line 1469, in dispatch_request\n    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)\n  File \"/tmp/flask/./app.py\", line 14, in fail\n    x = 1/0\nZeroDivisionError: division by zero\n",
                "exception.escaped": "False"
            }
        }
    ],
    "links": [],
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.23.0",
            "telemetry.auto.version": "0.44b0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}

Execute from a separated terminal:

$ curl 127.1:8080
got status: 200

## wait for the trace to appears in the flask terminal

$ curl 127.1:8080/fail
<!doctype html>
<html lang=en>
<title>500 Internal Server Error</title>
<h1>Internal Server Error</h1>
<p>The server encountered an internal error and was unable to complete your request. Either the server is overloaded or there is an error in the application.</p>

What is the expected behavior?

I expect to see the access log from flask to include the TraceId [trace_id=XXXXXXXX] 127.0.0.1 - - [20/Mar/2024 22:24:54] "GET / HTTP/1.1" 200 - just like it appears in the error log [trace_id=53240561043d889ee636f768405a0cc9] Exception on /fail [GET]

What is the actual behavior?

Access logs does not includes the TraceId values: [trace_id=0] 127.0.0.1 - - [20/Mar/2024 22:24:54] "GET / HTTP/1.1" 200 -

Start by running the reproduction in app.py with Flask and the OpenTelemetry instrumentation packages, then compare the access and exception log behavior under the shown environment. Trace how Flask access logging is emitted during the request and verify that the completed access line carries the same nonzero trace ID as the request span.