diff --git a/.pi/skills/yellowjacket-dev/references/android-tier.md b/.pi/skills/yellowjacket-dev/references/android-tier.md index 2037395..1af553a 100644 --- a/.pi/skills/yellowjacket-dev/references/android-tier.md +++ b/.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 diff --git a/backend/androidlog/android.go b/backend/androidlog/android.go new file mode 100644 index 0000000..6f4ae90 --- /dev/null +++ b/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 +#include +*/ +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) +} diff --git a/backend/androidlog/androidlog.go b/backend/androidlog/androidlog.go new file mode 100644 index 0000000..9a9c7ea --- /dev/null +++ b/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 +} diff --git a/backend/androidlog/androidlog_test.go b/backend/androidlog/androidlog_test.go new file mode 100644 index 0000000..d3865cb --- /dev/null +++ b/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") + } +} diff --git a/backend/player/buffered_streamer.go b/backend/player/buffered_streamer.go index 993286e..2408182 100644 --- a/backend/player/buffered_streamer.go +++ b/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{} diff --git a/backend/player/buffered_underrun_test.go b/backend/player/buffered_underrun_test.go new file mode 100644 index 0000000..ca26705 --- /dev/null +++ b/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 } diff --git a/backend/player/player.go b/backend/player/player.go index 1779438..2bc952d 100644 --- a/backend/player/player.go +++ b/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} diff --git a/loghandler_android.go b/loghandler_android.go new file mode 100644 index 0000000..0c83441 --- /dev/null +++ b/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) +} diff --git a/loghandler_default.go b/loghandler_default.go new file mode 100644 index 0000000..296db83 --- /dev/null +++ b/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}) +} diff --git a/main.go b/main.go index 067d8f2..b489659 100644 --- a/main.go +++ b/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) diff --git a/scripts/android-emulator.sh b/scripts/android-emulator.sh index 025b57c..a7453c0 100755 --- a/scripts/android-emulator.sh +++ b/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.