vgi-rpc Access Log Specification¶

This document is the cross-language contract for the access log emitted by every conformant vgi-rpc server implementation. The Python implementation in this repository is the reference; other-language implementations (Go, Rust, JS, Java, …) MUST emit records that satisfy this spec so a single tool — vgi-rpc-test --access-log — can validate them all.

The machine-checkable form of this spec is vgi_rpc/access_log.schema.json (JSON Schema 2020-12). Where this document and the schema disagree, the schema wins.

1. Stream¶

Logger / channel name: vgi_rpc.access. The string "vgi_rpc.access" MUST appear in each record's logger field.
Severity: every record is emitted at INFO. Implementations that don't carry severity SHOULD still set "level": "INFO" in each record.
Encoding: one record per RPC call, one record per line, UTF-8 encoded JSON, no trailing comma. Records are independently parseable; the stream as a whole is JSON-Lines (NDJSON).
Sink: implementations MUST accept a --access-log <path> command-line flag and write every record to that path. When the flag is absent the access log is implementation-defined (typically suppressed).
One record per call: emit on completion (success, error, or cancellation). Never emit a partial record. Never emit more than one record for the same call. Stream calls produce one record per init and one per exchange/produce continuation.

2. Top-level shape¶

Every record is a JSON object with these keys:

Key	Type	Required	Notes
`timestamp`	string	yes	RFC 3339 UTC, millisecond precision. Exact pattern: `YYYY-MM-DDTHH:MM:SS.sssZ` (e.g. `2026-04-26T15:30:45.123Z`).
`level`	string	yes	Always `"INFO"`.
`logger`	string	yes	Always `"vgi_rpc.access"`.
`message`	string	yes	Free-form summary, e.g. `"<protocol>.<method> ok"`. Not parsed by tooling — assertions go on structured fields.

All fields below appear at the top level of the same object — they are NOT nested under extra, data, or any other envelope.

3. Always-required structured fields¶

These fields MUST appear in every record, regardless of method type or status.

Field	Type	Notes
`server_id`	string	Stable identifier for the server instance (12-char hex by default). Same value attached to every record from the same process lifetime.
`protocol`	string	The wire name of the protocol that owns the dispatched method, e.g. `"ConformanceService"` or `"vgi_rpc.Reflection.v1"` — not a server-wide default. A server may host several protocols; a record labelled with the wrong one produces plausible-looking dashboards rather than an error, which is why this is the field most worth getting right. Framework endpoints that belong to no protocol log the server's primary.
`protocol_hash`	string	SHA-256 hex digest of the protocol's canonical description. 64 lowercase hex characters. Stable across processes, builds and language ports that expose the same Protocol; changes whenever any wire-relevant detail changes. Use as the registry key when decoding archived records. Defined in WIRE_PROTOCOL.md §14.
`method`	string	The RPC method name. For framework built-ins, the leading double-underscore is preserved (e.g. `"__transport_options__"`). Method names may collide across protocols, so anything aggregating on this field alone — a dashboard, an alert, a proxy policy — must group by `(protocol, method)` or it silently merges two protocols' traffic.
`method_type`	string	One of `"unary"` or `"stream"`.
`principal`	string	Authenticated principal, or empty string when anonymous.
`auth_domain`	string	Auth scheme/realm, or empty string when anonymous.
`authenticated`	boolean	`true` iff the call was authenticated.
`remote_addr`	string	IP:port for HTTP transport, empty string for pipe/subprocess/Unix-socket.
`duration_ms`	number	Wall-clock dispatch duration in milliseconds, rounded to 2 decimal places.
`status`	string	One of `"ok"` or `"error"`. `"error"` is used for any failure, including cancellation by the client.
`error_type`	string	Python-style exception class name on error (e.g. `"ValueError"`, `"RpcError"`). Empty string when `status == "ok"`. Implementations in non-Python languages SHOULD map their own error types to a stable, descriptive string and document the mapping.

4. Conditional fields¶

These fields appear when their condition is met and are absent (key not present) otherwise.

4.1 Errors¶

Field	Type	Condition
`error_message`	string	Required and non-empty when `status == "error"`. No length cap. The full server-side message is reported.
`error_code`	string	The canonical error code the call failed with — one of the sixteen names in WIRE_PROTOCOL.md §8 (`UNAVAILABLE`, `NOT_FOUND`, …), the same value the client received in `vgi_rpc.error_code`. Servers SHOULD emit it on every `status == "error"` record; it MUST be absent when `status == "ok"`. An operator alerts on the code ("page on `UNAVAILABLE`"), not on a language's exception class name. Optional in the schema for one release so ports that predate the error model still validate.

