diff --git a/ControlCommandWindow.xaml.cs b/ControlCommandWindow.xaml.cs index dfdbf3ea4..b2074ba0c 100644 --- a/ControlCommandWindow.xaml.cs +++ b/ControlCommandWindow.xaml.cs @@ -201,6 +201,15 @@ private async void SendCommand_Click(object sender, RoutedEventArgs e) CommandStatus = "The command operation was cancelled."; SetResultTone("Neutral"); } + catch (InvalidOperationException ex) when ( + ex.Message.Contains("command NOT SENT", StringComparison.OrdinalIgnoreCase)) + { + // The facade rejected locally before an MMS control service. + // Never label this as an attempted command's wire failure. + CommandStage = "Command not sent"; + CommandStatus = ex.Message; + SetResultTone("Warning"); + } catch (Exception ex) { CommandStage = "Command failed"; diff --git a/MainWindow.xaml.cs b/MainWindow.xaml.cs index c66294121..0eed0e818 100644 --- a/MainWindow.xaml.cs +++ b/MainWindow.xaml.cs @@ -1796,6 +1796,20 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo signal.ControlLastResult = "Command cancelled; if Operate was already dispatched, verify actual IED position."; SetStatus($"{device.Name}: {signal.Name} command cancelled; verify the final process state."); } + catch (InvalidOperationException ex) when ( + ex.Message.Contains("command NOT SENT", StringComparison.OrdinalIgnoreCase)) + { + // A rejected local admission is NOT an MMS failure and not an + // UNKNOWN process outcome. Surface the precise busy/stop reason + // instead of the generic "Command failed" control popup. + signal.ControlLastResult = ex.Message; + AddLog("WARN", device.Name, + $"CONTROL_UI_NOT_SENT: {signal.ObjectReference}; {ex.Message}"); + SetStatus($"{device.Name}: {signal.Name} — command NOT SENT (IED busy/stopping)."); + MarkDiagnosticAlert(); + ShowControlShout(Iec61850ControlShout.FromLocalRejection( + ex.Message + " Allow the current IED operation to finish before retrying.")); + } catch (InvalidOperationException ex) when ( ex.Message.Contains("control", StringComparison.OrdinalIgnoreCase) && (ex.Message.Contains("in progress", StringComparison.OrdinalIgnoreCase) || diff --git a/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs b/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs index f2777e558..3169e8969 100644 --- a/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs +++ b/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs @@ -1,4 +1,6 @@ using System.Collections.Concurrent; +using System.Diagnostics; +using System.Globalization; using ArIED61850Tester.Models; using ArIED61850Tester.Services; @@ -178,7 +180,7 @@ public Task ExecuteControlAsync( { ClearActiveCommandExpectations(expectationKeys); } - }, rejectIfBusy: true); + }, rejectIfBusy: true, traceCommandAdmission: true); public HybridReportPhysicalValidationSnapshot CaptureHybridReportPhysicalValidation(string deviceId) => _inner.CaptureHybridReportPhysicalValidation(deviceId); @@ -540,39 +542,104 @@ await Task.Run( } } + // Command-only latency accounting, deliberately outside the native MMS service. + // This records the UI facade's local gate/lifecycle/inner wall time; it MUST NOT + // be reported as wire RTT or as proof that an Operate reached the IED. + private void RecordCommandAdmission(string? deviceId, string phase, + long beganAt, long operationGateAt, long stopGateAt, long innerStartedAt, + long innerEndedAt, long finishedAt) + { + static string Ms(long start, long end) + => (start > 0 && end >= start + ? Stopwatch.GetElapsedTime(start, end).TotalMilliseconds : 0d) + .ToString("F2", CultureInfo.InvariantCulture); + try + { + Diagnostic?.Invoke(new DiagnosticEntry + { + Time = DateTime.Now, + Level = "INFO", + Source = NormalizeDeviceKey(deviceId), + Message = "P0_COMMAND_ADMISSION " + + $"phase={phase} operationGateMs={Ms(beganAt, operationGateAt)} " + + $"stopGateMs={Ms(operationGateAt, stopGateAt)} " + + $"innerMs={Ms(innerStartedAt, innerEndedAt)} " + + $"facadeTotalMs={Ms(beganAt, finishedAt)}" + }); + } + catch + { + // Diagnostics are observational only. A consumer exception must + // never change a control's sent/unknown outcome or hold the gate. + } + } + private async Task RunDeviceOperationAsync( string? deviceId, CancellationToken cancellationToken, Func> operation, - bool rejectIfBusy = false) + bool rejectIfBusy = false, + bool traceCommandAdmission = false) { ThrowIfDisposing(); ArgumentNullException.ThrowIfNull(operation); + var beganAt = traceCommandAdmission ? Stopwatch.GetTimestamp() : 0L; + long operationGateAt = 0, stopGateAt = 0, innerStartedAt = 0, innerEndedAt = 0; + var phase = "not-dispatched"; var slot = GetSlot(deviceId); if (rejectIfBusy) { - // Strict non-blocking admission prevents apparent commands that - // wait unseen behind slow reads. The only correct alternative to - // owning the MMS association is an explicit local BUSY result. + // Never FIFO-queue operator controls behind background Read/Discovery. if (!await slot.OperationGate.WaitAsync(0, cancellationToken) .ConfigureAwait(false)) + { + if (traceCommandAdmission) + RecordCommandAdmission(deviceId, "busy-operation-NOT-SENT", + beganAt, 0, 0, 0, 0, Stopwatch.GetTimestamp()); throw new InvalidOperationException( "IED MMS association busy: command NOT SENT. Finish/cancel the current operation and retry."); + } } else await slot.OperationGate.WaitAsync(cancellationToken).ConfigureAwait(false); + if (traceCommandAdmission) + operationGateAt = Stopwatch.GetTimestamp(); CancellationTokenSource? linkedCancellation = null; long generation = 0; try { - await slot.StopGate.WaitAsync(cancellationToken).ConfigureAwait(false); + // Stop retains priority. A command is never allowed to await this + // gate; even a short lifecycle transition must yield NOT SENT. + if (rejectIfBusy) + { + if (!await slot.StopGate.WaitAsync(0, cancellationToken) + .ConfigureAwait(false)) + { + phase = "busy-stop-gate-NOT-SENT"; + throw new InvalidOperationException( + "IED stopping or reconnecting: command NOT SENT (lifecycle gate busy)."); + } + } + else + await slot.StopGate.WaitAsync(cancellationToken).ConfigureAwait(false); + if (traceCommandAdmission) + stopGateAt = Stopwatch.GetTimestamp(); try { - linkedCancellation = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); lock (slot.SyncRoot) { + // Stop publishes ActiveStopTask before taking StopGate. + // Checking only the semaphore leaves a race where a new + // command could otherwise overtake the preemptive stop. + if (rejectIfBusy && slot.ActiveStopTask is { IsCompleted: false }) + { + phase = "stop-in-progress-NOT-SENT"; + throw new InvalidOperationException( + "IED stop is in progress: command NOT SENT."); + } + linkedCancellation = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); slot.ActiveOperationCancellation = linkedCancellation; generation = ++slot.Generation; } @@ -582,10 +649,28 @@ private async Task RunDeviceOperationAsync( slot.StopGate.Release(); } - var result = await Task.Run( - async () => await operation(linkedCancellation.Token).ConfigureAwait(false), - CancellationToken.None) - .ConfigureAwait(false); + // Stop may have cancelled this operation between ownership and + // dispatch. Check again ON THE WORKER before entering inner runtime. + linkedCancellation.Token.ThrowIfCancellationRequested(); + if (traceCommandAdmission) + innerStartedAt = Stopwatch.GetTimestamp(); + phase = "inner-threw-or-cancelled"; + T result; + try + { + result = await Task.Run( + async () => + { + linkedCancellation.Token.ThrowIfCancellationRequested(); + return await operation(linkedCancellation.Token).ConfigureAwait(false); + }, CancellationToken.None) + .ConfigureAwait(false); + } + finally + { + if (traceCommandAdmission) + innerEndedAt = Stopwatch.GetTimestamp(); + } linkedCancellation.Token.ThrowIfCancellationRequested(); lock (slot.SyncRoot) @@ -593,6 +678,7 @@ private async Task RunDeviceOperationAsync( if (slot.Generation != generation) throw new OperationCanceledException("IEC 61850 lifecycle operation was superseded."); } + phase = "inner-returned"; return result; } finally @@ -606,7 +692,13 @@ private async Task RunDeviceOperationAsync( } linkedCancellation.Dispose(); } + // Release before emitting diagnostic; logs must never extend + // association occupancy or slow the following operator action. slot.OperationGate.Release(); + if (traceCommandAdmission) + RecordCommandAdmission(deviceId, phase, beganAt, + operationGateAt, stopGateAt, innerStartedAt, innerEndedAt, + Stopwatch.GetTimestamp()); } } diff --git a/tests/ARSAS.Tests/P0CommandStopRaceAdmissionTests.cs b/tests/ARSAS.Tests/P0CommandStopRaceAdmissionTests.cs new file mode 100644 index 000000000..ad20917fd --- /dev/null +++ b/tests/ARSAS.Tests/P0CommandStopRaceAdmissionTests.cs @@ -0,0 +1,137 @@ +using System.Reflection; +using UiRuntime = ArIED61850Tester.Iec61850MonitorRuntime; + +namespace ARSAS.Tests; + +/// +/// An offline admission contract: none of these tests creates an MMS association, +/// sends an Operate or touches a relay. A null request MUST remain unobserved +/// because each rejection happens before the inner control implementation. +/// +public sealed class P0CommandStopRaceAdmissionTests +{ + [Theory] + [InlineData("OperationGate")] + [InlineData("StopGate")] + public async Task CommandBusyAtEitherGate_RejectsImmediatelyAndReleasesOwnedLease( + string busyGateName) + { + await using var runtime = new UiRuntime(); + const string id = "offline-stop-admission"; + var slot = Slot(runtime, id); + var busyGate = Gate(slot, busyGateName); + var operationGate = Gate(slot, "OperationGate"); + await busyGate.WaitAsync(); + try + { + // WaitAsync bounds the regression even if a future change wrongly + // restores an invisible FIFO wait on OperationGate or StopGate. + var ex = await Assert.ThrowsAsync(async () => + await runtime.ExecuteControlAsync(id, null!, CancellationToken.None) + .WaitAsync(TimeSpan.FromSeconds(2))); + Assert.Contains("NOT SENT", ex.Message, StringComparison.Ordinal); + if (busyGateName == "StopGate") + { + // Command briefly acquires OperationGate, then must release it + // even when StopGate has rejected the nonqueued admission. + Assert.True(await operationGate.WaitAsync(0)); + operationGate.Release(); + } + } + finally + { + busyGate.Release(); + } + } + + [Fact] + public async Task PublishedStopTask_RejectsCommandEvenWhenStopGateIsFree() + { + await using var runtime = new UiRuntime(); + const string id = "offline-stop-published"; + var slot = Slot(runtime, id); + var stopProperty = slot.GetType().GetProperty( + "ActiveStopTask", BindingFlags.Instance | BindingFlags.Public)!; + Assert.NotNull(stopProperty); + var pendingStop = new TaskCompletionSource( + TaskCreationOptions.RunContinuationsAsynchronously); + stopProperty.SetValue(slot, pendingStop.Task); + try + { + var ex = await Assert.ThrowsAsync(async () => + await runtime.ExecuteControlAsync(id, null!, CancellationToken.None) + .WaitAsync(TimeSpan.FromSeconds(2))); + Assert.Contains("command NOT SENT", ex.Message, StringComparison.Ordinal); + var operationGate = Gate(slot, "OperationGate"); + Assert.True(await operationGate.WaitAsync(0)); + operationGate.Release(); + } + finally + { + stopProperty.SetValue(slot, null); + pendingStop.TrySetResult(true); + } + } + + [Fact] + public async Task DistinctIeds_OwnIndependentAdmissionAndStopLanes() + { + // Slot isolation is the foundation for an unrelated IED remaining + // responsive when another IED is discovering or stopping. + await using var runtime = new UiRuntime(); + var first = Slot(runtime, "ied-1"); + var second = Slot(runtime, "ied-2"); + Assert.NotSame(first, second); + Assert.NotSame(Gate(first, "OperationGate"), Gate(second, "OperationGate")); + Assert.NotSame(Gate(first, "StopGate"), Gate(second, "StopGate")); + } + + [Fact] + public void QuickCommandDock_ClassifiesLocalBusyBeforeGenericFailure() + { + var current = new DirectoryInfo(AppContext.BaseDirectory); + string? source = null; + while (current is not null) + { + var filename = Path.Combine(current.FullName, "MainWindow.xaml.cs"); + if (File.Exists(filename)) + { + source = File.ReadAllText(filename); + break; + } + current = current.Parent; + } + Assert.NotNull(source); + + var specific = source.IndexOf( + "ex.Message.Contains(\"command NOT SENT\"", StringComparison.Ordinal); + var generic = source.IndexOf( + "signal.ControlLastResult = $\"Command failed:", StringComparison.Ordinal); + Assert.True(specific >= 0 && generic > specific, + "A facade-local NOT SENT must be classified before the generic failure popup."); + Assert.Contains("CONTROL_UI_NOT_SENT:", source, StringComparison.Ordinal); + Assert.Contains("Iec61850ControlShout.FromLocalRejection(", source, StringComparison.Ordinal); + var dialog = File.ReadAllText( + Path.Combine(current!.FullName, "ControlCommandWindow.xaml.cs")); + var dialogLocal = dialog.IndexOf("CommandStage = \"Command not sent\"", StringComparison.Ordinal); + var dialogGeneric = dialog.IndexOf("CommandStage = \"Command failed\"", StringComparison.Ordinal); + Assert.True(dialogLocal >= 0 && dialogGeneric > dialogLocal, + "The control dialog must also separate local busy from possible wire failure."); + } + + private static object Slot(UiRuntime runtime, string deviceId) + { + var method = typeof(UiRuntime).GetMethod( + "GetSlot", BindingFlags.Instance | BindingFlags.NonPublic); + Assert.NotNull(method); + return method.Invoke(runtime, [deviceId])!; + } + + private static SemaphoreSlim Gate(object slot, string name) + { + var property = slot.GetType().GetProperty( + name, BindingFlags.Instance | BindingFlags.Public); + Assert.NotNull(property); + return Assert.IsType(property.GetValue(slot)); + } +}