Skip to content

Observability

Three questions a running application has to be able to answer: what happened, to which request, and what does this process contain. The first two are logging, the third is diagnostics, and the runtime's position on both is deliberately narrow.

What the runtime configures: nothing

examples/learn_production/observability01_logging.py
"""Walkthrough — logging: the application owns the configuration, the framework owns the names.

Run it with:

    python -m learn_production.observability01_logging
"""

from __future__ import annotations

import logging
from io import StringIO

from xyberos import App
from xyberos.errors import HttpError
from xyberos.http import HttpAdapter
from xyberos.http.testing import create_test_client
from xyberos.runtime.context import ContextLogFilter

#: The header the adapter echoes, and the ID this walkthrough sends so the transcript is stable.
REQUEST_ID_HEADER = "X-Request-ID"
REQUEST_ID = "req-1"

#: What the application's own reference to a log record looks like: its namespace, then its view.
FORMAT = "%(levelname)s %(name)s %(message)s %(xyberos_context)s"


class OrderGone(HttpError):
    """A client mistake the application reports about, which the adapter logs on its way out."""

    def __init__(self, order_id: int) -> None:
        super().__init__(f"order {order_id} is gone", status_code=410)


def build_app() -> App:
    """Compose a two-route application: one that logs, and one that fails in a reportable way."""
    app = App()
    app.get("/orders/{order_id}")(read_order)
    app.get("/orders/{order_id}/cancel")(cancel_order)
    return app


async def read_order(order_id: int) -> dict[str, object]:
    """Log at the application's own logger, which is the only place a business event belongs."""
    logging.getLogger("orders.api").info("looked up order %s", order_id)
    return {"order": order_id}


async def cancel_order(order_id: int) -> dict[str, object]:
    """Fail in a way the adapter maps to a response, and logs on the way out."""
    raise OrderGone(order_id)


def main() -> None:
    """Serve the application with its own logging configuration, and read the records."""
    stream = StringIO()
    handler = logging.StreamHandler(stream)
    handler.setFormatter(logging.Formatter(FORMAT))
    # The filter is what puts the current context on every record: without it a log line cannot say
    # which request it belongs to, and with it the correlation ID arrives from the adapter.
    handler.addFilter(ContextLogFilter())

    framework = logging.getLogger("xyberos")
    print("handlers the framework configured:", framework.handlers)

    # Configure the root logger, not `xyberos`: that catches the application's own lines
    # (`orders.api`) as well as the framework's (`xyberos.http`).
    root = logging.getLogger()
    previous_level = root.level
    # The test client is not part of a deployment, and its request lines are not the application's.
    noisy = logging.getLogger("httpx")
    noisy_level = noisy.level
    noisy.setLevel(logging.WARNING)
    root.addHandler(handler)
    root.setLevel(logging.INFO)
    try:
        app = build_app()
        with create_test_client(HttpAdapter(app)) as client:
            path = "/orders/7"
            print(
                "GET", path, "->", client.get(path, headers={REQUEST_ID_HEADER: REQUEST_ID}).json()
            )
            gone = client.get("/orders/9/cancel", headers={REQUEST_ID_HEADER: REQUEST_ID})
            print("GET /orders/9/cancel ->", gone.status_code, gone.json())
            print("echoed header:", gone.headers[REQUEST_ID_HEADER])
    finally:
        root.removeHandler(handler)
        root.setLevel(previous_level)
        noisy.setLevel(noisy_level)

    print("--- records the application's handler saw ---")
    for line in stream.getvalue().splitlines():
        print(line)


if __name__ == "__main__":
    main()

The first line that module prints is the whole policy:

handlers the framework configured: []
GET /orders/7 -> {'order': 7}
GET /orders/9/cancel -> 410 {'error': {'type': 'OrderGone', 'message': 'order 9 is gone'}}
echoed header: req-1
--- records the application's handler saw ---
INFO orders.api looked up order 7 {'correlation_id': 'req-1'}
INFO xyberos.http request failed with OrderGone: order 9 is gone {'correlation_id': 'req-1'}

handlers the framework configured: [] is a promise, not an omission: the runtime never installs a handler, sets a level, or picks a format. A library that configures logging fights the application that embeds it, and the fight is invisible until two of them disagree. So the module configures the root logger itself, and the records it collects are the two kinds a real deployment has to distinguish:

Record Namespace Who writes it
INFO orders.api looked up order 7 the application's own the handler, in the application's logger
INFO xyberos.http request failed with OrderGone: order 9 is gone the framework's the error-mapping middleware

