From a16b667cbb4bb6f493d026192ae92af62cb462bf Mon Sep 17 00:00:00 2001 From: Julian Sommer <115516918+juliansommer@users.noreply.github.com> Date: Wed, 21 Oct 2026 09:31:57 +1100 Subject: [PATCH] fix: log the local node as node, not holder, in reconcile/lock and kvlease lease lines (#1234) A node that lost the election logged holder=, which reads as though it holds the lock. Lease lines now carry the local node as node, and a refused claim logs the node that owns the key, read from the Get the claim already makes, as holder at debug level. --- spinifex/domains/network/reconcile/lock.go | 4 +- .../domains/network/reconcile/lock_test.go | 34 ++++++++++++++ spinifex/foundation/state/kvlease/lease.go | 15 ++++-- .../foundation/state/kvlease/lease_test.go | 47 +++++++++++++++++++ 4 files changed, 94 insertions(+), 6 deletions(-) diff --git a/spinifex/domains/network/reconcile/lock.go b/spinifex/domains/network/reconcile/lock.go index ad625eb65..5f3a5111c 100644 --- a/spinifex/domains/network/reconcile/lock.go +++ b/spinifex/domains/network/reconcile/lock.go @@ -41,12 +41,12 @@ func AcquireLeader(ctx context.Context, nc *nats.Conn, bucket, holder string) (f }) if err != nil { slog.ErrorContext(ctx, "reconcile/lock: lease config invalid", - "holder", holder, "bucket", bucket, "err", err) + "node", holder, "bucket", bucket, "err", err) return nil, false } if !lease.TryAcquire(ctx) { slog.InfoContext(ctx, "reconcile/lock: not leader, skipping reconcile", - "holder", holder, "bucket", bucket) + "node", holder, "bucket", bucket) return nil, false } return func() { lease.Release(ctx) }, true diff --git a/spinifex/domains/network/reconcile/lock_test.go b/spinifex/domains/network/reconcile/lock_test.go index 3024c8f36..7d12e5a27 100644 --- a/spinifex/domains/network/reconcile/lock_test.go +++ b/spinifex/domains/network/reconcile/lock_test.go @@ -1,7 +1,10 @@ package reconcile import ( + "bytes" "context" + "encoding/json" + "log/slog" "testing" "time" @@ -103,3 +106,34 @@ func TestAcquireLeader_ReleaseDoesNotDeleteSuccessorKey(t *testing.T) { require.NoError(t, err, "stale release deleted the successor's leader key") assert.Equal(t, "node-2", string(entry.Value()), "successor's key must survive a stale release") } + +// A node that loses the election logs itself as node: "holder=node-2" on +// node-2's log reads as though node-2 holds the lock. +func TestAcquireLeader_NotLeaderLogNamesLocalNode(t *testing.T) { + _, nc, _ := testutil.StartTestJetStream(t) + + release, ok := AcquireLeader(t.Context(), nc, KVBucketVPCDReconcile, "node-1") + require.True(t, ok) + defer release() + + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))) + t.Cleanup(func() { slog.SetDefault(prev) }) + + _, ok = AcquireLeader(t.Context(), nc, KVBucketVPCDReconcile, "node-2") + require.False(t, ok) + + var line map[string]any + dec := json.NewDecoder(&buf) + for dec.More() { + var rec map[string]any + require.NoError(t, dec.Decode(&rec)) + if rec["msg"] == "reconcile/lock: not leader, skipping reconcile" { + line = rec + } + } + require.NotNil(t, line, "a losing acquire must log that it is skipping") + assert.Equal(t, "node-2", line["node"]) + assert.NotEqual(t, "node-2", line["holder"], "the local node is not the holder") +} diff --git a/spinifex/foundation/state/kvlease/lease.go b/spinifex/foundation/state/kvlease/lease.go index 7412be9f5..d3d504469 100644 --- a/spinifex/foundation/state/kvlease/lease.go +++ b/spinifex/foundation/state/kvlease/lease.go @@ -18,7 +18,10 @@ import ( // context and so cannot inherit the caller's deadline. const releaseTimeout = 5 * time.Second -var errNotHolder = errors.New("kvlease: another node holds the lease") +// heldError reports the node that owns the key when a claim loses to it. +type heldError struct{ holder string } + +func (e *heldError) Error() string { return "kvlease: lease held by " + e.holder } // BucketFunc returns the KV bucket holding the lease key. It is injected because // each subsystem initialises its own bucket, some with migrations attached. @@ -83,10 +86,11 @@ func (l *Lease) Held() bool { return l.held } -// logArgs prefixes the lease identity onto a log line's own fields. +// logArgs prefixes the lease identity onto a log line's own fields. The local +// node logs as "node"; "holder" is reserved for whoever owns the key. func (l *Lease) logArgs(extra ...any) []any { args := make([]any, 0, 4+len(l.cfg.Attrs)+len(extra)) - args = append(args, "lease", l.cfg.Name, "holder", l.cfg.Holder) + args = append(args, "lease", l.cfg.Name, "node", l.cfg.Holder) args = append(args, l.cfg.Attrs...) return append(args, extra...) } @@ -104,6 +108,9 @@ func (l *Lease) TryAcquire(ctx context.Context) bool { } rev, err := l.claim(ctx, kv) if err != nil { + if held, ok := errors.AsType[*heldError](err); ok { + slog.DebugContext(ctx, "kvlease: held by another node", l.logArgs("holder", held.holder)...) + } return false } @@ -142,7 +149,7 @@ func (l *Lease) claim(ctx context.Context, kv jetstream.KeyValue) (uint64, error return 0, gerr } if string(entry.Value()) != l.cfg.Holder { - return 0, errNotHolder + return 0, &heldError{holder: string(entry.Value())} } return kv.Update(ctx, l.cfg.Key, []byte(l.cfg.Holder), entry.Revision()) } diff --git a/spinifex/foundation/state/kvlease/lease_test.go b/spinifex/foundation/state/kvlease/lease_test.go index ee420dd7c..0fec0ac2c 100644 --- a/spinifex/foundation/state/kvlease/lease_test.go +++ b/spinifex/foundation/state/kvlease/lease_test.go @@ -3,6 +3,7 @@ package kvlease_test import ( "bytes" "context" + "encoding/json" "errors" "log/slog" "sync/atomic" @@ -388,3 +389,49 @@ func TestRelease_AfterRenewalLossWarns(t *testing.T) { a.Release(t.Context()) assert.Contains(t, buf.String(), "already lost before release") } + +// logLines captures default-logger output as decoded JSON records. +func logLines(t *testing.T) func() []map[string]any { + t.Helper() + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + t.Cleanup(func() { slog.SetDefault(prev) }) + return func() []map[string]any { + var out []map[string]any + dec := json.NewDecoder(&buf) + for dec.More() { + var rec map[string]any + require.NoError(t, dec.Decode(&rec)) + out = append(out, rec) + } + return out + } +} + +// "holder" must name whoever owns the key. The local node logs as "node", so a +// loser's log does not read as though it won. +func TestLogFields_SeparateLocalNodeFromCurrentHolder(t *testing.T) { + _, nc, _ := testutil.StartTestJetStream(t) + read := logLines(t) + + a := newTestLease(t, nc, "node-a", nil) + require.True(t, a.TryAcquire(t.Context())) + t.Cleanup(func() { a.Release(t.Context()) }) + b := newTestLease(t, nc, "node-b", nil) + require.False(t, b.TryAcquire(t.Context())) + + var elected, refused map[string]any + for _, rec := range read() { + switch { + case rec["msg"] == "kvlease: elected" && rec["node"] == "node-a": + elected = rec + case rec["node"] == "node-b": + refused = rec + } + } + require.NotNil(t, elected, "the elected line must carry the local node as node") + assert.NotContains(t, elected, "holder") + require.NotNil(t, refused, "a refused acquire must log the local node as node") + assert.Equal(t, "node-a", refused["holder"], "a refused acquire must report the node that holds the key") +}