feat: migrate DB error logging onto the generic OCORE MultiLogger SQL sink
Playwright Tests / test (push) Canceled after 0s

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>
This commit is contained in:
Stefan
2026-09-16 17:20:06 +02:00
co-authored by Claude Sonnet 5
parent a1e6002c3b
commit bcf1f2dbb6
23 changed files with 757 additions and 225 deletions
+92 -85
View File
@@ -1,113 +1,121 @@
using System;
using System.Collections.Generic;
using System.Data;
using System.Linq;
using Fuchs.Controllers;
using Fuchs.intranet;
using Microsoft.Extensions.Logging;
using Moq;
using Newtonsoft.Json;
using Xunit;
using static fds.FdsMfrClient;
namespace Fuchs.Tests;
/// <summary>
/// Covers the error-attribution fixes made after the 2026-09-16 production log review: every
/// "SQL Error in getSQLDataSet" row in fds__admin_logdebug carried Data=NULL (the failing SQL
/// was dropped), unhandled Do() exceptions and PDF-preview failures never reached the DB log at
/// all, and the browser alert always had an empty description. The DB write itself (debug_log →
/// fds__admin_logdebug) is SQL-bound and not unit-tested; these tests pin what gets handed to it.
/// Covers the error-attribution fixes from the 2026-09-16 production log review and the
/// subsequent migration onto the generic OCORE MultiLogger SQL log sink (ADR 0024):
/// <see cref="FIS_SQLOptions"/> now logs every SQL error through <see cref="ILogger"/> alone
/// (which the SQL sink additionally persists to <c>fds__debuglog</c> at Warning+, so the old,
/// separate <c>Fuchs_intranet.debug_log</c> DB write was retired to avoid double-logging), with
/// an <see cref="EventId"/> carrying the exact CodeReference text the retired DB write used to.
/// The DB write itself, and <c>IntranetController.Do</c>'s full catch-all, are SQL/DI-bound and
/// not unit-tested per repo convention; these tests pin the pure logic that feeds them.
/// </summary>
/// <remarks>
/// Shares <see cref="StaticOcoreLoggerCollection"/> with <c>FdsSqlOptionsTests</c>: both save/
/// mutate/restore the process-wide static <see cref="OCORE.Logging.Logger"/> field, which would
/// otherwise race across the two classes since xUnit parallelizes different test classes by
/// default.
/// </remarks>
[Collection(StaticOcoreLoggerCollection.Name)]
public class ErrorLoggingTests
{
/// <summary>Minimal <see cref="ILogger"/> double that records every call for assertion.</summary>
private sealed class RecordingLogger : ILogger
{
public sealed record Entry(LogLevel Level, EventId EventId, Exception? Exception, string Message,
IReadOnlyDictionary<string, object?> State);
public readonly List<Entry> Entries = new();
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter)
{
var pairs = (state as IEnumerable<KeyValuePair<string, object>>)?
.ToDictionary(kv => kv.Key, kv => (object?)kv.Value) ?? new Dictionary<string, object?>();
Entries.Add(new Entry(logLevel, eventId, exception, formatter(state, exception), pairs));
}
}
// ── FIS_SQLOptions ─────────────────────────────────────────────────────────
[Fact]
public void FisSqlOptions_OnError_ForwardsSqlStatementAndContextToDbLog()
public void FisSqlOptions_OnError_LogsWithEventIdAndStructuredPlaceholders()
{
string? codeRef = null; Exception? loggedEx = null; object? loggedData = null;
var logger = new Mock<ILogger>();
var logger = new RecordingLogger();
var context = new Dictionary<string, object> { ["fn"] = "inv", ["id"] = "invl", ["code"] = "" };
var opt = new FIS_SQLOptions(context, logger.Object, (p, ex, data) => { codeRef = p; loggedEx = ex; loggedData = data; });
var opt = new FIS_SQLOptions(context, logger);
var ex = new TimeoutException("Das Ausführungstimeout ist abgelaufen.");
var sqlPayload = new { sql = "EXECUTE [dbo].[fds__getInvoiceList] @authuser;" };
opt.OnError!("getSQLDataSet", ex, new { sql = "EXECUTE [dbo].[fds__getInvoiceList] @authuser;" });
opt.OnError!("getSQLDataSet", ex, sqlPayload);
Assert.Equal("SQL Error in getSQLDataSet", codeRef);
Assert.Same(ex, loggedEx);
// The DB column is the JSON of this object — it must carry the SQL, which was the missing piece.
string json = JsonConvert.SerializeObject(loggedData);
Assert.Contains("fds__getInvoiceList", json);
Assert.Contains("\"fn\":\"inv\"", json);
Assert.Contains("\"id\":\"invl\"", json);
logger.Verify(l => l.Log(LogLevel.Error, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), ex,
It.IsAny<Func<It.IsAnyType, Exception?, string>>()), Times.Once);
var entry = Assert.Single(logger.Entries);
Assert.Equal(LogLevel.Error, entry.Level);
// EventId.Name preserves the exact CodeReference text the retired DB write used, so the SQL
// sink's fallback COALESCE(procedure, category, 'MultiLogger') keeps existing dashboards working.
Assert.Equal("SQL Error in getSQLDataSet", entry.EventId.Name);
Assert.Same(ex, entry.Exception);
// The failing statement and caller context are structured placeholders, not string-concatenated
// — this is what was missing before (every row's Data column was NULL).
Assert.Equal("getSQLDataSet", entry.State["Procedure"]);
Assert.Same(sqlPayload, entry.State["Sql"]);
Assert.Same(context, entry.State["Context"]);
// Plain Microsoft.Extensions.Logging (not Serilog) does not treat '@' as a destructuring
// operator; it would be kept as a literal leading character in the key. This asserts the
// placeholder names in FIS_SQLOptions are plain ("Sql"/"Context"), not "@Sql"/"@Context".
Assert.False(entry.State.ContainsKey("@Sql"));
Assert.Contains("getSQLDataSet", entry.Message);
}
[Fact]
public void FisSqlOptions_OnError_DbLogThrows_DoesNotPropagate()
public void FisSqlOptions_OnError_NoLoggerGiven_FallsBackToStaticOcoreLogger()
{
var opt = new FIS_SQLOptions(null, null, (_, _, _) => throw new InvalidOperationException("no db"));
// Several call sites construct `new FIS_SQLOptions()` with neither logger nor context
// (Services/*.cs) — those must still reach a logger, not silently drop the error.
var fallback = new RecordingLogger();
var saved = OCORE.Logging.Logger;
OCORE.Logging.Logger = fallback;
try
{
var opt = new FIS_SQLOptions();
opt.OnError!("setSQLValue_async", new Exception("boom"), new { sql = "SELECT 1;" });
var recorded = Record.Exception(() => opt.OnError!("setSQLValue_async", new Exception("x"), new { sql = "SELECT 1;" }));
Assert.Null(recorded);
var entry = Assert.Single(fallback.Entries);
Assert.Equal("SQL Error in setSQLValue_async", entry.EventId.Name);
}
finally { OCORE.Logging.Logger = saved; }
}
[Fact]
public void FisSqlOptions_BuildLogData_UnwrapsOcoreSqlPayload()
public void FisSqlOptions_OnError_NoLoggerAndNoStaticFallback_DoesNotThrow()
{
var d = FIS_SQLOptions.BuildLogData(null, new { sql = "SELECT 1;" });
var saved = OCORE.Logging.Logger;
OCORE.Logging.Logger = null;
try
{
var opt = new FIS_SQLOptions();
var recorded = Record.Exception(() =>
opt.OnError!("getSQLDataSet", new Exception("x"), new { sql = "SELECT 1;" }));
Assert.Equal("SELECT 1;", d["sql"]);
Assert.False(d.ContainsKey("context"));
Assert.Null(recorded);
}
finally { OCORE.Logging.Logger = saved; }
}
[Fact]
public void FisSqlOptions_BuildLogData_KeepsForeignPayloadVerbatim()
{
var payload = new { statement = "SELECT 2;" };
var d = FIS_SQLOptions.BuildLogData(null, payload);
Assert.Same(payload, d["sql"]);
}
[Theory]
[InlineData(true)]
[InlineData(false)]
public void FisSqlOptions_BuildLogData_NullOrEmptyContextIsOmitted(bool empty)
{
var ctx = empty ? new Dictionary<string, object>() : null;
var d = FIS_SQLOptions.BuildLogData(ctx, new { sql = "SELECT 1;" });
Assert.False(d.ContainsKey("context"));
}
[Fact]
public void FisSqlOptions_BuildLogData_NullData_ProducesEmptyOrContextOnly()
{
Assert.Empty(FIS_SQLOptions.BuildLogData(null, null));
var ctx = new Dictionary<string, object> { ["fn"] = "rem" };
var d = FIS_SQLOptions.BuildLogData(ctx, null);
Assert.Single(d);
Assert.Same(ctx, d["context"]);
}
// ── Do() catch-all + response description header ──────────────────────────
[Fact]
public void BuildDoErrorLogData_ContainsRouteUserAndFormKeys_ButNoFormValues()
{
var d = IntranetController.BuildDoErrorLogData("rem", "dpreview", "", "user-1", new[] { "token" });
string json = JsonConvert.SerializeObject(d);
Assert.Contains("\"fn\":\"rem\"", json);
Assert.Contains("\"id\":\"dpreview\"", json);
Assert.Contains("\"user\":\"user-1\"", json);
Assert.Contains("\"formKeys\":[\"token\"]", json);
}
// ── Response description header (500 → x-ocms-desc) ────────────────────────
[Theory]
[InlineData("Die PDF-Vorschau konnte nicht erstellt werden.", "Die%20PDF-Vorschau%20konnte%20nicht%20erstellt%20werden.")]
@@ -134,7 +142,7 @@ public class ErrorLoggingTests
Assert.Equal(msg, Uri.UnescapeDataString(encoded));
}
// ── PDF preview failure payloads ──────────────────────────────────────────
// ── PDF preview failure message ─────────────────────────────────────────────
[Fact]
public void PdfPreviewFailureMessage_UsesInnermostExceptionText()
@@ -142,7 +150,7 @@ public class ErrorLoggingTests
var ex = new InvalidOperationException("outer",
new AggregateException("agg", new ApplicationException("Font 'Courier New' cannot be resolved")));
string msg = IntranetController.PdfPreviewFailureMessage(ex);
string msg = IntranetController.PdfPreviewFailureMessage(ex, includeDetail: true);
Assert.StartsWith("Die PDF-Vorschau konnte nicht erstellt werden: ", msg);
Assert.EndsWith("Font 'Courier New' cannot be resolved", msg);
@@ -154,21 +162,20 @@ public class ErrorLoggingTests
[InlineData(" ")]
public void PdfPreviewFailureMessage_EmptyExceptionText_FallsBackToGenericText(string text)
{
string msg = IntranetController.PdfPreviewFailureMessage(new Exception(text));
string msg = IntranetController.PdfPreviewFailureMessage(new Exception(text), includeDetail: true);
Assert.Equal("Die PDF-Vorschau konnte nicht erstellt werden.", msg);
}
[Fact]
public void BuildPdfPreviewLogData_CarriesEndpointRefUserAndDuration()
public void PdfPreviewFailureMessage_UnauthenticatedCaller_OmitsExceptionDetail()
{
var d = IntranetController.BuildPdfPreviewLogData("rem/dpreview", "tok-123", "user-1", 4321);
var ex = new ApplicationException("Font 'Courier New' cannot be resolved");
string json = JsonConvert.SerializeObject(d);
Assert.Contains("\"what\":\"rem/dpreview\"", json);
Assert.Contains("\"ref\":\"tok-123\"", json);
Assert.Contains("\"user\":\"user-1\"", json);
Assert.Contains("\"ms\":4321", json);
string msg = IntranetController.PdfPreviewFailureMessage(ex, includeDetail: false);
Assert.Equal("Die PDF-Vorschau konnte nicht erstellt werden.", msg);
Assert.DoesNotContain("Courier", msg);
}
// ── Data service: schema failure must not cascade into "FROM [dbo].[]" ────
+98
View File
@@ -0,0 +1,98 @@
using System;
using System.Collections.Generic;
using System.Linq;
using fds;
using Microsoft.Extensions.Logging;
using Xunit;
namespace Fuchs.Tests;
/// <summary>
/// Covers <see cref="FdsSqlOptions"/> (the MFR-sync worker's equivalent of
/// <c>Fuchs.intranet.FIS_SQLOptions</c>): after ADR 0024, it must log a SQL error through
/// <see cref="ILogger"/> alone — the original 2026-09-16 log review's deadlock/timeout rows came
/// from this exact class calling both <see cref="ILogger"/> and a direct
/// <c>EXECUTE [dbo].[fds__admin_logdebug]</c>, which would double-write every row once the
/// worker's ILogger calls also reach the SQL log sink (hosted in the same process as the web app,
/// ADR 0010).
/// </summary>
/// <remarks>
/// Shares <see cref="StaticOcoreLoggerCollection"/> with <c>ErrorLoggingTests</c>: both save/
/// mutate/restore the process-wide static <see cref="OCORE.Logging.Logger"/> field, which would
/// otherwise race across the two classes since xUnit parallelizes different test classes by
/// default.
/// </remarks>
[Collection(StaticOcoreLoggerCollection.Name)]
public class FdsSqlOptionsTests
{
private sealed class RecordingLogger : ILogger
{
public sealed record Entry(LogLevel Level, EventId EventId, Exception? Exception, string Message,
IReadOnlyDictionary<string, object?> State);
public readonly List<Entry> Entries = new();
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter)
{
var pairs = (state as IEnumerable<KeyValuePair<string, object>>)?
.ToDictionary(kv => kv.Key, kv => (object?)kv.Value) ?? new Dictionary<string, object?>();
Entries.Add(new Entry(logLevel, eventId, exception, formatter(state, exception), pairs));
}
}
[Fact]
public void OnError_LogsOnce_WithProcedureAsEventIdName_NotPrefixed()
{
var logger = new RecordingLogger();
var dic = new Dictionary<string, object> { ["uid"] = "abc" };
var opt = new FdsSqlOptions(dic, logger);
var ex = new TimeoutException("deadlock victim");
opt.OnError!("mfr__getSchema", ex, new { sql = "EXECUTE [dbo].[mfr__getSchema] 'table', @tgttype;" });
var entry = Assert.Single(logger.Entries);
Assert.Equal(LogLevel.Error, entry.Level);
// Unprefixed: the direct DebugLog() call this replaced passed `procedure` as-is.
Assert.Equal("mfr__getSchema", entry.EventId.Name);
Assert.Same(ex, entry.Exception);
Assert.Equal("mfr__getSchema", entry.State["Procedure"]);
Assert.Same(dic, entry.State["CtrlInfo"]);
}
[Fact]
public void OnError_NoLoggerGiven_FallsBackToStaticOcoreLogger()
{
var fallback = new RecordingLogger();
var saved = OCORE.Logging.Logger;
OCORE.Logging.Logger = fallback;
try
{
var opt = new FdsSqlOptions();
opt.OnError!("fds__getUpdateableRequests", new Exception("boom"), new { sql = "SELECT 1;" });
var entry = Assert.Single(fallback.Entries);
Assert.Equal("fds__getUpdateableRequests", entry.EventId.Name);
}
finally { OCORE.Logging.Logger = saved; }
}
[Fact]
public void OnError_NoLoggerAndNoStaticFallback_DoesNotThrow()
{
var saved = OCORE.Logging.Logger;
OCORE.Logging.Logger = null;
try
{
var opt = new FdsSqlOptions();
var recorded = Record.Exception(() =>
opt.OnError!("mfr__getSchema", new Exception("x"), new { sql = "SELECT 1;" }));
Assert.Null(recorded);
}
finally { OCORE.Logging.Logger = saved; }
}
}
@@ -0,0 +1,76 @@
using System.Security.Claims;
using Fuchs.intranet;
using Fuchs.Logging;
using Microsoft.AspNetCore.Http;
using Xunit;
namespace Fuchs.Tests;
/// <summary>
/// Covers <see cref="RequestLogScopeMiddleware.BuildScope"/>: the per-request scope that attributes
/// every log line (including ones written deep inside OCORE) to a request id, path, and — once
/// authenticated — the <c>fuchs:useraccount_id</c> claim, feeding both the generic serialized
/// context and (via the "authuser" key specifically) <c>LogEntry.AuthUser</c>. See ADR 0024.
/// </summary>
public class RequestLogScopeMiddlewareTests
{
private static DefaultHttpContext ContextWithPath(string path)
{
var ctx = new DefaultHttpContext();
ctx.Request.Path = path;
return ctx;
}
[Fact]
public void BuildScope_UnauthenticatedRequest_CarriesRequestIdAndPath_NoAuthUserKey()
{
var ctx = ContextWithPath("/do/inv/dpreview");
ctx.TraceIdentifier = "trace-123";
var scope = RequestLogScopeMiddleware.BuildScope(ctx);
Assert.Equal("trace-123", scope["requestId"]);
Assert.Equal("/do/inv/dpreview", scope["path"]);
Assert.False(scope.ContainsKey("authuser"));
}
[Fact]
public void BuildScope_AuthenticatedRequest_IncludesAuthUserFromClaim()
{
var ctx = ContextWithPath("/do/inv/dpreview");
var identity = new ClaimsIdentity(new[]
{
new Claim(FuchsUserIdentity.ClaimUserAccountId, "acct-42"),
}, "fuchs_intranet");
ctx.User = new ClaimsPrincipal(identity);
var scope = RequestLogScopeMiddleware.BuildScope(ctx);
Assert.Equal("acct-42", scope["authuser"]);
}
[Fact]
public void BuildScope_AuthenticatedPrincipalWithEmptyClaim_OmitsAuthUserKey()
{
var ctx = ContextWithPath("/do/inv/dpreview");
var identity = new ClaimsIdentity(new[]
{
new Claim(FuchsUserIdentity.ClaimUserAccountId, ""),
}, "fuchs_intranet");
ctx.User = new ClaimsPrincipal(identity);
var scope = RequestLogScopeMiddleware.BuildScope(ctx);
Assert.False(scope.ContainsKey("authuser"));
}
[Fact]
public void BuildScope_RootPath_UsesEmptyStringNotNull()
{
var ctx = new DefaultHttpContext();
var scope = RequestLogScopeMiddleware.BuildScope(ctx);
Assert.Equal("", scope["path"]);
}
}
@@ -0,0 +1,18 @@
using Xunit;
namespace Fuchs.Tests;
/// <summary>
/// Groups every test class that saves/mutates/restores the process-wide static
/// <see cref="OCORE.Logging.Logger"/> field (e.g. to exercise the <c>FIS_SQLOptions</c>/
/// <c>FdsSqlOptions</c> "no logger given" fallback). xUnit runs different test *classes* in
/// parallel by default (each is its own collection unless grouped); without this, two such tests
/// racing on the same static field could read/restore each other's value and fail intermittently
/// for reasons unrelated to the code under test. Putting them in one named collection makes xUnit
/// run them sequentially relative to each other while leaving the rest of the suite parallel.
/// </summary>
[CollectionDefinition(Name)]
public class StaticOcoreLoggerCollection
{
public const string Name = "OCORE.Logging.Logger (static)";
}