Checkpoint without waiting on readers and log a busy checkpoint (closes #102)

The 5-second checkpoint ran in TRUNCATE mode, which waits up to the
5-second busy timeout for every open read while holding the database
lock every batch write needs. It now runs in PASSIVE mode, which never
waits. A WAL file over 64 MiB instead gets one TRUNCATE checkpoint whose
wait for reads is capped at 500 ms and logged; it empties the file once
no read is open, and while reads follow one another with no pause it
can give up every time. A checkpoint that leaves part of the WAL
uncopied returns ErrCheckpointIncomplete, which the maintainer logs as
incomplete instead of completed. The writing connection's
journal_size_limit is 64 MiB.

Model: opus-5-5

internal/routewatch/dbmaintainer.go

@@ -2,6 +2,7 @@ package routewatch
 
 import (
 	"context"
+	"errors"
 	"log/slog"
 	"sync"
 	"time"
@@ -34,6 +35,12 @@ const (
 	analyzeTimeout = 5 * time.Minute
 )
 
+// checkpointIncompleteMessage is logged, at debug level like a completed
+// checkpoint, when a checkpoint leaves part of the WAL for a later one: while
+// reads overlap, most do. The database warns when the WAL file stays over its
+// size limit.
+const checkpointIncompleteMessage = "WAL checkpoint incomplete"
+
 // DBMaintainer handles background database maintenance tasks.
 type DBMaintainer struct {
 	db     database.Store
@@ -123,9 +130,13 @@ func (m *DBMaintainer) runCheckpoint(ctx context.Context) {
 	duration, err := runWithTimeout(ctx, checkpointTimeout, m.db.Checkpoint)
 	m.recordResult(&m.lastCheckpoint, &m.lastCheckpointError, &m.checkpointCount, err)
 
-	if err != nil {
+	switch {
+	case errors.Is(err, database.ErrCheckpointIncomplete):
+		m.logger.Debug(checkpointIncompleteMessage,
+			"error", err, "duration", duration)
+	case err != nil:
 		m.logger.Error("WAL checkpoint failed", "error", err, "duration", duration)
-	} else {
+	default:
 		m.logger.Debug("WAL checkpoint completed", "duration", duration)
 	}
 }

internal/routewatch/dbmaintainer_internal_test.go

@@ -0,0 +1,54 @@
+package routewatch
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"testing"
+
+	"git.eeqj.de/sneak/routewatch/internal/database"
+)
+
+// incompleteCheckpointStore is a store whose every checkpoint leaves part of
+// the WAL uncopied.
+type incompleteCheckpointStore struct{ *mockStore }
+
+// Checkpoint reports the checkpoint incomplete.
+func (incompleteCheckpointStore) Checkpoint(context.Context) error {
+	return database.ErrCheckpointIncomplete
+}
+
+// TestIncompleteCheckpointNotLoggedAsCompleted runs a checkpoint that leaves
+// part of the WAL uncopied and checks that the maintainer logs it as
+// incomplete, not as completed, and does not count it as a checkpoint that
+// completed.
+func TestIncompleteCheckpointNotLoggedAsCompleted(t *testing.T) {
+	t.Parallel()
+
+	var logs bytes.Buffer
+
+	logger := slog.New(slog.NewJSONHandler(&logs,
+		&slog.HandlerOptions{Level: slog.LevelDebug}))
+	m := NewDBMaintainer(incompleteCheckpointStore{newMockStore()}, logger)
+
+	m.runCheckpoint(t.Context())
+
+	var logged struct {
+		Msg string `json:"msg"`
+	}
+
+	err := json.Unmarshal(logs.Bytes(), &logged)
+	if err != nil {
+		t.Fatalf("want one log message, got %q: %v", logs.String(), err)
+	}
+
+	if logged.Msg != checkpointIncompleteMessage {
+		t.Errorf("logged %q, want %q", logged.Msg, checkpointIncompleteMessage)
+	}
+
+	if m.checkpointCount != 0 {
+		t.Errorf("checkpointCount = %d after an incomplete checkpoint, want 0",
+			m.checkpointCount)
+	}
+}