Testing on Firefox on Android generates Failed to decode response from marionette

[soulgalore]

System

• Version: 0.34.0
• Platform: macOS and Debian Raspberry running tests on an Android Samsung A51
• Firefox: 122.0
• Selenium: 4.17.0

Testcase

I've started to run performance test using Browsertime targeting Android phone Samsung A51 and when I try to do 11 test runs one or more runs always get Failed to decode response from marionette. I get the same running the tests from MacOS and from a Raspberry Pi. There was a couple years I tried the last so I wonder how do I actually get some useful logs? I've attached the ones I get running in verbose mode.

Stacktrace

1706802889404	geckodriver::android	DEBUG	Deleted GeckoView configuration file
1706802889404	mozdevice	DEBUG	Deleting /sdcard/Android/data/org.mozilla.firefox/files/test_root
1706802889644	mozdevice	TRACE	execute_host_command: >> "host:transport:R58N604Y0DW"
1706802889764	mozdevice	TRACE	execute_host_command: << []
1706802889764	mozdevice	TRACE	execute_host_command: >> "shell:su -c 'rm -rf /sdcard/Android/data/org.mozilla.firefox/files/test_root'"
1706802889950	mozdevice	TRACE	execute_host_command: << ""
1706802889950	geckodriver::android	DEBUG	Deleted test root folder: /sdcard/Android/data/org.mozilla.firefox/files/test_root
1706802890190	mozdevice	TRACE	execute_host_command: >> "host:transport:R58N604Y0DW"
1706802890310	mozdevice	TRACE	execute_host_command: << []
1706802890310	mozdevice	TRACE	execute_host_command: >> "host-serial:R58N604Y0DW:killforward:tcp:42681"
1706802890430	mozdevice	TRACE	execute_host_command: << ""
1706802890430	geckodriver::android	DEBUG	Marionette port forward (42681 -> 2829) stopped
1706802890671	mozdevice	TRACE	execute_host_command: >> "host:transport:R58N604Y0DW"
1706802890791	mozdevice	TRACE	execute_host_command: << []
1706802890791	mozdevice	TRACE	execute_host_command: >> "host-serial:R58N604Y0DW:killforward:tcp:9222"
1706802890911	mozdevice	TRACE	execute_host_command: << ""
1706802890911	geckodriver::android	DEBUG	WebSocket port forward (9222 -> 9222) stopped
1706802890911	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"unknown error","message":"Failed to decode response from marionette","stacktrace":""}}
[2024-02-01 15:54:50] ERROR: [browsertime] WebDriverError: Failed to decode response from marionette

[whimboo]

This is most likely a crash of Firefox. Would you mind checking the adb logcat for further information? Getting the crash minidump would be helpful. See our documentation for the necessary steps.

[soulgalore]

I'll try to see if I can get the crash minidump tomorrow. From logcat I get this:

02-01 21:37:16.456 30337 30391 D GeckoIdleService: Idle timer callback: tell observer 0x7561b0ec68 user is idle
02-01 21:37:19.009 30337 30337 I GeckoSession: handleMessage GeckoView:PageStart uri=
02-01 21:37:21.129 30337 30337 I GeckoSession: handleMessage GeckoView:PageStop uri=null
02-01 21:37:43.728 30337 30391 D GeckoIdleService: Get idle time: time since reset 32282 msec
02-01 21:37:54.570 30337 30391 I Gecko   : 1706819874570	Marionette	INFO	Stopped listening on port 2829
02-01 21:37:54.964 30719 30719 I ServiceChildProcess: Destroying GeckoServiceChildProcess
02-01 21:37:56.643  4926  4926 E audit   : type=1701 audit(1706819876.639:11676): auid=4294967295 uid=10302 gid=10302 ses=4294967295 subj=u:r:untrusted_app:s0:c46,c257,c512,c768 pid=30337 comm="Gecko" exe="/system/bin/app_process64" sig=11 res=1
02-01 21:37:56.704 30450 30629 I Gecko   : Exiting due to channel error.
02-01 21:37:56.825  5452  8831 W ActivityManager: Exception when unbinding service org.mozilla.firefox/org.mozilla.gecko.process.GeckoChildProcessServices$tab16
02-01 21:37:56.826  5452  8831 W ActivityManager: Exception when unbinding service org.mozilla.firefox/org.mozilla.gecko.process.GeckoChildProcessServices$gpu

[whimboo]

Would you mind adding more lines that are coming before the above ones? When got Firefox started? After some amount of time we are shutting down Firefox if no connection can be made to Marionette.

[soulgalore]

Ok, hope I got it better this time:

https://gist.github.com/soulgalore/c3af64b71215ab5e4fee6e9163a624c5

About the crash log, is it Firefox that stores it (so I should point out a directory on the phone) or is it Geckodriver?

[whimboo]

This is interesting given that it doesn't really show that a process crashed. So some details after my quick investigation:

1. The log output Stopped listening on port XYZ comes from calling server.setAcceptConnections(false)
2. Because no WebDriver session has been created yet, such a call can only come from server.stop(), which itself is called by MarionetteParentProcess.uninit().
3. The only place where uninit() is called when we receive an observer notification with the topic quit-application.

Peter, I assume that you did not enable trace logs yet? It would be important to see further details from the debug and trace log entries, which hopefully could give more details.

[soulgalore]

Ok here is a new batch, first from Geckodriver: https://gist.github.com/soulgalore/10024f558d71106ea1837aa970718be7

And then logcat: https://gist.github.com/soulgalore/73d571435a985f424718290745fc91fc

Hope that gives some extra information!

[whimboo]

This adb logcat looks all fine. The WebDriver session is created and a couple of commands are run until Marionette:Quit is send which causes the browser to shutdown. I can also see that [1,57,null,{"cause":"shutdown","forced":false,"in_app":true}] is returned, which should be the last message from Marionette.

There is a Failed to close browser connection: unknown error in the geckodriver log, which is puzzling. Not sure where this comes from. Would you have a chance to add some logging to geckodriver and check locally?

[soulgalore]

Not sure how I add more logging? I've been using serviceBuilder.enableVerboseLogging(true) in Selenium but maybe there's a better way?

[whimboo]

It would require you to touch geckodriver code and compile it. It's not hard and I'm happy to help with that.

[soulgalore]

Thanks, ok, I can do that early next week. I've compiled it for ARM already, can you show me what I need to do to turn on the extra logging before I compile?

[whimboo]

Thanks! So first it would be good to get the stack at these two locations:

• https://searchfox.org/mozilla-central/rev/14dc8f0e748d44778a02ffcf9ebcda3851b2bf9e/testing/geckodriver/src/marionette.rs#221
• https://searchfox.org/mozilla-central/rev/14dc8f0e748d44778a02ffcf9ebcda3851b2bf9e/testing/geckodriver/src/marionette.rs#1371

Then you can always add debug!("msg") lines to output some status so that we can see which path in the code it uses.

[nakodavati]

I am getting same issue
self = <selenium.webdriver.remote.errorhandler.ErrorHandler object at 0x40061b99d0>
response = {'status': 500, 'value': '{"value":{"error":"unknown error","message":"Failed to decode response from marionette","stacktrace":""}}'}.

i am using selenium 4.17.0, geckodriver : 0.33.0 , firefox-102.0.1

when i am trying to execute tests in firefox inside container facing above error , any solution ??