Filter concepts by levelShowing all levels.

Python · Section 20

Logging and Observability

Level
advanced
Read
130 min
Concepts
5

Replacing print("HERE") with real production diagnostics: logging levels/handlers/formatters, structured and JSON logging, correlation and request IDs with automatic stack-trace capture, metrics and distributed tracing (OpenTelemetry), and the health/readiness/liveness checks an orchestrator relies on.

Python overview
Learn Python - Full Course for Beginners [Tutorial]freeCodeCamp.org

What is true here

  1. A log record must clear both the logger's level and the handler's level — a formatter only changes how it looks, never whether it appears.
  2. Structured/JSON logs carry named fields a log aggregator can filter and query, instead of relying on full-text search.
  3. A correlation/request ID stamped on every log line for one request is what makes reconstructing that request's path possible.
  4. A child span's parent_id is literally its parent span's span_id — the shared value that stitches a distributed trace together.
  5. Liveness failing restarts the process; readiness failing only stops routing traffic — never let a dependency failure fail liveness.

What you will be able to do

  • Configure a logger, handler, and formatter, and explain why a record can be filtered by either gate independently
  • Write a custom JSON Formatter and attach per-record fields with extra=
  • Use logging.LoggerAdapter to stamp a correlation/request ID onto every log call for one request
  • Call logger.exception() correctly, only from inside an except block, to capture a real stack trace
  • Distinguish what logs, metrics, and distributed traces each answer, and start/nest spans with OpenTelemetry
  • Write separate liveness and readiness checks, and explain why a database check belongs only in readiness

Production diagnostics

Replacing print("HERE") with a real logging system — levels, handlers, formatters, and structured/JSON output a log aggregator can actually query.

Logging levels, handlers, and formatters

coreintermediate

The stdlib `logging` module replaces `print("HERE")` with a system that has a severity level, can route output to multiple destinations (handlers), and can format each destination differently — all without touching the calling code.

Think of it as

A logger is a newsroom desk, not a printer. A story (log record) is written once, then the desk decides where it goes: the wire (console handler), the morning edition (a file handler), or nowhere at all if it is too minor (filtered by level) — and each outlet can typeset the same story differently (its own formatter).

python
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler()
handler.setLevel(logging.WARNING)          # handler filters independently
handler.setFormatter(logging.Formatter('%(asctime)s %(levelname)s: %(message)s'))
logger.addHandler(handler)

What we're doing: Show that a record must clear BOTH the logger's level and the handler's level to actually appear — the two-gate filter this concept's mental model describes.

levels_and_handlers.pypython
import logging, io

logger = logging.getLogger('orders')
logger.setLevel(logging.DEBUG)             # gate 1: logger accepts DEBUG and up

buf = io.StringIO()
handler = logging.StreamHandler(buf)
handler.setLevel(logging.WARNING)          # gate 2: handler only emits WARNING and up
handler.setFormatter(logging.Formatter('%(levelname)s %(name)s: %(message)s'))
logger.addHandler(handler)

logger.debug('debug msg - filtered by handler')
logger.warning('low stock')
logger.error('payment failed')

print(buf.getvalue())
4
The logger itself accepts DEBUG and above — nothing is filtered here yet.
9
The handler is stricter: WARNING and above only, so the DEBUG record never reaches the output.
Output
WARNING orders: low stock
ERROR orders: payment failed

Why this works: The DEBUG call passes the logger's own level check but is then dropped by the handler's stricter WARNING level — a record needs to clear every gate in the chain, not just the logger's, to actually be written anywhere.

A record must clear every gate to be emitted

logger.debug(...)

gate 1: logger.setLevel(DEBUG) — passes

handler.setLevel(WARNING)

gate 2: DEBUG < WARNING — dropped here

Formatter

only shapes text — never filters what reaches it

Output

only WARNING and ERROR records actually appear

  1. logger.debug(...) — gate 1: logger.setLevel(DEBUG) — passes
  2. handler.setLevel(WARNING) — gate 2: DEBUG < WARNING — dropped here
  3. Formatter — only shapes text — never filters what reaches it
  4. Output — only WARNING and ERROR records actually appear

