search

mozilla / geckodriver

WebDriver for Firefox
https://firefox-source-docs.mozilla.org/testing/geckodriver/
Mozilla Public License 2.0
7.03k stars 1.51k forks source link

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

Open soulgalore opened 5 months ago

soulgalore commented 5 months ago

System

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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 commented 5 months ago

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

whimboo commented 5 months ago

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

soulgalore commented 5 months ago

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 commented 5 months ago

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

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 commented 4 months ago

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 ??