Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundScriptExecutorTests.cs
T
Joseph Doherty 463aced7a1 test(inboundapi): root the shared in-memory SQLite keep-alive so the database cannot vanish mid-test
Script_UsingDatabase_QueriesViaGateway failed in about 2 of 27 full InboundAPI runs. Looping the
suite 30 times captured the failure 4 times, always as "Internal script error". The exception
underneath was SqliteException 'no such table: Machine'.

Cause: the seeding helper opened its keep-alive SqliteConnection in a local. Once the helper
returned, nothing referenced that connection. After a GC (likely during the Roslyn compile, under
full-suite load), Microsoft.Data.Sqlite's pool reclaimed the leaked connection and closed the last
connection to the shared in-memory database, which destroyed it.

Fix: hold the keep-alive in a static field. InboundDatabaseHelperTests had the same latent bug and
gets the same fix. The test now forces GC plus SqliteConnection.ClearAllPools() before the query.
That makes the old pattern fail deterministically and the fix pass deterministically.

Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
2026-11-10 06:12:34 -05:00

1335 lines
64 KiB
C#

using System.Data.Common;
using Microsoft.Data.Sqlite;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using NSubstitute;
using ZB.MOM.WW.Audit;
using ZB.MOM.WW.ScadaBridge.AuditLog.Configuration;
using ZB.MOM.WW.ScadaBridge.Commons.Entities.InboundApi;
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
using ZB.MOM.WW.ScadaBridge.Commons.Messages.InboundApi;
using ZB.MOM.WW.ScadaBridge.Commons.Types;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
namespace ZB.MOM.WW.ScadaBridge.InboundAPI.Tests;
/// <summary>
/// Tests for script execution on central — timeout, handler dispatch, error handling.
/// Also covers safe error messages.
/// </summary>
public class InboundScriptExecutorTests
{
private readonly InboundScriptExecutor _executor;
private readonly RouteHelper _route;
/// <summary>Initializes a new instance of the <see cref="InboundScriptExecutorTests"/> class.</summary>
public InboundScriptExecutorTests()
{
_executor = new InboundScriptExecutor(NullLogger<InboundScriptExecutor>.Instance, Substitute.For<IServiceProvider>());
var locator = Substitute.For<IInstanceLocator>();
var router = Substitute.For<IInstanceRouter>();
_route = new RouteHelper(locator, router);
}
/// <summary>Verifies that the trace flag reaches the routed call request.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ExecuteAsync_TraceFlag_ReachesTheRoutedCallRequest()
{
// Flow Debugger (design 2026-09-05 §5.2): ExecuteAsync(trace: true) builds the script's
// Route helper WithTrace(true), so a Route.To(...).Call(...) inside the script sends a
// traced RouteToCallRequest; the default stays untraced.
var locator = Substitute.For<IInstanceLocator>();
var router = Substitute.For<IInstanceRouter>();
locator.GetSiteIdForInstanceAsync("inst", Arg.Any<CancellationToken>()).Returns("SiteA");
var captured = new List<RouteToCallRequest>();
router.RouteToCallAsync("SiteA", Arg.Do<RouteToCallRequest>(captured.Add), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(((RouteToCallRequest)ci[1]).CorrelationId, true, 1, null, DateTimeOffset.UtcNow));
var route = new RouteHelper(locator, router);
var method = new ApiMethod("routed", "x") { Id = 9, TimeoutSeconds = 10 };
_executor.RegisterHandler("routed", ctx => ctx.Route.To("inst").Call("work"));
var parent = Guid.NewGuid();
var traced = await _executor.ExecuteAsync(method, new Dictionary<string, object?>(), route,
TimeSpan.FromSeconds(10), parentExecutionId: parent, trace: true);
var plain = await _executor.ExecuteAsync(method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.True(traced.Success, traced.ErrorMessage);
Assert.True(plain.Success, plain.ErrorMessage);
Assert.Equal(2, captured.Count);
Assert.True(captured[0].Trace);
Assert.Equal(parent, captured[0].ParentExecutionId);
Assert.False(captured[1].Trace);
}
/// <summary>Verifies that a method with SkipBodyCapture set routes with body capture turned off.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Executor_MethodWithSkipBodyCapture_RoutesWithBodyCaptureOff()
{
// Arch-review F11: a method configured with PerTargetOverrides[method].SkipBodyCapture
// must build its Route helper WithBodyCapture(false), so the always-on RouteCall row
// carries no request/response summary — mirroring AuditWriteMiddleware's own
// SkipBodyCapture lookup for the inbound row (AuditWriteMiddleware.cs:183-187).
var locator = Substitute.For<IInstanceLocator>();
var router = Substitute.For<IInstanceRouter>();
locator.GetSiteIdForInstanceAsync("inst", Arg.Any<CancellationToken>()).Returns("SiteA");
router.RouteToCallAsync("SiteA", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(((RouteToCallRequest)ci[1]).CorrelationId, true, 1, null, DateTimeOffset.UtcNow));
var writer = Substitute.For<ICentralAuditWriter>();
AuditEvent? written = null;
writer.WriteAsync(Arg.Do<AuditEvent>(e => written = e), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var route = new RouteHelper(locator, router, writer, null);
var services = new ServiceCollection();
services.Configure<AuditLogOptions>(o =>
o.PerTargetOverrides["routed"] = new PerTargetRedactionOverride { SkipBodyCapture = true });
using var provider = services.BuildServiceProvider();
var executor = new InboundScriptExecutor(NullLogger<InboundScriptExecutor>.Instance, provider);
var method = new ApiMethod("routed", "x") { Id = 9, TimeoutSeconds = 10 };
executor.RegisterHandler("routed", ctx => ctx.Route.To("inst").Call("work", new { x = 1 }));
var result = await executor.ExecuteAsync(method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.NotNull(written);
var row = written!.AsRow();
Assert.Null(row.RequestSummary);
Assert.Null(row.ResponseSummary);
}
/// <summary>Verifies that a method without SkipBodyCapture routes with body capture turned on.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Executor_MethodWithoutSkipBodyCapture_RoutesWithBodyCaptureOn()
{
// Control: no PerTargetOverrides entry for this method → default behaviour unchanged.
var locator = Substitute.For<IInstanceLocator>();
var router = Substitute.For<IInstanceRouter>();
locator.GetSiteIdForInstanceAsync("inst", Arg.Any<CancellationToken>()).Returns("SiteA");
router.RouteToCallAsync("SiteA", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(((RouteToCallRequest)ci[1]).CorrelationId, true, 1, null, DateTimeOffset.UtcNow));
var writer = Substitute.For<ICentralAuditWriter>();
AuditEvent? written = null;
writer.WriteAsync(Arg.Do<AuditEvent>(e => written = e), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var route = new RouteHelper(locator, router, writer, null);
var services = new ServiceCollection();
services.Configure<AuditLogOptions>(o =>
o.PerTargetOverrides["other-method"] = new PerTargetRedactionOverride { SkipBodyCapture = true });
using var provider = services.BuildServiceProvider();
var executor = new InboundScriptExecutor(NullLogger<InboundScriptExecutor>.Instance, provider);
var method = new ApiMethod("routed", "x") { Id = 9, TimeoutSeconds = 10 };
executor.RegisterHandler("routed", ctx => ctx.Route.To("inst").Call("work", new { x = 1 }));
var result = await executor.ExecuteAsync(method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.NotNull(written);
var row = written!.AsRow();
Assert.Contains("\"x\":1", row.RequestSummary);
Assert.Equal("1", row.ResponseSummary);
}
/// <summary>Verifies that a registered handler executes successfully.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task RegisteredHandler_ExecutesSuccessfully()
{
var method = new ApiMethod("test", "return 42;") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("test", async ctx =>
{
await Task.CompletedTask;
return new { result = 42 };
});
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.True(result.Success);
Assert.NotNull(result.ResultJson);
Assert.Contains("42", result.ResultJson);
}
/// <summary>Verifies that an unregistered handler with an invalid script returns a compilation failure.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task UnregisteredHandler_InvalidScript_ReturnsCompilationFailure()
{
// Use an invalid script that cannot be compiled by Roslyn
var method = new ApiMethod("unknown", "%%% invalid C# %%%") { Id = 1, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Contains("Script compilation failed", result.ErrorMessage);
}
/// <summary>Verifies that an unregistered handler with a valid script is compiled lazily.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task UnregisteredHandler_ValidScript_LazyCompiles()
{
// Valid script that is not pre-registered triggers lazy compilation
var method = new ApiMethod("lazy", "return 1;") { Id = 1, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.True(result.Success);
}
/// <summary>Verifies that a throwing handler returns a safe error message.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task HandlerThrows_ReturnsSafeErrorMessage()
{
var method = new ApiMethod("failing", "throw new Exception();") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("failing", _ => throw new InvalidOperationException("internal detail leak"));
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.False(result.Success);
// Safe error message — should NOT contain "internal detail leak"
Assert.Equal("Internal script error", result.ErrorMessage);
}
/// <summary>Verifies that the error detail carries the exception while the message stays safe.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task HandlerThrows_ErrorDetailCarriesTheException_WhileTheMessageStaysSafe()
{
// Flow Debugger step logs (design 2026-09-09 D3): the generic SCRIPT_ERROR catch keeps
// the caller-facing message sanitised, but the exception itself must survive on the
// additive ErrorDetail so the endpoint can put it on the inbound audit row (and the
// Flow Debugger's inbound node can show why the run failed).
var method = new ApiMethod("failing-detail", "throw new InvalidOperationException(\"real reason\");")
{ Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("failing-detail", _ => throw new InvalidOperationException("real reason"));
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Equal("Internal script error", result.ErrorMessage);
Assert.Equal("SCRIPT_ERROR", result.ErrorCode);
Assert.NotNull(result.ErrorDetail);
Assert.Contains("InvalidOperationException", result.ErrorDetail);
Assert.Contains("real reason", result.ErrorDetail);
// The caller-safe fields must never carry it.
Assert.DoesNotContain("real reason", result.ErrorMessage!);
}
/// <summary>Verifies that a handler that times out carries no error detail.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task HandlerTimesOut_CarriesNoErrorDetail()
{
// A timeout is fully described by its message + TIMEOUT code — the
// OperationCanceledException adds nothing, so the row stays detail-less.
var method = new ApiMethod("slow-detail", "Thread.Sleep(60000);") { Id = 1, TimeoutSeconds = 1 };
_executor.RegisterHandler("slow-detail", async ctx =>
{
await Task.Delay(TimeSpan.FromSeconds(60), ctx.CancellationToken);
return "never";
});
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromMilliseconds(100));
Assert.False(result.Success);
Assert.Equal("TIMEOUT", result.ErrorCode);
Assert.Null(result.ErrorDetail);
}
/// <summary>Verifies that a timed-out routed ask returns a 500 with the site-unreachable code.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task RoutedAskTimeout_Returns500WithSiteUnreachableCode()
{
// N3: unreachability is the Ask EXPIRING (site never answered) — typed as
// AskTimeoutException by the communication layer — not a substring in a
// failure message. Pre-fix this fell into the generic catch as SCRIPT_ERROR.
var locator = Substitute.For<IInstanceLocator>();
locator.GetSiteIdForInstanceAsync("X", Arg.Any<CancellationToken>()).Returns("SiteA");
var router = Substitute.For<IInstanceRouter>();
router.RouteToCallAsync("SiteA", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(Task.FromException<RouteToCallResponse>(
new Akka.Actor.AskTimeoutException("Timeout after 00:00:30")));
var route = new RouteHelper(locator, router);
var method = new ApiMethod("routed", "return await Route.To(\"X\").Call(\"s\");")
{ Id = 7, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Equal("SITE_UNREACHABLE", result.ErrorCode);
}
/// <summary>Verifies that a site failure whose message mentions unreachable is reported as a script error rather than site unreachable.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task SiteRespondedFailure_MessageMentioningUnreachable_IsScriptErrorNotSiteUnreachable()
{
// N3 anti-sniff: a site that RESPONDED with Success=false is reachable by
// definition — even when its error text happens to contain "unreachable".
// Pre-fix the substring sniff misclassified this as SITE_UNREACHABLE.
var locator = Substitute.For<IInstanceLocator>();
locator.GetSiteIdForInstanceAsync("X", Arg.Any<CancellationToken>()).Returns("SiteA");
var router = Substitute.For<IInstanceRouter>();
router.RouteToCallAsync("SiteA", Arg.Any<RouteToCallRequest>(), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(
((RouteToCallRequest)ci[1]).CorrelationId,
Success: false, ReturnValue: null,
ErrorMessage: "PLC device unreachable behind the site gateway",
DateTimeOffset.UtcNow));
var route = new RouteHelper(locator, router);
var method = new ApiMethod("routed2", "return await Route.To(\"X\").Call(\"s\");")
{ Id = 8, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Equal("SCRIPT_ERROR", result.ErrorCode);
}
/// <summary>Verifies that a handler that times out returns a timeout error.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task HandlerTimesOut_ReturnsTimeoutError()
{
var method = new ApiMethod("slow", "Thread.Sleep(60000);") { Id = 1, TimeoutSeconds = 1 };
_executor.RegisterHandler("slow", async ctx =>
{
await Task.Delay(TimeSpan.FromSeconds(60), ctx.CancellationToken);
return "never";
});
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromMilliseconds(100));
Assert.False(result.Success);
Assert.Contains("timed out", result.ErrorMessage);
}
/// <summary>Verifies that a handler can access the request parameters.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task HandlerAccessesParameters()
{
var method = new ApiMethod("echo", "return params;") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("echo", async ctx =>
{
await Task.CompletedTask;
return ctx.Parameters["name"];
});
var parameters = new Dictionary<string, object?> { { "name", "ScadaBridge" } };
var result = await _executor.ExecuteAsync(
method, parameters, _route, TimeSpan.FromSeconds(10));
Assert.True(result.Success);
Assert.Contains("ScadaBridge", result.ResultJson!);
}
// --- Concurrent lazy-compile must not corrupt the handler cache ---
/// <summary>Verifies that concurrent lazy compilation of the same method does not corrupt the handler cache.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ConcurrentLazyCompile_SameMethod_DoesNotCorruptCache()
{
// Many concurrent first-callers of an uncompiled method race the lazy-compile
// path. With an unsynchronized Dictionary this can throw or return a torn/null
// handler; all calls must succeed and produce the same result.
var method = new ApiMethod("concurrent", "return 7;") { Id = 1, TimeoutSeconds = 10 };
var tasks = Enumerable.Range(0, 64).Select(_ => Task.Run(() =>
_executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10)))).ToArray();
var results = await Task.WhenAll(tasks);
Assert.All(results, r =>
{
Assert.True(r.Success, r.ErrorMessage);
Assert.Equal("7", r.ResultJson);
});
}
/// <summary>Verifies that concurrent registration and execution do not throw.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ConcurrentRegisterAndExecute_DoesNotThrow()
{
// RegisterHandler/RemoveHandler racing ExecuteAsync must not crash the process
// with an InvalidOperationException from concurrent Dictionary mutation.
var method = new ApiMethod("racy", "return 1;") { Id = 1, TimeoutSeconds = 10 };
var writers = Enumerable.Range(0, 32).Select(i => Task.Run(() =>
{
for (var n = 0; n < 50; n++)
{
_executor.RegisterHandler("racy", async ctx => { await Task.CompletedTask; return i; });
_executor.RemoveHandler("racy");
}
}));
var readers = Enumerable.Range(0, 32).Select(_ => Task.Run(async () =>
{
for (var n = 0; n < 50; n++)
{
await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
}
}));
// Should complete without an unhandled concurrency exception.
await Task.WhenAll(writers.Concat(readers));
}
// --- Compiled scripts must not bypass the script trust model ---
/// <summary>Verifies that compiling and registering a script that uses a forbidden API rejects the script.</summary>
/// <param name="script">The script source that uses a forbidden API.</param>
[Theory]
[InlineData("System.IO.File.Delete(\"/tmp/x\"); return null;")]
[InlineData("System.Diagnostics.Process.Start(\"/bin/sh\"); return null;")]
[InlineData("var t = System.Reflection.Assembly.GetExecutingAssembly(); return null;")]
[InlineData("new System.Threading.Thread(() => {}).Start(); return null;")]
[InlineData("var s = new System.Net.Sockets.Socket(System.Net.Sockets.AddressFamily.InterNetwork, System.Net.Sockets.SocketType.Stream, System.Net.Sockets.ProtocolType.Tcp); return null;")]
public void CompileAndRegister_ForbiddenApi_RejectsScript(string script)
{
var method = new ApiMethod("forbidden", script) { Id = 1, TimeoutSeconds = 10 };
var registered = _executor.CompileAndRegister(method);
Assert.False(registered);
}
/// <summary>Verifies that executing a script that uses a forbidden API does not run it and returns a failure.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ExecuteAsync_ForbiddenApiScript_DoesNotRunAndReturnsFailure()
{
// A fully-qualified forbidden API call must be rejected at compile/register time
// so the script never executes.
var marker = System.IO.Path.Combine(
System.IO.Path.GetTempPath(), $"scadabridge-pwned-{Guid.NewGuid():N}");
System.IO.File.Delete(marker);
var method = new ApiMethod("evil", $"System.IO.File.WriteAllText(@\"{marker}\", \"x\"); return 1;")
{
Id = 1,
TimeoutSeconds = 10
};
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.False(System.IO.File.Exists(marker));
}
/// <summary>Verifies that a permitted script still registers.</summary>
[Fact]
public void CompileAndRegister_PermittedScript_StillRegisters()
{
// The trust-model check must not reject legitimate scripts.
var method = new ApiMethod("ok", "var list = new List<int> { 1, 2, 3 }; return list.Sum();")
{
Id = 1,
TimeoutSeconds = 10
};
Assert.True(_executor.CompileAndRegister(method));
}
// --- Compile-diagnostics overload: surface errors so a non-compiling save is not a silent no-op ---
/// <summary>Verifies that a script that does not compile reports errors.</summary>
[Fact]
public void CompileAndRegister_NonCompilingScript_ReportsErrors()
{
// A genuine Roslyn error (undefined symbol) must be reported via the out-param,
// not just swallowed to a bare false. The Management Create/Update path turns
// these into the caller-visible compileWarning.
var method = new ApiMethod("broken", "return doesNotExist;") { Id = 1, TimeoutSeconds = 10 };
var ok = _executor.CompileAndRegister(method, out var errors);
Assert.False(ok);
Assert.NotEmpty(errors);
}
/// <summary>Verifies that a valid script reports no errors.</summary>
[Fact]
public void CompileAndRegister_ValidScript_ReportsNoErrors()
{
var method = new ApiMethod("fine", "return 1;") { Id = 1, TimeoutSeconds = 10 };
var ok = _executor.CompileAndRegister(method, out var errors);
Assert.True(ok);
Assert.Empty(errors);
}
/// <summary>Verifies that concurrent first callers of a new method share a single compile.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ExecuteAsync_ConcurrentFirstCallers_ShareOneCompile()
{
// Review 2026-10-21 05/M1: N concurrent first-callers used to each run Roslyn (N
// non-collectible loaded assemblies for one revision). Single-flight per name+revision.
var logger = new CompileCountingLogger();
var executor = new InboundScriptExecutor(logger, Substitute.For<IServiceProvider>());
var method = new ApiMethod("burst", "var x = 0; for (int i = 0; i < 10; i++) x += i; return x;") { Id = 1, TimeoutSeconds = 30 };
var results = await Task.WhenAll(Enumerable.Range(0, 12).Select(_ => Task.Run(() =>
executor.ExecuteAsync(method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(30)))));
Assert.All(results, r => Assert.True(r.Success, r.ErrorMessage));
Assert.Equal(1, logger.CompileCount);
}
private sealed class CompileCountingLogger : ILogger<InboundScriptExecutor>
{
private int _count;
public int CompileCount => _count;
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)
{
if (formatter(state, exception).EndsWith("script compiled", StringComparison.Ordinal))
Interlocked.Increment(ref _count);
}
}
/// <summary>Verifies that executing after a non-compiling update surfaces the compile failure.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task CompileAndRegister_NonCompilingUpdate_ExecuteSurfacesCompileFailure()
{
// Arch-review S1 (DB-authoritative): CompileAndRegister still leaves the old
// handler cached on a broken save (it never overwrites with a bad compile), but
// ExecuteAsync now revision-checks the cached script against the freshly-fetched
// row. A request carrying the broken row no longer silently serves the stale good
// delegate — the mismatch triggers a recompile, which fails, so the method returns
// a compilation error consistently on every node (honest failure over node-divergent
// stale success).
var good = new ApiMethod("evolving", "return 111;") { Id = 1, TimeoutSeconds = 10 };
Assert.True(_executor.CompileAndRegister(good, out var goodErrors));
Assert.Empty(goodErrors);
var broken = new ApiMethod("evolving", "this is not valid C#") { Id = 1, TimeoutSeconds = 10 };
Assert.False(_executor.CompileAndRegister(broken, out var brokenErrors));
Assert.NotEmpty(brokenErrors);
// The DB row is authoritative: the broken script now 500s rather than the old
// delegate silently serving.
var result = await _executor.ExecuteAsync(
broken, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Contains("Script compilation failed", result.ErrorMessage);
// The still-valid row keeps serving — only the broken revision fails.
var stillGood = await _executor.ExecuteAsync(
good, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.True(stillGood.Success);
Assert.Contains("111", stillGood.ResultJson);
}
// --- Lazy compile-and-fetch must be atomic, never KeyNotFoundException ---
/// <summary>Verifies that a lazy compile racing a handler removal never throws a <see cref="KeyNotFoundException"/>.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task LazyCompile_RacingRemoveHandler_NeverThrowsKeyNotFound()
{
// The lazy-compile path must compile-and-fetch atomically: a concurrent
// RemoveHandler must not be able to turn a first-call into an "Internal
// script error" (the old check-then-act re-read could throw KeyNotFoundException).
var method = new ApiMethod("atomic", "return 5;") { Id = 1, TimeoutSeconds = 10 };
var removers = Enumerable.Range(0, 16).Select(_ => Task.Run(() =>
{
for (var n = 0; n < 200; n++)
_executor.RemoveHandler("atomic");
}));
var callers = Enumerable.Range(0, 16).Select(_ => Task.Run(async () =>
{
for (var n = 0; n < 50; n++)
{
var r = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
// Result must always be a clean success or a clean compilation
// failure — never the catch-all "Internal script error".
Assert.NotEqual("Internal script error", r.ErrorMessage);
}
}));
await Task.WhenAll(removers.Concat(callers));
}
// --- A client disconnect must NOT be reported as a script timeout ---
/// <summary>Verifies that a client disconnect is not reported as a timeout.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ClientDisconnect_IsNotReportedAsTimeout()
{
// When the caller's request token is cancelled (client aborted the request),
// ExecuteAsync must report a client-cancelled failure, not "Script execution
// timed out" — that log line is reserved for genuine timeouts.
var method = new ApiMethod("aborted", "return 1;") { Id = 1, TimeoutSeconds = 30 };
_executor.RegisterHandler("aborted", async ctx =>
{
await Task.Delay(TimeSpan.FromSeconds(60), ctx.CancellationToken);
return "never";
});
using var clientAborted = new CancellationTokenSource();
clientAborted.CancelAfter(TimeSpan.FromMilliseconds(100));
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
// Generous method timeout so the timeout CTS is NOT the cause.
TimeSpan.FromSeconds(30),
clientAborted.Token);
Assert.False(result.Success);
Assert.DoesNotContain("timed out", result.ErrorMessage ?? string.Empty);
}
/// <summary>Verifies that a genuine timeout is still reported as a timeout.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task GenuineTimeout_StillReportedAsTimeout()
{
// A method that exceeds its timeout with no client abort must still be
// reported as "timed out" (regression guard for the client-disconnect fix).
var method = new ApiMethod("genuine", "return 1;") { Id = 1, TimeoutSeconds = 1 };
_executor.RegisterHandler("genuine", async ctx =>
{
await Task.Delay(TimeSpan.FromSeconds(60), ctx.CancellationToken);
return "never";
});
var result = await _executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromMilliseconds(100),
CancellationToken.None);
Assert.False(result.Success);
Assert.Contains("timed out", result.ErrorMessage);
}
// --- A script that fails to compile must be compiled at most
// once — repeated calls must not re-run the expensive Roslyn compilation. ---
/// <summary>Verifies that a failed compilation is not retried on every request.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task FailedCompilation_IsNotRetriedOnEveryRequest()
{
// A broken script compiled once must be remembered as bad: subsequent
// ExecuteAsync calls must NOT recompile (CPU amplification vector — there is
// no rate limiting on the inbound API). Compilation is observed via the
// "compilation failed" log line, which must appear exactly once.
var counter = new CompileLogCounter();
var executor = new InboundScriptExecutor(
new CountingLogger<InboundScriptExecutor>(counter),
Substitute.For<IServiceProvider>());
var method = new ApiMethod("broken", "%%% invalid C# %%%") { Id = 1, TimeoutSeconds = 10 };
for (var i = 0; i < 5; i++)
{
var result = await executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
}
Assert.Equal(1, counter.CompilationFailures);
}
/// <summary>Verifies that a failed compilation is recompiled after compile-and-register is called again.</summary>
[Fact]
public void FailedCompilation_RecompilesAfterCompileAndRegisterCalledAgain()
{
// The failure cache must not be permanent: when the method definition is
// updated via CompileAndRegister, a now-valid script must register.
var bad = new ApiMethod("fixable", "%%% invalid %%%") { Id = 1, TimeoutSeconds = 10 };
Assert.False(_executor.CompileAndRegister(bad));
var good = new ApiMethod("fixable", "return 1;") { Id = 1, TimeoutSeconds = 10 };
Assert.True(_executor.CompileAndRegister(good));
}
/// <summary>
/// ScadaBridge#75: a failure on the data-plane (lazy-compile) path is observable per method
/// with its real diagnostic while the caller only gets the generic message; the state is
/// judged against the current script text and clears on a successful compile.
/// </summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task CompileState_ReportsTheLazyCompileFailureWithItsDiagnostic()
{
var method = new ApiMethod("diag", "return doesNotExist;") { Id = 1, TimeoutSeconds = 10 };
Assert.Equal(new ApiMethodCompileState(false, false, null), _executor.GetCompileState("diag", method.Script));
var result = await _executor.ExecuteAsync(method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.Equal("Script compilation failed for this method", result.ErrorMessage);
var state = _executor.GetCompileState("diag", method.Script);
Assert.True(state.IsKnownBad);
Assert.Contains("doesNotExist", state.LastCompileError);
// A different script text is a different revision: the record no longer describes it.
Assert.False(_executor.GetCompileState("diag", "return 1;").IsKnownBad);
Assert.True(_executor.CompileAndRegister(new ApiMethod("diag", "return 1;") { Id = 1, TimeoutSeconds = 10 }));
Assert.Equal(new ApiMethodCompileState(true, false, null), _executor.GetCompileState("diag", "return 1;"));
}
// --- _knownBadMethods must be bounded so a spam attack of
// unique method names cannot grow the cache without bound. ---
/// <summary>Verifies that the known-bad-methods cache never exceeds its cap under a flood of unique method names.</summary>
[Fact]
public void KnownBadMethodsCache_SizeNeverExceedsCap_UnderUniqueNameFlood()
{
// Flood the executor with bad-method names well past the cache cap. The
// cache must stabilise at or below the cap — any further unique bad name
// is dropped rather than added (the per-request DB lookup remains the
// correctness path; this cache is only a fast-fail optimisation).
const int cap = 1000;
const int floodCount = cap + 500;
for (var i = 0; i < floodCount; i++)
{
var bad = new ApiMethod($"bad-{i}", "%%% invalid %%%") { Id = i + 1, TimeoutSeconds = 10 };
Assert.False(_executor.CompileAndRegister(bad));
}
Assert.True(
_executor.KnownBadMethodCount <= cap,
$"known-bad cache size {_executor.KnownBadMethodCount} must not exceed cap {cap}");
}
/// <summary>Verifies that the lazy-compile path also keeps the known-bad-methods cache capped under a flood of unique method names.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task KnownBadMethodsCache_LazyCompilePath_AlsoCappedUnderUniqueNameFlood()
{
// The lazy-compile path (ExecuteAsync on an unregistered method) records
// failures via the same capped helper as CompileAndRegister, so flooding
// it with unique URLs must not grow the cache without bound.
const int cap = 1000;
const int floodCount = cap + 250;
for (var i = 0; i < floodCount; i++)
{
var method = new ApiMethod($"lazy-bad-{i}", "%%% invalid %%%") { Id = i + 1, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
}
Assert.True(
_executor.KnownBadMethodCount <= cap,
$"known-bad cache size {_executor.KnownBadMethodCount} must not exceed cap {cap}");
}
// --- The script return value is validated against ReturnDefinition ---
/// <summary>Verifies that a return value matching the return definition succeeds.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ReturnValue_MatchingReturnDefinition_Succeeds()
{
var method = new ApiMethod("shaped", "return x;")
{
Id = 1,
TimeoutSeconds = 10,
ReturnDefinition = """[{"name":"siteName","type":"String"},{"name":"total","type":"Integer"}]""",
};
_executor.RegisterHandler("shaped", async ctx =>
{
await Task.CompletedTask;
return new { siteName = "Site Alpha", total = 14250 };
});
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
}
/// <summary>Verifies that a return value not matching the return definition returns a failure instead of a malformed 200.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ReturnValue_NotMatchingReturnDefinition_ReturnsFailureNotMalformed200()
{
// The script returns a structure inconsistent with the declared return
// definition (missing 'total'). It must surface as a failure, not a 200.
var method = new ApiMethod("misshaped", "return x;")
{
Id = 1,
TimeoutSeconds = 10,
ReturnDefinition = """[{"name":"siteName","type":"String"},{"name":"total","type":"Integer"}]""",
};
_executor.RegisterHandler("misshaped", async ctx =>
{
await Task.CompletedTask;
return new { siteName = "Site Alpha" }; // 'total' missing
});
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.False(result.Success);
Assert.Null(result.ResultJson);
}
/// <summary>Verifies that a method with no return definition leaves the return value unconstrained.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ReturnValue_NoReturnDefinition_IsUnconstrained()
{
// A method with no ReturnDefinition keeps the prior behaviour — the return
// value is serialized as-is.
var method = new ApiMethod("free", "return x;") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("free", async ctx =>
{
await Task.CompletedTask;
return new { whatever = 1 };
});
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.Contains("whatever", result.ResultJson!);
}
// --- ParentExecutionId: the inbound request's
// ExecutionId is threaded through ExecuteAsync onto routed calls ---
/// <summary>Verifies that executing with a parent execution id makes the routed call carry it as its parent execution id.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ExecuteAsync_WithParentExecutionId_RoutedCallCarriesItAsParentExecutionId()
{
// The endpoint hands ExecuteAsync the inbound request's ExecutionId; a
// routed Route.To(...).Call(...) inside the script must stamp that id onto
// the RouteToCallRequest as ParentExecutionId.
var inboundExecutionId = Guid.NewGuid();
var locator = Substitute.For<IInstanceLocator>();
locator.GetSiteIdForInstanceAsync("inst-1", Arg.Any<CancellationToken>()).Returns("SiteA");
var router = Substitute.For<IInstanceRouter>();
RouteToCallRequest? captured = null;
router.RouteToCallAsync("SiteA", Arg.Do<RouteToCallRequest>(r => captured = r), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(
((RouteToCallRequest)ci[1]).CorrelationId, true, null, null, DateTimeOffset.UtcNow));
var route = new RouteHelper(locator, router);
var method = new ApiMethod("routes", "return 1;") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("routes", async ctx =>
{
await ctx.Route.To("inst-1").Call("doWork");
return 1;
});
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10),
parentExecutionId: inboundExecutionId);
Assert.True(result.Success, result.ErrorMessage);
Assert.NotNull(captured);
Assert.Equal(inboundExecutionId, captured!.ParentExecutionId);
}
/// <summary>Verifies that executing without a parent execution id gives the routed call a null parent execution id.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ExecuteAsync_WithoutParentExecutionId_RoutedCallHasNullParentExecutionId()
{
// ExecuteAsync called without a parent execution id (the default) routes
// calls with ParentExecutionId null.
var locator = Substitute.For<IInstanceLocator>();
locator.GetSiteIdForInstanceAsync("inst-1", Arg.Any<CancellationToken>()).Returns("SiteA");
var router = Substitute.For<IInstanceRouter>();
RouteToCallRequest? captured = null;
router.RouteToCallAsync("SiteA", Arg.Do<RouteToCallRequest>(r => captured = r), Arg.Any<CancellationToken>())
.Returns(ci => new RouteToCallResponse(
((RouteToCallRequest)ci[1]).CorrelationId, true, null, null, DateTimeOffset.UtcNow));
var route = new RouteHelper(locator, router);
var method = new ApiMethod("routes2", "return 1;") { Id = 1, TimeoutSeconds = 10 };
_executor.RegisterHandler("routes2", async ctx =>
{
await ctx.Route.To("inst-1").Call("doWork");
return 1;
});
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.NotNull(captured);
Assert.Null(captured!.ParentExecutionId);
}
// --- IpsenMES MoveIn: the read-only Database helper is exposed on the script
// context and resolves IDatabaseGateway from a DI scope per execution. ---
/// <summary>Verifies that a script that uses Database queries through the gateway.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Script_UsingDatabase_QueriesViaGateway()
{
// A script that calls Database.QuerySingleAsync runs against an executor whose
// ServiceProvider registers an IDatabaseGateway backed by in-memory SQLite.
var services = new ServiceCollection();
services.AddSingleton<IDatabaseGateway>(SeededSqliteGateway());
using var provider = services.BuildServiceProvider();
// Regression guard for the old flake: force the collection the full suite used to hit during
// the script compile, then the pool reclaim that followed it. An unrooted keep-alive dies here
// deterministically ("Internal script error"); ClearAllPools only closes IDLE connections.
GC.Collect();
GC.WaitForPendingFinalizers();
GC.Collect();
SqliteConnection.ClearAllPools();
var executor = new InboundScriptExecutor(
NullLogger<InboundScriptExecutor>.Instance, provider);
var method = new ApiMethod(
"movein",
"return new { v = await Database.QuerySingleAsync<string>(\"BTDB\", \"SELECT Code FROM Machine WHERE SAPID=@s\", new { s = (string)Parameters[\"sap\"] }) };")
{
Id = 1,
TimeoutSeconds = 10,
// null ReturnDefinition → ReturnValueValidator is unconstrained.
ReturnDefinition = null,
};
var result = await executor.ExecuteAsync(
method,
new Dictionary<string, object?> { { "sap", "131453" } },
_route,
TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.Contains("Z28061A", result.ResultJson!);
}
/// <summary>Verifies that a script that does not use Database runs with a service provider that lacks the gateway.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Script_NotUsingDatabase_RunsWithProviderLackingGateway()
{
// A script that never touches Database must run even when no IDatabaseGateway
// is registered — the helper is built via GetService (nullable) and only
// throws on first use, which this script never reaches.
var executor = new InboundScriptExecutor(
NullLogger<InboundScriptExecutor>.Instance, Substitute.For<IServiceProvider>());
var method = new ApiMethod("no-db", "return 99;") { Id = 1, TimeoutSeconds = 10 };
var result = await executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
Assert.True(result.Success, result.ErrorMessage);
Assert.Contains("99", result.ResultJson!);
}
/// <summary>Verifies that a throwing script still disposes its DI scope.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task ScriptThrows_DisposesDiScope()
{
// When the script handler throws, ExecuteAsync must still dispose the
// per-execution DI scope it created (regression guard for the finally block).
var scopeServiceProvider = Substitute.For<IServiceProvider>();
// GetService<IDatabaseGateway>() returns null — script never needs it.
scopeServiceProvider.GetService(typeof(IDatabaseGateway)).Returns((object?)null);
var scope = Substitute.For<IServiceScope>();
scope.ServiceProvider.Returns(scopeServiceProvider);
var factory = Substitute.For<IServiceScopeFactory>();
factory.CreateScope().Returns(scope);
// Wire the factory into the provider so CreateScope() extension finds it.
var provider = Substitute.For<IServiceProvider>();
provider.GetService(typeof(IServiceScopeFactory)).Returns(factory);
var executor = new InboundScriptExecutor(
NullLogger<InboundScriptExecutor>.Instance, provider);
// A pre-registered handler that throws; ReturnDefinition=null so validation
// is not the failure path.
var method = new ApiMethod("throws", "throw new Exception(\"boom\");")
{
Id = 1,
TimeoutSeconds = 10,
ReturnDefinition = null,
};
executor.RegisterHandler("throws", _ => throw new Exception("boom"));
var result = await executor.ExecuteAsync(
method,
new Dictionary<string, object?>(),
_route,
TimeSpan.FromSeconds(10));
// The executor must swallow the script exception and return a non-success result.
Assert.False(result.Success);
// The scope must have been disposed via the finally block.
scope.Received(1).Dispose();
}
// SQLite-backed IDatabaseGateway fake (mirrors InboundDatabaseHelperTests). The
// shared in-memory db is seeded with Machine(Code,SAPID)=('Z28061A','131453').
private sealed class SqliteGateway : IDatabaseGateway
{
private readonly string _cs;
/// <summary>Initializes a new instance of the <see cref="SqliteGateway"/> class.</summary>
/// <param name="cs">The SQLite connection string.</param>
public SqliteGateway(string cs) => _cs = cs;
/// <inheritdoc />
public async Task<DbConnection> GetConnectionAsync(string name, CancellationToken ct = default)
{ var c = new SqliteConnection(_cs); await c.OpenAsync(ct); return c; }
/// <inheritdoc />
public Task<ExternalCallResult> CachedWriteAsync(string c, string s,
IReadOnlyDictionary<string, object?>? p = null, string? o = null, CancellationToken ct = default,
TrackedOperationId? t = null, Guid? e = null, string? src = null, Guid? pe = null)
=> throw new NotImplementedException();
}
/// <summary>
/// Keep-alive for the shared in-memory database, rooted in a static field. It used to be a
/// local in the seeding helper: once the helper returned nothing referenced it, so after a GC
/// (likely during the script compile under a full-suite run) Microsoft.Data.Sqlite's pool
/// reclaimed the leaked connection, closed the last connection and destroyed the database. The
/// query then failed with <c>no such table: Machine</c>, which the script reported as "Internal
/// script error" (4 runs in 30, captured 2026-11-10).
/// </summary>
private static readonly SqliteConnection KeepAlive = OpenKeepAlive();
private static SqliteConnection OpenKeepAlive()
{
var keep = new SqliteConnection("DataSource=file:movein-exec?mode=memory&cache=shared");
keep.Open(); // lives until process exit
return keep;
}
private static SqliteGateway SeededSqliteGateway()
{
using var cmd = KeepAlive.CreateCommand();
cmd.CommandText = "CREATE TABLE IF NOT EXISTS Machine(Code TEXT, SAPID TEXT); DELETE FROM Machine; INSERT INTO Machine VALUES('Z28061A','131453');";
cmd.ExecuteNonQuery();
return new SqliteGateway("DataSource=file:movein-exec?mode=memory&cache=shared");
}
/// <summary>Verifies that a timed-out script has its scope disposal deferred so no scope is orphaned.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task TimedOutScript_ScopeDisposalDeferred_NoOrphanLeak()
{
// Handler ignores the token and keeps running past the method timeout.
var release = new TaskCompletionSource();
_executor.RegisterHandler("slow", async _ => { await release.Task; return 1; });
var method = new ApiMethod("slow", "unused") { Id = 9, TimeoutSeconds = 1 };
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), _route, TimeSpan.FromMilliseconds(50));
Assert.False(result.Success);
Assert.Contains("timed out", result.ErrorMessage);
Assert.Equal(1, _executor.AbandonedExecutionCount); // orphan is COUNTED
release.SetResult(); // orphan finishes; continuation cleans up
await Task.Delay(200);
Assert.Equal(0, _executor.AbandonedExecutionCount); // ...and DECREMENTED
}
// --- Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the Log global ---
/// <summary>Verifies that a traced run emits one ScriptLog row on the trace sink.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Log_TracedRun_EmitsOneScriptLogRowOnTheTraceSink()
{
// D4/D5: a method script's Log.Info(...) binds as a top-level global and, because the
// execution is traced, produces exactly one ScriptTrace/ScriptLog row carrying the
// inbound request's own ExecutionId. stepEventId stays null on a central line — the
// graph builder attaches it to the execution's anchor step (design D2).
var sink = new List<AuditEvent>();
var route = NewRoute().WithTraceSink(sink.Add);
var method = new ApiMethod("logs", "Log.Info(\"central\"); return 1;") { Id = 7, TimeoutSeconds = 10 };
var executionId = Guid.NewGuid();
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10),
parentExecutionId: executionId, trace: true);
Assert.True(result.Success, result.ErrorMessage);
var row = Assert.Single(ScriptLogRows(sink));
var details = AuditDetailsCodec.Deserialize(row.DetailsJson);
Assert.Equal(nameof(AuditKind.ScriptLog), details.Kind);
Assert.Equal(nameof(AuditChannel.ScriptTrace), details.Channel);
Assert.Equal(executionId, details.ExecutionId);
Assert.Equal("logs", row.Target);
Assert.Equal("central", details.RequestSummary);
var extra = ScriptTraceExtra.TryParse(details.Extra);
Assert.NotNull(extra);
Assert.Equal("info", extra!.LogLevel);
Assert.Equal("script", extra.LogSource);
Assert.Null(extra.StepEventId);
}
/// <summary>Verifies that a traced run writes the ScriptLog row to the central audit store.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Log_TracedRun_WritesTheScriptLogRowToTheCentralAuditStore()
{
// D5: the row must be DURABLE, not just inline — Replay reads it back from the central
// audit store, so the write happens even when no Live trace sink is attached, and it
// carries the emitting node exactly as the RouteCall row does.
var writer = Substitute.For<ICentralAuditWriter>();
writer.WriteAsync(Arg.Any<AuditEvent>(), Arg.Any<CancellationToken>()).Returns(Task.CompletedTask);
var nodeIdentity = Substitute.For<INodeIdentityProvider>();
nodeIdentity.NodeName.Returns("central-a");
var services = new ServiceCollection();
services.AddSingleton(writer);
services.AddSingleton(nodeIdentity);
using var provider = services.BuildServiceProvider();
var executor = new InboundScriptExecutor(NullLogger<InboundScriptExecutor>.Instance, provider);
var method = new ApiMethod("persisted", "Log.Info(\"persist\"); return 1;") { Id = 7, TimeoutSeconds = 10 };
var result = await executor.ExecuteAsync(
method, new Dictionary<string, object?>(), NewRoute(), TimeSpan.FromSeconds(10),
parentExecutionId: Guid.NewGuid(), trace: true);
Assert.True(result.Success, result.ErrorMessage);
await writer.Received(1).WriteAsync(
Arg.Is<AuditEvent>(e =>
AuditDetailsCodec.Deserialize(e.DetailsJson).Kind == nameof(AuditKind.ScriptLog)
&& e.SourceNode == "central-a"),
Arg.Any<CancellationToken>());
}
/// <summary>Verifies that an untraced run writes only to the node logger.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Log_UntracedRun_WritesOnlyToTheNodeLogger()
{
// D5: untraced runs pay nothing — no trace-sink row, no central audit write — but the
// author's message still reaches the node's ILogger so it is never silently lost.
var sink = new List<AuditEvent>();
var route = NewRoute().WithTraceSink(sink.Add);
var writer = Substitute.For<ICentralAuditWriter>();
writer.WriteAsync(Arg.Any<AuditEvent>(), Arg.Any<CancellationToken>()).Returns(Task.CompletedTask);
var services = new ServiceCollection();
services.AddSingleton(writer);
using var provider = services.BuildServiceProvider();
var recorded = new List<string>();
var executor = new InboundScriptExecutor(new RecordingLogger<InboundScriptExecutor>(recorded), provider);
var method = new ApiMethod("quiet", "Log.Warn(\"unwatched\"); return 1;") { Id = 7, TimeoutSeconds = 10 };
var result = await executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10),
parentExecutionId: Guid.NewGuid());
Assert.True(result.Success, result.ErrorMessage);
Assert.Empty(ScriptLogRows(sink));
await writer.DidNotReceive().WriteAsync(Arg.Any<AuditEvent>(), Arg.Any<CancellationToken>());
Assert.Contains(recorded, m => m.Contains("unwatched", StringComparison.Ordinal));
}
/// <summary>Verifies that a traced log call with an exception carries both the message and the detail.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Log_TracedWithException_CarriesMessageAndDetail()
{
// §4: the attached exception rides errorMessage/errorDetail, exactly as the failure
// rows do, so the Log tab can render the type + stack.
var sink = new List<AuditEvent>();
var route = NewRoute().WithTraceSink(sink.Add);
var method = new ApiMethod(
"boom", "Log.Warn(\"x\", new InvalidOperationException(\"e\")); return 1;")
{ Id = 7, TimeoutSeconds = 10 };
var result = await _executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10),
parentExecutionId: Guid.NewGuid(), trace: true);
Assert.True(result.Success, result.ErrorMessage);
var details = AuditDetailsCodec.Deserialize(Assert.Single(ScriptLogRows(sink)).DetailsJson);
Assert.Equal("x", details.RequestSummary);
Assert.Equal("e", details.ErrorMessage);
Assert.StartsWith("System.InvalidOperationException", details.ErrorDetail);
Assert.Equal("warn", ScriptTraceExtra.TryParse(details.Extra)!.LogLevel);
}
/// <summary>Verifies that log lines past the per-run maximum are dropped and a single closing runtime warning is emitted.</summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task Log_PastMaxLogLinesPerRun_DropsAndEmitsOneClosingRuntimeWarning()
{
// D7: the per-run cap bounds the ROWS (the ILogger still sees every line); the run
// ends with one runtime-sourced warn row naming how many lines were dropped.
var sink = new List<AuditEvent>();
var route = NewRoute().WithTraceSink(sink.Add);
var services = new ServiceCollection();
services.Configure<InboundApiOptions>(o => o.MaxLogLinesPerRun = 2);
using var provider = services.BuildServiceProvider();
var executor = new InboundScriptExecutor(NullLogger<InboundScriptExecutor>.Instance, provider);
var method = new ApiMethod(
"chatty", "Log.Info(\"a\"); Log.Info(\"b\"); Log.Info(\"c\"); Log.Info(\"d\"); return 1;")
{ Id = 7, TimeoutSeconds = 10 };
var result = await executor.ExecuteAsync(
method, new Dictionary<string, object?>(), route, TimeSpan.FromSeconds(10),
parentExecutionId: Guid.NewGuid(), trace: true);
Assert.True(result.Success, result.ErrorMessage);
var rows = ScriptLogRows(sink)
.Select(e => AuditDetailsCodec.Deserialize(e.DetailsJson))
.Select(d => (Details: d, Extra: ScriptTraceExtra.TryParse(d.Extra)!))
.ToList();
Assert.Equal(3, rows.Count);
Assert.Equal(new[] { "a", "b" }, rows.Where(r => r.Extra.LogSource == "script").Select(r => r.Details.RequestSummary));
var closing = Assert.Single(rows, r => r.Extra.LogSource == "runtime");
Assert.Equal("warn", closing.Extra.LogLevel);
Assert.Contains("2", closing.Details.RequestSummary);
}
private RouteHelper NewRoute() =>
new(Substitute.For<IInstanceLocator>(), Substitute.For<IInstanceRouter>());
private static List<AuditEvent> ScriptLogRows(IEnumerable<AuditEvent> events) =>
events.Where(e => AuditDetailsCodec.Deserialize(e.DetailsJson).Kind == nameof(AuditKind.ScriptLog)).ToList();
// Minimal ILogger that keeps every formatted message so a test can prove the node
// logger saw a line even when nothing was audited.
private sealed class RecordingLogger<T>(List<string> messages) : ILogger<T>
{
/// <summary>Returns no scope; the fake logger does not track scopes.</summary>
/// <typeparam name="TState">The scope state type.</typeparam>
/// <param name="state">The scope state.</param>
/// <returns>Always null.</returns>
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
/// <summary>Reports every log level as enabled.</summary>
/// <param name="logLevel">The log level being queried.</param>
/// <returns>Always true.</returns>
public bool IsEnabled(LogLevel logLevel) => true;
/// <summary>Records the log entry for later assertions.</summary>
/// <typeparam name="TState">The log state type.</typeparam>
/// <param name="logLevel">The entry's log level.</param>
/// <param name="eventId">The entry's event id.</param>
/// <param name="state">The entry's state.</param>
/// <param name="exception">The entry's exception, if any.</param>
/// <param name="formatter">Formats the state and exception into the message.</param>
public void Log<TState>(
LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter)
{
lock (messages) messages.Add(formatter(state, exception));
}
}
private sealed class CompileLogCounter
{
public int CompilationFailures;
}
private sealed class CountingLogger<T>(CompileLogCounter counter) : ILogger<T>
{
/// <summary>Returns no scope; the fake does not track scopes.</summary>
/// <typeparam name="TState">The type of the scope state.</typeparam>
/// <param name="state">The scope state (ignored).</param>
/// <returns>Always null.</returns>
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
/// <summary>Reports every log level as enabled.</summary>
/// <param name="logLevel">The log level to check.</param>
/// <returns>Always true.</returns>
public bool IsEnabled(LogLevel logLevel) => true;
/// <summary>Counts entries whose message reports a script compilation failure.</summary>
/// <typeparam name="TState">The type of the log state.</typeparam>
/// <param name="logLevel">The severity of the entry.</param>
/// <param name="eventId">The event identifier.</param>
/// <param name="state">The state object to format.</param>
/// <param name="exception">The exception associated with the entry, if any.</param>
/// <param name="formatter">Formats the state and exception into the message.</param>
public void Log<TState>(
LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter)
{
var message = formatter(state, exception);
if (message.Contains("script compilation failed", StringComparison.OrdinalIgnoreCase))
Interlocked.Increment(ref counter.CompilationFailures);
}
}
}