4.2 Stream lifecycle¶

Field	Type	Condition
`stream_id`	string	Required when `method_type == "stream"`. UUID hex (32 lowercase hex chars, no dashes). MUST be the same value across the `init` record and every continuation record of the same stream call.
`cancelled`	boolean	Present and `true` when the stream was cancelled by the client. Absent on non-stream calls and on streams that completed normally or errored without cancellation.

4.3 Request shape (never the payload)¶

A record MUST NOT carry any request or response payload value, at any log level, in any form (raw, base64, truncated, or hashed). The framework cannot know which parameters are secret -- a VGI catalog_attach carries API keys and passwords in its options -- so a payload in a log is a credential leak that fires the moment someone turns on DEBUG. The fields request_data, request_state and response_state are forbidden; the schema rejects a record carrying any of them. No configuration may re-enable them.

Field	Type	Condition
`request_fields`	array of `{"name": string, "type": string}`	SHOULD be present on every `unary` record and every stream `init` record; absent on stream continuations. One entry per request parameter, in schema order: the field name and its Arrow type rendered as text. Entries carry no other keys -- in particular no value.
`request_rows`	integer	Present exactly when `request_fields` is. The request batch's row count: 1, or 0 for a zero-parameter method.

The request's size is request_bytes (§4.8). Do not add a digest of the payload: a hash of a request whose other fields are known is a brute-force oracle for a short secret.

Changed in 0.50.1. Earlier versions required request_data (the request as base64 Arrow IPC) at DEBUG and request_state/response_state (the decrypted stream state) on HTTP stream records. Both put secrets in logs. An emitter upgrading MUST drop them and SHOULD emit request_fields / request_rows; vgi-rpc-test --require-request-data now fails with an explanation rather than passing.

4.4 HTTP transport¶

These fields appear on HTTP transports only.

Field	Type	Condition
`http_status`	integer	The HTTP response status code (e.g. 200, 401, 404, 500).
`request_id`	string	Per-request correlation ID. Implementations SHOULD propagate inbound `X-Request-ID` if present, otherwise mint a UUID.
`trace_id`	string	W3C trace ID, 32 lowercase hex characters, of the span this call ran under. Present when the server participates in a trace. This is the join key to the surrounding distributed trace — `request_id` only correlates records within one service, so without this a log line and the span describing the same call cannot be matched. Read it from whatever span is current rather than from anything the framework threads through, so a record correlates with an application-opened span as readily as a framework-opened one.
`span_id`	string	W3C span ID, 16 lowercase hex characters. Emitted together with `trace_id` — both or neither.
`request_state_bytes`	integer	Size in bytes of the state token received on a stream continuation. The token itself MUST NOT be logged (§4.3): it serializes whatever the call was given, and it is replayable.
`response_state_bytes`	integer	Size in bytes of the state token returned on a stream turn that produces one.

Field	Type	Condition
`session_action`	enum	One of `"none"` / `"open"` / `"resume"` / `"close"`. `"none"` = the request flowed through sticky middleware but neither carried a session token nor opened one (e.g. a unary call from a non-`with_session_token()` caller). `"open"` = the method called `ctx.open_session(...)`. `"resume"` = a valid `VGI-Session` token resolved to a live registry entry. `"close"` = the method called `ctx.close_session()`. Absent for non-sticky servers.
`session_id`	string	Present when the request touched a session — i.e. when `session_action` is `"open"` / `"resume"` / `"close"`. Format: 12-byte hex, exactly 24 characters. Absent on `"none"` and on non-sticky servers. The id is stable across the open / resume / close lifecycle records for a given session.

Gaps: middleware-short-circuit cases (token validation failed; server_id mismatch; registry miss for an apparently-valid token) currently do NOT produce access-log records. The middleware emits a typed SessionLostError response without invoking dispatch, and the access-log emitter lives in the dispatch path. Operators monitoring for misroutes should rely on the typed error surface on the wire instead. Adding short-circuit access-log records is a documented follow-up.

5. Method-type rules¶

All conditional behavior is keyed off method_type (and, for streams, whether the record is an init or continuation — distinguishable by the presence of request_fields). Rules MUST NOT be keyed off method names. Method names are application-specific; framework conformance applies uniformly.

