Files
Fuchs_Intranet/Fuchs/Docs/Concepts/error-logging-pipeline.md
T
StefanandClaude Sonnet 5 bcf1f2dbb6
Playwright Tests / test (push) Canceled after 0s
feat: migrate DB error logging onto the generic OCORE MultiLogger SQL sink
Retires Fuchs_intranet.debug_log() and every direct EXECUTE [dbo].[fds__admin_logdebug]
call in favor of a single path: ILogger. A new SQL log sink (OCORE.MultiLogger.SqlLoggerProvider,
gated by Fuchs:Logging:SqlSink:Enabled, default on) mirrors every _logger.LogWarning/-Error/
-Critical call into [dbo].[fds__debuglog] via a new fds__admin_logdebug_ext proc, at Warning+.

- Program.cs registers the sink and RequestLogScopeMiddleware (request id/path/authenticated
  user, pushed after UseAuthentication) so every log line in a request — including ones written
  deep inside OCORE's SQL helpers — is attributed automatically.
- FIS_SQLOptions, IntranetController.Do's catch-all, PdfPreviewAsync, and the banking-upload
  handlers now log once, with an explicit EventId preserving the exact CodeReference text the
  retired debug_log() calls used to write, so existing dashboards/queries over fds__debuglog
  keep working unchanged.
- Fuchs_DataService/FdsMfr.cs's FdsSqlOptions had the identical double-write hazard (it's hosted
  in the same process per ADR 0010) — the original 2026-09-16 log review's mfr__getSchema/
  fds__getUpdateableRequests deadlock rows came from exactly this class. Fixed the same way.
- fds__debuglog gains LogLevel/Machine/Category/Account/AuthUser/IsDebug columns; the legacy
  fds__admin_logdebug proc is left in place unused, not dropped.
