P0-C follow-up: stop-race-safe nonqueued command admission with measured facade phases

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";

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) ||

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<Iec61850ControlCommandResult> 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<T> RunDeviceOperationAsync<T>(
         string? deviceId,
         CancellationToken cancellationToken,
         Func<CancellationToken, Task<T>> 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,17 +649,36 @@ private async Task<T> RunDeviceOperationAsync<T>(
                 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)
             {
                 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<T> RunDeviceOperationAsync<T>(
                 }
                 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());
         }
     }
 

tests/ARSAS.Tests/P0CommandStopRaceAdmissionTests.cs

@@ -0,0 +1,137 @@
+using System.Reflection;
+using UiRuntime = ArIED61850Tester.Iec61850MonitorRuntime;
+
+namespace ARSAS.Tests;
+
+/// <summary>
+/// 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.
+/// </summary>
+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<InvalidOperationException>(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<bool>(
+            TaskCreationOptions.RunContinuationsAsynchronously);
+        stopProperty.SetValue(slot, pendingStop.Task);
+        try
+        {
+            var ex = await Assert.ThrowsAsync<InvalidOperationException>(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<SemaphoreSlim>(property.GetValue(slot));
+    }
+}