Logging and Application Insights

An agent built your research API on FastAPI, deployed it to Azure, and sprinkled print() calls through the code so it could see what was happening locally. In production those lines go nowhere useful. When a survey import fails at 2am, or a dashboard endpoint takes eleven seconds for one client and eighty milliseconds for everyone else, you need the app to have written down enough for you to reconstruct what happened. This is the difference between an app that can be debugged and one you have to guess at.

The one line that turns telemetry on

Azure’s story for Python is the Azure Monitor OpenTelemetry Distro: a package that bundles the open OpenTelemetry standard’s instrumentation libraries and points them at Application Insights, the Azure service that stores and queries application telemetry.

# main.py — before any of your other imports
import logging
from azure.monitor.opentelemetry import configure_azure_monitor
from fastapi import FastAPI

# Reads APPLICATIONINSIGHTS_CONNECTION_STRING from the environment.
# logger_name scopes collection to your logger, not the SDK's own chatter.
configure_azure_monitor(logger_name="iff")

logger = logging.getLogger("iff.api")   # a child of "iff", so it is collected
app = FastAPI()

That single call installs the bundled instrumentation for FastAPI, requests, urllib3, urllib and psycopg2. You get a row per inbound request, a row per outbound HTTP or Postgres call, and automatic capture of unhandled exceptions, without writing tracing code.

The connection string decides which Application Insights resource receives the data. Microsoft’s documented precedence is code, then environment variable, then config file — so a hardcoded string wins everywhere, including production. Set it as an App Service application setting instead:

# App Service application setting, not a value in your repo
az webapp config appsettings set -g iff-rg -n iff-api \
  --settings APPLICATIONINSIGHTS_CONNECTION_STRING="$CONN" \
             OTEL_SERVICE_NAME="iff-api"   # becomes AppRoleName in queries

OTEL_SERVICE_NAME matters more than it looks. It becomes the AppRoleName column and the node name on the Application Map. If your API and your scheduled worker both report without it, they merge into one indistinguishable blob.

Structured logging, concretely

Here is the pattern agents reach for, and the one worth replacing it with.

# Before: a sentence. Findable only by guessing its exact wording.
logger.info(f"Imported {n} responses for survey {survey_id} in {ms}ms")

# After: a stable message plus named fields.
logger.info(
    "survey_import_complete",
    extra={"survey_id": survey_id, "rows": n, "duration_ms": ms},
)

Keys passed in extra land in the Properties column of the AppTraces table, so you can group by tostring(Properties.survey_id) or filter toint(Properties.rows) == 0. With the f-string version, answering “which surveys imported zero rows this week?” means a regular expression over prose that breaks the next time someone rewords the message.

One boundary worth drawing hard: log identifiers and counts, never payloads. A logged request body on a survey platform is respondent free-text sitting in a telemetry store with its own retention and access rules.

Four tables, and the one with a misleading name

Application Insights sorts telemetry into tables. Learning which is which is most of the skill.

Note the trap: in Application Insights, “traces” means log lines, not distributed traces. The distributed trace is the OperationId that stitches rows across all four tables.

You will also see two naming styles. Queried from the Application Insights resource, the legacy names requests, dependencies, traces, exceptions work, with fields like operation_Id and duration. From the Log Analytics workspace you use AppRequests and friends, with OperationId and DurationMs. Same data, two dialects. Mixing them in one query gives you “unknown column”.

Correlation: why the worker’s logs are orphaned

OperationId is the trace id. Every item produced while handling one request shares it, which is what makes a single request reconstructable. Across services it travels in the W3C traceparent HTTP header; the instrumentation reads it on the way in and writes it on the way out, so an HTTP call chain stays one trace.

A queue message is not an HTTP request, so that chain breaks the moment work goes asynchronous. This is the most common gap in agent-written pipelines:

from opentelemetry import trace

# Before: the job loses all connection to the request that created it.
await queue.send({"survey_id": survey_id})

# After: carry the trace id so the two halves can be joined later.
span = trace.get_current_span().get_span_context()
await queue.send({
    "survey_id": survey_id,
    "trace_id": format(span.trace_id, "032x"),  # same shape as OperationId
})

