From 4b1371568e4fc7cc4c5cc5e592fa6dccafe09e3b Mon Sep 17 00:00:00 2001 From: masarray Date: Mon, 13 Jul 2026 07:04:24 +0700 Subject: [PATCH 1/2] fix: filter CSWI close echo before value viewer --- MainWindow.ControlDiagnostics.cs | 335 +++++++++++++++++++------------ 1 file changed, 212 insertions(+), 123 deletions(-) diff --git a/MainWindow.ControlDiagnostics.cs b/MainWindow.ControlDiagnostics.cs index f8391dc07..999d6dc71 100644 --- a/MainWindow.ControlDiagnostics.cs +++ b/MainWindow.ControlDiagnostics.cs @@ -1,5 +1,5 @@ +using System.Collections.Concurrent; using System.ComponentModel; -using System.Globalization; using System.Text.RegularExpressions; using ArIED61850Tester.Models; @@ -7,34 +7,37 @@ namespace ArIED61850Tester; public partial class MainWindow { - private const double ImmediatePositionFeedbackEchoThresholdMs = 150d; - private static readonly TimeSpan StableFeedbackGuardWindow = TimeSpan.FromMilliseconds(750); - private static readonly TimeSpan StableFeedbackStateLifetime = TimeSpan.FromSeconds(15); + private static readonly TimeSpan CswiCloseDebounce = TimeSpan.FromMilliseconds(350); + private static readonly TimeSpan ControlFeedbackStateLifetime = TimeSpan.FromSeconds(15); private static readonly Regex ControlRequestedPattern = new( @"Control requested:\s*(?.+?)\s+value=(?[^;]+);", RegexOptions.Compiled | RegexOptions.CultureInvariant | RegexOptions.IgnoreCase); - private static readonly Regex ControlFeedbackPattern = new( - @"Control Feedback confirmed:\s*(?[^;]+);.*?requested=(?[^;]+);\s*feedback=(?[^;]+);.*?\bfeedback=(?\d+(?:[\.,]\d+)?)\s*ms(?:;|$)", - RegexOptions.Compiled | RegexOptions.CultureInvariant | RegexOptions.IgnoreCase); + private sealed class PendingCswiCloseSnapshot + { + public required Iec61850PointSnapshot Latest { get; set; } + public CancellationTokenSource Cancellation { get; } = new(); + public object Sync { get; } = new(); + } - private sealed class ControlFeedbackStabilityState + private sealed class ActivePositionCloseCommand { public required string Key { get; init; } - public required string Reference { get; init; } public required SignalDefinition Signal { get; init; } public required string BeforeValue { get; init; } - public required string RequestedValue { get; set; } public DateTimeOffset StartedUtc { get; init; } = DateTimeOffset.UtcNow; - public DateTimeOffset? EchoSuppressedAtUtc { get; set; } - public bool SuppressImmediateTarget { get; set; } - public bool SawNonTargetAfterEcho { get; set; } public bool Restoring { get; set; } public PropertyChangedEventHandler? PropertyChangedHandler { get; set; } } - private readonly Dictionary _controlFeedbackStability = + private readonly ConcurrentDictionary _pendingCswiCloseSnapshots = + new(StringComparer.OrdinalIgnoreCase); + + private readonly ConcurrentDictionary _stableClosedPositionReferences = + new(StringComparer.OrdinalIgnoreCase); + + private readonly Dictionary _activePositionCloseCommands = new(StringComparer.OrdinalIgnoreCase); private bool _controlDiagnosticNormalizerInstalled; @@ -47,18 +50,100 @@ protected override void OnContentRendered(EventArgs e) _controlDiagnosticNormalizerInstalled = true; - // The native Smart Control service deliberately rejects ctlModel=StatusOnly - // when asked to open an executable command session. For the explorer this is - // valid live-model information, not a communication failure. Replace the - // original diagnostic subscriber after the window is ready so status-only - // objects do not raise a red application error. + // Keep the normal runtime batching path, but filter the short CSWI Close pulse + // before it reaches the Value Viewer or command-row feedback binding. + _runtime.PointUpdated -= Runtime_PointUpdated; + _runtime.PointUpdated += Runtime_PointUpdatedWithStablePositionFilter; + + // ctlModel=StatusOnly is valid read-only model information, not a transport fault. _runtime.Diagnostic -= Runtime_Diagnostic; _runtime.Diagnostic += Runtime_DiagnosticWithControlModelClassification; } + private void Runtime_PointUpdatedWithStablePositionFilter(Iec61850PointSnapshot snapshot) + { + var reference = snapshot.Point.IecReference; + if (!IsPositionStatusReference(reference)) + { + Runtime_PointUpdated(snapshot); + return; + } + + var key = NormalizeReference(reference); + var value = NormalizeControlState(snapshot.Value); + + if (!value.Equals("Closed", StringComparison.OrdinalIgnoreCase)) + { + _stableClosedPositionReferences.TryRemove(key, out _); + CancelPendingCswiClose(key); + Runtime_PointUpdated(snapshot); + return; + } + + // XCBR/XSWI position is equipment feedback and remains immediate. Only CSWI.Pos + // is debounced because this relay exposes a short command-object Close echo there. + if (!IsCswiPositionStatusReference(reference)) + { + _stableClosedPositionReferences[key] = DateTimeOffset.UtcNow; + Runtime_PointUpdated(snapshot); + return; + } + + if (_pendingCswiCloseSnapshots.TryGetValue(key, out var existing)) + { + lock (existing.Sync) + existing.Latest = snapshot; + return; + } + + var pending = new PendingCswiCloseSnapshot { Latest = snapshot }; + if (!_pendingCswiCloseSnapshots.TryAdd(key, pending)) + { + if (_pendingCswiCloseSnapshots.TryGetValue(key, out existing)) + { + lock (existing.Sync) + existing.Latest = snapshot; + } + return; + } + + _ = ReleaseStableCswiCloseAsync(key, pending); + } + + private async Task ReleaseStableCswiCloseAsync(string key, PendingCswiCloseSnapshot pending) + { + try + { + await Task.Delay(CswiCloseDebounce, pending.Cancellation.Token).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + return; + } + + if (!_pendingCswiCloseSnapshots.TryRemove(key, out var active) || !ReferenceEquals(active, pending)) + return; + + Iec61850PointSnapshot stableSnapshot; + lock (pending.Sync) + stableSnapshot = pending.Latest; + + _stableClosedPositionReferences[key] = DateTimeOffset.UtcNow; + Runtime_PointUpdated(stableSnapshot); + } + + private void CancelPendingCswiClose(string key) + { + if (!_pendingCswiCloseSnapshots.TryRemove(key, out var pending)) + return; + + pending.Cancellation.Cancel(); + pending.Cancellation.Dispose(); + } + private void Runtime_DiagnosticWithControlModelClassification(DiagnosticEntry entry) { - ObserveControlFeedbackDiagnostic(entry); + ObserveControlRequest(entry.Message); if (IsStatusOnlyControlInspection(entry.Message)) { @@ -87,140 +172,115 @@ private void Runtime_DiagnosticWithControlModelClassification(DiagnosticEntry en Runtime_Diagnostic(entry); } - private void ObserveControlFeedbackDiagnostic(DiagnosticEntry entry) + private void ObserveControlRequest(string? message) { - var message = entry.Message ?? string.Empty; - if (message.Length == 0 || Dispatcher.HasShutdownStarted) + if (string.IsNullOrWhiteSpace(message) || Dispatcher.HasShutdownStarted) return; - var requested = ControlRequestedPattern.Match(message); - if (requested.Success) - { - _ = Dispatcher.InvokeAsync(() => BeginControlFeedbackStability( - requested.Groups["reference"].Value, - requested.Groups["value"].Value)); + var match = ControlRequestedPattern.Match(message); + if (!match.Success) return; - } - var feedback = ControlFeedbackPattern.Match(message); - if (!feedback.Success) + var requestedValue = NormalizeControlState(match.Groups["value"].Value); + if (!requestedValue.Equals("Closed", StringComparison.OrdinalIgnoreCase)) return; - _ = Dispatcher.InvokeAsync(() => ClassifyImmediateControlFeedback( - feedback.Groups["reference"].Value, - feedback.Groups["requested"].Value, - feedback.Groups["feedbackValue"].Value, - feedback.Groups["feedbackMs"].Value)); + _ = Dispatcher.InvokeAsync(() => BeginPositionCloseCommand( + match.Groups["reference"].Value, + requestedValue)); } - private void BeginControlFeedbackStability(string reference, string requestedValue) + private void BeginPositionCloseCommand(string reference, string requestedValue) { var key = NormalizeReference(reference); var signal = FindCommandSignal(reference); - if (string.IsNullOrWhiteSpace(key) || signal == null) + if (string.IsNullOrWhiteSpace(key) || signal == null || !IsPositionCommand(signal) || + !requestedValue.Equals("Closed", StringComparison.OrdinalIgnoreCase)) + { return; + } - RemoveControlFeedbackStability(key); + RemovePositionCloseCommand(key); - var state = new ControlFeedbackStabilityState + var state = new ActivePositionCloseCommand { Key = key, - Reference = reference.Trim(), Signal = signal, - BeforeValue = NormalizeControlState(signal.ControlCurrentValue), - RequestedValue = NormalizeControlState(requestedValue) + BeforeValue = NormalizeControlState(signal.ControlCurrentValue) }; - PropertyChangedEventHandler handler = (_, args) => - { - if (args.PropertyName == nameof(SignalDefinition.ControlCurrentValue)) - HandleControlCurrentValueChanged(state); - }; + PropertyChangedEventHandler handler = (_, args) => HandlePositionCloseCommandPropertyChanged(state, args.PropertyName); state.PropertyChangedHandler = handler; signal.PropertyChanged += handler; - _controlFeedbackStability[key] = state; - _ = ExpireControlFeedbackStabilityAsync(state); - } - - private void ClassifyImmediateControlFeedback( - string reference, - string requestedValue, - string feedbackValue, - string feedbackMilliseconds) - { - var key = NormalizeReference(reference); - if (!_controlFeedbackStability.TryGetValue(key, out var state)) - { - BeginControlFeedbackStability(reference, requestedValue); - _controlFeedbackStability.TryGetValue(key, out state); - } - - if (state == null) - return; + _activePositionCloseCommands[key] = state; - state.RequestedValue = NormalizeControlState(requestedValue); - var observedValue = NormalizeControlState(feedbackValue); - var millisecondsText = feedbackMilliseconds.Replace(',', '.'); - if (!double.TryParse(millisecondsText, NumberStyles.Float, CultureInfo.InvariantCulture, out var elapsedMs)) - return; + // A previous Closed state must not authorize the new command result. Only a fresh + // live position sample arriving after this request may confirm the new Close. + var feedbackKey = ResolveControlFeedbackKey(signal); + if (!string.IsNullOrWhiteSpace(feedbackKey)) + _stableClosedPositionReferences.TryRemove(feedbackKey, out _); - // A position Close that is reported within only a few milliseconds is normally - // the CSWI command-object echo, not settled primary-equipment feedback. The live - // report/poll stream remains authoritative for the stable final state. Open is - // intentionally not delayed because this relay reports genuine Open feedback fast. - state.SuppressImmediateTarget = - IsPositionCommand(state.Signal) && - state.RequestedValue.Equals("Closed", StringComparison.OrdinalIgnoreCase) && - observedValue.Equals(state.RequestedValue, StringComparison.OrdinalIgnoreCase) && - !state.BeforeValue.Equals(state.RequestedValue, StringComparison.OrdinalIgnoreCase) && - elapsedMs <= ImmediatePositionFeedbackEchoThresholdMs; + _ = ExpirePositionCloseCommandAsync(state); } - private void HandleControlCurrentValueChanged(ControlFeedbackStabilityState state) + private void HandlePositionCloseCommandPropertyChanged(ActivePositionCloseCommand state, string? propertyName) { - if (state.Restoring || !_controlFeedbackStability.TryGetValue(state.Key, out var currentState) || - !ReferenceEquals(state, currentState)) + if (state.Restoring || !_activePositionCloseCommands.TryGetValue(state.Key, out var active) || + !ReferenceEquals(active, state)) { return; } - var currentValue = NormalizeControlState(state.Signal.ControlCurrentValue); - var isRequestedTarget = currentValue.Equals(state.RequestedValue, StringComparison.OrdinalIgnoreCase); - - if (!isRequestedTarget) + if (propertyName == nameof(SignalDefinition.ControlCurrentValue)) { - if (state.EchoSuppressedAtUtc.HasValue) - state.SawNonTargetAfterEcho = true; + var current = NormalizeControlState(state.Signal.ControlCurrentValue); + if (!current.Equals("Closed", StringComparison.OrdinalIgnoreCase)) + return; + + if (HasFreshStableCloseEvidence(state)) + { + RemovePositionCloseCommand(state.Key); + state.Signal.ControlLastResult = "Stable process feedback confirmed: Closed."; + return; + } + + RestorePreCommandValue(state); return; } - if (state.SuppressImmediateTarget) - { - state.SuppressImmediateTarget = false; - SuppressCommandObjectEcho(state); + if (propertyName != nameof(SignalDefinition.ControlLastResult)) return; - } - if (state.EchoSuppressedAtUtc.HasValue && - !state.SawNonTargetAfterEcho && - DateTimeOffset.UtcNow - state.EchoSuppressedAtUtc.Value < StableFeedbackGuardWindow) + var result = state.Signal.ControlLastResult ?? string.Empty; + if (IsControlFailureResult(result)) { - SuppressCommandObjectEcho(state); + RemovePositionCloseCommand(state.Key); return; } - CompleteStableControlFeedback(state, currentValue); + if (!HasFreshStableCloseEvidence(state) && + result.Contains("Feedback confirmed", StringComparison.OrdinalIgnoreCase) && + result.Contains("Closed", StringComparison.OrdinalIgnoreCase)) + { + state.Restoring = true; + try + { + state.Signal.ControlLastResult = "Command accepted — waiting for stable Closed process feedback…"; + } + finally + { + state.Restoring = false; + } + } } - private void SuppressCommandObjectEcho(ControlFeedbackStabilityState state) + private void RestorePreCommandValue(ActivePositionCloseCommand state) { - state.EchoSuppressedAtUtc ??= DateTimeOffset.UtcNow; state.Restoring = true; try { state.Signal.ControlCurrentValue = state.BeforeValue; - state.Signal.ControlLastResult = - $"Command accepted — waiting for stable {state.RequestedValue} process feedback…"; + state.Signal.ControlLastResult = "Command accepted — waiting for stable Closed process feedback…"; } finally { @@ -228,32 +288,36 @@ private void SuppressCommandObjectEcho(ControlFeedbackStabilityState state) } } - private void CompleteStableControlFeedback(ControlFeedbackStabilityState state, string currentValue) + private bool HasFreshStableCloseEvidence(ActivePositionCloseCommand state) + { + var feedbackKey = ResolveControlFeedbackKey(state.Signal); + return !string.IsNullOrWhiteSpace(feedbackKey) && + _stableClosedPositionReferences.TryGetValue(feedbackKey, out var observedUtc) && + observedUtc >= state.StartedUtc; + } + + private static string ResolveControlFeedbackKey(SignalDefinition signal) { - var hadSuppressedEcho = state.EchoSuppressedAtUtc.HasValue; - RemoveControlFeedbackStability(state.Key); - if (hadSuppressedEcho) - state.Signal.ControlLastResult = $"Stable process feedback confirmed: {currentValue}."; + var reference = string.IsNullOrWhiteSpace(signal.ControlStatusReference) + ? $"{signal.ObjectReference}.stVal" + : signal.ControlStatusReference; + return NormalizeReference(reference); } - private async Task ExpireControlFeedbackStabilityAsync(ControlFeedbackStabilityState state) + private async Task ExpirePositionCloseCommandAsync(ActivePositionCloseCommand state) { - await Task.Delay(StableFeedbackStateLifetime).ConfigureAwait(false); + await Task.Delay(ControlFeedbackStateLifetime).ConfigureAwait(false); if (Dispatcher.HasShutdownStarted) return; await Dispatcher.InvokeAsync(() => { - if (!_controlFeedbackStability.TryGetValue(state.Key, out var active) || !ReferenceEquals(active, state)) + if (!_activePositionCloseCommands.TryGetValue(state.Key, out var active) || !ReferenceEquals(active, state)) return; - var hadSuppressedEcho = state.EchoSuppressedAtUtc.HasValue; - RemoveControlFeedbackStability(state.Key); - if (hadSuppressedEcho) - { - state.Signal.ControlLastResult = - $"Command accepted, but stable {state.RequestedValue} process feedback was not confirmed within {StableFeedbackStateLifetime.TotalSeconds:0} s."; - } + RemovePositionCloseCommand(state.Key); + state.Signal.ControlLastResult = + $"Command accepted, but stable Closed process feedback was not confirmed within {ControlFeedbackStateLifetime.TotalSeconds:0} s."; }); } @@ -266,9 +330,9 @@ await Dispatcher.InvokeAsync(() => .Equals(normalized, StringComparison.OrdinalIgnoreCase)); } - private void RemoveControlFeedbackStability(string key) + private void RemovePositionCloseCommand(string key) { - if (!_controlFeedbackStability.Remove(key, out var state)) + if (!_activePositionCloseCommands.Remove(key, out var state)) return; if (state.PropertyChangedHandler != null) @@ -281,6 +345,31 @@ private static bool IsPositionCommand(SignalDefinition signal) return reference.EndsWith(".Pos", StringComparison.OrdinalIgnoreCase); } + private static bool IsPositionStatusReference(string? reference) + { + var normalized = (reference ?? string.Empty).Trim().Replace('$', '.').TrimEnd('.'); + return normalized.EndsWith(".Pos.stVal", StringComparison.OrdinalIgnoreCase); + } + + private static bool IsCswiPositionStatusReference(string? reference) + { + var normalized = (reference ?? string.Empty).Trim().Replace('$', '.'); + if (!normalized.EndsWith(".Pos.stVal", StringComparison.OrdinalIgnoreCase)) + return false; + + var slash = normalized.LastIndexOf('/'); + var afterSlash = slash >= 0 ? normalized[(slash + 1)..] : normalized; + var dot = afterSlash.IndexOf('.'); + var logicalNode = dot > 0 ? afterSlash[..dot] : afterSlash; + return logicalNode.Contains("CSWI", StringComparison.OrdinalIgnoreCase); + } + + private static bool IsControlFailureResult(string result) + => result.Contains("failed", StringComparison.OrdinalIgnoreCase) || + result.Contains("rejected", StringComparison.OrdinalIgnoreCase) || + result.Contains("cancelled", StringComparison.OrdinalIgnoreCase) || + result.Contains("unsupported", StringComparison.OrdinalIgnoreCase); + private static string NormalizeControlState(string? value) { var text = string.IsNullOrWhiteSpace(value) ? "-" : value.Trim(); From 64aa083bc855817c84f086fb050004b860e9e4b4 Mon Sep 17 00:00:00 2001 From: masarray Date: Mon, 13 Jul 2026 07:04:46 +0700 Subject: [PATCH 2/2] docs: correct close-feedback filtering strategy --- STABLE_CLOSE_FEEDBACK_AUDIT.md | 39 +++++++++++++++++++++------------- 1 file changed, 24 insertions(+), 15 deletions(-) diff --git a/STABLE_CLOSE_FEEDBACK_AUDIT.md b/STABLE_CLOSE_FEEDBACK_AUDIT.md index 72d74de2e..4e9f7f3fe 100644 --- a/STABLE_CLOSE_FEEDBACK_AUDIT.md +++ b/STABLE_CLOSE_FEEDBACK_AUDIT.md @@ -13,21 +13,28 @@ This matches the observed screen sequence: a very short Closed indication, a ret ## Root cause -`CSWI1.Pos` is both the command object and a status-bearing object. Immediately after `SBOw → Operate → CommandTermination`, the relay can expose a short command-object echo matching the requested value before the stable process/equipment status settles. The previous UI accepted the first matching value as final feedback. +`CSWI1.Pos` is both the command object and a status-bearing object. Immediately after `SBOw → Operate → CommandTermination`, the relay can expose a short command-object echo matching the requested value before the stable process/equipment status settles. The `0.908 ms` feedback result is therefore not credible as mechanical breaker travel. Positive CommandTermination proves that the enhanced-security command completed; it does not prove that the primary-equipment position has already settled. -## Fix +## Why the first workaround made it worse -For position Close commands only: +The first workaround classified the echo only after the control-result diagnostic was emitted. By then the Closed value had already entered the normal WPF point-update queue. The command row also retained a deferred Closed value while `ControlIsBusy=true`, so that optimistic value could be published again when the command completed and remain visible until the next real live update. -1. Detect a matching feedback sample reported within 150 ms. -2. Treat that first sample as a possible CSWI command-object echo. -3. Keep the last stable position visible and show `waiting for stable Closed process feedback`. -4. Accept the requested state after either: - - a non-target sample followed by the final target state; or - - the target remains present beyond a 750 ms guard window. -5. Time out the UI stability state after 15 seconds without issuing any retry or second command. +That implementation reacted too late and operated only on the command-row model. It did not stop the transient sample before the main Value Viewer. + +## Corrected fix + +The correction now works at the source of the UI update: + +1. Replace the normal `PointUpdated` subscriber with a thin stability filter before snapshots enter the 100 ms Value Viewer batch. +2. Keep Open, Intermediate, Bad, XCBR, and XSWI position updates immediate. +3. Debounce only `CSWI*.Pos.stVal = Closed` for 350 ms. +4. Cancel the pending Closed snapshot immediately when Open/non-Closed follows, so the short command echo never reaches the Value Viewer. +5. Mark a Close as stable only after the debounce survives. +6. Suppress direct command-result Closed assignments until that fresh stable live-position evidence exists. +7. Keep the last real state visible and show `Command accepted — waiting for stable Closed process feedback…`. +8. Expire the waiting state after 15 seconds without issuing any retry or second command. Open is intentionally not delayed because the relay's Open movement and feedback are genuinely fast. @@ -36,11 +43,13 @@ Open is intentionally not delayed because the relay's Open movement and feedback - No automatic command retry. - No second Select/SBOw or Operate. - No change to ctlNum, origin, Test, Check, interlock, synchrocheck, or CommandTermination handling. -- The change is display/feedback stabilization only; the ARIEC61850 control sequence remains authoritative. +- Raw Event Log/SOE remains available; only the live Value Viewer and command-row presentation reject the short CSWI command echo. +- The ARIEC61850 command sequence remains authoritative. ## Live retest -- Open: value should change quickly without added guard delay. -- Close: the row should remain Open/Closing while the process is moving; it must not flash Closed for about 100 ms. -- Final Closed should appear when the stable report/poll value arrives, expected around four seconds on this OLSF501 configuration. -- Diagnostics should still show positive CommandTermination separately from stable process feedback. +- Open: value changes quickly without added guard delay. +- Close: the Value Viewer and command row remain Open while the short CSWI echo occurs. +- Final Closed appears after the real stable report/poll value arrives, expected around four seconds on this OLSF501 configuration, plus only the 350 ms stability window. +- XCBR/XSWI equipment-position updates are not delayed. +- Diagnostics continue to show CommandTermination separately from stable process feedback.