fix(calculation): dead logger cast + warm-up evaluated before change-gate (review)

Code review of Driver.Calculation found two real defects, both TDD-fixed: - CalculationDriver's ctor tried to reuse its ILogger<CalculationDriver> as the evaluator's ILogger<CalculationEvaluator> via an `is` check that can never succeed (unrelated closed generics), so CalculationEvaluator always ran with a NullLogger regardless of what the driver was constructed with. Fixed by having CalculationEvaluator accept the non-generic ILogger instead. - EvaluateTag called the evaluator BEFORE checking whether every declared dependency had arrived, so a multi-dependency change-triggered calc tag evaluated its script against a partial snapshot on every warm-up tick. VirtualTagContext.GetTag returns a Bad snapshot (.Value == null) for a missing dep, so the idiomatic `(double)ctx.GetTag("x").Value` cast throws NullReferenceException — caught and logged as a spurious "script threw" script-log Warning on ordinary deploy/restart warm-up, for the standard multi-input calc-tag shape. Fixed by gating evaluation itself on "all deps arrived", not just the publish. See code-reviews/Driver.Calculation/findings.md for full detail (5 findings: 001-004 Resolved, 005 Open/cross-module).
2026-08-10 06:59:23 -04:00
parent b990adae55
commit a836e0d983
4 changed files with 367 additions and 15 deletions
@@ -1,4 +1,5 @@
 using System.Collections.Concurrent;
+using Microsoft.Extensions.Logging;
 using Serilog;
 using Serilog.Events;
 using Shouldly;
@@ -74,6 +75,27 @@ public sealed class CalculationDriverTests
        e.Snapshot.StatusCode.ShouldBe(StatusGood);
    }

+    /// <summary>
+    ///     The change-gate must hold BEFORE the script ever runs, not just before the publish. A
+    ///     multi-dependency script that casts a missing dep's <c>.Value</c> to a non-nullable type (the
+    ///     common idiom used throughout this file) throws when evaluated against a partial snapshot, so
+    ///     evaluating anyway during ordinary warm-up produced a spurious "script threw" script-log Warning
+    ///     on every partial dependency arrival — even though nothing is actually wrong with the script.
+    /// </summary>
+    [Fact]
+    public async Task No_evaluation_or_script_log_while_a_declared_dep_is_still_missing()
+    {
+        var (driver, published, logs) = Build(
+            CalcTag("calc/e/sum", "return (double)ctx.GetTag(\"src/a\").Value + (double)ctx.GetTag(\"src/b\").Value;"));
+        await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
+
+        driver.OnDependencyValue("src/a", 10.0, StatusGood, DateTime.UtcNow);
+
+        published.ShouldBeEmpty();
+        logs.ShouldBeEmpty("a still-missing declared dependency must hold the gate BEFORE evaluation, " +
+                            "not merely before the publish");
+    }
+
    // ── dedup + recompute ─────────────────────────────────────────────────────────────────────

    [Fact]
@@ -209,6 +231,102 @@ public sealed class CalculationDriverTests
        driver.GetHealth().State.ShouldBe(DriverState.Unknown);
    }