Calling logging.basicConfig() more than once and expecting it to reconfigure

Wrong

python
import logging
logging.basicConfig(level=logging.INFO)
# ... later, in another module ...
logging.basicConfig(level=logging.DEBUG)   # silently does nothing

Better

python
import logging
# call basicConfig exactly once, at the application's entry point
logging.basicConfig(level=logging.DEBUG, force=True)  # force=True replaces existing config

What you see: DEBUG messages still do not appear after the second basicConfig() call — no error, no warning, just silence.

Why: basicConfig() is a no-op if the root logger already has handlers configured (from an earlier basicConfig() call, or a library that added one) — it is designed to configure logging ONCE. Pass force=True to intentionally replace an existing configuration.

The five standard levels

The five standard levels
LevelValueUse for
DEBUG10Detailed diagnostic info, off in production
INFO20Confirmation things are working as expected
WARNING30Something unexpected, but the program continues
ERROR40A specific operation failed
CRITICAL50The whole program may be about to stop working

Remember: A record needs to clear the logger's level AND the handler's level — a formatter only changes how it looks, never whether it appears.

See also: structured and json logging · logging exceptions

Structured and JSON logging

coreintermediate

Structured logging emits each record as a machine-parseable object (usually JSON) with named fields instead of a free-text sentence, so a log aggregator can filter, group, and alert on a specific field instead of grepping strings.

Think of it as

A free-text log line is a sentence you have to re-read to extract facts from; a structured log line is a filled-in form — the same facts, but already sorted into named boxes a machine can index without guessing at your sentence structure.

python
import logging, json

class JsonFormatter(logging.Formatter):
    def format(self, record):
        payload = {
            'level': record.levelname,
            'logger': record.name,
            'message': record.getMessage(),
            'request_id': getattr(record, 'request_id', None),
        }
        return json.dumps(payload)

What we're doing: Attach a custom request_id field via extra= and confirm the emitted line is real, parseable JSON with that field present.

json_logging.pypython
import logging, io, json

class JsonFormatter(logging.Formatter):
    def format(self, record):
        return json.dumps({
            'level': record.levelname,
            'logger': record.name,
            'message': record.getMessage(),
            'request_id': getattr(record, 'request_id', None),
        })

buf = io.StringIO()
handler = logging.StreamHandler(buf)
handler.setFormatter(JsonFormatter())
logger = logging.getLogger('api')
logger.setLevel(logging.INFO)
logger.addHandler(handler)

logger.info('order created', extra={'request_id': 'req-abc123'})

line = buf.getvalue().strip()
print(line)
print('parsed keys:', sorted(json.loads(line).keys()))
4
format() is overridden to return a JSON string instead of a text template — every other logging mechanic (levels, handlers) still works unchanged.
17
extra= injects request_id onto this one record; getattr(record, "request_id", None) reads it back safely even for calls that omit it.
Output
{"level": "INFO", "logger": "api", "message": "order created", "request_id": "req-abc123"}
parsed keys: ['level', 'logger', 'message', 'request_id']

Why this works: The output is real, valid JSON — json.loads() on the emitted line succeeds and returns exactly the four named fields, proving the log line is machine-parseable rather than a free-text sentence formatted to merely look like one.

A structured log line, field by field

{"level": "INFO", "logger": "api", "message": "order created", "request_id": "req-abc123"}

"level": "INFO"

record.levelname — queryable severity, not just a text prefix

"logger": "api"

record.name — which logger emitted this record

"message": "order created"

record.getMessage() — the human-readable text, still present

"request_id": "req-abc123"

extra={...} — a custom field injected on this one call

  • Whole: {"level": "INFO", "logger": "api", "message": "order created", "request_id": "req-abc123"}
  • "level": "INFO" — record.levelname: queryable severity, not just a text prefix
  • "logger": "api" — record.name: which logger emitted this record
  • "message": "order created" — record.getMessage(): the human-readable text, still present
  • "request_id": "req-abc123" — extra={...}: a custom field injected on this one call

Using extra= with a key that collides with a built-in LogRecord attribute

Wrong

