Skip to content

Extended progression tracking is write-path inert: heartbeat/agent_status/pause_reason columns are never persisted by any daemon path (never wired, not a regression) #537

Description

@jeremydmiller

Summary

Extended progression tracking (IEventStoreInstrumentation.ExtendedProgressionEnabled, #424 / marten#4686) is write-path inert: the schema columns (heartbeat, agent_status, pause_reason, running_on_node, warning_behind_threshold, critical_behind_threshold) are created, and the read surface (ProjectionProgressStatement / ShardStateSelector / ShardState.AgentStatus) faithfully reads them back — but no daemon path ever persists them. They are NULL for every shard at all times: while running, at the heartbeat interval, and after a stop.

This was observed in passing in #519 ("a feature that was built and never connected") and polecat#323; both resolved by making the contract honest (nullable AgentStatus, dead-code deletion, a pinning characterization test). Nothing tracks actually wiring the write path up. This issue is that tracker, now with a clean-room repro confirming the end-to-end behavior on the released stack.

Found via CritterWatch#750: CritterWatch forces the flag on for every monitored store, and everything that reads the DB columns (HWM-frozen alerting, poller fallbacks when a node is down, walkthrough SQL verifications) stays dark. Runtime status UI still works only because it rides in-process pushes.

Clean-room repro (no Wolverine, no CritterWatch)

Plain AddMarten().AddAsyncDaemon(DaemonMode.Solo), one async SingleStreamProjection, extended progression enabled via the DI-registered IEventStoreInstrumentation singleton (the only opt-in that works under DI — see the Marten companion issue). Events appended continuously (~3/sec), progression dumped every 15s, then a graceful host stop (agents StopAndDrainAsync, which publishes AgentStatus = "Stopped" to the in-proc tracker) and a final dump. Package provenance verified against nuget.org.

Marten 9.16.1 / JasperFx.Events 2.30.1 (current release):

--- running, t+15s ---
  Counters:All    seq=48   last_updated=2:32:21 PM  heartbeat=NULL  agent_status=NULL  pause_reason=NULL  running_on_node=NULL
  HighWaterMark   seq=48   last_updated=2:32:35 PM  heartbeat=NULL  agent_status=NULL  pause_reason=NULL  running_on_node=NULL
--- running, t+120s (longer run) ---
  Counters:All    seq=391  last_updated=2:24:19 PM  heartbeat=NULL  agent_status=NULL  pause_reason=NULL  running_on_node=NULL
=== stopping host (agents stop + drain) ===
--- after host stop ---
  Counters:All    seq=196  last_updated=2:32:21 PM  heartbeat=NULL  agent_status=NULL  pause_reason=NULL  running_on_node=NULL

Marten 9.16.0 / JasperFx.Events 2.29.0 (prior 6.20-era pins): byte-for-byte the same behavior — all extended columns NULL throughout, NULL after stop.

Marten 9.16.1 / JasperFx.Events 2.30.2 (released today, includes the #534/#535 daemon fixes): same repro run empirically — still inert, all extended columns NULL throughout and after stop. Those fixes are start-registration/failure-reason plumbing and do not touch progression writes.

Verdict: never wired, not a bump regression

Where the wiring gap actually is

The daemon side already computes everything: SubscriptionAgent publishes ShardState carrying AgentStatus / PauseReason / LastHeartbeat into the in-process ShardStateTracker on start / stop / pause, and from a 10-second heartbeat timer (SubscriptionAgent.startHeartbeatTimer). Nothing subscribes to those publications to persist them; the store-side writers that were built for exactly this are unreachable.

So the missing piece is daemon-level (this repo): when ExtendedProgressionEnabled, take the agent's ShardState transitions + heartbeat ticks and invoke a store-supplied extended-progress write —

  • Marten: call mt_mark_event_progression_extended() (exists, tested DDL, zero callers), and
  • Polecat: extend RecordProgressionOperation's extended path with agent state (its dedicated writer was deleted as dead code in polecat#325).

Filing here as the coordination point per the #519 discussion ("wiring agent state up is a daemon-level design question for both stores"). Note the heartbeat likely wants a write path that is not coupled to progress advance — a paused/stalled shard is precisely when the persisted heartbeat/status matters most (that is the CritterWatch node-down / HWM-frozen alerting case).

Marten-side defects found while building the repro

Filed separately (they bite anyone trying to use this feature today): SetEventStoreInstrumentation clobbers a direct EnableExtendedProgressionTracking = true opt-in; the async-daemon docs' cast-based opt-in snippet throws InvalidCastException; mt_event_progression.last_updated is frozen at insert time for daemon shard rows.

Repro program

Program.cs — net9.0; Marten 9.16.1, JasperFx + JasperFx.Events 2.30.1, Microsoft.Extensions.Hosting 9.0.0 (MartenVersion/JasperFxVersion overridable via MSBuild props for the prior-stack run)
using System.Diagnostics;
using JasperFx;
using JasperFx.Events;
using JasperFx.Events.Daemon;
using JasperFx.Events.Projections;
using Marten;
using Marten.Events.Aggregation;
using Marten.Events.Projections;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Npgsql;

// ---------------------------------------------------------------------------
// Clean-room repro for CritterWatch#750 item 1 + item 3:
// minimal Marten host, ExtendedProgressionEnabled = true, one async
// projection, async daemon in Solo mode. NO Wolverine, NO CritterWatch.
// Watches extprog_repro.mt_event_progression while appending events, then
// stops the agent and checks agent_status / pause_reason.
// ---------------------------------------------------------------------------

const string ConnectionString =
    "Host=localhost;Port=5442;Database=postgres;Username=postgres;Password=postgres";

var schema = Environment.GetEnvironmentVariable("REPRO_SCHEMA") ?? "extprog_repro";

Console.WriteLine($"Marten assembly:          {typeof(DocumentStore).Assembly.GetName().Version}  ({typeof(DocumentStore).Assembly.Location})");
Console.WriteLine($"JasperFx.Events assembly: {typeof(IEventStoreInstrumentation).Assembly.GetName().Version}  ({typeof(IEventStoreInstrumentation).Assembly.Location})");
Console.WriteLine($"Schema: {schema}");

// Fresh schema every run
await using (var conn = new NpgsqlConnection(ConnectionString))
{
    await conn.OpenAsync();
    await using var cmd = new NpgsqlCommand($"drop schema if exists {schema} cascade", conn);
    await cmd.ExecuteNonQueryAsync();
}

var builder = Host.CreateApplicationBuilder();
builder.Logging.SetMinimumLevel(LogLevel.Warning);

builder.Services.AddMarten(opts =>
    {
        opts.Connection(ConnectionString);
        opts.DatabaseSchemaName = schema;

        // Documented direct opt-in. NOTE: under AddMarten this gets
        // clobbered back to false by Marten's DI-registered
        // SetEventStoreInstrumentation adapter (IConfigureMarten), whose
        // Configure() unconditionally writes its own (default false) value
        // into EventGraph.EnableExtendedProgressionTracking at store build
        // time. Left in deliberately to demonstrate the clobber.
        opts.Events.EnableExtendedProgressionTracking = true;

        opts.Projections.Add(new CounterProjection(), ProjectionLifecycle.Async);
    })
    .AddAsyncDaemon(DaemonMode.Solo);

// The opt-in path that actually works under DI, and exactly what
// CritterWatch#321's ForceExtendedProgressionOnEventStores does: mutate the
// DI-registered IEventStoreInstrumentation singleton(s).
foreach (var descriptor in builder.Services
             .Where(x => !x.IsKeyedService && x.ServiceType == typeof(IEventStoreInstrumentation)))
{
    if (descriptor.ImplementationInstance is IEventStoreInstrumentation instrument)
    {
        instrument.ExtendedProgressionEnabled = true;
        Console.WriteLine($"flipped ExtendedProgressionEnabled on {instrument.GetType().Name}");
    }
}

var host = builder.Build();
await host.StartAsync();

var store = host.Services.GetRequiredService<IDocumentStore>();

// Sanity: confirm the flag stuck
Console.WriteLine($"EnableExtendedProgressionTracking sanity check via store options: " +
                  $"{store.Options.Events.EnableExtendedProgressionTracking}");

var cts = new CancellationTokenSource();
var streamIds = Enumerable.Range(0, 3).Select(_ => Guid.NewGuid()).ToArray();

// Continuous append loop
var appender = Task.Run(async () =>
{
    var rnd = new Random();
    while (!cts.IsCancellationRequested)
    {
        try
        {
            await using var session = store.LightweightSession();
            var id = streamIds[rnd.Next(streamIds.Length)];
            session.Events.Append(id, new Incremented(1));
            await session.SaveChangesAsync(cts.Token);
        }
        catch (OperationCanceledException) { }
        await Task.Delay(300, CancellationToken.None);
    }
});

async Task DumpProgression(string label)
{
    Console.WriteLine($"--- {label}  ({DateTimeOffset.Now:HH:mm:ss}) ---");
    await using var conn = new NpgsqlConnection(ConnectionString);
    await conn.OpenAsync();
    await using var cmd = new NpgsqlCommand(
        $"select name, last_seq_id, last_updated, heartbeat, agent_status, pause_reason, running_on_node " +
        $"from {schema}.mt_event_progression order by name", conn);
    await using var reader = await cmd.ExecuteReaderAsync();
    var any = false;
    while (await reader.ReadAsync())
    {
        any = true;
        string Val(int i) => reader.IsDBNull(i) ? "NULL" : reader.GetValue(i).ToString()!;
        Console.WriteLine(
            $"  {Val(0),-40} seq={Val(1),-6} last_updated={Val(2)}  heartbeat={Val(3)}  " +
            $"agent_status={Val(4)}  pause_reason={Val(5)}  running_on_node={Val(6)}");
    }
    if (!any) Console.WriteLine("  (no rows)");
}

// Phase 1: run for ~2 minutes, dumping every 15s. Heartbeat should advance
// ~every 5-10s per the docs if extended progression is actually written.
var runSeconds = int.TryParse(Environment.GetEnvironmentVariable("REPRO_RUNSECONDS"), out var rs) ? rs : 120;
var sw = Stopwatch.StartNew();
while (sw.Elapsed < TimeSpan.FromSeconds(runSeconds))
{
    await Task.Delay(TimeSpan.FromSeconds(15));
    await DumpProgression($"running, t+{sw.Elapsed.TotalSeconds:F0}s");
}

// Phase 2: stop appending, gracefully stop the host (agents StopAndDrain,
// SubscriptionAgent publishes AgentStatus=Stopped to the in-proc tracker),
// then re-check the DB. If agent state were persisted anywhere, this is
// where agent_status/pause_reason would show up.
cts.Cancel();
try { await appender; } catch { }

Console.WriteLine("=== stopping host (agents stop + drain) ===");
await host.StopAsync(TimeSpan.FromSeconds(30));
Console.WriteLine("host stopped");

await Task.Delay(TimeSpan.FromSeconds(5));
await DumpProgression("after host stop (agent_status would say Stopped if agent state were persisted)");

// Cleanup unless asked to keep
if (Environment.GetEnvironmentVariable("REPRO_KEEP") != "1")
{
    await using var conn2 = new NpgsqlConnection(ConnectionString);
    await conn2.OpenAsync();
    await using var cmd2 = new NpgsqlCommand($"drop schema if exists {schema} cascade", conn2);
    await cmd2.ExecuteNonQueryAsync();
    Console.WriteLine($"schema {schema} dropped");
}

public record Incremented(int Amount);

public class Counter
{
    public Guid Id { get; set; }
    public int Count { get; set; }
}

public partial class CounterProjection: SingleStreamProjection<Counter, Guid>
{
    public CounterProjection()
    {
        Name = "Counters";
    }

    public void Apply(Counter counter, Incremented e) => counter.Count += e.Amount;
}

Refs: #519, #435, #424, polecat#323, polecat#325, marten#4686, CritterWatch#750.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions