[opentelemetry] opentelemetry trace_id lost in http access log

[zffocussss]

when trying to record request trace_id in the http access log,the span context is not present.but it is here in the application log

granian --interface asgi main:app --reload --host 0.0.0.0 --port 8777 --workers 2 --workers-kill-timeout 120 --access-log --access-log-fmt '%(addr)s - "%(method)s %(path)s %(protocol)s" %(status)d'

config_trace.py

import logging

from fastapi import FastAPI
from opentelemetry import trace
from opentelemetry._logs import get_logger_provider, set_logger_provider
from opentelemetry.exporter.otlp.proto.http import Compression
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.aiohttp_client import AioHttpClientInstrumentor
from opentelemetry.instrumentation.aiohttp_server import AioHttpServerInstrumentor
from opentelemetry.instrumentation.asyncio import AsyncioInstrumentor
from opentelemetry.instrumentation.boto3sqs import Boto3SQSInstrumentor
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor, OpenTelemetryMiddleware
from opentelemetry.instrumentation.httpx import HTTPXClientInstrumentor
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.instrumentation.redis import RedisInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
from opentelemetry.sdk.resources import DEPLOYMENT_ENVIRONMENT, SERVICE_NAME, Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.instrumentation.fastapi import (
    _excluded_urls_from_env,
    _get_default_span_details,
)

from common.config import S

logger = logging.getLogger(__name__)


def init_tracing(app: FastAPI):
    if isinstance(trace.get_tracer_provider(), TracerProvider):
        logger.warning("TracerProvider already initialized. Skipping.")
        return

    resource = Resource(
        attributes={
            SERVICE_NAME: S.TRACE_SERVICE_NAME,
            DEPLOYMENT_ENVIRONMENT: S.TRACE_DEPLOYMENT_ENVIRONMENT,
        }
    )

    # # Attach OTLP handler to root logger
    #     logging.getLogger().addHandler(handler)
    exporter = OTLPSpanExporter(
        endpoint=S.TRACE_URL,
        headers={
            "Authorization": f"Basic {S.TRACE_AUTH}",
            "stream-name": S.TRACE_DEPLOYMENT_ENVIRONMENT,
        },
        compression=Compression.Gzip,
        timeout=60,
    )

    provider = TracerProvider(resource=resource)
    trace.set_tracer_provider(provider)
    provider.add_span_processor(
        BatchSpanProcessor(
            exporter, max_queue_size=2048, schedule_delay_millis=5000, max_export_batch_size=512
        )
    )
    LoggingInstrumentor().instrument(set_logging_format=True)
    RequestsInstrumentor().instrument()
    RedisInstrumentor().instrument()
    HTTPXClientInstrumentor().instrument()
    AsyncioInstrumentor().instrument()
    Boto3SQSInstrumentor().instrument()
    AioHttpClientInstrumentor().instrument()
    AioHttpServerInstrumentor().instrument()
    FastAPIInstrumentor.instrument_app(app, excluded_urls="/docs, /redoc, /zeus-static, /v/")
    logger.info("Tracing enabled")

log_config.py

def get_trace_id() -> str:
    """
    fetch OpenTelemetry trace_id and span_id then format as trace_id-span_id
    We call the returned value "trace_id" for simplicity.
    """
    span = trace.get_current_span()
    span_context = span.get_span_context()
    print(f"{span_context=}")
    if span_context.is_valid:
        return f"{format(span_context.trace_id, '032x')}-{format(span_context.span_id, '016x')}"
    return "-"

class InjectingFilter(logging.Filter):
    """
    A filter which injects context-specific information into logs and ensures
    that only information for a specific webapp is included in its log
    """

    def filter(self, record):
        record.username = request_user_context.get()
        record.process_time = request_process_time.get()
        record.trace_id = get_trace_id()
        return True

logging dict

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "standard": {
            "format": (
                "%(asctime)s %(hostname)s %(process)d %(levelname)s %(username)s"
                " %(trace_id)s"
                " %(name)s:%(funcName)s:%(lineno)s %(message)s"
            ),
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "uvicorn_formatter": {
            "format": (
                "%(asctime)s %(hostname)s %(process)d %(levelname)s %(username)s"
                " %(trace_id)s %(message)s"
                " %(process_time)s"
            ),
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "access": {
            "format": "%(asctime)s %(hostname)s %(process)d %(levelname)s %(username)s %(trace_id)s %(message)s %(process_time)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
    },
    "handlers": {
        "default": {
            "formatter": "standard",
            "class": "logging.StreamHandler",
            "filters": ["contexvars_log"],
        },
        "uvicorn_handler": {
            "formatter": "uvicorn_formatter",
            "class": "logging.StreamHandler",
            "filters": ["contexvars_log"],
        },
        "access": {
            "formatter": "access",
            "class": "logging.StreamHandler",
            "filters": ["contexvars_log"],
        },
    },
    "filters": {"contexvars_log": {"()": "common.log.InjectingFilter"}},
    "loggers": {
        "granian.access": {
            "handlers": ["access"],
            "level": "INFO",
            "propagate": False,
        },
        "uvicorn": {
            "handlers": ["uvicorn_handler"],
            "level": "INFO",
            "propagate": False,
        },
        "main": {
            "handlers": ["default"],
            "level": S.LOG_LEVEL,
            "propagate": False,
        },
    },
}

log output

span_context=SpanContext(trace_id=0x00000000000000000000000000000000, span_id=0x0000000000000000, trace_flags=0x00, trace_state=[], is_remote=False)
2025-10-22 11:12:28 - 24559 INFO zeus - 127.0.0.1 - "GET / HTTP/1.1" 200 4

[gi0baro]

I'm afraid you can't really interact with contextvars in Granian access log.

Those log lines are emitted after the whole async application object returned, thus the span – and trace – at that time is already finished and you exited the context.

[zffocussss]

I'm afraid you can't really interact with contextvars in Granian access log.

Those log lines are emitted after the whole async application object returned, thus the span – and trace – at that time is already finished and you exited the context.

Can you please allow the contextvars to deal with trace/span as it is very useful inforamtion in the access log.
By the way,When switching to uvicorn,it works without changing application codes.

[hiasr]

@zffocussss We had the same issue, we added a middleware which does the access logging while the trace context is still valid. We're quite happy with this since it also allows for more control and enables structured logging.