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
2026-11-09 14:17:53 -05:00
parent 7892c622cf
commit 5ef27fd9a3
8 changed files with 301 additions and 0 deletions
@@ -33,6 +33,45 @@ public static class ScadaBridgeTelemetry
        Meter.CreateCounter<long>("scadabridge.deployments.applied", unit: "1",
            description: "Deployments applied.");

+    /// <summary>
+    /// Incremented for each deployment that ends in a terminal failure (ScadaBridge#81), tagged
+    /// <c>reason</c>: <c>timeout</c> (the site round-trip timed out), <c>error</c> (any other fault
+    /// in the send or post-send persistence path) or <c>site_failed</c> (the site answered with a
+    /// non-Success status). Pairs with <c>scadabridge.deployments.applied</c> to give the deploy
+    /// success ratio; the rate-limited log lines cannot be alerted on.
+    /// </summary>
+    private static readonly Counter<long> _deploymentsFailed =
+        Meter.CreateCounter<long>("scadabridge.deployments.failed", unit: "1",
+            description: "Deployments that ended in a terminal failure, tagged by reason (timeout|error|site_failed).");
+
+    /// <summary>
+    /// Incremented for each store-and-forward lifecycle event (ScadaBridge#81), tagged <c>action</c>
+    /// (<c>Queued</c>, <c>Delivered</c>, <c>Retried</c>, <c>Parked</c>, <c>Retry</c>, <c>Discard</c>)
+    /// and <c>category</c>. A sustained <c>Parked</c> rate is the alertable signal that messages are
+    /// exhausting retries; the queue-depth gauge alone cannot distinguish a drain from a park.
+    /// </summary>
+    private static readonly Counter<long> _sfActivity =
+        Meter.CreateCounter<long>("scadabridge.store_and_forward.activity", unit: "1",
+            description: "Store-and-forward lifecycle events, tagged by action and category.");
+
+    /// <summary>
+    /// Incremented for each finished site script run (ScadaBridge#81), tagged <c>outcome</c>
+    /// (<c>completed</c> | <c>failed</c> | <c>timed_out</c>). Deliberately NOT tagged by instance or
+    /// script name: that cardinality is unbounded across a site's instances.
+    /// </summary>
+    private static readonly Counter<long> _scriptRuns =
+        Meter.CreateCounter<long>("scadabridge.site.script.runs", unit: "1",
+            description: "Finished site script runs, tagged by outcome (completed|failed|timed_out).");
+
+    /// <summary>
+    /// Incremented each time a data connection actually CHANGES state (ScadaBridge#81), tagged
+    /// <c>state</c> (the new <see cref="ConnectionHealth"/>). The data_connections gauges show the
+    /// current picture; this shows flapping that a scrape interval would otherwise average away.
+    /// </summary>
+    private static readonly Counter<long> _dataConnectionTransitions =
+        Meter.CreateCounter<long>("scadabridge.site.data_connections.transitions", unit: "1",
+            description: "Data connection state changes, tagged by the new state.");
+
    /// <summary>Incremented for each inbound API request, tagged with the API method.</summary>
    private static readonly Counter<long> _inboundApiRequests =
        Meter.CreateCounter<long>("scadabridge.inbound_api.requests", unit: "1",
@@ -151,6 +190,11 @@ public static class ScadaBridgeTelemetry
        Meter.CreateHistogram<int>("scadabridge.site.stream.batch_size", unit: "1",
            description: "Events per site gRPC stream frame (1 = unbatched frame), tagged by stream kind.");

+    /// <summary>Duration of finished site script runs in milliseconds (ScadaBridge#81), tagged by outcome.</summary>
+    private static readonly Histogram<long> _scriptRunDuration =
+        Meter.CreateHistogram<long>("scadabridge.site.script.duration", unit: "ms",
+            description: "Site script run duration in milliseconds, tagged by outcome (completed|failed|timed_out).");
+
    // ---------------- Observable gauges ----------------

    /// <summary>
@@ -271,6 +315,29 @@ public static class ScadaBridgeTelemetry
    /// <summary>Records that a deployment was applied.</summary>
    public static void RecordDeploymentApplied() => _deploymentsApplied.Add(1);

+    /// <summary>Records one deployment that ended in a terminal failure (ScadaBridge#81).</summary>
+    /// <param name="reason">One of <c>timeout</c>, <c>error</c>, <c>site_failed</c>.</param>
+    public static void RecordDeploymentFailed(string reason) =>
+        _deploymentsFailed.Add(1, new KeyValuePair<string, object?>("reason", reason));
+
+    /// <summary>Records one store-and-forward lifecycle event (ScadaBridge#81).</summary>
+    /// <param name="action">The activity action, e.g. <c>Parked</c>.</param>
+    /// <param name="category">The message category name.</param>
+    public static void RecordStoreAndForwardActivity(string action, string category) =>
+        _sfActivity.Add(1,
+            new KeyValuePair<string, object?>("action", action),
+            new KeyValuePair<string, object?>("category", category));
+
+    /// <summary>Records one finished site script run and its duration (ScadaBridge#81).</summary>
+    /// <param name="outcome">One of <c>completed</c>, <c>failed</c>, <c>timed_out</c>.</param>
+    /// <param name="durationMs">The run duration in milliseconds.</param>
+    public static void RecordScriptRun(string outcome, long durationMs)
+    {
+        var tag = new KeyValuePair<string, object?>("outcome", outcome);
+        _scriptRuns.Add(1, tag);
+        _scriptRunDuration.Record(durationMs < 0 ? 0 : durationMs, tag);
+    }
+
    /// <summary>Records an inbound API request for the given <paramref name="method"/>.</summary>
    /// <param name="method">The API method the request targeted.</param>
    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<string, object?>("state", state.ToString()));
