[DMS-1228] Make CMS request logging structured#1063
Merged
Conversation
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
CodeQL found more than 20 potential problems in the proposed changes. Check the Files changed tab for more details.
jleiva-gap
force-pushed
the
DMS-1228
branch
4 times, most recently
from
e0b7b13 to
9bae3b8
Compare
Squash-rebase of the DMS-1228 structured request logging work onto origin/main (currently at DMS-1227's 413 handling). The original pre-rebase history is preserved on the local branch DMS-1228-pre-rebase-backup. Rebase conflicts were resolved against DMS-1227's oversized-request-body 413 handling so the LoggingMiddleware BadHttpRequestException path continues to short-circuit oversized requests while participating in the structured logging pipeline. Structured request logging spans both services: - CMS RequestLoggingMiddleware emits structured start/completion events with a per-request BeginScope. - DMS Core RequestResponseLoggingMiddleware and the DMS frontend LoggingMiddleware emit HttpRequestCompleted / HttpRequestFailed contract events with sanitized correlation values. - Shared EventId definitions live in per-service RequestLoggingEventIds classes. - docs/LOGGING.md documents the request-log contract; the docker-compose effective-schema-hash module and its Pester tests are included.
Correctness: - Restore context.TraceIdentifier as the 500 error-response body traceId; the sanitized correlation value is used for log events only. - Emit a Debug "Request started" breadcrumb in CMS request logging so a hung request still produces a log line. - Emit the 413 oversized-body path as an HttpRequestCompleted contract event (StatusCode 413) instead of a bare Warning, so it is visible to the collector contract; the expected control-flow exception is not attached (S6667 is suppressed narrowly with justification). - Allow empty log output in the effective-schema-hash module (@() -> null). - Fix "after"/"in" DurationMs template drift in DMS core middleware. - Restore request identity (method/path/traceId) in the rethrow message so host-level logging retains correlation after the scope is disposed. Cleanup: - Collapse the CMS duplicate LogError to one nullable-exception call, replace scope-dictionary readbacks with locals computed once, and simplify GetFailureStatusCode in both frontends. - Remove the unused HasLongStructuredProperty helper, the duplicate DMS-app appsettings test and its now-unused helpers, and the dead legacy string-formatter branch; modernize the test TestLoggers. Docs: - Document the 413 completion path and the outputTemplate/JSON-formatter footgun in LOGGING.md and the DMS appsettings example. Known tradeoff: the per-request logging scope is still constructed unconditionally (not IsEnabled-gated) to preserve downstream scope enrichment.
…rilog appsettings binding Address review findings on the structured request logging work: - DMS frontend LoggingMiddleware now writes the same sanitized trace id in the 500 error response body that the request log events carry as TraceId, so a client-reported trace id can be located in the logs when CorrelationIdHeader is configured. This also matches the rest of DMS, where core FailureResponse bodies already return the correlation-aware value. The unit test that previously codified the divergence now asserts the body and log values match. - Add an end-to-end Serilog binding test to both CMS and DMS frontend unit suites. Each test loads the application's real appsettings.json, builds LoggerConfiguration().ReadFrom.Configuration(...).Enrich.FromLogContext() exactly as WebApplicationBuilderExtensions does, captures console output, and asserts the emitted line is newline-delimited JSON carrying the request-log contract properties, EventId, and RenderedMessage. The file sink path is redirected to the test work directory so creating the logger does not write into the repository. The existing JSON-shape tests remain as fast-failing complements. - Fix a vacuous-pass hazard in the JSON assertions added on this branch: null-conditional chains like properties?["X"]?.GetValue<T>().Should() silently skip the assertion when the property is missing. All such chains in the two request-logging test files are now parenthesized so a missing property flows into the assertion as null and fails. - Document the request logging EventId values (1228001/1228002) in docs/LOGGING.md as the source of truth shared by CMS and DMS, point both RequestLoggingEventIds class comments there, and pin the values with unit tests in both applications (DMS was missing its pin). EventId equality ignores Name, so the tests assert Id and Name separately. - Document in docs/LOGGING.md that the file sinks intentionally share the JSON formatter: file logs carry the same structured properties but are not part of the console collector contract and omit RenderedMessage. Cross-application sharing of the event-id type, test helpers, and log construction was reviewed and deliberately not done: CMS and DMS build as separate solutions with no shared assembly, so the documented contract plus per-application pinned tests are the drift control.
- DMS 413 completions log the status the client actually received when the response already started - CMS GlobalExceptionHandler no longer logs; HttpRequestFailed from the request middleware is the canonical (structured) request error event - CMS request middleware no longer mutates the logging scope after BeginScope; StatusCode/DurationMs travel in event state only - LOGGING.md examples now include EventId and a DMS example with RequestLayer; EventId JSON shape pinned in both contract tests - effective-schema-hash structured-hash regex made explicitly case-insensitive for consistency (behavior unchanged; -match was already case-insensitive)
- DMS frontend 500 error body now echoes the raw extracted correlation
value instead of the log-sanitized form. Sanitizing the body was an API
contract change unique to frontend-generated 500s: every core
FailureResponse body already returns the raw traceId.Value. Log events
still carry the sanitized TraceId; body and logs differ only when a
client-supplied correlation id contains characters outside the logging
whitelist, and applying the whitelist to a client-reported id yields
the logged value. A new unit test pins the raw-body/sanitized-log
divergence; the round-3 alignment test is renamed to match the settled
contract.
- docs/LOGGING.md failure-contract clarifications: the Exception field
carries the exception the logging layer itself observed, so a DMS
frontend HttpRequestFailed for a downstream 5xx has Exception null and
correlates to the core-layer event via TraceId + RequestLayer. CMS
handled 400s (malformed bodies, validation failures) are documented as
intentional HttpRequestCompleted events with no exception payload,
replacing the previous Error-level exception-handler logs. Corrected
the claim that CMS rethrows handled exceptions: only exceptions the
exception handler does not observe propagate through the request
logging middleware, which logs and rethrows them. The
GlobalExceptionHandler comment is updated to match.
- Simplified eng/docker-compose/effective-schema-hash.psm1: removed the
unreachable string/array recursion and PSObject property lookup. The
only JSON path is ConvertFrom-Json -AsHashtable on lines starting with
'{', which always yields dictionaries, so event handling is now inline
in Get-EffectiveSchemaHashFromLogLine.
- LogSanitizer.ReplaceLineEndings is kept with an explanatory comment:
it is behaviorally redundant with the whitelist (every character it
strips is already rejected) but CodeQL models ReplaceLineEndings as a
log-forging sanitizer and does not recognize the custom whitelist loop.
Verified: DMS frontend unit 254 passed, CMS frontend unit 464 passed,
effective-schema-hash Pester tests 9/9, csharpier formatted.
…ests The two Serilog JSON contract tests in RequestResponseLoggingMiddlewareTests used null-conditional chains into .Should() (properties?["X"]?.GetValue<T>().Should().Be(...)), so a missing Properties node or property short-circuited past the assertion and the test passed vacuously, leaving the DMS core request-log collector contract unprotected. All twelve chains in the two test methods are now parenthesized ((properties?["X"]?.GetValue<T>()).Should().Be(...)) so a missing property flows into the assertion as null and fails. This applies the same fix commit 827cf22 made to the CMS and DMS frontend request-logging test files, which had missed this DMS core file. The remaining occurrences of the unparenthesized pattern in the repository are in pre-existing test files outside this story's diff and are left as-is. Verified: Given_RequestResponseLoggingMiddleware fixture 8/8 passed, csharpier formatted.
…tion naming
Address two review findings on the request logging work:
- docs/LOGGING.md claimed request events carry "Exception": null when no
exception exists, but Serilog.Formatting.Json.JsonFormatter omits the
Exception field entirely when the log event has no exception attached.
Since the document is declared the collector contract, rules written
against a null-valued field would never match. Removed the
"Exception": null line from both the CMS and DMS examples and rewrote
the failure-log prose: the field is present only when the logging layer
itself observed an exception, and collectors must treat it as optional.
The omission behavior is pinned with ContainsKey("Exception") == false
assertions in the CMS and DMS frontend JSON shape and appsettings
binding tests and the DMS core JSON contract test, so a formatter
change that starts emitting a null field fails a test instead of
silently diverging from the documented contract.
- Renamed RequestInfo.UnhandledException (added on this branch) to
CaughtException: the property holds the exception
CoreExceptionLoggingMiddleware caught and converted into a 500
response, and its own XML doc already called it a handled exception.
Updated the XML doc to describe the capture-for-outer-logger intent.
CoreExceptionLoggingMiddleware's class summary still said it logs
requests and responses from before this branch removed its LogError;
it now describes the actual behavior: convert escaping exceptions to
error responses (403 for authorization failures, 500 otherwise) and
capture the 500-path exception for the outer request logging
middleware without logging it. The class name itself is pre-existing
and left unchanged.
Verified: DMS core Given_RequestResponseLoggingMiddleware 8/8, DMS
frontend Given_LoggingMiddleware 18/18, CMS RequestLoggingMiddleware
tests 18/18, csharpier formatted.
bradbanister
approved these changes
Jul 8, 2026
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
4 participants
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.
No description provided.