pkgproxy design: access log

The one log line pkgproxy writes per request. Part of the pkgproxy design, whose index says which file holds each § number.

• 23. Access log: one line per request, with an outcome

23. Access log: one line per request, with an outcome

internal/reqlog logs one “handled request” line per request: method, url, remote address, handler, outcome, status, bytes and duration. outcome says how the request was served; handlers record it with reqlog.SetOutcome (the last call wins), as they do handler. The values are stable words, not translated.

• hit — served from the cache without contacting the origin
• revalidated — the origin was consulted about a cached entry, which was then served (refreshed, or confirmed by a 304)
• stale — the origin could not be reached, the due-for-revalidation entry was served (also logged as a warning, with the reason)
• fetched — fetched from the origin, saved to the cache and served
• joined — waited for or followed another request’s fetch
• passthrough — relayed from the origin, not cached (uncacheable paths, the hash-mismatch fallback)
• synthesised — answered by pkgproxy itself from what it recorded, because it was not contacting the origin (§11.7)
• tunnel — a blind CONNECT tunnel
• error — the request failed; Wrap assumes this for any 4xx/5xx response nothing recorded an outcome for

A handler adds attributes of its own with reqlog.SetAttr, after the ones above. The line is logged when the handler returns, so it covers work done after the response was sent. A snap refresh answered online carries assertions_fetched (how many assertions it fetched ahead, §11.7) and chains_incomplete (how many of the snaps it recorded still lack some): the line appearing is how a reader, or a test, knows the fetch ahead is over.

A response with a 5xx status is logged at error level, with the first 512 bytes of its body as response: the error text of a failed cache lookup, or what the origin answered when its error was relayed. Only text is logged (valid UTF-8, trimmed): a compressed body (Content-Encoding set) or a non-text content type is skipped. A relayed origin body may contain sensitive data, which is why the capture is limited to server errors and to 512 bytes.

Every handler records an outcome on every path that serves an answer; a failure it does not label is error, from Wrap. The TTL-cached documents of the Go module proxy (list, @latest, .info) and of LXD (the simplestreams index and product catalogs) get theirs from revalidate.ServeDoc, which serves both. A HEAD for an uncached blob is passthrough on the registry, which asks upstream, and synthesised on LXD, which answers from the product catalog, and for a snap, answered from the size the store gave. Of the requests that share one fetch, only those that waited for another’s are joined; the one that started it is fetched or revalidated. That holds for fills (apt packages, registry and LXD blobs), Go .mod and .zip files and the documents ServeDoc serves, whose shared fetches say which request started them (internal/flight). A registry manifest’s does not yet, so all the requests that shared one are joined.