Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions docs/guide/logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -921,6 +921,15 @@ will be added back to Wolverine in 4.0.
| wolverine-outbox-count | Observable Gauge | Current number of persisted outgoing (outbox) messages. Tagged by `source` and `database` |
| wolverine-scheduled-count | Observable Gauge | Current number of persisted scheduled messages. Tagged by `source` and `database` |

::: tip System traffic is not counted <Badge type="tip" text="6.25" />
Wolverine's own internal traffic — node agent commands on the control queues, acknowledgements, and
CritterWatch monitoring messages — is excluded from all of the message-level instruments above, as is any
endpoint marked with the `System` role or with `TelemetryEnabled = false`. An idle application therefore
reports zero message volume even when Wolverine's node coordination or CritterWatch monitoring is busy
underneath. Before 6.25 this internal chatter was counted, which could show up as a steady, phantom
message rate (~150/minute was reported) on an otherwise quiet system.
:::

### Standard Metrics Tags

Every Wolverine metric instrument above is tagged with these dimensions so you can slice the series in your
Expand Down
194 changes: 194 additions & 0 deletions src/Testing/CoreTests/Runtime/system_traffic_metrics_silencing.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,194 @@
using System.Collections.Concurrent;
using System.Diagnostics.Metrics;
using CoreTests.Transports;
using JasperFx.Core;
using Microsoft.Extensions.Hosting;
using Shouldly;
using Wolverine.ComplianceTests;
using Wolverine.Configuration;
using Wolverine.Runtime;
using Wolverine.Runtime.Agents;
using Wolverine.Runtime.Handlers;
using Wolverine.Transports.Tcp;
using Xunit;

namespace CoreTests.Runtime;

/// <summary>
/// CritterWatch GH-907: a monitoring tool must not measurably inflate the thing it is monitoring. An idle
/// Wolverine app with CritterWatch applied reported ~150 messages/minute of nothing but its own agent
/// commands and monitoring traffic, because (a) the meter counters were unconditional, (b) the accumulator
/// guard was a string match that knew nothing of control endpoints, and (c) only IAgentCommand — not the
/// full system-message surface — was excluded from the CritterWatch publishing trackers. The fix resolves a
/// metrics-silent tracker ONCE at each construction site (endpoint agents, pipelines, executors); these
/// tests pin that selection and the resulting meter silence.
/// </summary>
public class system_traffic_metrics_silencing : IAsyncLifetime
{
private const string TheServiceName = "system-traffic-silencing";

private IHost _host = null!;
private WolverineRuntime _runtime = null!;
private MeterListener _listener = null!;
private readonly ConcurrentDictionary<string, int> _counts = new();

public async ValueTask InitializeAsync()
{
_host = await Host.CreateDefaultBuilder()
.UseWolverine(opts =>
{
opts.ServiceName = TheServiceName;
opts.Discovery.DisableConventionalDiscovery()
.IncludeType<SilencingProbeHandler>();
}).StartAsync();

_runtime = (WolverineRuntime)_host.Services.GetService(typeof(IWolverineRuntime))!;

_listener = new MeterListener
{
InstrumentPublished = (instrument, l) =>
{
if (instrument.Meter.Name == "Wolverine:" + TheServiceName)
{
l.EnableMeasurementEvents(instrument);
}
}
};

_listener.SetMeasurementEventCallback<int>((inst, _, _, _) => record(inst));
_listener.SetMeasurementEventCallback<long>((inst, _, _, _) => record(inst));
_listener.SetMeasurementEventCallback<double>((inst, _, _, _) => record(inst));
_listener.Start();
}

public async ValueTask DisposeAsync()
{
_listener.Dispose();
await _host.StopAsync();
_host.Dispose();
}

private void record(Instrument instrument)
{
_counts.AddOrUpdate(instrument.Name, 1, (_, count) => count + 1);
}

private static Endpoint appEndpoint()
=> new FakeEndpoint("fake://app".ToUri(), EndpointRole.Application);

private static Endpoint systemEndpoint()
=> new FakeEndpoint("fake://control".ToUri(), EndpointRole.System);

private Envelope envelopeFor(object message) => new()
{
Message = message,
Destination = "fake://somewhere".ToUri(),
MessageType = message.GetType().FullName
};

/*** TRACKER SELECTION — decided once at construction, never per envelope ***/

[Fact]
public void system_role_endpoints_get_the_metrics_silent_tracker()
{
_runtime.MessageTrackingFor(systemEndpoint())
.ShouldBeOfType<WolverineRuntime.SystemTrafficMessageTracker>();
}

[Fact]
public void telemetry_disabled_endpoints_get_the_metrics_silent_tracker()
{
var endpoint = appEndpoint();
endpoint.TelemetryEnabled = false;

_runtime.MessageTrackingFor(endpoint)
.ShouldBeOfType<WolverineRuntime.SystemTrafficMessageTracker>();
}

[Fact]
public void application_endpoints_keep_the_standard_tracker()
{
_runtime.MessageTrackingFor(appEndpoint()).ShouldBeSameAs(_runtime.MessageTracking);
}

[Fact]
public void agent_commands_execute_metrics_silent_even_on_an_application_endpoint()
{
// The message-type half of the gate: an agent command handled on ANY endpoint is system traffic.
var executor = ((IExecutorFactory)_runtime).BuildFor(typeof(CheckAgentHealth), appEndpoint());

executor.ShouldBeOfType<Executor>().Tracker
.ShouldBeOfType<WolverineRuntime.SystemTrafficMessageTracker>();
}

[Fact]
public void agent_commands_invoked_through_the_runtime_pipeline_are_metrics_silent()
{
var executor = ((IExecutorFactory)_runtime).BuildFor(typeof(CheckAgentHealth));

executor.ShouldBeOfType<Executor>().Tracker
.ShouldBeOfType<WolverineRuntime.SystemTrafficMessageTracker>();
}

[Fact]
public void application_messages_on_application_endpoints_keep_metrics()
{
var executor = ((IExecutorFactory)_runtime).BuildFor(typeof(SilencingProbeMessage), appEndpoint());

executor.ShouldBeOfType<Executor>().Tracker.ShouldBeSameAs(_runtime.MessageTracking);
}

[Fact]
public void promoting_an_endpoint_to_node_control_duty_marks_it_as_system()
{
// UseTcpForControlEndpoint promotes a plain TCP endpoint; before GH-907 it stayed
// Application-role and its agent-command traffic was counted as application volume.
var options = new WolverineOptions();
var endpoint = new TcpEndpoint(577);
endpoint.Role.ShouldBe(EndpointRole.Application);

options.Transports.NodeControlEndpoint = endpoint;

endpoint.Role.ShouldBe(EndpointRole.System);
}

/*** METER BEHAVIOR — the silent tracker records nothing, the standard one records ***/

[Fact]
public void the_silent_tracker_reaches_no_meter_instrument()
{
_counts.Clear();
var tracker = _runtime.MessageTrackingFor(systemEndpoint());
var envelope = envelopeFor(new CheckAgentHealth());

tracker.Sent(envelope);
tracker.Received(envelope);
tracker.ExecutionStarted(envelope);
tracker.ExecutionFinished(envelope);
tracker.MessageSucceeded(envelope);
tracker.MessageFailed(envelope, new InvalidOperationException("boom"));

_listener.RecordObservableInstruments();
_counts.ShouldBeEmpty();
}

[Fact]
public void the_standard_tracker_still_records()
{
_counts.Clear();
var envelope = envelopeFor(new SilencingProbeMessage());

_runtime.MessageTracking.Sent(envelope);

_counts.ContainsKey(MetricsConstants.MessagesSent).ShouldBeTrue();
}
}

