diff --git a/CHANGELOG.md b/CHANGELOG.md index ddfda590..744d0e31 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,11 +8,17 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] ### Fixed -- **WDA keeps enough idle connections for its own parallel reads.** The driver reads an element's name, rect, text and displayed at once, and a tap looks an element up four ways at once, but Go's default transport keeps two idle connections per host, so every burst closed two connections and opened two new ones. Through a forwarded port to a physical iPhone, new connections opened together fail with EOF and are sent again, which costs time on every step. The WDA client now keeps up to eight. +- **WDA keeps enough idle connections for its own parallel reads.** The driver reads an element's name, rect, text and displayed at once, and a tap looks an element up four ways at once, but Go's default transport keeps two idle connections per host, so every burst closed two connections and opened two new ones. Through a forwarded port to a physical iPhone, new connections opened together fail with EOF, which costs time on every step. The WDA client now keeps up to eight. - **`retry` counts retries, not attempts, as Maestro does.** `maxRetries: 1` now runs the commands twice (once, then one retry), an unset `maxRetries` means one retry, and the value is capped at 3. The runner ran exactly `maxRetries` attempts, three when unset and with no cap, so `maxRetries: 1` never retried. A value that is not an integer is logged and read as 1 instead of failing the step. - **WDA `launchApp` restarts a running app unless `stopApp: false`, as Maestro does.** It only activated the running app, so a relaunch left the app on the screen it was already on, and a flow checking what survives a restart restarted nothing. - **WDA `notVisible` passes only when a lookup finds the element absent.** `assertNotVisible` and `extendedWaitUntil: notVisible` treated any failed lookup, such as an unreadable page source or a dropped connection, as the element being gone, so they could pass without the screen being looked at. Other errors are now retried until the timeout, and then fail the step. - **`checked` selectors work on iOS.** The iOS drivers dropped `checked` with a warning, so `checked: true` matched a switch in either state. WDA now derives checked from a CheckBox, Switch or Toggle whose value is 1, as Maestro does, and filters on it on every path (tap, assert, relative). +- **`runScript` runs a script file as written, as Maestro does.** The runner expanded `${...}` across the whole file before running it, so a template literal that used the script's own variables, such as `${encodeURIComponent(email)}`, was replaced ahead of the script, against variables that did not exist yet, and came out as `undefined`. A script file now runs as plain JavaScript. Inline script text keeps its `${...}` expansion. +- **A `runFlow`, `retry` or sub-flow `env` no longer leaves its keys behind, as in Maestro.** The runner put each key back to its old value, but a key that had none was set to an empty string instead of being removed, so after `runFlow` with `env: {KEY: ...}` the name stayed defined: `typeof KEY` was `"string"`, `$KEY` expanded to nothing, and `runShell` saw `KEY=""`. A key the block added is now removed when it ends. +- **A script's `http` call waits up to 5 minutes, as in Maestro.** Maestro's script client allows a call 5 minutes. The runner gave up after 30 seconds unless the call set `timeout`, so a script that calls a slow endpoint, such as one that seeds test data, failed with `HTTP request failed` where Maestro waits. A call without a `timeout` option now gets 5 minutes, and the option still wins. +- **WDA sends a read or a lookup again when its connection drops.** Through a forwarded port to a physical iPhone, WDA sometimes closes a connection before it answers, and the request came back as EOF; one dropped text read made `copyTextFrom` copy an empty string. net/http does not send these again (it only repeats a GET on a connection it had used before). A GET, or a POST that only finds elements, is now sent once more, with a warning in the log. An action (a tap, typing, a swipe, launching an app) is never repeated, because it may have reached WDA before the connection went. +- **`when: true:` and `assertTrue` read their value as Maestro does.** Maestro reads the evaluated text as false only when it is blank, `false` in any case, `undefined`, `null` or zero, so `abc` is true. The runner took a string as true only when it was exactly `true`, so `assertTrue: ${name}` failed for any other value. A `when: true: ${name}` condition was worse: the value was run as JavaScript a second time, so `abc` became a ReferenceError, and an unset variable became an empty condition, which ran the branch Maestro skips. A condition that is one `${...}` is now evaluated once, and its value is read by Maestro's rule. +- **A failing `onFlowComplete` step fails the flow, as in Maestro.** The hook ran in a deferred call that ignored every failure, after the flow had already been reported, so a flow whose cleanup failed passed. It now runs before the result is final, also when `onFlowStart` failed. A failing step that is not optional ends the hook and fails a flow that had passed, and a flow that had already failed keeps its own error. The hook's steps are counted in the flow's totals, and a flow that fails in `onFlowStart` is a failed flow for `--video on-failure`, which had thrown its recording away. ## [1.1.28] - 2026-09-30 diff --git a/pkg/driver/uiautomator2/driver.go b/pkg/driver/uiautomator2/driver.go index baad23df..d34f3f76 100644 --- a/pkg/driver/uiautomator2/driver.go +++ b/pkg/driver/uiautomator2/driver.go @@ -1280,12 +1280,6 @@ func looksLikeRegex(text string) bool { return false } -// escapeUIAutomatorString escapes only the double quotes for UiAutomator string. -// Used when the text is already a regex pattern. -func escapeUIAutomatorString(s string) string { - return strings.ReplaceAll(s, `"`, `\"`) -} - // buildStateFilters returns UiSelector chain for state filters. // e.g., ".enabled(true).checked(false)" func buildStateFilters(sel flow.Selector) string { diff --git a/pkg/driver/wda/client.go b/pkg/driver/wda/client.go index 5078bc4e..d000568f 100644 --- a/pkg/driver/wda/client.go +++ b/pkg/driver/wda/client.go @@ -5,12 +5,14 @@ import ( "bytes" "encoding/base64" "encoding/json" + "errors" "fmt" "io" "net/http" "os" "strconv" "strings" + "syscall" "time" "github.com/devicelab-dev/maestro-runner/pkg/core" @@ -313,6 +315,26 @@ func (c *Client) ElementSendKeys(elementID, text string, frequency int) error { return err } +// isDroppedConnection reports a request that died on its connection before any +// response came back: an EOF, a reset or a broken pipe. Over a forwarded WDA port +// this happens. On a physical iPhone reached through usbmux and an SSH tunnel, WDA +// began dropping about one request in fourteen, 90 minutes into a run, each +// within about 10 ms and nearly all of them element reads sent in parallel; one +// such dropped text read made a copyTextFrom come back empty. net/http sends a +// request again by itself only when it is a GET on a connection that had been +// used before, so a fresh connection that is hung up on, and a POST, are not. +func isDroppedConnection(err error) bool { + return errors.Is(err, io.EOF) || errors.Is(err, io.ErrUnexpectedEOF) || + errors.Is(err, syscall.ECONNRESET) || errors.Is(err, syscall.EPIPE) +} + +// isLookupPath reports a POST that only finds elements, from the root or from an +// element (/element, /elements, /element/{id}/element(s)), so repeating it changes +// nothing on the device. +func isLookupPath(path string) bool { + return strings.HasSuffix(path, "/element") || strings.HasSuffix(path, "/elements") +} + // ElementClear clears an element's text. func (c *Client) ElementClear(elementID string) error { _, err := c.post(c.sessionPath(fmt.Sprintf("/element/%s/clear", elementID)), nil) @@ -631,6 +653,11 @@ func (c *Client) get(path string) (map[string]interface{}, error) { logger.Debug("WDA GET %s", path) resp, err := c.httpClient.Get(c.baseURL + path) + if err != nil && isDroppedConnection(err) { + // A read is safe to send twice. + logger.Warn("WDA GET %s: the connection dropped before a response (%v), sending it again", path, err) + resp, err = c.httpClient.Get(c.baseURL + path) + } duration := time.Since(start).Milliseconds() if err != nil { @@ -649,23 +676,35 @@ func (c *Client) get(path string) (map[string]interface{}, error) { func (c *Client) post(path string, body interface{}) (map[string]interface{}, error) { start := time.Now() - var reqBody io.Reader + var data []byte bodyStr := "" if body != nil { - data, err := json.Marshal(body) + var err error + data, err = json.Marshal(body) if err != nil { return nil, err } - reqBody = bytes.NewReader(data) bodyStr = string(data) if len(bodyStr) > 100 { bodyStr = bodyStr[:100] + "..." } } + newBody := func() io.Reader { + if data == nil { + return nil + } + return bytes.NewReader(data) + } logger.Debug("WDA POST %s body=%s", path, core.RedactTypedText(path, bodyStr)) - resp, err := c.httpClient.Post(c.baseURL+path, "application/json", reqBody) + resp, err := c.httpClient.Post(c.baseURL+path, "application/json", newBody()) + if err != nil && isDroppedConnection(err) && isLookupPath(path) { + // A lookup changes nothing, so it is as safe to repeat as a GET. An action is + // not sent twice: it may have reached WDA before the connection went. + logger.Warn("WDA POST %s: the connection dropped before a response (%v), sending it again", path, err) + resp, err = c.httpClient.Post(c.baseURL+path, "application/json", newBody()) + } duration := time.Since(start).Milliseconds() if err != nil { diff --git a/pkg/driver/wda/dropped_connection_test.go b/pkg/driver/wda/dropped_connection_test.go new file mode 100644 index 00000000..638f31eb --- /dev/null +++ b/pkg/driver/wda/dropped_connection_test.go @@ -0,0 +1,115 @@ +package wda + +import ( + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" +) + +// droppingServer closes the connection, with no response, on the first request to +// each path in drop; every later request is answered. +func droppingServer(t *testing.T, drop ...string) (*httptest.Server, func(string) int) { + t.Helper() + var mu sync.Mutex + seen := map[string]int{} + dropFirst := map[string]bool{} + for _, p := range drop { + dropFirst[p] = true + } + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + seen[r.URL.Path]++ + n := seen[r.URL.Path] + mu.Unlock() + if dropFirst[r.URL.Path] && n == 1 { + conn, _, err := w.(http.Hijacker).Hijack() + if err != nil { + t.Fatalf("hijack: %v", err) + } + _ = conn.Close() + return + } + w.Header().Set("Content-Type", "application/json") + switch { + case strings.HasSuffix(r.URL.Path, "/text"): + jsonResponse(w, map[string]interface{}{"value": "72.4"}) + case strings.HasSuffix(r.URL.Path, "/elements"): + jsonResponse(w, map[string]interface{}{"value": []interface{}{map[string]interface{}{"ELEMENT": "e1"}}}) + default: + jsonResponse(w, map[string]interface{}{"value": nil}) + } + })) + count := func(path string) int { + mu.Lock() + defer mu.Unlock() + return seen[path] + } + return server, count +} + +func testClient(server *httptest.Server) *Client { + return &Client{baseURL: server.URL, httpClient: http.DefaultClient, sessionID: "s"} +} + +// The measured failure: a text read whose connection dropped left copyTextFrom +// with an empty string. The read is now sent once more and gets its answer. +func TestGetIsSentAgainWhenItsConnectionDrops(t *testing.T) { + server, count := droppingServer(t, "/session/s/element/e1/text") + defer server.Close() + text, err := testClient(server).ElementText("e1") + if err != nil || text != "72.4" { + t.Fatalf("got %q, %v; want the text after one more try", text, err) + } + if n := count("/session/s/element/e1/text"); n != 2 { + t.Errorf("WDA saw the read %d times, want 2", n) + } +} + +func TestLookupIsSentAgainWhenItsConnectionDrops(t *testing.T) { + server, count := droppingServer(t, "/session/s/elements") + defer server.Close() + ids, err := testClient(server).FindElements("class chain", "**/XCUIElementTypeAny") + if err != nil || len(ids) != 1 { + t.Fatalf("got %v, %v; want the element after one more try", ids, err) + } + if n := count("/session/s/elements"); n != 2 { + t.Errorf("WDA saw the lookup %d times, want 2", n) + } +} + +// A tap may have reached WDA before the connection went, so it is never repeated: +// the error comes back and WDA saw it exactly once. +func TestActionIsNotSentAgainWhenItsConnectionDrops(t *testing.T) { + server, count := droppingServer(t, "/session/s/element/e1/click") + defer server.Close() + if err := testClient(server).ElementClick("e1"); err == nil { + t.Fatal("the tap reported success over a dropped connection") + } + if n := count("/session/s/element/e1/click"); n != 1 { + t.Errorf("WDA saw the tap %d times, want 1", n) + } +} + +// A request that fails twice fails: one more try, not a loop. +func TestGetIsTriedOnlyOnceMore(t *testing.T) { + var mu sync.Mutex + hits := 0 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + hits++ + mu.Unlock() + conn, _, _ := w.(http.Hijacker).Hijack() + _ = conn.Close() + })) + defer server.Close() + if _, err := testClient(server).ElementText("e1"); err == nil { + t.Fatal("a read that dropped twice reported success") + } + mu.Lock() + defer mu.Unlock() + if hits != 2 { + t.Errorf("WDA saw the read %d times, want 2", hits) + } +} diff --git a/pkg/executor/flow_hooks_test.go b/pkg/executor/flow_hooks_test.go new file mode 100644 index 00000000..fe94e359 --- /dev/null +++ b/pkg/executor/flow_hooks_test.go @@ -0,0 +1,209 @@ +package executor + +import ( + "context" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/devicelab-dev/maestro-runner/pkg/core" + "github.com/devicelab-dev/maestro-runner/pkg/flow" + "github.com/devicelab-dev/maestro-runner/pkg/report" +) + +func tapText(text string, optional bool) *flow.TapOnStep { + return &flow.TapOnStep{ + BaseStep: flow.BaseStep{StepType: flow.StepTapOn, Optional: optional}, + Selector: flow.Selector{Text: text}, + } +} + +// hookRun is what runHookFlow saw: the flow's result, every tap in order, and +// how many taps had run when the flow was reported as finished. +type hookRun struct { + result FlowResult + taps []string + tapsAtEnd int + passedAtEnd bool +} + +// runHookFlow runs one flow on a driver whose taps on "missing" fail and every +// other step passes. +func runHookFlow(t *testing.T, config flow.Config, body ...flow.Step) hookRun { + t.Helper() + var run hookRun + driver := &mockDriver{executeFunc: func(step flow.Step) *core.CommandResult { + if tap, ok := step.(*flow.TapOnStep); ok { + run.taps = append(run.taps, tap.Selector.Text) + if tap.Selector.Text == "missing" { + return &core.CommandResult{Success: false, Error: &testError{msg: "missing is not on screen"}} + } + } + return &core.CommandResult{Success: true} + }} + config.Name = "hooks" + runner := New(driver, RunnerConfig{ + OutputDir: t.TempDir(), + Artifacts: ArtifactNever, + Device: report.Device{ID: "test", Platform: "ios"}, + OnFlowEnd: func(_ string, passed bool, _ int64, _ string) { + run.tapsAtEnd = len(run.taps) + run.passedAtEnd = passed + }, + }) + result, err := runner.Run(context.Background(), []flow.Flow{{SourcePath: "test.yaml", Config: config, Steps: body}}) + if err != nil { + t.Fatalf("Run() error = %v", err) + } + run.result = result.FlowResults[0] + return run +} + +// Maestro fails a flow that passed when its onFlowComplete hook fails +// (Orchestra.kt:237-268). The runner ignored the hook, and ran it only after +// the flow had been reported. +func TestOnFlowComplete_FailingHookFailsAPassingFlow(t *testing.T) { + run := runHookFlow(t, flow.Config{OnFlowComplete: []flow.Step{tapText("missing", false)}}, tapText("body", false)) + + if run.result.Status != report.StatusFailed { + t.Fatalf("status = %v, want failed", run.result.Status) + } + if !strings.Contains(run.result.Error, "onFlowComplete failed") { + t.Errorf("error = %q, want it to name the onFlowComplete hook", run.result.Error) + } + if run.tapsAtEnd != 2 || run.passedAtEnd { + t.Errorf("the flow was reported (passed=%v) after %d of 2 taps: the hook must run first", run.passedAtEnd, run.tapsAtEnd) + } +} + +func TestOnFlowComplete_OptionalHookStepMayFail(t *testing.T) { + run := runHookFlow(t, flow.Config{OnFlowComplete: []flow.Step{tapText("missing", true), tapText("after", false)}}, tapText("body", false)) + + if run.result.Status != report.StatusPassed { + t.Errorf("status = %v, want passed: the failing hook step is optional", run.result.Status) + } + if strings.Join(run.taps, ",") != "body,missing,after" { + t.Errorf("taps = %v, want the hook to carry on past its optional step", run.taps) + } +} + +// Maestro's executeCommands stops at the hook's first failing step. +func TestOnFlowComplete_StopsAtItsFirstFailure(t *testing.T) { + run := runHookFlow(t, flow.Config{OnFlowComplete: []flow.Step{tapText("missing", false), tapText("after", false)}}, tapText("body", false)) + + if strings.Join(run.taps, ",") != "body,missing" { + t.Errorf("taps = %v, want the hook to stop at its failing step", run.taps) + } +} + +// A flow that already failed keeps its own error, and the hook still runs. +func TestOnFlowComplete_BodyFailureKeepsItsError(t *testing.T) { + run := runHookFlow(t, flow.Config{OnFlowComplete: []flow.Step{tapText("cleanup", false)}}, tapText("missing", false)) + + if run.result.Status != report.StatusFailed { + t.Fatalf("status = %v, want failed", run.result.Status) + } + if strings.Contains(run.result.Error, "onFlowComplete") || !strings.Contains(run.result.Error, "missing is not on screen") { + t.Errorf("error = %q, want the body's failure", run.result.Error) + } + if strings.Join(run.taps, ",") != "missing,cleanup" || run.tapsAtEnd != 2 { + t.Errorf("taps = %v (%d before the report), want the hook to run before the flow is reported", run.taps, run.tapsAtEnd) + } +} + +// When onFlowStart fails, Maestro skips the body, still runs onFlowComplete, +// and fails the flow with the onFlowStart error. +func TestOnFlowStart_FailureStillRunsOnFlowCompleteFirst(t *testing.T) { + run := runHookFlow(t, flow.Config{ + OnFlowStart: []flow.Step{tapText("missing", false)}, + OnFlowComplete: []flow.Step{tapText("cleanup", false)}, + }, tapText("body", false)) + + if run.result.Status != report.StatusFailed || !strings.Contains(run.result.Error, "onFlowStart failed") { + t.Fatalf("status = %v, error = %q: want failed by onFlowStart", run.result.Status, run.result.Error) + } + if strings.Join(run.taps, ",") != "missing,cleanup" { + t.Errorf("taps = %v, want the body skipped and onFlowComplete run", run.taps) + } + if run.tapsAtEnd != 2 { + t.Errorf("the flow was reported after %d of 2 taps: onFlowComplete must run first", run.tapsAtEnd) + } +} + +// A step that panics still leaves onFlowComplete to run, as Maestro runs the +// hook in a finally. +func TestOnFlowComplete_RunsAfterAPanic(t *testing.T) { + var taps []string + driver := &mockDriver{executeFunc: func(step flow.Step) *core.CommandResult { + tap, ok := step.(*flow.TapOnStep) + if ok && tap.Selector.Text == "body" { + panic("nil pointer dereference in a dependency") + } + if ok { + taps = append(taps, tap.Selector.Text) + } + return &core.CommandResult{Success: true} + }} + result := runOneFlow(t, driver, flow.Flow{ + SourcePath: "crash.yaml", + Config: flow.Config{Name: "crashing flow", OnFlowComplete: []flow.Step{tapText("cleanup", false)}}, + Steps: []flow.Step{tapText("body", false)}, + }) + + if result.Status != report.StatusFailed { + t.Errorf("status = %v, want failed", result.Status) + } + if strings.Join(taps, ",") != "cleanup" { + t.Errorf("taps = %v, want the onFlowComplete tap to have run", taps) + } +} + +// recordingDriver can record the screen; the recording is a file at the +// target the runner asks for. +type recordingDriver struct { + *mockDriver + target string +} + +func (d *recordingDriver) StartScreenRecording() error { return nil } + +func (d *recordingDriver) StopScreenRecording(target string) error { + d.target = target + if err := os.MkdirAll(filepath.Dir(target), 0o755); err != nil { + return err + } + return os.WriteFile(target, []byte("mp4"), 0o644) +} + +// A flow that fails in onFlowStart is a failed flow for --video on-failure +// too. Its status stayed "passed" there, so its recording was thrown away. +func TestOnFlowStart_FailureKeepsAnOnFailureRecording(t *testing.T) { + driver := &recordingDriver{mockDriver: &mockDriver{executeFunc: func(flow.Step) *core.CommandResult { + return &core.CommandResult{Success: false, Error: &testError{msg: "not there"}} + }}} + runner := New(driver, RunnerConfig{ + OutputDir: t.TempDir(), + Artifacts: ArtifactNever, + Device: report.Device{ID: "test", Platform: "ios"}, + Record: true, + RecordMode: "on-failure", + }) + result, err := runner.Run(context.Background(), []flow.Flow{{ + SourcePath: "test.yaml", + Config: flow.Config{Name: "start fails", OnFlowStart: []flow.Step{tapText("missing", false)}}, + Steps: []flow.Step{tapText("body", false)}, + }}) + if err != nil { + t.Fatalf("Run() error = %v", err) + } + if result.Status != report.StatusFailed { + t.Fatalf("status = %v, want failed", result.Status) + } + if driver.target == "" { + t.Fatal("the recording was never stopped") + } + if _, err := os.Stat(driver.target); err != nil { + t.Errorf("the failed flow's recording was discarded: %v", err) + } +} diff --git a/pkg/executor/flow_runner.go b/pkg/executor/flow_runner.go index a9cb8f3a..95edae80 100644 --- a/pkg/executor/flow_runner.go +++ b/pkg/executor/flow_runner.go @@ -178,8 +178,8 @@ func (fr *FlowRunner) Run() FlowResult { // starts, whether it will be wanted. flowStatus := report.StatusPassed - // --record: capture the whole flow, onFlowComplete hooks included — this - // defer is registered before theirs, so it runs after them. Best-effort + // --record: capture the whole flow, onFlowComplete hooks included. This + // defer runs when Run returns, after the hooks. Best-effort // throughout: a driver that can't record must not fail the flow. if fr.config.Record { if recorder, ok := innerDriver.(core.ScreenRecorder); ok { @@ -220,12 +220,13 @@ func (fr *FlowRunner) Run() FlowResult { // Execute all steps var flowError string - // Execute onFlowComplete in defer (runs even on failure) + // onFlowComplete runs before the result is final, below. When a panic + // skips that, it still runs here, as Maestro runs it in a finally + // (Orchestra.kt:236-272). + flowCompleteRan := false defer func() { - if len(fr.flow.Config.OnFlowComplete) > 0 { - for _, step := range fr.flow.Config.OnFlowComplete { - fr.executeNestedStep(step) // Ignore failures in cleanup - } + if !flowCompleteRan { + fr.runFlowCompleteHooks() } }() @@ -236,6 +237,11 @@ func (fr *FlowRunner) Run() FlowResult { if !result.Success && !step.IsOptional() { // onFlowStart failed - fail the flow errMsg := fmt.Sprintf("onFlowStart failed: %v", result.Error) + flowStatus = report.StatusFailed + // onFlowComplete still runs, as in Maestro, and the flow + // keeps this error whatever the hook does. + flowCompleteRan = true + fr.runFlowCompleteHooks() fr.flowWriter.End(report.StatusFailed, errMsg) if fr.config.OnFlowEnd != nil { fr.config.OnFlowEnd(flowName, false, time.Since(flowStart).Milliseconds(), errMsg) @@ -327,6 +333,15 @@ func (fr *FlowRunner) Run() FlowResult { } } + // onFlowComplete runs before the result is final. As in Maestro + // (Orchestra.kt:236-272), a failing hook fails a flow that had passed, + // and a flow that had failed keeps its own error. + flowCompleteRan = true + if hookErr := fr.runFlowCompleteHooks(); hookErr != "" && flowStatus == report.StatusPassed { + flowStatus = report.StatusFailed + flowError = hookErr + } + // Pull console / page error entries from the driver (web only). // Any driver that exposes ConsoleLogReport() — the CDP browser driver // does today, others return nothing — surfaces its captured entries @@ -381,6 +396,22 @@ func (fr *FlowRunner) Run() FlowResult { } } +// runFlowCompleteHooks runs the flow's onFlowComplete steps and returns why +// they failed, or "" when they passed. Maestro runs the hook through +// executeCommands (Orchestra.kt:237-256), which stops at the first failing +// step that is not optional, and so does this. +func (fr *FlowRunner) runFlowCompleteHooks() string { + for _, step := range fr.flow.Config.OnFlowComplete { + result := fr.executeNestedStep(step) + if !result.Success && !step.IsOptional() { + errMsg := fmt.Sprintf("onFlowComplete failed: %v", result.Error) + logger.Warn("%s", errMsg) + return errMsg + } + } + return "" +} + // executeStep executes a single step and updates the report. // Returns status, error message, and duration in milliseconds. func (fr *FlowRunner) executeStep(idx int, step flow.Step) (report.Status, string, int64) { diff --git a/pkg/executor/scoped_env_test.go b/pkg/executor/scoped_env_test.go new file mode 100644 index 00000000..7b495bb6 --- /dev/null +++ b/pkg/executor/scoped_env_test.go @@ -0,0 +1,53 @@ +package executor + +import ( + "testing" + + "github.com/devicelab-dev/maestro-runner/pkg/flow" + "github.com/devicelab-dev/maestro-runner/pkg/report" +) + +// A key a runFlow, retry or sub-flow env added is gone when it returns, as in +// Maestro, whose leaveEnvScope restores the env as it was (GraalJsEngine.kt: +// 223-238). It used to stay behind set to "". +func TestWithEnvVars_RestoreRemovesAddedKeys(t *testing.T) { + se := NewScriptEngine() + defer se.Close() + se.SetVariable("KEPT", "before") + + restore := se.withEnvVars(map[string]string{"KEPT": "inside", "ADDED": "inside"}) + if se.GetVariable("ADDED") != "inside" || se.GetVariable("KEPT") != "inside" { + t.Fatalf("env not applied: ADDED=%q KEPT=%q", se.GetVariable("ADDED"), se.GetVariable("KEPT")) + } + restore() + + if got := se.GetVariable("KEPT"); got != "before" { + t.Errorf("KEPT = %q after restore, want its old value", got) + } + if _, ok := se.Variables()["ADDED"]; ok { + t.Error("ADDED is still a variable after restore, want it removed") + } + if got, err := se.js.Eval("typeof ADDED"); err != nil || got != "undefined" { + t.Errorf("typeof ADDED = %v (%v) after restore, want undefined", got, err) + } +} + +func TestRunFlowEnv_IsGoneAfterTheRunFlow(t *testing.T) { + result := runOneFlow(t, &mockDriver{}, flow.Flow{ + SourcePath: "test.yaml", + Config: flow.Config{Name: "scoped env"}, + Steps: []flow.Step{ + &flow.RunFlowStep{ + BaseStep: flow.BaseStep{StepType: flow.StepRunFlow}, + Env: map[string]string{"SCOPED": "1"}, + Steps: []flow.Step{ + &flow.AssertTrueStep{BaseStep: flow.BaseStep{StepType: flow.StepAssertTrue}, Script: "${SCOPED === '1'}"}, + }, + }, + &flow.AssertTrueStep{BaseStep: flow.BaseStep{StepType: flow.StepAssertTrue}, Script: "${typeof SCOPED === 'undefined'}"}, + }, + }) + if result.Status != report.StatusPassed { + t.Errorf("status = %v, want passed: SCOPED should be set inside the runFlow and undefined after it", result.Status) + } +} diff --git a/pkg/executor/scripting.go b/pkg/executor/scripting.go index d453cb89..7107982e 100644 --- a/pkg/executor/scripting.go +++ b/pkg/executor/scripting.go @@ -251,8 +251,18 @@ func expandDollarVar(text, name, value string) string { // outlive a single runScript call still goes through the global `output` // bag, exactly as documented. func (se *ScriptEngine) RunScript(script string, env map[string]string) error { - // Expand variables in script - script = se.ExpandVariables(script) + return se.runScript(script, env, true) +} + +// runScript runs a script with its env. expandBody expands ${...} and $VAR in the script text +// first, which suits inline script text. A script file is plain JavaScript and runs as written, +// as in Maestro: expanding it first replaced the file's own template literals (`${localVar}`) +// ahead of the script, against variables that did not exist yet. +func (se *ScriptEngine) runScript(script string, env map[string]string, expandBody bool) error { + if expandBody { + // Expand variables in script + script = se.ExpandVariables(script) + } // Apply env variables for the duration of THIS script only, expanded so // values like "mockoon-cli start --port ${output.port}" resolve before the @@ -368,9 +378,9 @@ func (se *ScriptEngine) EvalCondition(script string) (bool, error) { // Expand any remaining $VAR style variables script = se.expandDollarVars(script) - // Pre-define potential env variables as undefined to avoid ReferenceError - matches := envVarPattern.FindAllString(script, -1) - for _, name := range matches { + // An undeclared name is undefined, not a ReferenceError, as in Maestro's + // JS engine (GraalJsEngine.kt:198-204). + for _, name := range referencedIdentifiers(script) { se.js.DefineUndefinedIfMissing(name) } @@ -384,7 +394,7 @@ func (se *ScriptEngine) EvalCondition(script string) (bool, error) { case bool: return v, nil case string: - return v == "true", nil + return maestroTruthy(v), nil case int64: return v != 0, nil case float64: @@ -394,6 +404,42 @@ func (se *ScriptEngine) EvalCondition(script string) (bool, error) { } } +// maestroTruthy is how Maestro reads the value of a `true:` condition or an +// assertTrue: false when it is blank, "false" in any case, "undefined", +// "null" or a number equal to zero, and true otherwise, so "abc" is true +// (Orchestra.kt:1030-1052). +func maestroTruthy(value string) bool { + if strings.TrimSpace(value) == "" || strings.EqualFold(value, "false") || + value == "undefined" || value == "null" { + return false + } + if f, err := strconv.ParseFloat(strings.TrimSpace(value), 64); err == nil && f == 0 { + return false + } + return true +} + +// isWholeExpression reports whether text is one ${...} and nothing else. +func isWholeExpression(text string) bool { + s := strings.TrimSpace(text) + if !strings.HasPrefix(s, "${") { + return false + } + depth := 0 + for i := 1; i < len(s); i++ { + switch s[i] { + case '{': + depth++ + case '}': + depth-- + if depth == 0 { + return i == len(s)-1 + } + } + } + return false +} + // ResolvePath resolves a relative path against the flow directory. func (se *ScriptEngine) ResolvePath(path string) string { if filepath.IsAbs(path) || se.flowDir == "" { @@ -422,7 +468,8 @@ func (se *ScriptEngine) ExecuteRunScript(step *flow.RunScriptStep) *core.Command script := step.ScriptPath() // Check if it's a file path (ends with .js) - if strings.HasSuffix(script, ".js") { + isFile := strings.HasSuffix(script, ".js") + if isFile { filePath := se.ResolvePath(script) content, err := os.ReadFile(filePath) if err != nil { @@ -435,7 +482,7 @@ func (se *ScriptEngine) ExecuteRunScript(step *flow.RunScriptStep) *core.Command script = string(content) } - if err := se.RunScript(script, step.Env); err != nil { + if err := se.runScript(script, step.Env, !isFile); err != nil { return &core.CommandResult{ Success: false, Error: err, @@ -656,17 +703,11 @@ func conditionTimeout(cond flow.Condition, sel *flow.Selector, fallback int) int // withEnvVars applies environment variables and returns a restore function. // Values are expanded through ExpandVariables to support ${VAR || "default"} syntax. +// The restore puts back what each key held and removes a key that was not set +// before, as Maestro's leaveEnvScope does (GraalJsEngine.kt:223-238), rather +// than leaving it set to "". func (se *ScriptEngine) withEnvVars(env map[string]string) func() { - oldVars := make(map[string]string) - for k, v := range env { - oldVars[k] = se.GetVariable(k) - se.SetVariable(k, se.ExpandVariables(v)) - } - return func() { - for k, v := range oldVars { - se.SetVariable(k, v) - } - } + return se.applyScopedEnv(env) } // parseBoolExpr converts the resolved value of an `enabled:` argument into a @@ -874,7 +915,10 @@ func (se *ScriptEngine) ExpandCondition(cond *flow.Condition) { if cond.NotVisible != nil { cond.NotVisible = se.expandSelector(cond.NotVisible) } - if cond.Script != "" { + // A script that is one ${...} is left for EvalCondition, which judges its + // value as Maestro does. Expanded here, the value was then run as JS + // itself: "abc" became a ReferenceError, and "" no condition at all. + if cond.Script != "" && !isWholeExpression(cond.Script) { cond.Script = se.ExpandVariables(cond.Script) } if cond.Platform != "" { diff --git a/pkg/executor/scripting_test.go b/pkg/executor/scripting_test.go index 5e4eaf71..7dd99f44 100644 --- a/pkg/executor/scripting_test.go +++ b/pkg/executor/scripting_test.go @@ -534,7 +534,7 @@ func TestScriptEngine_EvalCondition(t *testing.T) { {"comparison false", "count > 10", false}, {"equality", "count == 5", true}, {"string true", "'true'", true}, - {"string other", "'yes'", false}, + {"string other", "'yes'", true}, // true in Maestro: only a falsy string is false {"empty string", "''", false}, {"number non-zero", "42", true}, {"number zero", "0", false}, @@ -792,6 +792,29 @@ func TestScriptEngine_ExecuteRunScript_File(t *testing.T) { } } +// A script file's own template literals are plain JavaScript: they must see the script's local +// variables, not be expanded ahead of the script against the flow's variables. +func TestScriptEngine_ExecuteRunScript_FileTemplateLiteral(t *testing.T) { + se := NewScriptEngine() + defer se.Close() + + tmpDir := t.TempDir() + src := "const who = EMAIL;\nconst state = 'onboarded';\n" + + "output.url = `/v1/x?email=${encodeURIComponent(who)}&state=${state}`;\n" + if err := os.WriteFile(filepath.Join(tmpDir, "tl.js"), []byte(src), 0o644); err != nil { + t.Fatalf("Failed to create test script: %v", err) + } + se.SetFlowDir(tmpDir) + + step := &flow.RunScriptStep{Script: "tl.js", Env: map[string]string{"EMAIL": "a+b@x.io"}} + if result := se.ExecuteRunScript(step); !result.Success { + t.Fatalf("ExecuteRunScript() success = false, error = %v", result.Error) + } + if got, want := se.GetVariable("url"), "/v1/x?email=a%2Bb%40x.io&state=onboarded"; got != want { + t.Errorf("url = %q, want %q", got, want) + } +} + func TestScriptEngine_ExecuteRunScript_FileNotFound(t *testing.T) { se := NewScriptEngine() defer se.Close() diff --git a/pkg/executor/truthiness_test.go b/pkg/executor/truthiness_test.go new file mode 100644 index 00000000..9fb517e1 --- /dev/null +++ b/pkg/executor/truthiness_test.go @@ -0,0 +1,144 @@ +package executor + +import ( + "context" + "testing" + + "github.com/devicelab-dev/maestro-runner/pkg/core" + "github.com/devicelab-dev/maestro-runner/pkg/flow" + "github.com/devicelab-dev/maestro-runner/pkg/report" +) + +// Maestro reads a condition value as false only when it is blank, "false" in +// any case, "undefined", "null" or zero (Orchestra.kt:1030-1052). +func TestMaestroTruthy(t *testing.T) { + for value, want := range map[string]bool{ + "": false, + " ": false, + "false": false, + "FALSE": false, + "undefined": false, + "null": false, + "0": false, + "0.0": false, + "-0": false, + " 0 ": false, + "true": true, + "True": true, + "abc": true, + "yes": true, + "1": true, + "-1": true, + "NaN": true, + "Null": true, // the null check is case-sensitive + "UNDEFINED": true, + } { + if got := maestroTruthy(value); got != want { + t.Errorf("maestroTruthy(%q) = %v, want %v", value, got, want) + } + } +} + +func TestIsWholeExpression(t *testing.T) { + for text, want := range map[string]bool{ + "${a}": true, + " ${a == 1} ": true, + "${ {a: 1}.a }": true, + "${a} > ${b}": false, + "${a}-x": false, + "x ${a}": false, + "a": false, + "${a": false, + } { + if got := isWholeExpression(text); got != want { + t.Errorf("isWholeExpression(%q) = %v, want %v", text, got, want) + } + } +} + +// assertTrue on a string that is not "true" failed. +func TestAssertTrue_StringValueIsTrueAsInMaestro(t *testing.T) { + se := NewScriptEngine() + defer se.Close() + se.SetVariable("name", "abc") + + for script, want := range map[string]bool{ + "${name}": true, + "${'yes'}": true, + "${'false'}": false, + "${''}": false, + "${'0'}": false, + "${notDeclared}": false, + "${notDeclared||1}": true, + } { + result := se.ExecuteAssertTrue(&flow.AssertTrueStep{Script: script}) + if result.Success != want { + t.Errorf("assertTrue %s passed=%v, want %v (%s)", script, result.Success, want, result.Message) + } + } +} + +// A when: condition went through two readings: its ${...} was expanded to text, +// and that text then ran as JavaScript. So a value like "abc" was a +// ReferenceError, "YES" an undefined name, and an unset variable expanded to +// "", which counted as no condition at all and ran the branch. +func TestWhenCondition_ValueIsReadAsInMaestro(t *testing.T) { + se := NewScriptEngine() + defer se.Close() + se.SetVariable("name", "abc") + se.SetVariable("FLAG", "YES") + se.SetVariable("url", "https://example.com/a b") + se.SetVariable("count", "1") + + for script, want := range map[string]bool{ + "${name}": true, + "${FLAG}": true, + "${url}": true, + "${UNSET_FLAG}": false, + "${notDeclared}": false, + "${notDeclared||'x'}": true, + "${name == 'abc'}": true, + "${count > 3}": false, + "${count} > 0": true, // text around the ${...}: still run as JS, as before + } { + cond := flow.Condition{Script: script} + se.ExpandCondition(&cond) + if got := se.CheckCondition(context.Background(), cond, &mockDriver{}); got != want { + t.Errorf("when: true: %s = %v, want %v", script, got, want) + } + } +} + +func TestRunFlow_WhenUnsetVariableSkipsTheBranch(t *testing.T) { + var taps []string + driver := &mockDriver{executeFunc: func(step flow.Step) *core.CommandResult { + if tap, ok := step.(*flow.TapOnStep); ok { + taps = append(taps, tap.Selector.Text) + } + return &core.CommandResult{Success: true} + }} + branch := func(script, tap string) *flow.RunFlowStep { + return &flow.RunFlowStep{ + BaseStep: flow.BaseStep{StepType: flow.StepRunFlow}, + When: &flow.Condition{Script: script}, + Steps: []flow.Step{&flow.TapOnStep{ + BaseStep: flow.BaseStep{StepType: flow.StepTapOn}, + Selector: flow.Selector{Text: tap}, + }}, + } + } + result := runOneFlow(t, driver, flow.Flow{ + SourcePath: "test.yaml", + Config: flow.Config{Name: "when true", Env: map[string]string{"NAME": "abc"}}, + Steps: []flow.Step{ + branch("${UNSET_FLAG}", "unset"), + branch("${NAME}", "named"), + }, + }) + if result.Status != report.StatusPassed { + t.Fatalf("status = %v, want passed", result.Status) + } + if len(taps) != 1 || taps[0] != "named" { + t.Errorf("taps = %v, want only the branch whose variable is set", taps) + } +} diff --git a/pkg/jsengine/http.go b/pkg/jsengine/http.go index d986d121..4b6f0342 100644 --- a/pkg/jsengine/http.go +++ b/pkg/jsengine/http.go @@ -12,6 +12,11 @@ import ( "github.com/dop251/goja" ) +// defaultHTTPTimeout bounds an http.* call that sets no timeout of its own: +// the 5 minutes Maestro's script client allows a call (GraalJsEngine.kt:28-34). +// A variable so tests can shorten it. +var defaultHTTPTimeout = 5 * time.Minute + // httpModule returns the http object with get, post, put, delete methods func (e *Engine) httpModule() *goja.Object { obj := e.runtime.NewObject() @@ -84,7 +89,7 @@ func (e *Engine) doHTTPRequest(method string, call goja.FunctionCall) goja.Value // Parse options if provided var body io.Reader headers := make(map[string]string) - timeout := 30 * time.Second + timeout := defaultHTTPTimeout insecure := e.insecureHTTP if len(call.Arguments) > 1 && !goja.IsUndefined(call.Arguments[1]) { diff --git a/pkg/jsengine/http_timeout_test.go b/pkg/jsengine/http_timeout_test.go new file mode 100644 index 00000000..c4ed08f0 --- /dev/null +++ b/pkg/jsengine/http_timeout_test.go @@ -0,0 +1,48 @@ +package jsengine + +import ( + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" +) + +// Maestro's script client allows a call 5 minutes (GraalJsEngine.kt:28-34). +// The runner's gave up after 30 s, so a slow test-data endpoint that works +// under Maestro failed the script. +func TestDefaultHTTPTimeoutIsMaestros(t *testing.T) { + if defaultHTTPTimeout != 5*time.Minute { + t.Errorf("default http timeout = %v, want 5m", defaultHTTPTimeout) + } +} + +// A call with no timeout option waits for the default, and the option still +// wins over it. +func TestHTTPRequestWithoutATimeoutUsesTheDefault(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + time.Sleep(300 * time.Millisecond) + _, _ = w.Write([]byte(`ok`)) + })) + defer srv.Close() + + saved := defaultHTTPTimeout + defaultHTTPTimeout = 50 * time.Millisecond + defer func() { defaultHTTPTimeout = saved }() + + e := New() + defer e.Close() + + _, err := e.Eval(`http.get(` + jsString(srv.URL) + `).status`) + if err == nil || !strings.Contains(err.Error(), "HTTP request failed") { + t.Errorf("a call slower than the default timeout returned err = %v, want it to time out", err) + } + + v, err := e.Eval(`http.get(` + jsString(srv.URL) + `, { timeout: 5000 }).status`) + if err != nil { + t.Fatalf("a call with its own longer timeout failed: %v", err) + } + if n, _ := v.(int64); n != 200 { + t.Errorf("status = %v, want 200", v) + } +}