From 36188ca9062b7b19e867aa7ed9af709cd3d7bfb2 Mon Sep 17 00:00:00 2001 From: pjay Date: Mon, 20 Apr 2026 17:58:41 +0700 Subject: [PATCH] test+refactor: real sidecar test, deterministic test sleeps, slog step line (#22) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * test(sidecar): replace assertTrue(true) placeholder with real server test MainTest.mainExists() always passed and inflated the green-check count. DriverServiceTest covers RPCs, but SidecarServer start/stop had no coverage. Drop the placeholder and add SidecarServerTest that binds to port 0, asserts a real ephemeral port, and stops cleanly. * test(agent): drop 50ms sleep before cancel in TestServer_AcceptCancelsOnContext Accept's closeListenerOnCancel watcher closes the listener as soon as ctx fires, regardless of whether the outer Accept has reached listener.Accept() yet. The sleep was a CI-flake surface (50ms is not enough on a slow runner), and dropping it still exercises the same outcome — Accept returns with ctx.Err() after cancellation. Stable across 50x -count runs. * test(agent): replace 2s sleep with done-chan in TestConn_SnapshotTimesOutIfSDKSilent The silent-SDK fake held the connection open via time.Sleep(2s), which coupled the test's wall clock to the server's 200ms snapshot-timeout assertion. Swap for a done channel closed by t.Cleanup — the goroutine exits when the test ends, independent of timing. * test(maestro): make WaitForHealth_PollsUntilReady deterministic Replace the 50ms wall-clock sleep that flipped healthReady with a healthReadyAfterCall counter in the fake server. The handler returns ready=true once healthCalls reaches the threshold, so the test's "at least 2 polls before ready" assertion is satisfied by call count rather than a race between the flip goroutine and the 25ms poll loop. * refactor(runner): route per-step progress through slog instead of fmt.Printf The runner already carries a *slog.Logger for warnings (logger.Warn on decode failures, predicate errors). The per-step status line was the outlier — a bare fmt.Printf that wrote to os.Stdout unconditionally, bypassing both the injected logger and any caller-configured writer. Switch it to logger.Info("step", "index", ..., "screen", ..., "nodes", ...). The caller (cmd/uatu) is responsible for wiring a logger whose handler renders to the right stream; the next commit adds that wiring. * feat(cli): render runner progress via a thin slog handler on stdout progressHandler writes Info records as "msg key=value ..." and prefixes warnings/errors with their level, matching the prose style of the surrounding CLI status prints. Wired into the runner via runner.Options.Logger so the per-step status line still lands on stdout without slog's default time= / level= framing. --- cmd/uatu/progress_logger.go | 52 +++++++++++++++++++ cmd/uatu/test_run.go | 1 + internal/agent/server_test.go | 7 +-- internal/driver/maestro/client_test.go | 23 ++++---- internal/runner/runner.go | 3 +- .../test/kotlin/dev/uatu/sidecar/MainTest.kt | 11 ---- .../dev/uatu/sidecar/SidecarServerTest.kt | 17 ++++++ 7 files changed, 88 insertions(+), 26 deletions(-) create mode 100644 cmd/uatu/progress_logger.go delete mode 100644 sidecar/src/test/kotlin/dev/uatu/sidecar/MainTest.kt create mode 100644 sidecar/src/test/kotlin/dev/uatu/sidecar/SidecarServerTest.kt diff --git a/cmd/uatu/progress_logger.go b/cmd/uatu/progress_logger.go new file mode 100644 index 0000000..b854525 --- /dev/null +++ b/cmd/uatu/progress_logger.go @@ -0,0 +1,52 @@ +package main + +import ( + "context" + "fmt" + "io" + "log/slog" + "strings" +) + +// newProgressLogger wires a slog.Logger that prints user-facing progress +// lines to the CLI's stdout stream. Info messages render as +// "msg key=value ..." to match the prose style of other CLI prints; +// warnings and errors get a "warn:" / "error:" prefix so they stand +// out in the same stream. +func newProgressLogger(writer io.Writer) *slog.Logger { + return slog.New(&progressHandler{writer: writer, level: slog.LevelInfo}) +} + +type progressHandler struct { + writer io.Writer + level slog.Level +} + +func (h *progressHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level +} + +func (h *progressHandler) Handle(_ context.Context, record slog.Record) error { + var builder strings.Builder + if record.Level >= slog.LevelWarn { + fmt.Fprintf(&builder, "%s: ", strings.ToLower(record.Level.String())) + } + builder.WriteString(record.Message) + record.Attrs(func(attr slog.Attr) bool { + fmt.Fprintf(&builder, " %s=%s", attr.Key, formatAttrValue(attr.Value)) + return true + }) + builder.WriteByte('\n') + _, err := io.WriteString(h.writer, builder.String()) + return err +} + +func (h *progressHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } +func (h *progressHandler) WithGroup(_ string) slog.Handler { return h } + +func formatAttrValue(value slog.Value) string { + if value.Kind() == slog.KindString { + return fmt.Sprintf("%q", value.String()) + } + return value.String() +} diff --git a/cmd/uatu/test_run.go b/cmd/uatu/test_run.go index a5e763e..fc11dd9 100644 --- a/cmd/uatu/test_run.go +++ b/cmd/uatu/test_run.go @@ -181,6 +181,7 @@ func runTestPipeline(ctx context.Context, options testOptions, stdout io.Writer) Driver: driverClient, Verifier: verifierInstance, TraceWriter: traceWriter, + Logger: newProgressLogger(stdout), }) terminateCtx, terminateCancel := context.WithTimeout(context.Background(), 5*time.Second) diff --git a/internal/agent/server_test.go b/internal/agent/server_test.go index 11a5ab3..b71aa70 100644 --- a/internal/agent/server_test.go +++ b/internal/agent/server_test.go @@ -191,7 +191,6 @@ func TestServer_AcceptCancelsOnContext(t *testing.T) { acceptErr := make(chan error, 1) go func() { _, err := server.Accept(ctx); acceptErr <- err }() - time.Sleep(50 * time.Millisecond) cancel() select { @@ -321,12 +320,14 @@ func TestConn_SnapshotAfterAcceptContextCancel(t *testing.T) { func TestConn_SnapshotTimesOutIfSDKSilent(t *testing.T) { server := newLoopbackServer(t) + done := make(chan struct{}) + t.Cleanup(func() { close(done) }) go func() { client, _ := net.Dial("tcp", server.Addr().String()) defer client.Close() _ = WriteMessage(client, Hello("0.0.1", "android", "com.x")) - // Never respond to PAUSE. - time.Sleep(2 * time.Second) + // Never respond to PAUSE; stay alive until the test ends. + <-done }() ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) diff --git a/internal/driver/maestro/client_test.go b/internal/driver/maestro/client_test.go index 0e3b5a5..62b89ba 100644 --- a/internal/driver/maestro/client_test.go +++ b/internal/driver/maestro/client_test.go @@ -17,8 +17,9 @@ type fakeServer struct { driverpb.UnimplementedDriverServer mutex sync.Mutex - healthReady bool - healthCalls int + healthReady bool + healthCalls int + healthReadyAfterCall int launchedBundleID string launcherActivity string @@ -43,7 +44,11 @@ func (s *fakeServer) Health(_ context.Context, _ *driverpb.Empty) (*driverpb.Hea if s.healthError != nil { return nil, s.healthError } - return &driverpb.HealthStatus{Ready: s.healthReady, Version: "test", Platform: "android"}, nil + ready := s.healthReady + if s.healthReadyAfterCall > 0 && s.healthCalls >= s.healthReadyAfterCall { + ready = true + } + return &driverpb.HealthStatus{Ready: ready, Version: "test", Platform: "android"}, nil } func (s *fakeServer) Launch(_ context.Context, request *driverpb.LaunchRequest) (*driverpb.Empty, error) { @@ -144,25 +149,23 @@ func TestClient_HealthRoundTrip(t *testing.T) { func TestClient_WaitForHealth_PollsUntilReady(t *testing.T) { state := newHarness(t) + state.fake.mutex.Lock() state.fake.healthReady = false + state.fake.healthReadyAfterCall = 2 + state.fake.mutex.Unlock() client, err := Dial(state.address) if err != nil { t.Fatal(err) } defer client.Close() - go func() { - time.Sleep(50 * time.Millisecond) - state.fake.mutex.Lock() - state.fake.healthReady = true - state.fake.mutex.Unlock() - }() - ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() if err := client.WaitForHealth(ctx, 25*time.Millisecond); err != nil { t.Fatalf("WaitForHealth: %v", err) } + state.fake.mutex.Lock() + defer state.fake.mutex.Unlock() if state.fake.healthCalls < 2 { t.Errorf("expected at least 2 health polls, got %d", state.fake.healthCalls) } diff --git a/internal/runner/runner.go b/internal/runner/runner.go index 07136a5..e431e38 100644 --- a/internal/runner/runner.go +++ b/internal/runner/runner.go @@ -104,8 +104,7 @@ func Run(ctx context.Context, options Options) (Summary, error) { if screenErr != nil { logger.Warn("screen snapshot decode failed", "step", stepIndex, "err", screenErr) } - fmt.Printf("step %d: screen=%q hierarchy=%d nodes\n", - stepIndex, screen, treeSize) + logger.Info("step", "index", stepIndex, "screen", screen, "nodes", treeSize) verdicts := options.Verifier.EvaluateProperties() violations := violationNames(verdicts) for _, name := range violations { diff --git a/sidecar/src/test/kotlin/dev/uatu/sidecar/MainTest.kt b/sidecar/src/test/kotlin/dev/uatu/sidecar/MainTest.kt deleted file mode 100644 index b765c0e..0000000 --- a/sidecar/src/test/kotlin/dev/uatu/sidecar/MainTest.kt +++ /dev/null @@ -1,11 +0,0 @@ -package dev.uatu.sidecar - -import kotlin.test.Test -import kotlin.test.assertTrue - -class MainTest { - @Test - fun mainExists() { - assertTrue(true, "placeholder test; real tests land with DriverService") - } -} diff --git a/sidecar/src/test/kotlin/dev/uatu/sidecar/SidecarServerTest.kt b/sidecar/src/test/kotlin/dev/uatu/sidecar/SidecarServerTest.kt new file mode 100644 index 0000000..30aabd2 --- /dev/null +++ b/sidecar/src/test/kotlin/dev/uatu/sidecar/SidecarServerTest.kt @@ -0,0 +1,17 @@ +package dev.uatu.sidecar + +import kotlin.test.Test +import kotlin.test.assertTrue + +class SidecarServerTest { + @Test + fun startBindsEphemeralPortAndStopReleasesIt() { + val server = SidecarServer(port = 0, service = DriverService()) + val boundPort = server.start() + try { + assertTrue(boundPort > 0, "expected ephemeral port, got $boundPort") + } finally { + server.stop() + } + } +}