Azure Application Insights Logs is getting logged twice always

[bbaabemhp]

Hey guys,

I have a simple Python app, which I connected with Azure App Insights and OpenTelemetry. But, whenever I log something with the standard logging library, it is getting logged twice in Azure App Insights Logs (while locally, things are getting logged only once). I use the following code:

from azure.monitor.opentelemetry import configure_azure_monitor
from opentelemetry import trace
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.trace import get_tracer_provider

from .settings import settings

def configure_tracing(app=None):
    if settings.APPLICATIONINSIGHTS_CONNECTION_STRING:
        configure_azure_monitor(
            connection_string=settings.APPLICATIONINSIGHTS_CONNECTION_STRING,
            enable_live_metrics=True,
            logger_name="app",
        )
    else:
        provider = TracerProvider()
        console_exporter = ConsoleSpanExporter()
        provider.add_span_processor(BatchSpanProcessor(console_exporter))
        trace.set_tracer_provider(provider)
    RequestsInstrumentor().instrument()
    LoggingInstrumentor().instrument(set_logging_format=True)
    if app:
        FastAPIInstrumentor.instrument_app(app)

    tracer = trace.get_tracer(__name__, tracer_provider=get_tracer_provider())
    return tracer

import logging

import uvicorn
from dotenv import load_dotenv
from fastapi import Depends, FastAPI
from fastapi.middleware.cors import CORSMiddleware

from .app.settings import settings
from .app.telemetry import configure_tracing

app = FastAPI()

tracer = configure_tracing(app)
logging.getLogger("azure.core.pipeline.policies.http_logging_policy").setLevel(
    logging.WARNING
)
logging.getLogger("azure.monitor.opentelemetry.exporter.export").setLevel(
    logging.WARNING
)
logging.getLogger("opentelemetry.trace").setLevel(logging.ERROR)
logging.getLogger("opentelemetry._logs._internal").setLevel(logging.ERROR)
logging.getLogger("opentelemetry.metrics._internal").setLevel(logging.ERROR)
logging.getLogger("opentelemetry.instrumentation.instrumentor").setLevel(logging.ERROR)
logging.getLogger("opentelemetry.instrumentation.fastapi").setLevel(logging.ERROR)

logger = logging.getLogger("app")

@app.post(
    path="/myendpoint",
)
def func(item: Item) -> Item:
    logger.info("I am here.")
    return item

And my settings:

APPLICATIONINSIGHTS_CONNECTION_STRING: str = "STRING"
APPINSIGHTS_INSTRUMENTATION_KEY: str = "KEY"
OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_REQUEST: str = ".*"
OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_RESPONSE: str = ".*"
OTEL_PYTHON_LOG_CORRELATION: str = "true"
OTEL_LOGS_EXPORTER: str | None = "None"
OTEL_PYTHON_DISABLED_INSTRUMENTATIONS=logging,fastapi,requests

And this is the result in Azure App Insights Logs:

[github-actions[bot]]

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @hectorhdzg @jeremydvoss @lzchen.

[lzchen]

@bbaabemhp

A few questions:

1. How are you executing this Python script? With uvicorn? Please paste your command in the cli.
2. Where are these duplicate logs being called? I see "Chat history so far..." but I don't see the logging call for that in your Python script.
3. Could you expand the trace telemetry log and take a screenshot of the attributes of the log (most notably, I want to see "sdkVersion" field.

[bbaabemhp]

Hey @lzchen, thanks for your answer:

This is the sdkVersion:

The python script runs with "poetry run python app.py" and uvicorn is defined in the code itself. Here is an updated code to show the problem and hopefully is reproducible for you too:

# telemetry.py
import logging

from azure.monitor.opentelemetry import configure_azure_monitor
from opentelemetry import trace
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.trace import get_tracer_provider

from orchestrator.settings import settings

def configure_tracing(app=None):
    if settings.APPLICATIONINSIGHTS_CONNECTION_STRING:
        configure_azure_monitor(
            connection_string=settings.APPLICATIONINSIGHTS_CONNECTION_STRING,
            enable_live_metrics=True,
            logger_name="orchestrator",
        )
    else:
        provider = TracerProvider()
        console_exporter = ConsoleSpanExporter()
        provider.add_span_processor(BatchSpanProcessor(console_exporter))
        trace.set_tracer_provider(provider)
    RequestsInstrumentor().instrument()
    LoggingInstrumentor().instrument(set_logging_format=True, log_level=logging.DEBUG)
    if app:
        FastAPIInstrumentor.instrument_app(app)

    tracer = trace.get_tracer(__name__, tracer_provider=get_tracer_provider())
    return tracer

# main.py
import uvicorn
from dotenv import load_dotenv
from fastapi import FastAPI
from logging_config import suppress_warnings
from orchestrator.settings import settings
from orchestrator.telemetry import configure_tracing
import logging

load_dotenv()
suppress_warnings()

app = FastAPI()

tracer = configure_tracing(app)

logger = logging.getLogger("orchestrator")

@app.get("/")
def health():
    logger.info("Hello from root endpoint")
    return {"response":"Hello"}

def start() -> None:
    uvicorn.run(
        "main:app",
        host="0.0.0.0",
        port=int(settings.ORCHESTRATOR_PORT),
        reload=False,
        workers=3,
    )

if __name__ == "__main__":
    start()

With this result: