From c85d4e20db722bd0c2729f2533b323b13d3ef735 Mon Sep 17 00:00:00 2001 From: Ari Sulistiono Date: Tue, 20 Oct 2026 13:35:19 +0700 Subject: [PATCH] fix: isolate RCB reports from control indications and expose control stage timing --- CHANGELOG.md | 6 +++ .../Control/Iec61850ControlObjectSession.cs | 31 +++++++++--- .../Mms/MmsPersistentReportMonitor.cs | 11 +++++ .../Control/G1OrderedWireEvidenceTests.cs | 8 ++++ .../Mms/MmsPersistentReportRoutingTests.cs | 47 +++++++++++++++++++ 5 files changed, 97 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 61a1089e..2895c155 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Control/report isolation trial — 2026-10-20 + +- Reject non-RCB InformationReport shapes before persistent single-monitor fallback; control termination and LastApplError remain available to independent control subscribers. +- Include monotonic service duration and post-response wait in each control wire-step detail. UTC marks local service start, not wire send. This separates SBOw/Operate service latency from asynchronous completion wait without changing timeout, checks, or command sequencing. +- Synthetic regression coverage added; physical latency improvement is not yet established. + All notable public changes to ARIEC61850 are recorded here. The project is still evolving toward stable semantic releases; entries are grouped by engineering milestone until a formal versioning policy is adopted. ## Unreleased — public wording, provenance and release assurance diff --git a/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs b/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs index 9550388e..1018c50b 100644 --- a/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs +++ b/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs @@ -27,6 +27,10 @@ private sealed class AssociationControlState private CancellationTokenSource? _selectionLeaseCts; private bool _ownsLock; private bool _disposed; + private DateTimeOffset _serviceStartedUtc; + private TimeSpan _serviceElapsed; + private long _serviceCompletedTimestamp; + internal Iec61850ControlObjectSession( IIec61850ControlTransport transport, @@ -115,7 +119,7 @@ private async Task SelectCoreAsync( try { var context = CreateContext(request); - var read = await _transport.ReadAsync(Descriptor.References.Sbo, cancellationToken).ConfigureAwait(false); + var read = await MeasureServiceAsync(() => _transport.ReadAsync(Descriptor.References.Sbo, cancellationToken)).ConfigureAwait(false); if (!read.IsSuccess || !IsPositiveSboSelection(read.Value, Descriptor.References)) { ReleaseObject(); @@ -172,7 +176,7 @@ private async Task SelectWithValueCoreAsync( context, Descriptor.SelectWithValueSpecification, _options.RequireExactNamedControlFields); - var write = await _transport.WriteControlAsync(Descriptor.References.SboWithValue, value, cancellationToken).ConfigureAwait(false); + var write = await MeasureServiceAsync(() => _transport.WriteControlAsync(Descriptor.References.SboWithValue, value, cancellationToken)).ConfigureAwait(false); if (!write.IsSuccess) { var appError = await WaitForApplicationErrorAsync(_options.ApplicationErrorGracePeriod, cancellationToken, reports).ConfigureAwait(false); @@ -289,7 +293,7 @@ private async Task OperateCoreAsync( context, Descriptor.OperSpecification, _options.RequireExactNamedControlFields); - var write = await _transport.WriteControlAsync(Descriptor.References.Oper, operValue, linked.Token).ConfigureAwait(false); + var write = await MeasureServiceAsync(() => _transport.WriteControlAsync(Descriptor.References.Oper, operValue, linked.Token)).ConfigureAwait(false); if (!write.IsSuccess) { var applicationError = await WaitForApplicationErrorAsync(_options.ApplicationErrorGracePeriod, cancellationToken, reports).ConfigureAwait(false); @@ -432,7 +436,7 @@ private async Task CancelCoreAsync(CancellationToke return Unsupported(Iec61850ControlAction.Cancel, "IED did not expose a decodable Cancel type specification."); var value = Iec61850ControlStructureBuilder.BuildCancel(context, Descriptor.CancelSpecification, _options.RequireExactNamedControlFields); - var write = await _transport.WriteControlAsync(Descriptor.References.Cancel, value, cancellationToken).ConfigureAwait(false); + var write = await MeasureServiceAsync(() => _transport.WriteControlAsync(Descriptor.References.Cancel, value, cancellationToken)).ConfigureAwait(false); return write.IsSuccess ? Accepted(Iec61850ControlAction.Cancel, context, stopwatch.Elapsed, "Cancel accepted; local SBO ownership released.") : FromWriteFailure(Iec61850ControlAction.Cancel, write, null, context, stopwatch.Elapsed); @@ -691,7 +695,7 @@ private async Task BestEffortCancelAsync(CancellationToken cancellationToken) context, Descriptor.CancelSpecification, _options.RequireExactNamedControlFields); - await _transport.WriteControlAsync(Descriptor.References.Cancel, value, cancellationToken).ConfigureAwait(false); + await MeasureServiceAsync(() => _transport.WriteControlAsync(Descriptor.References.Cancel, value, cancellationToken)).ConfigureAwait(false); } } catch @@ -782,6 +786,20 @@ private Iec61850ControlActionResult FromApplicationRejection( BuildWireStep(action, requestAccepted: true, clientMessage)) }; + // Serialized by _operationGate. These are local service boundaries, not + // packet capture timestamps; elapsed measurement uses the monotonic clock. + private async Task MeasureServiceAsync(Func> service) + { + _serviceStartedUtc = DateTimeOffset.UtcNow; + var started = Stopwatch.GetTimestamp(); + try { return await service().ConfigureAwait(false); } + finally + { + _serviceElapsed = Stopwatch.GetElapsedTime(started); + _serviceCompletedTimestamp = Stopwatch.GetTimestamp(); + } + } + private Iec61850ControlWireStep BuildWireStep( Iec61850ControlAction action, bool requestAccepted, @@ -803,7 +821,8 @@ private Iec61850ControlWireStep BuildWireStep( RequestAccepted = requestAccepted, RequestHex = _transport.LastRequestHex, ResponseHex = _transport.LastResponseHex, - Detail = detail + Detail = FormattableString.Invariant( + $"{detail} serviceStartedUtc={_serviceStartedUtc:O}; serviceMs={_serviceElapsed.TotalMilliseconds:0.###}; postResponseWaitMs={Stopwatch.GetElapsedTime(_serviceCompletedTimestamp).TotalMilliseconds:0.###}; timingScope=local-service-not-wire") }; } diff --git a/src/AR.Iec61850/Mms/MmsPersistentReportMonitor.cs b/src/AR.Iec61850/Mms/MmsPersistentReportMonitor.cs index d5ec0490..387a415f 100644 --- a/src/AR.Iec61850/Mms/MmsPersistentReportMonitor.cs +++ b/src/AR.Iec61850/Mms/MmsPersistentReportMonitor.cs @@ -637,6 +637,12 @@ private void RoutePersistentInformationReport(byte[] payload) return; } + // Control termination / LastApplError use the same MMS service but are + // not RCB reports. Never feed them to the single-monitor fallback. + // Their independent control subscribers already received the envelope. + if (!HasRcbReportHeader(decoded)) + return; + var header = MmsReportFrameMapper.DecodeHeader(decoded); var active = SnapshotPersistentReportMonitors(); var target = SelectPersistentReportMonitor(active, header, out var evidence); @@ -655,6 +661,11 @@ private void RoutePersistentInformationReport(byte[] payload) $"Routed InformationReport to {target.ReportControl.Reference} by {evidence}. RptID={RoutingTextOrDash(header.ReportId)}, DatSet={RoutingTextOrDash(header.DataSetReference)}."; } + internal static bool HasRcbReportHeader(MmsInformationReport report) + => report.IsSuccess && report.Items.Count >= 2 && + report.Items[0].Value?.Kind is MmsDataKind.VisibleString or MmsDataKind.MmsString && + report.Items[1].Value?.Kind == MmsDataKind.BitString; + internal static MmsPersistentReportMonitorSession? SelectPersistentReportMonitor( IReadOnlyList active, MmsReportHeader header, diff --git a/tests/AR.Iec61850.Tests/Control/G1OrderedWireEvidenceTests.cs b/tests/AR.Iec61850.Tests/Control/G1OrderedWireEvidenceTests.cs index 856f2397..6482b3ee 100644 --- a/tests/AR.Iec61850.Tests/Control/G1OrderedWireEvidenceTests.cs +++ b/tests/AR.Iec61850.Tests/Control/G1OrderedWireEvidenceTests.cs @@ -69,6 +69,14 @@ public async Task SboEnhanced_PositiveTermination_PreservesSboWThenOperateWireSt Assert.True(result.WireSteps[1].RequestAccepted); Assert.Contains("positive CommandTermination", result.WireSteps[1].Detail, StringComparison.OrdinalIgnoreCase); + foreach (var step in result.WireSteps) + { + Assert.Contains("serviceStartedUtc=", step.Detail); + Assert.Contains("serviceMs=", step.Detail); + Assert.Contains("postResponseWaitMs=", step.Detail); + Assert.Contains("timingScope=local-service-not-wire", step.Detail); + } + Assert.Equal(2, transport.Writes.Count); Assert.EndsWith("$SBOw", transport.Writes[0].Reference.Item, StringComparison.Ordinal); Assert.EndsWith("$Oper", transport.Writes[1].Reference.Item, StringComparison.Ordinal); diff --git a/tests/AR.Iec61850.Tests/Mms/MmsPersistentReportRoutingTests.cs b/tests/AR.Iec61850.Tests/Mms/MmsPersistentReportRoutingTests.cs index 2fccfc4b..34f7494c 100644 --- a/tests/AR.Iec61850.Tests/Mms/MmsPersistentReportRoutingTests.cs +++ b/tests/AR.Iec61850.Tests/Mms/MmsPersistentReportRoutingTests.cs @@ -4,6 +4,53 @@ namespace AR.Iec61850.Tests.Mms; public sealed class MmsPersistentReportRoutingTests { + // Synthetic typed MMS evidence: no external packet capture or station data. + [Fact] + public void ControlInformationReportsCannotEnterSingleRcbFallback() + { + foreach (var value in new[] + { + MmsDataValue.Boolean(true), + MmsDataValue.Structure(new[] { MmsDataValue.VisibleString("LD0/CSWI1$CO$Pos$Oper"), MmsDataValue.Integer(0) }) + }) + { + var report = new MmsInformationReport + { + IsSuccess = true, + VariableReferences = new[] { "LD0/CSWI1$CO$Pos$Oper" }, + Items = new[] { new MmsInformationReportItem { Value = value } } + }; + Assert.False(MmsClientSession.HasRcbReportHeader(report)); + } + } + + [Fact] + public void RcbHeaderDoesNotRequireOptionalSequenceOrDatasetFields() + { + var report = new MmsInformationReport + { + IsSuccess = true, + Items = new[] + { + new MmsInformationReportItem { Value = MmsDataValue.VisibleString("RPT_A") }, + new MmsInformationReportItem { Value = MmsDataValue.BitString(6, new byte[] { 0, 0 }) }, + new MmsInformationReportItem { Value = MmsDataValue.BitString(7, new byte[] { 0x80 }) }, + new MmsInformationReportItem { Value = MmsDataValue.Boolean(true) } + } + }; + Assert.True(MmsClientSession.HasRcbReportHeader(report)); + Assert.False(MmsClientSession.HasRcbReportHeader(new MmsInformationReport())); + Assert.False(MmsClientSession.HasRcbReportHeader(new MmsInformationReport + { + IsSuccess = true, + Items = new[] + { + new MmsInformationReportItem { Value = MmsDataValue.Boolean(true) }, + new MmsInformationReportItem { Value = MmsDataValue.BitString(6, new byte[] { 0, 0 }) } + } + })); + } + [Fact] public void Selector_RoutesByExactReportIdBeforeDataSetProjection() {