Auto-instrumentation gives 0x00000... traces and spans; no metrics at all.

[ekquasar]

Summary

Following the OpenTelemetry docs for auto-instrumenting a Python service, the auto-instrumentation fails to export traces and metrics.

Environment

• macOS 14.1.1
  • identical result reproduced in Docker FROM ubuntu:latest, see Additional Context at bottom for details.
• Python 3.11.6
• opentelemetry.skd.version 1.21.0
• telemetry.auto.version: 0.42b0

Reproduction instructions

Make a simple Flask app, run it, send HTTP requests, and observe OpenTelemetry output in the console.

Setup Python virtual env & dependencies

Create a virtual environment and install both web-server and instrumentation dependencies by running this:

python3 -m venv venv && \
  source ./venv/bin/activate && \
  pip install --upgrade pip && \
  pip install 'flask<3' && \
  pip install opentelemetry-distro && \
  opentelemetry-bootstrap -a install

Simple Flask app

Copy this into app.py:

import logging, random, flask

app = flask.Flask('demo')
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger('demo')

@app.route('/')
def index():
    roll = random.randint(1, 6)
    logger.info('Rolled a %d', roll)
    return str(roll)

Run the web server

Run the tiny Flask app with OpenTelemetry auto-instrumentation as follows:

export OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true
opentelemetry-instrument \
    --traces_exporter console \
    --metrics_exporter console \
    --logs_exporter console \
    --service_name demo \
    flask run -p 8080

Notice that it should automatically export three things to the console: traces, metrics, and logs.

Observe the output

See "Actual behavior" section below for observed console output.

Expected behavior

As shown in the OpenTelemetry Python docs, the expected console output is (reproduced here):

{
    "name": "/rolldice",
    "context": {
        "trace_id": "0xdb1fc322141e64eb84f5bd8a8b1c6d1f",
        "span_id": "0x5c2b0f851030d17d",
        "trace_state": "[]"
    },
    "kind": "SpanKind.SERVER",
    "parent_id": null,
    "start_time": "2023-10-10T08:14:32.630332Z",
    "end_time": "2023-10-10T08:14:32.631523Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.server_name": "127.0.0.1",
        "http.scheme": "http",
        "net.host.port": 8080,
        "http.host": "localhost:8080",
        "http.target": "/rolldice?rolls=12",
        "net.peer.ip": "127.0.0.1",
        "http.user_agent": "curl/8.1.2",
        "net.peer.port": 58419,
        "http.flavor": "1.1",
        "http.route": "/rolldice",
        "http.status_code": 200
    },
    "events": [],
    "links": [],
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.17.0",
            "service.name": "dice-server",
            "telemetry.auto.version": "0.38b0"
        },
        "schema_url": ""
    }
}
{
    "body": "Anonymous player is rolling the dice: 3",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARNING",
    "attributes": {
        "otelSpanID": "5c2b0f851030d17d",
        "otelTraceID": "db1fc322141e64eb84f5bd8a8b1c6d1f",
        "otelServiceName": "dice-server"
    },
    "timestamp": "2023-10-10T08:14:32.631195Z",
    "trace_id": "0xdb1fc322141e64eb84f5bd8a8b1c6d1f",
    "span_id": "0x5c2b0f851030d17d",
    "trace_flags": 1,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.17.0', 'service.name': 'dice-server', 'telemetry.auto.version': '0.38b0'}, maxlen=None)"
}

of course with the endpoint and service name defined in app.py above rather than "rolldice". Moreover the telemetry.sdk.version etc. are as in the Environment section above.

Additionally, I expect to observe metrics output, especially the latency histogram (details in docs linked above).

Actual behavior

Instead of producing output indicating OpenTelemetry registered the index endpoint / successfully, there is no such information in the console output. Moreover, the traces and spans are 0x000... uniformly. Moreover, there are no metrics exported to the console.

The console output is as follows:

* Debug mode: off
{
    "body": "\u001b[31m\u001b[1mWARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.\u001b[0m\n * Running on http://127.0.0.1:8080",
    "severity_number": "<SeverityNumber.INFO: 9>",
    "severity_text": "INFO",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "demo"
    },
    "dropped_attributes": 0,
    "timestamp": "2023-12-01T16:30:33.590218Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.21.0', 'service.name': 'demo', 'telemetry.auto.version': '0.42b0'}, maxlen=None)"
}
{
    "body": "\u001b[33mPress CTRL+C to quit\u001b[0m",
    "severity_number": "<SeverityNumber.INFO: 9>",
    "severity_text": "INFO",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "demo"
    },
    "dropped_attributes": 0,
    "timestamp": "2023-12-01T16:30:33.591706Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.21.0', 'service.name': 'demo', 'telemetry.auto.version': '0.42b0'}, maxlen=None)"
}
{
    "body": "127.0.0.1 - - [01/Dec/2023 11:30:34] \"GET / HTTP/1.1\" 200 -",
    "severity_number": "<SeverityNumber.INFO: 9>",
    "severity_text": "INFO",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "demo"
    },
    "dropped_attributes": 0,
    "timestamp": "2023-12-01T16:30:34.281347Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": "BoundedAttributes({'telemetry.sdk.language': 'python', 'telemetry.sdk.name': 'opentelemetry', 'telemetry.sdk.version': '1.21.0', 'service.name': 'demo', 'telemetry.auto.version': '0.42b0'}, maxlen=None)"
}
...

After the startup behavior (* Debug mode: off \n ... and the first two messages) each request against the app is logged identically to the final message above (with timestamp changing, all else identical).

Additional context

Log levels

Neither using logger.warning nor raise Exception changes the above behavior - these are logged with 0x000... trace and span identities. The severity_text and severity_number are recorded correctly.

Docker

You can also reproduce this result in Docker, please see the following Dockerfile for ease of reproduction:

FROM ubuntu:latest
WORKDIR /opt/demo
# RUN apt-get update && apt-get install -y python3 python3-pip
RUN apt-get update && apt-get install -y python3-dev python3-pip build-essential
RUN useradd -ms /bin/bash demo
USER demo
ENV PATH="/home/demo/.local/bin:${PATH}"
RUN pip install 'flask<3' && \
    pip install opentelemetry-distro && \
    opentelemetry-bootstrap -a install
COPY src/app.py run.sh ./
CMD [ "bash", "run.sh" ]

and note that the run.sh is the following:

#/bin/sh
export OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true
opentelemetry-instrument \
    --traces_exporter console \
    --metrics_exporter console \
    --logs_exporter console \
    --service_name demo \
    flask run -p 8080 -h 0.0.0.0

^ you will need to chmod +x run.sh.

[flands]

Dup of open-telemetry/opentelemetry-python#3482?

[ekquasar]

@flands Yes looks like it, the addition of werkzeug<3 in the pip install was the fix - those "getting started" instructions were updated in December. These "auto-instrumentation doesn't work" bug reports should hopefully quiet down for a bit, now :)