public record SilencingProbeMessage;

public class SilencingProbeHandler
{
public void Handle(SilencingProbeMessage _)
{
}
}
6 changes: 3 additions & 3 deletions src/Wolverine/Configuration/EndpointCollection.cs
Original file line number Diff line number Diff line change
Expand Up @@ -453,17 +453,17 @@ private ISendingAgent buildSendingAgent(ISender sender, Endpoint endpoint)
: _runtime.Storage.Outbox;

return new DurableSendingAgent(sender, _options.Durability,
_runtime.LoggerFactory.CreateLogger<DurableSendingAgent>(), _runtime.MessageTracking,
_runtime.LoggerFactory.CreateLogger<DurableSendingAgent>(), _runtime.MessageTrackingFor(endpoint),
outbox, endpoint, _runtime, sendingPolicies);

case EndpointMode.BufferedInMemory:
return new BufferedSendingAgent(_runtime.LoggerFactory.CreateLogger<BufferedSendingAgent>(),
_runtime.MessageTracking, sender, _runtime.DurabilitySettings,
_runtime.MessageTrackingFor(endpoint), sender, _runtime.DurabilitySettings,
endpoint, _runtime, sendingPolicies);

case EndpointMode.Inline:
return new InlineSendingAgent(_runtime.LoggerFactory.CreateLogger<InlineSendingAgent>(), sender,
endpoint, _runtime.MessageTracking,
endpoint, _runtime.MessageTrackingFor(endpoint),
_runtime.DurabilitySettings, _runtime, sendingPolicies);
}

