fix(system): give the process a temp directory that exists

Android has no /tmp and hands an app no TMPDIR. Go's os.TempDir() falls
back to "/tmp" when the variable is unset, so every library in this
process that wants scratch space was being handed a path that has never
existed.

SQLite is the one that noticed, and it said so precisely:

    W/yellowjacket: msg="champion index rebuild failed"
      explore.search-index.error="populate champion fts: disk I/O error (6410)"

6410 is not a generic I/O error. `6410 & 0xff` is 10, SQLITE_IOERR, and
`6410 >> 8` is 25 -- SQLITE_IOERR_GETTEMPPATH. SQLite could not work out
where to put a temporary file. Two measurements on the device say why:
`ls -d /tmp` does not exist, and the app process's environment carries
no TMPDIR. A shell's does (/data/local/tmp), which is why this is easy
to miss from `adb shell`.

The cost was a silent performance cliff on the slowest device this app
runs on: `championReady` stayed false, so every Explore search took the
generic path over the whole 1,079,667-row index instead of the champion
subset, and the rebuild was re-attempted on every launch.

**The class is fixed rather than the statement.** The trigger is the
*size* of the work, not that query -- anything that spills fails the
same way there, so large sorts, large joins and VACUUM were all waiting
their turn. The repair belongs at the process's one answer to "where do
temporary files go".

`PRAGMA temp_store = MEMORY` was the alternative: cheaper, more local,
and a promise that every future spill fits in RAM on a phone. The
catalog is the largest thing in this app and that is not a promise
worth making silently.

UseTempDir sits beside UseHomeOverride and carries its two rules for
the same reasons. **An empty base is a no-op**, because that is what
application.Mobile.StoragePath() returns on desktop -- so this needs no
build tag and changes nothing off mobile, where /tmp is real. And **an
explicit TMPDIR wins**, so anyone who set one deliberately gets it;
nothing sets it on the platform this exists for. It needs no new Wails
API and no Java change: StoragePath() is already what YJ_HOME is
pointed at, and the directory goes under it.

Two things beyond the rename of a variable.

**Writability is probed, not assumed.** MkdirAll on an existing
unwritable directory succeeds, so without the probe this could set
TMPDIR to a directory nothing can use -- which is the same bug one
directory over, and just as quiet.

**It returns its error, and main logs it.** A temp directory that could
not be created is the same silent failure one step earlier. A failure
is not fatal: it leaves the platform's answer in place, which is what
every release before this one ran with. That log line is readable on
the platform only because of #160.

Verified on the reference device, where the same launch that used to
print the failure now prints:

    I/yellowjacket: msg="champion index rebuilt"
      explore.search-index.elapsed=6.496s

Closes #190

.pi/skills/yellowjacket-dev/references/android-tier.md

@@ -8,13 +8,29 @@ This tier answers "does the phone build run", nothing else. It is not a
 spec tier, it does not run in CI, and the app is not a usable Android
 player yet (plan 015 says why, at length).
 
-## Three facts that make failure invisible
+## Two facts that make failure invisible
 
