Files
lmxopcua/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs
T
Joseph Doherty 55ae230fa4 ci(#606): Gitea-compatible trx upload + deterministic fixes for the CI-load test flakes
- v2-ci.yml: upload-artifact@v4 -> @v3 + continue-on-error (act_runner reports as GHES and
  v4 refuses GHES, failing every run); runner-capacity diagnostic step; AKKA_TEST_TIMEFACTOR=3
  on the test step.
- Runtime/ControlPlane harnesses: akka.test.timefactor from AKKA_TEST_TIMEFACTOR
  (TestTimeFactor), single-expect-default 15s; ControlPlane gains PresenceBudget.
- Leaked spinner threads: the infinite-loop timeout tests (Calculation, Host.IntegrationTests
  RoslynVirtualTagEvaluator, 3x Core.Scripting) pinned a core for the rest of the test process
  (abandoned, never stopped). Now a bounded 5 s wall-clock spin; outer compile-inclusive bound 30 s.
- Real test races fixed: ScriptedAlarmEngine push-during-drain (Inactive is also the start
  state + persist-before-update => wait for the Cleared save); DriverReconnectE2e (both nodes
  host the driver; Created[] is last-writer-wins and ForceReconnect is a no-op while
  Connecting); ControlPlaneStarterOrder (lost-race heal waited for a 60 s refresh tick).
- Fixed sleeps -> poll-for-condition: ReconnectSupervisor LastError, Modbus deadband steps
  (wait for observed reads), Modbus dispose hygiene precondition, FOCAS probe-loop log.
- Short presence budgets -> PresenceBudget in the Runtime/ControlPlane tests seen failing on
  Gitea; Calculation Settle 10 -> 30 s. No assertion removed, nothing skipped.
- infra/README.md §10 CI; stale TreatWarningsAsErrors comment in Directory.Build.props.

Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe
2026-10-08 19:44:31 -04:00

131 lines
5.7 KiB
C#

using Microsoft.Extensions.Logging;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Driver.FOCAS;
namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests;
/// <summary>
/// Regression coverage for Driver.FOCAS-007 — the driver previously swallowed every
/// exception in its poll / probe / recycle / fixed-tree loops with no logging at all,
/// leaving operators blind when a CNC was silently failing every tick.
/// </summary>
[Trait("Category", "Unit")]
public sealed class FocasLoggingTests
{
/// <summary>Verifies that the constructor accepts an ILogger.</summary>
[Fact]
public void Constructor_accepts_an_ILogger()
{
// Constructor signature must allow an ILogger<FocasDriver> so the host can wire one
// through Microsoft.Extensions.DependencyInjection. The driver code project already
// references Microsoft.Extensions.Logging.Abstractions.
var logger = new CapturingLogger<FocasDriver>();
var drv = new FocasDriver(
new FocasDriverOptions { Probe = new FocasProbeOptions { Enabled = false } },
"drv-1",
new FakeFocasClientFactory(),
logger);
drv.ShouldNotBeNull();
}
/// <summary>Verifies that probe loop logs when an exception is swallowed.</summary>
[Fact]
public async Task ProbeLoop_logs_when_an_exception_is_swallowed()
{
var logger = new CapturingLogger<FocasDriver>();
var factory = new FakeFocasClientFactory
{
Customise = () => new FakeFocasClient
{
// Make ProbeAsync throw — the probe loop swallows it but must log.
ThrowOnConnect = false,
ProbeResult = true, // not used because the underlying probe path throws
},
};
// Force the probe to throw by making the client throw on connect.
factory.Customise = () => new FakeFocasClient
{
ThrowOnConnect = true,
Exception = new InvalidOperationException("simulated probe failure"),
};
var drv = new FocasDriver(
new FocasDriverOptions
{
Devices = [new FocasDeviceOptions("focas://10.0.0.5:8193")],
Probe = new FocasProbeOptions
{
Enabled = true,
Interval = TimeSpan.FromMilliseconds(50),
Timeout = TimeSpan.FromMilliseconds(100),
},
},
"drv-log",
factory,
logger);
await drv.InitializeAsync("{}", CancellationToken.None);
// Wait for the probe loop's first swallowed-exception log instead of sleeping a fixed 250 ms:
// on a loaded CI runner no tick had run yet and Entries was empty (#606). A presence wait —
// it returns as soon as the entry lands, and a loop that never logs still fails below.
var deadline = DateTime.UtcNow.AddSeconds(10);
while (!HasProbeEntry(logger) && DateTime.UtcNow < deadline)
await Task.Delay(10, TestContext.Current.CancellationToken);
await drv.ShutdownAsync(CancellationToken.None);
// We expect at least one log entry at Debug / Warning that mentions the simulated
// failure or the probe loop. Without logging there's literally no record on a wedged
// CNC — exactly the gap the finding called out.
logger.Entries.ShouldNotBeEmpty();
HasProbeEntry(logger)
.ShouldBeTrue("at least one log entry should reference the probe loop or surface the swallowed exception");
}
private static bool HasProbeEntry<T>(CapturingLogger<T> logger) =>
logger.Entries.Any(e => e.Message.Contains("probe", StringComparison.OrdinalIgnoreCase)
|| (e.Exception?.Message.Contains("simulated probe failure") ?? false));
private sealed class CapturingLogger<T> : ILogger<T>
{
private readonly List<(LogLevel Level, string Message, Exception? Exception)> _entries = new();
/// <summary>Gets a snapshot of the captured log entries (written from the probe loop's thread).</summary>
public IReadOnlyList<(LogLevel Level, string Message, Exception? Exception)> Entries
{
get { lock (_entries) return _entries.ToArray(); }
}
/// <summary>Begins a logging scope.</summary>
/// <param name="state">The scope state.</param>
/// <typeparam name="TState">The type of the state.</typeparam>
public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
/// <summary>Checks if logging is enabled for the specified level.</summary>
/// <param name="logLevel">The log level.</param>
public bool IsEnabled(LogLevel logLevel) => true;
/// <summary>Logs a message.</summary>
/// <param name="logLevel">The log level.</param>
/// <param name="eventId">The event ID.</param>
/// <param name="state">The state object.</param>
/// <param name="exception">The exception, if any.</param>
/// <param name="formatter">The formatter function.</param>
/// <typeparam name="TState">The type of the state.</typeparam>
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter)
{
lock (_entries) _entries.Add((logLevel, formatter(state, exception), exception));
}
private sealed class NullScope : IDisposable
{
/// <summary>Gets the singleton instance.</summary>
public static NullScope Instance { get; } = new();
/// <summary>Disposes the scope.</summary>
public void Dispose() { }
}
}
}