The worker then logs trace_id as a field, and you can join the two sides by hand even if the spans are separate traces.

Sampling, and the counting bug it causes

Sampling keeps a fraction of traces to control cost. The distro accepts two Microsoft samplers by environment variable:

OTEL_TRACES_SAMPLER=microsoft.fixed_percentage
OTEL_TRACES_SAMPLER_ARG=0.1        # keep roughly 10% of traces

# or cap the volume instead of the proportion:
OTEL_TRACES_SAMPLER=microsoft.rate_limited
OTEL_TRACES_SAMPLER_ARG=1.5        # at most 1.5 traces per second

Sampling introduces a quiet correctness problem in queries. Each stored row carries ItemCount: how many real items it stands for. At 10% sampling, count() under-reports by about ten times. Always count with sum(ItemCount).

Enough KQL to answer real questions

Kusto Query Language (KQL) reads like a pipeline: a table, then filters and summaries separated by |.

Recent exceptions, grouped so you see distinct problems rather than a wall of repeats:

AppExceptions
| where TimeGenerated > ago(24h) and AppRoleName == "iff-api"
| summarize Hits = sum(ItemCount), LastSeen = max(TimeGenerated),
            AnOperation = take_any(OperationId)  // one id to go and inspect
    by ProblemId, OuterMessage, OperationName
| top 20 by Hits desc

Slowest endpoints by tail latency, not by average — averages hide exactly the problem you are looking for:

AppRequests
| where TimeGenerated > ago(7d) and AppRoleName == "iff-api"
| summarize Calls = sum(ItemCount),
            p50 = percentile(DurationMs, 50),
            p95 = percentile(DurationMs, 95),
            p99 = percentile(DurationMs, 99)
    by OperationName
| where Calls > 50                               // ignore rarely-hit routes
| top 15 by p95 desc

Failure rate over time, which is what you actually want to alert on:

AppRequests
| where TimeGenerated > ago(2d) and AppRoleName == "iff-api"
| summarize Total = sum(ItemCount),
            Failed = sumif(ItemCount, Success == false)
    by bin(TimeGenerated, 15m)
| extend FailureRatePct = round(100.0 * Failed / Total, 2)
| project TimeGenerated, FailureRatePct
| render timechart

And one request, end to end — the query to reach for when a client sends you a timestamp and a complaint:

let opId = "8f3c1e9a4b2d4f5e9c7a1b3d5e7f9a0b";   // from a request or exception row
union
  (AppRequests     | where OperationId == opId
     | project TimeGenerated, Kind = "request", Name,
               Detail = strcat(ResultCode, " / ", DurationMs, " ms")),
  (AppDependencies | where OperationId == opId
     | project TimeGenerated, Kind = "dependency", Name,
               Detail = strcat(Target, " / ", DurationMs, " ms")),
  (AppTraces       | where OperationId == opId
     | project TimeGenerated, Kind = "trace", Name = OperationName, Detail = Message),
  (AppExceptions   | where OperationId == opId
     | project TimeGenerated, Kind = "exception", Name = ExceptionType, Detail = OuterMessage)
| sort by TimeGenerated asc

That output is a timeline: the request arrived, three Postgres queries ran, an LLM call took 9.4 seconds, a warning was logged, the request returned 200. The answer is usually visible in one read.

What to check in your own code

• Search for print( in the back end. Each one is a debug statement that produces nothing you can query.
• Confirm configure_azure_monitor(...) is called once, early, with logger_name set — and with no connection_string argument in committed code.
• Check App Service application settings for APPLICATIONINSIGHTS_CONNECTION_STRING and OTEL_SERVICE_NAME, and confirm staging and production point at different Application Insights resources.
• Grep your loggers for f-strings carrying values (logger.info(f"..."). Those values should be in extra.
• Grep for anything logging a body: request.json(), model_dump() or response.text inside a logging call.
• Run the failure-rate query above. If it returns no rows, your telemetry is not arriving and nothing else in this article is working either.
• Check every count() in saved queries and alert rules. With sampling on, they should be sum(ItemCount).
• Find one background job and ask whether its logs share an OperationId with the request that queued it. If not, carry the trace id in the payload.