-**Go's stdout does not reach logcat.** An Android app's fd 1 and 2 go to
-`/dev/null`. Every `slog` line the app writes is discarded — including
-the one naming the error it is about to exit on. `setprop
-log.redirect-stdio true` does not help: it redirects the *Java*
-runtime's `System.out`, and the Go code is a c-shared native library.
+There were three. The first was that **Go's stdout does not reach
+logcat** — an Android app's fd 1 and 2 go to `/dev/null`, so every
+`slog` line the app wrote was discarded, including the one naming the
+error it was about to exit on. That is fixed (#160):
+`backend/androidlog` is a `slog.Handler` over `__android_log_write`,
+selected in `main()` by build tag, and the app's whole diagnostic
+stream now arrives under the `yellowjacket` tag, which `make
+android-logs` filters for.
+
+What remains true about it is the part that misleads: **`setprop
+log.redirect-stdio true` still does not help**, because it redirects
+the *Java* runtime's `System.out` and the Go code is a c-shared native
+library. Nothing that reaches logcat here does so through stdout, so
+anything printed with `fmt.Println` is still lost. Log with `slog`.
+
+The tag is a fixed string rather than the application id, and that is
+load-bearing rather than tidy: the debug build carries
+`applicationIdSuffix ".dev"` so it can be installed beside the release
+app, and it is the only build whose WebView can be inspected — so a tag
+derived from the id would be filtered out on the one build anybody
+debugging this app is running.
 
 **`os.Exit` is a silent death.** `main()` ends several failure paths in
 `os.Exit(1)`. From Android's side that is a process that vanished:
@@ -34,7 +50,10 @@ the wrong question. `make android-smoke` asks the right one — is it the
 The tell, once you know it: `I/WailsBridge: Wails bridge initialized`
 followed immediately by a new pid doing the same thing. That means the
 native library loaded, the JNI bridge came up, Go's `main()` ran, and
-`main()` left. Work backwards through its `os.Exit(1)` paths.
+`main()` left. Work backwards through its `os.Exit(1)` paths — and
+since #160, **read the `E/yellowjacket` line above it first**, because
+every one of those paths logs the error before it exits. That line is
+what #52 spent months without.
 
 ## What to run
 

backend/androidlog/android.go

@@ -0,0 +1,55 @@
+//go:build android
+
+// The write itself, and nothing else. Everything decidable off a phone
+// is in androidlog.go; see the package comment for why.
+
+package androidlog
+
+/*
+#cgo LDFLAGS: -llog
+#include <stdlib.h>
+#include <android/log.h>
+*/
+import "C"
+
+import (
+	"log/slog"
+	"unsafe"
+)
+
+// The priorities in androidlog.go are android/log.h's own values, and
+// these are what says so. A constant expression that would be negative
+// does not compile as a uint, so a renumbered header fails the build
+// here rather than logging everything at the wrong severity -- which is
+// the failure that would otherwise be invisible, since logcat would
+// happily print whatever number it was handed.
+const (
+	_ = uint(C.ANDROID_LOG_VERBOSE - PrioVerbose)
+	_ = uint(PrioVerbose - C.ANDROID_LOG_VERBOSE)
+	_ = uint(C.ANDROID_LOG_DEBUG - PrioDebug)
+	_ = uint(PrioDebug - C.ANDROID_LOG_DEBUG)
+	_ = uint(C.ANDROID_LOG_INFO - PrioInfo)
+	_ = uint(PrioInfo - C.ANDROID_LOG_INFO)
+	_ = uint(C.ANDROID_LOG_WARN - PrioWarn)
+	_ = uint(PrioWarn - C.ANDROID_LOG_WARN)
+	_ = uint(C.ANDROID_LOG_ERROR - PrioError)
+	_ = uint(PrioError - C.ANDROID_LOG_ERROR)
+	_ = uint(C.ANDROID_LOG_FATAL - PrioFatal)
+	_ = uint(PrioFatal - C.ANDROID_LOG_FATAL)
+)
+
+// New returns the handler main() installs on Android.
+func New(opts *slog.HandlerOptions) slog.Handler {
+	return NewHandler(opts, write)
+}
+
+// write hands one line to liblog.
+func write(prio int, tag, msg string) {
+	cTag := C.CString(tag)
+	defer C.free(unsafe.Pointer(cTag))
+
+	cMsg := C.CString(msg)
+	defer C.free(unsafe.Pointer(cMsg))
+
+	C.__android_log_write(C.int(prio), cTag, cMsg)
+}

backend/androidlog/androidlog.go

@@ -0,0 +1,250 @@
+// Package androidlog routes slog to logcat.
+//
+// **An Android app's fd 1 and 2 go to /dev/null**, so every line this
+// app writes with slog is discarded on that platform -- including the
+// one naming the error it is about to os.Exit on. #52 is what that
+// cost: a process that vanished with no tombstone, no AndroidRuntime
+// stack and nothing in `logcat -b crash`, at Priority/Critical for
+// months, whose entire diagnosis was one slog.Error main.go was
+// already writing.
+//
+// The platform's own sink is __android_log_write, which is a handful
+// of cgo -- and cgo compiled by nothing `make lint` or `make test`
+// runs, since the only toolchain that builds the android tag is a
+// cross-compiler and the only thing that runs it is a phone. So the
+// split here is the one backend/mediacontrols/androidpayload.go makes,
+// pushed as far as it will go: **everything except the write itself is
+// in this file, untagged**. The priority mapping, the formatting, the
+// chunking and the handler's own attr and group bookkeeping are
+// ordinary Go that `go test` exercises on any platform; android.go is
+// fifteen lines that hand a string to liblog.
+package androidlog
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"strconv"
+	"strings"
+	"sync"
+)
+
+// Tag is what logcat labels these lines with.
+//
+// It is a constant of ours rather than the application id, because the
+// debug build carries `applicationIdSuffix ".dev"` so that it can be
+// installed beside the release app -- so a tag derived from the package
+// name is a *different* tag on the one build that can be inspected, and
+// the filter that is supposed to show these lines would hide them on
+// exactly the build used to look for them.
+const Tag = "yellowjacket"
+
+// Android's priorities, from android/log.h. These are the values
+// __android_log_write takes; android.go asserts at compile time that
+// they still match the header, so a renumbered platform is a build
+// failure here rather than a warning silently logged as an error.
+const (
+	PrioVerbose = 2
+	PrioDebug   = 3
+	PrioInfo    = 4
+	PrioWarn    = 5
+	PrioError   = 6
+	PrioFatal   = 7
+)
+
+// maxPayload is how much of one line liblog will carry.
+//
+// The kernel logger's entry is 4068 bytes for the tag, the message and
+// their two NULs together, and what does not fit is **dropped without
+// comment** -- so a long line would be truncated in the middle of the
+// thing worth reading. 3500 leaves room for the tag and for the "(N/M)"
+// a continuation carries.
+const maxPayload = 3500
+
+// WriteFunc is the platform sink: one already-formatted line, at one
+// priority, under one tag.
+//
+// It is a parameter rather than a package-level function so that the
+// handler can be driven by a test on a machine with no liblog at all.
+type WriteFunc func(prio int, tag, msg string)
+
+// Priority maps a slog level onto an Android one.
+//
+// slog's levels are open -- a caller may define its own at any int --
+// so this is a banding rather than a lookup: anything below Info is
+// debug, anything at or above Error is error. A custom level between
+// two of the standard ones lands in the band beneath it, which is what
+// slog's own level naming does.
+func Priority(level slog.Level) int {
+	switch {
+	case level < slog.LevelDebug:
+		return PrioVerbose
+	case level < slog.LevelInfo:
+		return PrioDebug
+	case level < slog.LevelWarn:
+		return PrioInfo
+	case level < slog.LevelError:
+		return PrioWarn
+	default:
+		return PrioError
+	}
+}
+
+// Handler formats records with slog's own TextHandler and hands each
+// line to a WriteFunc.
+//
+// It delegates the formatting rather than doing it, because WithAttrs
+// and WithGroup are the half of slog.Handler that is easy to get subtly
+// wrong -- and a logger whose groups are wrong is a logger nobody reads.
+// What it does own is what logcat needs and TextHandler does not know
+// about: the priority, and the fact that a line has a maximum length.
+type Handler struct {
+	write WriteFunc
+
+	// mu guards buf, which the delegate writes into. slog.Handler is
+	// documented as safe for concurrent use.
+	mu       *sync.Mutex
+	buf      *bytes.Buffer
+	delegate slog.Handler
+}
+
+// NewHandler builds a handler over an arbitrary sink.
+//
+// The time and the level are dropped from the formatted line: logcat
+// stamps every entry with both, and repeating them costs a quarter of
+// the width of a phone-sized terminal to say the same thing twice.
+func NewHandler(opts *slog.HandlerOptions, write WriteFunc) *Handler {
+	buf := &bytes.Buffer{}
+
+	inner := &slog.HandlerOptions{}
+	if opts != nil {
+		*inner = *opts
+	}
+
+	user := inner.ReplaceAttr
+	inner.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr {
+		if len(groups) == 0 && isBuiltin(a) {
+			return slog.Attr{}
+		}
+
+		if user != nil {
+			return user(groups, a)
+		}
+
+		return a
+	}
+
+	return &Handler{
+		write:    write,
+		mu:       &sync.Mutex{},
+		buf:      buf,
+		delegate: slog.NewTextHandler(buf, inner),
+	}
+}
+
+// isBuiltin reports whether an attr is slog's own time or level,
+// rather than a caller's attribute that happens to share the name.
+//
+// ReplaceAttr cannot tell those apart by key. It is called with an
+// empty group path for the built-ins *and* for every top-level
+// attribute, so a key comparison alone silently eats a caller's own
+// "level" or "time" -- which is not hypothetical: the probe that
+// verified this package on the device logged one, and the attribute
+// vanished. The kinds are what separate them, because slog builds the
+// built-ins as slog.Any(LevelKey, r.Level) and slog.Time(TimeKey, ...)
+// and an attribute value of type slog.Level is not something a caller
+// passes by accident.
+func isBuiltin(a slog.Attr) bool {
+	switch a.Key {
+	case slog.TimeKey:
+		return a.Value.Kind() == slog.KindTime
+	case slog.LevelKey:
+		_, ok := a.Value.Any().(slog.Level)
+
+		return ok
+	default:
+		return false
+	}
+}
+
+// Enabled reports whether the level is worth formatting.
+func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool {
+	return h.delegate.Enabled(ctx, level)
+}
+
+// Handle formats one record and writes it out, in as many entries as
+// its length demands.
+func (h *Handler) Handle(ctx context.Context, rec slog.Record) error {
+	h.mu.Lock()
+	defer h.mu.Unlock()
+
+	h.buf.Reset()
+
+	if err := h.delegate.Handle(ctx, rec); err != nil {
+		return err
+	}
+
+	prio := Priority(rec.Level)
+	for _, line := range Chunk(strings.TrimRight(h.buf.String(), "\n")) {
+		h.write(prio, Tag, line)
+	}
+
+	return nil
+}
+
+// WithAttrs returns a handler carrying the given attributes.
+func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return h.derive(h.delegate.WithAttrs(attrs))
+}
+
+// WithGroup returns a handler that qualifies subsequent attributes.
+func (h *Handler) WithGroup(name string) slog.Handler {
+	return h.derive(h.delegate.WithGroup(name))
+}
+
+// derive shares the buffer and its mutex with the parent.
+//
+// They must be shared rather than copied: the delegate returned by
+// WithAttrs writes into the *same* buffer this one does, so a second
+// mutex would guard nothing and two loggers derived from one would
+// interleave their bytes into a single line.
+func (h *Handler) derive(delegate slog.Handler) *Handler {
+	return &Handler{
+		write:    h.write,
+		mu:       h.mu,
+		buf:      h.buf,
+		delegate: delegate,
+	}
+}
+
+// Chunk splits a formatted record into entries liblog will carry
+// whole.
+//
+// A record short enough to fit is returned as it is, which is nearly
+// every record; the numbering only appears where something was going
+// to be silently truncated anyway. It splits on bytes rather than runes
+// because the limit is a byte count -- a multi-byte rune straddling the
+// boundary is a mojibake character in a log line, against a lost one.
+func Chunk(msg string) []string {
+	if len(msg) <= maxPayload {
+		return []string{msg}
+	}
+
+	var parts []string
+
+	for rest := msg; rest != ""; {
+		n := min(maxPayload, len(rest))
+		parts = append(parts, rest[:n])
+		rest = rest[n:]
+	}
+
+	numbered := make([]string, 0, len(parts))
+	for i, p := range parts {
+		numbered = append(
+			numbered,
+			"("+strconv.Itoa(i+1)+"/"+strconv.Itoa(len(parts))+") "+p,
+		)
+	}
+
+	return numbered
+}

backend/androidlog/androidlog_test.go

