feat(inbound-api): Log global for method scripts, central ScriptLog rows when traced (D4/D5)
This commit is contained in:
@@ -69,4 +69,17 @@ public class InboundApiOptions
|
||||
/// is still legitimately working and moves on to the next one. Default 60 s.
|
||||
/// </summary>
|
||||
public TimeSpan StandbyForwardTimeout { get; set; } = TimeSpan.FromSeconds(60);
|
||||
|
||||
/// <summary>Default value of <see cref="MaxLogLinesPerRun"/>, also used when no options instance is available.</summary>
|
||||
public const int DefaultMaxLogLinesPerRun = 200;
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D7): how many <c>Log.*</c> lines ONE traced
|
||||
/// method execution may turn into <c>ScriptTrace/ScriptLog</c> audit rows. Past the cap the
|
||||
/// lines are dropped from the trace — they still reach the node's <c>ILogger</c> — and the
|
||||
/// run ends with a single runtime-sourced warning row naming the dropped count, so a
|
||||
/// truncated trace is never silently short. Untraced executions emit no rows at all and are
|
||||
/// therefore unaffected by this value. Must be greater than zero.
|
||||
/// </summary>
|
||||
public int MaxLogLinesPerRun { get; set; } = DefaultMaxLogLinesPerRun;
|
||||
}
|
||||
|
||||
@@ -36,6 +36,10 @@ public sealed class InboundApiOptionsValidator : OptionsValidatorBase<InboundApi
|
||||
$"ScadaBridge:InboundApi:StandbyForwardTimeout must be a positive duration " +
|
||||
$"(was {options.StandbyForwardTimeout}); it bounds each standby→active relay attempt.");
|
||||
|
||||
builder.RequireThat(options.MaxLogLinesPerRun > 0,
|
||||
$"ScadaBridge:InboundApi:MaxLogLinesPerRun must be greater than zero " +
|
||||
$"(was {options.MaxLogLinesPerRun}); it caps the Log.* lines one traced method execution audits.");
|
||||
|
||||
foreach (var peer in options.StandbyForwardPeerEndpoints)
|
||||
{
|
||||
var ok = Uri.TryCreate(peer, UriKind.Absolute, out var uri)
|
||||
|
||||
@@ -4,7 +4,9 @@ using Microsoft.CodeAnalysis.CSharp.Scripting;
|
||||
using Microsoft.CodeAnalysis.Scripting;
|
||||
using Microsoft.Extensions.DependencyInjection;
|
||||
using Microsoft.Extensions.Logging;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Microsoft.Extensions.Options;
|
||||
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.Repositories;
|
||||
@@ -363,6 +365,9 @@ public class InboundScriptExecutor
|
||||
// client abort), disposing the scope underneath it would fault the still-running
|
||||
// task with ObjectDisposedException — so the finally defers disposal instead.
|
||||
Task<object?>? handlerTask = null;
|
||||
// Flow Debugger step logs (design 2026-09-09 D7): hoisted so the finally can flush the
|
||||
// "lines dropped" closing row on EVERY exit path — success, timeout, or a thrown script.
|
||||
InboundScriptLogger? scriptLogger = null;
|
||||
try
|
||||
{
|
||||
scope = _serviceProvider.CreateScope();
|
||||
@@ -392,10 +397,14 @@ public class InboundScriptExecutor
|
||||
// come from the same scope as the gateway (both null-tolerant: an unregistered
|
||||
// writer means no row, never a failed script), and the trace sink is the one the
|
||||
// caller attached to the RouteHelper so a Live run collects both row kinds.
|
||||
// Shared by the Database helper's outbound rows and the script's Log.* lines, so both
|
||||
// land in the same store and carry the same SourceNode.
|
||||
var auditWriter = scope?.ServiceProvider.GetService<ICentralAuditWriter>();
|
||||
var nodeIdentity = scope?.ServiceProvider.GetService<INodeIdentityProvider>();
|
||||
var dbHelper = new InboundDatabaseHelper(
|
||||
gateway, cts.Token, timeout,
|
||||
auditWriter: scope?.ServiceProvider.GetService<ICentralAuditWriter>(),
|
||||
nodeIdentity: scope?.ServiceProvider.GetService<INodeIdentityProvider>(),
|
||||
auditWriter: auditWriter,
|
||||
nodeIdentity: nodeIdentity,
|
||||
executionId: parentExecutionId,
|
||||
parentExecutionId: null,
|
||||
methodName: method.Name,
|
||||
@@ -424,6 +433,31 @@ public class InboundScriptExecutor
|
||||
&& auditOptions.PerTargetOverrides.TryGetValue(method.Name, out var perTargetOverride)
|
||||
&& perTargetOverride.SkipBodyCapture;
|
||||
|
||||
// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the script's Log global.
|
||||
// Lines ALWAYS reach this node's logger; only a TRACED execution also builds
|
||||
// ScriptTrace/ScriptLog rows, which are fanned out to the Live run's inline sink and
|
||||
// written best-effort to the central store for Replay — exactly as RouteHelper does
|
||||
// for its RouteCall row. The row cap comes from options when they are available
|
||||
// (the sandbox/test providers that register none fall back to the documented default).
|
||||
var maxLogLines = scope?.ServiceProvider
|
||||
.GetService<IOptionsMonitor<InboundApiOptions>>()?.CurrentValue.MaxLogLinesPerRun
|
||||
?? InboundApiOptions.DefaultMaxLogLinesPerRun;
|
||||
var logTraceSink = route.TraceSink;
|
||||
var methodName = method.Name;
|
||||
scriptLogger = new InboundScriptLogger(
|
||||
_logger,
|
||||
emit: trace
|
||||
? evt =>
|
||||
{
|
||||
logTraceSink?.Invoke(evt);
|
||||
WriteScriptLogBestEffort(auditWriter, evt, methodName);
|
||||
}
|
||||
: null,
|
||||
maxLines: maxLogLines,
|
||||
methodName: methodName,
|
||||
executionId: parentExecutionId,
|
||||
sourceNode: nodeIdentity?.NodeName);
|
||||
|
||||
var context = new InboundScriptContext(
|
||||
parameters,
|
||||
route.WithDeadline(cts.Token)
|
||||
@@ -432,7 +466,8 @@ public class InboundScriptExecutor
|
||||
.WithTrace(trace)
|
||||
.WithBodyCapture(!skipBodyCapture),
|
||||
dbHelper,
|
||||
cts.Token);
|
||||
cts.Token,
|
||||
scriptLogger);
|
||||
|
||||
_scriptHandlers.TryGetValue(method.Name, out var cached);
|
||||
// Revision check: a cached handler compiled from different script text is stale
|
||||
@@ -553,6 +588,17 @@ public class InboundScriptExecutor
|
||||
}
|
||||
finally
|
||||
{
|
||||
// The script body has finished (or been abandoned): close out its log lines before the
|
||||
// caller completes its trace collector. Idempotent and a no-op when nothing was dropped.
|
||||
try
|
||||
{
|
||||
scriptLogger?.FlushDropped();
|
||||
}
|
||||
catch (Exception)
|
||||
{
|
||||
// A debug observer must never fail the request.
|
||||
}
|
||||
|
||||
if (handlerTask is null || handlerTask.IsCompleted)
|
||||
{
|
||||
scope?.Dispose();
|
||||
@@ -577,6 +623,33 @@ public class InboundScriptExecutor
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Writes one <c>ScriptLog</c> row to the central audit store without ever blocking or failing
|
||||
/// the script (design 2026-09-09 D5) — the same fire-and-observe pattern
|
||||
/// <c>RouteHelper.EmitRouteCall</c> uses for its always-on <c>RouteCall</c> row. Never awaited on
|
||||
/// a script path: an audit write completes on the writer's own flush cadence.
|
||||
/// </summary>
|
||||
private void WriteScriptLogBestEffort(ICentralAuditWriter? writer, AuditEvent evt, string methodName)
|
||||
{
|
||||
if (writer is null) return;
|
||||
try
|
||||
{
|
||||
var t = writer.WriteAsync(evt, CancellationToken.None);
|
||||
if (!t.IsCompletedSuccessfully)
|
||||
{
|
||||
_ = t.ContinueWith(
|
||||
x => _logger.LogWarning(x.Exception, "Flow trace ScriptLog write failed for method {Method}", methodName),
|
||||
CancellationToken.None,
|
||||
TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously,
|
||||
TaskScheduler.Default);
|
||||
}
|
||||
}
|
||||
catch (Exception)
|
||||
{
|
||||
// A debug observer must never fail the request: an audit failure is not a script failure.
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -605,6 +678,14 @@ public class InboundScriptContext
|
||||
/// </summary>
|
||||
public CancellationToken CancellationToken { get; }
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D4): the script's leveled logger —
|
||||
/// <c>Log.Debug/Info/Warn/Error(message, exception?)</c>. Always reaches the node's log; a
|
||||
/// traced execution additionally records each line as a <c>ScriptTrace/ScriptLog</c> audit row
|
||||
/// the Flow Debugger folds onto the step that produced it.
|
||||
/// </summary>
|
||||
public InboundScriptLogger Log { get; }
|
||||
|
||||
/// <summary>
|
||||
/// Initializes a new instance of the InboundScriptContext.
|
||||
/// </summary>
|
||||
@@ -612,16 +693,25 @@ public class InboundScriptContext
|
||||
/// <param name="route">The route helper for cross-site routing.</param>
|
||||
/// <param name="database">The scoped, parameterized database helper for the script.</param>
|
||||
/// <param name="cancellationToken">The cancellation token.</param>
|
||||
/// <param name="log">
|
||||
/// The script's <c>Log</c> global. Optional so existing constructions (and the Central UI
|
||||
/// sandbox host) keep compiling: when omitted the context gets an inert logger that emits no
|
||||
/// audit rows and writes nowhere.
|
||||
/// </param>
|
||||
public InboundScriptContext(
|
||||
IReadOnlyDictionary<string, object?> parameters,
|
||||
RouteHelper route,
|
||||
InboundDatabaseHelper database,
|
||||
CancellationToken cancellationToken = default)
|
||||
CancellationToken cancellationToken = default,
|
||||
InboundScriptLogger? log = null)
|
||||
{
|
||||
Parameters = new ScriptParameters(parameters);
|
||||
Route = route;
|
||||
Database = database;
|
||||
CancellationToken = cancellationToken;
|
||||
Log = log ?? new InboundScriptLogger(
|
||||
NullLogger.Instance, emit: null, InboundApiOptions.DefaultMaxLogLinesPerRun,
|
||||
methodName: string.Empty, executionId: null);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -0,0 +1,219 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
using ZB.MOM.WW.Audit;
|
||||
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;
|
||||
|
||||
/// <summary>
|
||||
/// The <c>Log</c> global an inbound API method script writes through (Flow Debugger step logs,
|
||||
/// design 2026-09-09 D4/D5/D7). Central counterpart of the site runtime's script logger; the two
|
||||
/// deliberately share a shape but no code (the InboundAPI component never references SiteRuntime).
|
||||
///
|
||||
/// <para>
|
||||
/// Every call ALWAYS reaches the node's <see cref="ILogger"/>, so an author's message is never
|
||||
/// lost on an ordinary request. A <c>ScriptTrace</c>/<c>ScriptLog</c> audit row is emitted ONLY
|
||||
/// when the execution is traced — the executor supplies a non-null <c>emit</c> delegate in that
|
||||
/// case and <c>null</c> otherwise, so an untraced run pays nothing beyond the log write (D5).
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// The logger knows nothing about <c>ICentralAuditWriter</c> or the Live-run trace sink: the
|
||||
/// executor composes both into the single <c>emit</c> delegate it passes in.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Bounded per run (D7): at most <c>maxLines</c> rows, each message truncated to
|
||||
/// <see cref="MaxMessageChars"/>; further lines are counted and <see cref="FlushDropped"/> emits
|
||||
/// one closing runtime-sourced <c>warn</c> row naming the dropped count at the end of the run.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// A method script may log from several concurrent tasks, so the counters are guarded. Nothing in
|
||||
/// this class is allowed to throw into the script: a debug observer must never fail the request.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class InboundScriptLogger
|
||||
{
|
||||
/// <summary>Per-line message cap (design D7); longer messages are truncated with an ellipsis.</summary>
|
||||
public const int MaxMessageChars = 2_000;
|
||||
|
||||
private const string SourceScript = "script";
|
||||
private const string SourceRuntime = "runtime";
|
||||
|
||||
private readonly ILogger _logger;
|
||||
private readonly Action<AuditEvent>? _emit;
|
||||
private readonly int _maxLines;
|
||||
private readonly string _methodName;
|
||||
private readonly string? _actor;
|
||||
private readonly Guid? _executionId;
|
||||
private readonly string? _sourceNode;
|
||||
|
||||
private readonly object _gate = new();
|
||||
private int _emitted;
|
||||
private int _dropped;
|
||||
private int _seq;
|
||||
|
||||
/// <summary>
|
||||
/// Initializes the per-execution logger.
|
||||
/// </summary>
|
||||
/// <param name="logger">The node logger every line is forwarded to, traced or not.</param>
|
||||
/// <param name="emit">
|
||||
/// Receives each built <c>ScriptLog</c> row (the executor fans it out to the Live trace sink and
|
||||
/// the central audit writer). <c>null</c> for an untraced execution — no rows are built at all.
|
||||
/// </param>
|
||||
/// <param name="maxLines">Row cap for this run (<c>ScadaBridge:InboundApi:MaxLogLinesPerRun</c>).</param>
|
||||
/// <param name="methodName">The inbound method being executed; the row's <c>Target</c>.</param>
|
||||
/// <param name="executionId">The inbound request's execution id, tying the lines to its other rows.</param>
|
||||
/// <param name="sourceNode">Emitting central node (<c>central-a</c>/<c>central-b</c>); null = unstamped.</param>
|
||||
public InboundScriptLogger(
|
||||
ILogger logger,
|
||||
Action<AuditEvent>? emit,
|
||||
int maxLines,
|
||||
string methodName,
|
||||
Guid? executionId,
|
||||
string? sourceNode = null)
|
||||
{
|
||||
_logger = logger;
|
||||
_emit = emit;
|
||||
// A non-positive cap is rejected by the options validator; clamp defensively so a
|
||||
// hand-constructed logger can never silently audit nothing.
|
||||
_maxLines = maxLines > 0 ? maxLines : InboundApiOptions.DefaultMaxLogLinesPerRun;
|
||||
_methodName = methodName;
|
||||
_actor = string.IsNullOrEmpty(methodName) ? null : "api:" + methodName;
|
||||
_executionId = executionId;
|
||||
_sourceNode = sourceNode;
|
||||
}
|
||||
|
||||
/// <summary>Writes a debug-level line.</summary>
|
||||
/// <param name="message">The message; truncated to <see cref="MaxMessageChars"/>.</param>
|
||||
/// <param name="exception">Optional exception whose message/stack ride the row.</param>
|
||||
public void Debug(string message, Exception? exception = null) =>
|
||||
Write(LogLevel.Debug, "debug", message, exception);
|
||||
|
||||
/// <summary>Writes an information-level line.</summary>
|
||||
/// <param name="message">The message; truncated to <see cref="MaxMessageChars"/>.</param>
|
||||
/// <param name="exception">Optional exception whose message/stack ride the row.</param>
|
||||
public void Info(string message, Exception? exception = null) =>
|
||||
Write(LogLevel.Information, "info", message, exception);
|
||||
|
||||
/// <summary>Writes a warning-level line.</summary>
|
||||
/// <param name="message">The message; truncated to <see cref="MaxMessageChars"/>.</param>
|
||||
/// <param name="exception">Optional exception whose message/stack ride the row.</param>
|
||||
public void Warn(string message, Exception? exception = null) =>
|
||||
Write(LogLevel.Warning, "warn", message, exception);
|
||||
|
||||
/// <summary>Writes an error-level line. Does NOT fail the script — it is a message, not a throw.</summary>
|
||||
/// <param name="message">The message; truncated to <see cref="MaxMessageChars"/>.</param>
|
||||
/// <param name="exception">Optional exception whose message/stack ride the row.</param>
|
||||
public void Error(string message, Exception? exception = null) =>
|
||||
Write(LogLevel.Error, "error", message, exception);
|
||||
|
||||
/// <summary>
|
||||
/// Emits the single closing <c>warn</c>/<c>runtime</c> row naming how many lines the per-run
|
||||
/// cap dropped, then resets the count — so it is idempotent and a second call after a flushed
|
||||
/// run emits nothing. No-op when nothing was dropped or the run is untraced. Called by
|
||||
/// <see cref="InboundScriptExecutor"/> once the script body has finished, on every path.
|
||||
/// </summary>
|
||||
public void FlushDropped()
|
||||
{
|
||||
if (_emit is null) return;
|
||||
|
||||
int dropped;
|
||||
int seq;
|
||||
lock (_gate)
|
||||
{
|
||||
if (_dropped == 0) return;
|
||||
dropped = _dropped;
|
||||
_dropped = 0;
|
||||
seq = ++_seq;
|
||||
}
|
||||
|
||||
Emit("warn", SourceRuntime, seq,
|
||||
$"log line cap reached - {dropped} further log line(s) were not captured " +
|
||||
$"(ScadaBridge:InboundApi:MaxLogLinesPerRun = {_maxLines})",
|
||||
exception: null);
|
||||
}
|
||||
|
||||
private void Write(LogLevel level, string levelName, string message, Exception? exception)
|
||||
{
|
||||
var text = Truncate(message);
|
||||
|
||||
try
|
||||
{
|
||||
_logger.Log(level, exception,
|
||||
"Script log [{LogLevel}] for inbound method {Method} (execution {ExecutionId}): {Message}",
|
||||
levelName, _methodName, _executionId, text);
|
||||
}
|
||||
catch (Exception)
|
||||
{
|
||||
// A debug observer must never fail the request: a logging sink that throws is swallowed.
|
||||
}
|
||||
|
||||
if (_emit is null) return; // untraced run: the ILogger write above is the whole cost (D5)
|
||||
|
||||
int seq;
|
||||
lock (_gate)
|
||||
{
|
||||
if (_emitted >= _maxLines)
|
||||
{
|
||||
// Past the cap the LINE is still logged above; only the audit row is dropped,
|
||||
// and FlushDropped reports the total at the end of the run.
|
||||
_dropped++;
|
||||
return;
|
||||
}
|
||||
|
||||
_emitted++;
|
||||
seq = ++_seq;
|
||||
}
|
||||
|
||||
Emit(levelName, SourceScript, seq, text, exception);
|
||||
}
|
||||
|
||||
private void Emit(string level, string source, int seq, string message, Exception? exception)
|
||||
{
|
||||
AuditEvent evt;
|
||||
try
|
||||
{
|
||||
evt = ScadaBridgeAuditEventFactory.Create(
|
||||
AuditChannel.ScriptTrace,
|
||||
AuditKind.ScriptLog,
|
||||
AuditStatus.Delivered,
|
||||
actor: _actor,
|
||||
target: _methodName,
|
||||
sourceNode: _sourceNode,
|
||||
executionId: _executionId,
|
||||
// An inbound request is a root: its lines have no spawning execution, and
|
||||
// StepEventId stays null so the graph builder attaches them to the execution's
|
||||
// anchor step (design D2).
|
||||
parentExecutionId: null,
|
||||
errorMessage: exception?.Message,
|
||||
errorDetail: exception?.ToString(),
|
||||
requestSummary: message,
|
||||
extra: new ScriptTraceExtra { LogLevel = level, LogSource = source, Seq = seq }.ToJson());
|
||||
}
|
||||
catch (Exception)
|
||||
{
|
||||
// A debug observer must never fail the request: an unserializable row is dropped.
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
_emit!(evt);
|
||||
}
|
||||
catch (Exception)
|
||||
{
|
||||
// A debug observer must never fail the request: a misbehaving sink/writer is swallowed.
|
||||
}
|
||||
}
|
||||
|
||||
private static string Truncate(string? message)
|
||||
{
|
||||
if (string.IsNullOrEmpty(message)) return string.Empty;
|
||||
return message.Length <= MaxMessageChars
|
||||
? message
|
||||
: string.Concat(message.AsSpan(0, MaxMessageChars), "…");
|
||||
}
|
||||
}
|
||||
@@ -117,4 +117,19 @@ public class InboundApiOptionsValidatorTests
|
||||
Assert.True(result.Failed);
|
||||
Assert.Contains("StandbyForwardTimeout", result.FailureMessage);
|
||||
}
|
||||
|
||||
// --- Flow Debugger step logs (design 2026-09-09 D7) ---
|
||||
|
||||
[Theory]
|
||||
[InlineData(0)]
|
||||
[InlineData(-1)]
|
||||
public void NonPositiveMaxLogLinesPerRun_IsRejected(int max)
|
||||
{
|
||||
// A zero/negative cap would audit no line of a traced run at all while still
|
||||
// paying for the closing "dropped" row - the option must bound, not disable.
|
||||
var result = Validate(new InboundApiOptions { MaxLogLinesPerRun = max });
|
||||
|
||||
Assert.True(result.Failed);
|
||||
Assert.Contains("MaxLogLinesPerRun", result.FailureMessage);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -11,6 +11,8 @@ 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;
|
||||
|
||||
@@ -902,6 +904,142 @@ public class InboundScriptExecutorTests
|
||||
Assert.Equal(0, _executor.AbandonedExecutionCount); // ...and DECREMENTED
|
||||
}
|
||||
|
||||
// --- Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the Log global ---
|
||||
|
||||
[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);
|
||||
}
|
||||
|
||||
[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));
|
||||
}
|
||||
|
||||
[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);
|
||||
}
|
||||
|
||||
[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>
|
||||
{
|
||||
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)
|
||||
{
|
||||
lock (messages) messages.Add(formatter(state, exception));
|
||||
}
|
||||
}
|
||||
|
||||
private sealed class CompileLogCounter
|
||||
{
|
||||
public int CompilationFailures;
|
||||
|
||||
Reference in New Issue
Block a user