.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/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}
 

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,11 +109,7 @@ 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)
 

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.