Expand Down
4 changes: 3 additions & 1 deletion src/Wolverine/Runtime/HandlerPipeline.cs
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,9 @@ internal HandlerPipeline(WolverineRuntime runtime, IExecutorFactory executorFact
_contextPool = runtime.ExecutionPool;
_cancellation = runtime.Cancellation;

Logger = runtime.MessageTracking;
// CritterWatch GH-907: a system endpoint's received traffic never reaches the meters or the
// CritterWatch accumulator. Resolved once here, not per envelope.
Logger = runtime.MessageTrackingFor(endpoint);

_executors = new LightweightCache<Type, IExecutor>(type => executorFactory.BuildFor(type, endpoint));
}
Expand Down
6 changes: 6 additions & 0 deletions src/Wolverine/Runtime/Handlers/Executor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -57,6 +57,12 @@ internal class Executor : IExecutor
private readonly IMessageTracker _tracker;
private readonly IWolverineRuntime? _runtime;

/// <summary>
/// The tracker this executor reports to. Exposed for tests asserting which traffic is
/// metrics-silent (CritterWatch GH-907).
/// </summary>
internal IMessageTracker Tracker => _tracker;

public Executor(ObjectPool<MessageContext> contextPool, IWolverineRuntime runtime, IMessageHandler handler,
FailureRuleCollection rules, TimeSpan timeout)
: this(contextPool, runtime.LoggerFactory.CreateLogger(handler.MessageType), handler, runtime.MessageTracking, rules, timeout)
Expand Down
52 changes: 42 additions & 10 deletions src/Wolverine/Runtime/Wolverine.ExecutorFactory.cs
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
using JasperFx.Core.Reflection;
using Wolverine.Configuration;
using Wolverine.Configuration.Capabilities;
using Wolverine.Logging;
using Wolverine.Runtime.Agents;
using Wolverine.Runtime.Handlers;
Expand All @@ -13,6 +14,18 @@ public partial class WolverineRuntime : IExecutorFactory
{
IExecutor IExecutorFactory.BuildFor(Type messageType)
{
// CritterWatch GH-907: system message types (agent commands, acknowledgements, CritterWatch
// monitoring traffic) invoked through the runtime-level pipeline must not record execution
// metrics. Decided here, once per message type, never per envelope.
if (messageType.IsSystemMessageType())
{
var handler = Handlers.HandlerFor(messageType);
if (handler != null)
{
return Executor.Build(this, ExecutionPool, Handlers, handler, SystemTraffic);
}
}

var executor = Executor.Build(this, ExecutionPool, Handlers, messageType);

return executor;
Expand Down Expand Up @@ -45,23 +58,42 @@ IExecutor IExecutorFactory.BuildFor(Type messageType, Endpoint endpoint)
}
}

IMessageTracker tracker = this;
if (!messageType.CanBeCastTo<IAgentCommand>() && Options.Metrics.Mode == WolverineMetricsMode.CritterWatch)
var tracker = trackerFor(messageType, endpoint);

var executor = handler == null
? new NoHandlerExecutor(messageType, this)
: Executor.Build(this, ExecutionPool, Handlers, handler, tracker);

return executor;
}

// CritterWatch GH-907: pick each executor's tracker ONCE at construction. System traffic — a system
// message type (agent commands, acks, CritterWatch monitoring messages), a system-role endpoint (node
// control queues, internal local queues), or an endpoint with telemetry deliberately switched off —
// gets the metrics-silent tracker, in EVERY metrics mode. This used to exclude only IAgentCommand and
// only from the two CritterWatch-publishing modes, so agent commands still hit the OTel meters in the
// default mode and CritterWatch's own monitoring messages were counted (and re-published) as
// application volume — the feedback loop behind an idle app reporting hundreds of messages a minute.
private IMessageTracker trackerFor(Type messageType, Endpoint endpoint)
{
if (messageType.IsSystemMessageType() || endpoint.Role == EndpointRole.System || !endpoint.TelemetryEnabled)
{
var accumulator = MetricsAccumulator.FindAccumulator(messageType.ToMessageTypeName(), endpoint);
tracker = new DirectMetricsPublishingMessageTracker(this, accumulator.EntryPoint);
return SystemTraffic;
}
else if (!messageType.CanBeCastTo<IAgentCommand>() && Options.Metrics.Mode == WolverineMetricsMode.Hybrid)

if (Options.Metrics.Mode == WolverineMetricsMode.CritterWatch)
{
var accumulator = MetricsAccumulator.FindAccumulator(messageType.ToMessageTypeName(), endpoint);
tracker = new HybridMetricsPublishingMessageTracker(this, accumulator.EntryPoint);
return new DirectMetricsPublishingMessageTracker(this, accumulator.EntryPoint);
}

var executor = handler == null
? new NoHandlerExecutor(messageType, this)
: Executor.Build(this, ExecutionPool, Handlers, handler, tracker);
if (Options.Metrics.Mode == WolverineMetricsMode.Hybrid)
{
var accumulator = MetricsAccumulator.FindAccumulator(messageType.ToMessageTypeName(), endpoint);
return new HybridMetricsPublishingMessageTracker(this, accumulator.EntryPoint);
}

return executor;
return this;
}

/// <summary>
Expand Down
Loading
Loading