@@ -0,0 +1,355 @@
+package androidlog_test
+
+import (
+	"log/slog"
+	"strings"
+	"sync"
+	"testing"
+
+	"yellowjacket/backend/androidlog"
+)
+
+// entry is one call to the sink.
+type entry struct {
+	prio int
+	tag  string
+	msg  string
+}
+
+// recorder is the platform write, on a machine with no platform.
+type recorder struct {
+	mu      sync.Mutex
+	entries []entry
+}
+
+func (r *recorder) write(prio int, tag, msg string) {
+	r.mu.Lock()
+	defer r.mu.Unlock()
+
+	r.entries = append(r.entries, entry{prio: prio, tag: tag, msg: msg})
+}
+
+func (r *recorder) only(t *testing.T) entry {
+	t.Helper()
+
+	r.mu.Lock()
+	defer r.mu.Unlock()
+
+	if len(r.entries) != 1 {
+		t.Fatalf("want exactly one entry, got %d: %v", len(r.entries), r.entries)
+	}
+
+	return r.entries[0]
+}
+
+func newLogger(r *recorder, level slog.Level) *slog.Logger {
+	return slog.New(androidlog.NewHandler(
+		&slog.HandlerOptions{Level: level},
+		r.write,
+	))
+}
+
+// TestPriorityMapsEveryLevel pins the level banding.
+//
+// This is the one thing in #160 that a wrong answer hides rather than
+// breaks: logcat prints whatever priority it is handed, so an Error
+// filed as Info is a line that is present, correct and invisible to
+// every filter anyone would use to look for it.
+func TestPriorityMapsEveryLevel(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name  string
+		level slog.Level
+		want  int
+	}{
+		{"below debug is verbose", slog.LevelDebug - 1, androidlog.PrioVerbose},
+		{"debug", slog.LevelDebug, androidlog.PrioDebug},
+		{"info", slog.LevelInfo, androidlog.PrioInfo},
+		{"warn", slog.LevelWarn, androidlog.PrioWarn},
+		{"error", slog.LevelError, androidlog.PrioError},
+
+		// slog's levels are open, so a caller may sit between two of
+		// the named ones.  Each lands in the band beneath it, which is
+		// what slog's own level naming does ("INFO+2").
+		{"between info and warn", slog.LevelInfo + 2, androidlog.PrioInfo},
+		{"between warn and error", slog.LevelWarn + 1, androidlog.PrioWarn},
+		{"above error", slog.LevelError + 4, androidlog.PrioError},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			if got := androidlog.Priority(tt.level); got != tt.want {
+				t.Errorf("Priority(%v) = %d, want %d", tt.level, got, tt.want)
+			}
+		})
+	}
+}
+
+// TestPrioritiesAreTheHeadersValues pins the constants themselves.
+//
+// android.go asserts these against android/log.h at compile time, but
+// only a cross-compiler ever builds that file.  This is the assertion
+// that runs in CI, and the numbers are written out longhand on purpose
+// -- comparing a constant to itself would pass on any renumbering.
+func TestPrioritiesAreTheHeadersValues(t *testing.T) {
+	t.Parallel()
+
+	for _, tt := range []struct {
+		name string
+		got  int
+		want int
+	}{
+		{"verbose", androidlog.PrioVerbose, 2},
+		{"debug", androidlog.PrioDebug, 3},
+		{"info", androidlog.PrioInfo, 4},
+		{"warn", androidlog.PrioWarn, 5},
+		{"error", androidlog.PrioError, 6},
+		{"fatal", androidlog.PrioFatal, 7},
+	} {
+		if tt.got != tt.want {
+			t.Errorf("%s priority = %d, want %d", tt.name, tt.got, tt.want)
+		}
+	}
+}
+
+// TestRecordReachesTheSink is the whole point of the package: a line
+// written with slog arrives, under the app's tag, at the right
+// priority.
+func TestRecordReachesTheSink(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	newLogger(rec, slog.LevelInfo).Error("application error", "err", "boom")
+
+	got := rec.only(t)
+
+	if got.prio != androidlog.PrioError {
+		t.Errorf("priority = %d, want %d", got.prio, androidlog.PrioError)
+	}
+
+	if got.tag != androidlog.Tag {
+		t.Errorf("tag = %q, want %q", got.tag, androidlog.Tag)
+	}
+
+	if !strings.Contains(got.msg, "application error") {
+		t.Errorf("message %q does not carry the message", got.msg)
+	}
+
+	if !strings.Contains(got.msg, `err=boom`) {
+		t.Errorf("message %q does not carry the attribute", got.msg)
+	}
+}
+
+// TestTheTagIsNotTheApplicationID guards the trap the tag exists to
+// avoid.
+//
+// The debug build carries `applicationIdSuffix ".dev"`, so it is
+// installed as app.yellowjacket.dev -- and it is the *only* build whose
+// WebView can be inspected, so it is the build anyone debugging this
+// app is running.  A tag derived from the application id therefore
+// differs between the build being looked at and the build the filter
+// was written for, which is the failure this whole issue is about
+// wearing a different hat.
+func TestTheTagIsNotTheApplicationID(t *testing.T) {
+	t.Parallel()
+
+	if strings.Contains(androidlog.Tag, ".") {
+		t.Errorf(
+			"tag %q looks like an application id; it must be stable "+
+				"across the debug suffix",
+			androidlog.Tag,
+		)
+	}
+
+	// Logcat's tag field is 23 bytes.  A longer one is truncated, and a
+	// truncated tag matches no filter.
+	if len(androidlog.Tag) > 23 {
+		t.Errorf("tag %q is %d bytes, over logcat's 23", androidlog.Tag, len(androidlog.Tag))
+	}
+}
+
+// TestTimeAndLevelAreDropped checks the formatting decision.
+//
+// logcat stamps every entry with a timestamp and a priority letter, so
+// carrying slog's own is the same information twice on a 424px screen.
+func TestTimeAndLevelAreDropped(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	newLogger(rec, slog.LevelInfo).Warn("scan finished", "files", 1577)
+
+	got := rec.only(t).msg
+
+	if strings.Contains(got, "time=") {
+		t.Errorf("message %q still carries a timestamp", got)
+	}
+
+	if strings.Contains(got, "level=") {
+		t.Errorf("message %q still carries a level", got)
+	}
+
+	if !strings.Contains(got, "files=1577") {
+		t.Errorf("message %q lost its attributes with them", got)
+	}
+}
+
+// TestACallersOwnLevelAttrSurvives is a regression, and it was found on
+// the phone rather than here.
+//
+// Dropping slog's built-in time and level by key alone also drops a
+// caller's attribute of the same name, because ReplaceAttr sees an
+// empty group path for both. The probe that verified this package on
+// the device wrote slog.Info("...", "level", "info") and logcat showed
+// the message with no attributes at all.
+func TestACallersOwnLevelAttrSurvives(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	newLogger(rec, slog.LevelInfo).Info("probe", "level", "info", "time", "soon")
+
+	got := rec.only(t).msg
+
+	for _, want := range []string{"level=info", "time=soon"} {
+		if !strings.Contains(got, want) {
+			t.Errorf("message %q lost the caller's %q", got, want)
+		}
+	}
+
+	// And slog's own are still gone: the built-in level renders as a
+	// bare word like INFO, never as the caller's value.
+	if strings.Contains(got, "level=INFO") {
+		t.Errorf("message %q carries slog's own level", got)
+	}
+}
+
+// TestLevelIsHonoured checks that Enabled reaches the delegate.
+func TestLevelIsHonoured(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	log := newLogger(rec, slog.LevelWarn)
+
+	log.Info("not this one")
+	log.Warn("this one")
+
+	if got := rec.only(t).msg; !strings.Contains(got, "this one") {
+		t.Errorf("wrong record survived: %q", got)
+	}
+}
+
+// TestGroupsAndAttrsSurvive covers the half of slog.Handler this
+// delegates rather than implements -- the reason it delegates at all.
+func TestGroupsAndAttrsSurvive(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	log := newLogger(rec, slog.LevelInfo).
+		With("component", "player").
+		WithGroup("track")
+
+	log.Info("loaded", "path", "/sdcard/Music/a.flac")
+
+	got := rec.only(t).msg
+
+	for _, want := range []string{
+		"component=player",
+		"track.path=/sdcard/Music/a.flac",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("message %q is missing %q", got, want)
+		}
+	}
+}
+
+// TestDerivedHandlersDoNotInterleave is why derive shares the buffer's
+// mutex rather than taking a new one.
+//
+// Two loggers derived from one write into the same buffer, so a second
+// mutex would guard nothing and a concurrent pair would splice each
+// other's bytes into a single line -- which reads as corrupted logs
+// under load and as nothing at all in a test that logs once.
+func TestDerivedHandlersDoNotInterleave(t *testing.T) {
+	t.Parallel()
+
+	rec := &recorder{}
+	base := newLogger(rec, slog.LevelInfo)
+
+	var wg sync.WaitGroup
+
+	for i := range 8 {
+		wg.Add(1)
+
+		go func() {
+			defer wg.Done()
+
+			log := base.With("worker", i).WithGroup("g")
+			for range 50 {
+				log.Info("tick", "n", i)
+			}
+		}()
+	}
+
+	wg.Wait()
+
+	rec.mu.Lock()
+	defer rec.mu.Unlock()
+
+	if len(rec.entries) != 8*50 {
+		t.Fatalf("got %d entries, want %d", len(rec.entries), 8*50)
+	}
+
+	for _, e := range rec.entries {
+		if strings.Count(e.msg, "msg=tick") != 1 {
+			t.Fatalf("interleaved line: %q", e.msg)
+		}
+	}
+}
+
+// TestChunkLeavesShortLinesAlone is the common case: no numbering
+// appears on a record that was never going to be truncated.
+func TestChunkLeavesShortLinesAlone(t *testing.T) {
+	t.Parallel()
+
+	got := androidlog.Chunk("msg=short")
+
+	if len(got) != 1 || got[0] != "msg=short" {
+		t.Errorf("Chunk(short) = %q, want the input unchanged", got)
+	}
+}
+
+// TestChunkSplitsWhatWouldBeTruncated covers the case liblog drops
+// silently.
+func TestChunkSplitsWhatWouldBeTruncated(t *testing.T) {
+	t.Parallel()
+
+	const n = 9000
+
+	long := strings.Repeat("x", n)
+	parts := androidlog.Chunk(long)
+
+	if len(parts) < 2 {
+		t.Fatalf("a %d-byte line was not split", n)
+	}
+
+	var payload strings.Builder
+
+	for i, p := range parts {
+		if len(p) > 4000 {
+			t.Errorf("part %d is %d bytes, over liblog's entry", i, len(p))
+		}
+
+		_, rest, found := strings.Cut(p, ") ")
+		if !found {
+			t.Fatalf("part %d carries no (n/m) marker: %q", i, p)
+		}
+
+		payload.WriteString(rest)
+	}
+
+	if payload.String() != long {
+		t.Errorf("the parts do not reassemble into the input")
+	}
+}

