diff --git a/MainWindow.xaml.cs b/MainWindow.xaml.cs index 5557bca32..8b994c8c1 100644 --- a/MainWindow.xaml.cs +++ b/MainWindow.xaml.cs @@ -1500,7 +1500,8 @@ private bool RejectCommandWhenIedFlightUnavailable( // Reuse existing CommandSignals state instead of mirroring a new // runtime busy flag into the WPF view model. if (device is null || - !device.CommandSignals.Any(active => active.ControlCommandBusy)) + (!device.CommandSignals.Any(active => active.ControlCommandBusy) && + !_runtime.IsControlFlightUnavailable(device.DeviceId))) return false; const string reason = "another IED command is still active or its wire outcome is unresolved"; @@ -1671,6 +1672,7 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo DismissControlShout(); var clickStopwatch = Stopwatch.StartNew(); + Guid dispatchedAssociation = Guid.Empty; signal.ControlLastResult = $"Dispatching {claim.RequestedValue}…"; SetStatus($"{device.Name}: dispatching {signal.Name} = {claim.RequestedValue}…"); AddLog("INFO", device.Name, @@ -1700,6 +1702,7 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo AddLog("INFO", device.Name, $"IEC 61850 control execution started: {signal.ObjectReference}; sequence={claim.Sequence}; value={claim.RequestedValue}; wire send is not assumed until native evidence is returned."); + dispatchedAssociation = _runtime.GetControlAssociationId(device.DeviceId); var result = await _runtime.ExecuteControlAsync( device.DeviceId, new Iec61850ControlCommandRequest @@ -1716,6 +1719,26 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo }, _applicationCancellation.Token); + if (!_runtime.IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)) + { + AddLog("WARN", device.Name, + $"CONTROL_STALE_RESULT_IGNORED: {signal.ObjectReference}; " + + "original association retired while native operation was pending."); + return; + } + + if (Iec61850ControlWireOutcomePolicy.RequiresQuarantine(result.CompletionState)) + { + signal.ControlLastResult = + "Control outcome UNKNOWN — native MMS result is inconclusive. " + + "Verify IED state and reconnect before another command."; + AddLog("ERROR", device.Name, + $"CONTROL_UI_NATIVE_UNKNOWN: {signal.ObjectReference}; " + + $"completion={result.CompletionState}; {result.Message}"); + MarkDiagnosticAlert(); + ShowControlShout(Iec61850ControlShout.FromUnknownWireOutcome()); + return; // Do not publish ambiguous feedback as a process value. + } if (!string.IsNullOrWhiteSpace(result.ControlModelText)) signal.ControlModelText = result.ControlModelText; if (!string.IsNullOrWhiteSpace(result.FeedbackValue) && result.FeedbackValue != "-") @@ -1738,6 +1761,8 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo } catch (OperationCanceledException) { + if (dispatchedAssociation != Guid.Empty && + !_runtime.IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)) return; 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."); } @@ -1746,6 +1771,8 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo (ex.Message.Contains("in progress", StringComparison.OrdinalIgnoreCase) || ex.Message.Contains("unresolved", StringComparison.OrdinalIgnoreCase))) { + if (dispatchedAssociation != Guid.Empty && + !_runtime.IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)) return; signal.ControlLastResult = "Command NOT SENT: " + ex.Message; AddLog("WARN", device.Name, $"CONTROL_UI_LOCAL_GATE: {signal.ObjectReference}; {ex.Message}"); @@ -1756,6 +1783,8 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo } catch (TimeoutException ex) { + if (dispatchedAssociation != Guid.Empty && + !_runtime.IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)) return; signal.ControlLastResult = "Control outcome UNKNOWN — MMS flight exceeded deadline. " + "Verify IED process state and reconnect before another command."; @@ -1763,11 +1792,12 @@ private async Task ExecuteClaimedControlAsync(SignalDefinition signal, ControlCo $"CONTROL_UI_TIMEOUT: {signal.ObjectReference}; {ex.Message}"); SetStatus($"{device.Name}: {signal.Name} control outcome UNKNOWN; check Diagnostics."); MarkDiagnosticAlert(); - ShowControlShout(Iec61850ControlShout.FromLocalRejection( - "Control timed out with UNKNOWN wire outcome. Verify the IED position and reconnect; do not blindly retry")); + ShowControlShout(Iec61850ControlShout.FromUnknownWireOutcome()); } catch (Exception ex) { + if (dispatchedAssociation != Guid.Empty && + !_runtime.IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)) return; signal.ControlLastResult = $"Command failed: {ex.Message}"; AddLog("ERROR", device.Name, $"Quick control failed for {signal.ObjectReference}: {ex}"); SetStatus($"{device.Name}: {signal.Name} command failed — {ex.Message}"); diff --git a/Services/Iec61850ControlFlightAdmission.cs b/Services/Iec61850ControlFlightAdmission.cs index dd453cfe8..0594cb78d 100644 --- a/Services/Iec61850ControlFlightAdmission.cs +++ b/Services/Iec61850ControlFlightAdmission.cs @@ -28,3 +28,89 @@ public static void Quarantine(ref int quarantine) public static void Release(ref int active) => Interlocked.Exchange(ref active, 0); } + + +/// +/// One physical MMS association's command lifetime. Retirement atomically +/// prevents admission and never equates WaitAsync cancellation with release +/// of the underlying native operation. +/// +public sealed class Iec61850ControlSessionLease +{ + private readonly object _sync = new(); + private TaskCompletionSource? _activeFlightReleased; + private readonly CancellationTokenSource _retirement = new(); + private int _active; + private int _quarantine; + private int _retired; + + // Linked into native operations so Stop can cancel even the narrow window + // between successful admission and native task creation. + public CancellationToken RetirementToken => _retirement.Token; + public bool IsActive => Volatile.Read(ref _active) != 0; + public bool IsRetired => Volatile.Read(ref _retired) != 0; + public bool IsUnavailable => + IsRetired || Iec61850ControlFlightAdmission.IsUnavailable(ref _active, ref _quarantine); + + public bool TryEnter() + { + lock (_sync) + { + if (_retired != 0 || + !Iec61850ControlFlightAdmission.TryEnter(ref _active, ref _quarantine)) + return false; + _activeFlightReleased = new TaskCompletionSource( + TaskCreationOptions.RunContinuationsAsynchronously); + return true; + } + } + + public void Quarantine() + => Iec61850ControlFlightAdmission.Quarantine(ref _quarantine); + + public void Release() + { + lock (_sync) + { + Iec61850ControlFlightAdmission.Release(ref _active); + _activeFlightReleased?.TrySetResult(true); + } + } + + /// + /// Prevent future commands and return a drain which finishes only when + /// the original admitted native operation has actually released its lease. + /// + public Task Retire() + { + Task drain; + lock (_sync) + { + Volatile.Write(ref _retired, 1); + Quarantine(); + drain = _active != 0 + ? _activeFlightReleased!.Task + : Task.CompletedTask; + } + // Never execute native cancellation callbacks under the admission lock. + // Retirement was already committed atomically before releasing it. + _retirement.Cancel(); + return drain; + } +} + + +/// +/// A completed Task is not necessarily a definite wire result. Native services +/// can return UNKNOWN/timeout completion without throwing an exception. +/// +public static class Iec61850ControlWireOutcomePolicy +{ + public static bool RequiresQuarantine(string? completionState) => + !string.IsNullOrWhiteSpace(completionState) && + (completionState.Contains("Unknown", StringComparison.OrdinalIgnoreCase) || + completionState.Contains("TimedOut", StringComparison.OrdinalIgnoreCase) || + completionState.Contains("Timeout", StringComparison.OrdinalIgnoreCase) || + completionState.Equals("AssociationLost", StringComparison.OrdinalIgnoreCase) || + completionState.Equals("Cancelled", StringComparison.OrdinalIgnoreCase)); +} diff --git a/Services/Iec61850ControlRequestSnapshot.cs b/Services/Iec61850ControlRequestSnapshot.cs new file mode 100644 index 000000000..96277fceb --- /dev/null +++ b/Services/Iec61850ControlRequestSnapshot.cs @@ -0,0 +1,55 @@ +using ArIED61850Tester.Models; + +namespace ArIED61850Tester.Services; + +/// +/// Makes one disposable, command-only copy of the operator's selected signal. +/// ARIEC may update the request's SignalDefinition after an asynchronous MMS +/// reply; a retired association must never mutate a WPF-owned signal model. +/// The copy carries no process-value authority or extra observation cache. +/// +public static class Iec61850ControlRequestSnapshot +{ + public static Iec61850ControlCommandRequest Create(Iec61850ControlCommandRequest request) + { + ArgumentNullException.ThrowIfNull(request); + return new Iec61850ControlCommandRequest + { + Signal = CopySignal(request.Signal), + ValueText = request.ValueText, + InterlockCheck = request.InterlockCheck, + SynchroCheck = request.SynchroCheck, + TestMode = request.TestMode, + Originator = request.Originator, + OriginCategory = request.OriginCategory, + FeedbackTimeoutMs = request.FeedbackTimeoutMs, + CommandTerminationTimeoutMs = request.CommandTerminationTimeoutMs + }; + } + + private static SignalDefinition CopySignal(SignalDefinition signal) + { + ArgumentNullException.ThrowIfNull(signal); + var copy = new SignalDefinition + { + Name = signal.Name, + ObjectReference = signal.ObjectReference, + FunctionalConstraint = signal.FunctionalConstraint, + DataType = signal.DataType, + Category = signal.Category, + IsControlSignal = signal.IsControlSignal, + ControlCdc = signal.ControlCdc, + ControlStatusReference = signal.ControlStatusReference, + ControlValueType = signal.ControlValueType, + ControlModelReference = signal.ControlModelReference, + ControlModelText = signal.ControlModelText, + ControlCurrentValue = signal.ControlCurrentValue, + ControlSemanticVerified = signal.ControlSemanticVerified + }; + // Preserve only the authority already verified by the current MMS + // association. Never promote DataSet/SCL advisory CDC to live proof. + if (!string.IsNullOrWhiteSpace(signal.VerifiedLiveControlCdc)) + copy.AcceptVerifiedLiveControlCdc(signal.VerifiedLiveControlCdc); + return copy; + } +} diff --git a/Services/Iec61850ControlShout.cs b/Services/Iec61850ControlShout.cs index 4d770b426..01547286a 100644 --- a/Services/Iec61850ControlShout.cs +++ b/Services/Iec61850ControlShout.cs @@ -118,6 +118,11 @@ explanation.Confidence is "ConfirmedClient" or "LocalValidation" Safe($"ARSAS blocked the request before dispatch: {reason}.", 175), Iec61850ControlNoticeTone.Warning); + internal static Notice FromUnknownWireOutcome() => new( + "Command outcome UNKNOWN", + "MMS wire result is inconclusive. Verify actual IED state and reconnect before any new Operate.", + Iec61850ControlNoticeTone.Warning); + internal static Notice FromDemo(string feedback) => new( "Simulation updated", Safe($"Demo feedback: {feedback}. No command was sent to a physical IED.", 175), diff --git a/Services/Iec61850MonitorRuntime.cs b/Services/Iec61850MonitorRuntime.cs index a5b718a6a..5a547dfe8 100644 --- a/Services/Iec61850MonitorRuntime.cs +++ b/Services/Iec61850MonitorRuntime.cs @@ -86,10 +86,10 @@ private sealed class DeviceSession public DateTime NextHealthProbeUtc { get; set; } = DateTime.MinValue; public int ConsecutiveHealthProbeFailures { get; set; } public string HealthProbePointKey { get; set; } = string.Empty; - public int ControlCommandActive; - // A timed-out/cancelled native Operate may still be in-flight on the - // association. Do not admit another control until a fresh session. - public int ControlFlightQuarantined; + public Guid ControlAssociationId { get; } = Guid.NewGuid(); + // The old socket remains owned until its original native flight drains. + // Never share admission or retirement with a replacement association. + public Iec61850ControlSessionLease ControlFlight { get; } = new(); public HybridReportPhysicalValidationTracker HybridValidation { get; } = new(); public StaticDataSetReportProjectionAccumulator StaticReportProjection { get; } = new(); public bool StaticDataSetReportOnly { get; set; } @@ -97,7 +97,6 @@ private sealed class DeviceSession } private readonly ConcurrentDictionary _sessions = new(StringComparer.OrdinalIgnoreCase); - private readonly ConcurrentDictionary _activeControlTargets = new(StringComparer.OrdinalIgnoreCase); private long _eventSequence; public event Action? Diagnostic; @@ -882,24 +881,19 @@ Iec61850ControlModelKind.SboNormal or Iec61850ControlModelKind.SboEnhanced)) throw new ArgumentException("A valid expected live ctlModel and target 1-4 are required."); - var targetKey = deviceId + "|" + Iec61850ControlIdentity.Normalize(signal.ObjectReference); - if (!_activeControlTargets.TryAdd(targetKey, 0)) - throw new InvalidOperationException("A command is already running for this object."); - - if (!Iec61850ControlFlightAdmission.TryEnter( - ref session.ControlCommandActive, ref session.ControlFlightQuarantined)) - { - _activeControlTargets.TryRemove(targetKey, out _); + if (!session.ControlFlight.TryEnter()) throw new InvalidOperationException( - "This IED already has an active or unresolved control flight. No ctlModel Write was sent."); - } + "This IED already has an active, unresolved or retired control flight. No ctlModel Write was sent."); + using var modelCancellation = CancellationTokenSource.CreateLinkedTokenSource( + cancellationToken, session.ControlFlight.RetirementToken); + modelCancellation.Token.ThrowIfCancellationRequested(); try { Log("WARN", session.Device.Name, $"OPERATOR_CTL_MODEL_CONFIGURATION: {signal.ObjectReference}; expected={expected}; requested={target}; " + "explicit commissioning confirmed; one CF Write maximum, never Operate."); var result = await session.Client.ConfigureControlModelAsync( - signal, expected, target, cancellationToken).ConfigureAwait(false); + signal, expected, target, modelCancellation.Token).ConfigureAwait(false); Log(result.ReadbackVerified ? "INFO" : "WARN", session.Device.Name, $"CTL_MODEL_CONFIGURATION_RESULT: {signal.ObjectReference}; " + $"writeAccepted={result.WriteAccepted}; readbackVerified={result.ReadbackVerified}; " + @@ -908,8 +902,7 @@ Iec61850ControlModelKind.SboNormal or } finally { - Iec61850ControlFlightAdmission.Release(ref session.ControlCommandActive); - _activeControlTargets.TryRemove(targetKey, out _); + session.ControlFlight.Release(); } } @@ -924,8 +917,7 @@ public async Task InspectControlAsync( if (!_sessions.TryGetValue(deviceId, out var session) || !session.Client.IsConnected) throw new InvalidOperationException("The IED must be connected before a control object can be inspected."); - if (Volatile.Read(ref session.ControlCommandActive) != 0 || - Volatile.Read(ref session.ControlFlightQuarantined) != 0) + if (session.ControlFlight.IsUnavailable) throw new InvalidOperationException( "Control inspection deferred: another command is in flight or the association requires recovery."); try @@ -950,8 +942,22 @@ public async Task InspectControlAsync( public bool IsControlFlightUnavailable(string deviceId) => _sessions.TryGetValue(deviceId, out var session) && - (Iec61850ControlFlightAdmission.IsUnavailable( - ref session.ControlCommandActive, ref session.ControlFlightQuarantined)); + session.ControlFlight.IsUnavailable; + + private bool IsCurrentSession(DeviceSession session) + => !session.ControlFlight.IsRetired && + _sessions.TryGetValue(session.Device.DeviceId, out var current) && + ReferenceEquals(current, session); + + public Guid GetControlAssociationId(string deviceId) + => _sessions.TryGetValue(deviceId, out var session) && !session.ControlFlight.IsRetired + ? session.ControlAssociationId : Guid.Empty; + + public bool IsControlAssociationCurrent(string deviceId, Guid associationId) + => associationId != Guid.Empty && + _sessions.TryGetValue(deviceId, out var session) && + !session.ControlFlight.IsRetired && + session.ControlAssociationId == associationId; public async Task ExecuteControlAsync( string deviceId, @@ -964,47 +970,58 @@ public async Task ExecuteControlAsync( if (!_sessions.TryGetValue(deviceId, out var session) || !session.Client.IsConnected) throw new InvalidOperationException("The IED must be connected before a command can be sent."); - // One physical control target per device, regardless of DataSet aliases. - // Failed concurrent admission is local: no additional MMS Operate. - var targetKey = deviceId + "|" + Iec61850ControlIdentity.Normalize(request.Signal.ObjectReference); - if (!_activeControlTargets.TryAdd(targetKey, 0)) + // A per-association lease prevents a late command from an old session + // from unlocking the same deviceId/CSWI target on a new MMS socket. + if (!session.ControlFlight.TryEnter()) { - Log("WARN", session.Device.Name, - $"CONTROL_LOCAL_BUSY: {request.Signal.ObjectReference}; no additional MMS Operate was sent."); - throw new InvalidOperationException("Command already in progress for this IEC 61850 control object. No new MMS Operate was sent."); - } - - // Association-wide single-flight, not merely one lock per control - // object. Different CSWIs on the same MMS socket must never accumulate - // behind the native semaphore while the report loop is paused. - if (!Iec61850ControlFlightAdmission.TryEnter( - ref session.ControlCommandActive, ref session.ControlFlightQuarantined)) - { - _activeControlTargets.TryRemove(targetKey, out _); Log("WARN", session.Device.Name, $"CONTROL_IED_SINGLE_FLIGHT: rejected {request.Signal.ObjectReference}; another control is active or its wire outcome is unresolved; Operate NOT SENT."); throw new InvalidOperationException( "Another command is active or its wire outcome is unresolved on this IED. No MMS Operate was sent. Reconnect and verify actual status before retrying."); } + var attemptId = Guid.NewGuid(); + var admittedAtUtc = DateTimeOffset.UtcNow; var clientStopwatch = Stopwatch.StartNew(); - var nativeCancellation = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + var nativeCancellation = CancellationTokenSource.CreateLinkedTokenSource( + cancellationToken, session.ControlFlight.RetirementToken); Task? nativeFlight = null; Iec61850ControlCommandResult result; try { + Log("INFO", session.Device.Name, + $"CONTROL_ATTEMPT_ADMITTED: attemptId={attemptId}; associationId={session.ControlAssociationId}; " + + $"reference={request.Signal.ObjectReference}; ctlModel={request.Signal.ControlModelText}; " + + $"admittedUtc={admittedAtUtc:O}; wireSent=UNKNOWN; no native invoke ID exposed."); Log("INFO", session.Device.Name, $"Control execution requested: {request.Signal.ObjectReference} value={request.ValueText}; test={request.TestMode}; interlock={request.InterlockCheck}; synchro={request.SynchroCheck}; origin={request.OriginCategory}/{request.Originator}; IED acceptance is determined only from native MMS wire evidence."); - nativeFlight = session.Client.ExecuteControlAsync(request, nativeCancellation.Token); + nativeCancellation.Token.ThrowIfCancellationRequested(); + nativeFlight = session.Client.ExecuteControlAsync( + Iec61850ControlRequestSnapshot.Create(request), + nativeCancellation.Token); + Log("INFO", session.Device.Name, + $"CONTROL_NATIVE_TASK_STARTED: attemptId={attemptId}; associationId={session.ControlAssociationId}; " + + "Task created does not prove Operate transmitted."); result = await nativeFlight.WaitAsync(ControlFlightDeadline, cancellationToken) .ConfigureAwait(false); + // A native Task can complete with an explicitly uncertain MMS + // result. Quarantine BEFORE finally releases the physical flight; + // otherwise a second Operate could enter on the same association. + if (Iec61850ControlWireOutcomePolicy.RequiresQuarantine(result.CompletionState)) + { + session.ControlFlight.Quarantine(); + Log("ERROR", session.Device.Name, + $"CONTROL_OUTCOME_UNKNOWN_NATIVE_RESULT: attemptId={attemptId}; associationId={session.ControlAssociationId}; {request.Signal.ObjectReference}; " + + $"completion={result.CompletionState}; stage={result.Stage}; " + + "further controls blocked until a new, verified association."); + } } catch (TimeoutException) { - Iec61850ControlFlightAdmission.Quarantine(ref session.ControlFlightQuarantined); + session.ControlFlight.Quarantine(); nativeCancellation.Cancel(); Log("ERROR", session.Device.Name, - $"CONTROL_OUTCOME_UNKNOWN_TIMEOUT: {request.Signal.ObjectReference}; deadline={ControlFlightDeadline.TotalSeconds:0}s; nativeCompleted={nativeFlight?.IsCompleted}; no further commands on this MMS association. Actual IED position must be checked before reconnect."); + $"CONTROL_OUTCOME_UNKNOWN_TIMEOUT: attemptId={attemptId}; associationId={session.ControlAssociationId}; {request.Signal.ObjectReference}; deadline={ControlFlightDeadline.TotalSeconds:0}s; nativeCompleted={nativeFlight?.IsCompleted}; no further commands on this MMS association. Actual IED position must be checked before reconnect."); throw new TimeoutException( "Control exceeded the end-to-end deadline. The MMS wire outcome is UNKNOWN, not necessarily rejected. This association is quarantined; verify process state and reconnect before any further Operate."); } @@ -1012,10 +1029,10 @@ public async Task ExecuteControlAsync( { if (nativeFlight is { IsCompleted: false }) { - Iec61850ControlFlightAdmission.Quarantine(ref session.ControlFlightQuarantined); + session.ControlFlight.Quarantine(); nativeCancellation.Cancel(); Log("WARN", session.Device.Name, - $"CONTROL_CANCEL_OUTCOME_UNKNOWN: {request.Signal.ObjectReference}; native flight not completed; association quarantined."); + $"CONTROL_CANCEL_OUTCOME_UNKNOWN: attemptId={attemptId}; associationId={session.ControlAssociationId}; {request.Signal.ObjectReference}; native flight not completed; association quarantined."); } throw; } @@ -1027,14 +1044,13 @@ public async Task ExecuteControlAsync( // still own a socket and may still apply Operate. Retain the // per-IED gate until it ACTUALLY terminates. Never dispose its // CTS or let another command use that association prematurely. - _ = ObserveLateControlFlightAsync(session, targetKey, - request.Signal.ObjectReference, nativeFlight, nativeCancellation); + _ = ObserveLateControlFlightAsync(session, + attemptId, request.Signal.ObjectReference, nativeFlight, nativeCancellation); } else { nativeCancellation.Dispose(); - Iec61850ControlFlightAdmission.Release(ref session.ControlCommandActive); - _activeControlTargets.TryRemove(targetKey, out _); + session.ControlFlight.Release(); } } clientStopwatch.Stop(); @@ -1076,7 +1092,7 @@ public async Task ExecuteControlAsync( }.Where(text => !string.IsNullOrWhiteSpace(text))); Log(result.IsSuccess ? "INFO" : "ERROR", session.Device.Name, - $"Control {result.Stage}: {request.Signal.ObjectReference}; sequence={result.SequenceText}; requested={result.RequestedValue}; feedback={result.FeedbackValue}; {protocolEvidence}; {result.Message}"); + $"CONTROL_ATTEMPT_RESULT: attemptId={attemptId}; associationId={session.ControlAssociationId}; Control {result.Stage}: {request.Signal.ObjectReference}; sequence={result.SequenceText}; requested={result.RequestedValue}; feedback={result.FeedbackValue}; {protocolEvidence}; {result.Message}"); if (!result.IsSuccess) { @@ -1130,7 +1146,7 @@ public async Task ExecuteControlAsync( } private async Task ObserveLateControlFlightAsync(DeviceSession session, - string targetKey, string reference, + Guid attemptId, string reference, Task nativeFlight, CancellationTokenSource nativeCancellation) { @@ -1138,18 +1154,17 @@ private async Task ObserveLateControlFlightAsync(DeviceSession session, { var late = await nativeFlight.ConfigureAwait(false); Log("WARN", session.Device.Name, - $"CONTROL_LATE_NATIVE_RESULT: {reference}; completed after caller timeout/cancellation; stage={late.Stage}; success={late.IsSuccess}; association remains quarantined pending verified recovery."); + $"CONTROL_LATE_NATIVE_RESULT: attemptId={attemptId}; associationId={session.ControlAssociationId}; {reference}; completed after caller timeout/cancellation; stage={late.Stage}; success={late.IsSuccess}; association remains quarantined pending verified recovery."); } catch (Exception ex) { Log("WARN", session.Device.Name, - $"CONTROL_LATE_NATIVE_FAILURE: {reference}; {ex.GetType().Name}: {ex.Message}; association remains quarantined."); + $"CONTROL_LATE_NATIVE_FAILURE: attemptId={attemptId}; associationId={session.ControlAssociationId}; {reference}; {ex.GetType().Name}: {ex.Message}; association remains quarantined."); } finally { nativeCancellation.Dispose(); - Iec61850ControlFlightAdmission.Release(ref session.ControlCommandActive); - _activeControlTargets.TryRemove(targetKey, out _); + session.ControlFlight.Release(); } } @@ -1183,45 +1198,103 @@ public async Task StopDeviceAsync(string deviceId) if (!_sessions.TryRemove(deviceId, out var session)) return; - // Stop MUST leave a reusable device after any teardown failure. The - // session is already removed from the live registry, so never leave a - // half-connected UI or a stale control authority behind on exception. - try + // Revoke new admission before ANY await. Already-dispatched native + // operations are still owned by the old association, not by the UI. + var nativeDrain = session.ControlFlight.Retire(); + var deferred = !nativeDrain.IsCompleted; + if (deferred) { - await StopMonitoringSessionAsync(session, preservePointDefinitions: false).ConfigureAwait(false); - } - catch (Exception ex) - { - Log("WARN", session.Device.Name, $"Monitor stop cleanup: {ex.GetType().Name}: {ex.Message}"); + session.MonitorCancellation.Cancel(); + _ = DisposeDetachedSessionAfterDrainAsync(session, nativeDrain); + Log("WARN", session.Device.Name, + "CONTROL_DETACHED_ASSOCIATION: old native control is unresolved; " + + "MMS disposal deferred until its operation actually finishes. " + + "Wire outcome UNKNOWN; do not retry blindly."); } + try { - await session.Client.DisposeAsync().ConfigureAwait(false); - } - catch (Exception ex) - { - Log("WARN", session.Device.Name, $"MMS disconnect cleanup: {ex.GetType().Name}: {ex.Message}"); + if (!deferred) + { + try + { + await StopMonitoringSessionAsync(session, preservePointDefinitions: false) + .ConfigureAwait(false); + } + catch (Exception ex) + { + Log("WARN", session.Device.Name, + $"Monitor stop cleanup: {ex.GetType().Name}: {ex.Message}"); + } + + try + { + await session.Client.DisposeAsync().ConfigureAwait(false); + } + catch (Exception ex) + { + Log("WARN", session.Device.Name, + $"MMS disconnect cleanup: {ex.GetType().Name}: {ex.Message}"); + } + } } finally { - // WPF-owned CommandSignals may only be replaced on its Dispatcher. - // Await this work before allowing the facade's StopGate to release. try { await ResetAssociationControlAuthorityAsync(session.Device).ConfigureAwait(false); } catch (Exception ex) { - Log("WARN", session.Device.Name, $"Control UI authority cleanup: {ex.GetType().Name}: {ex.Message}"); + Log("WARN", session.Device.Name, + $"Control UI authority cleanup: {ex.GetType().Name}: {ex.Message}"); } - session.MonitorCancellation.Dispose(); + if (!deferred) + session.MonitorCancellation.Dispose(); session.Device.IsMonitoring = false; session.Device.IsConnected = false; session.Device.AcquisitionMode = "Not started"; session.Device.Status = "Disconnected"; - session.Device.Detail = "IEC 61850 session closed. Saved model remains available for Play."; + session.Device.Detail = deferred + ? "Old MMS operation unresolved (UNKNOWN); old session detached. " + + "Verify actual IED status before reconnecting." + : "IEC 61850 session closed. Saved model remains available for Play."; session.Device.RefreshComputed(); - Log("INFO", session.Device.Name, "IEC 61850 session disconnected."); + Log("INFO", session.Device.Name, + deferred + ? "IEC 61850 session detached; native teardown pending actual completion." + : "IEC 61850 session disconnected."); + } + } + + private async Task DisposeDetachedSessionAfterDrainAsync(DeviceSession session, Task nativeDrain) + { + try + { + await nativeDrain.ConfigureAwait(false); + // A cancelled monitor read may still be in the old MMS receive + // pipeline. Wait for that task too before disposing the old client. + if (session.MonitorTask is { } monitorTask) + { + try { await monitorTask.ConfigureAwait(false); } + catch (Exception ex) + { + Log("WARN", session.Device.Name, + $"Detached monitor ended: {ex.GetType().Name}: {ex.Message}"); + } + } + await session.Client.DisposeAsync().ConfigureAwait(false); + Log("INFO", session.Device.Name, + "CONTROL_DETACHED_CLEANUP_COMPLETE: old MMS client disposed."); + } + catch (Exception ex) + { + Log("WARN", session.Device.Name, + $"CONTROL_DETACHED_CLEANUP_FAILED: {ex.GetType().Name}: {ex.Message}"); + } + finally + { + session.MonitorCancellation.Dispose(); } } @@ -1386,11 +1459,11 @@ private async Task StartReportPlansAsync( private async Task MonitorLoopAsync(DeviceSession session, CancellationToken cancellationToken) { - while (!cancellationToken.IsCancellationRequested) + while (!cancellationToken.IsCancellationRequested && !session.ControlFlight.IsRetired) { try { - if (Volatile.Read(ref session.ControlCommandActive) > 0) + if (session.ControlFlight.IsActive) { await Task.Delay(5, cancellationToken).ConfigureAwait(false); continue; @@ -1607,7 +1680,7 @@ private async Task ReceiveReportSlicesAsync(DeviceSession session, CancellationT var batchCount = Math.Min(plans.Count, 4); for (var offset = 0; offset < batchCount; offset++) { - if (Volatile.Read(ref session.ControlCommandActive) > 0) + if (session.ControlFlight.IsActive) break; cancellationToken.ThrowIfCancellationRequested(); var index = (session.ReportPlanCursor + offset) % plans.Count; @@ -1963,7 +2036,7 @@ private async Task PollDuePointsAsync(DeviceSession session, CancellationToken c var processed = 0; while (processed < 4 && session.PollQueue.TryPeek(out var pointKey, out var dueTicks)) { - if (Volatile.Read(ref session.ControlCommandActive) > 0) + if (session.ControlFlight.IsActive) break; var nowUtc = DateTime.UtcNow; if (dueTicks > nowUtc.Ticks) @@ -2121,6 +2194,8 @@ private void ApplyValueUpdate( string? reportId = null, string? reportControlReference = null) { + if (!IsCurrentSession(session)) + return; // Never publish an old MMS observation into a new association. var state = session.States[point.PointKey]; var hadValue = state.HasValue; var oldValue = state.Value; @@ -2230,6 +2305,8 @@ private void EmitStatusSnapshot( string status, string quality) { + if (!IsCurrentSession(session)) + return; state.Status = status; PointUpdated?.Invoke(new Iec61850PointSnapshot { @@ -2615,7 +2692,7 @@ private async Task ProbeSessionHealthAsync(DeviceSession session, CancellationTo // process leaves are never repurposed as cyclic MMS heartbeat reads. if (session.StaticDataSetReportOnly) return; - if (Volatile.Read(ref session.ControlCommandActive) > 0) + if (session.ControlFlight.IsActive) return; var now = DateTime.UtcNow; if (now < session.RecoveryWarmupUntilUtc) diff --git a/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs b/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs index 0a4bfe2ac..362a36031 100644 --- a/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs +++ b/Services/UiResponsiveIec61850MonitorRuntimeFacade.cs @@ -78,6 +78,17 @@ public IReadOnlySet GetActiveBrowserRcbReferences(string deviceId) public int ConnectedDeviceCount => _inner.ConnectedDeviceCount; public int MonitoringDeviceCount => _inner.MonitoringDeviceCount; + // Read-only association lifetime queries used by the Command Dock. + // The facade forwards authority; it never recreates a second flight gate. + public bool IsControlFlightUnavailable(string deviceId) + => _inner.IsControlFlightUnavailable(deviceId); + + public Guid GetControlAssociationId(string deviceId) + => _inner.GetControlAssociationId(deviceId); + + public bool IsControlAssociationCurrent(string deviceId, Guid associationId) + => _inner.IsControlAssociationCurrent(deviceId, associationId); + public Task ReadBrowserValuesAsync( Iec61850MonitorDevice device, IReadOnlyList targets, diff --git a/tests/ARSAS.Tests/F650CanonicalCommandFailureTests.cs b/tests/ARSAS.Tests/F650CanonicalCommandFailureTests.cs index 8b8e1f9fd..145f96bae 100644 --- a/tests/ARSAS.Tests/F650CanonicalCommandFailureTests.cs +++ b/tests/ARSAS.Tests/F650CanonicalCommandFailureTests.cs @@ -110,8 +110,9 @@ public void ProducersAndDispatcher_EnforceCanonicalIdentity() Assert.Contains("DistinctSelected(Signals)", model, StringComparison.Ordinal); Assert.Contains("ControlSupportsOperate", model, StringComparison.Ordinal); var runtime = Read("Services/Iec61850MonitorRuntime.cs"); - Assert.Contains("_activeControlTargets.TryAdd(targetKey, 0)", runtime, StringComparison.Ordinal); - Assert.Contains("_activeControlTargets.TryRemove(targetKey, out _)", runtime, StringComparison.Ordinal); + Assert.Contains("session.ControlFlight.TryEnter()", runtime, StringComparison.Ordinal); + Assert.Contains("session.ControlFlight.Release()", runtime, StringComparison.Ordinal); + Assert.DoesNotContain("_activeControlTargets", runtime, StringComparison.Ordinal); Assert.Contains("CONTROL_FAILURE_CLASSIFIED", runtime, StringComparison.Ordinal); } diff --git a/tests/ARSAS.Tests/F650CommandShoutIntegrationTests.cs b/tests/ARSAS.Tests/F650CommandShoutIntegrationTests.cs index de6f36d71..90e3a29bd 100644 --- a/tests/ARSAS.Tests/F650CommandShoutIntegrationTests.cs +++ b/tests/ARSAS.Tests/F650CommandShoutIntegrationTests.cs @@ -224,8 +224,9 @@ public void IdentityProjection_AndSingleFlightProtection_StillActive() var runtime = Read("Services/Iec61850MonitorRuntime.cs"); Assert.Contains("Iec61850ControlIdentity.DistinctSelected(Signals)", model, StringComparison.Ordinal); Assert.Contains("ControlSupportsOperate", model, StringComparison.Ordinal); - Assert.Contains("_activeControlTargets.TryAdd(targetKey, 0)", runtime, StringComparison.Ordinal); - Assert.Contains("_activeControlTargets.TryRemove(targetKey, out _)", runtime, StringComparison.Ordinal); + Assert.Contains("session.ControlFlight.TryEnter()", runtime, StringComparison.Ordinal); + Assert.Contains("session.ControlFlight.Release()", runtime, StringComparison.Ordinal); + Assert.DoesNotContain("_activeControlTargets", runtime, StringComparison.Ordinal); } private static string Read(string path) @@ -239,4 +240,15 @@ private static string Read(string path) } throw new FileNotFoundException(path); } + + [Fact] + public void UncertainWireOutcomeMustNeverBeLabelledCommandNotSent() + { + var notice = Iec61850ControlShout.FromUnknownWireOutcome(); + Assert.Equal("Command outcome UNKNOWN", notice.Title); + Assert.Equal(Iec61850ControlNoticeTone.Warning, notice.Tone); + Assert.Contains("Verify actual IED state", notice.Detail, StringComparison.Ordinal); + Assert.DoesNotContain("not sent", notice.Detail, StringComparison.OrdinalIgnoreCase); + } + } diff --git a/tests/ARSAS.Tests/M217P0ControlSingleFlightRecoveryTests.cs b/tests/ARSAS.Tests/M217P0ControlSingleFlightRecoveryTests.cs index af0cf62b8..b647a5324 100644 --- a/tests/ARSAS.Tests/M217P0ControlSingleFlightRecoveryTests.cs +++ b/tests/ARSAS.Tests/M217P0ControlSingleFlightRecoveryTests.cs @@ -1,4 +1,5 @@ using System.Threading; +using ArIED61850Tester.Models; using ArIED61850Tester.Services; namespace ARSAS.Tests; @@ -82,7 +83,15 @@ public void RuntimeDoesNotConfuseWaitTimeoutWithNativeOperationCompletion() Assert.Contains("ObserveLateControlFlightAsync(", code); Assert.Contains("CONTROL_OUTCOME_UNKNOWN_TIMEOUT", code); Assert.Contains("CONTROL_IED_SINGLE_FLIGHT", code); - Assert.Contains("Iec61850ControlFlightAdmission.TryEnter(", code); + Assert.Contains("session.ControlFlight.TryEnter()", code); + Assert.Contains("session.ControlFlight.Retire()", code); + Assert.Contains("CONTROL_OUTCOME_UNKNOWN_NATIVE_RESULT", code); + Assert.Contains("CONTROL_ATTEMPT_ADMITTED", code); + Assert.Contains("CONTROL_NATIVE_TASK_STARTED", code); + Assert.Contains("attemptId={attemptId}", code); + Assert.Contains("DisposeDetachedSessionAfterDrainAsync(", code); + Assert.Contains("if (!IsCurrentSession(session))", code); + Assert.DoesNotContain("_activeControlTargets", code); } [Fact] @@ -100,4 +109,136 @@ public void BrowserMustRejectNewConfirmationBeforeClaimingPhysicalCommand() Assert.Contains("CONTROL_UI_TIMEOUT", code); Assert.Contains("Control outcome UNKNOWN", code); } + + [Fact] + public async Task RetiredAssociationWaitsForActualNativeRelease() + { + var oldAssociation = new Iec61850ControlSessionLease(); + Assert.True(oldAssociation.TryEnter()); + var retirementToken = oldAssociation.RetirementToken; + Assert.False(retirementToken.IsCancellationRequested); + var drain = oldAssociation.Retire(); + Assert.True(retirementToken.IsCancellationRequested); + Assert.False(drain.IsCompleted); + Assert.True(oldAssociation.IsUnavailable); + Assert.True(oldAssociation.IsActive); + Assert.False(oldAssociation.TryEnter()); + + // A new socket has an independent lease even for the same deviceId/CSWI. + var newAssociation = new Iec61850ControlSessionLease(); + Assert.True(newAssociation.TryEnter()); + oldAssociation.Release(); + await drain.WaitAsync(TimeSpan.FromSeconds(1)); + Assert.True(newAssociation.IsActive); + Assert.False(oldAssociation.TryEnter()); + newAssociation.Release(); + } + + [Fact] + public void RetirementIsAtomicAgainstConcurrentAdmission() + { + for (var iteration = 0; iteration < 100; iteration++) + { + var oldAssociation = new Iec61850ControlSessionLease(); + var contenders = new Task[8]; + // Once Retire returns, no further physical admission is possible. + var drain = oldAssociation.Retire(); + Assert.True(drain.IsCompleted); + for (var i = 0; i < contenders.Length; i++) + contenders[i] = Task.Run(() => + Assert.False(oldAssociation.TryEnter())); + Task.WaitAll(contenders); + } + } + + [Fact] + public void LateCompletionNeverClearsUnknownWireQuarantine() + { + var lease = new Iec61850ControlSessionLease(); + Assert.True(lease.TryEnter()); + lease.Quarantine(); + lease.Release(); + Assert.True(lease.IsUnavailable); + Assert.False(lease.TryEnter()); + } + + [Theory] + [InlineData("WireStateUnknown")] + [InlineData("TimedOut")] + [InlineData("MmsTimeout")] + [InlineData("AssociationLost")] + [InlineData("Cancelled")] + public void NativeCompletedButUncertainOutcomeRequiresQuarantine(string state) + { + Assert.True(Iec61850ControlWireOutcomePolicy.RequiresQuarantine(state)); + Assert.False(Iec61850ControlWireOutcomePolicy.RequiresQuarantine("NotSent")); + Assert.False(Iec61850ControlWireOutcomePolicy.RequiresQuarantine("Rejected")); + Assert.False(Iec61850ControlWireOutcomePolicy.RequiresQuarantine("Completed")); + } + + [Fact] + public void BrowserDiscardsResultFromRetiredControlAssociation() + { + DirectoryInfo? root = new(AppContext.BaseDirectory); + while (root is not null && + !File.Exists(Path.Combine(root.FullName, "MainWindow.xaml.cs"))) + root = root.Parent; + Assert.NotNull(root); + var code = File.ReadAllText(Path.Combine(root!.FullName, "MainWindow.xaml.cs")); + Assert.Contains("GetControlAssociationId(device.DeviceId)", code); + Assert.Contains("IsControlAssociationCurrent(device.DeviceId, dispatchedAssociation)", code); + Assert.Contains("CONTROL_STALE_RESULT_IGNORED", code); + } + + + [Fact] + public void NativeFlightSnapshotNeverSharesMutableGuiSignal() + { + var shared = new SignalDefinition + { + Name = "CSWI6 Position", + ObjectReference = "BCUGE/CSWI6.Pos", + IsControlSignal = true, + ControlCdc = "DPC", + ControlStatusReference = "BCUGE/CSWI6.Pos.stVal", + ControlValueType = "Dbpos", + ControlModelText = "Direct normal", + ControlCurrentValue = "Open [01]", + ControlSemanticVerified = true + }; + shared.AcceptVerifiedLiveControlCdc("DPC"); + var original = new Iec61850ControlCommandRequest + { + Signal = shared, + ValueText = "Closed [10]", + InterlockCheck = false, + SynchroCheck = true, + TestMode = true, + Originator = "ARSAS test", + OriginCategory = "StationControl", + FeedbackTimeoutMs = 9000, + CommandTerminationTimeoutMs = 7000 + }; + var originalDisplay = shared.ControlCurrentValue; + var detached = Iec61850ControlRequestSnapshot.Create(original); + Assert.NotSame(shared, detached.Signal); + Assert.Equal(shared.ObjectReference, detached.Signal.ObjectReference); + Assert.Equal(shared.ControlStatusReference, detached.Signal.ControlStatusReference); + Assert.Equal("DPC", detached.Signal.VerifiedLiveControlCdc); + Assert.Equal(original.ValueText, detached.ValueText); + Assert.Equal(original.InterlockCheck, detached.InterlockCheck); + Assert.Equal(original.SynchroCheck, detached.SynchroCheck); + Assert.Equal(original.TestMode, detached.TestMode); + Assert.Equal(original.Originator, detached.Originator); + Assert.Equal(original.OriginCategory, detached.OriginCategory); + Assert.Equal(original.FeedbackTimeoutMs, detached.FeedbackTimeoutMs); + Assert.Equal(original.CommandTerminationTimeoutMs, detached.CommandTerminationTimeoutMs); + + // Simulate a late native reply after the caller retired old MMS state. + detached.Signal.ControlCurrentValue = "Closed [10]"; + detached.Signal.ControlSemanticVerified = false; + Assert.Equal(originalDisplay, shared.ControlCurrentValue); + Assert.True(shared.ControlSemanticVerified); + } + } diff --git a/tests/ARSAS.Tests/P109QCommandDockCommissioningRegressionTests.cs b/tests/ARSAS.Tests/P109QCommandDockCommissioningRegressionTests.cs index 4454a5327..e81a48892 100644 --- a/tests/ARSAS.Tests/P109QCommandDockCommissioningRegressionTests.cs +++ b/tests/ARSAS.Tests/P109QCommandDockCommissioningRegressionTests.cs @@ -172,10 +172,11 @@ public void OnlyEngineOwnsSingleControlModelWriteAndInvalidatesOldDescriptor() Assert.Contains("signal.ClearLiveControlAuthority();", client); Assert.Contains("signal.ControlModelText = \"Auto-detect\";", client); Assert.Contains("OPERATOR_CTL_MODEL_CONFIGURATION", runtime); - Assert.Contains("_activeControlTargets.TryAdd(targetKey, 0)", runtime); - // A single atomic IED-wide flight now protects ctlModel Write and - // ordinary Operate. Increment-and-reject was not a safe admission gate. - Assert.Contains("Iec61850ControlFlightAdmission.TryEnter(", runtime); + // A physical association-scoped lease covers both ctlModel Write and + // Operate. A detached old session must not unlock the new association. + Assert.Contains("session.ControlFlight.TryEnter()", runtime); + Assert.Contains("session.ControlFlight.Release()", runtime); + Assert.DoesNotContain("_activeControlTargets", runtime); Assert.Contains("CONTROL_OUTCOME_UNKNOWN_TIMEOUT", runtime); } }