yellowjacket/backend/androidlog/androidlog_test.go

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")
	}
}