Intermittent /webdriver/tests/bidi/network/<random> | <random> - webdriver.bidi.error.UnknownErrorException: unknown error (TypeError: stack is null)
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=412996283&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Vy3USARXQM-5XY8pZSkW4A/runs/0/artifacts/public/logs/live_backing.log
INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - self = <webdriver.bidi.modules.script.Script object at 0x0000015C729006D0>
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - result = {'exceptionDetails': {'columnNumber': 0, 'exception': {'type': 'error'}, 'lineNumber': 0, 'stackTrace': {'callFrames':.../tests/bidi/network/support/empty.html'}]}, ...}, 'realm': 'ffd8e777-6c4f-4637-93dd-df36cff1d570', 'type': 'exception'}
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - @evaluate.result
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - def _evaluate(self, result: Mapping[str, Any]) -> Any:
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - assert "type" in result
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - if result["type"] == "success":
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - return result["result"]
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - elif result["type"] == "exception":
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - > raise ScriptEvaluateResultException(result)
[task 2023-04-19T12:31:34.733Z] 12:31:34 INFO - E webdriver.bidi.modules.script.ScriptEvaluateResultException: Script execution failed.
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - result = {'exceptionDetails': {'columnNumber': 0,
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'exception': {'type': 'error'},
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'lineNumber': 0,
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'stackTrace': {'callFrames': [{'columnNumber': 0,
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'functionName': '',
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'lineNumber': 0,
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'url': 'http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html'}]},
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'text': 'SyntaxError: redeclaration of const controller'},
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'realm': 'ffd8e777-6c4f-4637-93dd-df36cff1d570',
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - 'type': 'exception'}
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - self = <webdriver.bidi.modules.script.Script object at 0x0000015C729006D0>
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\script.py:157: ScriptEvaluateResultException
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/network/before_request_sent/before_request_sent.py | test_redirect - webdriver.bidi.error.UnknownErrorException: unknown error (TypeError: stack is null)
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000015C72900880>
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000015C729828B0>
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - url = <function url.<locals>.url at 0x0000015C72982C10>
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - fetch = <function fetch.<locals>.fetch at 0x0000015C72982790>
[task 2023-04-19T12:31:34.734Z] 12:31:34 INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x0000015C72982E50>
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - @pytest.mark.asyncio
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - async def test_redirect(bidi_session, wait_for_event, url, fetch, setup_network_test):
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - text_url = url(PAGE_EMPTY_TEXT)
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - redirect_url = url(
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - f"/webdriver/tests/support/http_handlers/redirect.py?location={text_url}"
INFO - )
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - network_events = await setup_network_test(events=["network.beforeRequestSent"])
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - events = network_events["network.beforeRequestSent"]
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - > await fetch(redirect_url, method="GET")
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO -
[task 2023-04-19T12:31:34.735Z] 12:31:34 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000015C72900880>
<...>
|
||
Comment 1•2 years ago
|
||
The reported failure is triggered for a beta simulation try build by the following JavaScript error:
[task 2023-04-19T12:31:33.413Z] 12:31:33 INFO - PID 8544 | 1681907493409 RemoteAgent DEBUG WebDriverBiDiConnection 6a0674da-d6b3-4913-8da0-b241e0d316da <- {"id":85,"error":"unknown error","message":"TypeError: stack is null","stacktrace":"#buildExceptionDetails@chrome://remote/content/webdriver-bidi/modules/windowglobal/script.sys.mjs:100:7\n#buildReturnValue@chr ... eiveMessage@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:57:37\n"}
The related source is here:
https://searchfox.org/mozilla-central/rev/31f5847a4494b3646edabbdd7ea39cb88509afe2/remote/webdriver-bidi/modules/windowglobal/script.sys.mjs#104
The above output is the response for the following command:
[task 2023-04-19T12:31:32.505Z] 12:31:32 INFO - PID 8544 | 1681907492402 RemoteAgent DEBUG WebDriverBiDiConnection 6a0674da-d6b3-4913-8da0-b241e0d316da -> {"id":85,"method":"script.evaluate","params":{"expression":"\n const controller = new AbortController();\n setTimeout(() => controller.abort(), 1000);\n ... GET',\n \n signal: controller.signal\n }).then(response => response.text());","target":{"context":"e64a0399-9c25-4cd7-9627-ea3933f40617"},"awaitPromise":true}}
Maybe this is a side-effect from bug 1826819 which added a timeout to the fetch helper?
|
||
Comment 2•2 years ago
|
||
Good find, that sounds plausible. The timeout uses a const, which triggers an issue here when used twice in the same context (interesting by the way, didn't think about that during the review). We should fix that.
Now I'm not exactly sure why this leaks to another test with a different failure, and why this would only show up intermittently but let's fix the const error first.
|
|
||
Updated•2 years ago
|
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 5•2 years ago
|
||
The patch from bug 1828950 landed on April 20th but we still have failure on autoland on April 22nd:
https://treeherder.mozilla.org/logviewer?job_id=413374034&repo=autoland&lineNumber=48271
While the network.beforeRequestSent has been successfully sent the script.evaluate command fails in building the exception details:
927d-49f6-988b-65e8d46c9b6a -> {"id":26,"method":"script.evaluate","params":{"expression":"\n {\n const controller = new AbortController();\n setTimeout(() => controll ... \n signal: controller.signal\n }).then(response => response.text());\n }","target":{"context":"9e26688e-0198-4787-ae4d-fee4f46708c6"},"awaitPromise":true}}
[task 2023-04-22T05:36:35.385Z] 05:36:35 INFO - PID 2808 | 1682141795370 RemoteAgent TRACE Received command script.evaluate for destination ROOT
[task 2023-04-22T05:36:35.385Z] 05:36:35 INFO - PID 2808 | 1682141795370 RemoteAgent TRACE Received command script.evaluateExpression for destination WINDOW_GLOBAL
[task 2023-04-22T05:36:35.385Z] 05:36:35 INFO - PID 2808 | 1682141795370 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-04-22T05:36:36.372Z] 05:36:36 INFO - PID 2808 | 1682141796373 RemoteAgent DEBUG WebDriverBiDiConnection d219c45a-927d-49f6-988b-65e8d46c9b6a <- {"method":"network.beforeRequestSent","params":{"context":"9e26688e-0198-4787-ae4d-fee4f46708c6","navigation":null,"redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":"web-platform.test:8000"},{"name":"User-Agent","value":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/114.0"},{"name":"Accept","value":"*/*"},{"name":"Accept-Language","value":"en-US,en;q=0.5"},{"name":"Accept-Encoding","value":"gzip, deflate"},{"name":"Referer","value":"http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html"},{"name":"Connection","value":"keep-alive"}],"headersSize":0,"method":"HEAD","request":"19","timings":{"originTime":0,"requestTime":1682141795366000,"redirectStart":0,"redirectEnd":0,"fetchStart":0,"dnsStart":0,"dnsEnd":0,"connectStart":0,"connectEnd":0,"tlsStart":0,"tlsEnd":0,"requestStart":0,"responseStart":0,"responseEnd":0},"url":"http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.txt"},"timestamp":1682141796373,"initiator":{"type":"other"}}}
[task 2023-04-22T05:36:36.379Z] 05:36:36 INFO - PID 2808 | 1682141796374 RemoteAgent DEBUG WebDriverBiDiConnection d219c45a-927d-49f6-988b-65e8d46c9b6a <- {"id":26,"error":"unknown error","message":"TypeError: can't access property \"column\", stack is null","stacktrace":"#buildExceptionDetails@chrome://remote/content/webdriver-bidi/modules/windowglobal/script.sys.mjs:101:7\n#buildReturnValue@chr ... eiveMessage@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:57:37\n"}
https://treeherder.mozilla.org/logviewer?job_id=413374034&repo=autoland&lineNumber=47080-47086
Julian, maybe this could be related to the missing async stack support (see bug 1745440 - which might not only be for log.entryAdded)? In most of the cases it seems to work now but getting details in case of failures would be great. So probably bug 1745440 is a dependency here.
|
|
||
Comment 6•2 years ago
|
||
If we use script.evaluate, then we should enable async stacktraces via https://searchfox.org/mozilla-central/rev/26790fecfcda622dab234b28859da721b80f3a35/remote/webdriver-bidi/Realm.sys.mjs#183
The issue with log.entryAdded, is that we bypass the realm creation, which should not be the case here.
My suspicion was Bug 1791715 (where stack is undefined if there are more than 50 stacktraces)
So previously I thought that the many const errors from the fetch helper were making us reach the 50 stacktraces limit, but now I'm not sure.
First of all, this helper should not throw. Maybe we encounter an error for which we really can't get a stacktrace? And we should stop assuming that stacktrace is always available (although it's great in order to detect missing stack traces).
I think we should first try to figure out which error we face here. If we can reproduce on try, we can check if enabling async straces or unlimited stacktraces helps.
|
|
||
Comment 7•2 years ago
|
||
The possibility to fetch that failure on try might be low given that it failed only 4 times within the last week. But yes, given that we were trying to build error details we must have hit an exception with that code. Maybe it's related to the AbortController?
I wonder if we actually want to print an extra log entry in case an exception is raised. Given that only some of the tests have the log.entryAdded event listener attached we might miss details.
Not sure if it would be helpful to always have such a listener attached for all the WebDriver BiDi tests, to at least print details? Lets discuss today.
|
|
||
Comment 8•2 years ago
|
||
I imagine a trace in the error codepath of our script evaluation helpers could be helpful. Although it might just be redundant information when we successfully return the error, because it should be serialized and visible in the logs? Maybe in a try / catch?
|
|
||
Comment 9•2 years ago
|
||
I reproduced it on try, the error is AbortError: The operation was aborted., so that's basically when we reach the timeout of 1s.
Interesting that the AbortController has no stack attached.
|
|
||
Comment 10•2 years ago
•
|
||
Practically speaking it means that we might have to increase the timeout for those tests (or increase the default to a few seconds instead of just 1?), and file another bug about missing stacks for AbortController + fetch.
Edit: It's not really related to AbortController, I think it's mostly about rejected promises + then
|
|
||
Comment 11•2 years ago
|
||
Note that we do not actually use catch() for the Promise chain. Maybe we should do and explicitly reject the result?
|
|
||
Updated•2 years ago
|
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 13•2 years ago
|
||
No more failures with this message over the last month.
Description
•