backend/database/sql/queries/albums.sql

@@ -40,7 +40,8 @@ WHERE id = ? AND (mbid IS NULL OR mbid = '');
 -- name: GetAlbumsWithPendingReleaseMBID :many
 SELECT id, pending_release_mbid FROM albums
 WHERE pending_release_mbid IS NOT NULL AND pending_release_mbid != ''
-  AND (mbid IS NULL OR mbid = '');
+  AND (mbid IS NULL OR mbid = '')
+LIMIT ?;
 
 -- name: DeleteAlbum :exec
 DELETE FROM albums WHERE id = ?;

backend/database/sql/sqlcgen/albums.sql.go

@@ -331,6 +331,7 @@ const getAlbumsWithPendingReleaseMBID = `-- name: GetAlbumsWithPendingReleaseMBI
 SELECT id, pending_release_mbid FROM albums
 WHERE pending_release_mbid IS NOT NULL AND pending_release_mbid != ''
   AND (mbid IS NULL OR mbid = '')
+LIMIT ?
 `
 
 type GetAlbumsWithPendingReleaseMBIDRow struct {
@@ -338,8 +339,8 @@ type GetAlbumsWithPendingReleaseMBIDRow struct {
 	PendingReleaseMbid sql.NullString
 }
 
-func (q *Queries) GetAlbumsWithPendingReleaseMBID(ctx context.Context) ([]GetAlbumsWithPendingReleaseMBIDRow, error) {
-	rows, err := q.db.QueryContext(ctx, getAlbumsWithPendingReleaseMBID)
+func (q *Queries) GetAlbumsWithPendingReleaseMBID(ctx context.Context, limit int64) ([]GetAlbumsWithPendingReleaseMBIDRow, error) {
+	rows, err := q.db.QueryContext(ctx, getAlbumsWithPendingReleaseMBID, limit)
 	if err != nil {
 		return nil, err
 	}

backend/explore/explore.go

@@ -2,6 +2,7 @@ package explore
 
 import (
 	"context"
+	"database/sql"
 	"log/slog"
 	"math"
 	"sort"
@@ -12,6 +13,7 @@ import (
 	"golang.org/x/sync/singleflight"
 
 	"yellowjacket/backend/database"
+	"yellowjacket/backend/database/sql/sqlcgen"
 	"yellowjacket/backend/events"
 	"yellowjacket/backend/jobs"
 )
@@ -279,37 +281,32 @@ func (e *Service) BackfillReleaseGroupMBIDs() {
 	go e.backfillReleaseGroupMBIDs(e.ctx)
 }
 
-func (e *Service) backfillReleaseGroupMBIDs(ctx context.Context) {
-	rows, err := e.db.QueryContext(
-		"SELECT id, pending_release_mbid FROM release_groups "+
-			"WHERE (mbid IS NULL OR mbid = '') "+
-			"AND pending_release_mbid IS NOT NULL AND pending_release_mbid != '' "+
-			"LIMIT ?",
-		releaseGroupMBIDBackfillMaxPerRun,
+// pendingReleaseMBIDs is the albums this pass has work to do on.
+//
+// It is separate from the pass, and returns its error rather than
+// logging it, so that a test can assert the statement runs against the
+// real schema. That is not a general preference -- it is this
+// statement's history: it named `release_groups`, a table plan 013
+// renamed to `albums`, so it failed on every launch since e7748f1 and
+// the pass returned quietly having done nothing. A test of the pass
+// as a whole cannot see that, because a query error and an empty
+// library are the same early return.
+func (e *Service) pendingReleaseMBIDs(
+	ctx context.Context,
+) ([]sqlcgen.GetAlbumsWithPendingReleaseMBIDRow, error) {
+	return e.db.ReadQueries.GetAlbumsWithPendingReleaseMBID(
+		ctx, releaseGroupMBIDBackfillMaxPerRun,
 	)
+}
+
+func (e *Service) backfillReleaseGroupMBIDs(ctx context.Context) {
+	pending, err := e.pendingReleaseMBIDs(ctx)
 	if err != nil {
 		e.logger.Warn("release-group mbid backfill: query failed", "error", err)
 
 		return
 	}
 
-	type pendingRow struct {
-		id          int64
-		releaseMBID string
-	}
-
-	var pending []pendingRow
-
-	for rows.Next() {
-		var p pendingRow
-
-		if err := rows.Scan(&p.id, &p.releaseMBID); err == nil {
-			pending = append(pending, p)
-		}
-	}
-
-	_ = rows.Close()
-
 	if len(pending) == 0 {
 		return
 	}
@@ -335,7 +332,7 @@ func (e *Service) backfillReleaseGroupMBIDs(ctx context.Context) {
 
 		job.progress(i, len(pending))
 
-		release, err := e.mb.LookupRelease(ctx, p.releaseMBID)
+		release, err := e.mb.LookupRelease(ctx, p.PendingReleaseMbid.String)
 		if err != nil || release.ReleaseGroupMBID == "" {
 			// Left alone rather than cleared: LookupRelease caches its
 			// answer (success or a release with no group) for 7 days,
@@ -344,12 +341,19 @@ func (e *Service) backfillReleaseGroupMBIDs(ctx context.Context) {
 			continue
 		}
 
-		_, err = e.db.ExecContext(
-			"UPDATE release_groups SET mbid = ?, pending_release_mbid = NULL "+
-				"WHERE id = ? AND (mbid IS NULL OR mbid = '')",
-			release.ReleaseGroupMBID, p.id,
-		)
-		if err != nil {
+		// The writer, not ReadQueries: an UPDATE issued on the
+		// query-only pool fails at runtime with "attempt to write a
+		// readonly database".
+		if err := e.db.Queries.ResolveAlbumPendingReleaseMBID(
+			ctx,
+			sqlcgen.ResolveAlbumPendingReleaseMBIDParams{
+				Mbid: sql.NullString{
+					String: release.ReleaseGroupMBID,
+					Valid:  true,
+				},
+				ID: p.ID,
+			},
+		); err != nil {
 			e.logger.Warn("release-group mbid backfill: update failed", "error", err)
 		}
 	}

backend/explore/pendingreleasembid_test.go

@@ -0,0 +1,250 @@
+package explore
+
+import (
+	"database/sql"
+	"log/slog"
+	"strconv"
+	"testing"
+
+	"yellowjacket/backend/database"
+	"yellowjacket/backend/database/sql/sqlcgen"
+)
+
+// The release-group MBID backfill queried `release_groups`, a table
+// plan 013 renamed to `albums`, so it failed on its first statement on
+// every launch from e7748f1 until #189 -- and the pass swallowed that,
+// because a query error and an empty library are the same early
+// return. Nothing noticed for two reasons worth keeping in mind:
+//
+//   - the statement was **raw SQL**, so sqlc never read it. Every other
+//     statement in the repo was renamed by the same change because sqlc
+//     reads sql/schemas/ and cannot generate against a table that is not
+//     declared. The two sqlc queries this now calls were written by 013
+//     and left uncalled.
+//   - it needs no network and no fixture library to reproduce. The
+//     failure is at prepare time.
+
+// seedPendingAlbum inserts an album whose files carried a release MBID
+// but no release-group MBID, which is what `library.updateMBIDs`
+// leaves behind for this pass to resolve.
+func seedPendingAlbum(
+	t *testing.T,
+	db *database.DB,
+	name, pendingMBID string,
+) int64 {
+	t.Helper()
+
+	res, err := db.ExecContext(
+		"INSERT INTO albums (name, artist_credit, pending_release_mbid) "+
+			"VALUES (?, ?, ?)",
+		name, "Test Artist", pendingMBID,
+	)
+	if err != nil {
+		t.Fatalf("insert albums row: %v", err)
+	}
+
+	id, err := res.LastInsertId()
+	if err != nil {
+		t.Fatalf("last insert id: %v", err)
+	}
+
+	return id
+}
+
+func newPendingTestService(db *database.DB) *Service {
+	return &Service{db: db, logger: slog.Default()}
+}
+
+// TestPendingReleaseMBIDsRunsAgainstTheRealSchema is the regression.
+//
+// It asserts the statement *runs*, which is the whole of what was
+// broken: against the old raw SQL this returns
+// "no such table: release_groups" rather than a row.
+func TestPendingReleaseMBIDsRunsAgainstTheRealSchema(t *testing.T) {
+	t.Parallel()
+
+	db := database.NewTestDB(t)
+	e := newPendingTestService(db)
+
+	want := seedPendingAlbum(t, db, "Pending Album", "release-mbid-1")
+
+	pending, err := e.pendingReleaseMBIDs(db.Ctx)
+	if err != nil {
+		t.Fatalf("the backfill's query failed: %v", err)
+	}
+
+	if len(pending) != 1 {
+		t.Fatalf("got %d pending albums, want 1", len(pending))
+	}
+
+	if pending[0].ID != want {
+		t.Errorf("got album id %d, want %d", pending[0].ID, want)
+	}
+
+	if got := pending[0].PendingReleaseMbid.String; got != "release-mbid-1" {
+		t.Errorf("got pending mbid %q, want %q", got, "release-mbid-1")
+	}
+}
+
+// TestOnlyUnresolvedAlbumsAreReturned pins the two conditions that make
+// the pass idempotent, since between them they are what stops it doing
+// the same MusicBrainz lookups on every launch forever.
+func TestOnlyUnresolvedAlbumsAreReturned(t *testing.T) {
+	t.Parallel()
+
+	db := database.NewTestDB(t)
+	e := newPendingTestService(db)
+
+	pendingID := seedPendingAlbum(t, db, "Still Pending", "release-mbid-1")
+
+	// Already resolved: it has a real MBID, so there is nothing to
+	// look up even though a marker is still sitting on it.
+	resolved := seedPendingAlbum(t, db, "Already Resolved", "release-mbid-2")
+	if err := db.Queries.SetAlbumMBID(db.Ctx, sqlcgen.SetAlbumMBIDParams{
+		Mbid: sql.NullString{String: "rg-mbid", Valid: true},
+		ID:   resolved,
+	}); err != nil {
+		t.Fatalf("set album mbid: %v", err)
+	}
+
+	// Never had a release MBID to resolve in the first place, which is
+	// most of a library.
+	seedPendingAlbum(t, db, "Nothing Pending", "")
+
+	pending, err := e.pendingReleaseMBIDs(db.Ctx)
+	if err != nil {
+		t.Fatalf("the backfill's query failed: %v", err)
+	}
+
+	if len(pending) != 1 || pending[0].ID != pendingID {
+		t.Fatalf(
+			"got %d albums %v, want only the unresolved one (%d)",
+			len(pending), pending, pendingID,
+		)
+	}
+}
+
+// TestResolvingClearsTheMarker is the other half: once the lookup has
+// answered, the album must stop being a candidate, or the pass repeats
+// the same live MusicBrainz call on every launch.
+func TestResolvingClearsTheMarker(t *testing.T) {
+	t.Parallel()
+
+	db := database.NewTestDB(t)
+	e := newPendingTestService(db)
+
+	id := seedPendingAlbum(t, db, "Pending Album", "release-mbid-1")
+
+	// The writer, deliberately: this is an UPDATE, and the read pool
+	// would refuse it at runtime.
+	if err := db.Queries.ResolveAlbumPendingReleaseMBID(
+		db.Ctx,
+		sqlcgen.ResolveAlbumPendingReleaseMBIDParams{
+			Mbid: sql.NullString{String: "resolved-rg-mbid", Valid: true},
+			ID:   id,
+		},
+	); err != nil {
+		t.Fatalf("resolve pending release mbid: %v", err)
+	}
+
+	pending, err := e.pendingReleaseMBIDs(db.Ctx)
+	if err != nil {
+		t.Fatalf("the backfill's query failed: %v", err)
+	}
+
+	if len(pending) != 0 {
+		t.Fatalf("a resolved album is still a candidate: %v", pending)
+	}
+
+	album, err := db.ReadQueries.GetAlbum(db.Ctx, id)
+	if err != nil {
+		t.Fatalf("get album: %v", err)
+	}
+
+	if album.Mbid.String != "resolved-rg-mbid" {
+		t.Errorf("album mbid = %q, want the resolved one", album.Mbid.String)
+	}
+
+	if album.PendingReleaseMbid.Valid &&
+		album.PendingReleaseMbid.String != "" {
+		t.Errorf(
+			"the pending marker survived as %q",
+			album.PendingReleaseMbid.String,
+		)
+	}
+}
+
+// TestAResolvedMBIDIsNeverOverwritten covers the guard in the UPDATE.
+//
+// The pass runs against rows it read earlier, and a rescan can resolve
+// an album from its tags in between -- a real MBID from the file must
+// win over one this pass inferred from a release.
+func TestAResolvedMBIDIsNeverOverwritten(t *testing.T) {
+	t.Parallel()
+
+	db := database.NewTestDB(t)
+
+	id := seedPendingAlbum(t, db, "Pending Album", "release-mbid-1")
+
+	if err := db.Queries.SetAlbumMBID(db.Ctx, sqlcgen.SetAlbumMBIDParams{
+		Mbid: sql.NullString{String: "from-the-tags", Valid: true},
+		ID:   id,
+	}); err != nil {
+		t.Fatalf("set album mbid: %v", err)
+	}
+
+	if err := db.Queries.ResolveAlbumPendingReleaseMBID(
+		db.Ctx,
+		sqlcgen.ResolveAlbumPendingReleaseMBIDParams{
+			Mbid: sql.NullString{String: "from-the-backfill", Valid: true},
+			ID:   id,
+		},
+	); err != nil {
+		t.Fatalf("resolve pending release mbid: %v", err)
+	}
+
+	album, err := db.ReadQueries.GetAlbum(db.Ctx, id)
+	if err != nil {
+		t.Fatalf("get album: %v", err)
+	}
+
+	if album.Mbid.String != "from-the-tags" {
+		t.Errorf(
+			"album mbid = %q, want the tagged one to have won",
+			album.Mbid.String,
+		)
+	}
+}
+
+// TestThePassIsBounded checks the LIMIT.
+//
+// Each row costs a live MusicBrainz lookup on a 1 req/s limiter shared
+// with every page the user can open, so an unbounded read is a run that
+// lasts as long as the library is untagged. The sqlc query 013 wrote
+// had no LIMIT; the raw statement it was replacing did.
+func TestThePassIsBounded(t *testing.T) {
+	t.Parallel()
+
+	db := database.NewTestDB(t)
+	e := newPendingTestService(db)
+
+	for i := range releaseGroupMBIDBackfillMaxPerRun + 10 {
+		seedPendingAlbum(
+			t, db,
+			"Album "+string(rune('A'+i%26))+strconv.Itoa(i),
+			"release-mbid-"+strconv.Itoa(i),
+		)
+	}
+
+	pending, err := e.pendingReleaseMBIDs(db.Ctx)
+	if err != nil {
+		t.Fatalf("the backfill's query failed: %v", err)
+	}
+
+	if len(pending) != releaseGroupMBIDBackfillMaxPerRun {
+		t.Errorf(
+			"got %d albums, want the run bounded at %d",
+			len(pending), releaseGroupMBIDBackfillMaxPerRun,
+		)
+	}
+}

backend/player/buffered_streamer.go

@@ -47,6 +47,39 @@ type BufferedStreamer struct {
 	// seek bar and suppresses its interpolation.
 	starved      int
 	starvedSince time.Time
+
+	// underruns accumulates for the life of this streamer, where
+	// starved is reset by every arriving sample.
+	//
+	// The two answer different questions and only the first was being
+	// asked. starved is a *stall* detector: it exists to end a track
+	// whose source has died, so it forgets a run the moment audio
+	// resumes -- which is exactly the case this counts. A hundred 20ms
+	// underruns a minute never approach the give-up threshold and were
+	// invisible to the log, the UI and every test tier, while being
+	// audible as static: an underrun is served as a run of zeros
+	// spliced into the waveform, and a step discontinuity at each edge
+	// is what a click is.
+	underruns UnderrunStats
+}
+
+// UnderrunStats is what the ring buffer missed, cumulatively.
+//
+// Samples rather than milliseconds because this type does not know the
+// sample rate -- the player does, and converts at the point of
+// reporting.
+type UnderrunStats struct {
+	// Runs is the number of *episodes*: transitions from healthy into
+	// starved. Calls is how many Stream calls were served with
+	// silence, and Samples is how much silence that was.
+	//
+	// Runs is the count that means something audible. One episode is
+	// one pop however many calls it spans, and the ratio of the two is
+	// how long the average episode was -- which is what separates
+	// "clicking" from "dropping out".
+	Runs    int64
+	Calls   int64
+	Samples int64
 }
 
 // The silence fill is bounded by both a duration and a run of calls,
@@ -226,6 +259,13 @@ func (bs *BufferedStreamer) Stream(
 		// but only for a bounded stretch, because "forever" is
 		// reported upward as healthy playback and there is no watchdog
 		// above this to notice otherwise.
+		if bs.starved == 0 {
+			bs.underruns.Runs++
+		}
+
+		bs.underruns.Calls++
+		bs.underruns.Samples += int64(len(samples))
+
 		bs.starved++
 
 		if bs.starvedSince.IsZero() {
@@ -269,6 +309,20 @@ func (bs *BufferedStreamer) Stream(
 	return n, true
 }
 
+// Underruns returns the cumulative underrun count.
+//
+// It is a snapshot rather than a live view, and it is read from
+// outside the audio callback: counting happens in Stream, under the
+// lock it already takes, because that path has a real-time deadline
+// and anything that allocates or formats on it is a cause of the
+// defect it is measuring rather than a measurement of it.
+func (bs *BufferedStreamer) Underruns() UnderrunStats {
+	bs.mu.Lock()
+	defer bs.mu.Unlock()
+
+	return bs.underruns
+}
+
 // Err returns any error encountered by the source streamer.
 func (bs *BufferedStreamer) Err() error {
 	bs.mu.Lock()
@@ -298,6 +352,10 @@ func (bs *BufferedStreamer) Flush() {
 
 // resetStarvationLocked forgets an underrun run.  Must be called with
 // bs.mu held.
+//
+// Deliberately does not touch bs.underruns: forgetting the run is what
+// makes starved a stall detector, and remembering it is the whole
+// point of the counter beside it.
 func (bs *BufferedStreamer) resetStarvationLocked() {
 	bs.starved = 0
 	bs.starvedSince = time.Time{}

backend/player/buffered_underrun_test.go

@@ -0,0 +1,279 @@
+package player
+
+import (
+	"sync"
+	"testing"
+	"time"
+)
+
+// An underrun is audible and nothing counted it (#135).
+//
+// The distinction these tests exist for is that `starved` and
+// `underruns` disagree on purpose. `starved` is a stall detector: it is
+// reset by every arriving sample, because its job is to end a track
+// whose source has died and a source that is merely slow must not be
+// cut short (TestUnderrunsDoNotAccumulateAcrossASlowSource, next
+// door). That reset is exactly what made the audible case invisible --
+// a hundred short underruns a minute never approach the give-up
+// threshold, and each one is a run of zeros spliced into the waveform
+// with a step discontinuity at both edges.
+
+// TestAnEmptyRingIsCounted is the measurement itself: silence served
+// for a missing sample is recorded rather than merely tolerated.
+func TestAnEmptyRingIsCounted(t *testing.T) {
+	t.Parallel()
+
+	// A source that never produces is the cleanest way to make the
+	// ring empty on demand; the stall budget is far longer than the
+	// handful of calls below.
+	bs := NewBufferedStreamer(stalledStreamer{}, 1024)
+	defer bs.Close()
+
+	if got := bs.Underruns(); got != (UnderrunStats{}) {
+		t.Fatalf("a fresh streamer already reports %+v", got)
+	}
+
+	buf := make([][2]float64, 256)
+
+	for range 3 {
+		if _, ok := bs.Stream(buf); !ok {
+			t.Fatal("the stall budget ran out before the test did")
+		}
+	}
+
+	got := bs.Underruns()
+
+	if got.Calls != 3 {
+		t.Errorf("Calls = %d, want 3", got.Calls)
+	}
+
+	if got.Samples != int64(3*len(buf)) {
+		t.Errorf("Samples = %d, want %d", got.Samples, 3*len(buf))
+	}
+
+	// Three consecutive silent calls are one episode, not three. That
+	// is the number that means something audible: one interruption is
+	// one pop however many callbacks it spans.
+	if got.Runs != 1 {
+		t.Errorf("Runs = %d, want 1 -- an unbroken run is one episode", got.Runs)
+	}
+}
+
+// TestSilenceIsWhatIsCounted pins what an underrun actually does to the
+// waveform, which is the reason to count it at all.
+func TestSilenceIsWhatIsCounted(t *testing.T) {
+	t.Parallel()
+
+	bs := NewBufferedStreamer(stalledStreamer{}, 1024)
+	defer bs.Close()
+
+	buf := make([][2]float64, 64)
+	for i := range buf {
+		buf[i] = [2]float64{0.5, 0.5}
+	}
+
+	n, ok := bs.Stream(buf)
+	if !ok || n != len(buf) {
+		t.Fatalf("Stream = (%d, %v), want (%d, true)", n, ok, len(buf))
+	}
+
+	for i := range buf {
+		if buf[i] != ([2]float64{}) {
+			t.Fatalf("sample %d is %v, want silence", i, buf[i])
+		}
+	}
+
+	if got := bs.Underruns().Samples; got != int64(len(buf)) {
+		t.Errorf("counted %d samples of silence, wrote %d", got, len(buf))
+	}
+}
+
+// TestSeparateEpisodesAreSeparateRuns is the counter's whole shape:
+// audio arriving between two underruns makes them two, because that is
+// two interruptions and two clicks.
+func TestSeparateEpisodesAreSeparateRuns(t *testing.T) {
+	t.Parallel()
+
+	// A source that yields nothing until it is fed, so the ring can be
+	// emptied, filled and emptied again on demand.
+	src := &gatedStreamer{}
+
+	bs := NewBufferedStreamer(src, 1024)
+	defer bs.Close()
+
+	buf := make([][2]float64, 128)
+
+	starve := func() {
+		t.Helper()
+
+		for range 2 {
+			if _, ok := bs.Stream(buf); !ok {
+				t.Fatal("the stall budget ran out before the test did")
+			}
+		}
+	}
+
+	// feed lets exactly one bufferful through and drains it, so the
+	// ring is empty again on return. Allowing more would mean the
+	// starve() after it drained real audio instead of underrunning,
+	// which is what the first version of this test did -- it reported
+	// one episode and looked like the counter was wrong.
+	feed := func() {
+		t.Helper()
+
+		src.allow(len(buf))
+
+		// The read-ahead is a goroutine, so wait for real samples
+		// rather than assuming they have landed.
+		deadline := time.Now().Add(2 * time.Second)
+		for time.Now().Before(deadline) {
+			n, ok := bs.Stream(buf)
+			if ok && n > 0 && buf[0] != ([2]float64{}) {
+				return
+			}
+
+			time.Sleep(time.Millisecond)
+		}
+
+		t.Fatal("the source never delivered a sample")
+	}
+
+	starve()
+	feed()
+	starve()
+
+	if got := bs.Underruns().Runs; got < 2 {
+		t.Errorf(
+			"Runs = %d, want at least 2 -- audio in between makes two "+
+				"episodes, not one",
+			got,
+		)
+	}
+}
+
+// TestTheStallResetDoesNotClearTheCounter is the regression this file
+// is really about.
+//
+// resetStarvationLocked runs on every arriving sample and on every
+// Flush. If it cleared the cumulative count too, the counter would
+// report zero on exactly the workload it exists to measure -- a stream
+// that underruns repeatedly but always recovers -- which is
+// indistinguishable from healthy playback and is what the code did
+// before #135.
+func TestTheStallResetDoesNotClearTheCounter(t *testing.T) {
+	t.Parallel()
+
+	bs := NewBufferedStreamer(stalledStreamer{}, 1024)
+	defer bs.Close()
+
+	buf := make([][2]float64, 128)
+
+	if _, ok := bs.Stream(buf); !ok {
+		t.Fatal("the stall budget ran out before the test did")
+	}
+
+	before := bs.Underruns()
+	if before.Runs == 0 {
+		t.Fatal("nothing was counted, so the reset cannot be tested")
+	}
+
+	// Both of the ways a run is forgotten.
+	bs.mu.Lock()
+	bs.resetStarvationLocked()
+	bs.mu.Unlock()
+
+	bs.Flush()
+
+	if got := bs.Underruns(); got != before {
+		t.Errorf(
+			"forgetting the stall run also discarded the count: %+v, "+
+				"want %+v",
+			got, before,
+		)
+	}
+}
+
+// TestUnderrunDeltaNeverGoesBackwards covers the one arithmetic trap in
+// the reporting side.
+//
+// The counter belongs to the streamer and the streamer is replaced on
+// every track, so a baseline carried across a track change is the
+// previous track's total subtracted from a fresh zero. The load path
+// resets the baseline, and this clamps as well -- a negative count in a
+// log line reads as a broken instrument, which would discredit the
+// measurement rather than merely mis-state it.
+func TestUnderrunDeltaNeverGoesBackwards(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name string
+		now  UnderrunStats
+		last UnderrunStats
+		want UnderrunStats
+	}{
+		{
+			name: "ordinary progress",
+			now:  UnderrunStats{Runs: 5, Calls: 40, Samples: 4000},
+			last: UnderrunStats{Runs: 2, Calls: 10, Samples: 1000},
+			want: UnderrunStats{Runs: 3, Calls: 30, Samples: 3000},
+		},
+		{
+			name: "nothing happened",
+			now:  UnderrunStats{Runs: 5, Calls: 40, Samples: 4000},
+			last: UnderrunStats{Runs: 5, Calls: 40, Samples: 4000},
+			want: UnderrunStats{},
+		},
+		{
+			name: "a new streamer, with a stale baseline",
+			now:  UnderrunStats{},
+			last: UnderrunStats{Runs: 9, Calls: 90, Samples: 9000},
+			want: UnderrunStats{},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			if got := underrunDelta(tt.now, tt.last); got != tt.want {
+				t.Errorf("underrunDelta = %+v, want %+v", got, tt.want)
+			}
+		})
+	}
+}
+
+// gatedStreamer produces only what it has been allowed to, and
+// otherwise stalls without ending -- so a test can decide exactly when
+// the ring runs dry.
+type gatedStreamer struct {
+	mu        sync.Mutex
+	remaining int
+}
+
+func (g *gatedStreamer) allow(n int) {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	g.remaining += n
+}
+
+func (g *gatedStreamer) Stream(samples [][2]float64) (int, bool) {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	if g.remaining <= 0 {
+		return 0, true
+	}
+
+	n := min(len(samples), g.remaining)
+
+	for i := range n {
+		samples[i] = [2]float64{0.25, 0.25}
+	}
+
+	g.remaining -= n
+
+	return n, true
+}
+
+func (g *gatedStreamer) Err() error { return nil }

backend/player/player.go

@@ -39,16 +39,21 @@ type Player struct {
 	// via the queue).
 	mu sync.Mutex
 
-	ctx                     context.Context
-	logger                  *slog.Logger
-	db                      *database.DB
-	state                   State
-	currentFile             *os.File
-	format                  beep.Format
-	baseStreamer            beep.Streamer
-	seeker                  beep.StreamSeeker
-	resampled               beep.Streamer
-	buffered                *BufferedStreamer
+	ctx          context.Context
+	logger       *slog.Logger
+	db           *database.DB
+	state        State
+	currentFile  *os.File
+	format       beep.Format
+	baseStreamer beep.Streamer
+	seeker       beep.StreamSeeker
+	resampled    beep.Streamer
+	buffered     *BufferedStreamer
+
+	// lastUnderruns is the previous report, so the 1 Hz log can say
+	// what happened in the last second and stay quiet when nothing did.
+	// It is reset with the streamer, in loadFileLocked.
+	lastUnderruns           UnderrunStats
 	control                 *beep.Ctrl
 	volume                  *effects.Volume
 	speakerStreamer         beep.Streamer
@@ -292,9 +297,78 @@ func (p *Player) emitPositionIfPlaying() {
 		return
 	}
 
+	p.reportUnderrunsLocked()
 	p.emitPositionLocked()
 }
 
+// underrunDelta is what happened since the last report.
+//
+// It clamps at zero rather than subtracting blind, because the counter
+// belongs to the *streamer* and the streamer is replaced on every
+// track: a baseline carried across that boundary is the previous
+// track's total subtracted from a fresh zero, which is negative. That
+// is repaired at the load (lastUnderruns is reset with the streamer)
+// and clamped here as well, because a negative count in a log line
+// reads as a broken instrument and would discredit the measurement
+// this exists to make.
+func underrunDelta(now, last UnderrunStats) UnderrunStats {
+	return UnderrunStats{
+		Runs:    max(0, now.Runs-last.Runs),
+		Calls:   max(0, now.Calls-last.Calls),
+		Samples: max(0, now.Samples-last.Samples),
+	}
+}
+
+// reportUnderrunsLocked logs what the ring buffer missed, at most once
+// a second and only when the number moved.  Must be called with p.mu
+// held.
+//
+// **An underrun is audible and nothing counted it** (#135). The ring
+// serves silence when it is empty, so a run of zeros is spliced into
+// the waveform and the step discontinuity at each edge is a click; a
+// series of short ones is static. Everything that makes one likelier
+// is worse on a phone than on a desktop -- slower storage, a governor
+// that parks cores, background work, GC -- and no tier here can see it,
+// since CI's audio device is a null sink chosen because it keeps time.
+//
+// Three things about the reporting are deliberate.
+//
+// **It is on the 1 Hz position ticker rather than in Stream.** Stream
+// runs on the speaker callback's real-time deadline, and a log line
+// there would allocate, format and write on the exact path whose
+// missed deadline is the defect -- measuring by making it worse.
+//
+// **An unchanged count is not logged.** That is emitStatus' rule one
+// package over: a healthy player is silent, so anything in the log is
+// news, and the line appears exactly while it is popping. Reading it
+// off a device means `make android-logs` with the audio audible.
+//
+// **It is Info rather than Debug**, because the default level is Info
+// and a phone has no convenient way to set YJ_LOG_LEVEL -- a debug
+// line here would be a counter nobody on the affected platform can
+// read, which is the shape of the bug that made #160 necessary.
+func (p *Player) reportUnderrunsLocked() {
+	if p.buffered == nil {
+		return
+	}
+
+	stats := p.buffered.Underruns()
+	if stats == p.lastUnderruns {
+		return
+	}
+
+	since := underrunDelta(stats, p.lastUnderruns)
+	p.lastUnderruns = stats
+
+	slog.Info("audio underrun",
+		"runs", since.Runs,
+		"calls", since.Calls,
+		"silenceMs", speakerSampleRate.D(int(since.Samples)).Milliseconds(),
+		"trackRuns", stats.Runs,
+		"trackSilenceMs", speakerSampleRate.D(int(stats.Samples)).Milliseconds(),
+	)
+}
+
 // emitPositionLocked pushes the current position to the frontend.
 // Must be called with p.mu held.
 func (p *Player) emitPositionLocked() {
@@ -484,6 +558,12 @@ func (p *Player) updateStreamers(
 		p.resampled, int(speakerSampleRate)*2,
 	)
 
+	// The counter belongs to the streamer, so the baseline it is
+	// reported against has to go with it -- otherwise the first report
+	// of a new track is the previous track's total subtracted from
+	// zero, which is negative and looks like the instrument is broken.
+	p.lastUnderruns = UnderrunStats{}
+
 	// wrap in ctrl streamer to allow play/pause
 	p.control = &beep.Ctrl{Streamer: p.buffered}
 

backend/system/userdata.go

@@ -52,6 +52,75 @@ func UseHomeOverride(base string) {
 	_ = os.Setenv(envHomeOverride, base)
 }
 
+// envTempDir is the variable Go's os.TempDir() reads, and through it
+// every library in the process that asks for a temporary file.
+const envTempDir = "TMPDIR"
+
+// tempDirName is the subdirectory of the app's own storage that
+// becomes that answer.
+const tempDirName = "tmp"
+
+// UseTempDir gives the process a temporary directory that exists.
+//
+// **Android has no /tmp and hands an app no TMPDIR**, and Go's
+// os.TempDir() falls back to "/tmp" when the variable is unset -- so
+// every library in the process that wants scratch space is handed a
+// path that has never existed. SQLite is the one that noticed: an
+// INSERT ... SELECT large enough to spill returned
+// SQLITE_IOERR_GETTEMPPATH (disk I/O error 6410), which is how the
+// champion search index came to fail its rebuild on every launch while
+// the app otherwise looked healthy (#190).
+//
+// It is the *class* that is fixed here rather than that statement.
+// Anything that spills fails the same way on that platform -- large
+// sorts, large joins, VACUUM -- so the repair belongs at the process's
+// one answer to the question rather than at each caller. The
+// alternative considered was PRAGMA temp_store = MEMORY, which is
+// cheaper and more local and is a promise that every future spill fits
+// in RAM on a phone; the catalog is the largest thing in this app and
+// that is not a promise worth making silently.
+//
+// The rules are UseHomeOverride's, for the same reasons. **An empty
+// base is a no-op**, because that is what
+// application.Mobile.StoragePath() returns on desktop -- so this needs
+// no build tag and changes nothing off mobile, where /tmp is real. And
+// **an explicit TMPDIR wins**, so anyone who set one deliberately gets
+// what they asked for; nothing sets it on the platform this exists for.
+//
+// It returns its error rather than swallowing it because a temp
+// directory that could not be created is the same silent failure one
+// step earlier, and since #160 a log line on that platform is
+// something a person can actually read.
+func UseTempDir(base string) error {
+	if base == "" || os.Getenv(envTempDir) != "" {
+		return nil
+	}
+
+	dir := filepath.Join(base, tempDirName)
+
+	if err := os.MkdirAll(dir, os.ModePerm); err != nil {
+		return fmt.Errorf("could not make the temp directory %s: %w", dir, err)
+	}
+
+	// Writability is checked rather than assumed: the whole failure
+	// this repairs is a directory that is named and cannot be used, and
+	// MkdirAll on an existing unwritable directory succeeds.
+	probe, err := os.CreateTemp(dir, "probe")
+	if err != nil {
+		return fmt.Errorf("temp directory %s is not writable: %w", dir, err)
+	}
+
+	name := probe.Name()
+	_ = probe.Close()
+	_ = os.Remove(name)
+
+	if err := os.Setenv(envTempDir, dir); err != nil {
+		return fmt.Errorf("could not set %s: %w", envTempDir, err)
+	}
+
+	return nil
+}
+
 // getUserDirPath returns and creates the path for a user directory.
 func getUserDirPath(dt dirType) (string, error) {
 	path, err := resolveUserDirPath(dt)

backend/system/userdata_test.go

@@ -87,3 +87,116 @@ func TestUseHomeOverride(t *testing.T) {
 		})
 	}
 }
+
+// UseTempDir carries UseHomeOverride's two rules for the same reasons,
+// plus one of its own: the directory it names has to be usable.
+//
+// **The only tier that can compile the platform this exists for is a
+// phone**, so everything decidable off one is decided here -- which is
+// androidpayload.go's discipline, and is why the platform call is a
+// parameter rather than something this package reaches for. The
+// device's half is a single measurement: no /tmp, no TMPDIR (#190).
+func TestUseTempDir(t *testing.T) {
+	t.Run("an empty base is a no-op", func(t *testing.T) {
+		// This is the desktop case in full: StoragePath() answers ""
+		// off mobile, where /tmp is real and must be left alone.
+		t.Setenv(envTempDir, "")
+
+		if err := UseTempDir(""); err != nil {
+			t.Fatalf("UseTempDir(\"\") = %v, want nil", err)
+		}
+
+		if got := os.Getenv(envTempDir); got != "" {
+			t.Errorf("%s = %q, want it untouched", envTempDir, got)
+		}
+	})
+
+	t.Run("an explicit TMPDIR wins", func(t *testing.T) {
+		const chosen = "/somewhere/deliberate"
+
+		// The base is taken before TMPDIR moves, because t.TempDir()
+		// reads TMPDIR too -- which is the same fact this function is
+		// about, met from the other side.
+		base := t.TempDir()
+
+		t.Setenv(envTempDir, chosen)
+
+		if err := UseTempDir(base); err != nil {
+			t.Fatalf("UseTempDir = %v, want nil", err)
+		}
+
+		if got := os.Getenv(envTempDir); got != chosen {
+			t.Errorf("%s = %q, want the explicit %q", envTempDir, got, chosen)
+		}
+	})
+
+	t.Run("points at a real directory under the base", func(t *testing.T) {
+		base := t.TempDir()
+
+		t.Setenv(envTempDir, "")
+
+		if err := UseTempDir(base); err != nil {
+			t.Fatalf("UseTempDir = %v, want nil", err)
+		}
+
+		got := os.Getenv(envTempDir)
+
+		want := filepath.Join(base, tempDirName)
+		if got != want {
+			t.Fatalf("%s = %q, want %q", envTempDir, got, want)
+		}
+
+		// The whole failure being repaired is a temp directory that is
+		// named and does not exist, so naming one is not enough.
+		info, err := os.Stat(got)
+		if err != nil {
+			t.Fatalf("the temp directory was named but not created: %v", err)
+		}
+
+		if !info.IsDir() {
+			t.Fatalf("%s is not a directory", got)
+		}
+	})
+
+	t.Run("os.TempDir then answers with it", func(t *testing.T) {
+		// The point of setting the variable at all: this is what every
+		// library in the process reads, SQLite's driver included.
+		base := t.TempDir()
+
+		t.Setenv(envTempDir, "")
+
+		if err := UseTempDir(base); err != nil {
+			t.Fatalf("UseTempDir = %v, want nil", err)
+		}
+
+		if got := os.TempDir(); got != filepath.Join(base, tempDirName) {
+			t.Errorf("os.TempDir() = %q, want the directory we made", got)
+		}
+	})
+
+	t.Run("an unwritable directory is an error, not a silent success", func(t *testing.T) {
+		if os.Getuid() == 0 {
+			t.Skip("root can write anywhere, so there is nothing to refuse")
+		}
+
+		base := t.TempDir()
+
+		// MkdirAll on an existing directory succeeds whatever its
+		// mode, so without the write probe this case would set TMPDIR
+		// to a directory nothing can use -- which is the bug again,
+		// one directory over.
+		if err := os.Mkdir(filepath.Join(base, tempDirName), 0o500); err != nil {
+			t.Fatalf("prepare the unwritable directory: %v", err)
+		}
+
+		t.Setenv(envTempDir, "")
+
+		if err := UseTempDir(base); err == nil {
+			t.Fatal("UseTempDir accepted a directory it cannot write to")
+		}
+
+		if got := os.Getenv(envTempDir); got != "" {
+			t.Errorf("%s was set to %q despite the failure", envTempDir, got)
+		}
+	})
+}

loghandler_android.go

@@ -0,0 +1,18 @@
+//go:build android
+
+package main
+
+import (
+	"log/slog"
+
+	"yellowjacket/backend/androidlog"
+)
+
+// newLogHandler builds the handler slog writes through.
+//
+// On Android stdout is /dev/null, so devslog here writes the app's
+// entire diagnosis into a hole -- see backend/androidlog. logcat is
+// the platform's sink and this is what reaches it.
+func newLogHandler(opts *slog.HandlerOptions) slog.Handler {
+	return androidlog.New(opts)
+}

loghandler_default.go

@@ -0,0 +1,20 @@
+//go:build !android
+
+package main
+
+import (
+	"log/slog"
+	"os"
+
+	"github.com/golang-cz/devslog"
+)
+
+// newLogHandler builds the handler slog writes through.
+//
+// Off Android that is devslog to stdout, as it has always been. The
+// selection is a build tag rather than a runtime check so that a
+// desktop binary links no cgo for a platform it will never run on --
+// backend/androidlog's write is -llog, which does not exist here.
+func newLogHandler(opts *slog.HandlerOptions) slog.Handler {
+	return devslog.NewHandler(os.Stdout, &devslog.Options{HandlerOptions: opts})
+}

main.go

@@ -8,7 +8,6 @@ import (
 	"strings"
 	"sync/atomic"
 
-	"github.com/golang-cz/devslog"
 	"github.com/wailsapp/wails/v3/pkg/application"
 	"github.com/wailsapp/wails/v3/pkg/events"
 
@@ -110,14 +109,23 @@ func main() {
 	// create sLogger
 	loglevel := resolveLogLevel(isDev)
 
-	sLogger := slog.New(devslog.NewHandler(os.Stdout, &devslog.Options{
-		HandlerOptions: &slog.HandlerOptions{
-			Level: loglevel,
-		},
-	}))
+	sLogger := slog.New(newLogHandler(&slog.HandlerOptions{Level: loglevel}))
 	slog.SetDefault(sLogger)
 	sLogger.Info("starting yellowjacket", "version", version, "commit", commit)
 
+	// Android has no /tmp and gives an app no TMPDIR, so anything in
+	// this process that spills to a temporary file is handed a path that
+	// does not exist -- see system.UseTempDir. It runs here rather than
+	// beside UseHomeOverride above because it has something to say when
+	// it fails and the logger does not exist up there; what matters is
+	// that it is before NewYellowJacketApp, which opens the database.
+	//
+	// A failure is not fatal: it leaves the platform's own answer in
+	// place, which is what every release before this one ran with.
+	if err := system.UseTempDir(application.Mobile.StoragePath()); err != nil {
+		sLogger.Error("could not set up a temp directory", "err", err.Error())
+	}
+
 	// Start profiling server (pprof + trace). In production builds this
 	// is a no-op — the compiler eliminates all profiling code.
 	stopProfiler := profiling.Start(sLogger)

scripts/android-emulator.sh

@@ -276,8 +276,14 @@ cmd_logs() {
 	# The app's own tags plus the two that report its death.  Chasing a
 	# raw logcat here is hopeless: the emulator emits thousands of lines
 	# a second, almost all of them WindowManager transitions.
+	#
+	# `yellowjacket` is where the Go side's slog goes (backend/androidlog,
+	# #160).  It is a fixed tag rather than "$PKG", which is the whole
+	# point of it being fixed: the debug build's id carries a ".dev"
+	# suffix, so a tag derived from the id would be filtered out on the
+	# one build anybody debugging this app is running.
 	"$ADB" logcat -v time \
-		WailsBridge:V "$PKG":V GoLog:V AndroidRuntime:E DEBUG:V libc:F ActivityManager:I '*:S'
+		yellowjacket:V WailsBridge:V "$PKG":V GoLog:V AndroidRuntime:E DEBUG:V libc:F ActivityManager:I '*:S'
 }
 
 # Forward the WebView's devtools socket, so the page can be asked things.