diff --git a/docs/phase-3-spotify-recipe.md b/docs/phase-3-spotify-recipe.md index 0de82c8..4ce8f16 100644 --- a/docs/phase-3-spotify-recipe.md +++ b/docs/phase-3-spotify-recipe.md @@ -54,7 +54,8 @@ Run it with: ``` The verbs are `launch`, `foreground`, `wait`, `wait_gone`, `tap`, `tap_if`, -`tap_row`, `type`, `key`, `back`, `home` and `sleep`. `tap exact "Pause"` +`tap_row`, `type`, `key`, `back`, `home` and `sleep`. A `wait` step may add +`retry N` (see below). `tap exact "Pause"` matches the whole text, not a substring. `tap_if` taps only when the text is already on screen, which lets one recipe cope with an app that remembers its last screen. `foreground` waits until the recipe's app is really in front, so a @@ -114,7 +115,7 @@ its own reason instead of a generic "element not found". ## Timeouts (FR-11) -`step_timeout: 20s` is the default per step, `total_timeout: 150s` bounds the +`step_timeout: 20s` is the default per step, `total_timeout: 420s` bounds the whole run. A step may name its own timeout (`wait "Search" 30s`). The engine checks the remaining budget before each step and stops when it runs out. Every `adb` call is already bounded by `adb.DefaultTimeout`. @@ -192,8 +193,23 @@ keyguard; reading the state first would say "unlocked" about a locked phone. | All acting commands refuse on a locked phone | **live, verified** (above) | | `artemis run spotify_play` refuses on a locked phone | **live, verified** (above) | | `spotify_play` plays the right song | **not yet run end to end** — see below | +| `spotify_play` picks the right row on the real results list | **live, verified** — `tapped row "Honky Tonk Women" at (540,878)` | | Spotify search reaches the result list | live (Home → Search → type → results) | +## Retrying a dropped tap + +A step can ask for the step above it to be pressed again: + +``` +- tap_row "{query}" 40s +- wait exact "Pause" 45s retry 3 +``` + +`retry N` is only allowed on a `wait` step, needs a step above it to repeat, and +never taps anything that was not matched by text. It exists because a busy phone +can deliver a tap and then not act on it. The retry only re-runs the step above, +so nothing else can be pressed by accident. + ## Live run log Six attempts, in order. Each failure was clean, named its screen and tapped @@ -220,12 +236,46 @@ nothing random — which is the point of the phase. screen shows: "Cancel", "App logo", "Settings", "Verify that it's you" ...`. Artemis did not touch the prompt, and it must not: it needs Sam's fingerprint or PIN, exactly like the lock screen. -6. **Still blocked** by the same prompt on the next attempt. +6. **Same prompt again**, until Sam cleared it. +7. **Through to the row, but no playback.** After the prompt was cleared the + recipe reached step 11 (`tap_row`) with every earlier step ok, and the run + log shows it chose exactly the right element: + `tapped row "Honky Tonk Women" at (540,878) from Honky Tonk Women / + Song • The Rolling Stones`. Only the last step failed: + `text "Pause" did not appear within 40s`, with the search results still on + screen. The tap was delivered (the dispatcher lists the Spotify window as the + touch target) and Spotify did nothing with it. +8. **Duration logging fixed, retry added.** `wait ... retry N` now re-runs the + step above and waits again. Steps 9–12 made four attempts each. +9. **A dropped tap is not the whole story.** With retries, `tap_if "Clear + search query"` reported ok four times and never cleared the box. A probe + showed typing no longer reached the app either (`input text "zz"` left the + field unchanged) and neither did taps on the tab bar, while `keyevent 3` + (HOME) still worked. The app was deaf to input while still drawing. +10. **It recovers on its own, then wedges again.** After a 75-second rest with + no dumps and no input, the screen had moved to Home — queued input had been + processed — so a fresh run was started immediately. It failed at + `tap "Search"`: the tap reported ok, the screen never left Home. + +### Diagnosis + +This is the phone, not the recipe. Spotify's UI thread is starved: the phone is +at `MemFree ~300MB` with 3.2GB of swap in use, load average ~4, and Spotify +sustains ~70% CPU. When it is in that state it accepts no input at all — not +injected taps, not injected keys — while `keyevent 3` (HOME, handled by the +system) still works, and it recovers only after minutes of quiet. A force-stop +would clear it, and that is a restart on Sam's phone, so it is not something +Artemis does on its own. + +Artemis made this worse than it needed to be: `uiautomator dump` starts a JVM on +the phone, and the wait helpers were polling every 400ms. `ui.PollInterval` is +now 1500ms, which cuts that load by roughly two thirds. ### What is left The live end-to-end run of `spotify_play` (Phase 3 DoD) has not completed. It -needs the phone unlocked and free of the biometric prompt, and then: +needs the phone's Spotify restarted — swipe it away from Recents, or force-stop +it — and the phone left awake and unlocked. Then: ```sh ./bin/artemis run spotify_play query="Rolling Stones Honky Tonk" diff --git a/internal/recipe/engine.go b/internal/recipe/engine.go index bc3664b..4a18314 100644 --- a/internal/recipe/engine.go +++ b/internal/recipe/engine.go @@ -96,14 +96,34 @@ func Run(r *adb.Runner, rec *Recipe, opts Options) *RunResult { w, h, _ := ui.ScreenSize(r) // best effort: bounds checking degrades gracefully deadline := started.Add(rec.TotalTimeout) - for i, step := range rec.Steps { - if remaining := time.Until(deadline); remaining <= 0 { - return fail(fmt.Errorf("recipe timed out after %s at step %d (%s)", rec.TotalTimeout, i+1, step.Verb)) - } - sr := executeStep(r, rec, step, i, params, w, h, deadline, logf) - res.Steps = append(res.Steps, sr) - if !sr.OK { - return fail(fmt.Errorf("step %d (%s %s) failed: %s", i+1, step.Verb, strings.Join(step.Args, " "), sr.Error)) + for i := 0; i < len(rec.Steps); i++ { + step := rec.Steps[i] + var sr StepResult + for attempt := 0; ; attempt++ { + if remaining := time.Until(deadline); remaining <= 0 { + return fail(fmt.Errorf("recipe timed out after %s at step %d (%s)", rec.TotalTimeout, i+1, step.Verb)) + } + sr = executeStep(r, rec, step, i, params, w, h, deadline, logf) + res.Steps = append(res.Steps, sr) + if sr.OK { + break + } + // A wait step with "retry N" presses the step above again: on a + // busy phone a tap can be delivered but never acted on, or dropped. + if attempt >= step.Retry { + return fail(fmt.Errorf("step %d (%s %s) failed: %s", i+1, step.Verb, strings.Join(step.Args, " "), sr.Error)) + } + if i == 0 { + return fail(fmt.Errorf("step %d: retry needs a step above it to repeat", i+1)) + } + logf(" step %d %s: retrying, pressing %s again", i+1, step.Verb, rec.Steps[i-1].Verb) + again := executeStep(r, rec, rec.Steps[i-1], i-1, params, w, h, deadline, logf) + res.Steps = append(res.Steps, again) + if !again.OK { + // The wait is the real failure; the repeat just could not run. + return fail(fmt.Errorf("step %d (%s %s) failed: %s; repeating %s failed too: %s", + i+1, step.Verb, strings.Join(step.Args, " "), sr.Error, rec.Steps[i-1].Verb, again.Error)) + } } } @@ -184,7 +204,7 @@ func executeStep(r *adb.Runner, rec *Recipe, step Step, index int, params map[st } return fmt.Errorf("%s never came to the foreground within %s (foreground=%s)", pkg, timeout, got) } - time.Sleep(400 * time.Millisecond) + time.Sleep(ui.PollInterval) } case "wait": @@ -269,6 +289,8 @@ func executeStep(r *adb.Runner, rec *Recipe, step Step, index int, params map[st } sr.OK = true + sr.Duration = time.Since(started) + sr.DurationMS = sr.Duration.Milliseconds() logf(" step %d %s %v: ok (%s)", sr.Index, step.Verb, args, sr.Duration.Round(time.Millisecond)) return sr } @@ -321,7 +343,7 @@ func tapRow(r *adb.Runner, rec *Recipe, query string, timeout time.Duration, w, } else { lastErr = err } - time.Sleep(500 * time.Millisecond) + time.Sleep(ui.PollInterval) } if lastErr == nil { lastErr = fmt.Errorf("no result row matches %q", query) diff --git a/internal/recipe/recipe.go b/internal/recipe/recipe.go index 35abec3..1897bb9 100644 --- a/internal/recipe/recipe.go +++ b/internal/recipe/recipe.go @@ -31,6 +31,9 @@ // - launch start the recipe's app // - foreground 30s wait until the recipe's app is in front // - wait "Search" 30s wait for an element whose text matches +// - wait exact "Pause" 60s retry 3 +// if it never appears, re-run the step above and +// wait again (a busy phone can drop a tap) // - wait_gone "Recents" 30s wait until no element matches the text // - tap "Search" tap the element whose text matches (FR-4) // - tap exact "Pause" tap an element whose text matches exactly @@ -50,6 +53,7 @@ import ( "os" "path/filepath" "sort" + "strconv" "strings" "time" ) @@ -80,7 +84,10 @@ type Step struct { Args []string Exact bool Timeout time.Duration - Line int + // Retry, on a wait step, re-runs the preceding step and waits again, up to + // this many extra times. A busy phone can drop a tap. + Retry int + Line int } // Defaults used when a recipe does not set its own timeouts. @@ -312,6 +319,26 @@ func parseStep(body string, lineNo int) (*Step, error) { args = args[1:] } + // "retry N" is pulled out first, so the timeout can still be the last word. + for i := 0; i < len(args); i++ { + if !strings.EqualFold(args[i], "retry") { + continue + } + if i+1 >= len(args) { + return nil, fmt.Errorf("line %d: retry needs a number, as in retry 3", lineNo) + } + n, err := strconv.Atoi(args[i+1]) + if err != nil || n < 1 { + return nil, fmt.Errorf("line %d: retry needs a positive number, got %q", lineNo, args[i+1]) + } + if verb != "wait" { + return nil, fmt.Errorf("line %d: retry is only allowed on a wait step", lineNo) + } + step.Retry = n + args = append(args[:i], args[i+2:]...) + break + } + // A trailing duration is the step timeout, except for sleep where the // duration is the step itself. if !spec.durArg && len(args) > spec.min { diff --git a/internal/recipe/recipe_test.go b/internal/recipe/recipe_test.go index b821979..5aa023e 100644 --- a/internal/recipe/recipe_test.go +++ b/internal/recipe/recipe_test.go @@ -172,6 +172,9 @@ func TestSpotifyRecipeIsValid(t *testing.T) { if last.Verb != "wait" || last.Args[0] != "Pause" { t.Fatalf("the last step must confirm playback, got %+v", last) } + if last.Retry < 1 { + t.Fatal("the playback check must be allowed to press the row again") + } } func TestLoadAndList(t *testing.T) { @@ -205,6 +208,38 @@ func TestLoadAndList(t *testing.T) { } } +func TestRetryOnWait(t *testing.T) { + rec, err := Parse("steps:\n - tap_row \"{query}\" 40s\n - wait exact \"Pause\" 45s retry 3\n") + if err != nil { + t.Fatalf("Parse: %v", err) + } + wait := rec.Steps[1] + if wait.Retry != 3 || wait.Timeout != 45*time.Second || !wait.Exact || wait.Args[0] != "Pause" { + t.Fatalf("retry wait step = %+v", wait) + } + // retry without a duration still works. + rec, err = Parse("steps:\n - tap_row \"x\"\n - wait \"Pause\" retry 2\n") + if err != nil { + t.Fatalf("Parse: %v", err) + } + if rec.Steps[1].Retry != 2 || rec.Steps[1].Timeout != 0 { + t.Fatalf("retry step = %+v", rec.Steps[1]) + } +} + +func TestRetryRejectsBadUse(t *testing.T) { + for name, src := range map[string]string{ + "on a tap": "steps:\n - tap \"x\" retry 3\n", + "no number": "steps:\n - tap_row \"x\"\n - wait \"y\" retry\n", + "zero": "steps:\n - tap_row \"x\"\n - wait \"y\" retry 0\n", + "not a number": "steps:\n - tap_row \"x\"\n - wait \"y\" retry soon\n", + } { + if _, err := Parse(src); err == nil { + t.Errorf("%s: expected a parse error", name) + } + } +} + func TestForegroundStep(t *testing.T) { rec, err := Parse("app: com.spotify.music\nsteps:\n - launch\n - foreground 30s\n") if err != nil { diff --git a/internal/ui/actions.go b/internal/ui/actions.go index 4d68d0e..2e08a35 100644 --- a/internal/ui/actions.go +++ b/internal/ui/actions.go @@ -11,6 +11,13 @@ import ( "gitea.lab.audasmedia.com.au/sam/artemis_control/internal/adb" ) +// PollInterval is how long the wait helpers sleep between screen dumps. +// +// A dump runs a whole uiautomator JVM on the phone, which is expensive on a +// loaded device: polling every 400ms starves the very app Artemis is driving. +// A slower poll costs a moment of latency and keeps the phone responsive. +const PollInterval = 1500 * time.Millisecond + // Android key events we use. const ( KeyHome = 3 @@ -173,7 +180,7 @@ func WaitForText(r *adb.Runner, query string, exact bool, timeout time.Duration) } } } - time.Sleep(400 * time.Millisecond) + time.Sleep(PollInterval) } if len(seen) > 0 { return nil, fmt.Errorf("text %q is on screen but no enabled match could be tapped", query) @@ -194,7 +201,7 @@ func WaitForNoText(r *adb.Runner, query string, exact bool, timeout time.Duratio if err == nil && len(h.FindText(query, exact)) == 0 { return nil } - time.Sleep(400 * time.Millisecond) + time.Sleep(PollInterval) } return fmt.Errorf("text %q was still on screen after %s", query, timeout) } diff --git a/recipes/spotify_play.recipe b/recipes/spotify_play.recipe index c8f979f..b58a9a2 100644 --- a/recipes/spotify_play.recipe +++ b/recipes/spotify_play.recipe @@ -19,7 +19,7 @@ param: query row_id: com.spotify.music:id/row_root step_timeout: 20s -total_timeout: 150s +total_timeout: 420s # Screens Artemis must never tap on. Each one fails the run with the reason, so # a wrong tap is impossible (FR-8). @@ -36,14 +36,16 @@ steps: # no-op, so this is safe to repeat. - launch - foreground 30s - - wait "Search" 30s + - wait "Search" 30s retry 2 # 2. Open the search tab. Spotify remembers the last tab, so a search screen # with the previous query can come back: clear that box only when the # clear button is actually on screen. - tap "Search" - tap_if "Clear search query" - - wait "What do you want to listen to?" 30s + # retry: the clear tap above can be dropped while the phone is busy, so press + # it again before giving up on the empty search box. + - wait "What do you want to listen to?" 30s retry 3 - tap "What do you want to listen to?" # 3. Type the query. The clear button proves the text landed. @@ -54,11 +56,20 @@ steps: # never match something from the history instead of a search result. - wait_gone "Recents" 30s - # 5. Play the result that matches the query. tap_row scores every visible + # 5. Give the app a moment. Spotify renders the results list after the query + # lands, and the tap below must land on the settled list. + - sleep 1s + + # 6. Play the result that matches the query. tap_row scores every visible # result row against the query words and taps the best one; equal matches # go to the highest row, which is how Spotify ranks them. - tap_row "{query}" 40s - # 6. Playback started when the transport button says "Pause". Exact match, so + # 7. Playback started when the transport button says "Pause". Exact match, so # Spotify's "Paused" labels do not count. - - wait exact "Pause" 40s + # + # This is the phone's slowest moment: the app is rendering a new list and + # can stop answering input for a while, so a tap can be dropped. "retry 3" + # presses the row again and waits, up to three more times. It never taps + # anything it did not match by text. + - wait exact "Pause" 45s retry 3