RSS

How we used OpenTelemetry to fix a bug in OpenTelemetry

OpenTelemetry is here to help us find the root cause of issues in our software quickly. We recently had an issue that we were able to fix by using one feature of OpenTelemetry to identify the root cause of bug in another feature.

In this blog post, we want to share this interesting experience with you. By that, you will learn that minor differences in the language-specific implementations can have interesting implications and that you have a feature for java & python, which is here to help you to debug context propagation issues.

The issue

Describe the bug

For the blog post Learn how to instrument nginx with OpenTelemetry we created a small sample app that had a frontend application in Node.JS, that called an nginx, which acted as a reverse proxy for a backend application in python.

Our goal was to create a re-usable docker-compose that would not only show people how to instrument nginx with OpenTelemetry, but also how a distributed trace crossing the webserver would look like.

While Jaeger showed us a trace flowing from the frontend application down to the nginx, the connection between nginx and python app was not visibile: we had two disconnected traces.

This came as a surprise, because in a prior test with a Java application as backend we were able to see traces going from nginx to that downstream application.

Steps to reproduce

Follow the instructions on how you can put nginx between two services. Replace the java-based application with a python application, e.g. put following three files into the backend folder instead:

  • app.py:

    import time
    
    import redis
    from flask import Flask
    
    app = Flask(__name__)
    cache = redis.Redis(host='redis', port=6379)
    
    def get_hit_count():
      retries = 5
      while True:
          try:
              return cache.incr('hits')
          except redis.exceptions.ConnectionError as exc:
              if retries == 0:
                  raise exc
              retries -= 1
              time.sleep(0.5)
    
    @app.route('/')
    def hello():
      count = get_hit_count()
      return 'Hello World! I have been seen {} times.\n'.format(count)
    
  • Dockerfile:

    FROM python:3.10-alpine
    WORKDIR /code
    ENV FLASK_APP=app.py
    ENV FLASK_RUN_HOST=0.0.0.0
    RUN apk add --no-cache gcc musl-dev linux-headers
    COPY requirements.txt requirements.txt
    RUN pip install -r requirements.txt
    RUN opentelemetry-bootstrap -a install
    EXPOSE 5000
    COPY . .
    CMD ["opentelemetry-instrument", "--traces_exporter", "otlp_proto_http", "--metrics_exporter", "console", "flask", "run"]
    
  • requirements.txt:

    flask
    redis
    opentelemetry-distro
    opentelemetry-exporter-otlp-proto-http
    

Update the docker-compose.yml with the following:

version: "2"
services:
  jaeger:
    image: jaegertracing/all-in-one:latest
    ports:
      - "16686:16686"
  collector:
    image: otel/opentelemetry-collector:latest
    command: ["--config=/etc/otel-collector-config.yaml"]
    volumes:
      - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml
  nginx:
    image: nginx-otel
    volumes:
      - ./opentelemetry_module.conf:/etc/nginx/conf.d/opentelemetry_module.conf
      - ./default.conf:/etc/nginx/conf.d/default.conf
  backend:
    build: ./backend
    image: backend-with-otel
    environment:
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://collector:4318/v1/traces
      - OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
      - OTEL_SERVICE_NAME=python-app
  redis:
    image: "redis:alpine"
  frontend:
    build: ./frontend
    image: frontend-with-otel
    ports:
      - "8000:8000"
    environment:
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://collector:4318/
      - OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
      - OTEL_SERVICE_NAME=frontend

Spin up that environment by running docker-compose up and send some requests to the frontend with curl localhost:8000

What did you expect to see?

In the jaeger UI at localhost:16686 you would expect to see traces going from the frontend through nginx down to the python-app.

What did you see instead?

In the jaeger UI at localhost:16686 you will see two traces, one going from the frontend down to nginx, and another one only for the python-app.

The solution

The hints

Since the setup worked with a java application in the backend, we knew that the problem was either caused by the python application or by the combination of the nginx instrumentation and the python application.

We could quickly rule out that the python application alone was the issue: trying out a simple Node.JS application as backend, we got the same result: two traces, one from frontend to nginx, another one for the Node.JS application alone.

With that, we knew that we had a propagation issue: the trace context was not transferred successfully from nginx down to the python and Node.JS application.

The analysis

Knowing that the issue does not occur with java and that it is likely a broken propagation, we knew what we had to do: we needed to see the trace headers.

Gladly, the instrumentations for Java and Python have a feature that allows us to capture HTTP request & response headers as span attributes easily.

By providing a comma-separated list of HTTP header names via the environment variables OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_REQUEST and OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_RESPONSE we can define which HTTP headers we want to capture. In our case we put all potential propagation headers:

OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_REQUEST=tracestate,traceparent,baggage,X-B3-TraceId

In our docker-compose-based example we simply can add it to the definition of our backend service:

  backend:
    build: ./backend
    image: backend-with-otel
    environment:
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://collector:4318/v1/traces
      - OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
      - OTEL_SERVICE_NAME=python-app
      - OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_REQUEST=tracestate,traceparent,baggage,X-B3-TraceId

Once again we ran docker-compose up to bring up our sample app and we send some request with curl localhost:8080 to the frontend application.

In Jaeger we still see that the traces are disconnected. However, when we look into one of those traces, we can see the collected request headers from nginx to backend:

A screenshot of the Jaeger UI showing that http.request.header.traceparent has multiple entries.

There it is! The trace headers (baggage, traceparent, tracestate) are send as multiple header fields.

Doing some research on that topic, we found out, that this is coved by RFC7230 and is allowed and defined for tracestate, but the definition for traceparent does not provide details on that corner-case.

Although we didn’t read into the source code of the OTel Java SDK & OTel Python SDK, it was obvious that Java was flexible in taking traceparent as multiple header field, while python (and other languages) do not allow that.

The fix

To fix our problem we added some checks to the nginx module, that make sure that the trace headers are only set once.

This fix is contained in the v1.0.1 release of the otel-webserver-module. This means you can update the Dockerfile to install the nginx module like the following:

FROM nginx:1.18
ADD https://github.com/open-telemetry/opentelemetry-cpp-contrib/releases/download/webserver%2Fv1.0.1/opentelemetry-webserver-sdk-x64-linux.tgz /opt
RUN cd /opt ; tar xvfz opentelemetry-webserver-sdk-x64-linux.tgz
RUN cd /opt/opentelemetry-webserver-sdk; ./install.sh
ENV LD_LIBRARY_PATH=$LD_LIBRARY_PATH:/opt/opentelemetry-webserver-sdk/sdk_lib/lib
RUN echo "load_module /opt/opentelemetry-webserver-sdk/WebServerModule/Nginx/ngx_http_opentelemetry_module.so;\n$(cat /etc/nginx/nginx.conf)" > /etc/nginx/nginx.conf
COPY default.conf /etc/nginx/conf.d
COPY opentelemetry_module.conf /etc/nginx/conf.d