2de317d feat(kv): one log record per writer group, zerowrap logging, ctx on every operation · ermite-kv

M batch.go +5 -4


@@ -80,13 +80,14 @@ func (b *Batch) Reset() {
80	80		b.err = nil
81	81		}
82	82
83		-	// payload returns the encoded record payload size; 0 for a batch without
84		-	// ops, which writes nothing.
85		-	func (b *Batch) payload() int {
	83	+	// encodedSize returns the size of the batch in a log record (op count and
	84	+	// ops), which MaxBatchBytes limits; 0 for a batch without ops, which writes
	85	+	// nothing.
	86	+	func (b *Batch) encodedSize() int {
86	87		if len(b.ops) == 0 {
87	88		return 0
88	89		}
89		-	return recordMinBody + b.opsBytes
	90	+	return batchHeader + b.opsBytes
90	91		}
91	92
92	93		func (b *Batch) add(o op) {

 	b.err = nil
 }
-// payload returns the encoded record payload size; 0 for a batch without
+// encodedSize returns the size of the batch in a log record (op count and
-// ops, which writes nothing.
+// ops), which MaxBatchBytes limits; 0 for a batch without ops, which writes
-func (b *Batch) payload() int {
+// nothing.
+func (b *Batch) encodedSize() int {
 	if len(b.ops) == 0 {
 		return 0
 	}
-	return recordMinBody + b.opsBytes
+	return batchHeader + b.opsBytes
 }
 func (b *Batch) add(o op) {

M batch_test.go +8 -8


@@ -52,8 +52,8 @@ func TestBatchErrors(t *testing.T) {
52	52		t.Fatalf("err = %v, want ErrInvalidKey", b.err)
53	53		}
54	54		b.Reset()
55		-	if b.err != nil \|\| b.Len() != 0 \|\| b.payload() != 0 {
56		-	t.Fatalf("Reset left err=%v len=%d payload=%d", b.err, b.Len(), b.payload())
	55	+	if b.err != nil \|\| b.Len() != 0 \|\| b.encodedSize() != 0 {
	56	+	t.Fatalf("Reset left err=%v len=%d size=%d", b.err, b.Len(), b.encodedSize())
57	57		}
58	58		})
59	59		}

@@ -65,19 +65,19 @@ func TestBatchErrors(t *testing.T) {
65	65		}
66	66		}
67	67
68		-	func TestBatchPayload(t *testing.T) {
	68	+	func TestBatchEncodedSize(t *testing.T) {
69	69		var b Batch
70		-	if b.payload() != 0 {
	70	+	if b.encodedSize() != 0 {
71	71		t.Fatal("empty batch has a payload")
72	72		}
73	73		b.RequireAbsent([]byte("k"))
74		-	if b.payload() != 0 {
	74	+	if b.encodedSize() != 0 {
75	75		t.Fatal("precondition-only batch has a payload")
76	76		}
77	77		b.Put([]byte("k"), []byte(strings.Repeat("v", 200)))
78	78		b.Delete([]byte("kk"))
79		-	want := len(appendRecord(nil, 1, b.ops)) - recordFrame
80		-	if got := b.payload(); got != want {
81		-	t.Fatalf("payload = %d, encoded record payload = %d", got, want)
	79	+	want := len(appendRecord(nil, 1, b.ops)) - recordFrame - recordHead
	80	+	if got := b.encodedSize(); got != want {
	81	+	t.Fatalf("payload = %d, encoded batch = %d", got, want)
82	82		}
83	83		}


@@ -52,8 +52,8 @@ func TestBatchErrors(t *testing.T) {
52		t.Fatalf("err = %v, want ErrInvalidKey", b.err)	52		t.Fatalf("err = %v, want ErrInvalidKey", b.err)
53		}	53		}
54		b.Reset()	54		b.Reset()
55	-	if b.err != nil \|\| b.Len() != 0 \|\| b.payload() != 0 {	55	+	if b.err != nil \|\| b.Len() != 0 \|\| b.encodedSize() != 0 {
56	-	t.Fatalf("Reset left err=%v len=%d payload=%d", b.err, b.Len(), b.payload())	56	+	t.Fatalf("Reset left err=%v len=%d size=%d", b.err, b.Len(), b.encodedSize())
57		}	57		}
58		})	58		})
59		}	59		}

@@ -65,19 +65,19 @@ func TestBatchErrors(t *testing.T) {
65		}	65		}
66		}	66		}
67			67
68	-	func TestBatchPayload(t *testing.T) {	68	+	func TestBatchEncodedSize(t *testing.T) {
69		var b Batch	69		var b Batch
70	-	if b.payload() != 0 {	70	+	if b.encodedSize() != 0 {
71		t.Fatal("empty batch has a payload")	71		t.Fatal("empty batch has a payload")
72		}	72		}
73		b.RequireAbsent([]byte("k"))	73		b.RequireAbsent([]byte("k"))
74	-	if b.payload() != 0 {	74	+	if b.encodedSize() != 0 {
75		t.Fatal("precondition-only batch has a payload")	75		t.Fatal("precondition-only batch has a payload")
76		}	76		}
77		b.Put([]byte("k"), []byte(strings.Repeat("v", 200)))	77		b.Put([]byte("k"), []byte(strings.Repeat("v", 200)))
78		b.Delete([]byte("kk"))	78		b.Delete([]byte("kk"))
79	-	want := len(appendRecord(nil, 1, b.ops)) - recordFrame	79	+	want := len(appendRecord(nil, 1, b.ops)) - recordFrame - recordHead
80	-	if got := b.payload(); got != want {	80	+	if got := b.encodedSize(); got != want {
81	-	t.Fatalf("payload = %d, encoded record payload = %d", got, want)	81	+	t.Fatalf("payload = %d, encoded batch = %d", got, want)
82		}	82		}
83		}	83		}

M db.go +47 -26


@@ -6,11 +6,12 @@ import (
6	6		"context"
7	7		"fmt"
8	8		"io"
9		-	"log/slog"
10	9		"sync"
11	10		"sync/atomic"
12	11		"time"
13	12
	13	+	"github.com/bnema/zerowrap"
	14	+
14	15		"bnema.dev/ermite-kv/internal/fsys"
15	16		)
16	17

