feat(android): route slog to logcat
Every slog line the app wrote on Android went to /dev/null, including the one naming the error it was 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 sLogger.Error main.go was already writing. backend/androidlog is a slog.Handler over __android_log_write, chosen in main() by build tag rather than by a runtime check so that a desktop binary links no cgo for a platform it cannot run on. **Everything except the write itself is untagged.** That is androidpayload.go's discipline pushed as far as it goes: the only toolchain that compiles the android tag is a cross-compiler and the only thing that runs it is a phone, so the priority mapping, the formatting, the chunking and the handler's own attr and group bookkeeping are ordinary Go that `go test` exercises everywhere, and android.go is fifteen lines that hand a string to liblog. Four things in it are load-bearing. **The tag is a fixed string, not the application id.** 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 is a different tag on the one build anybody debugging this app is running, and the filter meant to show these lines would hide them exactly where they were being looked for. **The priorities are android/log.h's own values, asserted twice.** android.go carries constant expressions that do not compile as uint if the header renumbers; the untagged test writes the six numbers out longhand, because comparing a constant to itself passes on any renumbering. A wrong priority is the failure that hides rather than breaks -- logcat prints whatever number it is handed, so an Error filed as Info is present, correct, and invisible to every filter. **Formatting is delegated to slog's TextHandler.** 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. The derived handlers share the parent's buffer *and its mutex*: a second mutex would guard nothing, and two loggers derived from one would splice their bytes into a single line under load. **A line is chunked, because liblog drops what does not fit.** The kernel logger's entry is 4068 bytes for tag and message together and the remainder goes without comment, so a long record would be truncated in the middle of the thing worth reading. Time and level are dropped from the formatted line, since logcat stamps every entry with both -- and dropping them by *key* also ate a caller's own "level" attribute, which the on-device probe caught and TestACallersOwnLevelAttrSurvives now holds. ReplaceAttr sees an empty group path for the built-ins and for every top-level attribute alike, so the kinds are what separate them. Verified on the reference device (TLP301, Android 14): a debug build logs I/W/E under the `yellowjacket` tag at the right priorities, and the first thing it surfaced was a real warning nobody could previously see -- `champion index rebuild failed ... disk I/O error (6410)`. Closes #160
This commit is contained in:
@@ -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
|
||||
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
@@ -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
|
||||
}
|
||||
@@ -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")
|
||||
}
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
@@ -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})
|
||||
}
|
||||
@@ -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)
|
||||
|
||||
|
||||
@@ -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.
|
||||
|
||||
Reference in New Issue
Block a user