webdriverio/webdriverio

[🐛 Bug]: Setting script timeout using browser.setTimeout doesn't seem to work

Open

#14220 opened on Feb 24, 2025

View on GitHub
 (8 comments) (0 reactions) (0 assignees)JavaScript (6,029 stars) (1,793 forks)batch import
Bug 🐛help wanted

Description

Have you read the Contributing Guidelines on issues?

WebdriverIO Version

9.10.0

Node.js Version

22.12.0

Mode

WDIO Testrunner

Which capabilities are you using?

What happened?

Test spec is here - https://github.com/heraldantony/webdriverio-tests/blob/main/async-script-timeout/v9/test/specs/test.timeout.js

I set script timeout using browser.setTimeout({ script: 20000 }) and execute a script that would take about 30 seconds. I would expect an error in this case, but it doesn't timeout.

it("script should fail with timeout error, timeout = 20 secs, script execution 30 secs", async () => {
    await browser.setTimeout({ script: 20000 });
    await expect(
      browser.executeAsync((done) => {
        console.log("this should fail");
        setTimeout(done, 30000);
      })
    ).rejects.toThrowError(/Command script.callFunction.*timed out/);
  });

The following should not timeout, but it does. It seems there is an implicit timeout of about 60 seconds, which cannot be changed.

it("script should not fail, timeout = 90 secs, script execution 80 secs", async () => {
    await browser.setTimeout({ script: 90000 });
    await browser.executeAsync((done) => {
      console.log("this should not fail");
      setTimeout(done, 80000);
    });
  });

The third case should timeout, and it does. But although script timeout is set to 90 secs, I don't think it uses it.

it("script should fail with timeout error, timeout = 90 secs, script execution 120 secs", async () => {
    await browser.setTimeout({ script: 90000 });
    await expect(
      browser.executeAsync((done) => {
        console.log("this should fail");
        setTimeout(done, 120000);
      })
    ).rejects.toThrowError(/Command script.callFunction.*timed out/);
  });

What is your expected behavior?

await browser.setTimeout({ script: 90000 }) should set script timeout to specified value.

How to reproduce the bug.

  1. Clone https://github.com/heraldantony/webdriverio-tests
  2. cd async-script-timeout/v9
  3. npm install
  4. npm run test

Test spec file is https://github.com/heraldantony/webdriverio-tests/blob/main/async-script-timeout/v9/test/specs/test.timeout.js

To compare with webdriverio version 8, run the test in async-script-timeout/v8 folder

Version 8 runs fine, version 9 fails.

Relevant log output

> wdio wdio.conf.js


Execution of 1 workers started at 2025-02-24T10:01:59.432Z