python
logger.info('done', extra={'message': 'duplicate key'})
# KeyError: "Attempt to overwrite 'message' in LogRecord"

Better

python
# prefix custom fields, or pick names that do not collide with
# LogRecord's own attributes (message, args, levelname, name, ...)
logger.info('done', extra={'ctx_message': 'safe custom field'})

What you see: A KeyError is raised at log time, inside the logging call itself — not at some later point when the log is read.

Why: extra='s dict keys are set directly as attributes on the LogRecord object — a key that matches one of LogRecord's own reserved attribute names (message, args, levelname, and others) collides and raises immediately, so custom field names need to avoid that reserved set.

Remember: A structured/JSON log line is a filled-in form with named fields, queryable by field — not a text sentence formatted to look like one.

See also: logging levels and handlers · correlation and request ids

Advertisement

Observability at scale

The roadmap's own closing goal: reconstructing what happened to one request across a distributed system — correlation IDs, metrics, distributed tracing, and the health checks an orchestrator relies on.

Correlation IDs, request IDs, and stack traces

coreintermediate

A correlation ID (often a request ID) is one value attached to every log line produced while handling a single request, so every line touched by that request can be grepped as one group — across log statements, and across services if the ID is forwarded.

Think of it as

A correlation ID is a claim-check ticket stapled to a request the moment it arrives. Every service that touches the request re-attaches the same ticket number to its own log lines — so reconstructing what happened to one request means filtering for one ticket number, not reading everything in time order.

python
import logging, uuid

class RequestIdAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return f"[{self.extra['request_id']}] {msg}", kwargs

logger = logging.getLogger(__name__)
request_logger = RequestIdAdapter(logger, {'request_id': str(uuid.uuid4())[:8]})
request_logger.info('handling request')   # every call carries the same ID

What we're doing: Show a LoggerAdapter stamping the same request ID onto every log call for one request, and logger.exception() capturing a real traceback automatically.

correlation_and_traces.pypython
import logging, io, uuid

class RequestIdAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return f'[{self.extra["request_id"]}] {msg}', kwargs

buf = io.StringIO()
handler = logging.StreamHandler(buf)
handler.setFormatter(logging.Formatter('%(message)s'))
base_logger = logging.getLogger('svc')
base_logger.setLevel(logging.INFO)
base_logger.addHandler(handler)

request_logger = RequestIdAdapter(base_logger, {'request_id': str(uuid.uuid4())[:8]})
request_logger.info('validating input')
request_logger.info('charging card')

err_logger = logging.getLogger('errs')
err_logger.addHandler(handler)
try:
    1 / 0
except ZeroDivisionError:
    err_logger.exception('charge failed')

for line in buf.getvalue().splitlines():
    print(line)
12
Both calls through request_logger carry the same request_id — that ID is what groups these two lines as "the same request" later.
20
logger.exception() must be called from inside an except block — it automatically attaches the full traceback, no manual formatting needed.
Output
[<uuid>] validating input
[<uuid>] charging card
charge failed
Traceback (most recent call last):
  ...
ZeroDivisionError: division by zero

Why this works: The two info() calls both carry the same bracketed request ID because they went through the same adapter instance — filtering the aggregated log for that one ID reconstructs exactly this request's path. logger.exception() separately proves it captures a real traceback automatically, without any manual sys.exc_info() formatting.

The same request_id stamped on every log line
request
RequestIdAdapter
log output
  1. 1. request_id = uuid4()[:8]generated once, at request start
  2. 2. [a1b2c3d4] validating input
  3. 3. [a1b2c3d4] charging card
  4. 4. [a1b2c3d4] charge failedlogger.exception() attaches the traceback too
  1. request → RequestIdAdapter: request_id = uuid4()[:8] (generated once, at request start)
  2. RequestIdAdapter → log output: [a1b2c3d4] validating input
  3. RequestIdAdapter → log output: [a1b2c3d4] charging card
  4. RequestIdAdapter → log output: [a1b2c3d4] charge failed (logger.exception() attaches the traceback too)

Calling logger.exception() outside an except block

Wrong