@@ -18,16 +19,23 @@ import (
18	19		const (
19	20		defaultMaxBatchBytes = 16 << 20
20	21		defaultCompactAfter = 64 << 20
	22	+
	23	+	// maxBatchLimit is the largest encoded batch that fits in a record
	24	+	// together with the record head (seq and batch count).
	25	+	maxBatchLimit = maxRecord - recordHead
21	26		)
22	27
23	28		// Options configures Open. The zero value of every field means "default";
24	29		// Options{} is safe and durable.
25	30		type Options struct {
26	31		// NoSync skips fdatasync on commits. For tests and benchmarks only: an
27		-	// acknowledged batch may be lost on power failure.
	32	+	// acknowledged batch may be lost on power failure, and a power loss can
	33	+	// leave a log that Open rejects with ErrCorrupt (the pages of one
	34	+	// unsynced group may reach the disk out of order, which recovery cannot
	35	+	// tell from damage to acknowledged data).
28	36		NoSync bool
29		-	// MaxBatchBytes is the encoded batch limit. 0 means 16 MiB; it must be
30		-	// at most 64 MiB (the format limit).
	37	+	// MaxBatchBytes is the encoded batch limit (op count and ops). 0 means
	38	+	// 16 MiB; it must be at most 64 MiB minus 12 bytes (the format limit).
31	39		MaxBatchBytes int
32	40		// CompactAfter is the number of bytes in the current log that trigger
33	41		// compaction. 0 means 64 MiB; a negative value disables compaction.

@@ -35,15 +43,13 @@ type Options struct {
35	43		// GroupWindow is the extra time the writer waits to grow a commit
36	44		// group. 0 means it only drains what is already queued.
37	45		GroupWindow time.Duration
38		-	// Logger receives warnings and errors. nil discards them.
39		-	Logger *slog.Logger
40	46		}
41	47
42	48		// resolve validates o and fills in the defaults.
43	49		func (o Options) resolve() (Options, error) {
44	50		switch {
45		-	case o.MaxBatchBytes < 0 \|\| o.MaxBatchBytes > maxRecord:
46		-	return o, fmt.Errorf("kv: invalid MaxBatchBytes %d: must be in [0, %d]", o.MaxBatchBytes, maxRecord)
	51	+	case o.MaxBatchBytes < 0 \|\| o.MaxBatchBytes > maxBatchLimit:
	52	+	return o, fmt.Errorf("kv: invalid MaxBatchBytes %d: must be in [0, %d]", o.MaxBatchBytes, maxBatchLimit)
47	53		case o.GroupWindow < 0:
48	54		return o, fmt.Errorf("kv: invalid GroupWindow %v: must not be negative", o.GroupWindow)
49	55		}

@@ -53,9 +59,6 @@ func (o Options) resolve() (Options, error) {
53	59		if o.CompactAfter == 0 {
54	60		o.CompactAfter = defaultCompactAfter
55	61		}
56		-	if o.Logger == nil {
57		-	o.Logger = slog.New(slog.DiscardHandler)
58		-	}
59	62		return o, nil
60	63		}
61	64

@@ -63,7 +66,9 @@ func (o Options) resolve() (Options, error) {
63	66		// for concurrent use.
64	67		type DB struct {
65	68		fx fsys.FS
	69	+	dir string
66	70		opts Options
	71	+	log zerowrap.Logger // captured at Open; used by the writer
67	72		snap atomic.Pointer[Snapshot] // last published state
68	73
69	74		reqCh chan *request // never closed

@@ -75,12 +80,11 @@ type DB struct {
75	80		failErr error // first cause, wrapping ErrFailed; set before failed is closed
76	81
77	82		closeOnce sync.Once
78		-	closeErr error
79	83
80	84		lock io.Closer
81	85
82	86		// Owned by the writer goroutine (see writer.go).
83		-	log fsys.File
	87	+	file fsys.File
84	88		logBase uint64 // seq the current log starts after
85	89		logSize int64 // bytes in the current log, header included
86	90		buf []byte // group encoding buffer

@@ -91,17 +95,23 @@ type DB struct {
91	95		// takes an exclusive lock on the directory, returning ErrLocked if another
92	96		// DB holds it, and recovers the state from the snapshot and logs. Invalid
93	97		// options are an error.
94		-	func Open(dir string, opts Options) (*DB, error) {
95		-	return open(fsys.OS(), dir, opts)
	98	+	//
	99	+	// The logger of ctx (zerowrap.FromCtx), enriched with the component and the
	100	+	// directory, is used for the life of the DB; ctx is not used for anything
	101	+	// else and does not bound the life of the DB.
	102	+	func Open(ctx context.Context, dir string, opts Options) (*DB, error) {
	103	+	return open(ctx, fsys.OS(), dir, opts)
96	104		}
97	105
98		-	func open(fx fsys.FS, dir string, opts Options) (*DB, error) {
	106	+	func open(ctx context.Context, fx fsys.FS, dir string, opts Options) (*DB, error) {
99	107		opts, err := opts.resolve()
100	108		if err != nil {
101	109		return nil, err
102	110		}
	111	+	start := time.Now()
	112	+	log := zerowrap.FromCtxWithFields(ctx, map[string]any{"component": "ermite-kv", "dir": dir})
103	113		bld := tree{}.builder()
104		-	rec, err := recoverDir(fx, dir, opts.Logger,
	114	+	rec, err := recoverDir(fx, dir, log,
105	115		func(key, value []byte, version uint64) {
106	116		// Snapshot entries alias one shared file buffer: copy them so
107	117		// the tree does not keep the whole buffer alive.

@@ -124,29 +134,36 @@ func open(fx fsys.FS, dir string, opts Options) (*DB, error) {
124	134		}
125	135		db := &DB{
126	136		fx: fx,
	137	+	dir: dir,
127	138		opts: opts,
	139	+	log: log,
128	140		reqCh: make(chan *request),
129	141		closing: make(chan struct{}),
130	142		done: make(chan struct{}),
131	143		failed: make(chan struct{}),
132	144		lock: rec.lock,
133		-	log: rec.log,
	145	+	file: rec.log,
134	146		logBase: rec.logBase,
135	147		logSize: rec.logSize,
136	148		}
137		-	db.snap.Store(newSnapshot(bld.freeze(), rec.lastSeq))
	149	+	t := bld.freeze()
	150	+	db.snap.Store(newSnapshot(t, rec.lastSeq))
138	151		go db.writer()
	152	+	log.Info().Uint64("seq", rec.lastSeq).Int("keys", t.len()).Uint64("snapshot_seq", rec.snapSeq).
	153	+	Dur("duration", time.Since(start)).Msg("opened")
139	154		return db, nil
140	155		}
141	156
142	157		// Close stops the database: requests not yet taken by the writer get
143	158		// ErrClosed, the group in progress is committed and acknowledged, then the
144	159		// log is closed and the directory lock released. Snapshots stay readable.
	160	+	// Close always completes: ctx is only used for the logger of the closing
	161	+	// message.
145	162		//
146	163		// Close returns the first error met while stopping, including the cause of
147	164		// the failed state if the database failed, or nil. It is idempotent: later
148	165		// calls return nil.
149		-	func (db *DB) Close() error {
	166	+	func (db *DB) Close(ctx context.Context) error {
150	167		var err error
151	168		db.closeOnce.Do(func() {
152	169		close(db.closing)

@@ -157,22 +174,26 @@ func (db *DB) Close() error {
157	174		err = db.failErr
158	175		default:
159	176		}
160		-	if cerr := db.log.Close(); err == nil {
	177	+	if cerr := db.file.Close(); err == nil {
161	178		err = cerr
162	179		}
163	180		if cerr := db.lock.Close(); err == nil {
164	181		err = cerr
165	182		}
	183	+	log := zerowrap.FromCtxWithFields(ctx, map[string]any{"component": "ermite-kv", "dir": db.dir})
	184	+	log.Info().Uint64("seq", db.snap.Load().Seq()).Err(err).Msg("closed")
166	185		})
167	186		return err
168	187		}
169	188
170	189		// Snapshot returns the current immutable state. It is lock-free and O(1), and
171		-	// remains usable after Close.
172		-	func (db DB) Snapshot() Snapshot { return db.snap.Load() }
	190	+	// remains usable after Close. Like every read, it ignores ctx.
	191	+	func (db DB) Snapshot(_ context.Context) Snapshot { return db.snap.Load() }
173	192
174	193		// Get returns the item stored under key in the current snapshot.
175		-	func (db *DB) Get(key []byte) (Item, bool) { return db.snap.Load().Get(key) }
	194	+	func (db *DB) Get(ctx context.Context, key []byte) (Item, bool) {
	195	+	return db.snap.Load().Get(ctx, key)
	196	+	}
176	197
177	198		// Apply commits b atomically and returns its seq once it is durable (unless
178	199		// Options.NoSync) and visible in Snapshot.

@@ -193,7 +214,7 @@ func (db DB) Apply(ctx context.Context, b Batch) (uint64, error) {
193	214		if b.err != nil {
194	215		return 0, b.err
195	216		}
196		-	if b.payload() > db.opts.MaxBatchBytes {
	217	+	if b.encodedSize() > db.opts.MaxBatchBytes {
197	218		return 0, ErrBatchTooLarge
198	219		}
199	220		select {

@@ -219,6 +240,6 @@ func (db DB) Apply(ctx context.Context, b Batch) (uint64, error) {
219	240		return 0, r.release(db.failErr)
220	241		}
221	242		res := <-r.reply // the writer always answers a request it has taken
222		-	r.release(nil)
	243	+	_ = r.release(nil)
223	244		return res.seq, res.err
224	245		}

 	"context"
 	"fmt"
 	"io"
-	"log/slog"
 	"sync"
 	"sync/atomic"
 	"time"
+	"github.com/bnema/zerowrap"
 	"bnema.dev/ermite-kv/internal/fsys"
 )
 const (
 	defaultMaxBatchBytes = 16 << 20
 	defaultCompactAfter  = 64 << 20
+	// maxBatchLimit is the largest encoded batch that fits in a record
+	// together with the record head (seq and batch count).
+	maxBatchLimit = maxRecord - recordHead
 )
 // Options configures Open. The zero value of every field means "default";
 // Options{} is safe and durable.
 type Options struct {
 	// NoSync skips fdatasync on commits. For tests and benchmarks only: an
-	// acknowledged batch may be lost on power failure.
+	// acknowledged batch may be lost on power failure, and a power loss can
+	// leave a log that Open rejects with ErrCorrupt (the pages of one
+	// unsynced group may reach the disk out of order, which recovery cannot
+	// tell from damage to acknowledged data).
 	NoSync bool
-	// MaxBatchBytes is the encoded batch limit. 0 means 16 MiB; it must be
+	// MaxBatchBytes is the encoded batch limit (op count and ops). 0 means
-	// at most 64 MiB (the format limit).
+	// 16 MiB; it must be at most 64 MiB minus 12 bytes (the format limit).
 	MaxBatchBytes int
 	// CompactAfter is the number of bytes in the current log that trigger
 	// compaction. 0 means 64 MiB; a negative value disables compaction.
 	// GroupWindow is the extra time the writer waits to grow a commit
 	// group. 0 means it only drains what is already queued.
 	GroupWindow time.Duration
-	// Logger receives warnings and errors. nil discards them.
-	Logger *slog.Logger
 }
 // resolve validates o and fills in the defaults.
 func (o Options) resolve() (Options, error) {
 	switch {
-	case o.MaxBatchBytes < 0 || o.MaxBatchBytes > maxRecord:
+	case o.MaxBatchBytes < 0 || o.MaxBatchBytes > maxBatchLimit:
-		return o, fmt.Errorf("kv: invalid MaxBatchBytes %d: must be in [0, %d]", o.MaxBatchBytes, maxRecord)
+		return o, fmt.Errorf("kv: invalid MaxBatchBytes %d: must be in [0, %d]", o.MaxBatchBytes, maxBatchLimit)
 	case o.GroupWindow < 0:
 		return o, fmt.Errorf("kv: invalid GroupWindow %v: must not be negative", o.GroupWindow)
 	}
 	if o.CompactAfter == 0 {
 		o.CompactAfter = defaultCompactAfter
 	}
-	if o.Logger == nil {
-		o.Logger = slog.New(slog.DiscardHandler)
-	}
 	return o, nil
 }
 // for concurrent use.
 type DB struct {
 	fx   fsys.FS
+	dir  string
 	opts Options
+	log  zerowrap.Logger          // captured at Open; used by the writer
 	snap atomic.Pointer[Snapshot] // last published state
 	reqCh   chan *request // never closed
 	failErr  error // first cause, wrapping ErrFailed; set before failed is closed
 	closeOnce sync.Once
-	closeErr  error
 	lock io.Closer
 	// Owned by the writer goroutine (see writer.go).
-	log     fsys.File
+	file    fsys.File
 	logBase uint64 // seq the current log starts after
 	logSize int64  // bytes in the current log, header included
 	buf     []byte // group encoding buffer
 // takes an exclusive lock on the directory, returning ErrLocked if another
 // DB holds it, and recovers the state from the snapshot and logs. Invalid
 // options are an error.
-func Open(dir string, opts Options) (*DB, error) {
+//
-	return open(fsys.OS(), dir, opts)
+// The logger of ctx (zerowrap.FromCtx), enriched with the component and the
+// directory, is used for the life of the DB; ctx is not used for anything
+// else and does not bound the life of the DB.
+func Open(ctx context.Context, dir string, opts Options) (*DB, error) {
+	return open(ctx, fsys.OS(), dir, opts)
 }
-func open(fx fsys.FS, dir string, opts Options) (*DB, error) {
+func open(ctx context.Context, fx fsys.FS, dir string, opts Options) (*DB, error) {
 	opts, err := opts.resolve()
 	if err != nil {
 		return nil, err
 	}
+	start := time.Now()
+	log := zerowrap.FromCtxWithFields(ctx, map[string]any{"component": "ermite-kv", "dir": dir})
 	bld := tree{}.builder()
-	rec, err := recoverDir(fx, dir, opts.Logger,
+	rec, err := recoverDir(fx, dir, log,
 		func(key, value []byte, version uint64) {
 			// Snapshot entries alias one shared file buffer: copy them so
 			// the tree does not keep the whole buffer alive.
 	}
 	db := &DB{
 		fx:      fx,
+		dir:     dir,
 		opts:    opts,
+		log:     log,
 		reqCh:   make(chan *request),
 		closing: make(chan struct{}),
 		done:    make(chan struct{}),
 		failed:  make(chan struct{}),
 		lock:    rec.lock,
-		log:     rec.log,
+		file:    rec.log,
 		logBase: rec.logBase,
 		logSize: rec.logSize,
 	}
-	db.snap.Store(newSnapshot(bld.freeze(), rec.lastSeq))
+	t := bld.freeze()
+	db.snap.Store(newSnapshot(t, rec.lastSeq))
 	go db.writer()
+	log.Info().Uint64("seq", rec.lastSeq).Int("keys", t.len()).Uint64("snapshot_seq", rec.snapSeq).
+		Dur("duration", time.Since(start)).Msg("opened")
 	return db, nil
 }
 // Close stops the database: requests not yet taken by the writer get
 // ErrClosed, the group in progress is committed and acknowledged, then the
 // log is closed and the directory lock released. Snapshots stay readable.
+// Close always completes: ctx is only used for the logger of the closing
+// message.
 //
 // Close returns the first error met while stopping, including the cause of
 // the failed state if the database failed, or nil. It is idempotent: later
 // calls return nil.
-func (db *DB) Close() error {
+func (db *DB) Close(ctx context.Context) error {
 	var err error
 	db.closeOnce.Do(func() {
 		close(db.closing)
 			err = db.failErr
 		default:
 		}
-		if cerr := db.log.Close(); err == nil {
+		if cerr := db.file.Close(); err == nil {
 			err = cerr
 		}
 		if cerr := db.lock.Close(); err == nil {
 			err = cerr
 		}
+		log := zerowrap.FromCtxWithFields(ctx, map[string]any{"component": "ermite-kv", "dir": db.dir})
+		log.Info().Uint64("seq", db.snap.Load().Seq()).Err(err).Msg("closed")
 	})
 	return err
 }
 // Snapshot returns the current immutable state. It is lock-free and O(1), and
-// remains usable after Close.
+// remains usable after Close. Like every read, it ignores ctx.
-func (db *DB) Snapshot() *Snapshot { return db.snap.Load() }
+func (db *DB) Snapshot(_ context.Context) *Snapshot { return db.snap.Load() }
 // Get returns the item stored under key in the current snapshot.
-func (db *DB) Get(key []byte) (Item, bool) { return db.snap.Load().Get(key) }
+func (db *DB) Get(ctx context.Context, key []byte) (Item, bool) {
+	return db.snap.Load().Get(ctx, key)
+}
 // Apply commits b atomically and returns its seq once it is durable (unless
 // Options.NoSync) and visible in Snapshot.
 	if b.err != nil {
 		return 0, b.err
 	}
-	if b.payload() > db.opts.MaxBatchBytes {
+	if b.encodedSize() > db.opts.MaxBatchBytes {
 		return 0, ErrBatchTooLarge
 	}
 	select {
 		return 0, r.release(db.failErr)
 	}
 	res := <-r.reply // the writer always answers a request it has taken
-	r.release(nil)
+	_ = r.release(nil)
 	return res.seq, res.err
 }

M db_test.go +129 -106


@@ -7,7 +7,6 @@ import (
7	7		"context"
8	8		"errors"
9	9		"fmt"
10		-	"log/slog"
11	10		"math/rand/v2"
12	11		"os"
13	12		"path/filepath"

@@ -19,20 +18,38 @@ import (
19	18		"testing"
20	19		"time"
21	20
	21	+	"github.com/bnema/zerowrap"
	22	+
22	23		"bnema.dev/ermite-kv/internal/fsys"
23	24		"bnema.dev/ermite-kv/internal/fsys/faultfs"
24	25		)
25	26
26	27		var bg = context.Background()
27	28
	29	+	// testCtx returns a context carrying a console logger when
	30	+	// ERMITE_KV_LOG_LEVEL is set (the library itself never reads the
	31	+	// environment), and context.Background() (logging disabled) otherwise.
	32	+	func testCtx(t testing.TB) context.Context {
	33	+	level := os.Getenv("ERMITE_KV_LOG_LEVEL")
	34	+	if level == "" {
	35	+	return bg
	36	+	}
	37	+	return zerowrap.WithCtx(bg, zerowrap.New(zerowrap.Config{Level: level, Format: "console", Output: t.Output()}))
	38	+	}
	39	+
28	40		// mustOpen opens a database on fx and closes it when the test ends.
29	41		func mustOpen(t testing.TB, fx fsys.FS, opts Options) *DB {
30	42		t.Helper()
31		-	db, err := open(fx, testDir, opts)
	43	+	return mustOpenCtx(t, testCtx(t), fx, opts)
	44	+	}
	45	+
	46	+	func mustOpenCtx(t testing.TB, ctx context.Context, fx fsys.FS, opts Options) *DB {
	47	+	t.Helper()
	48	+	db, err := open(ctx, fx, testDir, opts)
32	49		if err != nil {
33	50		t.Fatalf("open: %v", err)
34	51		}
35		-	t.Cleanup(func() { _ = db.Close() })
	52	+	t.Cleanup(func() { _ = db.Close(bg) })
36	53		return db
37	54		}
38	55

@@ -50,7 +67,7 @@ func putKV(t testing.TB, db *DB, key, value string) uint64 {
50	67
51	68		func mustGet(t testing.TB, s *Snapshot, key, want string) Item {
52	69		t.Helper()
53		-	it, ok := s.Get([]byte(key))
	70	+	it, ok := s.Get(bg, []byte(key))
54	71		if !ok \|\| string(it.Value) != want {
55	72		t.Fatalf("Get(%q) = %q, %v; want %q", key, it.Value, ok, want)
56	73		}

@@ -59,7 +76,7 @@ func mustGet(t testing.TB, s *Snapshot, key, want string) Item {
59	76
60	77		func mustMissing(t testing.TB, s *Snapshot, key string) {
61	78		t.Helper()
62		-	if it, ok := s.Get([]byte(key)); ok {
	79	+	if it, ok := s.Get(bg, []byte(key)); ok {
63	80		t.Fatalf("Get(%q) = %q, want missing", key, it.Value)
64	81		}
65	82		}

@@ -74,7 +91,7 @@ func short(full, quick int) int {
74	91		func TestReopenFaultfs(t *testing.T) {
75	92		fx := faultfs.New()
76	93		db := mustOpen(t, fx, Options{})
77		-	if s := db.Snapshot(); s.Seq() != 0 \|\| s.Len() != 0 {
	94	+	if s := db.Snapshot(bg); s.Seq() != 0 \|\| s.Len() != 0 {
78	95		t.Fatalf("new db: seq %d len %d", s.Seq(), s.Len())
79	96		}
80	97		for i := range 50 {

@@ -89,15 +106,15 @@ func TestReopenFaultfs(t *testing.T) {
89	106		if seq, err := db.Apply(bg, &b); err != nil \|\| seq != 51 {
90	107		t.Fatalf("Apply = %d, %v", seq, err)
91	108		}
92		-	if err := db.Close(); err != nil {
	109	+	if err := db.Close(bg); err != nil {
93	110		t.Fatalf("Close: %v", err)
94	111		}
95		-	if err := db.Close(); err != nil {
	112	+	if err := db.Close(bg); err != nil {
96	113		t.Fatalf("second Close: %v", err)
97	114		}
98	115
99	116		db = mustOpen(t, fx, Options{})
100		-	s := db.Snapshot()
	117	+	s := db.Snapshot(bg)
101	118		if s.Seq() != 51 \|\| s.Len() != 49 {
102	119		t.Fatalf("reopened: seq %d len %d, want 51 and 49", s.Seq(), s.Len())
103	120		}

@@ -115,36 +132,36 @@ func TestReopenFaultfs(t *testing.T) {
115	132
116	133		func TestReopenOS(t *testing.T) {
117	134		dir := filepath.Join(t.TempDir(), "sub", "db")
118		-	db, err := Open(dir, Options{})
	135	+	db, err := Open(testCtx(t), dir, Options{})
119	136		if err != nil {
120	137		t.Fatal(err)
121	138		}
122	139		for i := range 100 {
123	140		putKV(t, db, fmt.Sprintf("k%03d", i), strings.Repeat("v", i))
124	141		}
125		-	if err := db.Close(); err != nil {
	142	+	if err := db.Close(bg); err != nil {
126	143		t.Fatal(err)
127	144		}
128	145		if fi, err := os.Stat(dir); err != nil \|\| fi.Mode().Perm() != 0o700 {
129	146		t.Fatalf("dir stat: %v, %v", fi, err)
130	147		}
131	148
132		-	db, err = Open(dir, Options{})
	149	+	db, err = Open(testCtx(t), dir, Options{})
133	150		if err != nil {
134	151		t.Fatal(err)
135	152		}
136		-	defer db.Close()
137		-	s := db.Snapshot()
	153	+	defer func() { _ = db.Close(bg) }()
	154	+	s := db.Snapshot(bg)
138	155		if s.Seq() != 100 \|\| s.Len() != 100 {
139	156		t.Fatalf("seq %d len %d, want 100", s.Seq(), s.Len())
140	157		}
141	158		for i := range 100 {
142	159		mustGet(t, s, fmt.Sprintf("k%03d", i), strings.Repeat("v", i))
143	160		}
144		-	if got := db.Snapshot(); got != s {
	161	+	if got := db.Snapshot(bg); got != s {
145	162		t.Fatal("Snapshot changed without a write")
146	163		}
147		-	if it, ok := db.Get([]byte("k005")); !ok \|\| it.Version != 6 {
	164	+	if it, ok := db.Get(bg, []byte("k005")); !ok \|\| it.Version != 6 {
148	165		t.Fatalf("DB.Get = %v, %v", it, ok)
149	166		}
150	167		}

@@ -163,7 +180,7 @@ func TestOpenFromSnapshot(t *testing.T) {
163	180		fx.WriteFile(filepath.Join(testDir, snapshotName(9)), buf.Bytes())
164	181
165	182		db := mustOpen(t, fx, Options{})
166		-	s := db.Snapshot()
	183	+	s := db.Snapshot(bg)
167	184		if s.Seq() != 9 \|\| s.Len() != 3 {
168	185		t.Fatalf("seq %d len %d", s.Seq(), s.Len())
169	186		}

@@ -173,14 +190,14 @@ func TestOpenFromSnapshot(t *testing.T) {
173	190		if seq := putKV(t, db, "d", "4"); seq != 10 {
174	191		t.Fatalf("seq = %d, want 10", seq)
175	192		}
176		-	if err := db.Close(); err != nil {
	193	+	if err := db.Close(bg); err != nil {
177	194		t.Fatal(err)
178	195		}
179	196		db = mustOpen(t, fx, Options{})
180		-	mustGet(t, db.Snapshot(), "d", "4")
181		-	mustGet(t, db.Snapshot(), "c", "3")
182		-	if db.Snapshot().Seq() != 10 {
183		-	t.Fatalf("seq = %d", db.Snapshot().Seq())
	197	+	mustGet(t, db.Snapshot(bg), "d", "4")
	198	+	mustGet(t, db.Snapshot(bg), "c", "3")
	199	+	if db.Snapshot(bg).Seq() != 10 {
	200	+	t.Fatalf("seq = %d", db.Snapshot(bg).Seq())
184	201		}
185	202		}
186	203

@@ -205,7 +222,7 @@ func TestConcurrentWriters(t *testing.T) {
205	222		t.Errorf("writer %d: %v", g, err)
206	223		return
207	224		}
208		-	if it, ok := db.Get([]byte(key)); !ok \|\| it.Version < seq {
	225	+	if it, ok := db.Get(bg, []byte(key)); !ok \|\| it.Version < seq {
209	226		t.Errorf("writer %d: no read-your-writes for %s at seq %d", g, key, seq)
210	227		return
211	228		}

@@ -228,10 +245,10 @@ func TestConcurrentWriters(t *testing.T) {
228	245		t.Fatalf("seq %d at rank %d: seqs are not 1..%d", s, i, len(all))
229	246		}
230	247		}
231		-	if got := db.Snapshot().Seq(); got != writers*uint64(per) {
	248	+	if got := db.Snapshot(bg).Seq(); got != writers*uint64(per) {
232	249		t.Fatalf("Seq = %d, want %d", got, writers*per)
233	250		}
234		-	if got := db.Snapshot().Len(); got != writers*per {
	251	+	if got := db.Snapshot(bg).Len(); got != writers*per {
235	252		t.Fatalf("Len = %d, want %d", got, writers*per)
236	253		}
237	254		}

@@ -271,9 +288,9 @@ func TestRequireAbsentRace(t *testing.T) {
271	288		t.Fatalf("%d winners, want 1", wins.Load())
272	289		}
273	290		w := slices.Index(winner, true)
274		-	mustGet(t, db.Snapshot(), "lock", strconv.Itoa(w))
275		-	if db.Snapshot().Seq() != 1 {
276		-	t.Fatalf("Seq = %d, want 1 (conflicts consume no seq)", db.Snapshot().Seq())
	291	+	mustGet(t, db.Snapshot(bg), "lock", strconv.Itoa(w))
	292	+	if db.Snapshot(bg).Seq() != 1 {
	293	+	t.Fatalf("Seq = %d, want 1 (conflicts consume no seq)", db.Snapshot(bg).Seq())
277	294		}
278	295		})
279	296		}

@@ -298,9 +315,9 @@ func TestRequireVersion(t *testing.T) {
298	315		if seq, err := cas("missing", 1, "c"); !errors.Is(err, ErrConflict) \|\| seq != 0 {
299	316		t.Fatalf("cas on missing key: %d, %v", seq, err)
300	317		}
301		-	mustGet(t, db.Snapshot(), "k", "b")
302		-	mustMissing(t, db.Snapshot(), "missing")
303		-	if got := db.Snapshot().Seq(); got != v2 {
	318	+	mustGet(t, db.Snapshot(bg), "k", "b")
	319	+	mustMissing(t, db.Snapshot(bg), "missing")
	320	+	if got := db.Snapshot(bg).Seq(); got != v2 {
304	321		t.Fatalf("Seq = %d, want %d", got, v2)
305	322		}
306	323		}

@@ -323,15 +340,15 @@ func TestPreconditionsBeforeOps(t *testing.T) {
323	340		b.Put([]byte("other"), []byte("x"))
324	341		b.RequireAbsent([]byte("never"))
325	342		b.RequireAbsent([]byte("exists")) // fails
326		-	before := db.Snapshot()
	343	+	before := db.Snapshot(bg)
327	344		if seq, err := db.Apply(bg, &b); !errors.Is(err, ErrConflict) \|\| seq != 0 {
328	345		t.Fatalf("Apply = %d, %v; want ErrConflict", seq, err)
329	346		}
330		-	if db.Snapshot() != before {
	347	+	if db.Snapshot(bg) != before {
331	348		t.Fatal("a conflicting batch published a snapshot")
332	349		}
333		-	mustGet(t, db.Snapshot(), "exists", "1")
334		-	mustMissing(t, db.Snapshot(), "other")
	350	+	mustGet(t, db.Snapshot(bg), "exists", "1")
	351	+	mustMissing(t, db.Snapshot(bg), "other")
335	352		}
336	353
337	354		// TestGroupPreconditions checks that preconditions see earlier batches of

@@ -367,7 +384,7 @@ func TestEmptyAndConflictOnlyBatches(t *testing.T) {
367	384		putKV(t, db, "a", "1")
368	385		putKV(t, db, "b", "2")
369	386		writes, syncs := fx.Writes(), fx.Syncs()
370		-	snap := db.Snapshot()
	387	+	snap := db.Snapshot(bg)
371	388
372	389		var empty Batch
373	390		if seq, err := db.Apply(bg, &empty); err != nil \|\| seq != 2 {

@@ -403,15 +420,15 @@ func TestEmptyAndConflictOnlyBatches(t *testing.T) {
403	420		if got := fx.Syncs() - syncs; got != 1 {
404	421		t.Fatalf("%d syncs, want 1", got)
405	422		}
406		-	if db.Snapshot().Len() != snap.Len() \|\| db.Snapshot().Seq() != 3 {
407		-	t.Fatalf("snapshot after: seq %d len %d", db.Snapshot().Seq(), db.Snapshot().Len())
	423	+	if db.Snapshot(bg).Len() != snap.Len() \|\| db.Snapshot(bg).Seq() != 3 {
	424	+	t.Fatalf("snapshot after: seq %d len %d", db.Snapshot(bg).Seq(), db.Snapshot(bg).Len())
408	425		}
409		-	if err := db.Close(); err != nil {
	426	+	if err := db.Close(bg); err != nil {
410	427		t.Fatal(err)
411	428		}
412	429		db = mustOpen(t, fx, Options{})
413		-	if db.Snapshot().Seq() != 3 \|\| db.Snapshot().Len() != 2 {
414		-	t.Fatalf("reopened: seq %d len %d", db.Snapshot().Seq(), db.Snapshot().Len())
	430	+	if db.Snapshot(bg).Seq() != 3 \|\| db.Snapshot(bg).Len() != 2 {
	431	+	t.Fatalf("reopened: seq %d len %d", db.Snapshot(bg).Seq(), db.Snapshot(bg).Len())
415	432		}
416	433		}
417	434

@@ -461,7 +478,7 @@ func TestGroupCommitSyncs(t *testing.T) {
461	478		if syncs >= total/4 {
462	479		t.Fatalf("%d syncs for %d batches: no group commit", syncs, total)
463	480		}
464		-	if got := db.Snapshot().Len(); got != total {
	481	+	if got := db.Snapshot(bg).Len(); got != total {
465	482		t.Fatalf("Len = %d, want %d", got, total)
466	483		}
467	484		}

@@ -474,10 +491,10 @@ func TestNoSync(t *testing.T) {
474	491		if fx.Syncs() != base {
475	492		t.Fatal("NoSync still syncs")
476	493		}
477		-	if err := db.Close(); err != nil {
	494	+	if err := db.Close(bg); err != nil {
478	495		t.Fatal(err)
479	496		}
480		-	mustGet(t, mustOpen(t, fx, Options{}).Snapshot(), "a", "1")
	497	+	mustGet(t, mustOpen(t, fx, Options{}).Snapshot(bg), "a", "1")
481	498		}
482	499
483	500		// TestLargeBatches covers a batch above the 4 MiB group cap (a group of one)

@@ -502,10 +519,10 @@ func TestLargeBatches(t *testing.T) {
502	519		t.Fatalf("seqs = %v", seqs)
503	520		}
504	521		}
505		-	if err := db.Close(); err != nil {
	522	+	if err := db.Close(bg); err != nil {
506	523		t.Fatal(err)
507	524		}
508		-	s := mustOpen(t, fx, Options{}).Snapshot()
	525	+	s := mustOpen(t, fx, Options{}).Snapshot(bg)
509	526		mustGet(t, s, "big", big)
510	527		for i := range n {
511	528		mustGet(t, s, fmt.Sprintf("chunk%d", i), chunk)

@@ -532,48 +549,49 @@ func TestInvalidInputs(t *testing.T) {
532	549		t.Fatalf("version 0: %v", err)
533	550		}
534	551
535		-	// Payload = 12 (seq, count) + 1 (kind) + 1 (klen) + 1 (key) + 1 (vlen) + v.
	552	+	// Encoded batch = 4 (count) + 1 (kind) + 1 (klen) + 1 (key) + 1 (vlen) + v.
536	553		b.Reset()
537		-	b.Put([]byte("k"), make([]byte, 85))
	554	+	b.Put([]byte("k"), make([]byte, 93))
538	555		if seq, err := db.Apply(bg, &b); !errors.Is(err, ErrBatchTooLarge) \|\| seq != 0 {
539		-	t.Fatalf("101-byte payload: %d, %v", seq, err)
	556	+	t.Fatalf("101-byte batch: %d, %v", seq, err)
540	557		}
541	558		b.Reset()
542		-	b.Put([]byte("k"), make([]byte, 84))
	559	+	b.Put([]byte("k"), make([]byte, 92))
543	560		if _, err := db.Apply(bg, &b); err != nil {
544		-	t.Fatalf("100-byte payload: %v", err)
	561	+	t.Fatalf("100-byte batch: %v", err)
545	562		}
546		-	if db.Snapshot().Seq() != 1 {
547		-	t.Fatalf("Seq = %d: rejected batches reached the log", db.Snapshot().Seq())
	563	+	if db.Snapshot(bg).Seq() != 1 {
	564	+	t.Fatalf("Seq = %d: rejected batches reached the log", db.Snapshot(bg).Seq())
548	565		}
549	566		}
550	567
551	568		func TestOptionValidation(t *testing.T) {
552	569		bad := []Options{
553	570		{MaxBatchBytes: maxRecord + 1},
	571	+	{MaxBatchBytes: maxRecord - 11},
554	572		{MaxBatchBytes: -1},
555	573		{GroupWindow: -time.Second},
556	574		}
557	575		for _, o := range bad {
558	576		fx := faultfs.New()
559		-	if db, err := open(fx, testDir, o); err == nil {
560		-	_ = db.Close()
	577	+	if db, err := open(testCtx(t), fx, testDir, o); err == nil {
	578	+	_ = db.Close(bg)
561	579		t.Errorf("open(%+v) succeeded", o)
562	580		}
563	581		if _, err := fx.ReadDir(testDir); err == nil {
564	582		t.Errorf("open(%+v) created the directory", o)
565	583		}
566	584		}
567		-	if _, err := Open(t.TempDir(), Options{MaxBatchBytes: 65 << 20}); err == nil {
	585	+	if _, err := Open(testCtx(t), t.TempDir(), Options{MaxBatchBytes: 65 << 20}); err == nil {
568	586		t.Error("Open with MaxBatchBytes > 64 MiB succeeded")
569	587		}
570		-	for _, o := range []Options{{MaxBatchBytes: maxRecord}, {CompactAfter: -1}, {NoSync: true, CompactAfter: 1}} {
571		-	db, err := open(faultfs.New(), testDir, o)
	588	+	for _, o := range []Options{{MaxBatchBytes: maxRecord - 12}, {CompactAfter: -1}, {NoSync: true, CompactAfter: 1}} {
	589	+	db, err := open(testCtx(t), faultfs.New(), testDir, o)
572	590		if err != nil {
573	591		t.Errorf("open(%+v): %v", o, err)
574	592		continue
575	593		}
576		-	_ = db.Close()
	594	+	_ = db.Close(bg)
577	595		}
578	596		}
579	597

@@ -581,39 +599,39 @@ func TestLocked(t *testing.T) {
581	599		t.Run("faultfs", func(t *testing.T) {
582	600		fx := faultfs.New()
583	601		db := mustOpen(t, fx, Options{})
584		-	if _, err := open(fx, testDir, Options{}); !errors.Is(err, ErrLocked) {
	602	+	if _, err := open(testCtx(t), fx, testDir, Options{}); !errors.Is(err, ErrLocked) {
585	603		t.Fatalf("second open: %v, want ErrLocked", err)
586	604		}
587		-	if err := db.Close(); err != nil {
	605	+	if err := db.Close(bg); err != nil {
588	606		t.Fatal(err)
589	607		}
590	608		mustOpen(t, fx, Options{})
591	609		})
592	610		t.Run("os", func(t *testing.T) {
593	611		dir := t.TempDir()
594		-	db, err := Open(dir, Options{})
	612	+	db, err := Open(testCtx(t), dir, Options{})
595	613		if err != nil {
596	614		t.Fatal(err)
597	615		}
598		-	if _, err := Open(dir, Options{}); !errors.Is(err, ErrLocked) {
	616	+	if _, err := Open(testCtx(t), dir, Options{}); !errors.Is(err, ErrLocked) {
599	617		t.Fatalf("second Open: %v, want ErrLocked", err)
600	618		}
601	619		putKV(t, db, "still", "works")
602		-	if err := db.Close(); err != nil {
	620	+	if err := db.Close(bg); err != nil {
603	621		t.Fatal(err)
604	622		}
605		-	db, err = Open(dir, Options{})
	623	+	db, err = Open(testCtx(t), dir, Options{})
606	624		if err != nil {
607	625		t.Fatalf("Open after Close: %v", err)
608	626		}
609		-	db.Close()
	627	+	_ = db.Close(bg)
610	628		})
611	629		}
612	630
613	631		func TestApplyAfterClose(t *testing.T) {
614	632		db := mustOpen(t, faultfs.New(), Options{})
615	633		putKV(t, db, "a", "1")
616		-	if err := db.Close(); err != nil {
	634	+	if err := db.Close(bg); err != nil {
617	635		t.Fatal(err)
618	636		}
619	637		var b Batch

@@ -621,8 +639,8 @@ func TestApplyAfterClose(t *testing.T) {
621	639		if _, err := db.Apply(bg, &b); !errors.Is(err, ErrClosed) {
622	640		t.Fatalf("Apply after Close: %v", err)
623	641		}
624		-	mustGet(t, db.Snapshot(), "a", "1") // reads keep working
625		-	if err := db.Close(); err != nil {
	642	+	mustGet(t, db.Snapshot(bg), "a", "1") // reads keep working
	643	+	if err := db.Close(bg); err != nil {
626	644		t.Fatalf("second Close: %v", err)
627	645		}
628	646		}

@@ -671,10 +689,10 @@ func TestContextBeforeDequeue(t *testing.T) {
671	689		t.Fatalf("Apply with cancelled ctx = %v", err)
672	690		}
673	691		putKV(t, db, "fourth", "4") // the writer is still healthy
674		-	if err := db.Close(); err != nil {
	692	+	if err := db.Close(bg); err != nil {
675	693		t.Fatal(err)
676	694		}
677		-	s := mustOpen(t, fx, Options{}).Snapshot()
	695	+	s := mustOpen(t, fx, Options{}).Snapshot(bg)
678	696		mustGet(t, s, "first", "1")
679	697		mustGet(t, s, "fourth", "4")
680	698		mustMissing(t, s, "second")

@@ -712,7 +730,7 @@ func TestCloseDuringApplies(t *testing.T) {
712	730		}
713	731		time.Sleep(time.Duration(2+i) * time.Millisecond)
714	732		closed := make(chan error, 1)
715		-	go func() { closed <- db.Close() }()
	733	+	go func() { closed <- db.Close(bg) }()
716	734		select {
717	735		case err := <-closed:
718	736		if err != nil {

@@ -724,12 +742,12 @@ func TestCloseDuringApplies(t *testing.T) {
724	742		wg.Wait()
725	743
726	744		fx.SetSyncDelay(0)
727		-	s := mustOpen(t, fx, Options{}).Snapshot()
	745	+	s := mustOpen(t, fx, Options{}).Snapshot(bg)
728	746		for g, n := range acked {
729	747		if n == 0 {
730	748		continue
731	749		}
732		-	it, ok := s.Get(fmt.Appendf(nil, "g%02d", g))
	750	+	it, ok := s.Get(bg, fmt.Appendf(nil, "g%02d", g))
733	751		got, _ := strconv.Atoi(string(it.Value))
734	752		// The batch after the last acknowledged one may have been
735	753		// committed by the final group.

@@ -767,8 +785,9 @@ func TestInjectedFailures(t *testing.T) {
767	785
768	786		func testInjectedFailure(t *testing.T, f failure, powerLoss bool) {
769	787		fx := faultfs.New()
770		-	logger, logs := captureLogger()
771		-	db := mustOpen(t, fx, Options{GroupWindow: 150 * time.Millisecond, Logger: logger})
	788	+	var logs syncBuffer
	789	+	ctx := zerowrap.WithCtx(bg, zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logs}))
	790	+	db := mustOpenCtx(t, ctx, fx, Options{GroupWindow: 150 * time.Millisecond})
772	791		putKV(t, db, "before", "1")
773	792		f.inject(fx)
774	793

@@ -792,7 +811,7 @@ func testInjectedFailure(t *testing.T, f failure, powerLoss bool) {
792	811		t.Fatalf("batch %d: %v does not wrap %v", i, err, f.cause)
793	812		}
794	813		}
795		-	if !strings.Contains(logs.String(), "database failed") {
	814	+	if !strings.Contains(logs.String(), `"level":"error"`) \|\| !strings.Contains(logs.String(), "database failed") {
796	815		t.Errorf("failure not logged: %q", logs.String())
797	816		}
798	817

@@ -808,27 +827,27 @@ func testInjectedFailure(t *testing.T, f failure, powerLoss bool) {
808	827		if _, err := db.Apply(bg, &empty); !errors.Is(err, ErrFailed) {
809	828		t.Fatalf("empty Apply on a failed db: %v", err)
810	829		}
811		-	s := db.Snapshot()
	830	+	s := db.Snapshot(bg)
812	831		if s.Seq() != 1 \|\| s.Len() != 1 {
813	832		t.Fatalf("snapshot after failure: seq %d len %d", s.Seq(), s.Len())
814	833		}
815	834		mustGet(t, s, "before", "1")
816	835		mustMissing(t, s, "failed0")
817		-	if err := db.Close(); !errors.Is(err, ErrFailed) {
	836	+	if err := db.Close(bg); !errors.Is(err, ErrFailed) {
818	837		t.Fatalf("Close = %v, want the failure", err)
819	838		}
820		-	if err := db.Close(); err != nil {
	839	+	if err := db.Close(bg); err != nil {
821	840		t.Fatalf("second Close = %v", err)
822	841		}
823	842
824	843		if powerLoss {
825	844		fx.PowerLoss(faultfs.PowerLossOptions{})
826	845		}
827		-	s = mustOpen(t, fx, Options{}).Snapshot()
	846	+	s = mustOpen(t, fx, Options{}).Snapshot(bg)
828	847		mustGet(t, s, "before", "1")
829	848		present := 0
830	849		for i := range group {
831		-	if _, ok := s.Get(fmt.Appendf(nil, "failed%d", i)); ok {
	850	+	if _, ok := s.Get(bg, fmt.Appendf(nil, "failed%d", i)); ok {
832	851		present++
833	852		}
834	853		}

@@ -868,12 +887,6 @@ func TestFailedWriterAnswersOverflow(t *testing.T) {
868	887		}
869	888		}
870	889
871		-	// captureLogger returns a logger writing to a buffer.
872		-	func captureLogger() (slog.Logger, syncBuffer) {
873		-	var sb syncBuffer
874		-	return slog.New(slog.NewTextHandler(&sb, nil)), &sb
875		-	}
876		-
877	890		type syncBuffer struct {
878	891		mu sync.Mutex
879	892		b strings.Builder

@@ -910,8 +923,10 @@ func powerLossBase(t *testing.T) uint64 {
910	923		// Every writer g applies batches n = 0, 1, … that set cur/g = n and
911	924		// all/g/n, and delete all/g/(n-1). The recovered state therefore says how
912	925		// many batches of each writer were applied, and the seq must equal their sum.
913		-	// (PowerLossOptions.KeepPages is not exercised: see the open question about
914		-	// recovery rule 6 under out-of-order page writeback.)
	926	+	// The modes include KeepPages (a random subset of the unsynced pages
	927	+	// survives). They always run with NoSync=false: with NoSync, KeepPages can
	928	+	// legitimately make Open fail with ErrCorrupt, which is documented on
	929	+	// Options.NoSync and not tested.
915	930		func TestPowerLoss(t *testing.T) {
916	931		modes := []struct {
917	932		name string

@@ -919,6 +934,10 @@ func TestPowerLoss(t *testing.T) {
919	934		}{
920	935		{"drop", faultfs.PowerLossOptions{}},
921	936		{"zerofill", faultfs.PowerLossOptions{ZeroFill: true}},
	937	+	// Pages of the unsynced tail reach the disk in any order. One record
	938	+	// per group makes this safe when commits are synced.
	939	+	{"keeppages", faultfs.PowerLossOptions{KeepPages: true}},
	940	+	{"keeppages+zerofill", faultfs.PowerLossOptions{KeepPages: true, ZeroFill: true}},
922	941		}
923	942		base := powerLossBase(t)
924	943		iterations := short(150, 10)

@@ -937,7 +956,7 @@ func TestPowerLoss(t *testing.T) {
937	956		func runPowerLoss(t *testing.T, seed uint64, plo faultfs.PowerLossOptions) (ok bool) {
938	957		rng := rand.New(rand.NewPCG(seed, 0x9e3779b97f4a7c15))
939	958		fx := faultfs.New()
940		-	db, err := open(fx, testDir, Options{GroupWindow: time.Duration(rng.IntN(3)) * 100 * time.Microsecond})
	959	+	db, err := open(testCtx(t), fx, testDir, Options{GroupWindow: time.Duration(rng.IntN(3)) * 100 * time.Microsecond})
941	960		if err != nil {
942	961		t.Errorf("seed %d: open: %v", seed, err)
943	962		return false

@@ -966,39 +985,43 @@ func runPowerLoss(t *testing.T, seed uint64, plo faultfs.PowerLossOptions) (ok b
966	985		})
967	986		}
968	987		time.Sleep(time.Duration(rng.IntN(4000)) * time.Microsecond)
	988	+	plo.Rand = rand.New(rand.NewPCG(seed, 7))
	989	+	if plo.KeepPages {
	990	+	plo.PageSize = 64 // small pages: a group record spans several of them
	991	+	}
969	992		fx.PowerLoss(plo)
970	993		wg.Wait()
971		-	_ = db.Close()
	994	+	_ = db.Close(bg)
972	995		fx.SetSyncDelay(0)
973	996
974		-	db, err = open(fx, testDir, Options{})
	997	+	db, err = open(testCtx(t), fx, testDir, Options{})
975	998		if err != nil {
976	999		t.Errorf("seed %d: reopen after power loss: %v", seed, err)
977	1000		return false
978	1001		}
979		-	defer db.Close()
980		-	if !checkPowerLossState(t, seed, db.Snapshot(), acked, ackSeq) {
	1002	+	defer func() { _ = db.Close(bg) }()
	1003	+	if !checkPowerLossState(t, seed, db.Snapshot(bg), acked, ackSeq) {
981	1004		return false
982	1005		}
983	1006
984	1007		// The recovered log accepts new records and survives another reopen.
985		-	seq := db.Snapshot().Seq()
	1008	+	seq := db.Snapshot(bg).Seq()
986	1009		if got := putKV(t, db, "after", "x"); got != seq+1 {
987	1010		t.Errorf("seed %d: seq after recovery = %d, want %d", seed, got, seq+1)
988	1011		return false
989	1012		}
990		-	if err := db.Close(); err != nil {
	1013	+	if err := db.Close(bg); err != nil {
991	1014		t.Errorf("seed %d: Close: %v", seed, err)
992	1015		return false
993	1016		}
994		-	db, err = open(fx, testDir, Options{})
	1017	+	db, err = open(testCtx(t), fx, testDir, Options{})
995	1018		if err != nil {
996	1019		t.Errorf("seed %d: second reopen: %v", seed, err)
997	1020		return false
998	1021		}
999		-	defer db.Close()
1000		-	if db.Snapshot().Seq() != seq+1 {
1001		-	t.Errorf("seed %d: seq after second reopen = %d, want %d", seed, db.Snapshot().Seq(), seq+1)
	1022	+	defer func() { _ = db.Close(bg) }()
	1023	+	if db.Snapshot(bg).Seq() != seq+1 {
	1024	+	t.Errorf("seed %d: seq after second reopen = %d, want %d", seed, db.Snapshot(bg).Seq(), seq+1)
1002	1025		return false
1003	1026		}
1004	1027		return true

@@ -1012,7 +1035,7 @@ func checkPowerLossState(t testing.T, seed uint64, s Snapshot, acked []int, ac
1012	1035		var applied uint64
1013	1036		keys := 0
1014	1037		for g := range acked {
1015		-	it, ok := s.Get(fmt.Appendf(nil, "cur/%d", g))
	1038	+	it, ok := s.Get(bg, fmt.Appendf(nil, "cur/%d", g))
1016	1039		last := -1
1017	1040		if ok {
1018	1041		n, err := strconv.Atoi(string(it.Value))

@@ -1030,12 +1053,12 @@ func checkPowerLossState(t testing.T, seed uint64, s Snapshot, acked []int, ac
1030	1053		if !ok {
1031	1054		continue
1032	1055		}
1033		-	cur, ok := s.Get(fmt.Appendf(nil, "all/%d/%d", g, last))
	1056	+	cur, ok := s.Get(bg, fmt.Appendf(nil, "all/%d/%d", g, last))
1034	1057		if !ok \|\| cur.Version != it.Version {
1035	1058		return fail("writer %d: batch %d is partially applied (%v, %v)", g, last, cur, ok)
1036	1059		}
1037	1060		count := 0
1038		-	for range s.Prefix(fmt.Appendf(nil, "all/%d/", g)) {
	1061	+	for range s.Prefix(bg, fmt.Appendf(nil, "all/%d/", g)) {
1039	1062		count++
1040	1063		}
1041	1064		if count != 1 {

@@ -1082,11 +1105,11 @@ func (f countFile) Sync() error {
1082	1105		// around the OS file system, so the numbers are real fdatasync calls.
1083	1106		func BenchmarkApply(b *testing.B) {
1084	1107		fx := &countFS{FS: fsys.OS()}
1085		-	db, err := open(fx, filepath.Join(b.TempDir(), "db"), Options{})
	1108	+	db, err := open(bg, fx, filepath.Join(b.TempDir(), "db"), Options{})
1086	1109		if err != nil {
1087	1110		b.Fatal(err)
1088	1111		}
1089		-	defer db.Close()
	1112	+	defer func() { _ = db.Close(bg) }()
1090	1113		b.SetParallelism(16)
1091	1114		value := bytes.Repeat([]byte("v"), 100)
1092	1115		var next atomic.Uint64

 	"context"
 	"errors"
 	"fmt"
-	"log/slog"
 	"math/rand/v2"
 	"os"
 	"path/filepath"
 	"testing"
 	"time"
+	"github.com/bnema/zerowrap"
 	"bnema.dev/ermite-kv/internal/fsys"
 	"bnema.dev/ermite-kv/internal/fsys/faultfs"
 )
 var bg = context.Background()
+// testCtx returns a context carrying a console logger when
+// ERMITE_KV_LOG_LEVEL is set (the library itself never reads the
+// environment), and context.Background() (logging disabled) otherwise.
+func testCtx(t testing.TB) context.Context {
+	level := os.Getenv("ERMITE_KV_LOG_LEVEL")
+	if level == "" {
+		return bg
+	}
+	return zerowrap.WithCtx(bg, zerowrap.New(zerowrap.Config{Level: level, Format: "console", Output: t.Output()}))
+}
 // mustOpen opens a database on fx and closes it when the test ends.
 func mustOpen(t testing.TB, fx fsys.FS, opts Options) *DB {
 	t.Helper()
-	db, err := open(fx, testDir, opts)
+	return mustOpenCtx(t, testCtx(t), fx, opts)
+}
+func mustOpenCtx(t testing.TB, ctx context.Context, fx fsys.FS, opts Options) *DB {
+	t.Helper()
+	db, err := open(ctx, fx, testDir, opts)
 	if err != nil {
 		t.Fatalf("open: %v", err)
 	}
-	t.Cleanup(func() { _ = db.Close() })
+	t.Cleanup(func() { _ = db.Close(bg) })
 	return db
 }
 func mustGet(t testing.TB, s *Snapshot, key, want string) Item {
 	t.Helper()
-	it, ok := s.Get([]byte(key))
+	it, ok := s.Get(bg, []byte(key))
 	if !ok || string(it.Value) != want {
 		t.Fatalf("Get(%q) = %q, %v; want %q", key, it.Value, ok, want)
 	}
 func mustMissing(t testing.TB, s *Snapshot, key string) {
 	t.Helper()
-	if it, ok := s.Get([]byte(key)); ok {
+	if it, ok := s.Get(bg, []byte(key)); ok {
 		t.Fatalf("Get(%q) = %q, want missing", key, it.Value)
 	}
 }
 func TestReopenFaultfs(t *testing.T) {
 	fx := faultfs.New()
 	db := mustOpen(t, fx, Options{})
-	if s := db.Snapshot(); s.Seq() != 0 || s.Len() != 0 {
+	if s := db.Snapshot(bg); s.Seq() != 0 || s.Len() != 0 {
 		t.Fatalf("new db: seq %d len %d", s.Seq(), s.Len())
 	}
 	for i := range 50 {
 	if seq, err := db.Apply(bg, &b); err != nil || seq != 51 {
 		t.Fatalf("Apply = %d, %v", seq, err)
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatalf("Close: %v", err)
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatalf("second Close: %v", err)
 	}
 	db = mustOpen(t, fx, Options{})
-	s := db.Snapshot()
+	s := db.Snapshot(bg)
 	if s.Seq() != 51 || s.Len() != 49 {
 		t.Fatalf("reopened: seq %d len %d, want 51 and 49", s.Seq(), s.Len())
 	}
 func TestReopenOS(t *testing.T) {
 	dir := filepath.Join(t.TempDir(), "sub", "db")
-	db, err := Open(dir, Options{})
+	db, err := Open(testCtx(t), dir, Options{})
 	if err != nil {
 		t.Fatal(err)
 	}
 	for i := range 100 {
 		putKV(t, db, fmt.Sprintf("k%03d", i), strings.Repeat("v", i))
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
 	if fi, err := os.Stat(dir); err != nil || fi.Mode().Perm() != 0o700 {
 		t.Fatalf("dir stat: %v, %v", fi, err)
 	}
-	db, err = Open(dir, Options{})
+	db, err = Open(testCtx(t), dir, Options{})
 	if err != nil {
 		t.Fatal(err)
 	}
-	defer db.Close()
+	defer func() { _ = db.Close(bg) }()
-	s := db.Snapshot()
+	s := db.Snapshot(bg)
 	if s.Seq() != 100 || s.Len() != 100 {
 		t.Fatalf("seq %d len %d, want 100", s.Seq(), s.Len())
 	}
 	for i := range 100 {
 		mustGet(t, s, fmt.Sprintf("k%03d", i), strings.Repeat("v", i))
 	}
-	if got := db.Snapshot(); got != s {
+	if got := db.Snapshot(bg); got != s {
 		t.Fatal("Snapshot changed without a write")
 	}
-	if it, ok := db.Get([]byte("k005")); !ok || it.Version != 6 {
+	if it, ok := db.Get(bg, []byte("k005")); !ok || it.Version != 6 {
 		t.Fatalf("DB.Get = %v, %v", it, ok)
 	}
 }
 	fx.WriteFile(filepath.Join(testDir, snapshotName(9)), buf.Bytes())
 	db := mustOpen(t, fx, Options{})
-	s := db.Snapshot()
+	s := db.Snapshot(bg)
 	if s.Seq() != 9 || s.Len() != 3 {
 		t.Fatalf("seq %d len %d", s.Seq(), s.Len())
 	}
 	if seq := putKV(t, db, "d", "4"); seq != 10 {
 		t.Fatalf("seq = %d, want 10", seq)
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
 	db = mustOpen(t, fx, Options{})
-	mustGet(t, db.Snapshot(), "d", "4")
+	mustGet(t, db.Snapshot(bg), "d", "4")
-	mustGet(t, db.Snapshot(), "c", "3")
+	mustGet(t, db.Snapshot(bg), "c", "3")
-	if db.Snapshot().Seq() != 10 {
+	if db.Snapshot(bg).Seq() != 10 {
-		t.Fatalf("seq = %d", db.Snapshot().Seq())
+		t.Fatalf("seq = %d", db.Snapshot(bg).Seq())
 	}
 }
 					t.Errorf("writer %d: %v", g, err)
 					return
 				}
-				if it, ok := db.Get([]byte(key)); !ok || it.Version < seq {
+				if it, ok := db.Get(bg, []byte(key)); !ok || it.Version < seq {
 					t.Errorf("writer %d: no read-your-writes for %s at seq %d", g, key, seq)
 					return
 				}
 			t.Fatalf("seq %d at rank %d: seqs are not 1..%d", s, i, len(all))
 		}
 	}
-	if got := db.Snapshot().Seq(); got != writers*uint64(per) {
+	if got := db.Snapshot(bg).Seq(); got != writers*uint64(per) {
 		t.Fatalf("Seq = %d, want %d", got, writers*per)
 	}
-	if got := db.Snapshot().Len(); got != writers*per {
+	if got := db.Snapshot(bg).Len(); got != writers*per {
 		t.Fatalf("Len = %d, want %d", got, writers*per)
 	}
 }
 				t.Fatalf("%d winners, want 1", wins.Load())
 			}
 			w := slices.Index(winner, true)
-			mustGet(t, db.Snapshot(), "lock", strconv.Itoa(w))
+			mustGet(t, db.Snapshot(bg), "lock", strconv.Itoa(w))
-			if db.Snapshot().Seq() != 1 {
+			if db.Snapshot(bg).Seq() != 1 {
-				t.Fatalf("Seq = %d, want 1 (conflicts consume no seq)", db.Snapshot().Seq())
+				t.Fatalf("Seq = %d, want 1 (conflicts consume no seq)", db.Snapshot(bg).Seq())
 			}
 		})
 	}
 	if seq, err := cas("missing", 1, "c"); !errors.Is(err, ErrConflict) || seq != 0 {
 		t.Fatalf("cas on missing key: %d, %v", seq, err)
 	}
-	mustGet(t, db.Snapshot(), "k", "b")
+	mustGet(t, db.Snapshot(bg), "k", "b")
-	mustMissing(t, db.Snapshot(), "missing")
+	mustMissing(t, db.Snapshot(bg), "missing")
-	if got := db.Snapshot().Seq(); got != v2 {
+	if got := db.Snapshot(bg).Seq(); got != v2 {
 		t.Fatalf("Seq = %d, want %d", got, v2)
 	}
 }
 	b.Put([]byte("other"), []byte("x"))
 	b.RequireAbsent([]byte("never"))
 	b.RequireAbsent([]byte("exists")) // fails
-	before := db.Snapshot()
+	before := db.Snapshot(bg)
 	if seq, err := db.Apply(bg, &b); !errors.Is(err, ErrConflict) || seq != 0 {
 		t.Fatalf("Apply = %d, %v; want ErrConflict", seq, err)
 	}
-	if db.Snapshot() != before {
+	if db.Snapshot(bg) != before {
 		t.Fatal("a conflicting batch published a snapshot")
 	}
-	mustGet(t, db.Snapshot(), "exists", "1")
+	mustGet(t, db.Snapshot(bg), "exists", "1")
-	mustMissing(t, db.Snapshot(), "other")
+	mustMissing(t, db.Snapshot(bg), "other")
 }
 // TestGroupPreconditions checks that preconditions see earlier batches of
 	putKV(t, db, "a", "1")
 	putKV(t, db, "b", "2")
 	writes, syncs := fx.Writes(), fx.Syncs()
-	snap := db.Snapshot()
+	snap := db.Snapshot(bg)
 	var empty Batch
 	if seq, err := db.Apply(bg, &empty); err != nil || seq != 2 {
 	if got := fx.Syncs() - syncs; got != 1 {
 		t.Fatalf("%d syncs, want 1", got)
 	}
-	if db.Snapshot().Len() != snap.Len() || db.Snapshot().Seq() != 3 {
+	if db.Snapshot(bg).Len() != snap.Len() || db.Snapshot(bg).Seq() != 3 {
-		t.Fatalf("snapshot after: seq %d len %d", db.Snapshot().Seq(), db.Snapshot().Len())
+		t.Fatalf("snapshot after: seq %d len %d", db.Snapshot(bg).Seq(), db.Snapshot(bg).Len())
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
 	db = mustOpen(t, fx, Options{})
-	if db.Snapshot().Seq() != 3 || db.Snapshot().Len() != 2 {
+	if db.Snapshot(bg).Seq() != 3 || db.Snapshot(bg).Len() != 2 {
-		t.Fatalf("reopened: seq %d len %d", db.Snapshot().Seq(), db.Snapshot().Len())
+		t.Fatalf("reopened: seq %d len %d", db.Snapshot(bg).Seq(), db.Snapshot(bg).Len())
 	}
 }
 	if syncs >= total/4 {
 		t.Fatalf("%d syncs for %d batches: no group commit", syncs, total)
 	}
-	if got := db.Snapshot().Len(); got != total {
+	if got := db.Snapshot(bg).Len(); got != total {
 		t.Fatalf("Len = %d, want %d", got, total)
 	}
 }
 	if fx.Syncs() != base {
 		t.Fatal("NoSync still syncs")
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
-	mustGet(t, mustOpen(t, fx, Options{}).Snapshot(), "a", "1")
+	mustGet(t, mustOpen(t, fx, Options{}).Snapshot(bg), "a", "1")
 }
 // TestLargeBatches covers a batch above the 4 MiB group cap (a group of one)
 			t.Fatalf("seqs = %v", seqs)
 		}
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
-	s := mustOpen(t, fx, Options{}).Snapshot()
+	s := mustOpen(t, fx, Options{}).Snapshot(bg)
 	mustGet(t, s, "big", big)
 	for i := range n {
 		mustGet(t, s, fmt.Sprintf("chunk%d", i), chunk)
 		t.Fatalf("version 0: %v", err)
 	}
-	// Payload = 12 (seq, count) + 1 (kind) + 1 (klen) + 1 (key) + 1 (vlen) + v.
+	// Encoded batch = 4 (count) + 1 (kind) + 1 (klen) + 1 (key) + 1 (vlen) + v.
 	b.Reset()
-	b.Put([]byte("k"), make([]byte, 85))
+	b.Put([]byte("k"), make([]byte, 93))
 	if seq, err := db.Apply(bg, &b); !errors.Is(err, ErrBatchTooLarge) || seq != 0 {
-		t.Fatalf("101-byte payload: %d, %v", seq, err)
+		t.Fatalf("101-byte batch: %d, %v", seq, err)
 	}
 	b.Reset()
-	b.Put([]byte("k"), make([]byte, 84))
+	b.Put([]byte("k"), make([]byte, 92))
 	if _, err := db.Apply(bg, &b); err != nil {
-		t.Fatalf("100-byte payload: %v", err)
+		t.Fatalf("100-byte batch: %v", err)
 	}
-	if db.Snapshot().Seq() != 1 {
+	if db.Snapshot(bg).Seq() != 1 {
-		t.Fatalf("Seq = %d: rejected batches reached the log", db.Snapshot().Seq())
+		t.Fatalf("Seq = %d: rejected batches reached the log", db.Snapshot(bg).Seq())
 	}
 }
 func TestOptionValidation(t *testing.T) {
 	bad := []Options{
 		{MaxBatchBytes: maxRecord + 1},
+		{MaxBatchBytes: maxRecord - 11},
 		{MaxBatchBytes: -1},
 		{GroupWindow: -time.Second},
 	}
 	for _, o := range bad {
 		fx := faultfs.New()
-		if db, err := open(fx, testDir, o); err == nil {
+		if db, err := open(testCtx(t), fx, testDir, o); err == nil {
-			_ = db.Close()
+			_ = db.Close(bg)
 			t.Errorf("open(%+v) succeeded", o)
 		}
 		if _, err := fx.ReadDir(testDir); err == nil {
 			t.Errorf("open(%+v) created the directory", o)
 		}
 	}
-	if _, err := Open(t.TempDir(), Options{MaxBatchBytes: 65 << 20}); err == nil {
+	if _, err := Open(testCtx(t), t.TempDir(), Options{MaxBatchBytes: 65 << 20}); err == nil {
 		t.Error("Open with MaxBatchBytes > 64 MiB succeeded")
 	}
-	for _, o := range []Options{{MaxBatchBytes: maxRecord}, {CompactAfter: -1}, {NoSync: true, CompactAfter: 1}} {
+	for _, o := range []Options{{MaxBatchBytes: maxRecord - 12}, {CompactAfter: -1}, {NoSync: true, CompactAfter: 1}} {
-		db, err := open(faultfs.New(), testDir, o)
+		db, err := open(testCtx(t), faultfs.New(), testDir, o)
 		if err != nil {
 			t.Errorf("open(%+v): %v", o, err)
 			continue
 		}
-		_ = db.Close()
+		_ = db.Close(bg)
 	}
 }
 	t.Run("faultfs", func(t *testing.T) {
 		fx := faultfs.New()
 		db := mustOpen(t, fx, Options{})
-		if _, err := open(fx, testDir, Options{}); !errors.Is(err, ErrLocked) {
+		if _, err := open(testCtx(t), fx, testDir, Options{}); !errors.Is(err, ErrLocked) {
 			t.Fatalf("second open: %v, want ErrLocked", err)
 		}
-		if err := db.Close(); err != nil {
+		if err := db.Close(bg); err != nil {
 			t.Fatal(err)
 		}
 		mustOpen(t, fx, Options{})
 	})
 	t.Run("os", func(t *testing.T) {
 		dir := t.TempDir()
-		db, err := Open(dir, Options{})
+		db, err := Open(testCtx(t), dir, Options{})
 		if err != nil {
 			t.Fatal(err)
 		}
-		if _, err := Open(dir, Options{}); !errors.Is(err, ErrLocked) {
+		if _, err := Open(testCtx(t), dir, Options{}); !errors.Is(err, ErrLocked) {
 			t.Fatalf("second Open: %v, want ErrLocked", err)
 		}
 		putKV(t, db, "still", "works")
-		if err := db.Close(); err != nil {
+		if err := db.Close(bg); err != nil {
 			t.Fatal(err)
 		}
-		db, err = Open(dir, Options{})
+		db, err = Open(testCtx(t), dir, Options{})
 		if err != nil {
 			t.Fatalf("Open after Close: %v", err)
 		}
-		db.Close()
+		_ = db.Close(bg)
 	})
 }
 func TestApplyAfterClose(t *testing.T) {
 	db := mustOpen(t, faultfs.New(), Options{})
 	putKV(t, db, "a", "1")
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
 	var b Batch
 	if _, err := db.Apply(bg, &b); !errors.Is(err, ErrClosed) {
 		t.Fatalf("Apply after Close: %v", err)
 	}
-	mustGet(t, db.Snapshot(), "a", "1") // reads keep working
+	mustGet(t, db.Snapshot(bg), "a", "1") // reads keep working
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatalf("second Close: %v", err)
 	}
 }
 		t.Fatalf("Apply with cancelled ctx = %v", err)
 	}
 	putKV(t, db, "fourth", "4") // the writer is still healthy
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatal(err)
 	}
-	s := mustOpen(t, fx, Options{}).Snapshot()
+	s := mustOpen(t, fx, Options{}).Snapshot(bg)
 	mustGet(t, s, "first", "1")
 	mustGet(t, s, "fourth", "4")
 	mustMissing(t, s, "second")
 			}
 			time.Sleep(time.Duration(2+i) * time.Millisecond)
 			closed := make(chan error, 1)
-			go func() { closed <- db.Close() }()
+			go func() { closed <- db.Close(bg) }()
 			select {
 			case err := <-closed:
 				if err != nil {
 			wg.Wait()
 			fx.SetSyncDelay(0)
-			s := mustOpen(t, fx, Options{}).Snapshot()
+			s := mustOpen(t, fx, Options{}).Snapshot(bg)
 			for g, n := range acked {
 				if n == 0 {
 					continue
 				}
-				it, ok := s.Get(fmt.Appendf(nil, "g%02d", g))
+				it, ok := s.Get(bg, fmt.Appendf(nil, "g%02d", g))
 				got, _ := strconv.Atoi(string(it.Value))
 				// The batch after the last acknowledged one may have been
 				// committed by the final group.
 func testInjectedFailure(t *testing.T, f failure, powerLoss bool) {
 	fx := faultfs.New()
-	logger, logs := captureLogger()
+	var logs syncBuffer
-	db := mustOpen(t, fx, Options{GroupWindow: 150 * time.Millisecond, Logger: logger})
+	ctx := zerowrap.WithCtx(bg, zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logs}))
+	db := mustOpenCtx(t, ctx, fx, Options{GroupWindow: 150 * time.Millisecond})
 	putKV(t, db, "before", "1")
 	f.inject(fx)
 			t.Fatalf("batch %d: %v does not wrap %v", i, err, f.cause)
 		}
 	}
-	if !strings.Contains(logs.String(), "database failed") {
+	if !strings.Contains(logs.String(), `"level":"error"`) || !strings.Contains(logs.String(), "database failed") {
 		t.Errorf("failure not logged: %q", logs.String())
 	}
 	if _, err := db.Apply(bg, &empty); !errors.Is(err, ErrFailed) {
 		t.Fatalf("empty Apply on a failed db: %v", err)
 	}
-	s := db.Snapshot()
+	s := db.Snapshot(bg)
 	if s.Seq() != 1 || s.Len() != 1 {
 		t.Fatalf("snapshot after failure: seq %d len %d", s.Seq(), s.Len())
 	}
 	mustGet(t, s, "before", "1")
 	mustMissing(t, s, "failed0")
-	if err := db.Close(); !errors.Is(err, ErrFailed) {
+	if err := db.Close(bg); !errors.Is(err, ErrFailed) {
 		t.Fatalf("Close = %v, want the failure", err)
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Fatalf("second Close = %v", err)
 	}
 	if powerLoss {
 		fx.PowerLoss(faultfs.PowerLossOptions{})
 	}
-	s = mustOpen(t, fx, Options{}).Snapshot()
+	s = mustOpen(t, fx, Options{}).Snapshot(bg)
 	mustGet(t, s, "before", "1")
 	present := 0
 	for i := range group {
-		if _, ok := s.Get(fmt.Appendf(nil, "failed%d", i)); ok {
+		if _, ok := s.Get(bg, fmt.Appendf(nil, "failed%d", i)); ok {
 			present++
 		}
 	}
 	}
 }
-// captureLogger returns a logger writing to a buffer.
-func captureLogger() (*slog.Logger, *syncBuffer) {
-	var sb syncBuffer
-	return slog.New(slog.NewTextHandler(&sb, nil)), &sb
-}
 type syncBuffer struct {
 	mu sync.Mutex
 	b  strings.Builder
 // Every writer g applies batches n = 0, 1, … that set cur/g = n and
 // all/g/n, and delete all/g/(n-1). The recovered state therefore says how
 // many batches of each writer were applied, and the seq must equal their sum.
-// (PowerLossOptions.KeepPages is not exercised: see the open question about
+// The modes include KeepPages (a random subset of the unsynced pages
-// recovery rule 6 under out-of-order page writeback.)
+// survives). They always run with NoSync=false: with NoSync, KeepPages can
+// legitimately make Open fail with ErrCorrupt, which is documented on
+// Options.NoSync and not tested.
 func TestPowerLoss(t *testing.T) {
 	modes := []struct {
 		name string
 	}{
 		{"drop", faultfs.PowerLossOptions{}},
 		{"zerofill", faultfs.PowerLossOptions{ZeroFill: true}},
+		// Pages of the unsynced tail reach the disk in any order. One record
+		// per group makes this safe when commits are synced.
+		{"keeppages", faultfs.PowerLossOptions{KeepPages: true}},
+		{"keeppages+zerofill", faultfs.PowerLossOptions{KeepPages: true, ZeroFill: true}},
 	}
 	base := powerLossBase(t)
 	iterations := short(150, 10)
 func runPowerLoss(t *testing.T, seed uint64, plo faultfs.PowerLossOptions) (ok bool) {
 	rng := rand.New(rand.NewPCG(seed, 0x9e3779b97f4a7c15))
 	fx := faultfs.New()
-	db, err := open(fx, testDir, Options{GroupWindow: time.Duration(rng.IntN(3)) * 100 * time.Microsecond})
+	db, err := open(testCtx(t), fx, testDir, Options{GroupWindow: time.Duration(rng.IntN(3)) * 100 * time.Microsecond})
 	if err != nil {
 		t.Errorf("seed %d: open: %v", seed, err)
 		return false
 		})
 	}
 	time.Sleep(time.Duration(rng.IntN(4000)) * time.Microsecond)
+	plo.Rand = rand.New(rand.NewPCG(seed, 7))
+	if plo.KeepPages {
+		plo.PageSize = 64 // small pages: a group record spans several of them
+	}
 	fx.PowerLoss(plo)
 	wg.Wait()
-	_ = db.Close()
+	_ = db.Close(bg)
 	fx.SetSyncDelay(0)
-	db, err = open(fx, testDir, Options{})
+	db, err = open(testCtx(t), fx, testDir, Options{})
 	if err != nil {
 		t.Errorf("seed %d: reopen after power loss: %v", seed, err)
 		return false
 	}
-	defer db.Close()
+	defer func() { _ = db.Close(bg) }()
-	if !checkPowerLossState(t, seed, db.Snapshot(), acked, ackSeq) {
+	if !checkPowerLossState(t, seed, db.Snapshot(bg), acked, ackSeq) {
 		return false
 	}
 	// The recovered log accepts new records and survives another reopen.
-	seq := db.Snapshot().Seq()
+	seq := db.Snapshot(bg).Seq()
 	if got := putKV(t, db, "after", "x"); got != seq+1 {
 		t.Errorf("seed %d: seq after recovery = %d, want %d", seed, got, seq+1)
 		return false
 	}
-	if err := db.Close(); err != nil {
+	if err := db.Close(bg); err != nil {
 		t.Errorf("seed %d: Close: %v", seed, err)
 		return false
 	}
-	db, err = open(fx, testDir, Options{})
+	db, err = open(testCtx(t), fx, testDir, Options{})
 	if err != nil {
 		t.Errorf("seed %d: second reopen: %v", seed, err)
 		return false
 	}
-	defer db.Close()
+	defer func() { _ = db.Close(bg) }()
-	if db.Snapshot().Seq() != seq+1 {
+	if db.Snapshot(bg).Seq() != seq+1 {
-		t.Errorf("seed %d: seq after second reopen = %d, want %d", seed, db.Snapshot().Seq(), seq+1)
+		t.Errorf("seed %d: seq after second reopen = %d, want %d", seed, db.Snapshot(bg).Seq(), seq+1)
 		return false
 	}
 	return true
 	var applied uint64
 	keys := 0
 	for g := range acked {
-		it, ok := s.Get(fmt.Appendf(nil, "cur/%d", g))
+		it, ok := s.Get(bg, fmt.Appendf(nil, "cur/%d", g))
 		last := -1
 		if ok {
 			n, err := strconv.Atoi(string(it.Value))
 		if !ok {
 			continue
 		}
-		cur, ok := s.Get(fmt.Appendf(nil, "all/%d/%d", g, last))
+		cur, ok := s.Get(bg, fmt.Appendf(nil, "all/%d/%d", g, last))
 		if !ok || cur.Version != it.Version {
 			return fail("writer %d: batch %d is partially applied (%v, %v)", g, last, cur, ok)
 		}
 		count := 0
-		for range s.Prefix(fmt.Appendf(nil, "all/%d/", g)) {
+		for range s.Prefix(bg, fmt.Appendf(nil, "all/%d/", g)) {
 			count++
 		}
 		if count != 1 {
 // around the OS file system, so the numbers are real fdatasync calls.
 func BenchmarkApply(b *testing.B) {
 	fx := &countFS{FS: fsys.OS()}
-	db, err := open(fx, filepath.Join(b.TempDir(), "db"), Options{})
+	db, err := open(bg, fx, filepath.Join(b.TempDir(), "db"), Options{})
 	if err != nil {
 		b.Fatal(err)
 	}
-	defer db.Close()
+	defer func() { _ = db.Close(bg) }()
 	b.SetParallelism(16)
 	value := bytes.Repeat([]byte("v"), 100)
 	var next atomic.Uint64

M go.mod +10 -0

@@ -1,3 +1,13 @@
1	1		module bnema.dev/ermite-kv
2	2
3	3		go 1.27.1
	4	+
	5	+	require github.com/bnema/zerowrap v1.4.1
	6	+
	7	+	require (
	8	+	github.com/mattn/go-colorable v0.1.15 // indirect
	9	+	github.com/mattn/go-isatty v0.0.22 // indirect
	10	+	github.com/rs/zerolog v1.35.1 // indirect
	11	+	golang.org/x/sys v0.45.0 // indirect
	12	+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
	13	+	)

@@ -1,3 +1,13 @@
1	module bnema.dev/ermite-kv	1		module bnema.dev/ermite-kv
2		2
3	go 1.27.1	3		go 1.27.1
		4	+
		5	+	require github.com/bnema/zerowrap v1.4.1
		6	+
		7	+	require (
		8	+	github.com/mattn/go-colorable v0.1.15 // indirect
		9	+	github.com/mattn/go-isatty v0.0.22 // indirect
		10	+	github.com/rs/zerolog v1.35.1 // indirect
		11	+	golang.org/x/sys v0.45.0 // indirect
		12	+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
		13	+	)

A go.sum +12 -0 generated file: collapsed

load diff

M record.go +80 -40


@@ -29,7 +29,9 @@ const (
29	29		snapshotMagic = "EKVSNP01"
30	30		logHeaderSize = 8 + 8 + 4
31	31		recordFrame = 4 + 4 // len + crc
32		-	recordMinBody = 8 + 4 // seq + count
	32	+	recordHead = 8 + 4 // seq + batch count
	33	+	batchHeader = 4 // op count
	34	+	recordMinBody = 16 // smallest readable payload length
33	35		snapHeaderSize = 8 + 8 + 8 + 4
34	36		minOpSize = 3 // kind + klen + 1 key byte
35	37		)

@@ -85,13 +87,20 @@ func decodeLogHeader(b []byte) (base uint64, err error) {
85	87		return binary.LittleEndian.Uint64(b[8:16]), nil
86	88		}
87	89
88		-	// appendRecord appends one encoded record (len, crc, seq, count, ops) to dst.
89		-	// The payload must not exceed maxRecord and ops must be non-empty with valid
90		-	// keys; the caller enforces this (batches are validated before encoding).
91		-	func appendRecord(dst []byte, seq uint64, ops []op) []byte {
92		-	start := len(dst)
	90	+	// beginRecord starts a group record: it appends the frame placeholder, the
	91	+	// seq of the first batch and the batch count placeholder to dst. Batches are
	92	+	// added with appendBatch and the record is completed by finishRecord, which
	93	+	// expects the record to start at index 0 of the slice.
	94	+	func beginRecord(dst []byte, seq uint64) []byte {
93	95		dst = append(dst, make([]byte, recordFrame)...)
94	96		dst = binary.LittleEndian.AppendUint64(dst, seq)
	97	+	return binary.LittleEndian.AppendUint32(dst, 0)
	98	+	}
	99	+
	100	+	// appendBatch appends one batch (count, ops) to the record being built. ops
	101	+	// must be non-empty with valid keys; the caller enforces this (batches are
	102	+	// validated before encoding).
	103	+	func appendBatch(dst []byte, ops []op) []byte {
95	104		dst = binary.LittleEndian.AppendUint32(dst, uint32(len(ops)))
96	105		for _, o := range ops {
97	106		dst = append(dst, o.kind)

@@ -102,15 +111,33 @@ func appendRecord(dst []byte, seq uint64, ops []op) []byte {
102	111		dst = append(dst, o.value...)
103	112		}
104	113		}
105		-	payload := dst[start+recordFrame:]
106		-	binary.LittleEndian.PutUint32(dst[start:], uint32(len(payload)))
107		-	binary.LittleEndian.PutUint32(dst[start+4:], crc32.Checksum(payload, castagnoli))
108	114		return dst
109	115		}
110	116
	117	+	// finishRecord patches the batch count, length and checksum into rec, which
	118	+	// holds exactly one record started by beginRecord.
	119	+	func finishRecord(rec []byte, batches int) {
	120	+	binary.LittleEndian.PutUint32(rec[recordFrame+8:], uint32(batches))
	121	+	payload := rec[recordFrame:]
	122	+	binary.LittleEndian.PutUint32(rec, uint32(len(payload)))
	123	+	binary.LittleEndian.PutUint32(rec[4:], crc32.Checksum(payload, castagnoli))
	124	+	}
	125	+
	126	+	// appendRecord appends one encoded group record to dst. Batch i has seq
	127	+	// seq+i. The payload must not exceed maxRecord and every batch must hold
	128	+	// valid ops.
	129	+	func appendRecord(dst []byte, seq uint64, batches ...[]op) []byte {
	130	+	rec := beginRecord(nil, seq)
	131	+	for _, ops := range batches {
	132	+	rec = appendBatch(rec, ops)
	133	+	}
	134	+	finishRecord(rec, len(batches))
	135	+	return append(dst, rec...)
	136	+	}
	137	+
111	138		// peekRecord returns the total encoded size (frame + payload) announced by
112	139		// the record frame at the start of b. ok is false if fewer than 8 bytes are
113		-	// present or the announced payload length is outside [12, maxRecord]. It does
	140	+	// present or the announced payload length is outside [16, maxRecord]. It does
114	141		// not check that the payload is present.
115	142		func peekRecord(b []byte) (total int, ok bool) {
116	143		if len(b) < recordFrame {

@@ -124,13 +151,14 @@ func peekRecord(b []byte) (total int, ok bool) {
124	151		}
125	152
126	153		// decodeRecord decodes the record at the start of b. A record is readable
127		-	// only if the frame is present, 12 ≤ len ≤ maxRecord, len payload bytes are
128		-	// present, the CRC matches, and the payload holds exactly count ≥ 1 valid
129		-	// ops consuming exactly len bytes. Otherwise the error wraps errUnreadable.
	154	+	// only if the frame is present, 16 ≤ len ≤ maxRecord, len payload bytes are
	155	+	// present, the CRC matches, and the payload holds batches ≥ 1 batches of
	156	+	// count ≥ 1 valid ops each, consuming exactly len bytes. Otherwise the error
	157	+	// wraps errUnreadable.
130	158		//
131		-	// The decoded ops are appended to ops[:0]; their keys and values alias b.
132		-	// n is the number of bytes consumed.
133		-	func decodeRecord(b []byte, ops []op) (seq uint64, out []op, n int, err error) {
	159	+	// Batch i has seq seq+i. The decoded keys and values alias b. n is the number
	160	+	// of bytes consumed.
	161	+	func decodeRecord(b []byte) (seq uint64, batches [][]op, n int, err error) {
134	162		total, ok := peekRecord(b)
135	163		if !ok {
136	164		return 0, nil, 0, fmt.Errorf("%w: bad or short frame", errUnreadable)

@@ -142,45 +170,57 @@ func decodeRecord(b []byte, ops []op) (seq uint64, out []op, n int, err error) {
142	170		if crc32.Checksum(payload, castagnoli) != binary.LittleEndian.Uint32(b[4:8]) {
143	171		return 0, nil, 0, fmt.Errorf("%w: checksum mismatch", errUnreadable)
144	172		}
145		-	seq, out, err = decodePayload(payload, ops)
	173	+	seq, batches, err = decodePayload(payload)
146	174		if err != nil {
147	175		return 0, nil, 0, err
148	176		}
149		-	return seq, out, total, nil
	177	+	return seq, batches, total, nil
150	178		}
151	179
152		-	// decodePayload decodes seq, count and ops from a whole payload.
153		-	func decodePayload(p []byte, ops []op) (uint64, []op, error) {
	180	+	// decodePayload decodes seq, batch count and batches from a whole payload.
	181	+	func decodePayload(p []byte) (uint64, [][]op, error) {
154	182		seq := binary.LittleEndian.Uint64(p)
155		-	count := binary.LittleEndian.Uint32(p[8:])
156		-	p = p[recordMinBody:]
157		-	if count == 0 \|\| uint64(count) > uint64(len(p)/minOpSize) {
158		-	return 0, nil, fmt.Errorf("%w: bad op count %d", errUnreadable, count)
	183	+	nb := binary.LittleEndian.Uint32(p[8:])
	184	+	p = p[recordHead:]
	185	+	if nb == 0 \|\| uint64(nb) > uint64(len(p)/(batchHeader+minOpSize)) {
	186	+	return 0, nil, fmt.Errorf("%w: bad batch count %d", errUnreadable, nb)
159	187		}
160		-	ops = ops[:0]
161		-	for range count {
162		-	if len(p) == 0 {
163		-	return 0, nil, fmt.Errorf("%w: truncated op", errUnreadable)
164		-	}
165		-	o := op{kind: p[0]}
166		-	if o.kind != opPut && o.kind != opDelete {
167		-	return 0, nil, fmt.Errorf("%w: bad op kind %d", errUnreadable, o.kind)
	188	+	batches := make([][]op, 0, nb)
	189	+	for i := range nb {
	190	+	if len(p) < batchHeader {
	191	+	return 0, nil, fmt.Errorf("%w: truncated batch %d", errUnreadable, i)
168	192		}
169		-	var ok bool
170		-	if o.key, p, ok = cutBytes(p[1:], maxKeyLen); !ok \|\| len(o.key) == 0 {
171		-	return 0, nil, fmt.Errorf("%w: bad key", errUnreadable)
	193	+	count := binary.LittleEndian.Uint32(p)
	194	+	p = p[batchHeader:]
	195	+	if count == 0 \|\| uint64(count) > uint64(len(p)/minOpSize) {
	196	+	return 0, nil, fmt.Errorf("%w: bad op count %d in batch %d", errUnreadable, count, i)
172	197		}
173		-	if o.kind == opPut {
174		-	if o.value, p, ok = cutBytes(p, maxRecord); !ok {
175		-	return 0, nil, fmt.Errorf("%w: bad value", errUnreadable)
	198	+	ops := make([]op, 0, count)
	199	+	for range count {
	200	+	if len(p) == 0 {
	201	+	return 0, nil, fmt.Errorf("%w: truncated op", errUnreadable)
	202	+	}
	203	+	o := op{kind: p[0]}
	204	+	if o.kind != opPut && o.kind != opDelete {
	205	+	return 0, nil, fmt.Errorf("%w: bad op kind %d", errUnreadable, o.kind)
	206	+	}
	207	+	var ok bool
	208	+	if o.key, p, ok = cutBytes(p[1:], maxKeyLen); !ok \|\| len(o.key) == 0 {
	209	+	return 0, nil, fmt.Errorf("%w: bad key", errUnreadable)
	210	+	}
	211	+	if o.kind == opPut {
	212	+	if o.value, p, ok = cutBytes(p, maxRecord); !ok {
	213	+	return 0, nil, fmt.Errorf("%w: bad value", errUnreadable)
	214	+	}
176	215		}
	216	+	ops = append(ops, o)
177	217		}
178		-	ops = append(ops, o)
	218	+	batches = append(batches, ops)
179	219		}
180	220		if len(p) != 0 {
181	221		return 0, nil, fmt.Errorf("%w: %d trailing payload bytes", errUnreadable, len(p))
182	222		}
183		-	return seq, ops, nil
	223	+	return seq, batches, nil
184	224		}
185	225
186	226		// cutBytes reads a uvarint length (at most limit) and that many bytes from

 	snapshotMagic  = "EKVSNP01"
 	logHeaderSize  = 8 + 8 + 4
 	recordFrame    = 4 + 4 // len + crc
-	recordMinBody  = 8 + 4 // seq + count
+	recordHead     = 8 + 4 // seq + batch count
+	batchHeader    = 4     // op count
+	recordMinBody  = 16    // smallest readable payload length
 	snapHeaderSize = 8 + 8 + 8 + 4
 	minOpSize      = 3 // kind + klen + 1 key byte
 )
 	return binary.LittleEndian.Uint64(b[8:16]), nil
 }
-// appendRecord appends one encoded record (len, crc, seq, count, ops) to dst.
+// beginRecord starts a group record: it appends the frame placeholder, the
-// The payload must not exceed maxRecord and ops must be non-empty with valid
+// seq of the first batch and the batch count placeholder to dst. Batches are
-// keys; the caller enforces this (batches are validated before encoding).
+// added with appendBatch and the record is completed by finishRecord, which
-func appendRecord(dst []byte, seq uint64, ops []op) []byte {
+// expects the record to start at index 0 of the slice.
-	start := len(dst)
+func beginRecord(dst []byte, seq uint64) []byte {
 	dst = append(dst, make([]byte, recordFrame)...)
 	dst = binary.LittleEndian.AppendUint64(dst, seq)
+	return binary.LittleEndian.AppendUint32(dst, 0)
+}
+// appendBatch appends one batch (count, ops) to the record being built. ops
+// must be non-empty with valid keys; the caller enforces this (batches are
+// validated before encoding).
+func appendBatch(dst []byte, ops []op) []byte {
 	dst = binary.LittleEndian.AppendUint32(dst, uint32(len(ops)))
 	for _, o := range ops {
 		dst = append(dst, o.kind)
 			dst = append(dst, o.value...)
 		}
 	}
-	payload := dst[start+recordFrame:]
-	binary.LittleEndian.PutUint32(dst[start:], uint32(len(payload)))
-	binary.LittleEndian.PutUint32(dst[start+4:], crc32.Checksum(payload, castagnoli))
 	return dst
 }
+// finishRecord patches the batch count, length and checksum into rec, which
+// holds exactly one record started by beginRecord.
+func finishRecord(rec []byte, batches int) {
+	binary.LittleEndian.PutUint32(rec[recordFrame+8:], uint32(batches))
+	payload := rec[recordFrame:]
+	binary.LittleEndian.PutUint32(rec, uint32(len(payload)))
+	binary.LittleEndian.PutUint32(rec[4:], crc32.Checksum(payload, castagnoli))
+}
+// appendRecord appends one encoded group record to dst. Batch i has seq
+// seq+i. The payload must not exceed maxRecord and every batch must hold
+// valid ops.
+func appendRecord(dst []byte, seq uint64, batches ...[]op) []byte {
+	rec := beginRecord(nil, seq)
+	for _, ops := range batches {
+		rec = appendBatch(rec, ops)
+	}
+	finishRecord(rec, len(batches))
+	return append(dst, rec...)
+}
 // peekRecord returns the total encoded size (frame + payload) announced by
 // the record frame at the start of b. ok is false if fewer than 8 bytes are
-// present or the announced payload length is outside [12, maxRecord]. It does
+// present or the announced payload length is outside [16, maxRecord]. It does
 // not check that the payload is present.
 func peekRecord(b []byte) (total int, ok bool) {
 	if len(b) < recordFrame {
 }
 // decodeRecord decodes the record at the start of b. A record is readable
-// only if the frame is present, 12 ≤ len ≤ maxRecord, len payload bytes are
+// only if the frame is present, 16 ≤ len ≤ maxRecord, len payload bytes are
-// present, the CRC matches, and the payload holds exactly count ≥ 1 valid
+// present, the CRC matches, and the payload holds batches ≥ 1 batches of
-// ops consuming exactly len bytes. Otherwise the error wraps errUnreadable.
+// count ≥ 1 valid ops each, consuming exactly len bytes. Otherwise the error
+// wraps errUnreadable.
 //
-// The decoded ops are appended to ops[:0]; their keys and values alias b.
+// Batch i has seq seq+i. The decoded keys and values alias b. n is the number
-// n is the number of bytes consumed.
+// of bytes consumed.
-func decodeRecord(b []byte, ops []op) (seq uint64, out []op, n int, err error) {
+func decodeRecord(b []byte) (seq uint64, batches [][]op, n int, err error) {
 	total, ok := peekRecord(b)
 	if !ok {
 		return 0, nil, 0, fmt.Errorf("%w: bad or short frame", errUnreadable)
 	if crc32.Checksum(payload, castagnoli) != binary.LittleEndian.Uint32(b[4:8]) {
 		return 0, nil, 0, fmt.Errorf("%w: checksum mismatch", errUnreadable)
 	}
-	seq, out, err = decodePayload(payload, ops)
+	seq, batches, err = decodePayload(payload)
 	if err != nil {
 		return 0, nil, 0, err
 	}
-	return seq, out, total, nil
+	return seq, batches, total, nil
 }
-// decodePayload decodes seq, count and ops from a whole payload.
+// decodePayload decodes seq, batch count and batches from a whole payload.
-func decodePayload(p []byte, ops []op) (uint64, []op, error) {
+func decodePayload(p []byte) (uint64, [][]op, error) {
 	seq := binary.LittleEndian.Uint64(p)
-	count := binary.LittleEndian.Uint32(p[8:])
+	nb := binary.LittleEndian.Uint32(p[8:])
-	p = p[recordMinBody:]
+	p = p[recordHead:]
-	if count == 0 || uint64(count) > uint64(len(p)/minOpSize) {
+	if nb == 0 || uint64(nb) > uint64(len(p)/(batchHeader+minOpSize)) {
-		return 0, nil, fmt.Errorf("%w: bad op count %d", errUnreadable, count)
+		return 0, nil, fmt.Errorf("%w: bad batch count %d", errUnreadable, nb)
 	}
-	ops = ops[:0]
+	batches := make([][]op, 0, nb)
-	for range count {
+	for i := range nb {
-		if len(p) == 0 {
+		if len(p) < batchHeader {
-			return 0, nil, fmt.Errorf("%w: truncated op", errUnreadable)
+			return 0, nil, fmt.Errorf("%w: truncated batch %d", errUnreadable, i)
-		}
-		o := op{kind: p[0]}
-		if o.kind != opPut && o.kind != opDelete {
-			return 0, nil, fmt.Errorf("%w: bad op kind %d", errUnreadable, o.kind)
 		}
-		var ok bool
+		count := binary.LittleEndian.Uint32(p)
-		if o.key, p, ok = cutBytes(p[1:], maxKeyLen); !ok || len(o.key) == 0 {
+		p = p[batchHeader:]
-			return 0, nil, fmt.Errorf("%w: bad key", errUnreadable)
+		if count == 0 || uint64(count) > uint64(len(p)/minOpSize) {
+			return 0, nil, fmt.Errorf("%w: bad op count %d in batch %d", errUnreadable, count, i)
 		}
-		if o.kind == opPut {
+		ops := make([]op, 0, count)
-			if o.value, p, ok = cutBytes(p, maxRecord); !ok {
+		for range count {
-				return 0, nil, fmt.Errorf("%w: bad value", errUnreadable)
+			if len(p) == 0 {
+				return 0, nil, fmt.Errorf("%w: truncated op", errUnreadable)
+			}
+			o := op{kind: p[0]}
+			if o.kind != opPut && o.kind != opDelete {
+				return 0, nil, fmt.Errorf("%w: bad op kind %d", errUnreadable, o.kind)
+			}
+			var ok bool
+			if o.key, p, ok = cutBytes(p[1:], maxKeyLen); !ok || len(o.key) == 0 {
+				return 0, nil, fmt.Errorf("%w: bad key", errUnreadable)
+			}
+			if o.kind == opPut {
+				if o.value, p, ok = cutBytes(p, maxRecord); !ok {
+					return 0, nil, fmt.Errorf("%w: bad value", errUnreadable)
+				}
 			}
+			ops = append(ops, o)
 		}
-		ops = append(ops, o)
+		batches = append(batches, ops)
 	}
 	if len(p) != 0 {
 		return 0, nil, fmt.Errorf("%w: %d trailing payload bytes", errUnreadable, len(p))
 	}
-	return seq, ops, nil
+	return seq, batches, nil
 }
 // cutBytes reads a uvarint length (at most limit) and that many bytes from

M record_test.go +83 -36


@@ -28,28 +28,46 @@ func opsEqual(a, b []op) bool {
28	28
29	29		func TestRecordRoundTrip(t *testing.T) {
30	30		ops := sampleOps()
31		-	enc := appendRecord([]byte("prefix"), 42, ops)[6:]
	31	+	second := []op{{kind: opDelete, key: []byte("z")}}
	32	+	enc := appendRecord([]byte("prefix"), 42, ops, second, ops[:1])[6:]
32	33		size := 0
33		-	for _, o := range ops {
34		-	size += opSize(o)
	34	+	for _, b := range [][]op{ops, second, ops[:1]} {
	35	+	size += batchHeader
	36	+	for _, o := range b {
	37	+	size += opSize(o)
	38	+	}
35	39		}
36		-	if want := recordFrame + recordMinBody + size; len(enc) != want {
	40	+	if want := recordFrame + recordHead + size; len(enc) != want {
37	41		t.Fatalf("encoded size = %d, want %d", len(enc), want)
38	42		}
39		-	seq, got, n, err := decodeRecord(append(enc, 0xff, 0xee), nil)
	43	+	seq, got, n, err := decodeRecord(append(enc, 0xff, 0xee))
40	44		if err != nil {
41	45		t.Fatal(err)
42	46		}
43		-	if seq != 42 \|\| n != len(enc) \|\| !opsEqual(got, ops) {
44		-	t.Fatalf("got seq=%d n=%d ops=%v", seq, n, got)
	47	+	if seq != 42 \|\| n != len(enc) \|\| len(got) != 3 \|\|
	48	+	!opsEqual(got[0], ops) \|\| !opsEqual(got[1], second) \|\| !opsEqual(got[2], ops[:1]) {
	49	+	t.Fatalf("got seq=%d n=%d batches=%v", seq, n, got)
45	50		}
46		-	owned := ownOps(got)
	51	+	owned := ownOps(got[0])
47	52		clear(enc)
48	53		if !opsEqual(owned, ops) {
49	54		t.Fatal("ownOps aliases the source buffer")
50	55		}
51	56		}
52	57
	58	+	// TestRecordBuilder checks that beginRecord/appendBatch/finishRecord produce
	59	+	// the same bytes as appendRecord.
	60	+	func TestRecordBuilder(t *testing.T) {
	61	+	ops := sampleOps()
	62	+	rec := beginRecord(nil, 7)
	63	+	rec = appendBatch(rec, ops)
	64	+	rec = appendBatch(rec, ops[:2])
	65	+	finishRecord(rec, 2)
	66	+	if want := appendRecord(nil, 7, ops, ops[:2]); !bytes.Equal(rec, want) {
	67	+	t.Fatal("builder output differs from appendRecord")
	68	+	}
	69	+	}
	70	+
53	71		func TestLogHeader(t *testing.T) {
54	72		h := appendLogHeader(nil, 0x0102030405)
55	73		if len(h) != logHeaderSize {

@@ -77,43 +95,62 @@ func rawRecord(payload []byte) []byte {
77	95		return append(b, payload...)
78	96		}
79	97
80		-	func rawPayload(seq uint64, count uint32, body ...byte) []byte {
	98	+	// rawPayload builds a payload from the seq, the batch count and raw batch
	99	+	// bytes.
	100	+	func rawPayload(seq uint64, batches uint32, body ...byte) []byte {
81	101		p := binary.LittleEndian.AppendUint64(nil, seq)
82		-	p = binary.LittleEndian.AppendUint32(p, count)
	102	+	p = binary.LittleEndian.AppendUint32(p, batches)
83	103		return append(p, body...)
84	104		}
85	105
	106	+	// rawBatch encodes a batch header and raw op bytes.
	107	+	func rawBatch(count uint32, ops ...byte) []byte {
	108	+	return append(binary.LittleEndian.AppendUint32(nil, count), ops...)
	109	+	}
	110	+
	111	+	func cat(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
	112	+
86	113		func TestDecodeRecordUnreadable(t *testing.T) {
87		-	good := appendRecord(nil, 1, []op{{kind: opPut, key: []byte("k"), value: []byte("v")}})
	114	+	one := []op{{kind: opPut, key: []byte("k"), value: []byte("v")}}
	115	+	good := appendRecord(nil, 1, one)
88	116		badCRC := slices.Clone(good)
89	117		badCRC[len(badCRC)-1] ^= 1
90	118		tooBig := binary.LittleEndian.AppendUint32(nil, maxRecord+1)
91	119		tooBig = append(tooBig, make([]byte, 16)...)
	120	+	put := rawBatch(1, opPut, 1, 'k', 1, 'v')
	121	+	del := rawBatch(1, opDelete, 1, 'k')
92	122		cases := map[string][]byte{
93		-	"empty": nil,
94		-	"short frame": good[:7],
95		-	"short payload": good[:len(good)-1],
96		-	"bad crc": badCRC,
97		-	"len too small": rawRecord(make([]byte, 11)),
98		-	"len too big": tooBig,
99		-	"zero count": rawRecord(rawPayload(1, 0)),
100		-	"count too big": rawRecord(rawPayload(1, 2, opPut, 1, 'k', 1, 'v')),
101		-	"count too small": rawRecord(rawPayload(1, 1, opPut, 1, 'k', 1, 'v', opDelete, 1, 'k')),
102		-	"bad kind": rawRecord(rawPayload(1, 1, 3, 1, 'k')),
103		-	"empty key": rawRecord(rawPayload(1, 1, opDelete, 0, 0)),
104		-	"key past end": rawRecord(rawPayload(1, 1, opDelete, 9, 'k')),
105		-	"value past end": rawRecord(rawPayload(1, 1, opPut, 1, 'k', 5, 'v')),
106		-	"trailing byte": rawRecord(rawPayload(1, 1, opDelete, 1, 'k', 0)),
107		-	"huge count": rawRecord(rawPayload(1, 0xffffffff, opDelete, 1, 'k')),
	123	+	"empty": nil,
	124	+	"short frame": good[:7],
	125	+	"short payload": good[:len(good)-1],
	126	+	"bad crc": badCRC,
	127	+	"len too small": rawRecord(make([]byte, 15)),
	128	+	"len too big": tooBig,
	129	+	"zero batches": rawRecord(rawPayload(1, 0, put...)),
	130	+	"batches too big": rawRecord(rawPayload(1, 2, put...)),
	131	+	"batches too few": rawRecord(rawPayload(1, 1, cat(put, del)...)),
	132	+	"zero ops": rawRecord(rawPayload(1, 1, rawBatch(0, opDelete, 1, 'k')...)),
	133	+	"zero ops 2nd": rawRecord(rawPayload(1, 2, cat(put, rawBatch(0))...)),
	134	+	"ops too many": rawRecord(rawPayload(1, 1, rawBatch(2, opPut, 1, 'k', 1, 'v')...)),
	135	+	"ops too few": rawRecord(rawPayload(1, 1, rawBatch(1, opPut, 1, 'k', 1, 'v', opDelete, 1, 'k')...)),
	136	+	"bad kind": rawRecord(rawPayload(1, 1, rawBatch(1, 3, 1, 'k')...)),
	137	+	"empty key": rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 0, 0)...)),
	138	+	"key past end": rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 9, 'k')...)),
	139	+	"value past end": rawRecord(rawPayload(1, 1, rawBatch(1, opPut, 1, 'k', 5, 'v')...)),
	140	+	"trailing byte": rawRecord(rawPayload(1, 1, cat(del, []byte{0})...)),
	141	+	"huge batches": rawRecord(rawPayload(1, 0xffffffff, del...)),
	142	+	"huge op count": rawRecord(rawPayload(1, 1, rawBatch(0xffffffff, opDelete, 1, 'k')...)),
	143	+	"truncated batch": rawRecord(rawPayload(1, 2, cat(del, []byte{1, 0})...)),
	144	+	"second batch bad": rawRecord(rawPayload(1, 2, cat(del, rawBatch(1, 9, 1, 'k'))...)),
108	145		}
109	146		for name, b := range cases {
110	147		t.Run(name, func(t *testing.T) {
111		-	if _, _, _, err := decodeRecord(b, nil); !errors.Is(err, errUnreadable) {
	148	+	if _, _, _, err := decodeRecord(b); !errors.Is(err, errUnreadable) {
112	149		t.Fatalf("err = %v, want errUnreadable", err)
113	150		}
114	151		})
115	152		}
116		-	if _, _, _, err := decodeRecord(rawRecord(rawPayload(1, 1, opDelete, 1, 'k')), nil); err != nil {
	153	+	if _, _, _, err := decodeRecord(rawRecord(rawPayload(1, 1, del...))); err != nil {
117	154		t.Fatalf("control record: %v", err)
118	155		}
119	156		}

@@ -209,7 +246,6 @@ func TestSnapshotStructure(t *testing.T) {
209	246		b = binary.AppendUvarint(b, uint64(len(v)))
210	247		return append(b, v...)
211	248		}
212		-	cat := func(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
213	249		cases := map[string][]byte{
214	250		"not ascending": forgeSnapshot(5, 2, cat(entry("b", 1, ""), entry("a", 1, ""))),
215	251		"duplicate key": forgeSnapshot(5, 2, cat(entry("a", 1, ""), entry("a", 2, ""))),

@@ -259,8 +295,9 @@ func TestWriteSnapshotRejectsBadInput(t *testing.T) {
259	295
260	296		func FuzzDecodeRecord(f *testing.F) {
261	297		f.Add(appendRecord(nil, 1, sampleOps()))
	298	+	f.Add(appendRecord(nil, 1, sampleOps(), sampleOps()[:2]))
262	299		f.Add(appendRecord(nil, 1<<40, []op{{kind: opDelete, key: []byte("k")}}))
263		-	f.Add(rawRecord(rawPayload(1, 1, opDelete, 1, 'k')))
	300	+	f.Add(rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 1, 'k')...)))
264	301		f.Add([]byte{})
265	302		f.Add(make([]byte, 64))
266	303		f.Add(appendLogHeader(nil, 7))

@@ -272,19 +309,29 @@ func FuzzDecodeRecord(f *testing.F) {
272	309		view.each(func(k, v []byte, ver uint64) {})
273	310		}
274	311		peekRecord(b)
275		-	seq, ops, n, err := decodeRecord(b, nil)
	312	+	seq, batches, n, err := decodeRecord(b)
276	313		if err != nil {
277	314		return
278	315		}
279	316		// A readable record survives re-encoding (varints may be
280	317		// non-canonical in the input, so the bytes can differ).
281		-	if n > len(b) \|\| len(ops) == 0 {
282		-	t.Fatalf("n=%d len=%d ops=%d", n, len(b), len(ops))
	318	+	if n > len(b) \|\| len(batches) == 0 {
	319	+	t.Fatalf("n=%d len=%d batches=%d", n, len(b), len(batches))
	320	+	}
	321	+	for _, ops := range batches {
	322	+	if len(ops) == 0 {
	323	+	t.Fatal("readable record with an empty batch")
	324	+	}
283	325		}
284		-	enc := appendRecord(nil, seq, ops)
285		-	seq2, ops2, n2, err := decodeRecord(enc, nil)
286		-	if err != nil \|\| seq2 != seq \|\| n2 != len(enc) \|\| !opsEqual(ops2, ops) {
	326	+	enc := appendRecord(nil, seq, batches...)
	327	+	seq2, batches2, n2, err := decodeRecord(enc)
	328	+	if err != nil \|\| seq2 != seq \|\| n2 != len(enc) \|\| len(batches2) != len(batches) {
287	329		t.Fatalf("round trip failed: err=%v", err)
288	330		}
	331	+	for i := range batches {
	332	+	if !opsEqual(batches[i], batches2[i]) {
	333	+	t.Fatalf("batch %d differs after round trip", i)
	334	+	}
	335	+	}
289	336		})
290	337		}

 func TestRecordRoundTrip(t *testing.T) {
 	ops := sampleOps()
-	enc := appendRecord([]byte("prefix"), 42, ops)[6:]
+	second := []op{{kind: opDelete, key: []byte("z")}}
+	enc := appendRecord([]byte("prefix"), 42, ops, second, ops[:1])[6:]
 	size := 0
-	for _, o := range ops {
+	for _, b := range [][]op{ops, second, ops[:1]} {
-		size += opSize(o)
+		size += batchHeader
+		for _, o := range b {
+			size += opSize(o)
+		}
 	}
-	if want := recordFrame + recordMinBody + size; len(enc) != want {
+	if want := recordFrame + recordHead + size; len(enc) != want {
 		t.Fatalf("encoded size = %d, want %d", len(enc), want)
 	}
-	seq, got, n, err := decodeRecord(append(enc, 0xff, 0xee), nil)
+	seq, got, n, err := decodeRecord(append(enc, 0xff, 0xee))
 	if err != nil {
 		t.Fatal(err)
 	}
-	if seq != 42 || n != len(enc) || !opsEqual(got, ops) {
+	if seq != 42 || n != len(enc) || len(got) != 3 ||
-		t.Fatalf("got seq=%d n=%d ops=%v", seq, n, got)
+		!opsEqual(got[0], ops) || !opsEqual(got[1], second) || !opsEqual(got[2], ops[:1]) {
+		t.Fatalf("got seq=%d n=%d batches=%v", seq, n, got)
 	}
-	owned := ownOps(got)
+	owned := ownOps(got[0])
 	clear(enc)
 	if !opsEqual(owned, ops) {
 		t.Fatal("ownOps aliases the source buffer")
 	}
 }
+// TestRecordBuilder checks that beginRecord/appendBatch/finishRecord produce
+// the same bytes as appendRecord.
+func TestRecordBuilder(t *testing.T) {
+	ops := sampleOps()
+	rec := beginRecord(nil, 7)
+	rec = appendBatch(rec, ops)
+	rec = appendBatch(rec, ops[:2])
+	finishRecord(rec, 2)
+	if want := appendRecord(nil, 7, ops, ops[:2]); !bytes.Equal(rec, want) {
+		t.Fatal("builder output differs from appendRecord")
+	}
+}
 func TestLogHeader(t *testing.T) {
 	h := appendLogHeader(nil, 0x0102030405)
 	if len(h) != logHeaderSize {
 	return append(b, payload...)
 }
-func rawPayload(seq uint64, count uint32, body ...byte) []byte {
+// rawPayload builds a payload from the seq, the batch count and raw batch
+// bytes.
+func rawPayload(seq uint64, batches uint32, body ...byte) []byte {
 	p := binary.LittleEndian.AppendUint64(nil, seq)
-	p = binary.LittleEndian.AppendUint32(p, count)
+	p = binary.LittleEndian.AppendUint32(p, batches)
 	return append(p, body...)
 }
+// rawBatch encodes a batch header and raw op bytes.
+func rawBatch(count uint32, ops ...byte) []byte {
+	return append(binary.LittleEndian.AppendUint32(nil, count), ops...)
+}
+func cat(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
 func TestDecodeRecordUnreadable(t *testing.T) {
-	good := appendRecord(nil, 1, []op{{kind: opPut, key: []byte("k"), value: []byte("v")}})
+	one := []op{{kind: opPut, key: []byte("k"), value: []byte("v")}}
+	good := appendRecord(nil, 1, one)
 	badCRC := slices.Clone(good)
 	badCRC[len(badCRC)-1] ^= 1
 	tooBig := binary.LittleEndian.AppendUint32(nil, maxRecord+1)
 	tooBig = append(tooBig, make([]byte, 16)...)
+	put := rawBatch(1, opPut, 1, 'k', 1, 'v')
+	del := rawBatch(1, opDelete, 1, 'k')
 	cases := map[string][]byte{
-		"empty":           nil,
+		"empty":            nil,
-		"short frame":     good[:7],
+		"short frame":      good[:7],
-		"short payload":   good[:len(good)-1],
+		"short payload":    good[:len(good)-1],
-		"bad crc":         badCRC,
+		"bad crc":          badCRC,
-		"len too small":   rawRecord(make([]byte, 11)),
+		"len too small":    rawRecord(make([]byte, 15)),
-		"len too big":     tooBig,
+		"len too big":      tooBig,
-		"zero count":      rawRecord(rawPayload(1, 0)),
+		"zero batches":     rawRecord(rawPayload(1, 0, put...)),
-		"count too big":   rawRecord(rawPayload(1, 2, opPut, 1, 'k', 1, 'v')),
+		"batches too big":  rawRecord(rawPayload(1, 2, put...)),
-		"count too small": rawRecord(rawPayload(1, 1, opPut, 1, 'k', 1, 'v', opDelete, 1, 'k')),
+		"batches too few":  rawRecord(rawPayload(1, 1, cat(put, del)...)),
-		"bad kind":        rawRecord(rawPayload(1, 1, 3, 1, 'k')),
+		"zero ops":         rawRecord(rawPayload(1, 1, rawBatch(0, opDelete, 1, 'k')...)),
-		"empty key":       rawRecord(rawPayload(1, 1, opDelete, 0, 0)),
+		"zero ops 2nd":     rawRecord(rawPayload(1, 2, cat(put, rawBatch(0))...)),
-		"key past end":    rawRecord(rawPayload(1, 1, opDelete, 9, 'k')),
+		"ops too many":     rawRecord(rawPayload(1, 1, rawBatch(2, opPut, 1, 'k', 1, 'v')...)),
-		"value past end":  rawRecord(rawPayload(1, 1, opPut, 1, 'k', 5, 'v')),
+		"ops too few":      rawRecord(rawPayload(1, 1, rawBatch(1, opPut, 1, 'k', 1, 'v', opDelete, 1, 'k')...)),
-		"trailing byte":   rawRecord(rawPayload(1, 1, opDelete, 1, 'k', 0)),
+		"bad kind":         rawRecord(rawPayload(1, 1, rawBatch(1, 3, 1, 'k')...)),
-		"huge count":      rawRecord(rawPayload(1, 0xffffffff, opDelete, 1, 'k')),
+		"empty key":        rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 0, 0)...)),
+		"key past end":     rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 9, 'k')...)),
+		"value past end":   rawRecord(rawPayload(1, 1, rawBatch(1, opPut, 1, 'k', 5, 'v')...)),
+		"trailing byte":    rawRecord(rawPayload(1, 1, cat(del, []byte{0})...)),
+		"huge batches":     rawRecord(rawPayload(1, 0xffffffff, del...)),
+		"huge op count":    rawRecord(rawPayload(1, 1, rawBatch(0xffffffff, opDelete, 1, 'k')...)),
+		"truncated batch":  rawRecord(rawPayload(1, 2, cat(del, []byte{1, 0})...)),
+		"second batch bad": rawRecord(rawPayload(1, 2, cat(del, rawBatch(1, 9, 1, 'k'))...)),
 	}
 	for name, b := range cases {
 		t.Run(name, func(t *testing.T) {
-			if _, _, _, err := decodeRecord(b, nil); !errors.Is(err, errUnreadable) {
+			if _, _, _, err := decodeRecord(b); !errors.Is(err, errUnreadable) {
 				t.Fatalf("err = %v, want errUnreadable", err)
 			}
 		})
 	}
-	if _, _, _, err := decodeRecord(rawRecord(rawPayload(1, 1, opDelete, 1, 'k')), nil); err != nil {
+	if _, _, _, err := decodeRecord(rawRecord(rawPayload(1, 1, del...))); err != nil {
 		t.Fatalf("control record: %v", err)
 	}
 }
 		b = binary.AppendUvarint(b, uint64(len(v)))
 		return append(b, v...)
 	}
-	cat := func(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
 	cases := map[string][]byte{
 		"not ascending":  forgeSnapshot(5, 2, cat(entry("b", 1, ""), entry("a", 1, ""))),
 		"duplicate key":  forgeSnapshot(5, 2, cat(entry("a", 1, ""), entry("a", 2, ""))),
 func FuzzDecodeRecord(f *testing.F) {
 	f.Add(appendRecord(nil, 1, sampleOps()))
+	f.Add(appendRecord(nil, 1, sampleOps(), sampleOps()[:2]))
 	f.Add(appendRecord(nil, 1<<40, []op{{kind: opDelete, key: []byte("k")}}))
-	f.Add(rawRecord(rawPayload(1, 1, opDelete, 1, 'k')))
+	f.Add(rawRecord(rawPayload(1, 1, rawBatch(1, opDelete, 1, 'k')...)))
 	f.Add([]byte{})
 	f.Add(make([]byte, 64))
 	f.Add(appendLogHeader(nil, 7))
 			view.each(func(k, v []byte, ver uint64) {})
 		}
 		peekRecord(b)
-		seq, ops, n, err := decodeRecord(b, nil)
+		seq, batches, n, err := decodeRecord(b)
 		if err != nil {
 			return
 		}
 		// A readable record survives re-encoding (varints may be
 		// non-canonical in the input, so the bytes can differ).
-		if n > len(b) || len(ops) == 0 {
+		if n > len(b) || len(batches) == 0 {
-			t.Fatalf("n=%d len=%d ops=%d", n, len(b), len(ops))
+			t.Fatalf("n=%d len=%d batches=%d", n, len(b), len(batches))
+		}
+		for _, ops := range batches {
+			if len(ops) == 0 {
+				t.Fatal("readable record with an empty batch")
+			}
 		}
-		enc := appendRecord(nil, seq, ops)
+		enc := appendRecord(nil, seq, batches...)
-		seq2, ops2, n2, err := decodeRecord(enc, nil)
+		seq2, batches2, n2, err := decodeRecord(enc)
-		if err != nil || seq2 != seq || n2 != len(enc) || !opsEqual(ops2, ops) {
+		if err != nil || seq2 != seq || n2 != len(enc) || len(batches2) != len(batches) {
 			t.Fatalf("round trip failed: err=%v", err)
 		}
+		for i := range batches {
+			if !opsEqual(batches[i], batches2[i]) {
+				t.Fatalf("batch %d differs after round trip", i)
+			}
+		}
 	})
 }

M recover.go +28 -27


@@ -6,13 +6,14 @@ import (
6	6		"errors"
7	7		"fmt"
8	8		"io"
9		-	"log/slog"
10	9		"os"
11	10		"path/filepath"
12	11		"slices"
13	12		"strconv"
14	13		"strings"
15	14
	15	+	"github.com/bnema/zerowrap"
	16	+
16	17		"bnema.dev/ermite-kv/internal/fsys"
17	18		)
18	19

@@ -60,21 +61,19 @@ type recovered struct {
60	61		// the in-memory tree.
61	62		//
62	63		// load is called once per snapshot entry in ascending key order, only after
63		-	// the whole snapshot file has been validated. apply is called for each log
64		-	// record newer than the snapshot, in seq order. Both receive freshly
65		-	// allocated slices that the callee may retain but must not modify; recovery
66		-	// never reuses them (snapshot entries share one read-only buffer, log ops are
67		-	// copied per record). Either callback may be nil. A nil logger discards logs.
	64	+	// the whole snapshot file has been validated. apply is called for each batch
	65	+	// newer than the snapshot, in seq order (a record that straddles the snapshot
	66	+	// seq contributes only its newer batches). The ops passed to apply are freshly
	67	+	// allocated and the callee may retain them but must not modify them. load
	68	+	// receives slices of one shared read-only buffer: it must copy what it keeps.
	69	+	// Either callback may be nil. A zero logger discards logs.
68	70		//
69	71		// On error nothing stays open or locked. ErrLocked and ErrCorrupt are
70	72		// returned wrapped.
71		-	func recoverDir(fx fsys.FS, dir string, logger *slog.Logger,
	73	+	func recoverDir(fx fsys.FS, dir string, logger zerowrap.Logger,
72	74		load func(key, value []byte, version uint64),
73	75		apply func(seq uint64, ops []op),
74	76		) (rec recovered, err error) {
75		-	if logger == nil {
76		-	logger = slog.New(slog.DiscardHandler)
77		-	}
78	77		dir = filepath.Clean(dir)
79	78		if err := fx.MkdirAll(dir, 0o700); err != nil {
80	79		return rec, err

@@ -138,7 +137,7 @@ func recoverDir(fx fsys.FS, dir string, logger *slog.Logger,
138	137		err = fmt.Errorf("%w: snapshot seq %d does not match its name", ErrCorrupt, view.seq)
139	138		}
140	139		if err != nil {
141		-	logger.Warn("kv: ignoring invalid snapshot", "file", path, "err", err)
	140	+	logger.Warn().Err(err).Str("file", path).Msg("ignoring invalid snapshot")
142	141		continue
143	142		}
144	143		if load != nil {

@@ -200,7 +199,7 @@ func recoverDir(fx fsys.FS, dir string, logger *slog.Logger,
200	199		// the last log it is used to truncate a torn tail. It returns the size of the
201	200		// log after recovery.
202	201		func replayLog(f fsys.File, data []byte, path string, base uint64, rec *recovered,
203		-	logger *slog.Logger, apply func(seq uint64, ops []op),
	202	+	logger zerowrap.Logger, apply func(seq uint64, ops []op),
204	203		) (int64, error) {
205	204		last := f != nil
206	205		corrupt := func(off int, format string, args ...any) error {

@@ -217,20 +216,18 @@ func replayLog(f fsys.File, data []byte, path string, base uint64, rec *recovere
217	216		return 0, corrupt(0, "base %d is above the last recovered seq %d", base, rec.lastSeq)
218	217		}
219	218
220		-	var ops []op
221		-	expected := base + 1 // seq of the next record of this file
	219	+	expected := base + 1 // seq of the first batch of the next record
222	220		off := logHeaderSize
223	221		for off < len(data) {
224		-	seq, decoded, n, err := decodeRecord(data[off:], ops)
	222	+	seq, batches, n, err := decodeRecord(data[off:])
225	223		if err != nil {
226	224		if !last {
227	225		return 0, corrupt(off, "%v", err)
228	226		}
229		-	// Rule 6: a readable next record means acknowledged data
230		-	// lies beyond the damage.
	227	+	// Rule 6: a readable record after the damaged one proves that
	228	+	// the damaged one was synced: acknowledged data is damaged.
231	229		if total, ok := peekRecord(data[off:]); ok && off+total < len(data) {
232		-	nseq, _, _, nerr := decodeRecord(data[off+total:], nil)
233		-	if nerr == nil && nseq == expected+1 {
	230	+	if _, _, _, nerr := decodeRecord(data[off+total:]); nerr == nil {
234	231		return 0, corrupt(off, "%v, followed by a valid record", err)
235	232		}
236	233		}

@@ -240,24 +237,28 @@ func replayLog(f fsys.File, data []byte, path string, base uint64, rec *recovere
240	237		if err := f.SyncAll(); err != nil {
241	238		return 0, err
242	239		}
243		-	logger.Warn("kv: dropped torn log tail", "file", path, "offset", off, "bytes", len(data)-off)
	240	+	logger.Warn().Str("file", path).Int("offset", off).Int("bytes", len(data)-off).
	241	+	Msg("dropped torn log tail")
244	242		data = data[:off]
245	243		break
246	244		}
247		-	ops = decoded[:0]
248	245		if seq != expected {
249	246		return 0, corrupt(off, "record seq %d, want %d", seq, expected)
250	247		}
251		-	if seq > rec.snapSeq {
252		-	if seq != rec.lastSeq+1 {
253		-	return 0, corrupt(off, "record seq %d, want %d", seq, rec.lastSeq+1)
	248	+	for i, ops := range batches {
	249	+	s := seq + uint64(i)
	250	+	if s <= rec.snapSeq {
	251	+	continue
	252	+	}
	253	+	if s != rec.lastSeq+1 {
	254	+	return 0, corrupt(off, "batch seq %d, want %d", s, rec.lastSeq+1)
254	255		}
255	256		if apply != nil {
256		-	apply(seq, ownOps(decoded))
	257	+	apply(s, ownOps(ops))
257	258		}
258		-	rec.lastSeq = seq
	259	+	rec.lastSeq = s
259	260		}
260		-	expected++
	261	+	expected += uint64(len(batches))
261	262		off += n
262	263		}
263	264		if last && expected-1 < rec.lastSeq {

 	"errors"
 	"fmt"
 	"io"
-	"log/slog"
 	"os"
 	"path/filepath"
 	"slices"
 	"strconv"
 	"strings"
+	"github.com/bnema/zerowrap"
 	"bnema.dev/ermite-kv/internal/fsys"
 )
 // the in-memory tree.
 //
 // load is called once per snapshot entry in ascending key order, only after
-// the whole snapshot file has been validated. apply is called for each log
+// the whole snapshot file has been validated. apply is called for each batch
-// record newer than the snapshot, in seq order. Both receive freshly
+// newer than the snapshot, in seq order (a record that straddles the snapshot
-// allocated slices that the callee may retain but must not modify; recovery
+// seq contributes only its newer batches). The ops passed to apply are freshly
-// never reuses them (snapshot entries share one read-only buffer, log ops are
+// allocated and the callee may retain them but must not modify them. load
-// copied per record). Either callback may be nil. A nil logger discards logs.
+// receives slices of one shared read-only buffer: it must copy what it keeps.
+// Either callback may be nil. A zero logger discards logs.
 //
 // On error nothing stays open or locked. ErrLocked and ErrCorrupt are
 // returned wrapped.
-func recoverDir(fx fsys.FS, dir string, logger *slog.Logger,
+func recoverDir(fx fsys.FS, dir string, logger zerowrap.Logger,
 	load func(key, value []byte, version uint64),
 	apply func(seq uint64, ops []op),
 ) (rec recovered, err error) {
-	if logger == nil {
-		logger = slog.New(slog.DiscardHandler)
-	}
 	dir = filepath.Clean(dir)
 	if err := fx.MkdirAll(dir, 0o700); err != nil {
 		return rec, err
 			err = fmt.Errorf("%w: snapshot seq %d does not match its name", ErrCorrupt, view.seq)
 		}
 		if err != nil {
-			logger.Warn("kv: ignoring invalid snapshot", "file", path, "err", err)
+			logger.Warn().Err(err).Str("file", path).Msg("ignoring invalid snapshot")
 			continue
 		}
 		if load != nil {
 // the last log it is used to truncate a torn tail. It returns the size of the
 // log after recovery.
 func replayLog(f fsys.File, data []byte, path string, base uint64, rec *recovered,
-	logger *slog.Logger, apply func(seq uint64, ops []op),
+	logger zerowrap.Logger, apply func(seq uint64, ops []op),
 ) (int64, error) {
 	last := f != nil
 	corrupt := func(off int, format string, args ...any) error {
 		return 0, corrupt(0, "base %d is above the last recovered seq %d", base, rec.lastSeq)
 	}
-	var ops []op
+	expected := base + 1 // seq of the first batch of the next record
-	expected := base + 1 // seq of the next record of this file
 	off := logHeaderSize
 	for off < len(data) {
-		seq, decoded, n, err := decodeRecord(data[off:], ops)
+		seq, batches, n, err := decodeRecord(data[off:])
 		if err != nil {
 			if !last {
 				return 0, corrupt(off, "%v", err)
 			}
-			// Rule 6: a readable next record means acknowledged data
+			// Rule 6: a readable record after the damaged one proves that
-			// lies beyond the damage.
+			// the damaged one was synced: acknowledged data is damaged.
 			if total, ok := peekRecord(data[off:]); ok && off+total < len(data) {
-				nseq, _, _, nerr := decodeRecord(data[off+total:], nil)
+				if _, _, _, nerr := decodeRecord(data[off+total:]); nerr == nil {
-				if nerr == nil && nseq == expected+1 {
 					return 0, corrupt(off, "%v, followed by a valid record", err)
 				}
 			}
 			if err := f.SyncAll(); err != nil {
 				return 0, err
 			}
-			logger.Warn("kv: dropped torn log tail", "file", path, "offset", off, "bytes", len(data)-off)
+			logger.Warn().Str("file", path).Int("offset", off).Int("bytes", len(data)-off).
+				Msg("dropped torn log tail")
 			data = data[:off]
 			break
 		}
-		ops = decoded[:0]
 		if seq != expected {
 			return 0, corrupt(off, "record seq %d, want %d", seq, expected)
 		}
-		if seq > rec.snapSeq {
+		for i, ops := range batches {
-			if seq != rec.lastSeq+1 {
+			s := seq + uint64(i)
-				return 0, corrupt(off, "record seq %d, want %d", seq, rec.lastSeq+1)
+			if s <= rec.snapSeq {
+				continue
+			}
+			if s != rec.lastSeq+1 {
+				return 0, corrupt(off, "batch seq %d, want %d", s, rec.lastSeq+1)
 			}
 			if apply != nil {
-				apply(seq, ownOps(decoded))
+				apply(s, ownOps(ops))
 			}
-			rec.lastSeq = seq
+			rec.lastSeq = s
 		}
-		expected++
+		expected += uint64(len(batches))
 		off += n
 	}
 	if last && expected-1 < rec.lastSeq {

M recover_test.go +125 -19


@@ -4,14 +4,17 @@ package kv
4	4
5	5		import (
6	6		"bytes"
	7	+	"context"
7	8		"errors"
8	9		"fmt"
9	10		"io"
10		-	"log/slog"
11	11		"path/filepath"
	12	+	"slices"
12	13		"strings"
13	14		"testing"
14	15
	16	+	"github.com/bnema/zerowrap"
	17	+
15	18		"bnema.dev/ermite-kv/internal/fsys"
16	19		"bnema.dev/ermite-kv/internal/fsys/faultfs"
17	20		)

@@ -44,7 +47,15 @@ func (s *state) apply(seq uint64, ops []op) {
44	47		}
45	48		}
46	49
47		-	func recoverState(t testing.T, fx fsys.FS, logger slog.Logger) (*state, recovered, error) {
	50	+	// noLog is a disabled logger.
	51	+	var noLog = zerowrap.FromCtx(context.Background())
	52	+
	53	+	// bufLogger returns a JSON logger at debug level writing to buf.
	54	+	func bufLogger(buf *bytes.Buffer) zerowrap.Logger {
	55	+	return zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: buf})
	56	+	}
	57	+
	58	+	func recoverState(t testing.T, fx fsys.FS, logger zerowrap.Logger) (state, recovered, error) {
48	59		t.Helper()
49	60		s := &state{m: map[string]string{}, versions: map[string]uint64{}}
50	61		rec, err := recoverDir(fx, testDir, logger, s.load, s.apply)

@@ -55,7 +66,7 @@ func recoverState(t testing.T, fx fsys.FS, logger slog.Logger) (*state, recove
55	66		// releases the lock and the log file.
56	67		func mustRecover(t testing.T, fx fsys.FS) (state, recovered) {
57	68		t.Helper()
58		-	s, rec, err := recoverState(t, fx, nil)
	69	+	s, rec, err := recoverState(t, fx, noLog)
59	70		if err != nil {
60	71		t.Fatalf("recoverDir: %v", err)
61	72		}

@@ -134,12 +145,12 @@ func TestRecoverEmptyDirCreatesLog(t *testing.T) {
134	145		func TestRecoverLockedAndRelease(t *testing.T) {
135	146		fx := faultfs.New()
136	147		_, rec := mustRecover(t, fx)
137		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrLocked) {
	148	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrLocked) {
138	149		t.Fatalf("second recover: err = %v, want ErrLocked", err)
139	150		}
140	151		_ = rec.log.Close()
141	152		_ = rec.lock.Close()
142		-	_, rec2, err := recoverState(t, fx, nil)
	153	+	_, rec2, err := recoverState(t, fx, noLog)
143	154		if err != nil {
144	155		t.Fatalf("recover after release: %v", err)
145	156		}

@@ -150,7 +161,7 @@ func TestRecoverLockedAndRelease(t *testing.T) {
150	161		func TestRecoverReleasesLockOnError(t *testing.T) {
151	162		fx := faultfs.New()
152	163		put(fx, logName(0), []byte("garbage"))
153		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
	164	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
154	165		t.Fatalf("err = %v, want ErrCorrupt", err)
155	166		}
156	167		l, err := fx.Lock(filepath.Join(testDir, lockName))

@@ -228,7 +239,7 @@ func TestRecoverTornTail(t *testing.T) {
228	239		fx := faultfs.New()
229	240		put(fx, logName(0), append(append([]byte(nil), good...), tail...))
230	241		var logs bytes.Buffer
231		-	s, rec, err := recoverState(t, fx, slog.New(slog.NewTextHandler(&logs, nil)))
	242	+	s, rec, err := recoverState(t, fx, bufLogger(&logs))
232	243		if err != nil {
233	244		t.Fatal(err)
234	245		}

@@ -270,20 +281,19 @@ func TestRecoverDamageFollowedByValidRecord(t *testing.T) {
270	281		return c
271	282		}
272	283		hdr := appendLogHeader(nil, 0)
273		-	cat := func(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
274	284		cases := map[string][]byte{
275	285		"bad crc in middle record": cat(hdr, r1, flip(r2, len(r2)-1), r3),
276	286		"bad payload in first record": cat(hdr, flip(r1, 9), r2),
277	287		"bad checksum field": cat(hdr, r1, flip(r2, 4), r3),
278	288		"damaged record before last": cat(hdr, flip(r1, len(r1)-1), r2, r3),
279		-	"record with wrong count": cat(hdr, rawRecord(rawPayload(1, 5, opDelete, 1, 'k')), r2),
	289	+	"record with wrong count": cat(hdr, rawRecord(rawPayload(1, 5, rawBatch(1, opDelete, 1, 'k')...)), r2),
280	290		"corrupt but len looks intact": cat(hdr, r1, flip(r2, 12), r3),
281	291		}
282	292		for name, data := range cases {
283	293		t.Run(name, func(t *testing.T) {
284	294		fx := faultfs.New()
285	295		put(fx, logName(0), data)
286		-	_, _, err := recoverState(t, fx, nil)
	296	+	_, _, err := recoverState(t, fx, noLog)
287	297		if !errors.Is(err, ErrCorrupt) {
288	298		t.Fatalf("err = %v, want ErrCorrupt", err)
289	299		}

@@ -308,7 +318,7 @@ func TestRecoverDamageInOlderLog(t *testing.T) {
308	318		fx := faultfs.New()
309	319		put(fx, logName(0), data)
310	320		put(fx, logName(2), logBytes(2, []op{putOp("c", "3")}))
311		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
	321	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
312	322		t.Fatalf("err = %v, want ErrCorrupt", err)
313	323		}
314	324		})

@@ -338,7 +348,7 @@ func TestRecoverBadLogHeader(t *testing.T) {
338	348		t.Run(name, func(t *testing.T) {
339	349		fx := faultfs.New()
340	350		put(fx, c.name, c.data)
341		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
	351	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
342	352		t.Fatalf("err = %v, want ErrCorrupt", err)
343	353		}
344	354		})

@@ -347,7 +357,7 @@ func TestRecoverBadLogHeader(t *testing.T) {
347	357		fx := faultfs.New()
348	358		put(fx, logName(0), good[:10])
349	359		put(fx, logName(1), logBytes(1, []op{putOp("b", "2")}))
350		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
	360	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
351	361		t.Fatalf("err = %v, want ErrCorrupt", err)
352	362		}
353	363		})

@@ -391,7 +401,7 @@ func TestRecoverSeqGap(t *testing.T) {
391	401		t.Run(name, func(t *testing.T) {
392	402		fx := faultfs.New()
393	403		setup(fx)
394		-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
	404	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
395	405		t.Fatalf("err = %v, want ErrCorrupt", err)
396	406		}
397	407		})

@@ -444,7 +454,7 @@ func TestRecoverInvalidNewestSnapshotFallsBack(t *testing.T) {
444	454		put(fx, snapshotName(4), bad)
445	455		put(fx, logName(2), logBytes(2, []op{putOp("c", "3")}, []op{putOp("d", "4")}, []op{delOp("a")}))
446	456		var logs bytes.Buffer
447		-	s, rec, err := recoverState(t, fx, slog.New(slog.NewTextHandler(&logs, nil)))
	457	+	s, rec, err := recoverState(t, fx, bufLogger(&logs))
448	458		if err != nil {
449	459		t.Fatal(err)
450	460		}

@@ -489,7 +499,7 @@ func TestRecoverSnapshotLoadOrderAndOwnership(t *testing.T) {
489	499		put(fx, snapshotName(1), snapshotBytes(t, 1, snapEnt("a", "1", 1), snapEnt("b", "2", 1), snapEnt("c", "3", 1)))
490	500		var keys []string
491	501		var held [][]byte
492		-	_, err := recoverDir(fx, testDir, nil, func(k, v []byte, ver uint64) {
	502	+	_, err := recoverDir(fx, testDir, noLog, func(k, v []byte, ver uint64) {
493	503		keys = append(keys, string(k))
494	504		held = append(held, k, v)
495	505		}, nil)

@@ -528,11 +538,11 @@ func TestRecoverOSFilesystem(t *testing.T) {
528	538		data := logBytes(0, []op{putOp("a", "1")}, []op{putOp("b", "2")})
529	539		torn := append(append([]byte(nil), data...), 9, 9, 9)
530	540
531		-	rec, err := recoverDir(fsys.OS(), dir, nil, nil, nil)
	541	+	rec, err := recoverDir(fsys.OS(), dir, noLog, nil, nil)
532	542		if err != nil {
533	543		t.Fatal(err)
534	544		}
535		-	if _, err := recoverDir(fsys.OS(), dir, nil, nil, nil); !errors.Is(err, ErrLocked) {
	545	+	if _, err := recoverDir(fsys.OS(), dir, noLog, nil, nil); !errors.Is(err, ErrLocked) {
536	546		t.Fatalf("second recover: err = %v, want ErrLocked", err)
537	547		}
538	548		if _, err := rec.log.Write(data[logHeaderSize:]); err != nil {

@@ -548,7 +558,7 @@ func TestRecoverOSFilesystem(t *testing.T) {
548	558		_ = rec.lock.Close()
549	559
550	560		s := &state{m: map[string]string{}, versions: map[string]uint64{}}
551		-	rec, err = recoverDir(fsys.OS(), dir, nil, s.load, s.apply)
	561	+	rec, err = recoverDir(fsys.OS(), dir, noLog, s.load, s.apply)
552	562		if err != nil {
553	563		t.Fatal(err)
554	564		}

@@ -563,3 +573,99 @@ func TestRecoverOSFilesystem(t *testing.T) {
563	573		t.Fatalf("ReadAt = %d, %v: tail not truncated", n, err)
564	574		}
565	575		}
	576	+
	577	+	func TestRecoverGroupRecords(t *testing.T) {
	578	+	fx := faultfs.New()
	579	+	b := appendLogHeader(nil, 0)
	580	+	b = appendRecord(b, 1, []op{putOp("a", "1")}, []op{putOp("b", "2"), delOp("a")}, []op{putOp("c", "3")})
	581	+	b = appendRecord(b, 4, []op{putOp("a", "4")})
	582	+	put(fx, logName(0), b)
	583	+	s, rec := mustRecover(t, fx)
	584	+	wantState(t, s, map[string]string{"a": "4", "b": "2", "c": "3"})
	585	+	if got := fmt.Sprint(s.seqs); got != "[1 2 3 4]" {
	586	+	t.Fatalf("applied seqs %s", got)
	587	+	}
	588	+	if s.versions["b"] != 2 \|\| s.versions["c"] != 3 \|\| s.versions["a"] != 4 \|\| rec.lastSeq != 4 {
	589	+	t.Fatalf("versions = %v, rec = %+v", s.versions, rec)
	590	+	}
	591	+	}
	592	+
	593	+	// TestRecoverRecordStraddlesSnapshot checks that only the batches newer than
	594	+	// the snapshot of a record that spans the snapshot seq are replayed.
	595	+	func TestRecoverRecordStraddlesSnapshot(t *testing.T) {
	596	+	fx := faultfs.New()
	597	+	put(fx, snapshotName(2), snapshotBytes(t, 2, snapEnt("a", "1", 1), snapEnt("b", "2", 2)))
	598	+	b := appendLogHeader(nil, 0)
	599	+	b = appendRecord(b, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")}, []op{putOp("c", "3")}, []op{delOp("a")})
	600	+	b = appendRecord(b, 5, []op{putOp("d", "5")})
	601	+	put(fx, logName(0), b)
	602	+	s, rec := mustRecover(t, fx)
	603	+	wantState(t, s, map[string]string{"b": "2", "c": "3", "d": "5"})
	604	+	if got := fmt.Sprint(s.seqs); got != "[3 4 5]" {
	605	+	t.Fatalf("applied seqs %s, want [3 4 5]", got)
	606	+	}
	607	+	if rec.snapSeq != 2 \|\| rec.lastSeq != 5 {
	608	+	t.Fatalf("rec = %+v", rec)
	609	+	}
	610	+
	611	+	// A record that ends exactly at the snapshot seq adds nothing.
	612	+	fx = faultfs.New()
	613	+	put(fx, snapshotName(2), snapshotBytes(t, 2, snapEnt("a", "1", 1), snapEnt("b", "2", 2)))
	614	+	put(fx, logName(0), cat(appendLogHeader(nil, 0), appendRecord(nil, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")})))
	615	+	s, rec = mustRecover(t, fx)
	616	+	if len(s.seqs) != 0 \|\| rec.lastSeq != 2 {
	617	+	t.Fatalf("applied %v, rec = %+v", s.seqs, rec)
	618	+	}
	619	+	}
	620	+
	621	+	func TestRecoverTornGroupRecordFollowedByValidRecord(t *testing.T) {
	622	+	r1 := appendRecord(nil, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")})
	623	+	r2 := appendRecord(nil, 3, []op{putOp("c", "3")}, []op{putOp("d", "4")})
	624	+	r3 := appendRecord(nil, 5, []op{putOp("e", "5")})
	625	+	damaged := slices.Clone(r2)
	626	+	damaged[len(damaged)/2] ^= 0xff
	627	+	fx := faultfs.New()
	628	+	data := cat(appendLogHeader(nil, 0), r1, damaged, r3)
	629	+	put(fx, logName(0), data)
	630	+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
	631	+	t.Fatalf("err = %v, want ErrCorrupt", err)
	632	+	}
	633	+	if got, _ := fx.ReadFile(filepath.Join(testDir, logName(0))); !bytes.Equal(got, data) {
	634	+	t.Fatal("corrupt log was modified")
	635	+	}
	636	+
	637	+	// Without a readable record after it, the same damage is a torn tail
	638	+	// that drops the whole group record, and nothing of it is applied.
	639	+	fx = faultfs.New()
	640	+	put(fx, logName(0), cat(appendLogHeader(nil, 0), r1, damaged))
	641	+	s, rec := mustRecover(t, fx)
	642	+	wantState(t, s, map[string]string{"a": "1", "b": "2"})
	643	+	if rec.lastSeq != 2 {
	644	+	t.Fatalf("rec = %+v", rec)
	645	+	}
	646	+	}
	647	+
	648	+	// TestRecoverDamagedLenIsTornTail checks that a damaged len field of the last
	649	+	// record is handled as a torn tail: the record is dropped.
	650	+	func TestRecoverDamagedLenIsTornTail(t *testing.T) {
	651	+	good := logBytes(0, []op{putOp("a", "1")})
	652	+	r2 := appendRecord(nil, 2, []op{putOp("b", "2")})
	653	+	for name, patch := range map[string]func(b []byte){
	654	+	"len beyond EOF": func(b []byte) { b[1] = 0x7f },
	655	+	"len above max": func(b []byte) { b[3] = 0x7f },
	656	+	"len below min": func(b []byte) { clear(b[:4]) },
	657	+	"len off by some": func(b []byte) { b[0] += 3 },
	658	+	} {
	659	+	t.Run(name, func(t *testing.T) {
	660	+	bad := slices.Clone(r2)
	661	+	patch(bad)
	662	+	fx := faultfs.New()
	663	+	put(fx, logName(0), cat(good, bad))
	664	+	s, rec := mustRecover(t, fx)
	665	+	wantState(t, s, map[string]string{"a": "1"})
	666	+	if rec.lastSeq != 1 \|\| rec.logSize != int64(len(good)) {
	667	+	t.Fatalf("rec = %+v", rec)
	668	+	}
	669	+	})
	670	+	}
	671	+	}

 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"io"
-	"log/slog"
 	"path/filepath"
+	"slices"
 	"strings"
 	"testing"
+	"github.com/bnema/zerowrap"
 	"bnema.dev/ermite-kv/internal/fsys"
 	"bnema.dev/ermite-kv/internal/fsys/faultfs"
 )
 	}
 }
-func recoverState(t *testing.T, fx fsys.FS, logger *slog.Logger) (*state, recovered, error) {
+// noLog is a disabled logger.
+var noLog = zerowrap.FromCtx(context.Background())
+// bufLogger returns a JSON logger at debug level writing to buf.
+func bufLogger(buf *bytes.Buffer) zerowrap.Logger {
+	return zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: buf})
+}
+func recoverState(t *testing.T, fx fsys.FS, logger zerowrap.Logger) (*state, recovered, error) {
 	t.Helper()
 	s := &state{m: map[string]string{}, versions: map[string]uint64{}}
 	rec, err := recoverDir(fx, testDir, logger, s.load, s.apply)
 // releases the lock and the log file.
 func mustRecover(t *testing.T, fx fsys.FS) (*state, recovered) {
 	t.Helper()
-	s, rec, err := recoverState(t, fx, nil)
+	s, rec, err := recoverState(t, fx, noLog)
 	if err != nil {
 		t.Fatalf("recoverDir: %v", err)
 	}
 func TestRecoverLockedAndRelease(t *testing.T) {
 	fx := faultfs.New()
 	_, rec := mustRecover(t, fx)
-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrLocked) {
+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrLocked) {
 		t.Fatalf("second recover: err = %v, want ErrLocked", err)
 	}
 	_ = rec.log.Close()
 	_ = rec.lock.Close()
-	_, rec2, err := recoverState(t, fx, nil)
+	_, rec2, err := recoverState(t, fx, noLog)
 	if err != nil {
 		t.Fatalf("recover after release: %v", err)
 	}
 func TestRecoverReleasesLockOnError(t *testing.T) {
 	fx := faultfs.New()
 	put(fx, logName(0), []byte("garbage"))
-	if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
 		t.Fatalf("err = %v, want ErrCorrupt", err)
 	}
 	l, err := fx.Lock(filepath.Join(testDir, lockName))
 			fx := faultfs.New()
 			put(fx, logName(0), append(append([]byte(nil), good...), tail...))
 			var logs bytes.Buffer
-			s, rec, err := recoverState(t, fx, slog.New(slog.NewTextHandler(&logs, nil)))
+			s, rec, err := recoverState(t, fx, bufLogger(&logs))
 			if err != nil {
 				t.Fatal(err)
 			}
 		return c
 	}
 	hdr := appendLogHeader(nil, 0)
-	cat := func(parts ...[]byte) []byte { return bytes.Join(parts, nil) }
 	cases := map[string][]byte{
 		"bad crc in middle record":     cat(hdr, r1, flip(r2, len(r2)-1), r3),
 		"bad payload in first record":  cat(hdr, flip(r1, 9), r2),
 		"bad checksum field":           cat(hdr, r1, flip(r2, 4), r3),
 		"damaged record before last":   cat(hdr, flip(r1, len(r1)-1), r2, r3),
-		"record with wrong count":      cat(hdr, rawRecord(rawPayload(1, 5, opDelete, 1, 'k')), r2),
+		"record with wrong count":      cat(hdr, rawRecord(rawPayload(1, 5, rawBatch(1, opDelete, 1, 'k')...)), r2),
 		"corrupt but len looks intact": cat(hdr, r1, flip(r2, 12), r3),
 	}
 	for name, data := range cases {
 		t.Run(name, func(t *testing.T) {
 			fx := faultfs.New()
 			put(fx, logName(0), data)
-			_, _, err := recoverState(t, fx, nil)
+			_, _, err := recoverState(t, fx, noLog)
 			if !errors.Is(err, ErrCorrupt) {
 				t.Fatalf("err = %v, want ErrCorrupt", err)
 			}
 			fx := faultfs.New()
 			put(fx, logName(0), data)
 			put(fx, logName(2), logBytes(2, []op{putOp("c", "3")}))
-			if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
+			if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
 				t.Fatalf("err = %v, want ErrCorrupt", err)
 			}
 		})
 		t.Run(name, func(t *testing.T) {
 			fx := faultfs.New()
 			put(fx, c.name, c.data)
-			if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
+			if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
 				t.Fatalf("err = %v, want ErrCorrupt", err)
 			}
 		})
 		fx := faultfs.New()
 		put(fx, logName(0), good[:10])
 		put(fx, logName(1), logBytes(1, []op{putOp("b", "2")}))
-		if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
+		if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
 			t.Fatalf("err = %v, want ErrCorrupt", err)
 		}
 	})
 		t.Run(name, func(t *testing.T) {
 			fx := faultfs.New()
 			setup(fx)
-			if _, _, err := recoverState(t, fx, nil); !errors.Is(err, ErrCorrupt) {
+			if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
 				t.Fatalf("err = %v, want ErrCorrupt", err)
 			}
 		})
 			put(fx, snapshotName(4), bad)
 			put(fx, logName(2), logBytes(2, []op{putOp("c", "3")}, []op{putOp("d", "4")}, []op{delOp("a")}))
 			var logs bytes.Buffer
-			s, rec, err := recoverState(t, fx, slog.New(slog.NewTextHandler(&logs, nil)))
+			s, rec, err := recoverState(t, fx, bufLogger(&logs))
 			if err != nil {
 				t.Fatal(err)
 			}
 	put(fx, snapshotName(1), snapshotBytes(t, 1, snapEnt("a", "1", 1), snapEnt("b", "2", 1), snapEnt("c", "3", 1)))
 	var keys []string
 	var held [][]byte
-	_, err := recoverDir(fx, testDir, nil, func(k, v []byte, ver uint64) {
+	_, err := recoverDir(fx, testDir, noLog, func(k, v []byte, ver uint64) {
 		keys = append(keys, string(k))
 		held = append(held, k, v)
 	}, nil)
 	data := logBytes(0, []op{putOp("a", "1")}, []op{putOp("b", "2")})
 	torn := append(append([]byte(nil), data...), 9, 9, 9)
-	rec, err := recoverDir(fsys.OS(), dir, nil, nil, nil)
+	rec, err := recoverDir(fsys.OS(), dir, noLog, nil, nil)
 	if err != nil {
 		t.Fatal(err)
 	}
-	if _, err := recoverDir(fsys.OS(), dir, nil, nil, nil); !errors.Is(err, ErrLocked) {
+	if _, err := recoverDir(fsys.OS(), dir, noLog, nil, nil); !errors.Is(err, ErrLocked) {
 		t.Fatalf("second recover: err = %v, want ErrLocked", err)
 	}
 	if _, err := rec.log.Write(data[logHeaderSize:]); err != nil {
 	_ = rec.lock.Close()
 	s := &state{m: map[string]string{}, versions: map[string]uint64{}}
-	rec, err = recoverDir(fsys.OS(), dir, nil, s.load, s.apply)
+	rec, err = recoverDir(fsys.OS(), dir, noLog, s.load, s.apply)
 	if err != nil {
 		t.Fatal(err)
 	}
 		t.Fatalf("ReadAt = %d, %v: tail not truncated", n, err)
 	}
 }
+func TestRecoverGroupRecords(t *testing.T) {
+	fx := faultfs.New()
+	b := appendLogHeader(nil, 0)
+	b = appendRecord(b, 1, []op{putOp("a", "1")}, []op{putOp("b", "2"), delOp("a")}, []op{putOp("c", "3")})
+	b = appendRecord(b, 4, []op{putOp("a", "4")})
+	put(fx, logName(0), b)
+	s, rec := mustRecover(t, fx)
+	wantState(t, s, map[string]string{"a": "4", "b": "2", "c": "3"})
+	if got := fmt.Sprint(s.seqs); got != "[1 2 3 4]" {
+		t.Fatalf("applied seqs %s", got)
+	}
+	if s.versions["b"] != 2 || s.versions["c"] != 3 || s.versions["a"] != 4 || rec.lastSeq != 4 {
+		t.Fatalf("versions = %v, rec = %+v", s.versions, rec)
+	}
+}
+// TestRecoverRecordStraddlesSnapshot checks that only the batches newer than
+// the snapshot of a record that spans the snapshot seq are replayed.
+func TestRecoverRecordStraddlesSnapshot(t *testing.T) {
+	fx := faultfs.New()
+	put(fx, snapshotName(2), snapshotBytes(t, 2, snapEnt("a", "1", 1), snapEnt("b", "2", 2)))
+	b := appendLogHeader(nil, 0)
+	b = appendRecord(b, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")}, []op{putOp("c", "3")}, []op{delOp("a")})
+	b = appendRecord(b, 5, []op{putOp("d", "5")})
+	put(fx, logName(0), b)
+	s, rec := mustRecover(t, fx)
+	wantState(t, s, map[string]string{"b": "2", "c": "3", "d": "5"})
+	if got := fmt.Sprint(s.seqs); got != "[3 4 5]" {
+		t.Fatalf("applied seqs %s, want [3 4 5]", got)
+	}
+	if rec.snapSeq != 2 || rec.lastSeq != 5 {
+		t.Fatalf("rec = %+v", rec)
+	}
+	// A record that ends exactly at the snapshot seq adds nothing.
+	fx = faultfs.New()
+	put(fx, snapshotName(2), snapshotBytes(t, 2, snapEnt("a", "1", 1), snapEnt("b", "2", 2)))
+	put(fx, logName(0), cat(appendLogHeader(nil, 0), appendRecord(nil, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")})))
+	s, rec = mustRecover(t, fx)
+	if len(s.seqs) != 0 || rec.lastSeq != 2 {
+		t.Fatalf("applied %v, rec = %+v", s.seqs, rec)
+	}
+}
+func TestRecoverTornGroupRecordFollowedByValidRecord(t *testing.T) {
+	r1 := appendRecord(nil, 1, []op{putOp("a", "1")}, []op{putOp("b", "2")})
+	r2 := appendRecord(nil, 3, []op{putOp("c", "3")}, []op{putOp("d", "4")})
+	r3 := appendRecord(nil, 5, []op{putOp("e", "5")})
+	damaged := slices.Clone(r2)
+	damaged[len(damaged)/2] ^= 0xff
+	fx := faultfs.New()
+	data := cat(appendLogHeader(nil, 0), r1, damaged, r3)
+	put(fx, logName(0), data)
+	if _, _, err := recoverState(t, fx, noLog); !errors.Is(err, ErrCorrupt) {
+		t.Fatalf("err = %v, want ErrCorrupt", err)
+	}
+	if got, _ := fx.ReadFile(filepath.Join(testDir, logName(0))); !bytes.Equal(got, data) {
+		t.Fatal("corrupt log was modified")
+	}
+	// Without a readable record after it, the same damage is a torn tail
+	// that drops the whole group record, and nothing of it is applied.
+	fx = faultfs.New()
+	put(fx, logName(0), cat(appendLogHeader(nil, 0), r1, damaged))
+	s, rec := mustRecover(t, fx)
+	wantState(t, s, map[string]string{"a": "1", "b": "2"})
+	if rec.lastSeq != 2 {
+		t.Fatalf("rec = %+v", rec)
+	}
+}
+// TestRecoverDamagedLenIsTornTail checks that a damaged len field of the last
+// record is handled as a torn tail: the record is dropped.
+func TestRecoverDamagedLenIsTornTail(t *testing.T) {
+	good := logBytes(0, []op{putOp("a", "1")})
+	r2 := appendRecord(nil, 2, []op{putOp("b", "2")})
+	for name, patch := range map[string]func(b []byte){
+		"len beyond EOF":  func(b []byte) { b[1] = 0x7f },
+		"len above max":   func(b []byte) { b[3] = 0x7f },
+		"len below min":   func(b []byte) { clear(b[:4]) },
+		"len off by some": func(b []byte) { b[0] += 3 },
+	} {
+		t.Run(name, func(t *testing.T) {
+			bad := slices.Clone(r2)
+			patch(bad)
+			fx := faultfs.New()
+			put(fx, logName(0), cat(good, bad))
+			s, rec := mustRecover(t, fx)
+			wantState(t, s, map[string]string{"a": "1"})
+			if rec.lastSeq != 1 || rec.logSize != int64(len(good)) {
+				t.Fatalf("rec = %+v", rec)
+			}
+		})
+	}
+}

M snapshot.go +9 -5


@@ -2,7 +2,10 @@
2	2
3	3		package kv
4	4
5		-	import "iter"
	5	+	import (
	6	+	"context"
	7	+	"iter"
	8	+	)
6	9
7	10		// Item is the value stored under a key.
8	11		type Item struct {

@@ -29,18 +32,19 @@ func (s *Snapshot) Seq() uint64 { return s.seq }
29	32		// Len returns the number of keys.
30	33		func (s *Snapshot) Len() int { return s.t.len() }
31	34
32		-	// Get returns the item stored under key.
33		-	func (s *Snapshot) Get(key []byte) (Item, bool) { return s.t.get(key) }
	35	+	// Get returns the item stored under key. Reads never block or log: ctx is
	36	+	// not checked.
	37	+	func (s *Snapshot) Get(_ context.Context, key []byte) (Item, bool) { return s.t.get(key) }
34	38
35	39		// Range iterates over the keys in [start, end) in ascending order. A nil end
36	40		// (or an empty start) is unbounded. Breaking out of the loop stops the walk.
37		-	func (s *Snapshot) Range(start, end []byte) iter.Seq2[[]byte, Item] {
	41	+	func (s *Snapshot) Range(_ context.Context, start, end []byte) iter.Seq2[[]byte, Item] {
38	42		return s.t.ascend(start, end)
39	43		}
40	44
41	45		// Prefix iterates over the keys that begin with p in ascending order. An
42	46		// empty p matches every key.
43		-	func (s *Snapshot) Prefix(p []byte) iter.Seq2[[]byte, Item] {
	47	+	func (s *Snapshot) Prefix(_ context.Context, p []byte) iter.Seq2[[]byte, Item] {
44	48		return s.t.ascend(p, prefixEnd(p))
45	49		}
46	50

 package kv
-import "iter"
+import (
+	"context"
+	"iter"
+)
 // Item is the value stored under a key.
 type Item struct {
 // Len returns the number of keys.
 func (s *Snapshot) Len() int { return s.t.len() }
-// Get returns the item stored under key.
+// Get returns the item stored under key. Reads never block or log: ctx is
-func (s *Snapshot) Get(key []byte) (Item, bool) { return s.t.get(key) }
+// not checked.
+func (s *Snapshot) Get(_ context.Context, key []byte) (Item, bool) { return s.t.get(key) }
 // Range iterates over the keys in [start, end) in ascending order. A nil end
 // (or an empty start) is unbounded. Breaking out of the loop stops the walk.
-func (s *Snapshot) Range(start, end []byte) iter.Seq2[[]byte, Item] {
+func (s *Snapshot) Range(_ context.Context, start, end []byte) iter.Seq2[[]byte, Item] {
 	return s.t.ascend(start, end)
 }
 // Prefix iterates over the keys that begin with p in ascending order. An
 // empty p matches every key.
-func (s *Snapshot) Prefix(p []byte) iter.Seq2[[]byte, Item] {
+func (s *Snapshot) Prefix(_ context.Context, p []byte) iter.Seq2[[]byte, Item] {
 	return s.t.ascend(p, prefixEnd(p))
 }

M tree_test.go +13 -13


@@ -135,18 +135,18 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
135	135		}
136	136		}
137	137		}
138		-	verify("full scan", collect(s.Range(nil, nil)), nil, nil)
	138	+	verify("full scan", collect(s.Range(bg, nil, nil)), nil, nil)
139	139
140	140		for range 20 {
141	141		k := genKey()
142		-	got, ok := s.Get(k)
	142	+	got, ok := s.Get(bg, k)
143	143		want, wok := m[string(k)]
144	144		if ok != wok \|\| (ok && !equalItem(got, want)) {
145	145		t.Fatalf("Get(%x) = %v,%v want %v,%v", k, got, ok, want, wok)
146	146		}
147	147		}
148	148		for k, want := range m {
149		-	if got, ok := s.Get([]byte(k)); !ok \|\| !equalItem(got, want) {
	149	+	if got, ok := s.Get(bg, []byte(k)); !ok \|\| !equalItem(got, want) {
150	150		t.Fatalf("Get(%x) = %v,%v want %v", k, got, ok, want)
151	151		}
152	152		break // one arbitrary present key is enough per check

@@ -156,9 +156,9 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
156	156		if bytes.Compare(a, b) > 0 {
157	157		a, b = b, a
158	158		}
159		-	verify("range", collect(s.Range(a, b)), a, b)
160		-	verify("range open end", collect(s.Range(a, nil)), a, nil)
161		-	verify("range open start", collect(s.Range(nil, b)), nil, b)
	159	+	verify("range", collect(s.Range(bg, a, b)), a, b)
	160	+	verify("range open end", collect(s.Range(bg, a, nil)), a, nil)
	161	+	verify("range open start", collect(s.Range(bg, nil, b)), nil, b)
162	162		}
163	163		for range 10 {
164	164		p := genKey()

@@ -169,7 +169,7 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
169	169		want = append(want, k)
170	170		}
171	171		}
172		-	got := collect(s.Prefix(p))
	172	+	got := collect(s.Prefix(bg, p))
173	173		if len(got) != len(want) {
174	174		t.Fatalf("prefix %x: got %d items, want %d", p, len(got), len(want))
175	175		}

@@ -181,7 +181,7 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
181	181		}
182	182		// Early break stops the walk.
183	183		seen := 0
184		-	for range s.Range(nil, nil) {
	184	+	for range s.Range(bg, nil, nil) {
185	185		seen++
186	186		if seen == 3 {
187	187		break

@@ -355,10 +355,10 @@ func TestPrefixAllFF(t *testing.T) {
355	355		tr = tr.put(k, nil, uint64(i+1))
356	356		}
357	357		s := newSnapshot(tr, 4)
358		-	if got := collect(s.Prefix([]byte{0xFF})); len(got) != 3 {
	358	+	if got := collect(s.Prefix(bg, []byte{0xFF})); len(got) != 3 {
359	359		t.Fatalf("prefix FF: %d items, want 3", len(got))
360	360		}
361		-	if got := collect(s.Prefix(nil)); len(got) != 4 {
	361	+	if got := collect(s.Prefix(bg, nil)); len(got) != 4 {
362	362		t.Fatalf("empty prefix: %d items, want 4", len(got))
363	363		}
364	364		}

@@ -378,7 +378,7 @@ func BenchmarkSnapshotGet(b *testing.B) {
378	378		b.ReportAllocs()
379	379		b.ResetTimer()
380	380		for i := 0; b.Loop(); i++ {
381		-	if _, ok := s.Get(keys[(i*7919)%len(keys)]); !ok {
	381	+	if _, ok := s.Get(bg, keys[(i*7919)%len(keys)]); !ok {
382	382		b.Fatal("missing key")
383	383		}
384	384		}

@@ -389,7 +389,7 @@ func BenchmarkRange(b *testing.B) {
389	389		b.ReportAllocs()
390	390		for b.Loop() {
391	391		n := 0
392		-	for range s.Range(nil, nil) {
	392	+	for range s.Range(bg, nil, nil) {
393	393		n++
394	394		}
395	395		if n != 100_000 {

@@ -470,7 +470,7 @@ func TestConcurrentReaders(t *testing.T) {
470	470		s := cur.Load()
471	471		n := 0
472	472		var prev []byte
473		-	for k, it := range s.Range(nil, nil) {
	473	+	for k, it := range s.Range(bg, nil, nil) {
474	474		if prev != nil && bytes.Compare(prev, k) >= 0 {
475	475		t.Errorf("seq %d: keys out of order", s.Seq())
476	476		return


@@ -135,18 +135,18 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
135		}	135		}
136		}	136		}
137		}	137		}
138	-	verify("full scan", collect(s.Range(nil, nil)), nil, nil)	138	+	verify("full scan", collect(s.Range(bg, nil, nil)), nil, nil)
139			139
140		for range 20 {	140		for range 20 {
141		k := genKey()	141		k := genKey()
142	-	got, ok := s.Get(k)	142	+	got, ok := s.Get(bg, k)
143		want, wok := m[string(k)]	143		want, wok := m[string(k)]
144		if ok != wok \|\| (ok && !equalItem(got, want)) {	144		if ok != wok \|\| (ok && !equalItem(got, want)) {
145		t.Fatalf("Get(%x) = %v,%v want %v,%v", k, got, ok, want, wok)	145		t.Fatalf("Get(%x) = %v,%v want %v,%v", k, got, ok, want, wok)
146		}	146		}
147		}	147		}
148		for k, want := range m {	148		for k, want := range m {
149	-	if got, ok := s.Get([]byte(k)); !ok \|\| !equalItem(got, want) {	149	+	if got, ok := s.Get(bg, []byte(k)); !ok \|\| !equalItem(got, want) {
150		t.Fatalf("Get(%x) = %v,%v want %v", k, got, ok, want)	150		t.Fatalf("Get(%x) = %v,%v want %v", k, got, ok, want)
151		}	151		}
152		break // one arbitrary present key is enough per check	152		break // one arbitrary present key is enough per check

@@ -156,9 +156,9 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
156		if bytes.Compare(a, b) > 0 {	156		if bytes.Compare(a, b) > 0 {
157		a, b = b, a	157		a, b = b, a
158		}	158		}
159	-	verify("range", collect(s.Range(a, b)), a, b)	159	+	verify("range", collect(s.Range(bg, a, b)), a, b)
160	-	verify("range open end", collect(s.Range(a, nil)), a, nil)	160	+	verify("range open end", collect(s.Range(bg, a, nil)), a, nil)
161	-	verify("range open start", collect(s.Range(nil, b)), nil, b)	161	+	verify("range open start", collect(s.Range(bg, nil, b)), nil, b)
162		}	162		}
163		for range 10 {	163		for range 10 {
164		p := genKey()	164		p := genKey()

@@ -169,7 +169,7 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
169		want = append(want, k)	169		want = append(want, k)
170		}	170		}
171		}	171		}
172	-	got := collect(s.Prefix(p))	172	+	got := collect(s.Prefix(bg, p))
173		if len(got) != len(want) {	173		if len(got) != len(want) {
174		t.Fatalf("prefix %x: got %d items, want %d", p, len(got), len(want))	174		t.Fatalf("prefix %x: got %d items, want %d", p, len(got), len(want))
175		}	175		}

@@ -181,7 +181,7 @@ func checkAgainst(t testing.T, rng rand.Rand, tr tree, m model, genKey func()
181		}	181		}
182		// Early break stops the walk.	182		// Early break stops the walk.
183		seen := 0	183		seen := 0
184	-	for range s.Range(nil, nil) {	184	+	for range s.Range(bg, nil, nil) {
185		seen++	185		seen++
186		if seen == 3 {	186		if seen == 3 {
187		break	187		break

@@ -355,10 +355,10 @@ func TestPrefixAllFF(t *testing.T) {
355		tr = tr.put(k, nil, uint64(i+1))	355		tr = tr.put(k, nil, uint64(i+1))
356		}	356		}
357		s := newSnapshot(tr, 4)	357		s := newSnapshot(tr, 4)
358	-	if got := collect(s.Prefix([]byte{0xFF})); len(got) != 3 {	358	+	if got := collect(s.Prefix(bg, []byte{0xFF})); len(got) != 3 {
359		t.Fatalf("prefix FF: %d items, want 3", len(got))	359		t.Fatalf("prefix FF: %d items, want 3", len(got))
360		}	360		}
361	-	if got := collect(s.Prefix(nil)); len(got) != 4 {	361	+	if got := collect(s.Prefix(bg, nil)); len(got) != 4 {
362		t.Fatalf("empty prefix: %d items, want 4", len(got))	362		t.Fatalf("empty prefix: %d items, want 4", len(got))
363		}	363		}
364		}	364		}

@@ -378,7 +378,7 @@ func BenchmarkSnapshotGet(b *testing.B) {
378		b.ReportAllocs()	378		b.ReportAllocs()
379		b.ResetTimer()	379		b.ResetTimer()
380		for i := 0; b.Loop(); i++ {	380		for i := 0; b.Loop(); i++ {
381	-	if _, ok := s.Get(keys[(i*7919)%len(keys)]); !ok {	381	+	if _, ok := s.Get(bg, keys[(i*7919)%len(keys)]); !ok {
382		b.Fatal("missing key")	382		b.Fatal("missing key")
383		}	383		}
384		}	384		}

@@ -389,7 +389,7 @@ func BenchmarkRange(b *testing.B) {
389		b.ReportAllocs()	389		b.ReportAllocs()
390		for b.Loop() {	390		for b.Loop() {
391		n := 0	391		n := 0
392	-	for range s.Range(nil, nil) {	392	+	for range s.Range(bg, nil, nil) {
393		n++	393		n++
394		}	394		}
395		if n != 100_000 {	395		if n != 100_000 {

@@ -470,7 +470,7 @@ func TestConcurrentReaders(t *testing.T) {
470		s := cur.Load()	470		s := cur.Load()
471		n := 0	471		n := 0
472		var prev []byte	472		var prev []byte
473	-	for k, it := range s.Range(nil, nil) {	473	+	for k, it := range s.Range(bg, nil, nil) {
474		if prev != nil && bytes.Compare(prev, k) >= 0 {	474		if prev != nil && bytes.Compare(prev, k) >= 0 {
475		t.Errorf("seq %d: keys out of order", s.Seq())	475		t.Errorf("seq %d: keys out of order", s.Seq())
476		return	476		return

M writer.go +29 -15


@@ -85,7 +85,7 @@ func (db *DB) writer() {
85	85		// under maxGroupBytes.
86	86		func (db DB) collect(first request) (overflow *request) {
87	87		db.group = append(db.group[:0], first)
88		-	size := first.b.payload()
	88	+	size := recordHead + first.b.encodedSize()
89	89		var expired <-chan time.Time
90	90		if w := db.opts.GroupWindow; w > 0 {
91	91		t := time.NewTimer(w)

@@ -109,7 +109,7 @@ func (db DB) collect(first request) (overflow *request) {
109	109		return nil
110	110		}
111	111		}
112		-	if p := r.b.payload(); size+p <= maxGroupBytes {
	112	+	if p := r.b.encodedSize(); size+p <= maxGroupBytes {
113	113		db.group = append(db.group, r)
114	114		size += p
115	115		} else {

@@ -128,6 +128,8 @@ func (db *DB) commit() bool {
128	128		seq := cur.seq
129	129		buf := db.buf[:0]
130	130		results := make([]result, len(db.group))
	131	+	var batches int
	132	+	var firstSeq uint64
131	133
132	134		for i, r := range db.group {
133	135		b := r.b

@@ -147,7 +149,12 @@ func (db *DB) commit() bool {
147	149		bld.delete(o.key)
148	150		}
149	151		}
150		-	buf = appendRecord(buf, seq, b.ops)
	152	+	if batches == 0 {
	153	+	firstSeq = seq
	154	+	buf = beginRecord(buf, seq)
	155	+	}
	156	+	buf = appendBatch(buf, b.ops)
	157	+	batches++
151	158		results[i] = result{seq: seq}
152	159		}
153	160		db.buf = buf[:0]

@@ -155,8 +162,10 @@ func (db *DB) commit() bool {
155	162		db.buf = nil // do not pin the memory of one huge batch
156	163		}
157	164
158		-	if len(buf) > 0 {
159		-	if err := db.persist(buf); err != nil {
	165	+	if batches > 0 {
	166	+	finishRecord(buf, batches)
	167	+	syncTime, err := db.persist(buf)
	168	+	if err != nil {
160	169		err = db.fail(err)
161	170		for _, r := range db.group {
162	171		r.reply <- result{err: err}

@@ -165,6 +174,8 @@ func (db *DB) commit() bool {
165	174		}
166	175		db.logSize += int64(len(buf))
167	176		db.snap.Store(newSnapshot(bld.freeze(), seq))
	177	+	db.log.Debug().Uint64("seq", firstSeq).Int("batches", batches).Int("bytes", len(buf)).
	178	+	Dur("sync", syncTime).Msg("group committed")
168	179		}
169	180		for i, r := range db.group {
170	181		r.reply <- results[i]

@@ -172,21 +183,24 @@ func (db *DB) commit() bool {
172	183		return true
173	184		}
174	185
175		-	// persist appends buf to the log and syncs it (unless NoSync).
176		-	func (db *DB) persist(buf []byte) error {
177		-	n, err := db.log.Write(buf)
	186	+	// persist appends buf to the log and syncs it (unless NoSync). It returns
	187	+	// the time spent in the sync.
	188	+	func (db *DB) persist(buf []byte) (time.Duration, error) {
	189	+	n, err := db.file.Write(buf)
178	190		if err == nil && n < len(buf) {
179	191		err = io.ErrShortWrite
180	192		}
181	193		if err != nil {
182		-	return fmt.Errorf("write log: %w", err)
	194	+	return 0, fmt.Errorf("write log: %w", err)
183	195		}
184		-	if !db.opts.NoSync {
185		-	if err := db.log.Sync(); err != nil {
186		-	return fmt.Errorf("sync log: %w", err)
187		-	}
	196	+	if db.opts.NoSync {
	197	+	return 0, nil
	198	+	}
	199	+	start := time.Now()
	200	+	if err := db.file.Sync(); err != nil {
	201	+	return 0, fmt.Errorf("sync log: %w", err)
188	202		}
189		-	return nil
	203	+	return time.Since(start), nil
190	204		}
191	205
192	206		// fail puts the database in the failed state, keeping the first cause, and

@@ -194,7 +208,7 @@ func (db *DB) persist(buf []byte) error {
194	208		func (db *DB) fail(cause error) error {
195	209		db.failOnce.Do(func() {
196	210		db.failErr = fmt.Errorf("%w: %w", ErrFailed, cause)
197		-	db.opts.Logger.Error("kv: database failed", "err", cause)
	211	+	db.log.Error().Err(cause).Msg("database failed")
198	212		close(db.failed)
199	213		})
200	214		return db.failErr

 // under maxGroupBytes.
 func (db *DB) collect(first *request) (overflow *request) {
 	db.group = append(db.group[:0], first)
-	size := first.b.payload()
+	size := recordHead + first.b.encodedSize()
 	var expired <-chan time.Time
 	if w := db.opts.GroupWindow; w > 0 {
 		t := time.NewTimer(w)
 				return nil
 			}
 		}
-		if p := r.b.payload(); size+p <= maxGroupBytes {
+		if p := r.b.encodedSize(); size+p <= maxGroupBytes {
 			db.group = append(db.group, r)
 			size += p
 		} else {
 	seq := cur.seq
 	buf := db.buf[:0]
 	results := make([]result, len(db.group))
+	var batches int
+	var firstSeq uint64
 	for i, r := range db.group {
 		b := r.b
 				bld.delete(o.key)
 			}
 		}
-		buf = appendRecord(buf, seq, b.ops)
+		if batches == 0 {
+			firstSeq = seq
+			buf = beginRecord(buf, seq)
+		}
+		buf = appendBatch(buf, b.ops)
+		batches++
 		results[i] = result{seq: seq}
 	}
 	db.buf = buf[:0]
 		db.buf = nil // do not pin the memory of one huge batch
 	}
-	if len(buf) > 0 {
+	if batches > 0 {
-		if err := db.persist(buf); err != nil {
+		finishRecord(buf, batches)
+		syncTime, err := db.persist(buf)
+		if err != nil {
 			err = db.fail(err)
 			for _, r := range db.group {
 				r.reply <- result{err: err}
 		}
 		db.logSize += int64(len(buf))
 		db.snap.Store(newSnapshot(bld.freeze(), seq))
+		db.log.Debug().Uint64("seq", firstSeq).Int("batches", batches).Int("bytes", len(buf)).
+			Dur("sync", syncTime).Msg("group committed")
 	}
 	for i, r := range db.group {
 		r.reply <- results[i]
 	return true
 }
-// persist appends buf to the log and syncs it (unless NoSync).
+// persist appends buf to the log and syncs it (unless NoSync). It returns
-func (db *DB) persist(buf []byte) error {
+// the time spent in the sync.
-	n, err := db.log.Write(buf)
+func (db *DB) persist(buf []byte) (time.Duration, error) {
+	n, err := db.file.Write(buf)
 	if err == nil && n < len(buf) {
 		err = io.ErrShortWrite
 	}
 	if err != nil {
-		return fmt.Errorf("write log: %w", err)
+		return 0, fmt.Errorf("write log: %w", err)
 	}
-	if !db.opts.NoSync {
+	if db.opts.NoSync {
-		if err := db.log.Sync(); err != nil {
+		return 0, nil
-			return fmt.Errorf("sync log: %w", err)
+	}
-		}
+	start := time.Now()
+	if err := db.file.Sync(); err != nil {
+		return 0, fmt.Errorf("sync log: %w", err)
 	}
-	return nil
+	return time.Since(start), nil
 }
 // fail puts the database in the failed state, keeping the first cause, and
 func (db *DB) fail(cause error) error {
 	db.failOnce.Do(func() {
 		db.failErr = fmt.Errorf("%w: %w", ErrFailed, cause)
-		db.opts.Logger.Error("kv: database failed", "err", cause)
+		db.log.Error().Err(cause).Msg("database failed")
 		close(db.failed)
 	})
 	return db.failErr