Rule	Trigger
`request_fields` / `request_rows` present (SHOULD)	`method_type == "unary"` OR (`method_type == "stream"` AND record is the init record).
`request_fields` / `request_rows` absent	Stream continuations.
`request_data` / `request_state` / `response_state` present	Never.
`stream_id` present	`method_type == "stream"`.
`cancelled` present	Stream call cancelled by client.
`error_message` non-empty	`status == "error"`.

4.8 Egress accounting¶

Three byte figures answer three different questions, and conflating them is how an egress bill ends up wrong by orders of magnitude. The reference implementation measured only the middle pair until these were added.

Field	Type	Condition
`request_bytes`	integer	On-wire size of the request body as received, before decompression. What the peer actually sent.
`response_bytes`	integer	On-wire size of the response body as sent, after compression. Absent when the size cannot be known (a streamed response with no content length).
`externalized_bytes`	integer	Bytes uploaded to external storage during this call. Absent when nothing was externalised.

Contrast with §4.6's input_bytes / output_bytes, which measure logical Arrow buffer sizes — what the worker processed. Those are unaffected by compression and exclude externalised payloads entirely, so they are the wrong number for anything that costs money and the right number for capacity work.

The gap is not marginal. A compressible 200 KB result measured 200,008 logical bytes and 183 bytes on the wire in the reference implementation — a factor of about 1,000. In the other direction, a call that externalises a 10 GB batch leaves a pointer batch of a few hundred bytes in the HTTP body; without externalized_bytes the 10 GB is invisible.

Implementation note. response_bytes cannot be measured where the other fields are. A handler knows what it produced, but response compression runs afterwards, so a record emitted at handler time can only ever report the uncompressed body. An emitter MUST therefore defer emission until the final body exists — in the Python reference, a middleware installs a per-request sink, handlers append to it, and the middleware emits after compression has run. The cost is that a crash between handler and response loses that request's records; the alternative is a permanently wrong number.

5b. Truncation¶

Downstream log shippers (Vector's file source, Fluent Bit's tail input) impose a per-line ceiling — Vector defaults to 100 KiB and Fluent Bit's Buffer_Max_Size defaults to 256 KiB. Lines longer than the shipper's ceiling are silently dropped.

To stay compatible, an emitter MAY enforce a per-record byte cap. When it does, it MUST shed fields in this order and signal the truncation via top-level keys:

Replace claims with {}. Set truncated: true.
If the record still exceeds the cap, emit a sentinel form: keep all always-required envelope fields plus error_message (when status == "error") and set truncated: "record_too_large". All other optional fields are dropped.

error_message MUST NOT be truncated — operators rely on the full server-side message for debugging. The Python reference implementation uses a default cap of 1 048 576 bytes (1 MiB), configurable via --access-log-max-record-bytes or the env var VGI_RPC_ACCESS_LOG_MAX_RECORD_BYTES. Pair the cap with shipper configs that raise their per-line limits to match (Vector's max_line_bytes, Fluent Bit's Buffer_Max_Size).

Field	Type	Condition
`truncated`	`true`, `"record_too_large"`, or legacy `"payload_omitted"`	Present iff the record does not carry everything it otherwise would. `true` = at least one optional field dropped to fit the size cap. `"record_too_large"` = sentinel form; most optional fields dropped. `"payload_omitted"` is legacy: it marked a record whose payload was withheld at INFO, back when payloads were logged at DEBUG. Payloads are now never logged, so there is nothing to mark; new emitters MUST NOT use it. The schema still accepts it so an INFO log from an older emitter validates.
`original_request_bytes`	integer	Legacy, paired with `"payload_omitted"`. New emitters MUST NOT emit it; `request_bytes` carries the request size.

5bb. Sampling¶

An emitter MAY log only a fraction of calls. Sampling is optional; an emitter that does not implement it simply never emits sample_rate. An emitter that does MUST hold to three rules, each of which is the difference between a sampler that helps and one that quietly costs someone an incident.