+        }
    }

    /// <summary>
@@ -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}"
@@ -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);
    }

@@ -1347,6 +1347,8 @@ public class StoreAndForwardService
    /// </summary>
    private void RaiseActivity(string action, StoreAndForwardCategory category, string detail)
    {
+        ScadaBridgeTelemetry.RecordStoreAndForwardActivity(action, category.ToString());
+
        var handlers = OnActivity;
        if (handlers == null) return;

@@ -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;
+
+/// <summary>
+/// ScadaBridge#81: the instruments added beyond the first set. Each is observed through a
+/// <see cref="MeterListener"/> filtered to the emitting (test) thread, because the meter is
+/// process-global and other tests emit on it concurrently.
+/// </summary>
+public sealed class ExtendedInstrumentTests
+{
+    private static List<(long Value, Dictionary<string, object?> Tags)> Capture(string instrument, Action act)
+    {
+        var tid = Environment.CurrentManagedThreadId;
+        var got = new List<(long, Dictionary<string, object?>)>();
+        using var listener = new MeterListener
+        {
+            InstrumentPublished = (i, l) =>
+            {
+                if (i.Meter.Name == ScadaBridgeTelemetry.MeterName && i.Name == instrument)
+                    l.EnableMeasurementEvents(i);
+            }
+        };
+        listener.SetMeasurementEventCallback<long>((_, m, tags, _) =>
+        {
+            if (Environment.CurrentManagedThreadId != tid) return;
+            var d = new Dictionary<string, object?>();
+            foreach (var t in tags) d[t.Key] = t.Value;
+            got.Add((m, d));
+        });
+        listener.Start();
+        act();
+        return got;
+    }
+
+    /// <summary>A state change emits one transition tagged with the new state; repeating the same state emits none.</summary>
+    [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); }
+    }
+
+    /// <summary>Store-and-forward activity is counted by action and category.</summary>
+    [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"]);
+    }
+
+    /// <summary>Deployment failures are counted by reason.</summary>
+    [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"]);
+    }
+
+    /// <summary>A script run emits both the run counter and the duration histogram, clamping negatives.</summary>
+    [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"]);
+    }
+}
@@ -1063,6 +1063,45 @@ public class DeploymentServiceTests : TestKit
        Assert.Equal(1, Interlocked.Read(ref applied));
    }

+    /// <summary>Verifies a faulted deployment emits the deployments failed counter tagged reason=error (ScadaBridge#81).</summary>
+    /// <returns>A task that represents the asynchronous operation.</returns>
+    [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<CancellationToken>())
+            .Returns(Result<FlatteningPipelineResult>.Success(
+                new FlatteningPipelineResult(config, "sha256:abc", ValidationResult.Success())));
+
+        var reasons = new System.Collections.Concurrent.ConcurrentQueue<string?>();
+        using var listener = new MeterListener
+        {
+            InstrumentPublished = (instrument, l) =>
+            {
+                if (instrument.Meter.Name == ScadaBridgeTelemetry.MeterName
+                    && instrument.Name == "scadabridge.deployments.failed")
+                {
+                    l.EnableMeasurementEvents(instrument);
+                }
+            }
+        };
+        listener.SetMeasurementEventCallback<long>((_, _, 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);
+    }
+
    /// <summary>Verifies that deploy instance async reconciled does not emit deployments applied counter.</summary>
    /// <returns>A task that represents the asynchronous operation.</returns>
    [Fact]
@@ -12,6 +12,48 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts;
 /// </summary>
 public class ScriptRunSummaryRecorderTests
 {
+    /// <summary>Verifies each finished run emits the script runs counter and duration histogram with its outcome (ScadaBridge#81).</summary>
+    [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<string?>();
+        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<KeyValuePair<string, object?>> tags)
+        {
+            foreach (var t in tags) if (t.Key == "outcome") return t.Value as string;
+            return null;
+        }
+        listener.SetMeasurementEventCallback<long>((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);
+    }
+
    /// <summary>Verifies that flushing with no activity emits no row.</summary>
    /// <returns>A task that represents the asynchronous operation.</returns>
    [Fact]
@@ -97,6 +97,43 @@ public class QueueDepthGaugeTests : IAsyncLifetime, IDisposable
        return observed;
    }

+    /// <summary>
+    /// ScadaBridge#81: the service emits <c>scadabridge.store_and_forward.activity</c> for a buffered
+    /// message (Queued) and for a message that exhausts its retries (Parked), through the real service.
+    /// </summary>
+    /// <returns>A task that represents the asynchronous operation.</returns>
+    [Fact]
+    public async Task ActivityCounter_IsEmitted_ForQueuedAndParked()
+    {
+        var seen = new System.Collections.Concurrent.ConcurrentQueue<string>();
+        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<long>((_, _, 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);
+    }
+
    /// <summary>
    /// 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.