python
def check_status():
    logger.exception('checking status')   # no active exception here
# logs "NoneType: None" as the traceback -- misleading, not an error

Better

python
def check_status():
    logger.info('checking status')        # no exception in flight, use info/warning
try:
    risky_operation()
except Exception:
    logger.exception('risky_operation failed')  # correct: inside except

What you see: The log line appears with an ERROR level and a traceback body of "NoneType: None" instead of a real stack trace — easy to mistake for a broken logging setup rather than a misused call.

Why: logger.exception() calls sys.exc_info() internally to grab the currently-handled exception — outside an except block there is no active exception, so it silently logs a placeholder instead of raising an error to flag the misuse.

Remember: Stamp one correlation/request ID onto every log line for a request (LoggerAdapter), and only call logger.exception() from inside an except block.

See also: structured and json logging · logging exceptions

Metrics and distributed tracing

standardintermediate

Logs answer "what happened on this one request"; metrics answer "how is the whole system doing over time" (a number that goes up or down); distributed tracing answers "which service in the chain was slow" by linking spans across service boundaries with the same trace ID.

Think of it as

Logs are a diary entry — a Counter/Histogram is a dashboard needle — a distributed trace is a relay race baton, physically passed from one runner (service) to the next, so the baton itself proves which leg was slow instead of comparing five separate diaries by hand.

python
from opentelemetry import trace

tracer = trace.get_tracer(__name__)

with tracer.start_as_current_span('handle-request') as span:
    span.set_attribute('http.method', 'GET')
    with tracer.start_as_current_span('query-database'):
        ...   # this span is automatically nested under handle-request

What we're doing: Prove a child span is really linked to its parent — the child's parent_id and the parent's span_id must be the exact same value, run for real with the OpenTelemetry SDK.

nested_spans.pypython
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor, ConsoleSpanExporter

provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(ConsoleSpanExporter()))
trace.set_tracer_provider(provider)

tracer = trace.get_tracer(__name__)
with tracer.start_as_current_span('handle-request') as parent:
    parent.set_attribute('http.method', 'GET')
    with tracer.start_as_current_span('query-database') as child:
        pass

print('parent span_id: ', format(parent.get_span_context().span_id, 'x'))
print('child parent_id:', format(child.parent.span_id, 'x'))
9
start_as_current_span makes this the ACTIVE span — any span started while it is active is automatically nested under it.
11
query-database is started while handle-request is still active, so it becomes a child span of it, not a sibling.
Output
parent span_id:  5182e46831b95884
child parent_id: 5182e46831b95884

Why this works: The two printed hex values are identical — real proof the child span's parent_id field is not just conceptually "the parent," it is literally the same span_id the parent was assigned, the exact mechanism a tracing backend uses to rebuild the full call tree from independently-reported spans.

Starting a span without making it the "current" span

Wrong

python
span = tracer.start_span('query-database')   # created, but never made active
with tracer.start_as_current_span('handle-request'):
    do_work()   # any span started here does NOT nest under query-database
span.end()

Better

python
with tracer.start_as_current_span('handle-request'):
    with tracer.start_as_current_span('query-database'):
        do_work()   # correctly nests under handle-request

What you see: Spans that should visually nest in a trace viewer instead appear as unrelated, disconnected traces — no error, just a flat/wrong trace tree.

Why: start_span() creates a span but does not set it as the active context — only start_as_current_span() (or manually attaching the context) makes subsequent spans nest under it, so mixing the two APIs silently breaks the parent/child chain.

Observability signal comparison

Observability signal comparison
SignalAnswersExample
LogsWhat happened, in detail, for one event"Payment failed: card declined"
MetricsHow is the system trending, in aggregaterequests_total, p99 latency
TracesWhere did time actually go, across servicesAPI gateway → auth → database, 4 spans

Remember: Logs = one event in detail; metrics = a trend over time; traces = a shared ID stitching spans across services into one request's real path.

See also: correlation and request ids · health readiness and liveness checks

Health, readiness, and liveness checks

coreintermediate

A liveness check answers "is this process still running correctly, or should it be restarted"; a readiness check answers "can this instance accept traffic right now" — the same service can be alive but not ready (still loading, or a dependency is down).

