fix(logging): write log entries from a dedicated goroutine

Every goroutine wrote its log entries to the run file synchronously,
the libinput thread and the output owners included. With --debug=all a
slow disk (btrfs on dm-crypt under I/O pressure) stalled them: the run
log of one session shows entries written up to 25 s late, and libinput
reported its timers 14.6 s in the past.

Entries now go through a bounded zerolog diode writer drained by its own
goroutine. A full queue drops entries and reports the count on stderr
instead of blocking input, the display or the outputs. Close drains the
queue before closing the file.

commit: 657bbc2f644ac1729725ade0ea4464b9f54ad090
author: brice · 12d ago · 2026-10-10 14:12 UTC
committer: brice · 12d ago · 2026-10-10 15:39 UTC
parent: 18cc6d4
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

2 files · +58 -4

M internal/adapters/logging/logging.go +32 -4


@@ -4,6 +4,7 @@ package logging
4	4		import (
5	5		"context"
6	6		"fmt"
	7	+	"io"
7	8		"os"
8	9		"path/filepath"
9	10		"sort"

@@ -12,6 +13,7 @@ import (
12	13
13	14		"github.com/bnema/zerowrap"
14	15		"github.com/rs/zerolog"
	16	+	"github.com/rs/zerolog/diode"
15	17		"golang.org/x/term"
16	18		)
17	19

@@ -86,14 +88,40 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f
86	88		return nil, nil, err
87	89		}
88	90		pruneRuns(dir)
89		-	var output = zerowrap.Config{Level: level, Format: "json", Output: file}
	91	+	// Hide Close from the diode: asyncWriter closes the file once.
	92	+	var sink io.Writer = struct{ io.Writer }{file}
90	93		if term.IsTerminal(int(os.Stderr.Fd())) {
91		-	output.Output = &consoleAndFile{file: file}
	94	+	sink = &consoleAndFile{file: file}
92	95		}
93		-	ctx = zerowrap.WithCtx(ctx, zerowrap.New(output))
	96	+	w := newAsyncWriter(sink, file)
	97	+	ctx = zerowrap.WithCtx(ctx, zerowrap.New(zerowrap.Config{Level: level, Format: "json", Output: w}))
94	98		ctx = context.WithValue(ctx, debugKey{}, debugSet(selected))
95	99		ctx = context.WithValue(ctx, levelKey{}, level)
96		-	return ctx, file.Close, nil
	100	+	return ctx, w.Close, nil
	101	+	}
	102	+
	103	+	// logQueue is how many entries may wait for the disk. Past it, entries are
	104	+	// dropped (and counted on stderr) rather than blocking the logging
	105	+	// goroutine: input, outputs and the display must never wait on a slow disk.
	106	+	const logQueue = 8192
	107	+
	108	+	// newAsyncWriter writes entries to w from its own goroutine. Close drains
	109	+	// what is queued, then closes c.
	110	+	func newAsyncWriter(w io.Writer, c io.Closer) io.WriteCloser {
	111	+	d := diode.NewWriter(w, logQueue, 0, func(missed int) {
	112	+	fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed)
	113	+	})
	114	+	return asyncWriter{Writer: d, closer: c}
	115	+	}
	116	+
	117	+	type asyncWriter struct {
	118	+	diode.Writer
	119	+	closer io.Closer
	120	+	}
	121	+
	122	+	func (a asyncWriter) Close() error {
	123	+	_ = a.Writer.Close() // drains the queue
	124	+	return a.closer.Close()
97	125		}
98	126
99	127		func pruneRuns(dir string) {


@@ -4,6 +4,7 @@ package logging
4		import (	4		import (
5		"context"	5		"context"
6		"fmt"	6		"fmt"
			7	+	"io"
7		"os"	8		"os"
8		"path/filepath"	9		"path/filepath"
9		"sort"	10		"sort"

@@ -12,6 +13,7 @@ import (
12			13
13		"github.com/bnema/zerowrap"	14		"github.com/bnema/zerowrap"
14		"github.com/rs/zerolog"	15		"github.com/rs/zerolog"
			16	+	"github.com/rs/zerolog/diode"
15		"golang.org/x/term"	17		"golang.org/x/term"
16		)	18		)
17			19

@@ -86,14 +88,40 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f
86		return nil, nil, err	88		return nil, nil, err
87		}	89		}
88		pruneRuns(dir)	90		pruneRuns(dir)
89	-	var output = zerowrap.Config{Level: level, Format: "json", Output: file}	91	+	// Hide Close from the diode: asyncWriter closes the file once.
			92	+	var sink io.Writer = struct{ io.Writer }{file}
