search

dequelabs / axe-core-npm

Mozilla Public License 2.0
598 stars 68 forks source link

webdriverio: Timed out waiting for asynchronous script #1024

Open gromanas opened 7 months ago

gromanas commented 7 months ago

Product

webdriverio

Product Version

v4.8.5

Latest Version

Issue Description

Expectation

builder.analyze() to return results on iOS simulators/real devices

Actual

 2024-02-22T20:24:33.892Z INFO webdriver: RESULT true
[0-0] 2024-02-22T20:24:33.893Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:33.893Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:33.893Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 0ms
[0-0] 2024-02-22T20:24:33.894Z INFO webdriver: COMMAND getTimeouts()
[0-0] 2024-02-22T20:24:33.894Z INFO webdriver: [GET] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/timeouts
[0-0] 2024-02-22T20:24:34.019Z INFO webdriver: RESULT { command: 0, implicit: 0 }
[0-0] 2024-02-22T20:24:34.020Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.021Z INFO webdriver: COMMAND executeAsyncScript("
[0-0]       var callback = arguments[arguments.length - 1];
[0-0]       var context = {"exclude":[]};
[0-0]       var frameContexts = window.axe.utils.getFrameContexts(context);
[0-0]       callback(frameContexts)
[0-0]     ", <object>)
[0-0] 2024-02-22T20:24:34.022Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/async
[0-0] 2024-02-22T20:24:34.022Z INFO webdriver: DATA {
[0-0]   script: '\n' +
[0-0]     '      var callback = arguments[arguments.length - 1];\n' +
[0-0]     '      var context = {"exclude":[]};\n' +
[0-0]     '      var frameContexts = window.axe.utils.getFrameContexts(context);\n' +
[0-0]     '      callback(frameContexts)\n' +
[0-0]     '    ',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:34.024Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 3ms
[0-0] 2024-02-22T20:24:34.024Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.024Z INFO webdriver: COMMAND setTimeouts(undefined, 1000, undefined)
[0-0] 2024-02-22T20:24:34.025Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/timeouts
[0-0] 2024-02-22T20:24:34.025Z INFO webdriver: DATA { pageLoad: 1000 }
[0-0] 2024-02-22T20:24:34.217Z INFO webdriver: RESULT []
[0-0] 2024-02-22T20:24:34.218Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.218Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.218Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.218Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.218Z INFO webdriver: COMMAND executeAsyncScript("
[0-0]       var callback = arguments[arguments.length - 1];
[0-0]       var context = {"exclude":[]} || document;
[0-0]       var options = {"runOnly":{"type":"tag","values":["wcag2a","wcag2aa"]}} || {};
[0-0]       window.axe.runPartial(context, options).then(function (partials) {
[0-0]         callback(JSON.stringify(partials))
[0-0]       });", <object>)
[0-0] 2024-02-22T20:24:34.218Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/async
[0-0] 2024-02-22T20:24:34.219Z INFO webdriver: DATA {
[0-0]   script: '\n' +
[0-0]     '      var callback = arguments[arguments.length - 1];\n' +
[0-0]     '      var context = {"exclude":[]} || document;\n' +
[0-0]     '      var options = {"runOnly":{"type":"tag","values":["wcag2a","wcag2aa"]}} || {};\n' +
[0-0]     '      window.axe.runPartial(context, options).then(function (partials) {\n' +
[0-0]     '        callback(JSON.stringify(partials))\n' +
[0-0]     '      });',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:34.221Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:34.221Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:36.596Z DEBUG webdriver: request failed due to response error: script timeout
[0-0] 2024-02-22T20:24:36.597Z INFO webdriver: Retrying 1/3
[0-0] 2024-02-22T20:24:36.597Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/async
[0-0] 2024-02-22T20:24:36.597Z WARN webdriver: Request failed with status 408 due to Timed out waiting for asynchronous script result after 275 ms
[0-0] 2024-02-22T20:24:36.597Z INFO webdriver: DATA {
[0-0]   script: '\n' +
[0-0]     '      var callback = arguments[arguments.length - 1];\n' +
[0-0]     '      var context = {"exclude":[]} || document;\n' +
[0-0]     '      var options = {"runOnly":{"type":"tag","values":["wcag2a","wcag2aa"]}} || {};\n' +
[0-0]     '      window.axe.runPartial(context, options).then(function (partials) {\n' +
[0-0]     '        callback(JSON.stringify(partials))\n' +
[0-0]     '      });',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:38.828Z DEBUG webdriver: request failed due to response error: script timeout
[0-0] 2024-02-22T20:24:38.828Z INFO webdriver: Retrying 2/3
[0-0] 2024-02-22T20:24:38.829Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/async
[0-0] 2024-02-22T20:24:38.829Z INFO webdriver: DATA {
[0-0]   script: '\n' +
[0-0]     '      var callback = arguments[arguments.length - 1];\n' +
[0-0]     '      var context = {"exclude":[]} || document;\n' +
[0-0]     '      var options = {"runOnly":{"type":"tag","values":["wcag2a","wcag2aa"]}} || {};\n' +
[0-0]     '      window.axe.runPartial(context, options).then(function (partials) {\n' +
[0-0]     '        callback(JSON.stringify(partials))\n' +
[0-0]     '      });',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:38.828Z WARN webdriver: Request failed with status 408 due to Timed out waiting for asynchronous script result after 117 ms
[0-0] 2024-02-22T20:24:41.060Z DEBUG webdriver: request failed due to response error: script timeout
[0-0] 2024-02-22T20:24:41.062Z INFO webdriver: Retrying 3/3
[0-0] 2024-02-22T20:24:41.062Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/async
[0-0] 2024-02-22T20:24:41.062Z WARN webdriver: Request failed with status 408 due to Timed out waiting for asynchronous script result after 117 ms
[0-0] 2024-02-22T20:24:41.062Z INFO webdriver: DATA {
[0-0]   script: '\n' +
[0-0]     '      var callback = arguments[arguments.length - 1];\n' +
[0-0]     '      var context = {"exclude":[]} || document;\n' +
[0-0]     '      var options = {"runOnly":{"type":"tag","values":["wcag2a","wcag2aa"]}} || {};\n' +
[0-0]     '      window.axe.runPartial(context, options).then(function (partials) {\n' +
[0-0]     '        callback(JSON.stringify(partials))\n' +
[0-0]     '      });',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:43.292Z DEBUG webdriver: request failed due to response error: script timeout
[0-0] 2024-02-22T20:24:43.294Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:43.294Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 0ms
[0-0] 2024-02-22T20:24:43.297Z DEBUG @wdio/utils:shim: Finished to run "beforeCommand" hook in 1ms
[0-0] 2024-02-22T20:24:43.293Z ERROR webdriver: Request failed with status 408 due to script timeout: Timed out waiting for asynchronous script result after 112 ms
[0-0] 2024-02-22T20:24:43.318Z INFO webdriver: COMMAND executeScript("sauce:context=script timeout: Timed out waiting for asynchronous script result after 112 ms", <object>)
[0-0] 2024-02-22T20:24:43.320Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/sync
[0-0] 2024-02-22T20:24:43.320Z INFO webdriver: DATA {
[0-0]   script: 'sauce:context=script timeout: Timed out waiting for asynchronous script result after 112 ms',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:43.322Z INFO webdriver: COMMAND executeScript("sauce:context=    at AxeBuilder.runPartialRecursive (node_modules/@axe-core/webdriverio/dist/index.js:498:7)", <object>)
[0-0] 2024-02-22T20:24:43.323Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/sync
[0-0] 2024-02-22T20:24:43.323Z INFO webdriver: DATA {
[0-0]   script: 'sauce:context=    at AxeBuilder.runPartialRecursive (/node_modules/@axe-core/webdriverio/dist/index.js:498:7)',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:43.324Z INFO webdriver: COMMAND executeScript("sauce:context=    at AxeBuilder.analyzePromise (/node_modules/@axe-core/webdriverio/dist/index.js:440:18)", <object>)
[0-0] 2024-02-22T20:24:43.324Z INFO webdriver: [POST] https://ondemand.eu-central-1.saucelabs.com/wd/hub/session/016cae5cda3d446096ad55dbc281aa99/execute/sync
[0-0] 2024-02-22T20:24:43.324Z INFO webdriver: DATA {
[0-0]   script: 'sauce:context=    at AxeBuilder.analyzePromise (/node_modules/@axe-core/webdriverio/dist/index.js:440:18)',
[0-0]   args: []
[0-0] }
[0-0] 2024-02-22T20:24:43.324Z DEBUG @wdio/utils:shim: Finished to run "afterCommand" hook in 22ms
[0-0] 2024-02-22T20:24:43.331Z DEBUG @wdio/utils:shim: Finished to run "afterTest" hook in 7ms
[0-0] script timeout in "Verification of a money game in accessibility mode.should play a money game in accessibility mode and verify the AC"
script timeout: Timed out waiting for asynchronous script result after 112 ms
    at AxeBuilder.runPartialRecursive (/node_modules/@axe-core/webdriverio/dist/index.js:498:7)
    at AxeBuilder.analyzePromise (node_modules/@axe-core/webdriverio/dist/index.js:440:18)

How to Reproduce

On a test case that is running on iOS on a real device or simulator.

 const builder = new AxeBuilder({ client: browser }).withTags([ "wcag2a", "wcag2aa" ]);
 const result = await builder.analyze();
 console.log("Acessibility Results:", result);

Additional context

This is still happening on wdio v8 and wdio v7, on node 14, node 20, also I have tested previous version of @axe-core/webdriverio 4.6.0.

straker commented 7 months ago

Thanks for the issue. Out of curiosity, do you know what your webdriverio's script timeout is set to? This line especially looks like the axe.run script is only given 110 ms before webdriverio says it times out.

[0-0] 2024-02-22T20:24:41.062Z WARN webdriver: Request failed with status 408 due to Timed out waiting for asynchronous script result after 117 ms

Could you try increasing the script timeout and see if that fixes the problem? Running axe can take a bit, especially on larger pages.

gromanas commented 7 months ago

@straker Thank you very much 🙇🏻 ! It resolved the issue of timeout, so this can be closed. Then I get the other error Request failed with status 405 due to Method has not yet been implemented of https://github.com/dequelabs/axe-core-npm/issues/338. Using setLegacy(true) and also with my workaround on https://github.com/dequelabs/axe-core-npm/issues/338#issuecomment-1959656200, I was able to produce a report at the end. Maybe we should consider if it is worth fixing this, I can help you on creating the PR, etc... What do you think?