Both carry {'correlation_id': 'req-1'} because both went through a handler with a ContextLogFilter attached — that is the filter doing the only job the runtime asks of the application: ContextLogFilter copies the current diagnostic context onto each record, so the sink configuration decides what happens to it, not the framework.

The namespaces, and why they are namespaces

Logger What appears in it
xyberos.http request failures as mapped, and unhandled errors with their traceback at the level the handler uses
xyberos.plugins plugin registration, start, and stop, attributed to the plugin by name
xyberos.workflow workflow validation and execution outcomes
xyberos.ai provider calls and their failures, without prompt or completion bodies
xyberos.durable lease, recovery, and parked-attempt decisions

Naming one of them, or all of them with logging.getLogger("xyberos"), is a choice you make; nothing is configured for you, so xyberos.ai at DEBUG in one environment and WARNING in another is a deployment decision rather than a code change.

The request pipeline, in order

The adapter builds the middleware stack once, and the order is the design:

  1. correlation id — reads the incoming header (default X-Request-ID), or mints one, and binds it to the context before anything else can log.
  2. error mapping — turns a raised HttpError into its status and body, and everything else into a generic 500, logging both.
  3. request scope — opens the request's dependency and cleanup boundary. Everything resolved for this request is created inside it and released when it ends.
  4. your middleware — the list you passed to HttpAdapter(..., middleware=[...]).
  5. the router — the compiled routes.

echoed header: req-1 in the transcript is step 1 from the outside: the id the client sent comes back on the response, which is what makes a client-side trace and a server-side log line the same trace. A proxy that generates the header itself should strip what the client sent, which is the same rule the identity lesson applies to assertion headers.

The context a log line survives

A correlation id is only useful if it is still there when the work has moved to another task or thread. The honest answer has two halves, and both are measured:

examples/learn_production/observability02_context.py
"""Walkthrough — the diagnostic context, and where it is carried rather than lost.

Run it with:

    python -m learn_production.observability02_context
"""

from __future__ import annotations

import asyncio
import threading
import time

from xyberos.runtime.context import (
    bind_context,
    bind_correlation_id,
    bind_deadline,
    capture_context_runner,
    create_task_in_context,
    get_context,
    get_deadline,
)


def observe(label: str) -> None:
    """Report the context this caller can see, from wherever it is called."""
    print(f"{label}:", get_context())


async def observe_async(label: str) -> None:
    """Report the context from inside a task."""
    observe(label)


async def main() -> None:
    """Bind a request context, then send work across each boundary and report what arrived."""
    print("before anything is bound:", get_context())

    with bind_correlation_id("req-7"), bind_context(tenant="acme"):
        observe("inside the request")

        # Tasks and `to_thread` carry the context already: both copy it. The helpers exist for the
        # boundaries that do not, not for these.
        await asyncio.create_task(observe_async("a task"))  # noqa: RUF006
        await create_task_in_context(observe_async("create_task_in_context"))
        await asyncio.to_thread(observe, "asyncio.to_thread")

        # A bare executor call does not: the executor's threads start from an empty context. This is
        # the boundary a blocking library call or a background worker is usually written with.
        loop = asyncio.get_running_loop()
        await loop.run_in_executor(None, observe, "run_in_executor, uncarried")
        runner = capture_context_runner(observe, "capture_context_runner, in that executor")
        await loop.run_in_executor(None, runner)

        # A thread started by hand is the same boundary, and the helper crosses it the same way.
        borrowed: list[dict[str, object]] = []
        plain = threading.Thread(target=lambda: borrowed.append(get_context()))
        carried = threading.Thread(target=capture_context_runner(borrowed.append, get_context()))
        for thread in (plain, carried):
            thread.start()
            thread.join()
        print("hand-started threads saw:", borrowed)

        with bind_deadline(time.monotonic() + 30):
            print("a deadline is bound:", get_deadline() is not None)
        print("and the deadline afterwards:", get_deadline())

    print("after the block:", get_context())


if __name__ == "__main__":
    asyncio.run(main())

before anything is bound: {}
inside the request: {'correlation_id': 'req-7', 'tenant': 'acme'}
a task: {'correlation_id': 'req-7', 'tenant': 'acme'}
create_task_in_context: {'correlation_id': 'req-7', 'tenant': 'acme'}
asyncio.to_thread: {'correlation_id': 'req-7', 'tenant': 'acme'}
run_in_executor, uncarried: {}
capture_context_runner, in that executor: {'correlation_id': 'req-7', 'tenant': 'acme'}
hand-started threads saw: [{}, {'correlation_id': 'req-7', 'tenant': 'acme'}]
a deadline is bound: True
and the deadline afterwards: None
after the block: {}

Read that as three rows of a table rather than a list of prints:

