Wymcp.Telemetry.Logger (Wymcp v0.7.1)

View Source

Renders wymcp's telemetry events as structured Logger lines under one policy — attached at boot by default, off with config :wymcp, logger: false.

The library emits, this handler renders, the consuming application chooses. Wymcp.Telemetry owns the events and their metadata; this module owns nothing but the lines, so a consumer wanting different levels, keys or destinations attaches a handler of its own against the same events and turns this one off — that is what telemetry is for, and it is why there is no level knob here.

Nothing connects this to MCP's own logging capability. logging/setLevel sets a per-session threshold on the notifications/message push, which Wymcp.Session owns; this module renders wymcp's telemetry to the BEAM Logger. Neither reads the other, and the two level vocabularies are unrelated. The logging/setLevel threshold is legacy-only: MCP logging exists only on the legacy lane, and it goes at the legacy decommission. This module is unaffected — it renders telemetry, not MCP log messages.

Configuration

config :wymcp, logger: false stops Wymcp.Application attaching the handler at boot; the default is true. The key is read exactly once, at boot, through enabled?/0. attach/0 and detach/0 ignore it — a test that detaches can re-attach without consulting configuration, and the boot read stays the one place the key is consulted.

Turning it off means turning off every line below, including the fault lines: a tool that faults is contained and answered as an isError result, so with no handler attached nothing about that fault reaches the adapter and no line exists. That is the consumer's choice to make, and it is why the default is on.

Line policy

One sentence: a client-triggerable fact renders at :info, a consumer-code or wymcp fault at :error, and nothing renders at :warning.

A public MCP endpoint's rejections are attacker-triggerable volume, so a :warning per bad request is a flood the attacker chooses the size of. Nothing a client can provoke is therefore louder than :info. A start event renders no line; one call renders one line, plus a fault line where consumer code broke — an auth module that raises renders both wymcp.auth.error and the rejection's own line, because the two say different things and the fault is the consumer's to fix; and no line ever carries a session id — it is bearer-equivalent, and the facts that matter are on the line already.

Client- and consumer-controlled values are bounded on render by bounded/1, which replaces control characters as well as cutting length — a client able to put a newline on a line is a client able to forge one. The events themselves carry the raw values, because a consumer's own handler shapes its own line.

The message string is the dotted event name — wymcp.wire.reject — so one grep handle works in every formatter, and the facts are metadata. There is no event metadata key: that name is common in application line vocabularies and a collision is the consumer's to resolve, not wymcp's to cause.

Line table

A ★ marks a value bounded by bounded/1 on render — cut to 256 bytes, with control characters replaced; an atom, the consumer's own, passes as written.

eventlevelline keys
wire.reject:inforejecter, reason, status, http_method, method★, message_id★, message★, era when present
session.start:infoclient_name★, client_version★, era
session.expired:infoera
tool.startnot rendered
tool.stop:infotool_name★, action★, is_error, error_kind, result_type, duration_ms, era
tool.error:errortool_name★, action★, message_id★, exception, error★, duration_ms, era, crash_reason
help.callednot rendered
auth.error:errorauth_module, exception, error★, http_method, method★, message_id★, crash_reason
server.reject:infoserver, reason★, message_id★, era
server.error:errorserver, exception, error★, message_id★, era, crash_reason

The session.start, session.expired, server.reject and server.error rows are legacy-only: each renders an event only the legacy lane emits. The two session rows go at the legacy decommission; for the two server rows, whether a modern-lane replacement is owed is the legacy decommission's to decide, and until then both are fully supported.

This table is the metadata allowlist a consuming application copies into its own Logger :metadata config. wymcp ships no allowlist of its own: that config belongs to the application.

tool.start renders nothing because it carries nothing tool.stop lacks — the same tool, action and era, without the outcome — so a start line would be a second line per call saying less. Start events serve the metrics and tracing consumers, who read the event. The one case a start line alone would trace, a tool that never returns, is accepted.

help.called renders nothing because a help call is a tool call and already renders as tool.stop with tool_name: "help" and the target action, error answers included. What help.called adds — the target tool, the answer level — is product signal rather than an operator's line, and rendering it beside tool.stop would break one line per call.

Totality

:telemetry detaches a handler that raises, from every event it was attached to, and logs one error; after that every line is silently gone. So every clause here reads its metadata with Map.get/3 and matches no key in a head, and a value of an unexpected shape is rendered rather than matched. crash_reason is forwarded verbatim and never inspected.

bounded/1 holds the same property for the values themselves: it calls no grapheme function, nothing it does raises on any byte sequence, and its work is bounded by the constant it cuts to, never by the input — except for a consumer's own term that inspect/2 walks or copies before its limit applies (a struct with an Inspect implementation of its own, a keyword list, a tuple), which a client's body cannot carry. It runs on the request process, before authentication on a rejection, so a value whose cost grew with its size would be a cost the sender chose.

Summary

Functions

Attaches the handler to every event it renders, unconditionally.

A value made safe to put on a log line: a string cut to 256 bytes with a codepoint repair and its control characters replaced; an integer of up to 256 digits as it is, a larger one as <integer of more than 256 digits>; any other term inspected through a visitor that applies the same integer rule at any depth and never lists a wide map whole, then cut like a string. Total on every byte sequence, and its work bounded by the constant, never by the input — except for a consumer's own term that inspect/2 walks or copies before its limit applies: a struct with an Inspect implementation of its own above all, a keyword list, a tuple — none of which a JSON body decodes to.