90		if term.IsTerminal(int(os.Stderr.Fd())) {	93		if term.IsTerminal(int(os.Stderr.Fd())) {
91	-	output.Output = &consoleAndFile{file: file}	94	+	sink = &consoleAndFile{file: file}
92		}	95		}
93	-	ctx = zerowrap.WithCtx(ctx, zerowrap.New(output))	96	+	w := newAsyncWriter(sink, file)
			97	+	ctx = zerowrap.WithCtx(ctx, zerowrap.New(zerowrap.Config{Level: level, Format: "json", Output: w}))
94		ctx = context.WithValue(ctx, debugKey{}, debugSet(selected))	98		ctx = context.WithValue(ctx, debugKey{}, debugSet(selected))
95		ctx = context.WithValue(ctx, levelKey{}, level)	99		ctx = context.WithValue(ctx, levelKey{}, level)
96	-	return ctx, file.Close, nil	100	+	return ctx, w.Close, nil
			101	+	}
			102	+
			103	+	// logQueue is how many entries may wait for the disk. Past it, entries are
			104	+	// dropped (and counted on stderr) rather than blocking the logging
			105	+	// goroutine: input, outputs and the display must never wait on a slow disk.
			106	+	const logQueue = 8192
			107	+
			108	+	// newAsyncWriter writes entries to w from its own goroutine. Close drains
			109	+	// what is queued, then closes c.
			110	+	func newAsyncWriter(w io.Writer, c io.Closer) io.WriteCloser {
			111	+	d := diode.NewWriter(w, logQueue, 0, func(missed int) {
			112	+	fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed)
			113	+	})
			114	+	return asyncWriter{Writer: d, closer: c}
			115	+	}
			116	+
			117	+	type asyncWriter struct {
			118	+	diode.Writer
			119	+	closer io.Closer
			120	+	}
			121	+
			122	+	func (a asyncWriter) Close() error {
			123	+	_ = a.Writer.Close() // drains the queue
			124	+	return a.closer.Close()
97		}	125		}
98			126
99		func pruneRuns(dir string) {	127		func pruneRuns(dir string) {

M internal/adapters/logging/logging_test.go +26 -0


@@ -135,6 +135,32 @@ func TestCategoryEnablesComponentDebug(t *testing.T) {
135	135		}
136	136		}
137	137
	138	+	// A disk that stops answering must not block the goroutine that logs:
	139	+	// input and outputs log from their own loops.
	140	+	func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) {
	141	+	r, pw, err := os.Pipe() // nobody reads: writes block once the pipe is full
	142	+	if err != nil {
	143	+	t.Fatal(err)
	144	+	}
	145	+	defer r.Close()
	146	+	w := newAsyncWriter(pw, pw)
	147	+	line := bytes.Repeat([]byte{'x'}, 1024)
	148	+	done := make(chan struct{})
	149	+	go func() {
	150	+	defer close(done)
	151	+	for range 4 * logQueue { // far past the pipe buffer and the queue
	152	+	_, _ = w.Write(line)
	153	+	}
	154	+	}()
	155	+	select {
	156	+	case <-done:
	157	+	case <-time.After(5 * time.Second):
	158	+	t.Fatal("log write blocked on a stuck disk")
	159	+	}
	160	+	r.Close() // unblock the writer so Close can drain and return
	161	+	_ = w.Close()
	162	+	}
	163	+
138	164		// Narrow categories are on only when named, never through "all".
139	165		func TestEnabledCategories(t *testing.T) {
140	166		for _, category := range []string{"input-motion", "input-keys", "drm-flip"} {


@@ -135,6 +135,32 @@ func TestCategoryEnablesComponentDebug(t *testing.T) {
135	}	135		}
136	}	136		}
137		137
		138	+	// A disk that stops answering must not block the goroutine that logs:
		139	+	// input and outputs log from their own loops.
		140	+	func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) {
		141	+	r, pw, err := os.Pipe() // nobody reads: writes block once the pipe is full
		142	+	if err != nil {
		143	+	t.Fatal(err)
		144	+	}
		145	+	defer r.Close()
		146	+	w := newAsyncWriter(pw, pw)
		147	+	line := bytes.Repeat([]byte{'x'}, 1024)
		148	+	done := make(chan struct{})
		149	+	go func() {
		150	+	defer close(done)
		151	+	for range 4 * logQueue { // far past the pipe buffer and the queue
		152	+	_, _ = w.Write(line)
		153	+	}
		154	+	}()
		155	+	select {
		156	+	case <-done:
		157	+	case <-time.After(5 * time.Second):
		158	+	t.Fatal("log write blocked on a stuck disk")
		159	+	}
		160	+	r.Close() // unblock the writer so Close can drain and return
		161	+	_ = w.Close()
		162	+	}
		163	+
138	// Narrow categories are on only when named, never through "all".	164		// Narrow categories are on only when named, never through "all".
139	func TestEnabledCategories(t *testing.T) {	165		func TestEnabledCategories(t *testing.T) {
140	for _, category := range []string{"input-motion", "input-keys", "drm-flip"} {	166		for _, category := range []string{"input-motion", "input-keys", "drm-flip"} {