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=<itself>, 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

@@ -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

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")
+}

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())
 }

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")
+}