goss: replace global logging with injectable structured records - #1119
Draft
dukelion wants to merge 9 commits into
Draft
goss: replace global logging with injectable structured records#1119dukelion wants to merge 9 commits into
dukelion wants to merge 9 commits into
Conversation
goss is moving from the process-global log package to log/slog with a logger supplied by the caller. This is the first step: the level and the helpers the rest of the migration builds on, with no call site converted yet. LevelTrace is a constant below slog.LevelDebug, so a logger configured at DEBUG suppresses trace records. Standard handlers have no name for it and would render "DEBUG-4", so ReplaceTraceLevel carries the exact slog.HandlerOptions.ReplaceAttr signature and rewrites just the built-in level attribute. An embedder installs the same function rather than reimplementing goss's convention. Trace and TraceContext build the slog.Record by hand instead of calling Logger.Log, so the source position on the record is the caller's own. Both consult Enabled before doing that work and both route through LoggerOrDiscard, which is the guard every later derivation uses: util.Config is documented as usable as a composite literal, so its logger will be nil in ordinary embedded use, and a nil *slog.Logger panics on every method that matters. There is deliberately no slog.Default() fallback; silence is the correct default for library records. Refs: goss-org#1093
Adds the injection points the call-site conversions will read from, with no call site converted yet, so this commit changes no behaviour. util.Config gains a Logger field and a WithLogger option; util.OutputConfig gains the same field for the outputs/ sites. NewConfig deliberately does not default it. Resolving a level or a destination in the constructor would silently disable logging for the hand-built literals that util/config.go documents as the embedding pattern, and any default would be a destination the embedder did not choose. system.New becomes variadic over a new Option type with system.WithLogger, so every existing positional call keeps compiling. The System's logger is read back through an unexported guarded accessor rather than the field, because a System is constructible as a literal and New is callable without options, leaving the field nil in both cases. Refs: goss-org#1093
Under slog the level belongs to the handler, so the CLI resolves --log-level to one and injects the resulting logger through the runtime config. The library will interpret no level string once the last reader of util.Config.LogLevel is gone; until then the normalised value is still written to that field, because setLogLevel remains a reader on the validate, serve and add paths. newRuntimeConfigFromCLI now returns an error, which makes an unsupported level fail consistently. Today validate, serve and add reject one through setLogLevel while render and autoadd accept it silently and carry on, because they never called that function. Every executable action is built through one wrapper that runs the unchanged platform gate, constructs the runtime config, and returns its error without invoking the operation. Alpha rejection therefore keeps winning when both the platform and the level are unacceptable. The operations the actions call are held in an injected set, so the tests drive the real app, flags and actions without replacing an Action or exiting the test process. alphaRejected and alphaMessage split the platform decision and its diagnostic out of fatalAlphaIfNeeded, which makes the darwin and windows behaviour testable from any host while the log-and-exit stays where it was. The handler renders TRACE through the exported hook and normalises record timestamps to UTC. UTC is applied by a handler wrapper rather than ReplaceAttr because ReplaceAttr cannot tell slog's own time field from a user attribute that happens to be named "time". Refs: goss-org#1093
Two log sites had no route to a config, for different reasons, and both are now reported through the injected logger. The duplicate-resource warning was emitted from mergeType, five frames below the entry point, with no config or logger in any of them, and the chain crosses the exported GossConfig.Merge. Only mergeType knows whether the destination map already held the key, so detection stays there and an unexported callback carries the report up to the operation root that does have a logger. Merge keeps its signature and passes no callback, so a direct call is silent rather than writing to the process logger; getGossConfig and RenderJSON, whose callers all have a config, build the callback from it. getGossConfig now takes that config instead of three of its fields. The empty-configuration message was blocked by something else entirely: WriteJSON returns nil whether it wrote the file or declined to, so its two callers could not tell which had happened. An unexported writeJSON reports that, leaving the exported contract exactly as it was, and both add roots warn through their own logger and still return nil. The message also becomes filterable in the process. It carries no level prefix today, so the prefix filter emits it at every level including ERROR. Refs: goss-org#1093
Every serve site now emits through the config's logger, with its data in attributes rather than formatted into the message. The per-request record keeps its response-body gate, which is load-bearing: attaching the body unconditionally would put every check's result into the log of every successful probe. What changes is that the body is now the raw response under its own key, without the " - " prefix that used to join it to the message. The cache-miss message loses cacheMissLogFormat entirely. Its "[DEBUG]" prefix existed so the old filter could match on it, and a constant carrying a level and a format verb is exactly what a structured record replaces. Both tests that counted it, the cache regression test and the concurrent cold-cache dedupe test, now count records instead of substrings, and neither needs the process logger to do it. Serve builds its http.Server through newServer so that http.Server's own errors reach the configured logger at ERROR. That bridge hands over one preformatted message with no structure to recover, so it is the single record goss emits that is not built from attributes. Production still passes a nil handler, which keeps DefaultServeMux exactly as it was; the parameter is there so a test can run a real server without registering on a process-global mux. processAndEnsureCached takes a context, which gives TraceContext its callers, and the redundant System construction it did is gone: validate() builds one again two lines later. Refs: goss-org#1093
This converts the last library call sites. Subject command output and the per-result traces are the two highest-volume records goss produces, and both now carry their data in attributes. Command output records carry both the resource id, which is what the old message identified them by, and the command that actually ran, which is a different string whenever a resource sets an explicit exec. Reading the id needs no repair here: the context key it is stored under is exported. The line splitting is unchanged, including the empty record a trailing newline produces, because anything counting records would notice that going away. The two summary sites in each of json and rspecish collapse into one record per Output call. They differed only in the word in front of an otherwise identical payload, which is now a status attribute. json keeps the serialised document it always logged; rspecish keeps its counts and duration, which were its whole summary, minus the colour escapes the printed form carries. Every remaining System construction and both OutputConfig literals pass the logger, including the two places a System is rebuilt mid-operation: the validate retry loop and serve's cache expiry. A missed one there would lose logging for every attempt after the first, so a static test enumerates the construction sites as well as driving them. Exit codes and HTTP statuses are pinned across all nine outputers, passing and failing, because two Output methods changed and neither may move a code. The json outputer stops calling every result that did not fail a success. That was survivable when the word sat in prose next to the result number and is not survivable as an enum attribute named outcome, so skipped results now say so, as they always have under rspecish. The trace test drives all three outcomes through both outputers rather than one outcome through each, which is what let the disagreement through. Refs: goss-org#1093
Nothing reads them any more. logs.go held a logutils filter that matched a "[LEVEL]" prefix on each message, which is incompatible with structured records by construction, and setLogLevel, which reconfigured the process-wide logger's writer and flags on three of the nine operations and never put them back. An embedder who called goss had their own logging quietly rearranged. util.Config.LogLevel goes with them. It is removed rather than deprecated because its only remaining use was a keyed write in a composite literal: a deprecation marker warns on reads, so an embedder would have got a clean build and no logging, while removal gives them a compile error. It is not coming back either. Under slog the level belongs to the handler, and reintroducing the string would restore the two sources of truth that produced the --debug and --log-level overlap. --log-level now works under render and autoadd, where it was documented but inert because neither called setLogLevel. The static tests are the point of this commit as much as the deletions. "No library code writes to a process logger" is a claim about every file, not about the paths a test happens to drive, so the log import, the logutils dependency, slog.Default, the removed field, level-string interpretation, the handler's writer and the alpha gate's ordering are all checked across the module. slog.Default in particular is invisible to sloglint's no-global setting, so nothing else would catch a global logger returning that way. Refs: goss-org#1093
sloglint is what keeps the conventions from decaying: constant messages, snake_case keys, lowercased text and no global logger. util.Trace and util.TraceContext wrap Log and LogAttrs, so the linter needs their message and argument positions declared or it skips them, and skipping them would leave every TRACE site unchecked. The two custom-funcs entries are the whole reason the wrappers are safe to have. The issue caps are raised because they are not off by default: golangci-lint stops at 50 issues per linter and 3 per identical message, which it applies silently. The first run of this configuration reported three violations in one test file when there were five. A gate that reports part of the tree teaches you to trust it anyway. The new tests cover what the linter cannot. One pins the whole flag inventory, including -l being bound both globally and by serve's --listen-addr, because "adds no flag" is a claim about the entire command tree and this change deliberately reuses the existing --log-level rather than adding --log-format. Another checks that the seams introduced for testability have no test-only branch, which is the failure mode dependency injection invites: newServer, newApp, newCLIHandler, the alpha helpers, the operation set, the action wrappers and the UTC handler all take injected values or pure inputs and behave identically under test. docs/logging.md documents levels, the record schema, embedding, TRACE hook composition and what the records can contain. The sensitive-fields section is not reassurance: output, actual, expected and response_body were message text before and are queryable named fields now, nothing is redacted, no attribute is capped, and readers need to know that before they ship goss records to an index. The CLI page loses its claim that --log-level may appear after the command name, which was never true and cost a previous investigation time: --log-level is a parse error there and -l binds --listen-addr under serve. Refs: goss-org#1093
The strict site build has been failing on these, so nothing else could be checked by it. All three are links to anchors that do not exist: two to #patterns, which was never a heading, and one to #global-options from a page that does not have that section. The pattern syntax they mean is documented under io.Readers, which is where the "!foo" and "/regex/" forms are listed, and the global options are on the CLI page. Nothing else changes: no text, and no other link. Found while adding docs/logging.md, whose gate is that same build.
Contributor
Author
|
It turned out quite large and needs a bit more non-substantial polishing before the merge. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
log/slogloggersTRACElevel, structured record schemas, and CLI-owned UTC renderingCloses #1093.
Discussion points
util.Config.LogLevelis removed; callers configure levels on their handlersystem.Newgains variadic options andutil.OutputConfiggainsLoggerGossConfig.Mergecalls become silent because that API has no loggergorelease -base=v0.4.10recommendsv0.5.0because of the intentional API incompatibilitiesVerification
Passing locally:
go vet ./...go mod verifygolangci-lint v2.12.2 run --timeout 5m ./....venv/bin/zensical build --strict-race -shuffle=onKnown discussion issue:
go test -race -shuffle=on ./...can fail under heavy local parallel load when command-backed serve tests reach the inherited 10-second command timeout; the timeout path returns beforecmd.Runfinishes and the race detector then reports concurrent buffer access. This draft leaves the existing production timeout implementation unchanged, but the new command-backed tests should be serialized or moved to non-subprocess fixtures before merge.Scope
The final documentation-only commit repairs three pre-existing broken anchors required for the strict documentation build.
📚 Documentation preview 📚: https://goss--1119.org.readthedocs.build/en/1119/