+    // ── evaluator diagnostics reach the driver's own logger ──────────────────────────────────────
+
+    /// <summary>
+    ///     The <see cref="CalculationEvaluator"/> the driver constructs internally must log its host-side
+    ///     diagnostics (compile errors, sandbox violations, execution throws) through the SAME
+    ///     <c>ILogger&lt;CalculationDriver&gt;</c> the driver itself was given — not silently into a
+    ///     no-op logger. A timer-triggered tag with a deliberately broken script is the vehicle: it
+    ///     evaluates on its own cadence with no dependency needed to arrive first.
+    /// </summary>
+    [Fact]
+    public async Task Evaluator_compile_diagnostics_flow_through_to_the_drivers_own_logger()
+    {
+        var logger = new CapturingLogger();
+        var scriptRoot = new ScriptRootLogger(new LoggerConfiguration().CreateLogger());
+        var driver = new CalculationDriver(
+            new CalculationDriverOptions
+            {
+                RawTags = [CalcTag("calc/e/bad", "this is not valid C#;", changeTriggered: false, timerMs: 50)],
+            },
+            "calc-drv", scriptRoot, logger);
+        await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
+
+        var fired = await WaitUntil(
+            () => logger.Entries.Any(e => e.Level == LogLevel.Warning && e.Message.Contains("Roslyn compile failed")),
+            TimeSpan.FromSeconds(3));
+
+        fired.ShouldBeTrue("the evaluator's compile-failure diagnostic should reach the driver-supplied logger");
+
+        await driver.ShutdownAsync(TestContext.Current.CancellationToken);
+    }
+
+    // ── skipped-tag reporting (Gitea #541) ────────────────────────────────────────────────────────
+
+    [Fact]
+    public async Task GetSkippedTags_reports_a_raw_tag_with_no_scriptId_alongside_the_authored_total()
+    {
+        var noScriptId = new RawTagEntry("calc/e/nogood", "{\"foo\":\"bar\"}", WriteIdempotent: false);
+        var good = CalcTag("calc/e/good", "return 1.0;", changeTriggered: false);
+        var (driver, _, _) = Build(noScriptId, good);
+        await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
+
+        var report = driver.GetSkippedTags();
+
+        report.ShouldNotBeNull();
+        report!.AuthoredCount.ShouldBe(2);
+        report.SkippedCount.ShouldBe(1);
+        report.Sample.ShouldContain(s => s.RawPath == "calc/e/nogood");
+    }
+
+    [Fact]
+    public async Task GetSkippedTags_has_no_skips_when_every_authored_tag_maps()
+    {
+        var (driver, _, _) = Build(CalcTag("calc/e/good", "return 1.0;", changeTriggered: false));
+        await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
+
+        var report = driver.GetSkippedTags();
+
+        report.ShouldNotBeNull();
+        report!.AuthoredCount.ShouldBe(1);
+        report.SkippedCount.ShouldBe(0);
+        report.HasSkips.ShouldBeFalse();
+    }
+
+    /// <summary>The skip ledger must be REBUILT on ReinitializeAsync, not just at construction — an
+    /// ApplyDelta that drops a tag's scriptId (or adds a new tag with none) must be reflected immediately,
+    /// since RebuildTagTable is the one routine both the ctor and reinit share.</summary>
+    [Fact]
+    public async Task GetSkippedTags_updates_after_reinitialize()
+    {
+        var (driver, _, _) = Build(CalcTag("calc/e/x", "return 1.0;", changeTriggered: false));
+        await driver.InitializeAsync("{}", TestContext.Current.CancellationToken);
+        driver.GetSkippedTags()!.SkippedCount.ShouldBe(0);
+
+        const string reinitJson = """{"rawTags":[{"rawPath":"calc/e/x","tagConfig":"{}","writeIdempotent":false}]}""";
+        await driver.ReinitializeAsync(reinitJson, TestContext.Current.CancellationToken);
+
+        var report = driver.GetSkippedTags();
+        report!.AuthoredCount.ShouldBe(1);
+        report.SkippedCount.ShouldBe(1, "the reinit payload's tag has no scriptId, so it is no longer a calc tag");
+    }
+
+    /// <summary>Minimal capturing <see cref="ILogger{T}"/> so a test can assert on what the driver's own
+    /// logger received (mirrors the equivalent helper in CalculationEvaluatorTests).</summary>
+    private sealed class CapturingLogger : ILogger<CalculationDriver>
+    {
+        public List<(LogLevel Level, string Message)> Entries { get; } = [];
+
+        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) =>
+            Entries.Add((logLevel, formatter(state, exception)));
+    }
+
    private sealed class CapturingPublisher(List<ScriptLogEntry> sink) : IScriptLogPublisher
    {
        private readonly object _lock = new();