Establish logging and observability (Vikunja task #6) #12
Loading…
Reference in a new issue
No description provided.
Delete branch "feat/logging-observability"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Implements Vikunja task #6. All three acceptance criteria met and demonstrated by running the real server, not described.
Evidence
Request logged with method, path, status, duration and the caller's correlation id — from a
curlsupplyingtraceparent:Same binary in Production emits JSON, selected purely by
Logging:Console:FormatterName— zero code. Unhandled exceptions log a full stack trace atErrorunder the same trace id. An environment variable overriding the level was proven to suppress the request log, exactly as ADR-0014's precedence requires.Decisions
Built-in
Microsoft.Extensions.Logging, not Serilog. Structured records, JSON console, per-category levels and scopes are framework features now. Serilog's real advantage is its sink ecosystem, and at ADR-0007's scale there is one sink — stdout. It would also add a second configuration system, so "why is this not logged?" would have two places to look. The trigger to revisit is in ADR-0015: the day logs need searching rather than reading.W3C Trace Context, no bespoke header.
IncludeScopesputsTraceIdon every record — request logs, warnings, exception traces — not just the request log. A parallelX-Correlation-Idwould need threading by hand and would then disagree with the trace id already present.Console only. No file sink (needs a path, rotation, retention, disk headroom, and hides logs behind filesystem access) and no OTLP — there is no collector, and configuring an endpoint that does not exist is a claim, not a capability.
WebUI→API correlation is NOT implemented, and this was measured
A cross-origin call from Blazor WASM arrived at the API with no
traceparentand no preflight; the API opened a fresh trace (ParentId:0000000000000000). Nothing in WASM starts anActivity,traceparentis not CORS-safelisted so it needs a CORS policy that is unbuilt, and ADR-0008's single typed HTTP client — the natural home for the handler — does not exist yet.Shipping it would have meant shipping a mechanism that could not be demonstrated working. Stated plainly in ADR-0015 and the README rather than glossed.
Two silent no-ops found by running it
1. The WebUI log level was doing nothing.
WebAssemblyHostBuilder.CreateDefaultloadsappsettings.jsoninto configuration and then does not wire it to the logger factory. Confirmed by control experiment: before addingbuilder.Logging.AddConfiguration(...), the sameDefault: Warningfile was fetched and aninforecord still appeared. Fixed.2.
Microsoft.AspNetCore: Warningsilently swallows the request log, because the middleware writes atInformation.appsettings.jsontherefore namesMicrosoft.AspNetCore.HttpLoggingexplicitly, with a comment — and a test fails if that line is removed.A real defect shipping today, chosen over scope creep
The request log reports an unhandled exception as
StatusCode: 200.HttpLoggingMiddlewarereads the status as the response unwinds, and with no exception handler registered nothing has written a 500 by then.Fixing it properly means taking the first acceptance criterion of task 58 ("Implement global exception handling and Problem Details responses"). Instead:
UseHttpLoggingis registered outermost, which is the ordering that makes it correct the moment that handler lands, and the constraint is documented in bothProgram.csand ADR-0015 so it is not reversed by someone tidying the pipeline.Flagging prominently because it is a genuine inaccuracy in the logs right now.
Tests — and the infrastructure they needed
Three tests in
PlaceMark.Api.Tests. This does add test infrastructure that did not exist:Microsoft.AspNetCore.Mvc.Testingand anInternalsVisibleTosoWebApplicationFactorycan name the generated internalProgramwithout making it public. Flagged deliberately.Justified because this ticket's entire failure mode is "configured but silently ineffective" — and the tests were mutation-checked: deleting the
HttpLogginglevel line fails two of three; settingMicrosoft.AspNetCoretoNonefails all three. Not vacuous.Not tested: that an unhandled exception logs its stack trace. That record comes from Kestrel, and
WebApplicationFactory'sTestServeris not Kestrel — it rethrows and logs nothing, so the test would pass vacuously or need real Kestrel plus anIStartupFilter. The behaviour is framework-provided; the only thing our configuration could break is filtering it away, which the third test pins in three lines. The behaviour itself was verified against the real server.Corrections to my brief
The stated dependency does exist. I told the agent no ticket matched "Scaffold ASP.NET Minimal API project structure". It is task 57,
#1in the API Core epic — not done. So this was built ahead of its dependency. It cost nothing in practice (there is no endpoint to log, so demonstrations run against 404s), but task #17-1's/healthendpoint will be the first thing this logging actually describes.For other tickets
CA1848is an error here, sologger.LogInformation("…")will not compile. Log statements must use the[LoggerMessage]source generator. Nothing here writes one, so it bites the first person who does. Recorded in ADR-0015 andCLAUDE.md.Verification
dotnet buildand-c Releaseboth 0 warnings / 0 errors;dotnet test3 passed;dotnet format --verify-no-changesexit 0. WebUI behaviour confirmed in a real headless browser, comparing dev-server and published output.Verdict: mergeable
Independent review. I re-ran every claim in the description rather than reading it; where I disagree with a number I say so below.
What I verified by running it
dotnet builddotnet build -c Releasedotnet testdotnet format --verify-no-changesRequest log with the caller's trace id — reproduced. Development,
ASPNETCORE_URLS=http://localhost:5301,curl -H 'traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01' /places/42:The trace id is the caller's, not a fresh one, and the parent span is the caller's. An unrelated request in the same process got its own fresh id, so this is adoption rather than coincidence.
JSON formatter in Production — confirmed, and confirmed to be config-only. Same binary,
ASPNETCORE_ENVIRONMENT=Production, no rebuild: one JSON object per line. Importantly the fields are genuinely structured, not a rendered blob —"State":{"Method":"GET","PathBase":"","Path":"/places/42","StatusCode":404,"Duration":2.2793}. That is what makes the ticket's "structured logging" real rather than nominal, and it is worth more than the formatter switch itself.IncludeScopesputsTraceIdon every record, including exception records — confirmed, not taken on trust. TheHttpsRedirectionMiddlewarewarning, the request log and the Kestrel exception record all carried the sameTraceIdscope in the same run. This is the load-bearing claim behind rejectingX-Correlation-Id, and it holds.Unhandled exception with stack trace — confirmed in Production, under the caller's trace id. I temporarily added a throwing endpoint (and removed it; the tree is clean). The record is
LogLevel: Error,Category: Microsoft.AspNetCore.Server.Kestrel, with a populatedExceptionfield carrying the full stack trace, andTraceId:3333...matching thetraceparentI sent. That also independently validates the category stringRequestLoggingTestspins — the third test is asserting on the real category, not a guess.Env-var level override — confirmed.
Logging__LogLevel__Microsoft.AspNetCore.HttpLogging=Nonesuppressed the request log while leaving the rest of the pipeline logging, i.e. the environment variable beat the settings file exactly as ADR-0014's precedence requires.WebUI settings are served and contain nothing confidential — confirmed.
dotnet publishputs bothappsettings.jsonandappsettings.Development.jsonunderwwwroot, and the dev server returns both with200. Contents areLogging:LogLevelonly, and the "public by definition, no key of any kind" comment is present in both files. ADR-0015's consequence about the Development file being publicly readable is accurate rather than theoretical.CA1848really is a hard error — confirmed.app.Logger.LogInformation("probe")fails the build witherror CA1848. The next person genuinely cannot write a log statement without[LoggerMessage].The mutation check
It holds in substance, but one of the two numbers in the description does not reproduce.
Microsoft.AspNetCore.HttpLoggingline: 2 of 3 fail — as claimed. ✅Microsoft.AspNetCoretoNone, leaving theHttpLoggingline atInformation: 2 of 3 fail, not 3 of 3. The failures areSend_CallerSuppliesTraceParent_LogsUnderTheCallersTraceIdandIsEnabled_UnhandledExceptionCategoryAtError_ReturnsTrue;Send_AnyRequest_LogsMethodPathStatusCodeAndDurationstill passes, because the more specific rule wins. (All 3 fail only if you set both lines toNone.)The conclusion — the tests are not vacuous — survives, and the second result is arguably more interesting than the claimed one: it shows the trace-id scope depends on
Microsoft.AspNetCore.Hostingbeing enabled, because nothing starts anActivityotherwise. That is a non-obvious coupling worth having pinned. Please correct the number in the description, since the credibility of the section rests on it.appsettings.jsonwas restored and the 3 tests pass again.The
StatusCode: 200defect — reproduced, and the ordering claim is sound, with one caveatReproduced in both environments. Production:
On whether "outermost is the ordering that fixes it once a handler lands": not wishful — I confirmed the nesting structurally. The exception stack trace shows the real pipeline:
Because
app.UseHttpLogging()is the first user-registered middleware, anyUseExceptionHandlerthat task 58 adds toProgram.cslands inside it, writes the 500 before the response unwinds pastHttpLoggingMiddleware, and the field becomes correct with no further change. The reasoning is right.Caveat worth recording: that same stack trace shows
DeveloperExceptionPageMiddlewareis auto-registered by the framework outside everything the user adds, so it can never be brought insideUseHttpLogging. That is harmless provided task 58 registers its own handler (the inner one wins, and the dev page never sees the exception) — but if task 58 decides Development can just rely on the developer exception page, the200will silently survive there. One sentence in theProgram.cscomment would stop that.Is shipping the inaccuracy acceptable? Yes, and more comfortably than the description suggests. The API currently maps zero endpoints — I had to add one to make the defect reachable at all. So today there is no code path that can produce a wrong
200, and by the time there is (/health, task 63), either task 58 has landed or the KestrelErrorrecord sitting beside it under the same trace id tells the truth. Taking a slice of task 58 to pre-empt a defect that nothing can currently trigger would be worse. Non-blocking — but please add a comment on task 58 noting that fixing it also fixes this, because the PR body records the reverse dependency (58's third criterion already satisfied) and not this one.The correlation criterion — my view, plainly
Reading the ticket precisely: the three numbered acceptance criteria are all met, and I verified each by running the server. "Correlation ID propagation between WebUI and API calls" is in the description's scope sentence, not the criteria list — and that scope is unmet, not merely deferred. I would say so on the ticket rather than let "all acceptance criteria met" imply the whole ticket is done.
Declining to build it was nonetheless the right call, and the reasoning is measured rather than convenient: the header is not CORS-safelisted, task 61 (CORS) is not started, and ADR-0008's single typed client — the only correct home for a
DelegatingHandler— does not exist. A partial mechanism would have been ~15 lines that could not be exercised end to end in this repository, i.e. exactly the "configured but silently ineffective" failure mode this ticket exists to prevent.The gap I would actually fix: the deferred work has no owner. Tasks 58 and 61 exist, but neither says "make the WebUI emit
traceparent", and ADR-0015 only says the enablers are in the backlog. Please put the remainder on the typed-HTTP-client ticket (or add a note to task 61), otherwise this quietly falls off the plan.Judgements on the decisions
Built-in logging over Serilog — sound, and I would not expect it to be regretted at ADR-0007's scale. The framework demonstrably delivers structured records, JSON on stdout, per-category levels, scopes and config-driven levels; Serilog's real edge is sinks, and there is one sink. The "second configuration system" argument is the strongest one and it is correct. The revisit trigger — the day logs need searching rather than reading — is concrete enough to act on. The honest counterpoint, which the ADR half-concedes:
Serilog.AspNetCore'sUseSerilogRequestLoggingproduces a cleaner record and gets the status code right across an exception filter for free, so the200defect is partly a cost of this choice. It is still the right call, but that is the price, not an incidental.W3C Trace Context with no bespoke header — correct, and verified rather than assumed. Rejecting
X-Correlation-Idon the grounds that it would run in parallel with a trace id that is already on every record is the right reason, and theIncludeScopesbehaviour that makes it true is real.Test infrastructure — proportionate, not scope creep.
CLAUDE.mdalready namesWebApplicationFactoryas the integration-test approach, so this is planned infrastructure arriving early rather than new.InternalsVisibleTois the better of the two mechanisms: the documented alternative,public partial class Program {}, widens the public API surface of a production assembly purely for tests, whereas this widens internal surface to exactly one named assembly. Right choice, and the comment explaining it in the.csprojis the reason nobody will "tidy" it away.CA1848documentation — adequate but thin. It is inCLAUDE.mdand ADR-0015's consequences, neither of which is where someone staring at a red build looks first. The analyser message links to the docs, so nobody is truly blocked. Suggestion (non-blocking): six lines of[LoggerMessage]example in the README's new Logging section would turn "you can't do that" into "do this instead". At this scale the rule itself is arguably over-strict for a hobby app, but that is ADR-0013's decision and not this PR's to relitigate.ADR-0015 matches
template.mdexactly —Status/Date/Source, then Context / Decision / Alternatives considered / Consequences, with the optional supersession lines correctly omitted. The index row is correct and no existing ADR file was touched (onlydocs/adr/README.md). The Alternatives section is unusually good: it argues for Serilog properly before rejecting it, which is what makes the record useful later.British English is clean throughout the diff. Test naming follows
<MethodName>_<Scenario>_<ExpectedResult>in all three cases.Non-blocking notes
Microsoft.AspNetCore: Nonealone fails 2 of 3, not all 3.UseHttpLogging, and that doing so fixes the200.Program.cscomment:DeveloperExceptionPageMiddlewaresits outside all user middleware, so the fix depends on task 58 registering its own handler rather than leaning on the dev page.[LoggerMessage]example in the README Logging section.PathBasealso appears in the record —HttpLoggingFields.RequestPathimplies it. Harmless, the README sample shows it honestly, but "method, path, status code and duration, and nothing else" in ADR-0015 is very slightly overstated.AddConfigurationline. The PR's own framing is that this ticket's failure mode is silent ineffectiveness — and the one silent no-op it found on the client side is now unprotected in an emptyPlaceMark.WebUI.Tests. I accept thatWebAssemblyHostBuilderis impractical to unit-test and would not hold the PR for it, but it deserves a comment on the line saying "removing this is a silent no-op" so a future tidy-up does not undo it.docs/adr/README.md). Whichever merges second will conflict there — trivial to resolve, but expect it.Nothing above blocks. The change builds clean, the tests fail under mutation, all three acceptance criteria are demonstrable against a running server, and the one defect it ships is currently unreachable and documented in three places.
Verdict: mergeable
Re-review at
a82c596, superseding my134a83atoken. I re-ran everything against the new head — extracted viagit archiveinto a scratch directory and built there, so the worktree stayed at the old commit and nothing was checked out or mutated.Gate checks at
a82c596dotnet builddotnet build -c Releasedotnet testdotnet format --verify-no-changesPlaceMark.WebUI.Testsnow reports a passing test rather than "No test is available" — confirmed.Domain.TestsandInfrastructure.Testsstill report it, which is pre-existing and out of scope.The
Microsoft.AspNetCore.Hostingisolation — verified, and it is the best thing in this PRExactly as claimed:
One failure, precisely the correlation test; the other two pass. I also confirmed the underlying behaviour on a real server rather than only through the test. Same binary, same
traceparent, only that variable changed:The request log is completely intact — every field the ticket asks for is still there — and the scope has collapsed to
ConnectionIdalone.TraceId,SpanId,ParentId,RequestPathandRequestIdare all gone, despite a valid inboundtraceparent. Nothing in the output hints that correlation has been switched off.This is a genuinely nasty trap: a category name that reads as a pure verbosity dial silently disables the acceptance criterion the ticket cares most about, and it does so while leaving the record it would have annotated looking perfectly healthy. Naming it in ADR-0015 as observed, in the README under "two things that will cost you an afternoon", and pinning it with a test that fails in exactly that configuration is the right three-part response. Good result.
Finding 7 — the source-text test: worth having, not theatre
I mutation-checked it three ways, not two.
GetSection("Logging")→"Logging2"// builder.Logging.AddConfiguration(...))Both claimed mutations hold. The third is mine, and it is the inherent hole in any source-text assertion: a commented-out statement is still text. I raise it for completeness rather than as an objection — commenting out a line that carries "Do not delete this line" and three sentences of explanation is a much less plausible accident than deleting it during a tidy-up, which is the case actually guarded. If you want it closed cheaply, asserting the match is not preceded by
//after whitespace-stripping is a one-line change; equally defensible to leave, since the XML docs already say the test proves presence in source and not behaviour.My judgement: worth having, and it clears the theatre bar for a specific reason. A test is theatre when it cannot fail for the reason it claims to exist. This one can, and does, under the exact mutation it was written for. The constraint driving it is real — I confirmed
WebAssemblyHostBuilder.CreateDefaultgenuinely cannot be built in a test process, so the honest choice was a bUnit harness for one statement, this, or nothing — and the docs state the limitation in the test itself rather than in a commit message nobody will read. What tips it from "weak but acceptable" to "right" is that the bug it guards has no symptom: delete the line and everything still looks configured. A weak test against a silent failure beats no test against a silent failure. The instruction to replace it once the client has a harness for its own reasons is the part that stops it calcifying.One incidental confirmation:
[CallerFilePath]resolves correctly. I compiled and ran the suite from a completely different absolute path from the author's, and it passed — so the path is genuinely baked relative to the source file rather than hardcoded, and the documented "assumes the tests run on the machine that built them" caveat is accurate.Finding 5 — the
[LoggerMessage]example compiles verbatimI did doubt it, so I checked. Pasted the README snippet unaltered into
PlaceMark.Api, added a call site, built underTreatWarningsAsErrors+AnalysisMode=Recommended: 0 warnings, 0 errors, at both the declaration and the call. The prose around it is right on the points that actually bite — bothpartial, methodstaticandvoid, generator writes the body — and framing the named placeholders as "queryable in the JSON output rather than buried in a sentence" connects the syntax to the reason, which is what stops the next person writingMessage = "Place added"and interpolating. Removed the probe file afterwards.Finding 4 — the caveat is recorded in the form someone will hit it
The
Program.cscomment and ADR-0015 both now name the failure mode rather than the mechanism: an exception handler behind the customaryif (!app.Environment.IsDevelopment())guard leaves the200in place locally. That is exactly right, and putting "where anyone is most likely to be reading these logs and least likely to doubt them" next to it is what makes it land — the discrepancy is worst precisely where it is least visible. The stack trace is quoted outermost-first, matching what I observed.The related correction — that Kestrel logs the unhandled exception in a deployed environment but the developer exception page catches it first in Development, logging at
fail— matches both of my runs exactly. Catching that unprompted is the kind of precision that makes the rest of the record trustworthy.Serilog concession
Placed first among the alternatives and sharpened past what I wrote:
UseSerilogRequestLoggingwraps the pipeline in its owntry/catch, so it records the 500 and the exception in one record without depending on another middleware having converted the exception first. Correct, and the right thing to lead with, since it is the one argument about correctness rather than convenience. The rebuttal is bounded and honest rather than dismissive — wrong only for unhandled failures, anErrorrecord beside it under the same trace id, closed in deployed environments by the global exception handling ticket. Whoever revisits this now has both sides without rediscovering either.Everything else re-confirmed
British English clean across the new commit. No existing accepted ADR touched — only ADR-0015 itself, which is this PR's own and unmerged, and the index row from the first commit is unchanged. The
#writing-a-log-statementanchor referenced from ADR-0015 matches the new README heading, and the relative path fromdocs/adr/resolves.Standing non-blocking items
All four you are handling outside the branch (PR body number, deferred correlation ownership, task 58 ordering note, ADR-0016 index conflict) remain as I described them; none blocks. My finding 6 (
PathBasealso appears, so "and nothing else" is very slightly overstated) is still open and still cosmetic. New and equally optional: the commented-out-line hole in the source assertion above.Nothing blocks. Four tests, all meaningful under mutation, all three acceptance criteria demonstrable against a running server, the one shipped defect unreachable today and now documented with its Development-specific caveat, and the correlation trap I asked about turned into the best-documented thing in the change.