Closed
Bug 1764620
Opened 2 years ago
Closed 2 years ago
Intermittent [tier 2] /webdriver/tests/get_element_css_value/get.py | unknown error (500): Failed to decode response from marionette
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=374387979&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FAEiWXKWSCOPN6MGiy2-0A/runs/0/artifacts/public/logs/live_backing.log
[task 2022-04-13T18:01:10.311Z] 18:01:10 INFO - STDOUT: PASSED
[task 2022-04-13T18:01:10.312Z] 18:01:10 INFO - PID 3606 | 1649872870311 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/timeouts {"implicit": 0}
[task 2022-04-13T18:01:10.315Z] 18:01:10 INFO - PID 3606 | 1649872870314 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.316Z] 18:01:10 INFO - PID 3606 | 1649872870315 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/timeouts {"pageLoad": 300000}
[task 2022-04-13T18:01:10.321Z] 18:01:10 INFO - PID 3606 | 1649872870320 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.323Z] 18:01:10 INFO - PID 3606 | 1649872870322 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/timeouts {"script": 30000}
[task 2022-04-13T18:01:10.325Z] 18:01:10 INFO - PID 3606 | 1649872870325 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.327Z] 18:01:10 INFO - PID 3606 | 1649872870326 webdriver::server DEBUG -> GET /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window
[task 2022-04-13T18:01:10.329Z] 18:01:10 INFO - PID 3606 | 1649872870328 webdriver::server DEBUG <- 200 OK {"value":"b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.330Z] 18:01:10 INFO - PID 3606 | 1649872870329 webdriver::server DEBUG -> GET /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window
[task 2022-04-13T18:01:10.334Z] 18:01:10 INFO - PID 3606 | 1649872870333 webdriver::server DEBUG <- 200 OK {"value":"b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.335Z] 18:01:10 INFO - PID 3606 | 1649872870334 webdriver::server DEBUG -> GET /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window/handles
[task 2022-04-13T18:01:10.339Z] 18:01:10 INFO - PID 3606 | 1649872870338 webdriver::server DEBUG <- 200 OK {"value":["b5ac2152-697d-464a-bc2b-a6833aa457cd"]}
[task 2022-04-13T18:01:10.340Z] 18:01:10 INFO - PID 3606 | 1649872870339 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window {"handle": "b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.344Z] 18:01:10 INFO - PID 3606 | 1649872870343 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.346Z] 18:01:10 INFO - PID 3606 | 1649872870344 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/alert/dismiss {}
[task 2022-04-13T18:01:10.351Z] 18:01:10 INFO - PID 3606 | 1649872870350 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-04-13T18:01:10.352Z] 18:01:10 INFO - PID 3606 | 1649872870351 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window {"handle": "b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.355Z] 18:01:10 INFO - PID 3606 | 1649872870354 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.355Z] 18:01:10 INFO - PID 3606 | 1649872870355 webdriver::server DEBUG -> GET /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window
[task 2022-04-13T18:01:10.357Z] 18:01:10 INFO - PID 3606 | 1649872870357 webdriver::server DEBUG <- 200 OK {"value":"b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.358Z] 18:01:10 INFO - PID 3606 | 1649872870358 webdriver::server DEBUG -> GET /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window/handles
[task 2022-04-13T18:01:10.361Z] 18:01:10 INFO - PID 3606 | 1649872870360 webdriver::server DEBUG <- 200 OK {"value":["b5ac2152-697d-464a-bc2b-a6833aa457cd"]}
[task 2022-04-13T18:01:10.362Z] 18:01:10 INFO - PID 3606 | 1649872870361 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/window {"handle": "b5ac2152-697d-464a-bc2b-a6833aa457cd"}
[task 2022-04-13T18:01:10.366Z] 18:01:10 INFO - PID 3606 | 1649872870365 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.367Z] 18:01:10 INFO - PID 3606 | 1649872870367 webdriver::server DEBUG -> POST /session/9a397b52-c1d7-40ba-9244-dda4149c3247/frame {"id": null}
[task 2022-04-13T18:01:10.375Z] 18:01:10 INFO - PID 3606 | 1649872870374 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-04-13T18:01:10.378Z] 18:01:10 INFO - PID 3606 | 1649872870377 webdriver::server DEBUG -> DELETE /session/9a397b52-c1d7-40ba-9244-dda4149c3247
[task 2022-04-13T18:01:10.985Z] 18:01:10 INFO - PID 3606 | 1649872870984 webdriver::server DEBUG Teardown session
[task 2022-04-13T18:01:10.985Z] 18:01:10 INFO - PID 3606 | 1649872870984 geckodriver::android DEBUG Force stopping the Android package: org.mozilla.geckoview.test_runner
[task 2022-04-13T18:01:10.985Z] 18:01:10 INFO - PID 3606 | 1649872870984 mozdevice DEBUG Force stopping Android package: org.mozilla.geckoview.test_runner
[task 2022-04-13T18:01:10.986Z] 18:01:10 INFO - PID 3606 | 1649872870984 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2022-04-13T18:01:10.986Z] 18:01:10 INFO - PID 3606 | 1649872870984 mozdevice TRACE execute_host_command: << []
[task 2022-04-13T18:01:10.987Z] 18:01:10 INFO - PID 3606 | 1649872870984 mozdevice TRACE execute_host_command: >> "shell:am force-stop org.mozilla.geckoview.test_runner"
[task 2022-04-13T18:01:11.228Z] 18:01:11 INFO - PID 3606 | 1649872871227 mozdevice TRACE execute_host_command: << ""
[task 2022-04-13T18:01:11.229Z] 18:01:11 INFO - PID 3606 | 1649872871227 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2022-04-13T18:01:11.229Z] 18:01:11 INFO - PID 3606 | 1649872871227 mozdevice TRACE execute_host_command: << []
[task 2022-04-13T18:01:11.230Z] 18:01:11 INFO - PID 3606 | 1649872871227 mozdevice TRACE execute_host_command: >> "shell:am clear-debug-app org.mozilla.geckoview.test_runner"
[task 2022-04-13T18:01:11.491Z] 18:01:11 INFO - PID 3606 | 1649872871489 mozdevice TRACE execute_host_command: << ""
[task 2022-04-13T18:01:11.491Z] 18:01:11 INFO - PID 3606 | 1649872871489 geckodriver::android DEBUG Disabled reading from configuration file
[task 2022-04-13T18:01:11.492Z] 18:01:11 INFO - PID 3606 | 1649872871489 mozdevice DEBUG Deleting /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml
[task 2022-04-13T18:01:11.492Z] 18:01:11 INFO - PID 3606 | 1649872871490 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2022-04-13T18:01:11.493Z] 18:01:11 INFO - PID 3606 | 1649872871490 mozdevice TRACE execute_host_command: << []
[task 2022-04-13T18:01:11.493Z] 18:01:11 INFO - PID 3606 | 1649872871490 mozdevice TRACE execute_host_command: >> "shell:rm -rf /data/local/tmp/org.mozilla.geckoview.test_runner-geckoview-config.yaml"
[task 2022-04-13T18:01:11.498Z] 18:01:11 INFO - PID 3606 | 1649872871497 mozdevice TRACE execute_host_command: << ""
[task 2022-04-13T18:01:11.499Z] 18:01:11 INFO - PID 3606 | 1649872871497 geckodriver::android DEBUG Deleted GeckoView configuration file
[task 2022-04-13T18:01:11.499Z] 18:01:11 INFO - PID 3606 | 1649872871497 mozdevice DEBUG Deleting /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root
[task 2022-04-13T18:01:11.500Z] 18:01:11 INFO - PID 3606 | 1649872871497 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2022-04-13T18:01:11.500Z] 18:01:11 INFO - PID 3606 | 1649872871498 mozdevice TRACE execute_host_command: << []
[task 2022-04-13T18:01:11.501Z] 18:01:11 INFO - PID 3606 | 1649872871498 mozdevice TRACE execute_host_command: >> "shell:rm -rf /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root"
[task 2022-04-13T18:01:11.524Z] 18:01:11 INFO - PID 3606 | 1649872871523 mozdevice TRACE execute_host_command: << ""
[task 2022-04-13T18:01:11.525Z] 18:01:11 INFO - PID 3606 | 1649872871523 geckodriver::android DEBUG Deleted test root folder: /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root
[task 2022-04-13T18:01:11.525Z] 18:01:11 INFO - PID 3606 | 1649872871523 mozdevice TRACE execute_host_command: >> "host:transport:emulator-5554"
[task 2022-04-13T18:01:11.526Z] 18:01:11 INFO - PID 3606 | 1649872871523 mozdevice TRACE execute_host_command: << []
[task 2022-04-13T18:01:11.526Z] 18:01:11 INFO - PID 3606 | 1649872871523 mozdevice TRACE execute_host_command: >> "host-serial:emulator-5554:killforward:tcp:35445"
[task 2022-04-13T18:01:11.526Z] 18:01:11 INFO - PID 3606 | 1649872871523 mozdevice TRACE execute_host_command: << ""
[task 2022-04-13T18:01:11.527Z] 18:01:11 INFO - PID 3606 | 1649872871523 geckodriver::android DEBUG Marionette port forward (35445 -> 2829) stopped
[task 2022-04-13T18:01:11.529Z] 18:01:11 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/get_element_css_value/get.py | unknown error (500): Failed to decode response from marionette
[task 2022-04-13T18:01:11.529Z] 18:01:11 INFO - TEST-INFO took 6636ms
[task 2022-04-13T18:01:11.536Z] 18:01:11 INFO - PID 3606 | 1649872871523 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to decode response from marionette","stacktrace":""}}
[task 2022-04-13T18:01:11.547Z] 18:01:11 INFO - PID 3606 | 1649872871545 webdriver::server DEBUG -> GET /status
[task 2022-04-13T18:01:11.548Z] 18:01:11 INFO - PID 3606 | 1649872871545 webdriver::server DEBUG <- 200 OK {"value":{"message":"","ready":true}}
[task 2022-04-13T18:01:11.643Z] 18:01:11 INFO - Closing logging queue
[task 2022-04-13T18:01:11.643Z] 18:01:11 INFO - queue closed
[task 2022-04-13T18:01:11.821Z] 18:01:11 INFO - PID 3676 | 1649872871819 geckodriver INFO Listening on 127.0.0.1:58417
[task 2022-04-13T18:01:11.821Z] 18:01:11 INFO - Starting runner
[task 2022-04-13T18:01:12.180Z] 18:01:12 INFO - TEST-START | /webdriver/tests/get_element_css_value/user_prompts.py
Comment 1•2 years ago
|
||
:whimboo, since you are the author of the regressor, bug 1749444, could you take a look?
For more information, please visit auto_nag documentation.
Flags: needinfo?(hskupin)
Comment 2•2 years ago
|
||
Based on the Android logcat the testrunner application died:
04-13 18:01:09.017 31168 31183 I Gecko : 1649872869017 Marionette DEBUG 0 -> [0,95,"Marionette:Quit",{"flags":["eForceQuit"]}]
04-13 18:01:09.018 31168 31183 I Gecko : 1649872869018 Marionette INFO Stopped listening on port 2829
04-13 18:01:09.019 31229 31254 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-13 18:01:09.026 31168 31183 D GeckoViewNavigation: canClose
04-13 18:01:09.032 31168 31183 D GeckoViewContent: handleEvent: DOMWindowClose
04-13 18:01:09.033 31168 31183 I Gecko : 1649872869033 Marionette TRACE Received observer notification quit-application
04-13 18:01:09.033 31168 31183 I Gecko : 1649872869033 Marionette TRACE Received observer notification quit-application
04-13 18:01:09.034 31168 31183 I Gecko : 1649872869034 Marionette DEBUG Marionette stopped listening
04-13 18:01:09.034 31168 31183 D GeckoThread: State changed to EXITING
04-13 18:01:09.035 31168 31183 I Gecko : 1649872869035 Marionette DEBUG 0 <- [1,95,null,{"cause":"shutdown","forced":false}]
04-13 18:01:09.037 31168 31183 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":false}
04-13 18:01:09.038 31168 31183 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":false}
04-13 18:01:09.038 31168 31183 I Gecko : nsWindow[0x7f7846509200]::Show 0
04-13 18:01:09.042 31168 31183 D GeckoViewNavigation: onDisable
04-13 18:01:09.042 31168 31183 D GeckoViewProcessHangMonitor: onDisable
04-13 18:01:09.043 31168 31183 D GeckoViewModule: unregisterListener
04-13 18:01:09.043 31194 31210 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
04-13 18:01:09.043 31168 31183 D GeckoViewProcessHangMonitor: onDestroy
04-13 18:01:09.043 31229 31254 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-13 18:01:09.047 31194 31210 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
04-13 18:01:09.047 31194 31210 D GeckoViewAutoFill[C]: handleEvent: pagehide
04-13 18:01:09.047 31194 31210 D GeckoViewAutofill: Clearing auto-fill
04-13 18:01:09.068 31229 31254 D EGL_emulation: eglMakeCurrent: 0x7f7874e7d520: ver 3 0 (tinfo 0x7f786a5bcea0)
04-13 18:01:09.069 31168 31168 F MOZ_Assert: Assertion failure: pthread_rwlock_unlock(&mRWLock) == 0 (pthread_rwlock_unlock failed), at /builds/worker/checkouts/gecko/mozglue/misc/RWLock_posix.cpp:44
04-13 18:01:09.069 31168 31168 F MOZ_Assert: #01: _ZN7mozilla6detail10RWLockImpl10readUnlockEv[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libmozglue.so +0xb27c0]
04-13 18:01:09.069 31168 31168 F MOZ_Assert:
04-13 18:01:09.069 31168 31168 F MOZ_Assert: #02: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x3fa3959]
04-13 18:01:09.069 31168 31168 F MOZ_Assert:
04-13 18:01:09.069 31168 31168 F MOZ_Assert: #03: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x3fa77df]
04-13 18:01:09.069 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #04: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x1ef2260]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #05: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x1e5e670]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #06: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x1a9a9b0]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #07: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x1a99d3d]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #08: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x1a9a3d0]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #09: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x3f7e52a]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.070 31168 31168 F MOZ_Assert: #10: oatexec[/data/app/org.mozilla.geckoview.test_runner-1/oat/x86_64/base.odex +0xd6e026]
04-13 18:01:09.070 31168 31168 F MOZ_Assert:
04-13 18:01:09.074 31168 31168 W google-breakpad: ExceptionHandler::GenerateDump cloned child
04-13 18:01:09.074 31168 31168 W google-breakpad: 31305
04-13 18:01:09.074 31168 31168 W google-breakpad:
04-13 18:01:09.074 31168 31168 W google-breakpad: ExceptionHandler::SendContinueSignalToChild sent continue signal to child
04-13 18:01:09.074 31305 31168 W google-breakpad: ExceptionHandler::WaitForContinueSignal waiting for continue signal...
04-13 18:01:09.555 1658 1729 E TaskPersister: File error accessing recents directory (directory doesn't exist?).
04-13 18:01:09.621 1658 2122 I WindowManager: WIN DEATH: Window{192b501 u0 SurfaceView - org.mozilla.geckoview.test_runner/org.mozilla.geckoview.test_runner.App}
We would still need bug 1490906 to get proper crash reports. Otherwise this is not a regression but a new test job.
Comment hidden (Intermittent Failures Robot) |
Comment 4•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Comment 5•2 years ago
|
||
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in
before you can comment on or make changes to this bug.
Description
•