- FdsDebug.DebugLog (Fuchs_DataService's other ~9 call sites) deliberately left on its direct
  DB-write path — no ILogger call sits alongside it there, so no duplication risk today.

See ADR 0024 (supersedes 0023) and Docs/Concepts/error-logging-pipeline.md.

New tests: ErrorLoggingTests (FIS_SQLOptions), FdsSqlOptionsTests, RequestLogScopeMiddlewareTests.
694/694 pass (the 4 PdfPipelineTests failures seen under full-suite parallel runs are a
pre-existing, unrelated PdfSharp global-font-resolver test-isolation flake — they pass both
individually and in most full-suite runs).

Bumps the OCORE submodule to 3137b56 (SQL sink hardening: redaction matches short fragments
as whole identifier segments, per-entry-tolerant serialization, lazy dataSerialized, opt-in
SqlLoggerOptions.IncludeCategory, LogEntry.Category/AuthUser capture).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
2026-09-16 17:20:06 +02:00

100 lines
5.9 KiB
Markdown

---
status: Active
lastUpdated: 2026-09-16
applyTo:
- "Fuchs/Program.cs"
- "Fuchs/Logging/**"
- "Fuchs/code/FuchsIntranet.cs"
- "Fuchs/Controllers/**"
- "Fuchs/Observability/FuchsTelemetry.cs"
relatedDecisions:
- "0003-structured-diagnostic-logging.md"
- "0003-interrupting-exceptions-notify-the-user.md"
- "0004-opentelemetry-observability.md"
- "0023-user-action-failures-persisted-to-db-log.md"
- "0024-multilogger-sql-log-sink.md"
---
# Error logging pipeline
## Summary
A `_logger.LogWarning`/`-Error`/`-Critical` call anywhere in the app — or in OCORE code called
from it — reaches three places automatically: the always-on file sink, a DB row in
`[dbo].[fds__debuglog]` (what support actually queries), and, for a user-initiated action that
threw unhandled, a SignalR toast to the user. One `ILogger` call is the single thing a call site
writes; nothing calls a stored procedure directly for attribution logging.
## How it works
### The two `ILoggerProvider`s
- **`FuchsLoggerProvider`** (`Fuchs/Logging/FuchsLoggerProvider.cs`, [0003](0003-structured-diagnostic-logging.md)):
every level ≥ Debug → `Debug.WriteLine` + a rolling-free text file (`logs/AppLog.txt` /
`logs/ErrorLog.txt`). Always on, no DB dependency.
- **`OCORE.MultiLogger.SqlLoggerProvider`** ([0024](0024-multilogger-sql-log-sink.md)): registered
in `Program.cs` via `builder.Logging.AddSqlLogger()`, gated by
`Fuchs:Logging:SqlSink:Enabled` (default on), filtered to `LogLevel.Warning`+. Writes via
`EXECUTE [dbo].[fds__admin_logdebug_ext]` into `[dbo].[fds__debuglog]` — the same table the
legacy, now-unused `fds__admin_logdebug` proc wrote to.
### Attribution: EventId, category, scope
- **`CodeReference`** (the row's short label) is `COALESCE(EventId.Name, ILogger category,
'MultiLogger')`, computed in the stored procedure. Give a log call an explicit `EventId` when
the call site should be individually greppable:
```csharp
_logger.LogError(new EventId(0, "SQL Error in getSQLDataSet"), ex, "SQL error in {Procedure}: ...", ...);
```
See `FIS_SQLOptions.OnError`, `IntranetController.Do`'s catch-all, `PdfPreviewAsync`, and the
`bam/up` (banking upload) handlers for the pattern — each preserves the exact string the old,
explicit `debug_log()` calls used, so existing saved queries over `CodeReference` still match.
- **`RequestLogScopeMiddleware`** (`Fuchs/Logging/RequestLogScopeMiddleware.cs`, registered after
`app.UseAuthentication()`) pushes `{requestId, path, authuser}` as an `ILogger` scope for the
whole request. Every log line written while handling it — including ones written deep inside
OCORE's SQL helpers — carries that automatically, without the call site doing anything.
`authuser` specifically lands in the dedicated `fds__debuglog.AuthUser` column (OCORE's
`MultiLogger_base.Log` picks the `"authuser"` scope key out into `LogEntry.AuthUser`); the rest
of the scope + any `{Placeholder}` args + an explicit `data:` object are merged into one redacted
JSON blob (`fds__debuglog.Data`).
- **No request/service-scoped logger available** (`new FIS_SQLOptions()` — ~15 call sites in
`Services/*.cs` construct it this way): `FIS_SQLOptions.OnError` falls back to the static
`OCORE.Logging.Logger` (set once in `Program.cs` to `app.Logger`), so those SQL errors are still
attributed, just under a less specific category.
### Placeholder naming
Always `{Foo}`, never `{@Foo}`. Plain `Microsoft.Extensions.Logging` (not Serilog) does not treat
`@` as a destructuring operator — it stays a literal leading character of the resulting property
name (`"@Foo"`), which is confusing in the serialized `Data` column.
### Redaction and cost
`OCORE.MultiLogger.LogRedaction.SerializeRedacted` masks property names matching known-sensitive
fragments/segments (`password`, `secret`, `token`, `pin`, `otp` as a whole identifier segment —
not substrings like `Mapping`/`HotPath`) at any nesting depth, degrades one unserializable context
entry to its `ToString()` instead of losing the whole payload, and tolerates self-referencing
graphs. `LogEntry.dataSerialized` is computed lazily — at most once, only if a sink actually reads
it — so a Warning+ call that no sink is currently listening for costs nothing extra to serialize.
### User-visible failure surface (unrelated to the DB write, [0023](0023-user-action-failures-persisted-to-db-log.md))
- `IntranetController.Do`'s catch-all publishes a SignalR toast (`IEventService.UserIssueAsync`)
for any unmodeled exception, for authenticated users only.
- A 500 response carries its message in the `x-ocms-desc` header (`ServerError(msg)` →
`EncodeResponseDescription`), which the frontend's default failure handler
(`$ocms.failure`/`oci_basic.js`) reads.
- PDF-preview endpoints go through the shared `PdfPreviewAsync` guard: logs, counts
`fuchs.pdf.previews{what,outcome}` (`success`/`gone`/`failure` — an expired-draft `410` is its
own `gone` outcome, not a render failure), toasts an authenticated caller, and returns a
message with the innermost exception text (omitted for the handful of preview endpoints
reachable without authentication — see `_allowedGet` in `IntranetController.cs`).
## Configuration
- `Fuchs:Logging:SqlSink:Enabled` (bool, default `true`) — off switch for the SQL sink without a
redeploy.
- SQL sink connects via `fuchs_fds_ConnectionString` (same connection as everything else), proc
`dbo.fds__admin_logdebug_ext`, `TruncateTextAt = 4000`.
## Extending this
- Adding a new sink (email/SMS on Critical, a rolling file replacing `FuchsLoggerProvider`) is a
registration in `Program.cs` — `OCORE.MultiLogger` already ships `EmailLoggerOptions`/
`SMSLoggerOptions`/`FileLoggerProvider`.
- A new place that needs DB attribution just calls `_logger.LogWarning`/`-Error` with an
`EventId` if it wants a specific `CodeReference` — never add a second, explicit stored-procedure
call next to it; that duplicates the row once the SQL sink picks the `ILogger` call up.