Boundary Does the context arrive? Why
asyncio.create_task yes Python 3.11+ copies the context into a new task. On 3.10 it does not, which is why create_task_in_context exists and is used explicitly above
asyncio.to_thread yes it copies the context into the worker thread itself
loop.run_in_executor, a hand-started threading.Thread no the executor's threads start from an empty context and the call does not wrap the function

The last row is the boundary that actually loses work's identity, and capture_context_runner(func, *args) is the answer: called in the originating context it returns a runner bound to a copy of that context, so a blocking library call or a worker thread keeps the request's id and its deadline. Note the deadline in the transcript — bind_deadline is scoped, so it is present inside the block and None immediately after; a context that leaked would be worse than one that is lost, because the next request would inherit it.

Asking a process what it contains

app.diagnostics() is the third question, and it answers with sources rather than values:

examples/learn_production/observability03_diagnostics.py
"""Walkthrough — what a running application can be asked about itself, and when the answer changes.

Run it with:

    python -m learn_production.observability03_diagnostics
"""

from __future__ import annotations

import asyncio
from typing import Annotated

from xyberos import App, Inject, Scope
from xyberos.errors import LifecycleStateError


class Prices:
    """An app-scoped capability: built once, shared, and closed by the application."""

    @property
    def source(self) -> str:
        return "a price table the application loaded"


class Quote:
    """A service that depends on it, so the graph has an edge to show."""

    def __init__(self, prices: Annotated[Prices, Inject()]) -> None:
        self._prices = prices


def main() -> None:
    """Print the state and the graph before, during, and after the application's lifetime."""
    app = App()
    app.provide(Prices)
    app.provide(Quote, source="the pricing module")
    app.provide(Prices, replace=True, source="a deployment override")

    print("state before start:", app.state.value)
    print(app.diagnostics().render().strip())

    asyncio.run(scenario(app))


async def scenario(app: App) -> None:
    """Resolve the graph while the application is up, and report what its records say."""
    async with app.lifespan():
        print("state while serving:", app.state.value)
        resolved = await app.resolve(Quote)
        print("the service resolved:", type(resolved).__name__)
        records = app.diagnostics().providers
        print("records:", ", ".join(f"{info.contract} ({info.scope})" for info in records))
        print("request scope exists too:", Scope.REQUEST.value)

    print("state after stop:", app.state.value)
    try:
        await app.start()
    except LifecycleStateError as error:
        print("starting it again:", type(error).__name__, "-", error)


if __name__ == "__main__":
    main()

state before start: new
providers:
  Prices [app] from a deployment override
  Quote [app] from the pricing module
plugins:
  (none)
state while serving: ready
the service resolved: Quote
records: Prices (app), Quote (app)
request scope exists too: request
state after stop: stopped
starting it again: LifecycleStateError - cannot start an application in 'stopped' state

The interesting line is the first provider: Prices [app] from a deployment override. The module registers Prices twice — once as itself, then again with replace=True and a source — and the record names the later registration, which is exactly the question an operator asks when a value is not what they deployed. Sources are filled in as application, a test override, plugin:<name>, or whatever string a module passes, and xyberos check prints the same field (deploying it shows the report).

plugins: (none) is not a failure: a plugin declares its own metadata, and this application has none. A plugin's line reads audit 1 [registered] requires: -, so a diagnosis includes what was loaded and in what order.

What to hook up

Signal Where it comes from What to do with it
one id per request the adapter's correlation middleware log it on every line (ContextLogFilter), return it (X-Request-ID), and let the proxy strip what the client sent
request outcomes xyberos.http records alert on the rate of unhandled error while serving a request, not on one line
errors a client sees the error body's type the type is stable and public; the message is the mapped one, and internal detail is not in it (security)
readiness your /health route a load balancer wants the database, not the event loop (deploying it)
what is registered app.diagnostics() log it once at startup, so a diff between two deployments is a text comparison
cost and outcome per unit of work your own usage rows the hybrid path's usage lesson builds the table; the framework does not

Common mistakes

  • Configuring the xyberos logger and nothing else. An application's own lines and the framework's live under different names; the root logger is the one that catches both.
  • Attaching the context filter to the formatter instead of the handler. The filter belongs on the handler; a formatter receives only what it was given.
  • Assuming a task inherits the context without checking the Python version. On 3.10 you need create_task_in_context.
  • Losing the id at an executor boundary and reconstructing it from timestamps later. The transcript above is that failure mode, in one line: run_in_executor, uncarried: {}.
  • Logging prompt or completion bodies to make a model call debuggable. The AI namespace logs calls and failures, not payloads; whatever you add is yours to redact (the AI security lesson).