Closed
Bug 1767543
Opened 2 years ago
Closed 2 years ago
Perma Android 7.0 wd [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/log/entry_added/console.py | expected OK
Categories
(Core :: DOM: Core & HTML, defect, P2)
Core
DOM: Core & HTML
Tracking
()
RESOLVED
FIXED
102 Branch
| Tracking | Status | |
|---|---|---|
| firefox-esr91 | --- | unaffected |
| firefox100 | --- | unaffected |
| firefox101 | --- | unaffected |
| firefox102 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jdescottes)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [bidi-m3-mvp][webdriver:external])
Attachments
(1 file)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=376704993&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FaqGjfdOTMSDlm3yXzcKTQ/runs/0/artifacts/public/logs/live_backing.log
[task 2022-05-03T20:56:33.927Z] 20:56:33 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/console.py::test_level[table-info]
[task 2022-05-03T20:56:33.941Z] 20:56:33 INFO - PID 2658 | 1651611393940 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/execute/sync {"script": "console.table('foo')", "args": []}
[task 2022-05-03T20:56:33.955Z] 20:56:33 INFO - PID 2658 | 1651611393954 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:33.974Z] 20:56:33 INFO - STDOUT: PASSED
[task 2022-05-03T20:56:33.975Z] 20:56:33 INFO - PID 2658 | 1651611393974 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/timeouts {"implicit": 0}
[task 2022-05-03T20:56:33.978Z] 20:56:33 INFO - PID 2658 | 1651611393977 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:33.979Z] 20:56:33 INFO - PID 2658 | 1651611393978 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/timeouts {"pageLoad": 300000}
[task 2022-05-03T20:56:33.983Z] 20:56:33 INFO - PID 2658 | 1651611393982 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:33.984Z] 20:56:33 INFO - PID 2658 | 1651611393983 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/timeouts {"script": 30000}
[task 2022-05-03T20:56:33.987Z] 20:56:33 INFO - PID 2658 | 1651611393986 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:33.990Z] 20:56:33 INFO - PID 2658 | 1651611393987 webdriver::server DEBUG -> GET /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window
[task 2022-05-03T20:56:33.992Z] 20:56:33 INFO - PID 2658 | 1651611393990 webdriver::server DEBUG <- 200 OK {"value":"e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:33.992Z] 20:56:33 INFO - PID 2658 | 1651611393991 webdriver::server DEBUG -> GET /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window
[task 2022-05-03T20:56:33.995Z] 20:56:33 INFO - PID 2658 | 1651611393994 webdriver::server DEBUG <- 200 OK {"value":"e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:33.996Z] 20:56:33 INFO - PID 2658 | 1651611393995 webdriver::server DEBUG -> GET /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window/handles
[task 2022-05-03T20:56:33.999Z] 20:56:33 INFO - PID 2658 | 1651611393998 webdriver::server DEBUG <- 200 OK {"value":["e6575abd-8b09-49f4-8e8a-5b51e855908f"]}
[task 2022-05-03T20:56:34.000Z] 20:56:34 INFO - PID 2658 | 1651611393999 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window {"handle": "e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:34.003Z] 20:56:34 INFO - PID 2658 | 1651611394002 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:34.004Z] 20:56:34 INFO - PID 2658 | 1651611394003 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/alert/dismiss {}
[task 2022-05-03T20:56:34.008Z] 20:56:34 INFO - PID 2658 | 1651611394006 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:183:5\nNoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.jsm:384:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.js:2508:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2419:8\ndespatch@chrome://remote/content/marionette/server.js:306:40\nexecute@chrome://remote/content/marionette/server.js:279:16\nonPacket/<@chrome://remote/content/marionette/server.js:252:20\nonPacket@chrome://remote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"}}
[task 2022-05-03T20:56:34.009Z] 20:56:34 INFO - PID 2658 | 1651611394007 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window {"handle": "e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:34.011Z] 20:56:34 INFO - PID 2658 | 1651611394010 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:34.012Z] 20:56:34 INFO - PID 2658 | 1651611394011 webdriver::server DEBUG -> GET /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window
[task 2022-05-03T20:56:34.014Z] 20:56:34 INFO - PID 2658 | 1651611394013 webdriver::server DEBUG <- 200 OK {"value":"e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:34.015Z] 20:56:34 INFO - PID 2658 | 1651611394014 webdriver::server DEBUG -> GET /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window/handles
[task 2022-05-03T20:56:34.017Z] 20:56:34 INFO - PID 2658 | 1651611394016 webdriver::server DEBUG <- 200 OK {"value":["e6575abd-8b09-49f4-8e8a-5b51e855908f"]}
[task 2022-05-03T20:56:34.018Z] 20:56:34 INFO - PID 2658 | 1651611394017 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/window {"handle": "e6575abd-8b09-49f4-8e8a-5b51e855908f"}
[task 2022-05-03T20:56:34.022Z] 20:56:34 INFO - PID 2658 | 1651611394020 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:34.022Z] 20:56:34 INFO - PID 2658 | 1651611394021 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/frame {"id": null}
[task 2022-05-03T20:56:34.028Z] 20:56:34 INFO - PID 2658 | 1651611394027 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:56:34.031Z] 20:56:34 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/log/entry_added/console.py::test_level[trace-debug]
[task 2022-05-03T20:56:34.043Z] 20:56:34 INFO - PID 2658 | 1651611394042 webdriver::server DEBUG -> POST /session/b7b69c93-4f9d-47c0-af1d-ee6f655d8426/execute/sync {"script": "console.trace('foo')", "args": []}
[task 2022-05-03T20:56:34.055Z] 20:56:34 INFO - PID 2658 | 1651611394054 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-05-03T20:57:49.123Z] 20:57:49 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/log/entry_added/console.py | expected OK
[task 2022-05-03T20:57:49.123Z] 20:57:49 INFO - TEST-INFO took 80003ms
[task 2022-05-03T20:57:59.183Z] 20:57:59 WARNING - Forcibly terminating runner process
[task 2022-05-03T20:57:59.344Z] 20:57:59 INFO - PID 2906 | 1651611479341 geckodriver INFO Listening on 127.0.0.1:43373
[task 2022-05-03T20:57:59.346Z] 20:57:59 INFO - Starting runner
[task 2022-05-03T20:57:59.638Z] 20:57:59 INFO - TEST-START | /webdriver/tests/bidi/log/entry_added/console_args.py
|
||
Comment 1•2 years ago
|
||
Hi Doug! Can you please take a look at this?
Thank you!
Flags: needinfo?(dothayer)
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•2 years ago
|
||
When checking the adb logcat I can see the following error:
05-03 20:56:33.295 7401 7416 I Gecko : 1651611393295 Marionette DEBUG 0 -> [0,156,"WebDriver:ExecuteScript",{"args":[],"script":"console.trace('foo')"}]
05-03 20:56:33.301 7427 7445 E Web Content: [JavaScript Error: "TypeError: can't access property "indexOf", aSourceURL is undefined" {file: "resource://gre/modules/GeckoViewConsole.jsm" line: 176}]
05-03 20:56:33.301 7427 7445 E Web Content: abbreviateSourceURL@resource://gre/modules/GeckoViewConsole.jsm:176:23
05-03 20:56:33.301 7427 7445 E Web Content: _handleConsoleMessage@resource://gre/modules/GeckoViewConsole.jsm:89:29
05-03 20:56:33.301 7427 7445 E Web Content: CS_recordEvent@resource://gre/modules/ConsoleAPIStorage.jsm:173:17
05-03 20:56:33.301 7427 7445 E Web Content: @moz-nullprincipal:{f0be1c5e-6a0e-451b-8463-f7d83785669e}:2:15
05-03 20:56:33.301 7427 7445 E Web Content: @moz-nullprincipal:{f0be1c5e-6a0e-451b-8463-f7d83785669e}:3:8
05-03 20:56:33.301 7427 7445 E Web Content: evaluate.sandbox/promise<@chrome://remote/content/marionette/evaluate.js:157:10
05-03 20:56:33.301 7427 7445 E Web Content: evaluate.sandbox@chrome://remote/content/marionette/evaluate.js:133:17
05-03 20:56:33.301 7427 7445 E Web Content: executeScript@chrome://remote/content/marionette/actors/MarionetteCommandsChild.jsm:223:21
05-03 20:56:33.301 7427 7445 E Web Content: receiveMessage@chrome://remote/content/marionette/actors/MarionetteCommandsChild.jsm:95:31
05-03 20:56:33.301 7427 7445 I Gecko : [Child 7427, Main Thread] WARNING: Failed to record a console event.: file /builds/worker/checkouts/gecko/dom/console/Console.cpp:1551
|
||
Updated•2 years ago
|
status-firefox100:
--- → unaffected
status-firefox101:
--- → unaffected
status-firefox102:
--- → affected
status-firefox-esr91:
--- → unaffected
|
Assignee | |
Comment 4•2 years ago
|
||
Looking at this.
Regarding the error mentioned in the previous comment:
The event object we get for a console.trace("foo") has a single argument "foo" (https://searchfox.org/mozilla-central/rev/997a56b018662e2940c99bbaf57a6ac9d1aa5422/dom/console/ConsoleAPIStorage.jsm#109), but GeckoView expects the first argument to be an object with a filename property: https://searchfox.org/mozilla-central/rev/997a56b018662e2940c99bbaf57a6ac9d1aa5422/mobile/android/modules/geckoview/GeckoViewConsole.jsm#87-92
However this is not new, it was already in the logs before the patch, and that doesn't actually explain the failure.
|
|
Assignee | |
Comment 5•2 years ago
|
||
Well the error actually explains the problem. The new API is listener/callback based, but there's no try catch when calling the callbacks.
So any faulty callback (such as the geckoview one) will prevent all the other listeners from being called.
Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
|
|
Assignee | |
Comment 6•2 years ago
|
||
A failing callback would prevent calling any other callback. Added a try catch and a test
|
|
Assignee | |
Updated•2 years ago
|
Flags: needinfo?(dothayer)
|
|
Assignee | |
Updated•2 years ago
|
Points: --- → 1
Whiteboard: [bidi-m3-mvp]
|
|
Assignee | |
Updated•2 years ago
|
Whiteboard: [bidi-m3-mvp] → [bidi-m3-mvp][webdriver:external]
|
||
Updated•2 years ago
|
Has Regression Range: --- → yes
Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d99818286d15 Add try/catch around callbacks for ConsoleAPIStorage.jsm r=nchevobbe
|
||
Updated•2 years ago
|
Priority: P5 → P2
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 9•2 years ago
|
||
| bugherder | ||
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 102 Branch
|
|
||
Updated•2 years ago
|
Component: geckodriver → DOM: Core & HTML
Product: Testing → Core
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•