feat(scripting): evaluators log through root script logger → script-log page (F8)

This commit is contained in:
Joseph Doherty
2026-06-10 12:03:51 -04:00
parent bf86b3def6
commit bd2dd05a0c
7 changed files with 245 additions and 36 deletions
@@ -1,6 +1,10 @@
using Microsoft.Extensions.Logging.Abstractions;
using Serilog;
using Serilog.Events;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
using ZB.MOM.WW.OtOpcUa.Host.Engines;
namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests;
@@ -13,11 +17,25 @@ namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests;
/// </summary>
public sealed class RoslynScriptedAlarmEvaluatorTests
{
/// <summary>Captures published <see cref="ScriptLogEntry"/> records for assertion.</summary>
private sealed class FakePublisher : IScriptLogPublisher
{
/// <summary>Gets the entries published so far.</summary>
public List<ScriptLogEntry> Published { get; } = [];
/// <inheritdoc/>
public void Publish(ScriptLogEntry entry) => Published.Add(entry);
}
/// <summary>Builds a no-op <see cref="ScriptRootLogger"/> for tests that don't assert on logging.</summary>
private static ScriptRootLogger NoOpScriptRoot() =>
new(new LoggerConfiguration().CreateLogger());
/// <summary>Verifies evaluation of predicate returning true reports Active.</summary>
[Fact]
public void Evaluate_predicate_returning_true_reports_Active()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
alarmId: "alarm-hi",
@@ -32,7 +50,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_predicate_returning_false_reports_Inactive()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
alarmId: "alarm-hi",
@@ -47,7 +65,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_caches_compiled_predicate_across_calls()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
const string predicate = "return (bool)ctx.GetTag(\"door_open\").Value;";
var first = sut.Evaluate("alarm-door", predicate, new Dictionary<string, object?> { ["door_open"] = true });
@@ -61,7 +79,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_compile_error_returns_Failure()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate("alarm-bad", "this isn't C#;", new Dictionary<string, object?>());
@@ -73,7 +91,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_predicate_writing_virtual_tag_returns_Failure()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
// AlarmPredicateContext.SetVirtualTag throws — wrapper catches + reports as Failure.
var result = sut.Evaluate(
@@ -89,7 +107,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_empty_predicate_returns_Failure()
{
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
using var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
sut.Evaluate("alarm-empty", "", new Dictionary<string, object?>()).Success.ShouldBeFalse();
}
@@ -98,7 +116,7 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
[Fact]
public void Evaluate_after_dispose_returns_Failure()
{
var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance);
var sut = new RoslynScriptedAlarmEvaluator(NullLogger<RoslynScriptedAlarmEvaluator>.Instance, NoOpScriptRoot());
sut.Dispose();
var result = sut.Evaluate("alarm", "return true;", new Dictionary<string, object?>());
@@ -106,4 +124,36 @@ public sealed class RoslynScriptedAlarmEvaluatorTests
result.Success.ShouldBeFalse();
result.Reason!.ShouldContain("disposed");
}
/// <summary>
/// A predicate's <c>ctx.Logger.Warning(...)</c> call flows through the injected root script
/// logger and out the <see cref="ScriptLogTopicSink"/>, producing one
/// <see cref="ScriptLogEntry"/> carrying the message, the bound <c>AlarmId</c>, and the
/// Warning level.
/// </summary>
[Fact]
public void Script_logger_call_publishes_entry_with_bound_alarm_identity()
{
var publisher = new FakePublisher();
var root = new LoggerConfiguration()
.MinimumLevel.Verbose()
.WriteTo.Sink(new ScriptLogTopicSink(publisher, LogEventLevel.Information))
.CreateLogger();
using var sut = new RoslynScriptedAlarmEvaluator(
NullLogger<RoslynScriptedAlarmEvaluator>.Instance, new ScriptRootLogger(root));
var result = sut.Evaluate(
alarmId: "alarm-log",
predicate: "ctx.Logger.Warning(\"alarm log\"); return true;",
dependencies: new Dictionary<string, object?>());
result.Success.ShouldBeTrue(result.Reason);
result.Active.ShouldBeTrue();
publisher.Published.Count.ShouldBe(1);
var entry = publisher.Published[0];
entry.Message.ShouldBe("alarm log");
entry.AlarmId.ShouldBe("alarm-log");
entry.ScriptId.ShouldBe("alarm-log");
entry.Level.ShouldBe("Warning");
}
}
@@ -1,8 +1,12 @@
using System.Collections;
using System.Reflection;
using Microsoft.Extensions.Logging.Abstractions;
using Serilog;
using Serilog.Events;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
using ZB.MOM.WW.OtOpcUa.Host.Engines;
namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests;
@@ -15,11 +19,25 @@ namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests;
/// </summary>
public sealed class RoslynVirtualTagEvaluatorTests
{
/// <summary>Captures published <see cref="ScriptLogEntry"/> records for assertion.</summary>
private sealed class FakePublisher : IScriptLogPublisher
{
/// <summary>Gets the entries published so far.</summary>
public List<ScriptLogEntry> Published { get; } = [];
/// <inheritdoc/>
public void Publish(ScriptLogEntry entry) => Published.Add(entry);
}
/// <summary>Builds a no-op <see cref="ScriptRootLogger"/> for tests that don't assert on logging.</summary>
private static ScriptRootLogger NoOpScriptRoot() =>
new(new LoggerConfiguration().CreateLogger());
/// <summary>Verifies that simple addition expression is evaluated correctly.</summary>
[Fact]
public void Evaluate_simple_addition_returns_summed_value()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
virtualTagId: "vt-sum",
@@ -34,7 +52,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Evaluate_caches_compiled_expression_across_calls()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
const string expr = "return (int)ctx.GetTag(\"x\").Value * 2;";
var first = sut.Evaluate("vt-cache", expr, new Dictionary<string, object?> { ["x"] = 5 });
@@ -50,7 +68,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Evaluate_compile_error_returns_Failure_with_reason()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate("vt-bad", "this is not valid C#;", new Dictionary<string, object?>());
@@ -63,7 +81,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Evaluate_runtime_exception_returns_Failure_with_reason()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
virtualTagId: "vt-div0",
@@ -79,7 +97,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Evaluate_empty_expression_returns_Failure()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
sut.Evaluate("vt-empty", "", new Dictionary<string, object?>()).Success.ShouldBeFalse();
sut.Evaluate("vt-empty", " ", new Dictionary<string, object?>()).Success.ShouldBeFalse();
@@ -89,7 +107,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Evaluate_after_dispose_returns_Failure()
{
var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
sut.Dispose();
var result = sut.Evaluate("vt", "return 1;", new Dictionary<string, object?>());
@@ -105,7 +123,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_returns_dependency_value_without_compiling()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
virtualTagId: "vt-mirror",
@@ -121,7 +139,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_returns_same_object_reference_as_dependency()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var payload = new object();
var result = sut.Evaluate(
@@ -137,7 +155,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_whitespace_variants_match()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
virtualTagId: "vt-ws",
@@ -152,7 +170,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Non_passthrough_falls_through_to_Roslyn()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
var result = sut.Evaluate(
virtualTagId: "vt-plus1",
@@ -169,7 +187,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_missing_dependency_matches_Roslyn_behaviour()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
const string mirror = "return ctx.GetTag(\"missing\").Value;";
// Roslyn baseline: same source, but force a near-miss that compiles, to capture the
@@ -187,7 +205,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Roslyn_missing_dependency_also_returns_Ok_null()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
// `(object?)...Value` forces the compiled path (not the mirror shape) but reads the same
// missing tag; result must match the passthrough missing-dep result above.
var result = sut.Evaluate(
@@ -209,7 +227,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_exact_mirror_missing_dep_matches_Roslyn_baseline()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
// Fast-path: exact mirror shape → passthrough returns Ok(null) for missing dep.
var fastPath = sut.Evaluate(
@@ -238,7 +256,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
[Fact]
public void Passthrough_does_not_populate_the_compiled_script_cache()
{
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance);
using var sut = new RoslynVirtualTagEvaluator(NullLogger<RoslynVirtualTagEvaluator>.Instance, NoOpScriptRoot());
// Mirror shape — must take the fast-path, leaving the Roslyn cache untouched.
sut.Evaluate("vt-mirror", "return ctx.GetTag(\"a\").Value;",
@@ -251,6 +269,36 @@ public sealed class RoslynVirtualTagEvaluatorTests
CompiledCacheCount(sut).ShouldBe(1);
}
/// <summary>
/// A script's <c>ctx.Logger.*</c> call flows through the injected root script logger and out
/// the <see cref="ScriptLogTopicSink"/>, producing exactly one <see cref="ScriptLogEntry"/>
/// carrying the message and the bound identity (<c>ScriptId</c> + <c>VirtualTagId</c> both
/// equal the virtual-tag id in the live path).
/// </summary>
[Fact]
public void Script_logger_call_publishes_entry_with_bound_identity()
{
var publisher = new FakePublisher();
var root = new LoggerConfiguration()
.MinimumLevel.Verbose()
.WriteTo.Sink(new ScriptLogTopicSink(publisher, LogEventLevel.Information))
.CreateLogger();
using var sut = new RoslynVirtualTagEvaluator(
NullLogger<RoslynVirtualTagEvaluator>.Instance, new ScriptRootLogger(root));
var result = sut.Evaluate(
virtualTagId: "vt-log",
expression: "ctx.Logger.Information(\"hi from script\"); return 1;",
dependencies: new Dictionary<string, object?>());
result.Success.ShouldBeTrue(result.Reason);
publisher.Published.Count.ShouldBe(1);
var entry = publisher.Published[0];
entry.Message.ShouldBe("hi from script");
entry.ScriptId.ShouldBe("vt-log");
entry.VirtualTagId.ShouldBe("vt-log");
}
/// <summary>Reads the count of the private compiled-script cache via reflection.</summary>
private static int CompiledCacheCount(RoslynVirtualTagEvaluator sut)
{