init() and
its environment, running the server, minting
tokens, and running the relay daemon. This page
assumes those are done and something is still missing.
The outputs below come from several runs against several local servers, so the address in a
command is the one that produced the output under it, not the one above it. Substitute your own.
Start with what vexlo check does not check
vexlo check is the obvious first command and it answers a narrower question than its name
suggests. It validates the configuration vexlo serve would resolve, reports free disk on the
value store’s filesystem, and prints the retention arithmetic. It never opens the database and
never opens the value store, so it reads nothing about whether records are arriving, whether a
token works, or whether a relay daemon is running.
Two things to know about it before you run it. It exits 1 on its own retention defaults, because
the default 20 GiB value budget, 7-day shape retention and assumed 2 traces/s write rate do not
fit together. The run below names the database and the value store explicitly, which is the only
reason those two lines and the free-disk line read as they do; with neither flag given they
resolve under ~/.vexlo/data:
-allow-overcommit proceeds with the arithmetic printed and
proceeding: -allow-overcommit is set appended.
And vexlo serve starts on the configuration that made check exit 1, logging the same
retention numbers at INFO and nothing else. Only the address differs: this run passed
-api-addr 127.0.0.1:18690, where the check above reported the default 127.0.0.1:8080.
check does not mean your server is down, and a passing check does not mean
records are arriving. Nothing on the rest of this page depends on it. Check the
configuration covers its flags.
No traces at all
Is anything in the spool directory
The SDK writes to a spool directory and never talks to a server. A record that never reaches that directory never existed, so this is the first fork, and it is atest -d away.
The directory the SDK uses is the spool_dir argument to init(), then VEXLO_SPOOL_DIR, then
~/.vexlo. The relay daemon resolves -spool-dir the same way, with the same ~/.vexlo default.
Two processes running as different users therefore pick two different default directories while
both configurations read as correct, and the daemon finds an empty directory while your
application’s backlog grows next to it.
The directory is also created lazily, on the first record written, not by init(). An absent
directory means capture produced nothing, and these are the causes:
vexlo.diagnostics() is the one signal here, read from inside the process that runs the markers.
A marked function entered with no @vexlo.trace in scope above it produces no record at all, and
says so:
init() that never ran and an init()
that ran disabled produce byte-identical counters and no directory either way.
init()-never-called run. The VEXLO_ENABLED=0 run differs only in the
directory name on its third line. Separating them is a question about your own startup path, not
about Vexlo: whether init() is reached before the first request, and what VEXLO_ENABLED holds
in the environment the process actually got. Disabling the
SDK lists every input that turns capture off.
Diagnostics carries eleven counters and they are not one kind of fact. The first two are
swallowed faults. steps_outside_trace and redacted_tags are the SDK doing what it was asked
to. Each of the last seven counts a marked callable that ran without its step-attempt record
reaching the wire, which a trace is there and a record is
missing takes up below. Reading what the SDK
absorbed has all eleven.
internal_errors and adapter_errors above 0 mean the SDK swallowed a fault rather than
raising it into your request. They are the counters to check before anything else on this page,
because a non-zero one invalidates the reasoning in every section below it.Is a relay daemon draining the spool directory
Runvexlo relay status -spool-dir <dir> against the spool directory your application writes to.
It reads the directory and the writers’ own counter files, so it works with no daemon running and
no server reachable.
A backlog with no daemon behind it:
records sent: 0 with a non-zero backlog and an oldest unsent age that climbs between two runs of the command means nothing is draining this directory.
dropped: none means nothing has been lost yet.
oldest unsent age is the age of the oldest hour still holding unsent data for that writer, not
of the oldest record. Records are opaque bytes to the daemon with no parsed timestamp, so the
figure is a conservative proxy: the true age sits between it and that hour’s end, never above it.
The 2.0GiB on the first line is this command’s own -spool-budget-bytes, which defaults to
2 GiB. relay status reads the directory and the writers’ counter files and no daemon state, so
a daemon started with -spool-budget-bytes 536870912 still leaves this line reading 2.0GiB.
Pass the daemon’s own value to compare the two. Enforcement is the daemon’s retention tick, so
with no daemon running nothing evicts anything and the directory grows for as long as the process
keeps writing.
Point the same command at a directory no writer has ever touched and it says so, which is how a
daemon watching the wrong directory looks:
init() resolved. The spool directory
has its layout and vexlo relay status has the rest of
its output.
Is the server accepting what the daemon sends
With a daemon running there are four outcomes, and what separates them is how the daemon treats the response it got. A transport failure, a429, and a 500, 502, 503 or 504 are retried: three attempts per
send, then the batch is left on disk and the next poll loads it again, so the backlog holds and
nothing is lost. Every other status, 400, 401, 403, 413, 422, 501 and anything the
exchange does not recognise, is terminal on the first response. The batch is dropped, counted once
per record under daemon_terminal_reject, and never retried. Those records are gone.
The third row is the one worth reading twice. A daemon dropping every batch reports itself
healthy, because
/healthz degrades on a backlog with nothing accepted behind it, and a dropped
batch leaves no backlog. This is a daemon whose -environment did not match the pin on its
ingest token:
WARN line, a healthy health response, and seven records permanently gone. dropped: daemon_terminal_reject on a writer is the signal, and records sent: 0 beside it is what
separates this from a daemon that forwarded for a while and then started being rejected.
Four causes produce those three outputs and differ only in the status and in one line of
relay status. A -environment that does not match the token’s pin gives status=422, as above.
A token the server does not hold, or has revoked, gives status=401. A read-role token in
-token gives status=403, which the end of this section takes up. And a service pin the
records do not match gives status=422 as well, with the writer’s own service: line naming the
service the records carry:
-service delivery-service, and checkout-service on the writer line
is the whole of what the host told you. Read the pin back with GET /v1/whoami using the ingest
token and compare both fields against the writer:
relay status and in /healthz, and the
daemon’s log is the only thing that separates them. An unreachable destination, three attempts and
then the requeue:
500, which is the same three lines with a status in place of the
transport error. That log is the multi-environment-token daemon taken up below, which is the one
configuration in this set that makes a working server answer 500:
reason carefully. /healthz degrades the moment a backlog exists and the daemon has
never had a record accepted, which is the case for both daemons above: neither of them ever had a
record accepted. Once one send has been accepted, it takes five minutes without another accepted
send for the same backlog to degrade it again. The wording does not distinguish the two. Two more
triggers have nothing to do with sending. The directory holding more than 80% of its budget
degrades a daemon that is forwarding fine. And a spool status read that fails answers degraded
with spool status unavailable as its reason, which is what a permissions or filesystem fault
on the directory itself looks like. Read it with curl -s http://127.0.0.1:19690/healthz against
the daemon’s own -health-addr; health and
metrics has the rest of what it serves.
Here is the configuration behind that 500, with nothing wrong with the server. An ingest token
pinned to more than one environment fails authentication on every ingest route, and the failure
surfaces as a 500:
500 is retryable, the daemon retries that batch indefinitely and drops nothing, so the
symptom is a backlog that never moves. The same GET /v1/whoami call is the check, and it answers
200 on the token every ingest route refuses:
environment_scope is this failure. Mint the token with a single
-environment value. Pins covers the scoping rules and POST /v1/records covers the per-record rejections a 200 response
reports, which the daemon also counts as terminal.
The 403 is the one of the four where the token itself is good. POST /v1/records requires an
ingest-role token and refuses a read-role one, and the daemon runs no check of its own on the
token it was handed, so a read token in -token starts as cleanly as any other and the status in
the log is the whole of what you are told:
POST /v1/heartbeat requires the same role, so, like an unknown token, this one’s drops never
reach the server side either. That daemon heartbeated every two seconds for nine seconds, and the
service coverage read two sections below came back empty:
GET /v1/whoami settles it in one field, and the field is role:
-role ingest. Mint a
token has the roles and what each one reaches.
The two drop causes that are not a rejection
Adropped: block has two other causes, and neither is a response from anywhere. Both are
records the daemon gave up on before a server ever saw them.
daemon_spool_expired counts records the daemon deleted unsent. Pressure retention runs on the
daemon’s retention tick, a minute apart by default: while the directory is over
-spool-budget-bytes, it deletes the oldest hour that is past -finality-grace, counts every
still-unsent record in it under this cause, and repeats until the total is back under budget. The
current hour is never a candidate, so reaching this needs a backlog held across an hour boundary,
which is what a destination that stays unreachable for long enough produces. Every writer that
had unsent records in a deleted hour logs one spool pressure evicted unsent records WARN
carrying the writer, the hour and the count. A directory over budget with nothing old enough to
delete logs spool over budget with no hour past finality_grace yet instead and deletes nothing,
which is the line that comes first. Earlier still, /healthz reads degraded from 80% of the
budget, while every record is still on disk.
daemon_torn_record counts a segment’s trailing bytes past its last newline, once, when the hour
has gone final and the writer that would have completed the line is gone. It logs torn trailing record orphaned by hour finality with the byte count. This is a partial write, not a rejection,
and the records ahead of it are unaffected.
Both land in the dropped: block vexlo relay status already prints and in the same
records_lost_24h the heartbeat carries, so the cause name is the whole of the signal. The
spool directory has the sweep’s other job.
Where a terminally rejected batch does become visible
POST /v1/heartbeat consults neither pin, where POST /v1/records checks both, so a daemon
whose -environment or service pin is wrong keeps heartbeating successfully while every batch of
records is refused. The heartbeat carries the daemon’s own drop counters and the server folds them
into service coverage, which makes GET /v1/coverage the read that tells someone on the server
side that a producer exists and is losing everything:
last_seen_at. That combination is
the signal: traces_24h and last_seen_at are both computed from traces that arrived, so a
service listed with records_lost_24h above 0 and no last_seen_at has a relay daemon reaching
this server and no record getting past it. A service absent from the list has had neither an
arrived record nor a reported drop in the last 24 hours, so absence does not rule out a daemon
that is forwarding nothing and dropping nothing either.
Two bounds on that read. Drops appear only on the daemon’s next heartbeat, 30 seconds apart by
default, so checking within the first half-minute of starting a daemon shows nothing. And the
heartbeat admits exactly the token POST /v1/records admits, so the three failures that are about
the token rather than a pin, an unknown token, a read-role token and the multi-environment 500
above, stop the heartbeat as well and leave nothing here to read.
records_lost_24h is a trailing 24-hour window, not a running total. Each heartbeat’s new drops
are folded into the current hour’s bucket and the read sums only the buckets inside the last 24
hours, so a daemon that dropped 50,000 records yesterday and nothing since reports 0 here. Read
a zero as nothing reported lost in the last day, never as nothing ever lost. The figure covers all
three of the daemon’s drop causes and is not the same quantity as a trace’s own records_lost,
which the SDK stamps on the trace-close record for losses inside the process. The two are
counted on opposite sides of the spool directory and neither bounds the other. GET /v1/health
reports the same per-service loss counters beside the store’s own figures. GET /v1/coverage has every field.
Did records arrive under a team this token cannot read
Past the daemon, both the trace list and service coverage are scoped to the reading token’s teams, and the trace list filters further. An empty list says nothing on its own about whether records arrived. RunGET /v1/coverage first, for the reason above and because it carries no filter of your own:
last_seen_at means records are landing and the problem is in the query.
An empty list:
GET /v1/whoami settles which team that is:
team_ids against the team on the traces you expect. A trace carries the team of the
ingest token that delivered it, so a read token for another team sees an empty list against a
server holding the trace:
?environment=prod when the daemon
delivered the trace with -environment dev:
environment and service on a stored trace come from the daemon’s -environment flag and
the SDK’s service, not from anything the reader sets, so a filter written against what you meant
to deploy excludes traces delivered under what you actually deployed. Drop every filter, confirm
the trace is there, then add them back one at a time. Team and environment
filters has the rules, and GET /v1/traces has every parameter.
A trace is there and a record is missing
A trace is served from whatever has arrived, so a trace whose records are incomplete still returns, and it returns without complaint. The read is the ordinary one,GET /v1/traces with no
filter or GET /v1/traces/{id} for a trace you have an id for, and three fields on the list row
carry the difference, two of them by being absent.
trace-open and one
step-open record per entered function, which is what the spool directory holds at that moment.
Reading it back takes a few lines of Python, and every record block below this point on the page
is its output: one line per record, each record’s kind, the fields named on the command line,
and each slot’s state.
spool.py
step-open for every attempt from the moment the marked function is entered and
writes it on whichever of three triggers comes first: the attempt has been open 1 second, its
trace’s trace-close is written, or the process makes its 2-second shutdown flush. The held
record is discarded unwritten when the attempt’s own step-attempt is written, so a call that
returns inside that second produces no step-open at all. Three seconds
after the call above returned, the same row carries root_status, a duration_ms and
completeness: "complete".
Now the same read against two traces posted with records held back: the first without the root’s
own step-attempt or its trace-close, the second without its trace-close:
root_function as well as
root_status, and that is table row two: a record at the root, of either kind, creates the row
root_function is read from, so its absence means nothing at the root arrived at all. The second
trace is the one with no signal on it: a lost trace-close leaves completeness reading
complete, deliberately, because counting the close record would reclassify every trace whose
close was lost as partial. The cost is that a trace’s records_lost and truncated ride on
that record, so when it is the record that went missing, the trace reports no loss and means
nothing by it.
The gap in that table is between row three and row one, and it is the one to know about. When the
root’s completion record is lost inside the process, the step-open the SDK was holding for that
attempt is written in its place, so the row reads exactly like a request still running: running,
root_function present, no root_status. The trace list cannot separate those two, and the thing
that eventually does is the clock. running is time-bounded: a trace whose root has not arrived
reads running while a record for it arrived within the last fifteen minutes and abandoned
after that, derived per read, so two reads of one trace can differ with nothing written in
between. abandoned on a request you know returned is a lost root record.
Row two needs more than a lost completion. Nothing at the root path, of either record kind,
reached the server, and a completion lost on its own does not produce that, because the close
trigger writes the held step-open instead. The capture above made it past the spool directory:
the trace’s records were posted directly, minus the root’s own step-attempt and its
trace-close. In production the losses on that side of the handoff are the ones the sections
above cover, a batch the server rejected terminally among them.
The four fields on every row are the rest of the arithmetic. records_lost counts records the SDK
could not deliver for that trace, records_shed records ingest refused under pressure,
truncated a trace that hit the 10,000-step cap, and instance_mismatch records attributed to
more than one process. completeness reads complete when the root’s own completion record
arrived and all four of those report nothing, and partial when the root arrived and at least one
of them does not. records_lost and truncated are stamped by the SDK, so they are readable in
the spool directory as well. Ask spool.py for them by name and the last of its seven lines, the
trace-close, is the one that carries them:
records_shed and instance_mismatch have no counterpart there and are added by the server,
which is what tells you which side of the handoff a trace lost its records on.
For a step a marked function ran and no record was ever written for, the counters in
vexlo.diagnostics() are the surface, not the
trace: steps_after_trace_close, attempts_outlived_trace, drives_lost_to_trace_end,
drives_degraded, attempts_dropped_hidden_coroutine, traces_evicted and markers_declined
each count a marked callable that ran with no step-attempt record reaching the wire. They are
cumulative for the process and not attributable to one trace, so they tell you a shape of loss is
happening, not which trace it hit.
Three of them rise during ordinary operation and are not faults: drives_lost_to_trace_end once
per marked generator the host abandons before exhaustion, attempts_outlived_trace once per task
or carried-context thread that finishes after its trace closed, and markers_declined once per
decorated class at import. What a marker refuses to
wrap and finishing work before the root
returns cover the two you
can change.
One more case reads as missing steps when it is not. A single trace’s steps come back one page at
a time, at most 500, so “this step was never reported” holds only after a full walk with
next_cursor back to null. What a page leaves out depends on the sort. On the default
steps_sort=path it is whatever sorts after the page by path, with no bias toward either kind of
step. On steps_sort=duration_desc a step whose every attempt is still in flight has no duration
and sorts after every ranked step, so the unfinished ones are the last to come back. Either way
the number missing from one page is not a count of anything.
Step paging and sorting has the walk.
The steps are there and the values are missing
An input or an output that is absent is reported by its slot’sstate, not by the slot being
gone. Two of the four reasons below have a state of their own: sampled_out for the sampling
roll and expired for the byte budget. A capture policy that lowers value_sample_rate arrives
as that same sampled_out, a policy with enabled: false stops capture before a slot exists, and
redaction leaves the state untouched, so the state narrows the cause without settling it on its
own.
A trace captured with values on, read back with the spool.py above:
init(value_sample_rate=0.0), in a directory of its own:
sampled_out on the root’s slots and no value records at all. pending on pick_dasher reads
the same in both runs and means something different in each. It is the state of an ok attempt
below the root, whose fate is not settled until the root returns: in the first run the three
value records are what settled it, and in the second nothing ever will, because the trace was
excluded and an excluded pending slot is never revised.
So pending is the one state on this page that is not a signal, and every ok attempt below the
root carries it. A non-root ok slot also reads pending on the read API after its value
record has been ingested, so the same word covers bytes that are there, bytes still coming, and
bytes that
are never coming. Fetch the values and branch on whether a value came back, never on the state.
Handles states that rule for the read API and value
sampling has what the SDK writes.
The second cause is a capture policy set on the server. A policy lowers what init() asked for
and never raises it, so one set on the server reduces or stops capture for every process reading
that service’s policy file, with nothing logged in the application. vexlo policy show is the
check:
updated_at on that last line is not when the policy changed. vexlo policy show sends a
heartbeat and prints the response, and the route stamps that field with the time it answered, as a
liveness signal. Nothing the server serves says when a policy was last set.
The daemon writes that same policy into the spool directory on its next heartbeat, at
<spool-dir>/policy/<service>.json, and the SDK reads it from there. Its stamp is the earlier
heartbeat’s, for the same policy:
updated_at is what decides
whether it counts: a file older than five minutes by that stamp, or missing, or unparseable, is
ignored and the process falls back to init()’s own values, so a policy stops applying when the
daemon stops heartbeating. And the file is read on the writer thread’s own poll rather than at
init(), so a newly set policy does not apply to work that starts before that thread’s first
poll. The capture policy file and setting a capture
policy have the fields and the precedence.
Two more reasons a value is absent, neither of them loss, and the first is not a state at all.
Redaction replaces the value under any str dict key that
matches a redaction rule, at any depth in an input or an output, and drops a matching
vexlo.tag() pair. The slot keeps its state and the handle carries
redacted: true, so this is the one absence on this page the state does not report. A name rule
reaches no further than a name: a secret interpolated into an exception message, as in
ValueError(f"invalid token {token}"), or into a captured log message ships as written, whatever
redact_keys holds. Each of those two has a switch of its own:
capture_error_message for the message and
capture_logs for the log text.
The second reason is the clocks. Values are bounded by a byte budget while shape is bounded by
time, so values go first: on the default 20 GiB budget and 7-day shape retention, the arithmetic
vexlo check prints above puts values at about 104 hours against shape’s 168. A trace older than
its values keeps every step and has nothing to show in them. The state for that is expired,
resolved at read time, and vexlo serve answers it for a value that never arrived as well,
because its store keeps no record that a value once did. Read expired as no bytes to read, not
as bytes this server held and lost. The ninth state, missing, is reserved for a store that can
tell those two apart and vexlo serve never answers it. Retention
has the two clocks and handles has all nine states.