2025-02-24T10:01:59.704Z INFO @wdio/cli:launcher: Run onPrepare hook
2025-02-24T10:01:59.708Z INFO @wdio/utils: Setting up browser driver for: chrome@stable
2025-02-24T10:01:59.712Z INFO @wdio/utils: Setting up browser binaries for: chrome@stable
2025-02-24T10:01:59.724Z INFO webdriver: Using Chromedriver v133.0.6943.60 from cache directory C:\Users\xyz\AppData\Local\Temp
2025-02-24T10:01:59.735Z INFO @wdio/cli:launcher: Run onWorkerStart hook
2025-02-24T10:01:59.739Z INFO @wdio/local-runner: Start worker 0-0 with arg: wdio.conf.js
[0-0] 2025-02-24T10:02:11.367Z INFO @wdio/local-runner: Run worker command: run
[0-0] RUNNING in chrome - file:///C:/Users/xyz/work/samples/webdriverio-tests/async-script-timeout/v9/test/specs/test.timeout.js
[0-0] 2025-02-24T10:02:13.362Z INFO webdriver: Initiate new session using the WebDriver protocol
[0-0] 2025-02-24T10:02:16.060Z INFO webdriver: Using Chromedriver v133.0.6943.60 from cache directory C:\Users\xyz\AppData\Local\Temp
[0-0] 2025-02-24T10:02:17.230Z INFO chromedriver: Starting ChromeDriver 133.0.6943.60 (9b47b513b8a4d5273451257e3d78e644ac309ed7-refs/branch-heads/6943_53@{#4}) on port 54444
[0-0] 2025-02-24T10:02:17.231Z INFO chromedriver: Remote connections are allowed by an allowlist (0.0.0.0).   
[0-0] 2025-02-24T10:02:17.231Z INFO chromedriver: Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
[0-0] 2025-02-24T10:02:17.250Z INFO chromedriver: ChromeDriver was started successfully on port 54444.
[0-0] 2025-02-24T10:02:18.203Z INFO @wdio/utils: Started Chromedriver v133.0.6943.60 with params --port=54444 --allowed-origins=* --allowed-ips=0.0.0.0 in 2225ms on port 54444
[0-0] 2025-02-24T10:02:18.214Z INFO webdriver: [POST] http://localhost:54444/session
[0-0] 2025-02-24T10:02:18.215Z INFO webdriver: DATA {
[0-0]   capabilities: {
[0-0]     alwaysMatch: {
[0-0]       browserName: 'chrome',
[0-0]       'goog:chromeOptions': [Object],
[0-0]       webSocketUrl: true,
[0-0]       unhandledPromptBehavior: 'ignore'
[0-0]     },
[0-0]     firstMatch: [ {} ]
[0-0]   }
[0-0] }

DevTools listening on ws://127.0.0.1:54450/devtools/browser/3d45812d-5d65-430b-b576-8360a80a0661
[0-0] 2025-02-24T10:02:24.544Z INFO webdriver: Register BiDi handler for session with id 8e97fab18705e079c159de17d854568e
[0-0] 2025-02-24T10:02:24.546Z INFO webdriver: Connect to webSocketUrl ws://127.0.0.1:54444/session/8e97fab18705e079c159de17d854568e
[0-0] 2025-02-24T10:02:24.595Z INFO webdriver: Connected session to Bidi protocol
[0-0] 2025-02-24T10:02:24.599Z INFO webdriver: BIDI COMMAND session.subscribe {"events":["browsingContext.contextCreated"]}
[0-0] 2025-02-24T10:02:24.605Z INFO webdriver: BIDI COMMAND session.subscribe {"events":["log.entryAdded","browsingContext.navigationStarted"]}
[0-0] 2025-02-24T10:02:24.605Z INFO webdriver: BIDI COMMAND script.addPreloadScript { functionDeclaration: <PreloadScript[1319 bytes]>, contexts: undefined }
[0-0] 2025-02-24T10:02:24.608Z INFO webdriver: BIDI COMMAND session.subscribe {"events":["browsingContext.navigationStarted","browsingContext.fragmentNavigated","network.responseCompleted","network.beforeRequestSent","network.fetchError"]}
[0-0] 2025-02-24T10:02:24.611Z INFO webdriver: BIDI COMMAND session.subscribe {"events":["browsingContext.userPromptOpened"]}
[0-0] 2025-02-24T10:02:24.613Z INFO webdriver: BIDI COMMAND session.subscribe {"events":["browsingContext.navigationStarted"]}
[0-0] 2025-02-24T10:02:24.618Z INFO webdriver: COMMAND getWindowHandle()
[0-0] 2025-02-24T10:02:24.620Z INFO webdriver: Connected to WebDriver Bidi interface at ws://127.0.0.1:54444/session/8e97fab18705e079c159de17d854568e
[0-0] 2025-02-24T10:02:24.622Z INFO webdriver: BIDI COMMAND browsingContext.getTree {}
[0-0] 2025-02-24T10:02:24.623Z INFO webdriver: [GET] http://localhost:54444/session/8e97fab18705e079c159de17d854568e/window
[0-0] 2025-02-24T10:02:24.645Z INFO webdriver: RESULT 371B6A37C9B784C2EC9D07F94512B410
[0-0] 2025-02-24T10:02:24.685Z INFO webdriverio:PolyfillManager: Adding polyfill script to context with id 371B6A37C9B784C2EC9D07F94512B410
[0-0] 2025-02-24T10:02:24.686Z INFO webdriver: BIDI COMMAND script.callFunction {"functionDeclaration":"<Function[442 bytes] webdriverioPolyfill>","target":{"children":null,"clientWindow":"","context":"371B6A37C9B784C2EC9D07F94512B410","originalOpener":null,"parent":null,"url":"about:blank","userContext":"default"},"awaitPromise":false}
[0-0] 2025-02-24T10:02:24.687Z INFO webdriver: BIDI COMMAND script.addPreloadScript { functionDeclaration: <PreloadScript[442 bytes]>, contexts: ["371B6A37C9B784C2EC9D07F94512B410"] }
[0-0] 2025-02-24T10:02:24.690Z INFO webdriver: BIDI RESULT {"id":1,"result":{},"type":"success"}
[0-0] 2025-02-24T10:02:24.702Z INFO webdriver: BIDI RESULT {"id":2,"result":{},"type":"success"}
[0-0] 2025-02-24T10:02:24.732Z INFO webdriver: BIDI RESULT {"id":4,"result":{},"type":"success"}
[0-0] 2025-02-24T10:02:24.736Z INFO webdriver: BIDI RESULT {"id":5,"result":{},"type":"success"}
[0-0] 2025-02-24T10:02:24.744Z INFO webdriver: BIDI RESULT {"id":6,"result":{},"type":"success"}
[0-0] 2025-02-24T10:02:24.754Z INFO webdriver: BIDI RESULT {"id":7,"result":{"contexts":[{"children":[],"clientWindow":"","context":"371B6A37C9B784C2EC9D07F94512B410","originalOpener":null,"parent":null,"url":"about:blank","userContext":"default"}]},"type":"success"}
[0-0] 2025-02-24T10:02:24.783Z INFO webdriver: COMMAND setTimeouts(undefined, undefined, 20000)
[0-0] 2025-02-24T10:02:24.784Z INFO webdriver: [POST] http://localhost:54444/session/8e97fab18705e079c159de17d854568e/timeouts
[0-0] 2025-02-24T10:02:24.784Z INFO webdriver: DATA { script: 20000 }
[0-0] 2025-02-24T10:02:24.845Z INFO webdriver: RESULT null
[0-0] 2025-02-24T10:02:24.847Z INFO webdriver: BIDI COMMAND script.callFunction {"functionDeclaration":"<Function[470 bytes] anonymous>","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}
[0-0] 2025-02-24T10:02:24.915Z INFO webdriver: BIDI RESULT {"id":3,"result":{"script":"42a611eb-0a21-495a-87d3-b0dd454684c1"},"type":"success"}
[0-0] 2025-02-24T10:02:24.918Z INFO webdriver: BIDI RESULT {"id":8,"result":{"realm":"5190746597127847064.-1218484852835392525","result":{"type":"undefined"},"type":"success"},"type":"success"}
[0-0] 2025-02-24T10:02:24.919Z INFO webdriver: BIDI RESULT {"id":9,"result":{"script":"5de9fce3-839e-4330-aef6-a37a13463d52"},"type":"success"}
[0-0] 2025-02-24T10:02:41.396Z INFO webdriver: BIDI RESULT {"id":10,"result":{"realm":"5190746597127847064.-1218484852835392525","result":{"type":"undefined"},"type":"success"},"type":"success"}
[0-0] 2025-02-24T10:02:41.402Z INFO webdriver: COMMAND setTimeouts(undefined, undefined, 20000)
[0-0] 2025-02-24T10:02:41.403Z INFO webdriver: [POST] http://localhost:54444/session/8e97fab18705e079c159de17d854568e/timeouts
[0-0] 2025-02-24T10:02:41.404Z INFO webdriver: DATA { script: 20000 }
[0-0] 2025-02-24T10:02:41.430Z INFO webdriver: RESULT null
[0-0] 2025-02-24T10:02:41.433Z INFO webdriver: BIDI COMMAND script.callFunction {"functionDeclaration":"<Function[472 bytes] anonymous>","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}
Created TensorFlow Lite XNNPACK delegate for CPU.
Attempting to use a delegate that only supports static-sized tensors with a graph that has dynamic-sized tensors (tensor#-1 is a dynamic-sized tensor).
[0-0] 2025-02-24T10:03:11.516Z INFO webdriver: BIDI RESULT {"id":11,"result":{"realm":"5190746597127847064.-1218484852835392525","result":{"type":"undefined"},"type":"success"},"type":"success"}
[0-0] Error in "browser setTimeout.script should fail with timeout error, timeout = 20 secs, script execution 30 secs"
Error: expect(received).rejects.toThrowError()

Received promise resolved instead of rejected
Resolved to value: undefined
    at expect (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\expect\build\index.js:113:15)
    at Context.<anonymous> (file:///C:/Users/xyz/work/samples/webdriverio-tests/async-script-timeout/v9/test/specs/test.timeout.js:11:11)
    at async Context.executeAsync (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\@wdio\utils\build\index.js:1016:20)
    at async Context.testFrameworkFnWrapper (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\@wdio\utils\build\index.js:1087:14)
[0-0] 2025-02-24T10:03:11.569Z INFO webdriver: COMMAND setTimeouts(undefined, undefined, 90000)
[0-0] 2025-02-24T10:03:11.570Z INFO webdriver: [POST] http://localhost:54444/session/8e97fab18705e079c159de17d854568e/timeouts
[0-0] 2025-02-24T10:03:11.570Z INFO webdriver: DATA { script: 90000 }
[0-0] 2025-02-24T10:03:11.583Z INFO webdriver: RESULT null
[0-0] 2025-02-24T10:03:11.584Z INFO webdriver: BIDI COMMAND script.callFunction {"functionDeclaration":"<Function[470 bytes] anonymous>","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}
[0-0] Error in "browser setTimeout.script should not fail, timeout = 90 secs, script execution 80 secs"
Error: Command script.callFunction with id 12 (with the following parameter: {"functionDeclaration":"function anonymous(\n) {\n\n            const args = Array.from(arguments)\n            return new Promise(async (resolve, reject) => {\n                const cb = (result) => resolve(result)\n                try {\n             
       await ((done) => {\n      console.log(\"this should not fail\");\n      setTimeout(done, 80000);\n    }).apply(this, [...args, cb])\n                } catch (err) {\n                    return reject(err)\n                }\n            })\n        \n}","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}) timed out
    at listOnTimeout (node:internal/timers:594:17)
    at process.processTimers (node:internal/timers:529:7)
[0-0] 2025-02-24T10:04:11.603Z INFO webdriver: COMMAND setTimeouts(undefined, undefined, 90000)
[0-0] 2025-02-24T10:04:11.603Z INFO webdriver: [POST] http://localhost:54444/session/8e97fab18705e079c159de17d854568e/timeouts
[0-0] 2025-02-24T10:04:11.603Z INFO webdriver: DATA { script: 90000 }
[0-0] 2025-02-24T10:04:11.617Z INFO webdriver: RESULT null
[0-0] 2025-02-24T10:04:11.618Z INFO webdriver: BIDI COMMAND script.callFunction {"functionDeclaration":"<Function[473 bytes] anonymous>","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}
[0-0] 2025-02-24T10:04:31.622Z INFO webdriver: BIDI RESULT {"id":12,"result":{"realm":"5190746597127847064.-1218484852835392525","result":{"type":"undefined"},"type":"success"},"type":"success"}
[0-0] 2025-02-24T10:04:31.623Z ERROR webdriver: Couldn't resolve command with id 12
[0-0] 2025-02-24T10:05:11.635Z INFO webdriver: COMMAND deleteSession()
[0-0] 2025-02-24T10:05:11.636Z INFO webdriver: [DELETE] http://localhost:54444/session/8e97fab18705e079c159de17d854568e
[0-0] 2025-02-24T10:05:13.534Z INFO webdriver: RESULT null
[0-0] 2025-02-24T10:05:13.535Z INFO webdriver: Close Bidi connection to ws://127.0.0.1:54444/session/8e97fab18705e079c159de17d854568e
[0-0] 2025-02-24T10:05:13.536Z INFO webdriver: Kill driver process with PID 16308
[0-0] FAILED in chrome - file:///C:/Users/xyz/work/samples/webdriverio-tests/async-script-timeout/v9/test/specs/test.timeout.js
2025-02-24T10:05:13.704Z INFO @wdio/cli:launcher: Run onWorkerEnd hook

 "spec" Reporter:
------------------------------------------------------------------
[chrome 133.0.6943.60 windows #0-0] Running: chrome (v133.0.6943.60) on windows
[chrome 133.0.6943.60 windows #0-0] Session ID: 8e97fab18705e079c159de17d854568e
[chrome 133.0.6943.60 windows #0-0]
[chrome 133.0.6943.60 windows #0-0] » \test\specs\test.timeout.js
[chrome 133.0.6943.60 windows #0-0] browser setTimeout
[chrome 133.0.6943.60 windows #0-0]    ✓ script should not timeout
[chrome 133.0.6943.60 windows #0-0]    ✖ script should fail with timeout error, timeout = 20 secs, script execution 30 secs
[chrome 133.0.6943.60 windows #0-0]    ✖ script should not fail, timeout = 90 secs, script execution 80 secs  
[chrome 133.0.6943.60 windows #0-0]    ✓ script should fail with timeout error, timeout = 90 secs, script execution 120 secs
[chrome 133.0.6943.60 windows #0-0]
[chrome 133.0.6943.60 windows #0-0] 2 passing (2m 48.7s)
[chrome 133.0.6943.60 windows #0-0] 2 failing
[chrome 133.0.6943.60 windows #0-0]
[chrome 133.0.6943.60 windows #0-0] 1) browser setTimeout script should fail with timeout error, timeout = 20 secs, script execution 30 secs
[chrome 133.0.6943.60 windows #0-0] expect(received).rejects.toThrowError()

Received promise resolved instead of rejected
Resolved to value: undefined
[chrome 133.0.6943.60 windows #0-0] Error: expect(received).rejects.toThrowError()
[chrome 133.0.6943.60 windows #0-0]
[chrome 133.0.6943.60 windows #0-0] Received promise resolved instead of rejected
[chrome 133.0.6943.60 windows #0-0] Resolved to value: undefined
[chrome 133.0.6943.60 windows #0-0]     at expect (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\expect\build\index.js:113:15)
[chrome 133.0.6943.60 windows #0-0]     at Context.<anonymous> (file:///C:/Users/xyz/work/samples/webdriverio-tests/async-script-timeout/v9/test/specs/test.timeout.js:11:11)
[chrome 133.0.6943.60 windows #0-0]     at async Context.executeAsync (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\@wdio\utils\build\index.js:1016:20)
[chrome 133.0.6943.60 windows #0-0]     at async Context.testFrameworkFnWrapper (C:\Users\xyz\work\samples\webdriverio-tests\async-script-timeout\v9\node_modules\@wdio\utils\build\index.js:1087:14)
[chrome 133.0.6943.60 windows #0-0]
[chrome 133.0.6943.60 windows #0-0] 2) browser setTimeout script should not fail, timeout = 90 secs, script execution 80 secs
[chrome 133.0.6943.60 windows #0-0] Command script.callFunction with id 12 (with the following parameter: {"functionDeclaration":"function anonymous(\n) {\n\n            const args = Array.from(arguments)\n            return new Promise(async (resolve, reject) => {\n                const cb = (result) => resolve(result)\n                try {\n                    await ((done) => {\n      console.log(\"this should not fail\");\n      setTimeout(done, 80000);\n    }).apply(this, [...args, cb])\n                } catch (err) {\n                  
  return reject(err)\n                }\n            })\n        \n}","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}) timed out
[chrome 133.0.6943.60 windows #0-0] Error: Command script.callFunction with id 12 (with the following parameter: {"functionDeclaration":"function anonymous(\n) {\n\n            const args = Array.from(arguments)\n            return new Promise(async (resolve, reject) => {\n                const cb = (result) => resolve(result)\n                try {\n                    await ((done) => {\n      console.log(\"this should not fail\");\n      setTimeout(done, 80000);\n    }).apply(this, [...args, cb])\n                } catch (err) {\n           
         return reject(err)\n                }\n            })\n        \n}","awaitPromise":true,"arguments":[],"target":{"context":"371B6A37C9B784C2EC9D07F94512B410"}}) timed out
[chrome 133.0.6943.60 windows #0-0]     at listOnTimeout (node:internal/timers:594:17)
[chrome 133.0.6943.60 windows #0-0]     at process.processTimers (node:internal/timers:529:7)


Spec Files:      0 passed, 1 failed, 1 total (100% completed) in 00:03:14

2025-02-24T10:05:13.714Z INFO @wdio/local-runner: Shutting down spawned worker
2025-02-24T10:05:13.967Z INFO @wdio/local-runner: Waiting for 0 to shut down gracefully
2025-02-24T10:05:13.968Z INFO @wdio/local-runner: shutting down
2025-02-24T10:05:13.971Z INFO @wdio/cli:launcher: Run onComplete hook

Code of Conduct

  • I agree to follow this project's Code of Conduct

Is there an existing issue for this?

  • I have searched the existing issues

Contributor guide

Tech stack
javascripttypescriptnodejs
Domain
testing
Issue type
bug
DifficultyEstimated implementation difficulty for a new contributor, from 1 for very small changes to 5 for expert-level work.
3
Estimated timeA rough time range for an experienced contributor to investigate, implement, test, and prepare a pull request.
1-3 hours
Activity statusHow available the issue appears right now: fresh, active, stale, blocked, or waiting on maintainer input.
fresh
ClarityHow clearly the issue explains the expected change, acceptance criteria, and next step.
clear
Prerequisites
Node.jsWebdriverIO basicsAsync testing concepts
Newbie friendlinessA 1-100 score estimating how approachable this issue is for first-time contributors.
65
Research direction
Investigate the implementation of `browser.setTimeout` in the WebdriverIO codebase, specifically how it sets the script timeout via the WebDriver protocol (POST /session/:sessionId/timeouts). Check if the timeout is being correctly passed to the Bidi `script.callFunction` command or if there is a bug in the timeout application. Compare the v9 behavior with v8 to identify changes. Look at files like `packages/webdriverio/src/commands/browser/setTimeout.ts` and the script execution logic in `packages/webdriverio/src/scripts/executeAsync.ts`.