Closed Bug 1764620 Opened 3 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

Tracking

(Not tracked)

Status:

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Treeherder Bug Filer

Reporter

Description

•

3 years ago

treeherder

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

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

3 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)

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 2

•

3 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.

Depends on: 1490906

Flags: needinfo?(hskupin)

Keywords: regression

No longer regressed by: 1749444

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

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

BMO Automation

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.

Bugzilla

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)

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5