Never sample errors. A rate below 1 exists because successful calls are repetitive, which is exactly what failures are not. status == "error" records MUST always be emitted regardless of rate. A consumer must be able to read a fall in error count as a fix landing, not as the dice going the other way.
Decide deterministically, per call — not per record. The decision MUST be a function of a stable identifier for the call, keyed on stream_id when present and request_id otherwise, so that every record of one stream shares its init's fate. Random per-record sampling shreds a multi-record call into fragments indistinguishable from data loss, and the calls most likely to be split are the long streams most worth studying.
Carry the rate in-band. Every sampled-in record MUST carry sample_rate. A consumer counting calls has to divide by it, and a rate discoverable only from a deployment's flags is a rate that gets guessed wrong.

Field	Type	Condition
`sample_rate`	number, `0 < r <= 1`	Present iff sampling is active (rate below 1). Absent when the emitter logs everything. Error records MAY lack it even under sampling, since they bypass the decision.

The Python reference implements this as a logging.Filter on the handler — not the logger, so an application's own handlers keep seeing every record — configured by --access-log-sample / VGI_RPC_ACCESS_LOG_SAMPLE, defaulting to 1.0. An out-of-range rate fails at startup rather than at the first request, because 100 meaning "100%" would otherwise silently log everything.

5bc. Asynchronous emission¶

An emitter MAY hand records to a background writer so disk latency stays out of the request path. Optional; a synchronous emitter is conformant.

An emitter that does MUST bound the queue and MUST NOT block when it is full. An unbounded queue turns a stalled disk into an OOM; a blocking put reintroduces exactly the latency the thread was meant to remove. Full therefore means drop.

What makes dropping acceptable rather than silent corruption is that it is reported: the next record to get through MUST carry dropped_records (integer, count since the last successful enqueue). A log that loses records without saying so is worse than a slow one, because a consumer cannot tell a quiet period from a lossy one.

Field	Type	Condition
`dropped_records`	integer	Present on the first record enqueued after one or more were dropped. Reports how many were lost.

This trades durability: with a synchronous writer, a record on disk means the call completed; with a queue, a crash loses whatever is still in it. That is why the Python reference makes it opt-in (--access-log-async, --access-log-queue-size, default 10000) rather than the default — right for high throughput, wrong for audit.

5c. Encoding & atomicity¶

One JSON object per line, terminated by \n. UTF-8 encoded. No literal newlines inside field values (the standard json.dumps escapes them).
A single emitter process appending via the stdlib logging.FileHandler is thread-safe (the handler holds a lock) and atomic on Linux.
Two processes writing to the same access-log file is unsupported. Concurrent appends from multiple processes can interleave, and concurrent rotation will race. Run one access-log file per process — use {pid} and/or {server_id} placeholders in the path. The Python reference implementation expands these placeholders in --access-log paths automatically.

5d. Rotation¶

Implementations MAY rotate the access log via rename (e.g. access.jsonl → access.jsonl.1). Both logging.handlers.RotatingFileHandler (size-based) and TimedRotatingFileHandler (time-based) in Python's stdlib implement this correctly, and Vector and Fluent Bit are designed to follow rename-rotated files. Do not truncate-in-place — shippers will lose their read position.

The Python reference implementation exposes:

--access-log-max-bytes N / VGI_RPC_ACCESS_LOG_MAX_BYTES — size-based rotation when > 0.
--access-log-when STR / VGI_RPC_ACCESS_LOG_WHEN — time-based rotation (e.g. H, D, midnight); mutually exclusive with --access-log-max-bytes.
--access-log-backup-count N / VGI_RPC_ACCESS_LOG_BACKUP_COUNT — number of rotated files retained (default 5).

6. Extra fields¶

Implementations MAY add fields beyond those defined here. Validators MUST NOT reject records carrying unknown fields (additionalProperties: true). Conformance is measured by what the schema requires, not by what it forbids.

To avoid collision with future spec additions, custom fields SHOULD use a vendor prefix (e.g. acme_request_size).

7. Conformance check¶

# Validate any worker's access log against this spec.
vgi-rpc-test --cmd "./my-go-worker" --access-log /tmp/go-worker.log

The exit code is 0 if every record passes, 1 if any record fails, 2 if the runner itself errored.

8. Reference¶

JSON Schema: vgi_rpc/access_log.schema.json
Python emitter: vgi_rpc/rpc/_server.py (_emit_access_log)
Python JSON formatter: vgi_rpc/logging_utils.py (VgiJsonFormatter)
Python validator: vgi_rpc/access_log_conformance.py
Cross-language conformance overview: cross-language-conformance.md
Reference shipper configs (Vector and Fluent Bit, S3/GCS/Azure): log-shipping/