Files
Fuchs_Intranet/Fuchs/Docs/Decisions/0024-multilogger-sql-log-sink.md
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

8.1 KiB

status, date, applyTo, supersededBy
status date applyTo supersededBy
Accepted 2026-09-16
Fuchs/Program.cs
Fuchs/Logging/**
Fuchs/code/FuchsIntranet.cs
Fuchs/Controllers/**
Fuchs_DataService/FdsMfr.cs
OCORE/OCORE/logging/**
Fuchs_Database/dbo/Tables/fds__debuglog.sql
Fuchs_Database/dbo/Stored Procedures/fds__admin_logdebug_ext.sql

0024 — ILogger is the single path to the DB log, via the OCORE MultiLogger SQL sink

Context

0023 fixed the immediate gaps (SQL statement missing from the log row, unhandled Do() exceptions and PDF-preview failures never reaching the DB) by having a handful of call sites call both _logger.LogError(...) and the explicit Fuchs_intranet.debug_log(...) (→ EXECUTE [dbo].[fds__admin_logdebug]) for the same failure. That works, but only for the call sites someone remembered to wire up by hand, it writes every attributed failure to fds__debuglog twice as soon as any generic DB sink is added on top, and it leaves the ~15 new FIS_SQLOptions() call sites (no logger, no context — see Services/*.cs) without DB attribution at all, since their dbLog closure bypassed ILogger entirely.

OCORE ships a generic ILoggerProvider pipeline for exactly this (OCORE.MultiLogger, SqlLoggerProvider + FileLoggerProvider) that other ProcessWeb projects (VM_Regatta) already use: every _logger.LogX(...) call, from anywhere in the app or its dependencies (OCORE's own SQL helpers included), can be mirrored to a SQL sink automatically, with per-provider level filtering, structured context merging (scopes + {Placeholder} args + an explicit data: object), and redaction. It was not previously wired into Fuchs.

Decision

  • ILogger is the only thing a call site writes. No code calls Fuchs_intranet.debug_log (removed) or a stored procedure directly for attribution logging. _logger.LogWarning/-Error/ -Critical is sufficient; the SQL sink below persists it.
  • The OCORE MultiLogger SQL sink is registered at Warning+, gated by Fuchs:Logging:SqlSink:Enabled (default true), writing through the new [dbo].[fds__admin_logdebug_ext] proc into the same [dbo].[fds__debuglog] table the retired fds__admin_logdebug wrote to — existing report queries over that table keep working, now enriched with LogLevel/Machine/Category/AuthUser/IsDebug columns. fds__admin_logdebug itself is left in place (unused by the app, but not dropped — a compatibility no-op for anything external still calling it).
  • FuchsLoggerProvider's file sink (0003) is unchanged and stays the always-on baseline; the SQL sink is additive, not a replacement.
  • A call site that wants its own CodeReference gives the log call an explicit EventId (new EventId(0, "SQL Error in getSQLDataSet"), etc.) — its Name becomes the row's CodeReference, preserving the exact strings the retired debug_log calls used, so nothing downstream (dashboards, saved queries) had to change. Falls back to the ILogger category (new LogEntry.Category, OCORE-side), then the constant 'MultiLogger'.
  • RequestLogScopeMiddleware (Fuchs/Logging/, registered after 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 (SQL timeouts, PDF render failures), is attributed automatically without the call site doing anything. authuser specifically is picked up by OCORE's MultiLogger_base.Log into the dedicated LogEntry.AuthUser → fds__debuglog.AuthUser column, not just the serialized JSON blob.
  • FIS_SQLOptions.OnError falls back to the static OCORE.Logging.Logger (already set once in Program.cs) when no request/service-scoped ILogger was supplied, so the new FIS_SQLOptions() call sites keep working exactly as attributed as the ones that pass a logger.
  • Fuchs_DataService/FdsMfr.cs's FdsSqlOptions.OnError — the MFR-sync worker's equivalent of FIS_SQLOptions, and the actual source of the deadlock/timeout rows the original log review found — had the exact same problem in reverse: it called both logger?.LogError(...) and FdsDebug.DebugLog(...) (a second, direct EXECUTE [dbo].[fds__admin_logdebug]) for every SQL error. Since the worker is hosted inside this same web app (ADR 0010) and therefore shares the SQL sink, that combination would double-write every row. Fixed the same way: ILogger only, with the same static-logger fallback, EventId.Name = procedure (unprefixed, matching what the direct DebugLog call used to pass).
  • FdsDebug.DebugLog, used elsewhere in Fuchs_DataService (FdsMfr.cs, FdsShared.cs) was deliberately not migrated — those call sites don't separately call ILogger, so there is no duplication there today, and moving nine call sites onto the generic pipeline was out of scope for closing the one hazard (FdsSqlOptions.OnError) this ADR set out to fix. It still writes directly to the legacy fds__admin_logdebug proc (same fds__debuglog table) plus a local DebugLog.txt. Revisit if a future change adds an ILogger call alongside one of those sites.
  • OCORE-side hardening that made this safe to turn on (see the code-review this ADR grew out of): LogRedaction masks sensitive keys by segment, not substring (Pin/Otp as a whole identifier segment, not Mapping/HotPath), degrades one unserializable context entry to its ToString() instead of dropping the whole payload, and tolerates a self-referencing graph. LogEntry.dataSerialized is computed lazily (at most once, only if a sink actually reads it) so the per-call context-merging cost is paid only when something is written. Scope/state collection never throws into the caller. SqlLoggerProvider's new IncludeCategory option is off by default in OCORE (other consumers' stored procedures don't declare @category) — Fuchs turns it on explicitly since its proc does.
  • Never use {@Foo} placeholders. Plain Microsoft.Extensions.Logging (what OCORE.MultiLogger and Fuchs use — not Serilog) does not treat @ as a destructuring operator; it stays a literal leading character of the property name ("@Foo"), which is confusing in the serialized JSON. Use {Foo}.

Consequences

  • One _logger.LogError(...) call is enough; adding a second, explicit DB write next to it duplicates the row once the SQL sink is on. Code review should flag a reintroduced debug_log-style call.
  • A log call that should be individually attributable in fds__debuglog.CodeReference needs an explicit EventId; without one it falls back to the (often less specific, but still useful) ILogger category.
  • The SQL sink is a fire-and-forget async write with a 2-minute retry cooldown on failure (SqlLoggerProvider) — during a DB outage it goes quiet for that window, same as any other write to that DB. The file sink (0003) remains the log that is never gated on the DB being reachable at all.
  • Fuchs:Logging:SqlSink:Enabled is the escape hatch if the sink ever needs to be turned off without a deploy (e.g. investigating whether it is itself contributing to DB load).
  • OCORE's MultiLoggerOptions.SQL.IncludeCategory is a new, opt-in, backward-compatible knob; other SqlLoggerProvider consumers (VM_Regatta) are unaffected unless they opt in and add a matching @category parameter to their own stored procedure.

Alternatives considered

  • Keep the explicit debug_log write and just fix its parameter bug (0023's original scope). Rejected once the generic SQL sink became the actual plan — keeping both would permanently double-write every attributed failure, and still leave the new FIS_SQLOptions() call sites unattributed.
  • FuchsLoggerProvider.DatabaseLoggingEnabled = true (0003's prepared-but-disabled DB path). Rejected again here for the same reason 0023 rejected it: no per-request context (user, route), and it would fire on every LogError including background-service noise with no Warning+ gate.