diff --git a/CHANGELOG.md b/CHANGELOG.md index ddfda590..39684d3e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,11 +8,15 @@ 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. ## [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/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..05fac506 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 @@ -422,7 +432,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 +446,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 +667,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 diff --git a/pkg/executor/scripting_test.go b/pkg/executor/scripting_test.go index 5e4eaf71..82d5a96f 100644 --- a/pkg/executor/scripting_test.go +++ b/pkg/executor/scripting_test.go @@ -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/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) + } +}