From 00793cc0b59a2c656f46a91d0d12ae524eba65f9 Mon Sep 17 00:00:00 2001 From: Jake Howell Date: Sat, 20 Dec 2025 00:20:57 +1100 Subject: [PATCH] feat: add prometheus observability metrics for `dbpurge` (#21074) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Related to [`internal#1139`](https://github.com/coder/internal/issues/1139) This implements some prometheus metrics for records being removed from the database. Currently we're tracking the following fields being removed from the DB by this. They're viewable in the `/api/v2/debug/metrics` endpoint. * `expired_api_keys` * `aibridge_records` * `connection_logs` * `duration` ``` # HELP coderd_dbpurge_iteration_duration_seconds Duration of each dbpurge iteration in seconds. # TYPE coderd_dbpurge_iteration_duration_seconds histogram coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="1"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="5"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="10"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="30"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="60"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="300"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="600"} 1 coderd_dbpurge_iteration_duration_seconds_bucket{success="true",le="+Inf"} 1 coderd_dbpurge_iteration_duration_seconds_sum{success="true"} 0.014787814 coderd_dbpurge_iteration_duration_seconds_count{success="true"} 1 # HELP coderd_dbpurge_records_purged_total Total number of records purged by type. # TYPE coderd_dbpurge_records_purged_total counter coderd_dbpurge_records_purged_total{record_type="aibridge_records"} 0 coderd_dbpurge_records_purged_total{record_type="audit_logs"} 0 coderd_dbpurge_records_purged_total{record_type="connection_logs"} 0 coderd_dbpurge_records_purged_total{record_type="expired_api_keys"} 0 coderd_dbpurge_records_purged_total{record_type="workspace_agent_logs"} 0 ``` | Position | Pull-request | | -------- | ------------ | | ✅ | [feat: add prometheus observability metrics for `dbpurge`](https://github.com/coder/coder/pull/21074) | | | [feat: add rbac specificity for `dbpurge`](https://github.com/coder/coder/pull/21088) | --- cli/server.go | 2 +- coderd/database/dbpurge/dbpurge.go | 34 +++++- coderd/database/dbpurge/dbpurge_test.go | 133 +++++++++++++++++++++--- 3 files changed, 154 insertions(+), 15 deletions(-) diff --git a/cli/server.go b/cli/server.go index dbc35141e8..29bce5f53c 100644 --- a/cli/server.go +++ b/cli/server.go @@ -1038,7 +1038,7 @@ func (r *RootCmd) Server(newAPI func(context.Context, *coderd.Options) (*coderd. defer shutdownConns() // Ensures that old database entries are cleaned up over time! - purger := dbpurge.New(ctx, logger.Named("dbpurge"), options.Database, options.DeploymentValues, quartz.NewReal()) + purger := dbpurge.New(ctx, logger.Named("dbpurge"), options.Database, options.DeploymentValues, quartz.NewReal(), options.PrometheusRegistry) defer purger.Close() // Updates workspace usage diff --git a/coderd/database/dbpurge/dbpurge.go b/coderd/database/dbpurge/dbpurge.go index 8646fb6d02..540724909f 100644 --- a/coderd/database/dbpurge/dbpurge.go +++ b/coderd/database/dbpurge/dbpurge.go @@ -7,6 +7,8 @@ import ( "golang.org/x/xerrors" + "github.com/prometheus/client_golang/prometheus" + "cdr.dev/slog" "github.com/coder/coder/v2/coderd/database" @@ -40,13 +42,30 @@ const ( // It is the caller's responsibility to call Close on the returned instance. // // This is for cleaning up old, unused resources from the database that take up space. -func New(ctx context.Context, logger slog.Logger, db database.Store, vals *codersdk.DeploymentValues, clk quartz.Clock) io.Closer { +func New(ctx context.Context, logger slog.Logger, db database.Store, vals *codersdk.DeploymentValues, clk quartz.Clock, reg prometheus.Registerer) io.Closer { closed := make(chan struct{}) ctx, cancelFunc := context.WithCancel(ctx) //nolint:gocritic // The system purges old db records without user input. ctx = dbauthz.AsSystemRestricted(ctx) + iterationDuration := prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Namespace: "coderd", + Subsystem: "dbpurge", + Name: "iteration_duration_seconds", + Help: "Duration of each dbpurge iteration in seconds.", + Buckets: []float64{1, 5, 10, 30, 60, 300, 600}, // 1s to 10min + }, []string{"success"}) + reg.MustRegister(iterationDuration) + + recordsPurged := prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: "coderd", + Subsystem: "dbpurge", + Name: "records_purged_total", + Help: "Total number of records purged by type.", + }, []string{"record_type"}) + reg.MustRegister(recordsPurged) + // Start the ticker with the initial delay. ticker := clk.NewTicker(delay) doTick := func(ctx context.Context, start time.Time) { @@ -164,9 +183,22 @@ func New(ctx context.Context, logger slog.Logger, db database.Store, vals *coder slog.F("duration", clk.Since(start)), ) + duration := clk.Since(start) + iterationDuration.WithLabelValues("true").Observe(duration.Seconds()) + recordsPurged.WithLabelValues("workspace_agent_logs").Add(float64(purgedWorkspaceAgentLogs)) + recordsPurged.WithLabelValues("expired_api_keys").Add(float64(expiredAPIKeys)) + recordsPurged.WithLabelValues("aibridge_records").Add(float64(purgedAIBridgeRecords)) + recordsPurged.WithLabelValues("connection_logs").Add(float64(purgedConnectionLogs)) + recordsPurged.WithLabelValues("audit_logs").Add(float64(purgedAuditLogs)) + return nil }, database.DefaultTXOptions().WithID("db_purge")); err != nil { logger.Error(ctx, "failed to purge old database entries", slog.Error(err)) + + // Record metrics for failed purge iteration. + duration := clk.Since(start) + iterationDuration.WithLabelValues("false").Observe(duration.Seconds()) + return } } diff --git a/coderd/database/dbpurge/dbpurge_test.go b/coderd/database/dbpurge/dbpurge_test.go index 05092dd3a3..68bad45cda 100644 --- a/coderd/database/dbpurge/dbpurge_test.go +++ b/coderd/database/dbpurge/dbpurge_test.go @@ -12,14 +12,17 @@ import ( "time" "github.com/google/uuid" + "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/goleak" "go.uber.org/mock/gomock" + "golang.org/x/xerrors" "cdr.dev/slog" "cdr.dev/slog/sloggers/slogtest" + "github.com/coder/coder/v2/coderd/coderdtest/promhelp" "github.com/coder/coder/v2/coderd/database" "github.com/coder/coder/v2/coderd/database/dbgen" "github.com/coder/coder/v2/coderd/database/dbmock" @@ -52,11 +55,114 @@ func TestPurge(t *testing.T) { done := awaitDoTick(ctx, t, clk) mDB := dbmock.NewMockStore(gomock.NewController(t)) mDB.EXPECT().InTx(gomock.Any(), database.DefaultTXOptions().WithID("db_purge")).Return(nil).Times(2) - purger := dbpurge.New(context.Background(), testutil.Logger(t), mDB, &codersdk.DeploymentValues{}, clk) + purger := dbpurge.New(context.Background(), testutil.Logger(t), mDB, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) <-done // wait for doTick() to run. require.NoError(t, purger.Close()) } +//nolint:paralleltest // It uses LockIDDBPurge. +func TestMetrics(t *testing.T) { + t.Run("SuccessfulIteration", func(t *testing.T) { + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + reg := prometheus.NewRegistry() + clk := quartz.NewMock(t) + now := time.Date(2025, 1, 15, 7, 30, 0, 0, time.UTC) + clk.Set(now).MustWait(ctx) + + db, _ := dbtestutil.NewDB(t) + logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}) + user := dbgen.User(t, db, database.User{}) + + oldExpiredKey, _ := dbgen.APIKey(t, db, database.APIKey{ + UserID: user.ID, + ExpiresAt: now.Add(-8 * 24 * time.Hour), // Expired 8 days ago + TokenName: "old-expired-key", + }) + + _, err := db.GetAPIKeyByID(ctx, oldExpiredKey.ID) + require.NoError(t, err, "key should exist before purge") + + done := awaitDoTick(ctx, t, clk) + closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{ + Retention: codersdk.RetentionConfig{ + APIKeys: serpent.Duration(7 * 24 * time.Hour), // 7 days retention + }, + }, clk, reg) + defer closer.Close() + testutil.TryReceive(ctx, t, done) + + hist := promhelp.HistogramValue(t, reg, "coderd_dbpurge_iteration_duration_seconds", prometheus.Labels{ + "success": "true", + }) + require.NotNil(t, hist) + require.Greater(t, hist.GetSampleCount(), uint64(0), "should have at least one sample") + + expiredAPIKeys := promhelp.CounterValue(t, reg, "coderd_dbpurge_records_purged_total", prometheus.Labels{ + "record_type": "expired_api_keys", + }) + require.Greater(t, expiredAPIKeys, 0, "should have deleted at least one expired API key") + + _, err = db.GetAPIKeyByID(ctx, oldExpiredKey.ID) + require.Error(t, err, "key should be deleted after purge") + + workspaceAgentLogs := promhelp.CounterValue(t, reg, "coderd_dbpurge_records_purged_total", prometheus.Labels{ + "record_type": "workspace_agent_logs", + }) + require.GreaterOrEqual(t, workspaceAgentLogs, 0) + + aibridgeRecords := promhelp.CounterValue(t, reg, "coderd_dbpurge_records_purged_total", prometheus.Labels{ + "record_type": "aibridge_records", + }) + require.GreaterOrEqual(t, aibridgeRecords, 0) + + connectionLogs := promhelp.CounterValue(t, reg, "coderd_dbpurge_records_purged_total", prometheus.Labels{ + "record_type": "connection_logs", + }) + require.GreaterOrEqual(t, connectionLogs, 0) + + auditLogs := promhelp.CounterValue(t, reg, "coderd_dbpurge_records_purged_total", prometheus.Labels{ + "record_type": "audit_logs", + }) + require.GreaterOrEqual(t, auditLogs, 0) + }) + + t.Run("FailedIteration", func(t *testing.T) { + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + reg := prometheus.NewRegistry() + clk := quartz.NewMock(t) + now := clk.Now() + clk.Set(now).MustWait(ctx) + + ctrl := gomock.NewController(t) + mDB := dbmock.NewMockStore(ctrl) + mDB.EXPECT().InTx(gomock.Any(), database.DefaultTXOptions().WithID("db_purge")). + Return(xerrors.New("simulated database error")). + MinTimes(1) + + logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}) + + done := awaitDoTick(ctx, t, clk) + closer := dbpurge.New(ctx, logger, mDB, &codersdk.DeploymentValues{}, clk, reg) + defer closer.Close() + testutil.TryReceive(ctx, t, done) + + hist := promhelp.HistogramValue(t, reg, "coderd_dbpurge_iteration_duration_seconds", prometheus.Labels{ + "success": "false", + }) + require.NotNil(t, hist) + require.Greater(t, hist.GetSampleCount(), uint64(0), "should have at least one sample") + + successHist := promhelp.MetricValue(t, reg, "coderd_dbpurge_iteration_duration_seconds", prometheus.Labels{ + "success": "true", + }) + require.Nil(t, successHist, "should not have success=true metric on failure") + }) +} + //nolint:paralleltest // It uses LockIDDBPurge. func TestDeleteOldWorkspaceAgentStats(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong) @@ -130,7 +236,7 @@ func TestDeleteOldWorkspaceAgentStats(t *testing.T) { }) // when - closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk) + closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) defer closer.Close() // then @@ -155,7 +261,7 @@ func TestDeleteOldWorkspaceAgentStats(t *testing.T) { // Start a new purger to immediately trigger delete after rollup. _ = closer.Close() - closer = dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk) + closer = dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) defer closer.Close() // then @@ -250,7 +356,8 @@ func TestDeleteOldWorkspaceAgentLogs(t *testing.T) { Retention: codersdk.RetentionConfig{ WorkspaceAgentLogs: serpent.Duration(7 * 24 * time.Hour), }, - }, clk) + }, clk, prometheus.NewRegistry()) + defer closer.Close() <-done // doTick() has now run. @@ -464,7 +571,7 @@ func TestDeleteOldWorkspaceAgentLogsRetention(t *testing.T) { done := awaitDoTick(ctx, t, clk) closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{ Retention: tc.retentionConfig, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done) @@ -555,7 +662,7 @@ func TestDeleteOldProvisionerDaemons(t *testing.T) { require.NoError(t, err) // when - closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk) + closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) defer closer.Close() // then @@ -659,7 +766,7 @@ func TestDeleteOldAuditLogConnectionEvents(t *testing.T) { // Run the purge done := awaitDoTick(ctx, t, clk) - closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk) + closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) defer closer.Close() // Wait for tick testutil.TryReceive(ctx, t, done) @@ -822,7 +929,7 @@ func TestDeleteOldTelemetryHeartbeats(t *testing.T) { require.NoError(t, err) done := awaitDoTick(ctx, t, clk) - closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk) + closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{}, clk, prometheus.NewRegistry()) defer closer.Close() <-done // doTick() has now run. @@ -941,7 +1048,7 @@ func TestDeleteOldConnectionLogs(t *testing.T) { done := awaitDoTick(ctx, t, clk) closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{ Retention: tc.retentionConfig, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done) @@ -1197,7 +1304,7 @@ func TestDeleteOldAIBridgeRecords(t *testing.T) { Retention: serpent.Duration(tc.retention), }, }, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done) @@ -1284,7 +1391,7 @@ func TestDeleteOldAuditLogs(t *testing.T) { done := awaitDoTick(ctx, t, clk) closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{ Retention: tc.retentionConfig, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done) @@ -1374,7 +1481,7 @@ func TestDeleteOldAuditLogs(t *testing.T) { Retention: codersdk.RetentionConfig{ AuditLogs: serpent.Duration(retentionPeriod), }, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done) @@ -1494,7 +1601,7 @@ func TestDeleteExpiredAPIKeys(t *testing.T) { done := awaitDoTick(ctx, t, clk) closer := dbpurge.New(ctx, logger, db, &codersdk.DeploymentValues{ Retention: tc.retentionConfig, - }, clk) + }, clk, prometheus.NewRegistry()) defer closer.Close() testutil.TryReceive(ctx, t, done)