webdriverio icon indicating copy to clipboard operation
webdriverio copied to clipboard

[๐Ÿ› Bug]: Setting script timeout using browser.setTimeout doesn't seem to work

Open heraldantony opened this issue 9 months ago โ€ข 7 comments

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

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

Is there an existing issue for this?

  • [x] I have searched the existing issues

heraldantony avatar Feb 24 '25 10:02 heraldantony

Thanks for raising this issue. It seems that WebDriver Bidi currently has no support for script timeouts. I reached out to the team to see if this may become supported on protocol level. If not we will look into supporting this on the WebdriverIO side.

christian-bromann avatar Feb 24 '25 19:02 christian-bromann

I know the expect waits for promises but can you check when awaiting it outside of an expect?

erwinheitzman avatar Feb 24 '25 19:02 erwinheitzman

@erwinheitzman I think this issue is outlining a problem supporting asynchronous execution within our execute and executeAsync commands. Both of them us WebDriver Bidi to inject the script, however Bidi has no knowledge about possible timeout settings in the WebDriver Classic protocol.

christian-bromann avatar Feb 24 '25 19:02 christian-bromann

According to the spec authors it is less likely that script timeouts will become a thing in Bidi, hence we should add it to the execute and executeAsync commands.

christian-bromann avatar Feb 24 '25 21:02 christian-bromann

Thanks for reporting!

We greatly appreciate any contributions that help resolve the bug. While we understand that active contributors have their own priorities, we kindly request your assistance if you rely on this bug being fixed. We encourage you to take a look at our contribution guidelines or join our friendly Discord development server, where you can ask any questions you may have. Thank you for your support, and cheers!

wdio-bot avatar Feb 24 '25 21:02 wdio-bot

Thank you @christian-bromann for the quick update.

heraldantony avatar Feb 25 '25 16:02 heraldantony

I know the expect waits for promises but can you check when awaiting it outside of an expect?

@erwinheitzman - yes, "expect" does wait for promises. The behavior is consistent with BIDI response timeout being set to 60 secs.

heraldantony avatar Feb 26 '25 15:02 heraldantony

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);
    });
  });

I've also encountered this issue.

Could the 60 second BIDI response timeout be made configurable or default to browser.getTimeouts() script value?

Related: https://github.com/webdriverio/webdriverio/issues/13474

kgibb avatar Oct 21 '25 10:10 kgibb