Files
sanderling/internal/runner/runner.go
T
pj 69002b07b1 fix(runner,sample-app): surface silent errors and demo a failing property (#15)
* fix(runner): surface non-deadline WaitForIdle errors

Previously the WaitForIdle return value was discarded entirely, hiding
real driver failures (gRPC transport errors, sidecar crashes) behind
the expected deadline-exceeded case. Log non-deadline errors so they
are visible without changing control flow.

* chore(sample-app): drop unused uptime_millis extractor

Registered in SampleApplication but never consumed by spec.ts.

* fix(sample-app): drop trivial appIsRunning property

app_state was hardcoded to 'running' so the property was a tautology
that could never fail. Removing both the extractor and the property
is the simplest fix; demo-grade properties that can fail land next.

* feat(sample-app): add Reset button that zeroes clickCount

Pairs with the next commit's tap-reset action so the fuzzer can
violate clickCountNeverDecreases and demonstrate uatu actually
finding a property violation.

* feat(sample-app): add tap-reset action to exercise Reset button

Weighted at 10/122, fuzzer reaches it within a short run. Pairs with
the Reset button to demonstrate uatu detecting the
clickCountNeverDecreases violation.

* fix(runner): filter WaitForIdle errors via context state, not errors.Is

errors.Is(err, context.DeadlineExceeded) misses gRPC's wrapped
status.DeadlineExceeded, so every step under the maestro driver
logged a spurious warning. Check idleCtx.Err() instead — captures
both deadline-fired and parent-canceled cases regardless of how the
driver wraps them.

* chore(sample-app): tune action weights so demo violates in ~30s

Prior weights left tap-reset rare enough that short demo runs missed
the violation by chance. Bumped to 30/107, with typeUsername reduced
since username noise doesn't help exercise clickCount.

* refactor(runner): route warnings through slog

Adds Options.Logger (defaults to slog.Default()) and converts the
three warning sites that were using fmt.Printf. Progress line stays
on Printf since it's user-facing UI, not a log. Makes the warnings
testable via a capturing handler.

* test(runner): assert WaitForIdle driver errors are logged

Captures slog output via TextHandler into a buffer and asserts the
warning message + injected error text appear when the mock driver
returns a non-context error from WaitForIdle. Guards against a
regression of the silent-error swallow.
2026-04-18 18:48:25 +07:00

266 lines
7.3 KiB
Go

package runner
import (
"context"
"encoding/json"
"errors"
"fmt"
"log/slog"
"time"
"github.com/priyanshujain/uatu/internal/agent"
"github.com/priyanshujain/uatu/internal/driver"
"github.com/priyanshujain/uatu/internal/hierarchy"
"github.com/priyanshujain/uatu/internal/ltl"
"github.com/priyanshujain/uatu/internal/trace"
"github.com/priyanshujain/uatu/internal/verifier"
)
type Options struct {
Duration time.Duration
SnapshotTimeout time.Duration
IdleTimeout time.Duration
Connection *agent.Conn
Driver driver.Driver
Verifier *verifier.Verifier
TraceWriter *trace.Writer
Logger *slog.Logger
}
type Summary struct {
StartTime time.Time
EndTime time.Time
Steps int
Violations []ViolationRecord
}
type ViolationRecord struct {
StepIndex int
Properties []string
}
// Run drives the snapshot/evaluate/release/act loop until the duration
// elapses or the context is canceled. The caller is responsible for
// launching the app and connecting the SDK before Run is called, and for
// terminating the app afterwards.
func Run(ctx context.Context, options Options) (Summary, error) {
if err := validate(options); err != nil {
return Summary{}, err
}
logger := options.Logger
if logger == nil {
logger = slog.Default()
}
summary := Summary{StartTime: time.Now()}
deadline := summary.StartTime.Add(options.Duration)
stepIndex := 0
for time.Now().Before(deadline) {
if err := ctx.Err(); err != nil {
break
}
stepIndex++
stepStart := time.Now()
// Fetch hierarchy BEFORE pausing the SDK: uiautomator dump calls
// waitForIdle internally, and the SDK's Choreographer-held pause
// stalls the main thread, so dumping during the pause yields the
// pre-pause (stale) tree. Doing this first also means the spec sees
// a hierarchy that matches the snapshots captured a moment later.
tree, hierarchyErr := fetchHierarchy(ctx, options.Driver)
if hierarchyErr != nil {
logger.Warn("hierarchy fetch failed", "step", stepIndex, "err", hierarchyErr)
}
treeSize := 0
if tree != nil {
treeSize = len(tree.Elements)
}
snapshot, err := snapshotStep(ctx, options)
if err != nil {
return summary, fmt.Errorf("step %d snapshot: %w", stepIndex, err)
}
if err := options.Verifier.PushSnapshot(verifier.Snapshots(snapshot.Snapshots), tree); err != nil {
return summary, fmt.Errorf("step %d push: %w", stepIndex, err)
}
screen, screenErr := screenFromSnapshot(snapshot.Snapshots)
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)
verdicts := options.Verifier.EvaluateProperties()
violations := violationNames(verdicts)
nextAction, nextErr := options.Verifier.NextAction()
var traceAction *trace.Action
if nextErr == nil {
traceAction = traceActionFor(nextAction)
} else if !errors.Is(nextErr, verifier.ErrNoAction) {
return summary, fmt.Errorf("step %d next action: %w", stepIndex, nextErr)
}
step := trace.Step{
Index: stepIndex,
Timestamp: stepStart,
Screen: screen,
Snapshots: snapshot.Snapshots,
Action: traceAction,
Violations: violations,
}
if err := options.TraceWriter.WriteStep(step); err != nil {
return summary, fmt.Errorf("step %d trace: %w", stepIndex, err)
}
summary.Steps = stepIndex
if len(violations) > 0 {
summary.Violations = append(summary.Violations, ViolationRecord{
StepIndex: stepIndex,
Properties: violations,
})
}
if err := options.Connection.Release(ctx); err != nil {
return summary, fmt.Errorf("step %d release: %w", stepIndex, err)
}
if nextErr == nil {
if err := applyAction(ctx, options.Driver, nextAction, tree); err != nil {
return summary, fmt.Errorf("step %d apply: %w", stepIndex, err)
}
}
idleCtx, idleCancel := context.WithTimeout(ctx, options.IdleTimeout)
idleErr := options.Driver.WaitForIdle(idleCtx, options.IdleTimeout)
if idleErr != nil && idleCtx.Err() == nil {
logger.Warn("wait_for_idle failed", "step", stepIndex, "err", idleErr)
}
idleCancel()
}
summary.EndTime = time.Now()
return summary, nil
}
func validate(options Options) error {
if options.Connection == nil {
return errors.New("runner: Connection is required")
}
if options.Driver == nil {
return errors.New("runner: Driver is required")
}
if options.Verifier == nil {
return errors.New("runner: Verifier is required")
}
if options.TraceWriter == nil {
return errors.New("runner: TraceWriter is required")
}
if options.Duration <= 0 {
return errors.New("runner: Duration must be positive")
}
if options.SnapshotTimeout <= 0 {
options.SnapshotTimeout = 5 * time.Second
}
if options.IdleTimeout <= 0 {
options.IdleTimeout = 2 * time.Second
}
return nil
}
func snapshotStep(ctx context.Context, options Options) (agent.Message, error) {
snapshotTimeout := options.SnapshotTimeout
if snapshotTimeout <= 0 {
snapshotTimeout = 5 * time.Second
}
snapshotCtx, snapshotCancel := context.WithTimeout(ctx, snapshotTimeout)
defer snapshotCancel()
return options.Connection.Snapshot(snapshotCtx)
}
func violationNames(verdicts map[string]ltl.Verdict) []string {
var names []string
for name, verdict := range verdicts {
if verdict == ltl.VerdictViolated {
names = append(names, name)
}
}
return names
}
func screenFromSnapshot(snapshots map[string]json.RawMessage) (string, error) {
raw, ok := snapshots["screen"]
if !ok {
return "", nil
}
var screen string
if err := json.Unmarshal(raw, &screen); err != nil {
return "", err
}
return screen, nil
}
func applyAction(ctx context.Context, drv driver.Driver, action verifier.Action, tree *hierarchy.Tree) error {
switch action.Kind {
case verifier.ActionKindTap:
x, y, ok := resolveCoordinates(action, tree)
if !ok {
if action.On == "" {
return nil
}
return drv.TapSelector(ctx, action.On)
}
return drv.Tap(ctx, x, y)
case verifier.ActionKindInputText:
if x, y, ok := resolveCoordinates(action, tree); ok {
if err := drv.Tap(ctx, x, y); err != nil {
return err
}
} else if action.On != "" {
if err := drv.TapSelector(ctx, action.On); err != nil {
return err
}
}
return drv.InputText(ctx, action.Text)
default:
return fmt.Errorf("unknown action kind %q", action.Kind)
}
}
func resolveCoordinates(action verifier.Action, tree *hierarchy.Tree) (int, int, bool) {
if action.X > 0 && action.Y > 0 {
return action.X, action.Y, true
}
if tree != nil && action.On != "" {
if element := tree.Find(action.On); element != nil {
x, y := element.Bounds.Center()
if x > 0 && y > 0 {
return x, y, true
}
}
}
return 0, 0, false
}
func fetchHierarchy(ctx context.Context, drv driver.Driver) (*hierarchy.Tree, error) {
xmlText, err := drv.Hierarchy(ctx)
if err != nil {
return nil, err
}
return hierarchy.Parse(xmlText)
}
func traceActionFor(action verifier.Action) *trace.Action {
traceAction := &trace.Action{Kind: string(action.Kind)}
switch action.Kind {
case verifier.ActionKindTap:
// Selector lives in the trace step's action.text field for now —
// trace.Action only has X/Y/Text and we don't resolve coordinates
// at the runner layer.
traceAction.Text = action.On
case verifier.ActionKindInputText:
traceAction.Text = action.Text
}
return traceAction
}