From 5ef27fd9a364df3bcc38dbbdb0317fb8ad155f80 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 14:17:53 -0500 Subject: [PATCH] feat(telemetry): deploy-failure, S&F activity, script-run and DCL-transition instruments (ScadaBridge#81) Adds four instruments on the already-allow-listed ZB.MOM.WW.ScadaBridge meter: scadabridge.deployments.failed{reason}, scadabridge.store_and_forward.activity{action,category}, scadabridge.site.script.runs{outcome} + scadabridge.site.script.duration{outcome} (ms), scadabridge.site.data_connections.transitions{state}. Queue depth, DCL connection state and deploy-applied already existed. No new Meter, so ZbTelemetryOptions.Meters needs no change. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- .../Observability/ScadaBridgeTelemetry.cs | 73 ++++++++++++++ .../DeploymentService.cs | 6 ++ .../Scripts/ScriptRunSummaryRecorder.cs | 4 + .../StoreAndForwardService.cs | 2 + .../Observability/ExtendedInstrumentTests.cs | 98 +++++++++++++++++++ .../DeploymentServiceTests.cs | 39 ++++++++ .../Scripts/ScriptRunSummaryRecorderTests.cs | 42 ++++++++ .../QueueDepthGaugeTests.cs | 37 +++++++ 8 files changed, 301 insertions(+) create mode 100644 tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExtendedInstrumentTests.cs diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ScadaBridgeTelemetry.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ScadaBridgeTelemetry.cs index 5b4a2a44..40cd67b0 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ScadaBridgeTelemetry.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ScadaBridgeTelemetry.cs @@ -33,6 +33,45 @@ public static class ScadaBridgeTelemetry Meter.CreateCounter("scadabridge.deployments.applied", unit: "1", description: "Deployments applied."); + /// + /// Incremented for each deployment that ends in a terminal failure (ScadaBridge#81), tagged + /// reason: timeout (the site round-trip timed out), error (any other fault + /// in the send or post-send persistence path) or site_failed (the site answered with a + /// non-Success status). Pairs with scadabridge.deployments.applied to give the deploy + /// success ratio; the rate-limited log lines cannot be alerted on. + /// + private static readonly Counter _deploymentsFailed = + Meter.CreateCounter("scadabridge.deployments.failed", unit: "1", + description: "Deployments that ended in a terminal failure, tagged by reason (timeout|error|site_failed)."); + + /// + /// Incremented for each store-and-forward lifecycle event (ScadaBridge#81), tagged action + /// (Queued, Delivered, Retried, Parked, Retry, Discard) + /// and category. A sustained Parked rate is the alertable signal that messages are + /// exhausting retries; the queue-depth gauge alone cannot distinguish a drain from a park. + /// + private static readonly Counter _sfActivity = + Meter.CreateCounter("scadabridge.store_and_forward.activity", unit: "1", + description: "Store-and-forward lifecycle events, tagged by action and category."); + + /// + /// Incremented for each finished site script run (ScadaBridge#81), tagged outcome + /// (completed | failed | timed_out). Deliberately NOT tagged by instance or + /// script name: that cardinality is unbounded across a site's instances. + /// + private static readonly Counter _scriptRuns = + Meter.CreateCounter("scadabridge.site.script.runs", unit: "1", + description: "Finished site script runs, tagged by outcome (completed|failed|timed_out)."); + + /// + /// Incremented each time a data connection actually CHANGES state (ScadaBridge#81), tagged + /// state (the new ). The data_connections gauges show the + /// current picture; this shows flapping that a scrape interval would otherwise average away. + /// + private static readonly Counter _dataConnectionTransitions = + Meter.CreateCounter("scadabridge.site.data_connections.transitions", unit: "1", + description: "Data connection state changes, tagged by the new state."); + /// Incremented for each inbound API request, tagged with the API method. private static readonly Counter _inboundApiRequests = Meter.CreateCounter("scadabridge.inbound_api.requests", unit: "1", @@ -151,6 +190,11 @@ public static class ScadaBridgeTelemetry Meter.CreateHistogram("scadabridge.site.stream.batch_size", unit: "1", description: "Events per site gRPC stream frame (1 = unbatched frame), tagged by stream kind."); + /// Duration of finished site script runs in milliseconds (ScadaBridge#81), tagged by outcome. + private static readonly Histogram _scriptRunDuration = + Meter.CreateHistogram("scadabridge.site.script.duration", unit: "ms", + description: "Site script run duration in milliseconds, tagged by outcome (completed|failed|timed_out)."); + // ---------------- Observable gauges ---------------- /// @@ -271,6 +315,29 @@ public static class ScadaBridgeTelemetry /// Records that a deployment was applied. public static void RecordDeploymentApplied() => _deploymentsApplied.Add(1); + /// Records one deployment that ended in a terminal failure (ScadaBridge#81). + /// One of timeout, error, site_failed. + public static void RecordDeploymentFailed(string reason) => + _deploymentsFailed.Add(1, new KeyValuePair("reason", reason)); + + /// Records one store-and-forward lifecycle event (ScadaBridge#81). + /// The activity action, e.g. Parked. + /// The message category name. + public static void RecordStoreAndForwardActivity(string action, string category) => + _sfActivity.Add(1, + new KeyValuePair("action", action), + new KeyValuePair("category", category)); + + /// Records one finished site script run and its duration (ScadaBridge#81). + /// One of completed, failed, timed_out. + /// The run duration in milliseconds. + public static void RecordScriptRun(string outcome, long durationMs) + { + var tag = new KeyValuePair("outcome", outcome); + _scriptRuns.Add(1, tag); + _scriptRunDuration.Record(durationMs < 0 ? 0 : durationMs, tag); + } + /// Records an inbound API request for the given . /// The API method the request targeted. public static void RecordInboundApiRequest(string method) => @@ -333,7 +400,13 @@ public static class ScadaBridgeTelemetry return; } + var previous = _dataConnectionStates.TryGetValue(connectionName, out var prior) ? prior : (ConnectionHealth?)null; _dataConnectionStates[connectionName] = state; + + if (previous != state) + { + _dataConnectionTransitions.Add(1, new KeyValuePair("state", state.ToString())); + } } /// diff --git a/src/ZB.MOM.WW.ScadaBridge.DeploymentManager/DeploymentService.cs b/src/ZB.MOM.WW.ScadaBridge.DeploymentManager/DeploymentService.cs index 23f32ca8..968ac9e6 100644 --- a/src/ZB.MOM.WW.ScadaBridge.DeploymentManager/DeploymentService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.DeploymentManager/DeploymentService.cs @@ -631,6 +631,11 @@ public class DeploymentService await _repository.SaveChangesAsync(cancellationToken); NotifyStatusChange(record); + if (response.Status != DeploymentStatus.Success) + { + ScadaBridgeTelemetry.RecordDeploymentFailed("site_failed"); + } + if (response.Status == DeploymentStatus.Success) { // Telemetry: one instance deployment successfully applied to a @@ -721,6 +726,7 @@ public class DeploymentService string user, Exception cause) { + ScadaBridgeTelemetry.RecordDeploymentFailed(IsTimeoutFault(cause) ? "timeout" : "error"); record.Status = DeploymentStatus.Failed; record.ErrorMessage = IsTimeoutFault(cause) ? $"{TimeoutFailurePrefix} {cause.Message}" diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs index 0e6e0113..37b5d382 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs @@ -1,6 +1,7 @@ using System.Collections.Concurrent; using System.Globalization; using System.Text.Json; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.SiteEventLogging; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; @@ -70,6 +71,7 @@ public sealed class ScriptRunSummaryRecorder { var counters = GetOrAddCounters(instanceName, scriptName); Interlocked.Increment(ref counters.Completed); + ScadaBridgeTelemetry.RecordScriptRun("completed", durationMs); RecordDuration(counters, durationMs); } @@ -81,6 +83,7 @@ public sealed class ScriptRunSummaryRecorder { var counters = GetOrAddCounters(instanceName, scriptName); Interlocked.Increment(ref counters.Failed); + ScadaBridgeTelemetry.RecordScriptRun("failed", durationMs); RecordDuration(counters, durationMs); } @@ -95,6 +98,7 @@ public sealed class ScriptRunSummaryRecorder { var counters = GetOrAddCounters(instanceName, scriptName); Interlocked.Increment(ref counters.TimedOut); + ScadaBridgeTelemetry.RecordScriptRun("timed_out", durationMs); RecordDuration(counters, durationMs); } diff --git a/src/ZB.MOM.WW.ScadaBridge.StoreAndForward/StoreAndForwardService.cs b/src/ZB.MOM.WW.ScadaBridge.StoreAndForward/StoreAndForwardService.cs index 66c9532f..6d1ebd04 100644 --- a/src/ZB.MOM.WW.ScadaBridge.StoreAndForward/StoreAndForwardService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.StoreAndForward/StoreAndForwardService.cs @@ -1347,6 +1347,8 @@ public class StoreAndForwardService /// private void RaiseActivity(string action, StoreAndForwardCategory category, string detail) { + ScadaBridgeTelemetry.RecordStoreAndForwardActivity(action, category.ToString()); + var handlers = OnActivity; if (handlers == null) return; diff --git a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExtendedInstrumentTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExtendedInstrumentTests.cs new file mode 100644 index 00000000..f8497437 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExtendedInstrumentTests.cs @@ -0,0 +1,98 @@ +using System.Diagnostics.Metrics; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; + +namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Observability; + +/// +/// ScadaBridge#81: the instruments added beyond the first set. Each is observed through a +/// filtered to the emitting (test) thread, because the meter is +/// process-global and other tests emit on it concurrently. +/// +public sealed class ExtendedInstrumentTests +{ + private static List<(long Value, Dictionary Tags)> Capture(string instrument, Action act) + { + var tid = Environment.CurrentManagedThreadId; + var got = new List<(long, Dictionary)>(); + using var listener = new MeterListener + { + InstrumentPublished = (i, l) => + { + if (i.Meter.Name == ScadaBridgeTelemetry.MeterName && i.Name == instrument) + l.EnableMeasurementEvents(i); + } + }; + listener.SetMeasurementEventCallback((_, m, tags, _) => + { + if (Environment.CurrentManagedThreadId != tid) return; + var d = new Dictionary(); + foreach (var t in tags) d[t.Key] = t.Value; + got.Add((m, d)); + }); + listener.Start(); + act(); + return got; + } + + /// A state change emits one transition tagged with the new state; repeating the same state emits none. + [Fact] + public void DataConnectionTransitions_EmitOnlyOnRealStateChange() + { + var name = "xfer-" + Guid.NewGuid().ToString("N"); + try + { + var got = Capture("scadabridge.site.data_connections.transitions", () => + { + ScadaBridgeTelemetry.RecordDataConnectionState(name, ConnectionHealth.Connecting); + ScadaBridgeTelemetry.RecordDataConnectionState(name, ConnectionHealth.Connected); + ScadaBridgeTelemetry.RecordDataConnectionState(name, ConnectionHealth.Connected); + ScadaBridgeTelemetry.RecordDataConnectionState(name, ConnectionHealth.Disconnected); + }); + + Assert.Equal( + new object?[] { "Connecting", "Connected", "Disconnected" }, + got.Select(g => g.Tags["state"]).ToArray()); + } + finally { ScadaBridgeTelemetry.RemoveDataConnection(name); } + } + + /// Store-and-forward activity is counted by action and category. + [Fact] + public void StoreAndForwardActivity_IsCountedByActionAndCategory() + { + var got = Capture("scadabridge.store_and_forward.activity", + () => ScadaBridgeTelemetry.RecordStoreAndForwardActivity("Parked", "ExternalSystem")); + + var m = Assert.Single(got); + Assert.Equal(1, m.Value); + Assert.Equal("Parked", m.Tags["action"]); + Assert.Equal("ExternalSystem", m.Tags["category"]); + } + + /// Deployment failures are counted by reason. + [Fact] + public void DeploymentsFailed_IsCountedByReason() + { + var got = Capture("scadabridge.deployments.failed", + () => ScadaBridgeTelemetry.RecordDeploymentFailed("timeout")); + + var m = Assert.Single(got); + Assert.Equal("timeout", m.Tags["reason"]); + } + + /// A script run emits both the run counter and the duration histogram, clamping negatives. + [Fact] + public void ScriptRun_EmitsCounterAndDuration() + { + var runs = Capture("scadabridge.site.script.runs", + () => ScadaBridgeTelemetry.RecordScriptRun("failed", 5)); + Assert.Equal("failed", Assert.Single(runs).Tags["outcome"]); + + var durations = Capture("scadabridge.site.script.duration", + () => ScadaBridgeTelemetry.RecordScriptRun("completed", -3)); + var d = Assert.Single(durations); + Assert.Equal(0, d.Value); + Assert.Equal("completed", d.Tags["outcome"]); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.DeploymentManager.Tests/DeploymentServiceTests.cs b/tests/ZB.MOM.WW.ScadaBridge.DeploymentManager.Tests/DeploymentServiceTests.cs index e226e85e..1bc82507 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.DeploymentManager.Tests/DeploymentServiceTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.DeploymentManager.Tests/DeploymentServiceTests.cs @@ -1063,6 +1063,45 @@ public class DeploymentServiceTests : TestKit Assert.Equal(1, Interlocked.Read(ref applied)); } + /// Verifies a faulted deployment emits the deployments failed counter tagged reason=error (ScadaBridge#81). + /// A task that represents the asynchronous operation. + [Fact] + public async Task DeployInstanceAsync_Fault_EmitsDeploymentsFailedCounter() + { + var instance = new Instance("FailMetricInst") { Id = 1, SiteId = 1, State = InstanceState.NotDeployed }; + _repo.GetInstanceByIdAsync(1).Returns(instance); + var config = new FlattenedConfiguration { InstanceUniqueName = "FailMetricInst" }; + _pipeline.FlattenAndValidateAsync(1, Arg.Any()) + .Returns(Result.Success( + new FlatteningPipelineResult(config, "sha256:abc", ValidationResult.Success()))); + + var reasons = new System.Collections.Concurrent.ConcurrentQueue(); + using var listener = new MeterListener + { + InstrumentPublished = (instrument, l) => + { + if (instrument.Meter.Name == ScadaBridgeTelemetry.MeterName + && instrument.Name == "scadabridge.deployments.failed") + { + l.EnableMeasurementEvents(instrument); + } + } + }; + listener.SetMeasurementEventCallback((_, _, tags, _) => + { + foreach (var t in tags) + if (t.Key == "reason") reasons.Enqueue(t.Value as string); + }); + listener.Start(); + + // _comms has no actor set -> non-timeout fault -> MarkDeploymentFailedAsync. + var result = await _service.DeployInstanceAsync(1, "admin"); + listener.Dispose(); + + Assert.True(result.IsFailure); + Assert.Contains("error", reasons); + } + /// Verifies that deploy instance async reconciled does not emit deployments applied counter. /// A task that represents the asynchronous operation. [Fact] diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs index 81a03f1b..463c43ae 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs @@ -12,6 +12,48 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; /// public class ScriptRunSummaryRecorderTests { + /// Verifies each finished run emits the script runs counter and duration histogram with its outcome (ScadaBridge#81). + [Fact] + public void FinishedRuns_EmitRunCounterAndDurationHistogram_TaggedByOutcome() + { + // MeterListener callbacks run synchronously on the emitting thread, so filtering on the + // test thread isolates this test from other tests emitting on the same process-wide meter. + var tid = Environment.CurrentManagedThreadId; + var runs = new List(); + var durations = new List<(string? Outcome, long Ms)>(); + using var listener = new System.Diagnostics.Metrics.MeterListener + { + InstrumentPublished = (i, l) => + { + if (i.Meter.Name == Commons.Observability.ScadaBridgeTelemetry.MeterName + && (i.Name == "scadabridge.site.script.runs" || i.Name == "scadabridge.site.script.duration")) + l.EnableMeasurementEvents(i); + } + }; + static string? Outcome(ReadOnlySpan> tags) + { + foreach (var t in tags) if (t.Key == "outcome") return t.Value as string; + return null; + } + listener.SetMeasurementEventCallback((inst, m, tags, _) => + { + if (Environment.CurrentManagedThreadId != tid) return; + if (inst.Name == "scadabridge.site.script.runs") runs.Add(Outcome(tags)); + else durations.Add((Outcome(tags), m)); + }); + listener.Start(); + + var recorder = new ScriptRunSummaryRecorder(); + recorder.RecordCompleted("i", "s", 10); + recorder.RecordFailed("i", "s", 20); + recorder.RecordTimedOut("i", "s", 30); + + Assert.Equal(new string?[] { "completed", "failed", "timed_out" }, runs); + Assert.Equal( + new (string?, long)[] { ("completed", 10), ("failed", 20), ("timed_out", 30) }, + durations); + } + /// Verifies that flushing with no activity emits no row. /// A task that represents the asynchronous operation. [Fact] diff --git a/tests/ZB.MOM.WW.ScadaBridge.StoreAndForward.Tests/QueueDepthGaugeTests.cs b/tests/ZB.MOM.WW.ScadaBridge.StoreAndForward.Tests/QueueDepthGaugeTests.cs index a3b8ba35..72b06717 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.StoreAndForward.Tests/QueueDepthGaugeTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.StoreAndForward.Tests/QueueDepthGaugeTests.cs @@ -97,6 +97,43 @@ public class QueueDepthGaugeTests : IAsyncLifetime, IDisposable return observed; } + /// + /// ScadaBridge#81: the service emits scadabridge.store_and_forward.activity for a buffered + /// message (Queued) and for a message that exhausts its retries (Parked), through the real service. + /// + /// A task that represents the asynchronous operation. + [Fact] + public async Task ActivityCounter_IsEmitted_ForQueuedAndParked() + { + var seen = new System.Collections.Concurrent.ConcurrentQueue(); + using var listener = new MeterListener + { + InstrumentPublished = (i, l) => + { + if (i.Meter.Name == ScadaBridgeTelemetry.MeterName + && i.Name == "scadabridge.store_and_forward.activity") + l.EnableMeasurementEvents(i); + } + }; + listener.SetMeasurementEventCallback((_, _, tags, _) => + { + foreach (var t in tags) + if (t.Key == "action" && t.Value is string a) seen.Enqueue(a); + }); + listener.Start(); + + _service.RegisterDeliveryHandler(StoreAndForwardCategory.ExternalSystem, + _ => throw new HttpRequestException("transient")); + + var r = await _service.EnqueueAsync( + StoreAndForwardCategory.ExternalSystem, "api-activity", """{}""", maxRetries: 1); + Assert.True(r.WasBuffered); + await _service.RetryPendingMessagesAsync(); + + Assert.Contains("Queued", seen); + Assert.Contains("Parked", seen); + } + /// /// Review 2026-10-21 02/C3: rows that arrive without passing through this node's counter /// paths (LocalDb CDC on a standby) are picked up by the sweep's periodic re-seed.