feat(logging): carry ExecutionId across actor hops onto other actors' log lines (ScadaBridge#56)
LogContext is an AsyncLocal and does not cross an Akka message hop, so the run's id now rides the message: Commons.Observability.IExecutionCorrelated (explicit interface member, no wire change) on SetStaticAttributeCommand, AttributeValueChanged (not for an inferred writer), ScriptCallRequest and the four RouteTo*Requests, plus a new additive SourceExecutionId on GetAttributeRequest, WaitForAttributeRequest, WriteAttributeBatchRequest, WriteTagRequest and WriteTagBatchRequest. ScriptRuntimeContext stamps its id on the requests it sends, the Instance Actor hands it on to the DCL, and the Instance, Script, Alarm, Deployment Manager and both DCL actors re-push it per message in AroundReceive (ExecutionLogContext.PushFor: one type test when the message names no execution). The inbound executor pushes the request's ExecutionId for the method execution. Tests (TestKit): Instance Actor line carries the message's id, no leak from the sender's ambient context, scope ends with the message, per-write ids inside a batched SetAttributes, ids forwarded on DCL writes, ScriptRuntimeContext stamps; DCL adapter lines on single/batch writes carry the id; inbound executor lines carry the request id; Commons mapping + no serialized member. Each mutation- proved. Still open on #56: a queryable per-execution sink and a Flow Debugger section. The DCL actors' own Akka _log lines bypass Serilog (filed #120). Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
This commit is contained in:
Joseph Doherty
@@ -0,0 +1,105 @@
|
||||
using System.Collections.Concurrent;
|
||||
using Newtonsoft.Json;
|
||||
using Serilog;
|
||||
using Serilog.Core;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.InboundApi;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Observability;
|
||||
|
||||
/// <summary>
|
||||
/// ScadaBridge#56: which messages name the execution they serve, and what pushing one does to a
|
||||
/// LogContext-enriched logger.
|
||||
/// </summary>
|
||||
public class ExecutionLogContextTests
|
||||
{
|
||||
private static readonly DateTimeOffset Now = DateTimeOffset.UtcNow;
|
||||
private static readonly Guid Id = Guid.NewGuid();
|
||||
|
||||
private sealed class CaptureSink : ILogEventSink
|
||||
{
|
||||
public ConcurrentQueue<LogEvent> Events { get; } = new();
|
||||
public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent);
|
||||
}
|
||||
|
||||
/// <summary>Every correlated message, built with <see cref="Id"/> on its execution field.</summary>
|
||||
/// <returns>The messages.</returns>
|
||||
public static TheoryData<object> CorrelatedMessages() => new()
|
||||
{
|
||||
new SetStaticAttributeCommand("c", "i", "a", "v", Now, SourceExecutionId: Id),
|
||||
new AttributeValueChanged("i", "p", "a", 1, "Good", Now, SourceExecutionId: Id),
|
||||
new ScriptCallRequest("s", null, 0, "c", ParentExecutionId: Id),
|
||||
new RouteToCallRequest("c", "i", "s", null, Now, ParentExecutionId: Id),
|
||||
new RouteToGetAttributesRequest("c", "i", ["a"], Now, ParentExecutionId: Id),
|
||||
new RouteToSetAttributesRequest("c", "i", new Dictionary<string, string>(), Now, ParentExecutionId: Id),
|
||||
new RouteToWaitForAttributeRequest("c", "i", "a", null, TimeSpan.FromSeconds(1), Now, ParentExecutionId: Id),
|
||||
new GetAttributeRequest("c", "i", "a", Now, SourceExecutionId: Id),
|
||||
new WaitForAttributeRequest("c", "i", "a", null, null, TimeSpan.FromSeconds(1), Now, SourceExecutionId: Id),
|
||||
new WriteAttributeBatchRequest("c", "i", new Dictionary<string, string?>(), null, null, Now, SourceExecutionId: Id),
|
||||
new WriteTagRequest("c", "conn", "tag", 1, Now, SourceExecutionId: Id),
|
||||
new WriteTagBatchRequest("c", "conn", new Dictionary<string, object?>(), null, null, Now, SourceExecutionId: Id),
|
||||
};
|
||||
|
||||
/// <summary>Each correlated message reports the execution id it was built with.</summary>
|
||||
/// <param name="message">The message.</param>
|
||||
[Theory]
|
||||
[MemberData(nameof(CorrelatedMessages))]
|
||||
public void CorrelatedMessage_ReportsItsExecutionId(object message)
|
||||
=> Assert.Equal(Id, Assert.IsAssignableFrom<IExecutionCorrelated>(message).CorrelatedExecutionId);
|
||||
|
||||
/// <summary>
|
||||
/// The correlation member is an explicit interface implementation: it adds nothing to the
|
||||
/// serialized shape, so the wire is unchanged.
|
||||
/// </summary>
|
||||
/// <param name="message">The message.</param>
|
||||
[Theory]
|
||||
[MemberData(nameof(CorrelatedMessages))]
|
||||
public void CorrelatedMessage_SerializesNoExtraMember(object message)
|
||||
=> Assert.DoesNotContain(nameof(IExecutionCorrelated.CorrelatedExecutionId), JsonConvert.SerializeObject(message));
|
||||
|
||||
/// <summary>An inferred writer (the trace arm's device-echo heuristic) is not stamped onto log lines.</summary>
|
||||
[Fact]
|
||||
public void InferredValueChange_NamesNoExecution()
|
||||
{
|
||||
IExecutionCorrelated inferred = new AttributeValueChanged(
|
||||
"i", "p", "a", 1, "Good", Now, SourceExecutionId: Id, Trace: true, SourceExecutionInferred: true);
|
||||
Assert.Null(inferred.CorrelatedExecutionId);
|
||||
}
|
||||
|
||||
/// <summary>A message that names no execution - or is not correlated at all - pushes nothing.</summary>
|
||||
[Fact]
|
||||
public void PushFor_NothingToStamp_ReturnsNull()
|
||||
{
|
||||
Assert.Null(ExecutionLogContext.PushFor(new WriteTagRequest("c", "conn", "tag", 1, Now)));
|
||||
Assert.Null(ExecutionLogContext.PushFor("not a message"));
|
||||
Assert.Null(ExecutionLogContext.PushFor(null));
|
||||
Assert.Null(ExecutionLogContext.Push(null));
|
||||
}
|
||||
|
||||
/// <summary>Lines inside the scope carry the id, lines after it do not, and a nested push wins.</summary>
|
||||
[Fact]
|
||||
public void PushFor_StampsLinesInsideTheScope_AndTheInnermostWins()
|
||||
{
|
||||
var sink = new CaptureSink();
|
||||
var log = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(sink).CreateLogger();
|
||||
var child = Guid.NewGuid();
|
||||
|
||||
using (ExecutionLogContext.PushFor(new ScriptCallRequest("s", null, 0, "c", ParentExecutionId: Id)))
|
||||
{
|
||||
log.Information("parent");
|
||||
using (ExecutionLogContext.Push(child))
|
||||
log.Information("child");
|
||||
}
|
||||
log.Information("outside");
|
||||
|
||||
var events = sink.Events.ToList();
|
||||
Assert.Equal(Id.ToString(), events[0].Properties[ExecutionLogContext.ExecutionIdProperty].ToString().Trim('"'));
|
||||
Assert.Equal(child.ToString(), events[1].Properties[ExecutionLogContext.ExecutionIdProperty].ToString().Trim('"'));
|
||||
Assert.False(events[2].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty));
|
||||
}
|
||||
}
|
||||
+122
@@ -0,0 +1,122 @@
|
||||
using System.Collections.Concurrent;
|
||||
using Akka.Actor;
|
||||
using Akka.TestKit.Xunit2;
|
||||
using NSubstitute;
|
||||
using Serilog;
|
||||
using Serilog.Core;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Protocol;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
||||
using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors;
|
||||
using ZB.MOM.WW.ScadaBridge.HealthMonitoring;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests.Actors;
|
||||
|
||||
/// <summary>
|
||||
/// ScadaBridge#56: a device write the DCL performs for an execution runs the protocol adapter
|
||||
/// inside that execution's log scope, so whatever the adapter logs while writing carries the
|
||||
/// execution's id - though the write crossed two actor hops (script, Instance Actor, DCL).
|
||||
/// </summary>
|
||||
public class ExecutionLogEnrichmentTests : TestKit
|
||||
{
|
||||
private sealed class CaptureSink : ILogEventSink
|
||||
{
|
||||
public ConcurrentQueue<LogEvent> Events { get; } = new();
|
||||
public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent);
|
||||
}
|
||||
|
||||
private readonly CaptureSink _sink = new();
|
||||
private readonly Serilog.ILogger _adapterLog;
|
||||
private readonly IDataConnection _adapter = Substitute.For<IDataConnection>();
|
||||
|
||||
/// <summary>Creates the adapter double; its writes log through a LogContext-enriched Serilog logger.</summary>
|
||||
public ExecutionLogEnrichmentTests()
|
||||
{
|
||||
_adapterLog = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(_sink).CreateLogger();
|
||||
_adapter.ConnectAsync(Arg.Any<IDictionary<string, string>>(), Arg.Any<CancellationToken>())
|
||||
.Returns(Task.CompletedTask);
|
||||
_adapter.WriteAsync(Arg.Any<string>(), Arg.Any<object?>(), Arg.Any<CancellationToken>())
|
||||
.Returns(ci =>
|
||||
{
|
||||
_adapterLog.Information("adapter wrote {Tag}", ci.ArgAt<string>(0));
|
||||
return Task.FromResult(new WriteResult(true, null));
|
||||
});
|
||||
_adapter.WriteBatchAsync(Arg.Any<IDictionary<string, object?>>(), Arg.Any<CancellationToken>())
|
||||
.Returns(ci =>
|
||||
{
|
||||
_adapterLog.Information("adapter batch-wrote");
|
||||
return Task.FromResult<IReadOnlyDictionary<string, WriteResult>>(
|
||||
ci.ArgAt<IDictionary<string, object?>>(0).ToDictionary(kv => kv.Key, _ => new WriteResult(true, null)));
|
||||
});
|
||||
}
|
||||
|
||||
private async Task<IActorRef> ConnectedActor(string name)
|
||||
{
|
||||
var options = new DataConnectionOptions
|
||||
{
|
||||
ReconnectInterval = TimeSpan.FromMilliseconds(100),
|
||||
WriteTimeout = TimeSpan.FromSeconds(5),
|
||||
SeedReadMaxAttempts = 1,
|
||||
SeedReadRetryDelay = TimeSpan.FromMilliseconds(10),
|
||||
};
|
||||
var actor = Sys.ActorOf(Props.Create(() => new DataConnectionActor(
|
||||
name, _adapter, options, Substitute.For<ISiteHealthCollector>(),
|
||||
Substitute.For<IDataConnectionFactory>(), "OpcUa")), name);
|
||||
AwaitCondition(() => _adapter.ReceivedCalls().Any(c => c.GetMethodInfo().Name == "ConnectAsync"),
|
||||
TimeSpan.FromSeconds(3));
|
||||
await Task.Delay(200);
|
||||
return actor;
|
||||
}
|
||||
|
||||
private Guid? ExecutionIdOf(string fragment)
|
||||
{
|
||||
var evt = _sink.Events.First(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal));
|
||||
return evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var v)
|
||||
? Guid.Parse(v.ToString().Trim('"'))
|
||||
: null;
|
||||
}
|
||||
|
||||
/// <summary>The adapter's line for a single write carries the execution id the request names.</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task SingleWrite_AdapterLinesCarryTheExecutionId()
|
||||
{
|
||||
var actor = await ConnectedActor("enrich-single");
|
||||
var executionId = Guid.NewGuid();
|
||||
|
||||
actor.Tell(new WriteTagRequest("c1", "enrich-single", "tagA", 1, DateTimeOffset.UtcNow, executionId));
|
||||
Assert.True(ExpectMsg<WriteTagResponse>(TimeSpan.FromSeconds(5)).Success);
|
||||
|
||||
Assert.Equal(executionId, ExecutionIdOf("tagA"));
|
||||
}
|
||||
|
||||
/// <summary>The adapter's line for a batch write carries the execution id the request names.</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task BatchWrite_AdapterLinesCarryTheExecutionId()
|
||||
{
|
||||
var actor = await ConnectedActor("enrich-batch");
|
||||
var executionId = Guid.NewGuid();
|
||||
|
||||
actor.Tell(new WriteTagBatchRequest("c1", "enrich-batch",
|
||||
new Dictionary<string, object?> { ["tagB"] = 2 }, null, null, DateTimeOffset.UtcNow, executionId));
|
||||
Assert.True(ExpectMsg<WriteTagBatchResponse>(TimeSpan.FromSeconds(5)).Success);
|
||||
|
||||
Assert.Equal(executionId, ExecutionIdOf("batch-wrote"));
|
||||
}
|
||||
|
||||
/// <summary>A write that names no execution logs untagged (control for the two tests above).</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task UncorrelatedWrite_AdapterLinesAreUntagged()
|
||||
{
|
||||
var actor = await ConnectedActor("enrich-none");
|
||||
|
||||
actor.Tell(new WriteTagRequest("c1", "enrich-none", "tagC", 1, DateTimeOffset.UtcNow));
|
||||
Assert.True(ExpectMsg<WriteTagResponse>(TimeSpan.FromSeconds(5)).Success);
|
||||
|
||||
Assert.Null(ExecutionIdOf("tagC"));
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,79 @@
|
||||
using System.Collections.Concurrent;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using NSubstitute;
|
||||
using Serilog;
|
||||
using Serilog.Core;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Entities.InboundApi;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.InboundAPI.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// ScadaBridge#56: an inbound API method request stamps its <c>ExecutionId</c> on the Serilog
|
||||
/// <c>LogContext</c> for the whole execution, so a line logged anywhere on the request's async flow
|
||||
/// (the method script's callees - route, database, communication) carries it.
|
||||
/// </summary>
|
||||
public class InboundScriptExecutorLogContextTests
|
||||
{
|
||||
private sealed class CaptureSink : ILogEventSink
|
||||
{
|
||||
public ConcurrentQueue<LogEvent> Events { get; } = new();
|
||||
public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent);
|
||||
}
|
||||
|
||||
private readonly CaptureSink _sink = new();
|
||||
private readonly Serilog.ILogger _log;
|
||||
private readonly InboundScriptExecutor _executor =
|
||||
new(NullLogger<InboundScriptExecutor>.Instance, Substitute.For<IServiceProvider>());
|
||||
private readonly RouteHelper _route = new(Substitute.For<IInstanceLocator>(), Substitute.For<IInstanceRouter>());
|
||||
private readonly ApiMethod _method = new("logs", "x") { Id = 1, TimeoutSeconds = 10 };
|
||||
|
||||
/// <summary>Registers a handler that logs one line from inside the method execution.</summary>
|
||||
public InboundScriptExecutorLogContextTests()
|
||||
{
|
||||
_log = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(_sink).CreateLogger();
|
||||
_executor.RegisterHandler("logs", async _ =>
|
||||
{
|
||||
await Task.Yield(); // the line is written after an await, on a continuation
|
||||
_log.Information("inside the method");
|
||||
return null;
|
||||
});
|
||||
}
|
||||
|
||||
private static Guid? ExecutionIdOf(LogEvent evt)
|
||||
=> evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var v)
|
||||
? Guid.Parse(v.ToString().Trim('"'))
|
||||
: null;
|
||||
|
||||
/// <summary>A line written during the execution carries the request's id; one written after does not.</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task LinesDuringTheExecution_CarryTheRequestsExecutionId()
|
||||
{
|
||||
var executionId = Guid.NewGuid();
|
||||
|
||||
var result = await _executor.ExecuteAsync(_method, new Dictionary<string, object?>(), _route,
|
||||
TimeSpan.FromSeconds(10), parentExecutionId: executionId);
|
||||
_log.Information("after the method");
|
||||
|
||||
Assert.True(result.Success, result.ErrorMessage);
|
||||
var events = _sink.Events.ToList();
|
||||
Assert.Equal(2, events.Count);
|
||||
Assert.Equal(executionId, ExecutionIdOf(events[0]));
|
||||
Assert.Null(ExecutionIdOf(events[1]));
|
||||
}
|
||||
|
||||
/// <summary>A request with no execution id (outside the inbound flow) logs untagged.</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task NoExecutionId_LinesAreUntagged()
|
||||
{
|
||||
var result = await _executor.ExecuteAsync(_method, new Dictionary<string, object?>(), _route,
|
||||
TimeSpan.FromSeconds(10));
|
||||
|
||||
Assert.True(result.Success, result.ErrorMessage);
|
||||
Assert.Null(ExecutionIdOf(Assert.Single(_sink.Events)));
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,228 @@
|
||||
using System.Reflection;
|
||||
using System.Text.Json;
|
||||
using Akka.Actor;
|
||||
using Akka.TestKit.Xunit2;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Serilog.Context;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Types.Flattening;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Messages;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Persistence;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
using ZB.MOM.WW.ScadaBridge.TestSupport;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Logging;
|
||||
|
||||
/// <summary>
|
||||
/// ScadaBridge#56: a log line the Instance Actor (or any other actor serving an execution) writes
|
||||
/// while handling a message sent on behalf of that execution carries the execution's id, although
|
||||
/// <c>LogContext</c> itself never crosses the message hop - the id rides the message and the actor
|
||||
/// re-pushes it per message.
|
||||
/// </summary>
|
||||
public class ExecutionLogEnrichmentTests : TestKit, IDisposable
|
||||
{
|
||||
private const string InstanceName = "Enrich1";
|
||||
private const string NoDclLine = "cannot be routed";
|
||||
|
||||
private readonly SiteStorageService _storage;
|
||||
private readonly ScriptCompilationService _compilationService;
|
||||
private readonly SharedScriptLibrary _sharedScriptLibrary;
|
||||
private readonly TestLocalDb _localDb;
|
||||
|
||||
/// <summary>Creates a temporary LocalDb-backed site store per test.</summary>
|
||||
public ExecutionLogEnrichmentTests()
|
||||
{
|
||||
_localDb = TestLocalDb.CreateTemp("execution-log-enrichment");
|
||||
_storage = new SiteStorageService(_localDb.Db, NullLogger<SiteStorageService>.Instance);
|
||||
_storage.InitializeAsync().GetAwaiter().GetResult();
|
||||
_compilationService = new ScriptCompilationService(NullLogger<ScriptCompilationService>.Instance);
|
||||
_sharedScriptLibrary = new SharedScriptLibrary(
|
||||
_compilationService, NullLogger<SharedScriptLibrary>.Instance);
|
||||
}
|
||||
|
||||
/// <inheritdoc />
|
||||
void IDisposable.Dispose()
|
||||
{
|
||||
Shutdown();
|
||||
var path = _localDb.Path;
|
||||
_localDb.Dispose();
|
||||
TestLocalDb.DeleteFiles(path);
|
||||
}
|
||||
|
||||
private IActorRef StartInstance(Microsoft.Extensions.Logging.ILogger logger, IActorRef? dcl = null)
|
||||
{
|
||||
var config = new FlattenedConfiguration
|
||||
{
|
||||
InstanceUniqueName = InstanceName,
|
||||
Attributes =
|
||||
[
|
||||
new ResolvedAttribute
|
||||
{
|
||||
CanonicalName = "Speed", Value = "0", DataType = "Int32",
|
||||
DataSourceReference = "ns=2;s=Speed", BoundDataConnectionName = "conn-1"
|
||||
},
|
||||
new ResolvedAttribute
|
||||
{
|
||||
CanonicalName = "Trigger", Value = "0", DataType = "Int32",
|
||||
DataSourceReference = "ns=2;s=Trigger", BoundDataConnectionName = "conn-1"
|
||||
}
|
||||
]
|
||||
};
|
||||
var json = JsonSerializer.Serialize(config);
|
||||
return ActorOf(Props.Create(() => new InstanceActor(
|
||||
InstanceName, json, _storage, _compilationService, _sharedScriptLibrary, null,
|
||||
new SiteRuntimeOptions(), logger, dcl)));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A data-sourced write with no DCL logs a warning while the Instance Actor serves it; that
|
||||
/// line carries the writing execution's id.
|
||||
/// </summary>
|
||||
[Fact]
|
||||
public void InstanceActor_LineLoggedWhileServingAnExecution_CarriesItsExecutionId()
|
||||
{
|
||||
var capture = new LogContextCapture();
|
||||
var instance = StartInstance(capture);
|
||||
var executionId = Guid.NewGuid();
|
||||
|
||||
instance.Tell(new SetStaticAttributeCommand(
|
||||
"c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: executionId));
|
||||
Assert.False(ExpectMsg<SetStaticAttributeResponse>(TimeSpan.FromSeconds(10)).Success);
|
||||
|
||||
Assert.Equal(executionId, capture.ExecutionIdOf(NoDclLine));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The id comes from the MESSAGE, never from the sender's ambient context: a message that names
|
||||
/// no execution produces an untagged line even when the sending thread had one pushed. (The
|
||||
/// positive control is the test above - same command, same line, id on the message.)
|
||||
/// </summary>
|
||||
[Fact]
|
||||
public void InstanceActor_UncorrelatedMessage_DoesNotInheritTheSendersLogContext()
|
||||
{
|
||||
var capture = new LogContextCapture();
|
||||
var instance = StartInstance(capture);
|
||||
|
||||
using (LogContext.PushProperty(ExecutionLogContext.ExecutionIdProperty, Guid.NewGuid()))
|
||||
{
|
||||
instance.Tell(new SetStaticAttributeCommand("c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow));
|
||||
}
|
||||
ExpectMsg<SetStaticAttributeResponse>(TimeSpan.FromSeconds(10));
|
||||
|
||||
Assert.True(capture.Has(NoDclLine));
|
||||
Assert.Null(capture.ExecutionIdOf(NoDclLine));
|
||||
}
|
||||
|
||||
/// <summary>The scope is popped after the message: the next uncorrelated message logs untagged.</summary>
|
||||
[Fact]
|
||||
public void InstanceActor_ExecutionScopeEndsWithTheMessage()
|
||||
{
|
||||
var capture = new LogContextCapture();
|
||||
var instance = StartInstance(capture);
|
||||
|
||||
instance.Tell(new SetStaticAttributeCommand(
|
||||
"first", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: Guid.NewGuid()));
|
||||
ExpectMsg<SetStaticAttributeResponse>(TimeSpan.FromSeconds(10));
|
||||
instance.Tell(new SetStaticAttributeCommand("second", InstanceName, "Trigger", "1", DateTimeOffset.UtcNow));
|
||||
ExpectMsg<SetStaticAttributeResponse>(TimeSpan.FromSeconds(10));
|
||||
|
||||
var lines = capture.Events.Where(e => e.RenderMessage().Contains(NoDclLine, StringComparison.Ordinal)).ToList();
|
||||
Assert.Equal(2, lines.Count);
|
||||
Assert.True(lines[0].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty));
|
||||
Assert.False(lines[1].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A routed SetAttributes arrives as one <see cref="InstanceSetAttributesRequest"/> that names no
|
||||
/// execution; each write inside it does, and its line carries that write's id.
|
||||
/// </summary>
|
||||
[Fact]
|
||||
public void InstanceActor_BatchedWrites_LogUnderEachWritesExecution()
|
||||
{
|
||||
var capture = new LogContextCapture();
|
||||
var instance = StartInstance(capture);
|
||||
var executionId = Guid.NewGuid();
|
||||
|
||||
instance.Tell(new InstanceSetAttributesRequest("c1",
|
||||
[
|
||||
new SetStaticAttributeCommand("w1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow,
|
||||
SourceExecutionId: executionId),
|
||||
]));
|
||||
ExpectMsg<InstanceSetAttributesResponse>(TimeSpan.FromSeconds(10));
|
||||
|
||||
Assert.Equal(executionId, capture.ExecutionIdOf(NoDclLine));
|
||||
}
|
||||
|
||||
/// <summary>A script run stamps its own id on every request it sends the Instance Actor.</summary>
|
||||
/// <returns>A task that represents the asynchronous operation.</returns>
|
||||
[Fact]
|
||||
public async Task ScriptRuntimeContext_StampsItsExecutionIdOnInstanceRequests()
|
||||
{
|
||||
var probe = CreateTestProbe();
|
||||
var executionId = Guid.NewGuid();
|
||||
var ctx = new ScriptRuntimeContext(
|
||||
probe.Ref, _sharedScriptLibrary,
|
||||
currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5),
|
||||
instanceName: InstanceName, logger: NullLogger.Instance,
|
||||
executionId: executionId);
|
||||
|
||||
var read = ctx.GetAttribute("Speed");
|
||||
var get = probe.ExpectMsg<GetAttributeRequest>(TimeSpan.FromSeconds(5));
|
||||
Assert.Equal(executionId, get.SourceExecutionId);
|
||||
probe.Reply(new GetAttributeResponse(get.CorrelationId, InstanceName, "Speed", 1, true, "Good", DateTimeOffset.UtcNow));
|
||||
await read;
|
||||
|
||||
var call = ctx.WriteBatchAndWait(
|
||||
new Dictionary<string, string?> { ["Speed"] = "7" }, "Trigger", "1", "Ack", "1", TimeSpan.FromSeconds(3));
|
||||
var batch = probe.ExpectMsg<WriteAttributeBatchRequest>(TimeSpan.FromSeconds(5));
|
||||
Assert.Equal(executionId, batch.SourceExecutionId);
|
||||
probe.Reply(new WriteAttributeBatchResponse(batch.CorrelationId, true, null));
|
||||
var wait = probe.ExpectMsg<WaitForAttributeRequest>(TimeSpan.FromSeconds(5));
|
||||
Assert.Equal(executionId, wait.SourceExecutionId);
|
||||
probe.Reply(new WaitForAttributeResponse(wait.CorrelationId, Matched: true, "1", "Good", TimedOut: false));
|
||||
Assert.True(await call);
|
||||
}
|
||||
|
||||
/// <summary>The Instance Actor hands the writing execution's id on to the DCL, single and batch writes alike.</summary>
|
||||
[Fact]
|
||||
public void InstanceActor_ForwardsTheExecutionIdOnDclWrites()
|
||||
{
|
||||
var dcl = CreateTestProbe();
|
||||
var instance = StartInstance(NullLogger.Instance, dcl.Ref);
|
||||
dcl.ExpectMsg<SubscribeTagsRequest>(TimeSpan.FromSeconds(10));
|
||||
var single = Guid.NewGuid();
|
||||
var batch = Guid.NewGuid();
|
||||
|
||||
instance.Tell(new SetStaticAttributeCommand(
|
||||
"c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: single));
|
||||
Assert.Equal(single, dcl.ExpectMsg<WriteTagRequest>(TimeSpan.FromSeconds(10)).SourceExecutionId);
|
||||
|
||||
instance.Tell(new WriteAttributeBatchRequest(
|
||||
"c2", InstanceName, new Dictionary<string, string?> { ["Speed"] = "7" }, "Trigger", "1",
|
||||
DateTimeOffset.UtcNow, SourceExecutionId: batch));
|
||||
Assert.Equal(batch, dcl.ExpectMsg<WriteTagBatchRequest>(TimeSpan.FromSeconds(10)).SourceExecutionId);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Every site actor that serves executions re-pushes the id per message. A behavioural test
|
||||
/// covers the Instance Actor (above) and the DCL connection actor (DCL tests); this pins the
|
||||
/// hook on the rest so a refactor that drops it is caught.
|
||||
/// </summary>
|
||||
/// <param name="actorType">The actor type.</param>
|
||||
[Theory]
|
||||
[InlineData(typeof(InstanceActor))]
|
||||
[InlineData(typeof(ScriptActor))]
|
||||
[InlineData(typeof(AlarmActor))]
|
||||
[InlineData(typeof(DeploymentManagerActor))]
|
||||
[InlineData(typeof(ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionManagerActor))]
|
||||
[InlineData(typeof(ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionActor))]
|
||||
public void ExecutionServingActors_OverrideAroundReceive(Type actorType)
|
||||
{
|
||||
var method = actorType.GetMethod(
|
||||
"AroundReceive", BindingFlags.Instance | BindingFlags.NonPublic | BindingFlags.DeclaredOnly);
|
||||
Assert.NotNull(method);
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,57 @@
|
||||
using System.Collections.Concurrent;
|
||||
using Microsoft.Extensions.Logging;
|
||||
using Serilog;
|
||||
using Serilog.Core;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
||||
using ILogger = Microsoft.Extensions.Logging.ILogger;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Logging;
|
||||
|
||||
/// <summary>
|
||||
/// A Microsoft <see cref="ILogger"/> that writes each call straight to a Serilog logger enriched
|
||||
/// from <c>LogContext</c> - the shape the host gets from <c>UseSerilog</c> - and keeps the events,
|
||||
/// so a test can read the <c>ExecutionId</c> a line carried at the moment it was logged.
|
||||
/// </summary>
|
||||
internal sealed class LogContextCapture : ILogger, ILogEventSink
|
||||
{
|
||||
private readonly Serilog.ILogger _serilog;
|
||||
|
||||
/// <summary>Creates the capture with its own Serilog pipeline.</summary>
|
||||
public LogContextCapture()
|
||||
=> _serilog = new LoggerConfiguration().MinimumLevel.Verbose()
|
||||
.Enrich.FromLogContext().WriteTo.Sink(this).CreateLogger();
|
||||
|
||||
/// <summary>Every event logged so far.</summary>
|
||||
public ConcurrentQueue<LogEvent> Events { get; } = new();
|
||||
|
||||
/// <summary>The <c>ExecutionId</c> the first line containing <paramref name="fragment"/> carried (null when none).</summary>
|
||||
/// <param name="fragment">Text the rendered message contains.</param>
|
||||
/// <returns>The id, or null when the line carried none.</returns>
|
||||
public Guid? ExecutionIdOf(string fragment)
|
||||
{
|
||||
var evt = Events.First(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal));
|
||||
return evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var value)
|
||||
? Guid.Parse(value.ToString().Trim('"'))
|
||||
: null;
|
||||
}
|
||||
|
||||
/// <summary>Whether a line containing <paramref name="fragment"/> was logged.</summary>
|
||||
/// <param name="fragment">Text the rendered message contains.</param>
|
||||
/// <returns>True once such a line exists.</returns>
|
||||
public bool Has(string fragment) => Events.Any(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal));
|
||||
|
||||
/// <inheritdoc />
|
||||
public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent);
|
||||
|
||||
/// <inheritdoc />
|
||||
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
|
||||
|
||||
/// <inheritdoc />
|
||||
public bool IsEnabled(LogLevel logLevel) => true;
|
||||
|
||||
/// <inheritdoc />
|
||||
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
|
||||
Func<TState, Exception?, string> formatter)
|
||||
=> _serilog.Write(LogEventLevel.Information, exception, "{Line}", formatter(state, exception));
|
||||
}
|
||||
Reference in New Issue
Block a user