Think of it as

Liveness is a pulse check — is the patient's heart beating at all. Readiness is asking if the patient can actually walk out and see visitors right now — alive is necessary but not sufficient for that. An orchestrator restarts on a failed pulse check, and simply stops sending visitors (traffic) on a failed readiness check, no restart needed.

python
def liveness() -> dict:
    return {'status': 'ok'}          # cheap, no external dependency checks

def readiness(db_ok: bool, cache_ok: bool) -> tuple[dict, int]:
    ready = db_ok and cache_ok
    body = {'status': 'ok' if ready else 'unavailable', 'checks': {'db': db_ok, 'cache': cache_ok}}
    return body, 200 if ready else 503

What we're doing: Show readiness correctly reporting unavailable (with a 503) the moment one dependency fails, while liveness stays independent of that dependency entirely.

health_checks.pypython
def liveness() -> dict:
    return {'status': 'ok'}

def readiness(db_ok: bool, cache_ok: bool) -> tuple[dict, int]:
    ready = db_ok and cache_ok
    body = {'status': 'ok' if ready else 'unavailable', 'checks': {'db': db_ok, 'cache': cache_ok}}
    return body, 200 if ready else 503

print('liveness:', liveness())
print('readiness (all ok):    ', readiness(True, True))
print('readiness (cache down):', readiness(True, False))
1
liveness() takes no dependency arguments at all — a broken cache should never fail a liveness check.
5
readiness() is unavailable the moment ANY dependency is down, with a 503 an orchestrator recognizes as "stop sending traffic here".
Output
liveness: {'status': 'ok'}
readiness (all ok):     ({'status': 'ok', 'checks': {'db': True, 'cache': True}}, 200)
readiness (cache down): ({'status': 'unavailable', 'checks': {'db': True, 'cache': False}}, 503)

Why this works: liveness() returns the same {"status": "ok"} regardless of cache_ok because it never receives that argument — the process itself is fine even though a dependency failed. readiness() correctly flips to unavailable/503 the instant cache_ok is False, which is exactly the signal that should pull traffic away without restarting anything.

Liveness vs. readiness — different question, different response

Liveness

  • +Is the process itself stuck or broken?
  • +Cheap — no external dependency checks
  • +On failure: orchestrator RESTARTS the instance

Readiness

  • −Can this instance serve a request right now?
  • −Checks real dependencies — db, cache
  • −On failure: orchestrator stops routing traffic, no restart
  • Liveness
    • Is the process itself stuck or broken?
    • Cheap — no external dependency checks
    • On failure: orchestrator RESTARTS the instance
  • Readiness
    • Can this instance serve a request right now?
    • Checks real dependencies — db, cache
    • On failure: orchestrator stops routing traffic, no restart

Making the liveness check ping a downstream dependency (like the database)

Wrong

python
def liveness() -> dict:
    db.ping()   # if the database is briefly down, this raises
    return {'status': 'ok'}
# database blip -> liveness fails -> orchestrator restarts a perfectly healthy process

Better

python
def liveness() -> dict:
    return {'status': 'ok'}          # process-level only, no external calls

def readiness() -> dict:
    db.ping()                        # dependency checks belong here instead
    return {'status': 'ok'}

What you see: A restart storm during an unrelated database blip — every instance restarts simultaneously even though none of them were actually broken, often making the outage worse (a thundering-herd reconnect on recovery).

Why: A liveness probe failing tells the orchestrator "kill and restart this process" — but a dependency being briefly unreachable is not a reason to kill the process itself. Dependency checks belong in readiness, where the correct response (stop routing traffic, no restart) actually matches the problem.

Liveness vs. readiness

Liveness vs. readiness
CheckQuestionOn failure
LivenessIs the process itself stuck or broken?Orchestrator RESTARTS the instance
ReadinessCan this instance serve a request right now?Orchestrator STOPS routing traffic, no restart

Remember: Liveness failing restarts the process; readiness failing only stops traffic — never let a downstream dependency fail your liveness check.

See also: metrics and distributed tracing

Advertisement