From bcf1f2dbb61938778e04f0c53663119495ec3344 Mon Sep 17 00:00:00 2001 From: Stefan Date: Wed, 16 Sep 2026 17:20:06 +0200 Subject: [PATCH] feat: migrate DB error logging onto the generic OCORE MultiLogger SQL sink MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- .github/copilot-instructions.md | 3 +- CLAUDE.md | 3 +- CODEX.md | 3 +- Fuchs.Tests/ErrorLoggingTests.cs | 177 +++++++++--------- Fuchs.Tests/FdsSqlOptionsTests.cs | 98 ++++++++++ Fuchs.Tests/RequestLogScopeMiddlewareTests.cs | 76 ++++++++ Fuchs.Tests/StaticOcoreLoggerCollection.cs | 18 ++ .../Controllers/IntranetController.Banking.cs | 20 +- .../IntranetController.PdfPreview.cs | 67 +++---- Fuchs/Controllers/IntranetController.cs | 24 +-- Fuchs/Docs/Concepts/error-logging-pipeline.md | 99 ++++++++++ ...ser-action-failures-persisted-to-db-log.md | 21 ++- .../0024-multilogger-sql-log-sink.md | 114 +++++++++++ Fuchs/Logging/RequestLogScopeMiddleware.cs | 41 ++++ Fuchs/Program.cs | 24 +++ Fuchs/appsettings.json | 5 + Fuchs/code/FuchsIntranet.cs | 71 ++----- Fuchs_DataService/FdsMfr.cs | 24 ++- Fuchs_DataService/Fuchs_DataService.xml | 17 +- Fuchs_Database/FuchsDatabase.sqlproj | 1 + .../fds__admin_logdebug_ext.sql | 61 ++++++ Fuchs_Database/dbo/Tables/fds__debuglog.sql | 13 +- OCORE | 2 +- 23 files changed, 757 insertions(+), 225 deletions(-) create mode 100644 Fuchs.Tests/FdsSqlOptionsTests.cs create mode 100644 Fuchs.Tests/RequestLogScopeMiddlewareTests.cs create mode 100644 Fuchs.Tests/StaticOcoreLoggerCollection.cs create mode 100644 Fuchs/Docs/Concepts/error-logging-pipeline.md create mode 100644 Fuchs/Docs/Decisions/0024-multilogger-sql-log-sink.md create mode 100644 Fuchs/Logging/RequestLogScopeMiddleware.cs create mode 100644 Fuchs_Database/dbo/Stored Procedures/fds__admin_logdebug_ext.sql diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 91bb4f9..c0e02f7 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -68,8 +68,9 @@ ## Observability - Use **OpenTelemetry**. The app's instrumentation is centralised in `Fuchs/Observability/FuchsTelemetry.cs` (one `ActivitySource` + one `Meter`). -- When adding a meaningful operation: start an activity (`FuchsTelemetry.StartActivity(...)`), record the relevant counter/histogram, and log entry/result/timing/errors via the injected `ILogger`. Prefer structured logging (named placeholders), never string interpolation in log messages. +- When adding a meaningful operation: start an activity (`FuchsTelemetry.StartActivity(...)`), record the relevant counter/histogram, and log entry/result/timing/errors via the injected `ILogger`. Prefer structured logging (named placeholders), never string interpolation in log messages — and never `{@Foo}`: plain `Microsoft.Extensions.Logging` (unlike Serilog) does not strip the `@`, it becomes a literal part of the key. - Tracing/metrics are always collected; OTLP export is opt-in via `Fuchs:Telemetry:OtlpEndpoint`. Don't add exporters that fail hard when no collector is present. +- **DB log sink (ADR 0024):** every `_logger.LogWarning`/`-Error`/`-Critical` call additionally lands in `[dbo].[fds__debuglog]` via the OCORE MultiLogger SQL sink (`fds__admin_logdebug_ext`), gated by `Fuchs:Logging:SqlSink:Enabled` (default on). `RequestLogScopeMiddleware` (`Fuchs/Logging/`) attributes every log line in a request to a request id/path/authenticated user automatically. Give a log call an explicit `EventId` (its `Name` becomes the row's `CodeReference`) when the call site should be individually greppable — see `FIS_SQLOptions`, `IntranetController.Do`'s catch-all, `PdfPreviewAsync`, and the banking-upload handlers for the pattern. Do not also call the retired `Fuchs_intranet.debug_log` — one `ILogger` call is the single write path; a second explicit DB write duplicates the row. ## Testing - xUnit in `Fuchs.Tests`. Testing must be **extensive**, not superficial: diff --git a/CLAUDE.md b/CLAUDE.md index 8b48c9d..0ebd9a5 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -56,8 +56,9 @@ ## Observability - OpenTelemetry. Instrumentation is centralised in `Fuchs/Observability/FuchsTelemetry.cs` (one `ActivitySource`, one `Meter`). -- For meaningful operations: start an activity, record the matching counter/histogram, and log entry/result/timing/errors via injected `ILogger` using **structured** placeholders (never interpolated strings). +- For meaningful operations: start an activity, record the matching counter/histogram, and log entry/result/timing/errors via injected `ILogger` using **structured** placeholders (never interpolated strings) — never `{@Foo}`; plain `Microsoft.Extensions.Logging` (unlike Serilog) does not strip the `@`, it becomes a literal part of the key. - Always collected; OTLP export opt-in via `Fuchs:Telemetry:OtlpEndpoint`. No exporters that hard-fail without a collector. +- **DB log sink (ADR 0024):** every `_logger.LogWarning`/`-Error`/`-Critical` call additionally lands in `[dbo].[fds__debuglog]` via the OCORE MultiLogger SQL sink (`fds__admin_logdebug_ext`), gated by `Fuchs:Logging:SqlSink:Enabled` (default on). `RequestLogScopeMiddleware` (`Fuchs/Logging/`) attributes every log line in a request to a request id/path/authenticated user automatically. Give a log call an explicit `EventId` (its `Name` becomes the row's `CodeReference`) when the call site should be individually greppable — see `FIS_SQLOptions`, `IntranetController.Do`'s catch-all, `PdfPreviewAsync`, and the banking-upload handlers for the pattern. Do not also call the retired `Fuchs_intranet.debug_log` — one `ILogger` call is the single write path; a second explicit DB write duplicates the row. ## Testing - xUnit in `Fuchs.Tests`. Testing must be **extensive**, not superficial: diff --git a/CODEX.md b/CODEX.md index 5e5dddb..3ee73ce 100644 --- a/CODEX.md +++ b/CODEX.md @@ -56,8 +56,9 @@ ## Observability - OpenTelemetry. Instrumentation is centralised in `Fuchs/Observability/FuchsTelemetry.cs` (one `ActivitySource`, one `Meter`). -- For meaningful operations: start an activity, record the matching counter/histogram, and log entry/result/timing/errors via injected `ILogger` using **structured** placeholders (never interpolated strings). +- For meaningful operations: start an activity, record the matching counter/histogram, and log entry/result/timing/errors via injected `ILogger` using **structured** placeholders (never interpolated strings) — never `{@Foo}`; plain `Microsoft.Extensions.Logging` (unlike Serilog) does not strip the `@`, it becomes a literal part of the key. - Always collected; OTLP export opt-in via `Fuchs:Telemetry:OtlpEndpoint`. No exporters that hard-fail without a collector. +- **DB log sink (ADR 0024):** every `_logger.LogWarning`/`-Error`/`-Critical` call additionally lands in `[dbo].[fds__debuglog]` via the OCORE MultiLogger SQL sink (`fds__admin_logdebug_ext`), gated by `Fuchs:Logging:SqlSink:Enabled` (default on). `RequestLogScopeMiddleware` (`Fuchs/Logging/`) attributes every log line in a request to a request id/path/authenticated user automatically. Give a log call an explicit `EventId` (its `Name` becomes the row's `CodeReference`) when the call site should be individually greppable — see `FIS_SQLOptions`, `IntranetController.Do`'s catch-all, `PdfPreviewAsync`, and the banking-upload handlers for the pattern. Do not also call the retired `Fuchs_intranet.debug_log` — one `ILogger` call is the single write path; a second explicit DB write duplicates the row. ## Testing - xUnit in `Fuchs.Tests`. Testing must be **extensive**, not superficial: diff --git a/Fuchs.Tests/ErrorLoggingTests.cs b/Fuchs.Tests/ErrorLoggingTests.cs index 145207f..42e9e89 100644 --- a/Fuchs.Tests/ErrorLoggingTests.cs +++ b/Fuchs.Tests/ErrorLoggingTests.cs @@ -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; /// -/// 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): +/// now logs every SQL error through alone +/// (which the SQL sink additionally persists to fds__debuglog at Warning+, so the old, +/// separate Fuchs_intranet.debug_log DB write was retired to avoid double-logging), with +/// an carrying the exact CodeReference text the retired DB write used to. +/// The DB write itself, and IntranetController.Do's full catch-all, are SQL/DI-bound and +/// not unit-tested per repo convention; these tests pin the pure logic that feeds them. /// +/// +/// Shares with FdsSqlOptionsTests: both save/ +/// mutate/restore the process-wide static field, which would +/// otherwise race across the two classes since xUnit parallelizes different test classes by +/// default. +/// +[Collection(StaticOcoreLoggerCollection.Name)] public class ErrorLoggingTests { + /// Minimal double that records every call for assertion. + private sealed class RecordingLogger : ILogger + { + public sealed record Entry(LogLevel Level, EventId EventId, Exception? Exception, string Message, + IReadOnlyDictionary State); + + public readonly List Entries = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + var pairs = (state as IEnumerable>)? + .ToDictionary(kv => kv.Key, kv => (object?)kv.Value) ?? new Dictionary(); + 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(); + var logger = new RecordingLogger(); var context = new Dictionary { ["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(), It.IsAny(), ex, - It.IsAny>()), 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() : 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 { ["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].[]" ──── diff --git a/Fuchs.Tests/FdsSqlOptionsTests.cs b/Fuchs.Tests/FdsSqlOptionsTests.cs new file mode 100644 index 0000000..1fef0fe --- /dev/null +++ b/Fuchs.Tests/FdsSqlOptionsTests.cs @@ -0,0 +1,98 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using fds; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Fuchs.Tests; + +/// +/// Covers (the MFR-sync worker's equivalent of +/// Fuchs.intranet.FIS_SQLOptions): after ADR 0024, it must log a SQL error through +/// alone — the original 2026-09-16 log review's deadlock/timeout rows came +/// from this exact class calling both and a direct +/// EXECUTE [dbo].[fds__admin_logdebug], 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). +/// +/// +/// Shares with ErrorLoggingTests: both save/ +/// mutate/restore the process-wide static field, which would +/// otherwise race across the two classes since xUnit parallelizes different test classes by +/// default. +/// +[Collection(StaticOcoreLoggerCollection.Name)] +public class FdsSqlOptionsTests +{ + private sealed class RecordingLogger : ILogger + { + public sealed record Entry(LogLevel Level, EventId EventId, Exception? Exception, string Message, + IReadOnlyDictionary State); + + public readonly List Entries = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + var pairs = (state as IEnumerable>)? + .ToDictionary(kv => kv.Key, kv => (object?)kv.Value) ?? new Dictionary(); + 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 { ["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; } + } +} diff --git a/Fuchs.Tests/RequestLogScopeMiddlewareTests.cs b/Fuchs.Tests/RequestLogScopeMiddlewareTests.cs new file mode 100644 index 0000000..0bc6b6d --- /dev/null +++ b/Fuchs.Tests/RequestLogScopeMiddlewareTests.cs @@ -0,0 +1,76 @@ +using System.Security.Claims; +using Fuchs.intranet; +using Fuchs.Logging; +using Microsoft.AspNetCore.Http; +using Xunit; + +namespace Fuchs.Tests; + +/// +/// Covers : the per-request scope that attributes +/// every log line (including ones written deep inside OCORE) to a request id, path, and — once +/// authenticated — the fuchs:useraccount_id claim, feeding both the generic serialized +/// context and (via the "authuser" key specifically) LogEntry.AuthUser. See ADR 0024. +/// +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"]); + } +} diff --git a/Fuchs.Tests/StaticOcoreLoggerCollection.cs b/Fuchs.Tests/StaticOcoreLoggerCollection.cs new file mode 100644 index 0000000..58a625f --- /dev/null +++ b/Fuchs.Tests/StaticOcoreLoggerCollection.cs @@ -0,0 +1,18 @@ +using Xunit; + +namespace Fuchs.Tests; + +/// +/// Groups every test class that saves/mutates/restores the process-wide static +/// field (e.g. to exercise the FIS_SQLOptions/ +/// FdsSqlOptions "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. +/// +[CollectionDefinition(Name)] +public class StaticOcoreLoggerCollection +{ + public const string Name = "OCORE.Logging.Logger (static)"; +} diff --git a/Fuchs/Controllers/IntranetController.Banking.cs b/Fuchs/Controllers/IntranetController.Banking.cs index 292e16d..26258b6 100644 --- a/Fuchs/Controllers/IntranetController.Banking.cs +++ b/Fuchs/Controllers/IntranetController.Banking.cs @@ -55,22 +55,22 @@ public partial class IntranetController { importFailed = true; importFailure = exc.Message; - _logger.LogError(exc, - "Banking upload SQL exception — file={File} destTable={DestTable} user={User}", - fle.FileName, dtwa.DestinationTableName, UserAccountID); - _intranet.debug_log("IntranetController.bam.up - sql exception", - exc, UserAccountID, new { uid = dtwa.InstanceGUID, tmptbl }); + // EventId.Name keeps the exact CodeReference the DB log used before the + // generic SQL sink existed (ADR 0024); {Data} carries uid/tmptbl into it. + _logger.LogError(new EventId(0, "IntranetController.bam.up - sql exception"), exc, + "Banking upload SQL exception — file={File} destTable={DestTable} user={User} data={Data}", + fle.FileName, dtwa.DestinationTableName, UserAccountID, + new { uid = dtwa.InstanceGUID, tmptbl }); }; dtwa.OnCommandAfterError += (_, exc) => { importFailed = true; importFailure = exc.Message; - _logger.LogError(exc, + _logger.LogError(new EventId(0, "IntranetController.bam.up - command-after exception"), exc, "Banking upload merge-command exception — file={File} destTable={DestTable} " + - "rescueTable={RescueTable} user={User}", - fle.FileName, dtwa.DestinationTableName, tmptbl, UserAccountID); - _intranet.debug_log("IntranetController.bam.up - command-after exception", - exc, UserAccountID, new { uid = dtwa.InstanceGUID, tmptbl }); + "rescueTable={RescueTable} user={User} data={Data}", + fle.FileName, dtwa.DestinationTableName, tmptbl, UserAccountID, + new { uid = dtwa.InstanceGUID, tmptbl }); }; _logger.LogDebug("Banking upload parsed {Rows} rows → temp table submit (user={User})", tbl.Rows.Count, UserAccountID); diff --git a/Fuchs/Controllers/IntranetController.PdfPreview.cs b/Fuchs/Controllers/IntranetController.PdfPreview.cs index e9e7877..63dc8ba 100644 --- a/Fuchs/Controllers/IntranetController.PdfPreview.cs +++ b/Fuchs/Controllers/IntranetController.PdfPreview.cs @@ -9,11 +9,12 @@ namespace Fuchs.Controllers; // // A preview render can fail deep inside MigraDoc / Spire (fonts, licence, malformed HTML in an // item text, an oversized inline image, ...). Before this guard such a failure only surfaced as -// the generic catch-all in Do(): an ErrorLog.txt line on the web server, nothing in the -// fds__admin_logdebug table support actually reads, and an empty "Der Server hat einen Fehler -// gemeldet:" alert in the browser. Every preview now goes through PdfPreviewAsync so the failure -// is (1) written to the DB log with what/id/user/duration, (2) counted, (3) toasted to the user -// and (4) returned with a readable description header. +// the generic catch-all in Do(): an ErrorLog.txt line on the web server, nothing in the DB log +// support actually reads, and an empty "Der Server hat einen Fehler gemeldet:" alert in the +// browser. Every preview now goes through PdfPreviewAsync so the failure is (1) logged with +// what/ref/user/duration — which the SQL log sink (ADR 0024) additionally persists to +// fds__debuglog — (2) counted, (3) toasted to the user and (4) returned with a readable +// description header. public partial class IntranetController { internal const string PdfPreviewLogReference = "PDF preview failed"; @@ -35,11 +36,15 @@ public partial class IntranetController { var result = await render(); sw.Stop(); + // A draft session that expired between page load and preview click is an expected + // client-driven outcome (the browser reopens the draft), not a render failure — keep + // it out of the failure telemetry/logging this guard exists to produce. + var outcome = result is ObjectResult { StatusCode: 410 } ? "gone" : "success"; FuchsTelemetry.PdfPreviews.Add(1, new KeyValuePair("what", what), - new KeyValuePair("outcome", "success")); - _logger.LogInformation("PDF preview {What} ref={RefId} user={User} done in {Ms} ms", - what, refId, UserAccountID, sw.ElapsedMilliseconds); + new KeyValuePair("outcome", outcome)); + _logger.LogInformation("PDF preview {What} ref={RefId} user={User} {Outcome} in {Ms} ms", + what, refId, UserAccountID, outcome, sw.ElapsedMilliseconds); return result; } catch (Exception ex) @@ -49,38 +54,34 @@ public partial class IntranetController FuchsTelemetry.PdfPreviews.Add(1, new KeyValuePair("what", what), new KeyValuePair("outcome", "failure")); - _logger.LogError(ex, "PDF preview {What} ref={RefId} user={User} failed after {Ms} ms", + // EventId.Name keeps the exact "PDF preview failed (what)" CodeReference the DB log + // used before the generic SQL sink existed (ADR 0024). + _logger.LogError(new EventId(0, $"{PdfPreviewLogReference} ({what})"), ex, + "PDF preview {What} ref={RefId} user={User} failed after {Ms} ms", what, refId, UserAccountID, sw.ElapsedMilliseconds); - _intranet.debug_log($"{PdfPreviewLogReference} ({what})", ex, UserAccountID, - BuildPdfPreviewLogData(what, refId, UserAccountID, sw.ElapsedMilliseconds)); - await _events.UserIssueAsync( - "PDF-Vorschau fehlgeschlagen", - "Die PDF-Vorschau konnte nicht erstellt werden. Der Fehler wurde protokolliert.", - UserAccountID, - new Dictionary { ["what"] = what, ["ref"] = refId }); - return ServerError(PdfPreviewFailureMessage(ex)); + // Pre-auth flows (some preview endpoints are in _allowedGet, see IntranetController.cs) + // have no user session to notify, matching the guard the Do() catch-all uses. + if (UserIdent.IsAuthenticated) + { + await _events.UserIssueAsync( + "PDF-Vorschau fehlgeschlagen", + "Die PDF-Vorschau konnte nicht erstellt werden. Der Fehler wurde protokolliert.", + UserAccountID, + new Dictionary { ["what"] = what, ["ref"] = refId }); + } + return ServerError(PdfPreviewFailureMessage(ex, UserIdent.IsAuthenticated)); } } - /// Serialisable payload for the DB log row of a failed preview. - internal static Dictionary BuildPdfPreviewLogData(string what, string refId, string user, long elapsedMs) => - new() - { - ["what"] = what, - ["ref"] = refId, - ["user"] = user, - ["ms"] = elapsedMs - }; - /// - /// User-facing message: the innermost exception text is included so the customer can quote - /// it to support (this is an internal intranet; the message never carries secrets). + /// User-facing message. The innermost exception text is only included for an authenticated + /// intranet user — some preview endpoints are reachable unauthenticated (see _allowedGet in + /// IntranetController.cs), so an anonymous caller gets a generic message instead. /// - internal static string PdfPreviewFailureMessage(Exception ex) + internal static string PdfPreviewFailureMessage(Exception ex, bool includeDetail) { - var root = ex; - while (root.InnerException != null) root = root.InnerException; - string detail = (root.Message ?? "").Trim(); + if (!includeDetail) return "Die PDF-Vorschau konnte nicht erstellt werden."; + string detail = ex.GetBaseException().Message?.Trim() ?? ""; return detail.Length == 0 ? "Die PDF-Vorschau konnte nicht erstellt werden." : $"Die PDF-Vorschau konnte nicht erstellt werden: {detail}"; diff --git a/Fuchs/Controllers/IntranetController.cs b/Fuchs/Controllers/IntranetController.cs index 4e34709..7a7327f 100644 --- a/Fuchs/Controllers/IntranetController.cs +++ b/Fuchs/Controllers/IntranetController.cs @@ -205,13 +205,11 @@ public partial class IntranetController : Microsoft.AspNetCore.Mvc.Controller } catch (Exception ex) { - _logger.LogError(ex, "Unhandled exception in Do fn={Fn} id={Id} code={Code} user={User}", - fn, id, code, UserAccountID); - // Also persist to fds__admin_logdebug: the ILogger sink is a file on the web server, - // while the DB log is what support actually pulls from the customer's database — an - // unhandled handler exception used to be invisible there. - _intranet.debug_log($"Unhandled exception in Do {fn}/{id}", ex, UserAccountID, - BuildDoErrorLogData(fn, id, code, UserAccountID, RequestFormKeys())); + // EventId.Name keeps the exact CodeReference the DB log used before the generic SQL + // sink existed (ADR 0024); formKeys is form field NAMES only, never values (PII/tokens). + _logger.LogError(new EventId(0, $"Unhandled exception in Do {fn}/{id}"), ex, + "Unhandled exception in Do fn={Fn} id={Id} code={Code} user={User} formKeys={FormKeys}", + fn, id, code, UserAccountID, RequestFormKeys()); // Standing rule: an exception that interrupts a user-initiated action must reach the // user as a notification, not only the log. This is the catch-all safety net for any // Do_Process_* action that throws without first publishing its own (more specific) @@ -233,18 +231,6 @@ public partial class IntranetController : Microsoft.AspNetCore.Mvc.Controller private string[] RequestFormKeys() => Request.HasFormContentType ? Request.Form.Keys.ToArray() : Array.Empty(); - /// Serialisable context for the DB log row of an unhandled exception. - internal static Dictionary BuildDoErrorLogData( - string fn, string id, string code, string user, IReadOnlyCollection formKeys) => - new() - { - ["fn"] = fn, - ["id"] = id, - ["code"] = code, - ["user"] = user, - ["formKeys"] = formKeys - }; - // ── Auth helper ─────────────────────────────────────────────────────────── private async Task HandleAuth(string fn, string id, string code) { diff --git a/Fuchs/Docs/Concepts/error-logging-pipeline.md b/Fuchs/Docs/Concepts/error-logging-pipeline.md new file mode 100644 index 0000000..83e0137 --- /dev/null +++ b/Fuchs/Docs/Concepts/error-logging-pipeline.md @@ -0,0 +1,99 @@ +--- +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. diff --git a/Fuchs/Docs/Decisions/0023-user-action-failures-persisted-to-db-log.md b/Fuchs/Docs/Decisions/0023-user-action-failures-persisted-to-db-log.md index a016aab..61b120e 100644 --- a/Fuchs/Docs/Decisions/0023-user-action-failures-persisted-to-db-log.md +++ b/Fuchs/Docs/Decisions/0023-user-action-failures-persisted-to-db-log.md @@ -1,13 +1,20 @@ --- -status: Accepted +status: Superseded date: 2026-09-16 applyTo: - "Fuchs/Controllers/**" - "Fuchs/code/FuchsIntranet.cs" - "Fuchs/js/intranet/**" -supersededBy: "" +supersededBy: "0024-multilogger-sql-log-sink.md" --- +> **Superseded by [0024](0024-multilogger-sql-log-sink.md).** The explicit `Fuchs_intranet.debug_log` / +> `fds__admin_logdebug` DB write this decision introduced was retired the same day, once +> [0024](0024-multilogger-sql-log-sink.md) made `ILogger` itself the single path to the DB log +> (`fds__admin_logdebug_ext`, same `fds__debuglog` table). Keeping both would have double-written +> every row. The frontend/`x-ocms-desc`/`EncodeResponseDescription`/preview-timeout decisions below +> are unaffected and still in force — only the *DB write mechanism* changed. + # 0023 — Failures of user actions are persisted to `fds__admin_logdebug`, with the SQL and a readable description ## Context @@ -36,7 +43,10 @@ rarely reachable. Reviewing the 2026-09-16 production extract of that table show `Unhandled exception in Do {fn}/{id}` with route, user and the form *field names* (never values — they can carry tokens/PII); the PDF-preview endpoints go through a shared guard (`IntranetController.PdfPreviewAsync`) that logs `PDF preview failed (endpoint)` with - ref/user/duration, counts `fuchs.pdf.previews{outcome}` and toasts the user. + ref/user/duration, counts `fuchs.pdf.previews{outcome}` (`success`/`gone`/`failure` — an + expired-draft `410` from inside `render()` is its own `gone` outcome, not `success`, since + it is not the render failure this guard exists to catch) and, for an authenticated caller, + toasts the user. - **A 500 carries its message in the `x-ocms-desc` header** (`ServerError(msg)` → `EncodeResponseDescription`: percent-encoded ASCII, spaces as `%20` because the client maps `+` to space before `decodeURIComponent`). Handlers that return a 500 should pass a @@ -53,7 +63,10 @@ rarely reachable. Reviewing the 2026-09-16 production extract of that table show added to hot/success paths (see [0003](0003-structured-diagnostic-logging.md) on the cost of DB logging). - `x-ocms-desc` is user-facing: messages must be German, short, and free of secrets. The - innermost exception text is acceptable for an internal intranet audience. + innermost exception text is acceptable for an authenticated intranet user, but some + preview endpoints (`req/idoc`, `inv/rdoc`, `inv/rdocn`, `rem/idoc` — see `_allowedGet` + in `IntranetController.cs`) are reachable without authentication; `PdfPreviewFailureMessage` + omits the exception detail for those callers and falls back to the generic message. ## Alternatives considered - **Enable `FuchsLoggerProvider.DatabaseLoggingEnabled`** so every `ILogger` error lands in diff --git a/Fuchs/Docs/Decisions/0024-multilogger-sql-log-sink.md b/Fuchs/Docs/Decisions/0024-multilogger-sql-log-sink.md new file mode 100644 index 0000000..b966bfb --- /dev/null +++ b/Fuchs/Docs/Decisions/0024-multilogger-sql-log-sink.md @@ -0,0 +1,114 @@ +--- +status: Accepted +date: 2026-09-16 +applyTo: + - "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" +supersededBy: "" +--- + +# 0024 — `ILogger` is the single path to the DB log, via the OCORE MultiLogger SQL sink + +## Context +[0023](0023-user-action-failures-persisted-to-db-log.md) 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. diff --git a/Fuchs/Logging/RequestLogScopeMiddleware.cs b/Fuchs/Logging/RequestLogScopeMiddleware.cs new file mode 100644 index 0000000..68396cd --- /dev/null +++ b/Fuchs/Logging/RequestLogScopeMiddleware.cs @@ -0,0 +1,41 @@ +using Fuchs.intranet; + +namespace Fuchs.Logging; + +/// +/// Pushes a per-request logging scope (request id, path, and — once cookie auth has populated +/// — the authenticated user id) so every log line written while +/// handling this request, including ones written deep inside OCORE (SQL errors, PDF render +/// failures, ...), carries that attribution automatically. See ADR 0024: the scope flows into +/// every sink's serialized context (LogEntry.dataSerialized, via +/// 's context merging) and — for "authuser" +/// specifically — into the dedicated column the +/// SQL sink writes to fds__debuglog.AuthUser. +/// Registered after UseAuthentication() so the user claim is already populated. +/// +public sealed class RequestLogScopeMiddleware +{ + private readonly RequestDelegate _next; + + public RequestLogScopeMiddleware(RequestDelegate next) => _next = next; + + public async Task InvokeAsync(HttpContext context, ILogger logger) + { + using (logger.BeginScope(BuildScope(context))) + await _next(context); + } + + /// Pure so the scope shape is unit-testable without a live request pipeline. + internal static Dictionary BuildScope(HttpContext context) + { + var scope = new Dictionary + { + ["requestId"] = context.TraceIdentifier, + ["path"] = context.Request.Path.Value ?? "", + }; + string? authUser = context.User?.FindFirst(FuchsUserIdentity.ClaimUserAccountId)?.Value; + if (!string.IsNullOrEmpty(authUser)) + scope["authuser"] = authUser; + return scope; + } +} diff --git a/Fuchs/Program.cs b/Fuchs/Program.cs index ea0f2f5..3a90447 100644 --- a/Fuchs/Program.cs +++ b/Fuchs/Program.cs @@ -8,6 +8,7 @@ using Microsoft.AspNetCore.Authentication.Cookies; using Microsoft.AspNetCore.StaticFiles; using Microsoft.Extensions.FileProviders; using Microsoft.Extensions.Logging; +using OCORE.MultiLogger; using OCORE.security; using OCORE.web; using OpenTelemetry.Metrics; @@ -53,6 +54,26 @@ public class Program // Initialize the Fuchs intranet singleton with configuration FuchsOcmsIntranet.Initialize(builder.Configuration); + // SQL log sink (Warning+, ADR 0024): every _logger.LogWarning/-Error/-Critical call — not + // just the explicit ones that used to call Fuchs_intranet.debug_log — additionally lands in + // [dbo].[fds__debuglog] via [dbo].[fds__admin_logdebug_ext], with the failing SQL/context + // (redacted), the ILogger category, and — via RequestLogScopeMiddleware's scope — the + // request id and authenticated user, all in dedicated/serialized columns. The file sink + // above (AddFuchsLogging) stays the always-on baseline; this is the durable, queryable copy + // support actually reads from. Config switch (default on) allows disabling per environment. + if (builder.Configuration.GetValue("Fuchs:Logging:SqlSink:Enabled", true)) + { + builder.Logging.AddSqlLogger(); + builder.Services.Configure(o => + { + o.SQL.ConnectionString = FuchsOcmsIntranet.Instance.Intranet__SQLConnectionString; + o.SQL.StoredProcedure = "dbo.fds__admin_logdebug_ext"; + o.SQL.LogLevel = LogLevel.Warning; + o.SQL.TruncateTextAt = 4000; + o.SQL.IncludeCategory = true; // fds__admin_logdebug_ext declares @category + }); + } + // Initialize FdsConfig so FdsMfr / FdsMfrClient can resolve connection strings fds.FdsConfig.Initialize(builder.Configuration); @@ -238,6 +259,9 @@ public class Program app.UseRouting(); app.UseAuthentication(); + // After authentication (needs the user claim) and before authorization/dispatch — see + // RequestLogScopeMiddleware for what this attributes every log line in the request to. + app.UseMiddleware(); app.UseAuthorization(); app.MapHub("/notifications"); app.MapHub("/draftpreview"); diff --git a/Fuchs/appsettings.json b/Fuchs/appsettings.json index e44728d..7a8d6b9 100644 --- a/Fuchs/appsettings.json +++ b/Fuchs/appsettings.json @@ -70,6 +70,11 @@ "Enabled": true, "OtlpEndpoint": "" }, + "Logging": { + "SqlSink": { + "Enabled": true + } + }, "ERechnung": { "Enabled": false, "Profile": "EN16931", diff --git a/Fuchs/code/FuchsIntranet.cs b/Fuchs/code/FuchsIntranet.cs index a8720a5..e9e3620 100644 --- a/Fuchs/code/FuchsIntranet.cs +++ b/Fuchs/code/FuchsIntranet.cs @@ -153,25 +153,6 @@ public class Fuchs_intranet return val.Exception != "" ? -1 : val.Result; } - // -- Logging --------------------------------------------------------------- - public void debug_log(string procedure, Exception? ex = null, string authuser = "", object? data = null) - { - try - { - var pl = new List - { - SQL_VarChar("@CodeReference", procedure.Left(200)), - SQL_NVarChar("@ExceptionMessage", ex?.Message ?? "", dbNull_IfEmpty: true), - SQL_NVarChar("@StackTrace", ex?.StackTrace ?? "", dbNull_IfEmpty: true), - SQL_NVarChar("@Data", data != null ? Newtonsoft.Json.JsonConvert.SerializeObject(data) : "", dbNull_IfEmpty: true) - }; - string dbEx = ""; int? dbCode = null; - setSQLValue("EXECUTE [dbo].[fds__admin_logdebug] @CodeReference, @ExceptionMessage, @StackTrace, @Data;", - Intranet_SqlCon(), ref dbEx, ref dbCode, pl, Security: GetDbSecurity(authuser)); - } - catch { /* swallow logging errors */ } - } - // -- PDF license ----------------------------------------------------------- public static void SetPdfLicense() { @@ -219,52 +200,30 @@ public class FuchsUserIdentity // --------------------------- SQL options ------------------------------------- /// -/// Fuchs-specific SQL options — logs every SQL error both to the app's structured -/// /OpenTelemetry pipeline and to the fds__admin_logdebug SQL -/// table (via ). Handlers that don't separately inspect -/// the result's .Exception would otherwise return an empty/200 response on a failing -/// stored procedure with zero application-log signal — the DB table alone requires someone to -/// go looking for it. +/// Fuchs-specific SQL options — logs every SQL error through the app's structured +/// pipeline (which, at Warning+, also lands in fds__debuglog via +/// the SQL log sink — see ADR 0024). Handlers that don't separately inspect the result's +/// .Exception would otherwise return an empty/200 response on a failing stored procedure +/// with zero log signal. /// public class FIS_SQLOptions : sqloptions { public FIS_SQLOptions(Dictionary? context = null, ILogger? logger = null) - : this(context, logger, dbLog: (procedure, ex, data) => FuchsOcmsIntranet.Instance.debug_log(procedure, ex, data: data)) - { - } - - /// - /// Test seam: receives what would otherwise go to - /// (code reference, exception, serialisable data). - /// - internal FIS_SQLOptions(Dictionary? context, ILogger? logger, - Action dbLog) { OnError = (procedure, ex, data) => { // OCORE hands the failing statement in `data` (new { sql = ... }); `context` is the - // caller's fn/id/code. Both are needed to attribute a timeout in the DB log — logging - // only the (usually null) context left every "SQL Error in getSQLDataSet" row without - // the SQL that timed out. - var logData = BuildLogData(context, data); - logger?.LogError(ex, "SQL error in {Procedure}: {Message} — sql={@Sql} context={@Context}", + // caller's fn/id/code. Both are needed to attribute a timeout in the log — logging only + // the (usually null) context left every "SQL Error in getSQLDataSet" row without the + // SQL that timed out. Falls back to the static OCORE.Logging.Logger (set once in + // Program.cs) when no request/service-scoped logger was supplied — several callers + // construct `new FIS_SQLOptions()` with neither logger nor context, and those must + // still reach the log, not silently drop it. EventId.Name keeps the exact + // "SQL Error in {procedure}" CodeReference the DB log used before this pipeline existed. + var lg = logger ?? OCORE.Logging.Logger; + lg?.LogError(new EventId(0, $"SQL Error in {procedure}"), ex, + "SQL error in {Procedure}: {Message} — sql={Sql} context={Context}", procedure, ex.Message, data, context); - try { dbLog($"SQL Error in {procedure}", ex, logData); } - catch { } }; } - - /// Merges the OCORE error payload (the SQL) with the caller context into one JSON-able object. - internal static Dictionary BuildLogData(IReadOnlyDictionary? context, object? data) - { - var d = new Dictionary(); - if (data != null) - { - // OCORE passes new { sql = "..." }; unwrap so the log column reads as the plain statement. - var sqlProp = data.GetType().GetProperty("sql"); - d["sql"] = sqlProp?.GetValue(data) ?? data; - } - if (context is { Count: > 0 }) d["context"] = context; - return d; - } } diff --git a/Fuchs_DataService/FdsMfr.cs b/Fuchs_DataService/FdsMfr.cs index 1e15426..cdc27a1 100644 --- a/Fuchs_DataService/FdsMfr.cs +++ b/Fuchs_DataService/FdsMfr.cs @@ -14,11 +14,18 @@ using static OCORE.commons; namespace fds; /// -/// Logs every SQL error both to the worker's structured (so it reaches -/// whatever sink/OTel export is configured) and to (SQL/local-file -/// debug trail). Passing is optional for call sites that don't have one -/// in scope, but every caller that does have one in scope should pass it — otherwise a failing -/// stored procedure only ever shows up in the debug trail, never in the worker's own logs. +/// Logs every SQL error through the worker's structured alone — which, when +/// this worker runs hosted inside the Fuchs web app (ADR 0010), also reaches the OCORE MultiLogger +/// SQL sink at Warning+ (ADR 0024) and lands in the same fds__debuglog table +/// FdsDebug.DebugLog used to write to directly. Calling both here would double-write +/// every row, which is exactly what the original 2026-09-16 log review's back-to-back +/// "mfr__getSchema"/"fds__getUpdateableRequests" deadlock entries were heading towards once the +/// SQL sink went live — so this class no longer calls FdsDebug.DebugLog. Passing a +/// logger is optional; falls back to the static +/// (set once in Program.cs) so a failing stored procedure is never silently dropped. +/// FdsDebug.DebugLog remains the primary/only DB-attribution path for every other +/// call site in this project that doesn't separately log through — it was +/// deliberately not migrated onto the generic pipeline (see ADR 0024's Consequences). /// public class FdsSqlOptions : sqloptions { @@ -29,9 +36,12 @@ public class FdsSqlOptions : sqloptions _baseInfo = dic; OnError = (procedure, ex, data) => { - logger?.LogError(ex, "SQL error in {Procedure}: {Message} — ctrl_nfo={CtrlInfo} sql={Data}", + var lg = logger ?? OCORE.Logging.Logger; + // EventId.Name == procedure keeps the exact CodeReference the direct DebugLog() call + // used to write (it passed `procedure` as-is, not prefixed). + lg?.LogError(new EventId(0, procedure), ex, + "SQL error in {Procedure}: {Message} — ctrl_nfo={CtrlInfo} sql={Data}", procedure, ex.Message, dic, data); - FdsDebug.DebugLog(procedure, exc: ex, data: $"ctrl_nfo={dic}, sql={data}"); }; } } diff --git a/Fuchs_DataService/Fuchs_DataService.xml b/Fuchs_DataService/Fuchs_DataService.xml index a160844..e22f5eb 100644 --- a/Fuchs_DataService/Fuchs_DataService.xml +++ b/Fuchs_DataService/Fuchs_DataService.xml @@ -6,11 +6,18 @@ - Logs every SQL error both to the worker's structured (so it reaches - whatever sink/OTel export is configured) and to (SQL/local-file - debug trail). Passing is optional for call sites that don't have one - in scope, but every caller that does have one in scope should pass it — otherwise a failing - stored procedure only ever shows up in the debug trail, never in the worker's own logs. + Logs every SQL error through the worker's structured alone — which, when + this worker runs hosted inside the Fuchs web app (ADR 0010), also reaches the OCORE MultiLogger + SQL sink at Warning+ (ADR 0024) and lands in the same fds__debuglog table + FdsDebug.DebugLog used to write to directly. Calling both here would double-write + every row, which is exactly what the original 2026-09-16 log review's back-to-back + "mfr__getSchema"/"fds__getUpdateableRequests" deadlock entries were heading towards once the + SQL sink went live — so this class no longer calls FdsDebug.DebugLog. Passing a + logger is optional; falls back to the static + (set once in Program.cs) so a failing stored procedure is never silently dropped. + FdsDebug.DebugLog remains the primary/only DB-attribution path for every other + call site in this project that doesn't separately log through — it was + deliberately not migrated onto the generic pipeline (see ADR 0024's Consequences). diff --git a/Fuchs_Database/FuchsDatabase.sqlproj b/Fuchs_Database/FuchsDatabase.sqlproj index 7eb264c..a313bc4 100644 --- a/Fuchs_Database/FuchsDatabase.sqlproj +++ b/Fuchs_Database/FuchsDatabase.sqlproj @@ -353,6 +353,7 @@ + diff --git a/Fuchs_Database/dbo/Stored Procedures/fds__admin_logdebug_ext.sql b/Fuchs_Database/dbo/Stored Procedures/fds__admin_logdebug_ext.sql new file mode 100644 index 0000000..8b696d6 --- /dev/null +++ b/Fuchs_Database/dbo/Stored Procedures/fds__admin_logdebug_ext.sql @@ -0,0 +1,61 @@ +-- ============================================= +-- Author: Dr. Stefan Ott +-- Create date: 2026-09-16 +-- Description: Sink for OCORE.MultiLogger.SqlLoggerProvider (see ADR 0024 in Fuchs/Docs/Decisions). +-- Parameter names/types must match SqlLoggerProvider.BuildParameters exactly — this +-- proc is called generically (CommandType.StoredProcedure), so a mismatched or missing +-- parameter fails every write, not just this one. +-- Writes into the same [dbo].[fds__debuglog] table the legacy, explicit +-- fds__admin_logdebug proc writes to, so both paths are queried identically. +-- ============================================= +CREATE PROCEDURE [dbo].[fds__admin_logdebug_ext] + @machine varchar(max) = NULL + ,@error varchar(max) = NULL + ,@exception varchar(max) = NULL + ,@data nvarchar(max) = NULL + ,@procedure varchar(max) = NULL + ,@category varchar(max) = NULL + ,@account varchar(max) = NULL + ,@authuser varchar(max) = NULL + ,@isdebug bit = 0 + ,@loglevel varchar(1) = NULL +AS +BEGIN + SET NOCOUNT ON; + + -- Every text parameter is declared varchar(max)/nvarchar(max), matching the client's wire size + -- (SqlLoggerProvider's local SQL_VarChar/SQL_NVarChar helpers always send Size=-1) — so nothing + -- can fail at the parameter-assignment boundary. The [dbo].[fds__debuglog] columns that are + -- narrower (Machine/Category/Account/AuthUser, CodeReference) are explicitly LEFT()-truncated + -- below instead, so a value longer than the column never raises a truncation error on INSERT. + -- + -- CodeReference: the EventId name a caller gave the log call (@procedure) when there is one — + -- most call sites that matter (SQL errors, PDF-preview failures, the Do() catch-all) set this + -- explicitly to the same string the legacy debug_log() callers used, so existing CodeReference + -- queries/dashboards keep working unchanged. Falls back to the ILogger category, then a + -- constant, for the many ordinary _logger.LogWarning/-Error calls that carry no EventId. + INSERT INTO [dbo].[fds__debuglog] + ([CodeReference] + ,[ExceptionMessage] + ,[StackTrace] + ,[Data] + ,[timestamp] + ,[LogLevel] + ,[Machine] + ,[Category] + ,[Account] + ,[AuthUser] + ,[IsDebug]) + VALUES + (LEFT(COALESCE(NULLIF(@procedure, ''), NULLIF(@category, ''), 'MultiLogger'), 255) + ,@error + ,@exception + ,@data + ,GETUTCDATE() + ,@loglevel + ,LEFT(@machine, 255) + ,LEFT(@category, 255) + ,NULLIF(LEFT(@account, 100), '') + ,NULLIF(LEFT(@authuser, 100), '') + ,@isdebug); +END diff --git a/Fuchs_Database/dbo/Tables/fds__debuglog.sql b/Fuchs_Database/dbo/Tables/fds__debuglog.sql index 8a1b197..6880871 100644 --- a/Fuchs_Database/dbo/Tables/fds__debuglog.sql +++ b/Fuchs_Database/dbo/Tables/fds__debuglog.sql @@ -4,6 +4,15 @@ [ExceptionMessage] VARCHAR (MAX) NULL, [StackTrace] VARCHAR (MAX) NULL, [Data] VARCHAR (MAX) NULL, - [timestamp] DATETIME NULL + [timestamp] DATETIME NULL, + -- Columns below are populated only by rows written through the generic OCORE MultiLogger SQL + -- sink (fds__admin_logdebug_ext, see ADR 0024) — every _logger.LogWarning/-Error/-Critical call + -- at Warning+, attributed automatically. NULL on rows still written by the legacy, explicit + -- fds__admin_logdebug proc call. + [LogLevel] CHAR (1) NULL, -- T/D/I/W/E/C, see OCORE.MultiLogger.SqlLoggerProvider.LogLevelChar + [Machine] VARCHAR (255) NULL, -- Environment.MachineName of the writing process + [Category] VARCHAR (255) NULL, -- ILogger category, e.g. Fuchs.Controllers.IntranetController + [Account] VARCHAR (100) NULL, -- reserved by the shared OCORE proc contract; unused by Fuchs + [AuthUser] VARCHAR (100) NULL, -- fuchs:useraccount_id of the request, when known + [IsDebug] BIT NULL -- true when a debugger was attached to the writing process ); - diff --git a/OCORE b/OCORE index d249bb3..3137b56 160000 --- a/OCORE +++ b/OCORE @@ -1 +1 @@ -Subproject commit d249bb3b2a7c1cb565771c6a647683ec9b7b55c4 +Subproject commit 3137b5601a506b02316f8d07368f65720b7eada0