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.
| event | level | line keys |
|---|---|---|
wire.reject | :info | rejecter, reason, status, http_method, method★, message_id★, message★, era when present |
session.start | :info | client_name★, client_version★, era |
session.expired | :info | era |
tool.start | not rendered | — |
tool.stop | :info | tool_name★, action★, is_error, error_kind, result_type, duration_ms, era |
tool.error | :error | tool_name★, action★, message_id★, exception, error★, duration_ms, era, crash_reason |
help.called | not rendered | — |
auth.error | :error | auth_module, exception, error★, http_method, method★, message_id★, crash_reason |
server.reject | :info | server, reason★, message_id★, era |
server.error | :error | server, 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
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.
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>}}"
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.
Wymcp.Application is the only caller: attach/0 and detach/0
deliberately do not consult it.