Detaches the handler. Idempotent: detaching when nothing is attached answers :ok.

Whether the handler is attached at boot — the config :wymcp, logger: … key, default true.

Functions

attach()

Attaches the handler to every event it renders, unconditionally.

Idempotent: a second call is a no-op, so a test that detached in setup can re-attach on exit without coordinating with boot.

bounded(value)

A value made safe to put on a log line: a string cut to 256 bytes with a codepoint repair and its control characters replaced; an integer of up to 256 digits as it is, a larger one as <integer of more than 256 digits>; any other term inspected through a visitor that applies the same integer rule at any depth and never lists a wide map whole, then cut like a string. Total on every byte sequence, and its work bounded by the constant, never by the input — except for a consumer's own term that inspect/2 walks or copies before its limit applies: a struct with an Inspect implementation of its own above all, a keyword list, a tuple — none of which a JSON body decodes to.

256 is read in the value's own unit: bytes for a string and for a rendering, digits for an integer, and codepoints for a string inside an inspected term, which inspect/2's :printable_limit counts before the rendering is cut.

The cut is String.byte_slice/3, never a grapheme function such as String.slice/3, for two reasons. A grapheme cut walks to the end of the cluster it stops in, and one cluster can be the whole value: a letter followed by a megabyte of combining marks is walked whole and returned whole. And on OTP 28.4, String.slice/3 and String.length/1 raise on a zero-width joiner followed by a byte no UTF-8 sequence admits — a header value reaches this function as the client sent it, and a raising handler is detached from every event. String.byte_slice/3 cuts the bytes and drops a malformed sequence at either end of what it keeps — the bytes of a codepoint split there, and at the tail a whole codepoint followed by stray continuation bytes — so a cluster cut at the bound renders as its parts, and a header value that opens or ends partway through a codepoint renders without those bytes. It finds continuation bytes at the front by scanning them, so it is handed the first 256 bytes and no more: a value opening on 256 or more continuation bytes renders as the empty string, and one opening on a megabyte of them costs what 256 do.

An integer is compared by magnitude and never rendered, because rendering one costs time quadratic in its digits; the placeholder is fixed text, since a digit count would cost the render it avoids. Inside a term the visitor replaces such an integer wherever inspect/2 meets it — a list or tuple element, a map key or value, a struct field — and cuts a map wider than inspect's limit before inspect would list it whole. That limit is a budget over the whole term, so a term's depth and breadth past it cost nothing. A list renders as a list, never as a charlist: left to infer, inspect/2 reads a list opening on printable integers as text and converts it whole, outside the visitor and its limit, raising on the first element that is no codepoint. A struct with an Inspect implementation of its own renders as that implementation makes it — MapSet lists every member, and one that formats an integer itself renders every digit — and one that raises reads #Inspect.Error<…>, which renders the struct again with inspect's defaults. Inspect also walks a keyword list whole to tell it from a plain list, and copies a tuple to a list, before its limit applies. Such terms reach this function only from a consumer's own code, as a server.reject reason; a JSON body decodes to no struct, tuple or keyword list.

A float, boolean or nil passes through — none can be long or carry a control character — and so does any other atom, which is the consumer's own: no client value decodes to one beyond those three, and a consumer that writes a control character into a reason atom writes it onto its own line.

The replacement is what stops a client forging log lines. A JSON-RPC string may decode to an embedded newline, and several of the values bounded here come straight out of the client's body or headers, so rendering one raw would let a client write a whole line of its own into the operator's stream — including a line that looks like one of wymcp's. The scrub runs after the cut and replaces byte for byte, so it keeps the bound. It is byte-wise rather than a regex because a header value need not be valid UTF-8 and a ~r/.../u match raises on the bytes that are not. A rendering is scrubbed too: inspect/2 escapes a control character inside any string it renders, but a struct's own Inspect implementation can emit one raw.

Examples

iex> Wymcp.Telemetry.Logger.bounded("tools/call")
"tools/call"

iex> Wymcp.Telemetry.Logger.bounded("id\n[error] forged line")
"id [error] forged line"

iex> Wymcp.Telemetry.Logger.bounded(:invalid_token)
:invalid_token

iex> Wymcp.Telemetry.Logger.bounded(42)
42

iex> Wymcp.Telemetry.Logger.bounded(Integer.pow(10, 256))
"<integer of more than 256 digits>"

iex> Wymcp.Telemetry.Logger.bounded(nil)
nil

iex> Wymcp.Telemetry.Logger.bounded(%{"a" => 1})
"%{\"a\" => 1}"

iex> Wymcp.Telemetry.Logger.bounded({:error, %{"id" => Integer.pow(10, 256)}})
"{:error, %{\"id\" => <integer of more than 256 digits>}}"

detach()

Detaches the handler. Idempotent: detaching when nothing is attached answers :ok.

enabled?()

Whether the handler is attached at boot — the config :wymcp, logger: … key, default true.

Wymcp.Application is the only caller: attach/0 and detach/0 deliberately do not consult it.