Hanging HTTP request when deleting session

[vovka3003]

System

• Version: 0.28.0
• Platform: Windows 8.1 SL
• Firefox: 83.0 (64-битный)
• Selenium: none (only http requests are used directly from geckodriver)

Testcase

When running commands sequentially:

POST [..url ..] / session
DELETE [..url ..] / window

if there was no url opening between them:

POST [..url ..] / url

the calling script hangs after executing a DELETE request. The geckodriver appears to be not responding to the request.

Sample (Pascal Script):

procedure test(Sender: TObject);
var s, sessionId :string;
begin
s := HttpQuery('POST','http://localhost:1234/session',conn_timeout,'',TStringStream.Create('{"capabilities": {}}'));
debug('Open session:');
debug(s);
  try
    sessionId := ReadJSonFromString(s).FindPath('value.sessionId').value;
  except
    sessionId := '';
  end;
    debug(sessionId);  // ok

      // If you uncomment this part of the code, the script will work fine.
      //s := HttpQuery('POST','http://localhost:1234/session/'+sessionId+'/url',conn_timeout,'',
      //TStringStream.Create(
      //'{"url": "https://yandex.ru"}'
      //));
      //debug(s)

debug('Close window')

// Problem:
s := HttpQuery('DELETE','http://localhost:1234/session/'+sessionId+'/window',conn_timeout,'',nil);

debug(s);
end;     

P.S. The same script, when used with operadriver and chromedriver, works correctly, even if there was no url request P.P.S. Sorry for the english (I am using google translate))

[whimboo]

Could you please attach a trace-level log from geckodriver? Read more about reporting actionable bugs in our contribution guidelines.

[vovka3003]

Hello! Here's what I got (sorry for the picasso):

[whimboo]

First, please provide a real trace log. What I see here is just debug. As such please re-read the link that I gave above. Further attach the log file instead of screenshots.

My suspicion here is that Firefox has a shutdown hang, which would be good to know more about. With the correct trace logs we should get closer to it. As such when creating the log file please also set toolkit.asyncshutdown.log=true for the Firefox preferences.

[whimboo]

Is this actually some new behavior or was it already present in Firefox 82 or earlier?

[dylanlive]

I have been experiencing this as well. My healthcheck script does the same thing as the author's example: POST /session and DELETE /session - nothing in between.

I'm seeing delete requests occasionally take ~1m4.92s. My reproduction rate in the last 6 hours: 33 out of 360 times

Firefox 81.0.1 was working well Firefox 82.0.3 started raising some errors (much less - currently unsure if it's the same issue. Can work to verify) Firefox 83 is significantly worse

This is on both Geckodriver 0.27 and 0.28.

I'll see if I can get you some trace logs. If there's an OS environment variable I can set the log level with, please let me know as that'll make it a bit quicker :)

[whimboo]

You will have to pass -vv to geckodriver, or set the preference marionette.log.level to true. And the same for the preference toolkit.asyncshutdown.log.

Mind checking if the first 83 beta already showed it? Which platform are you on?

[dylanlive]

Windows 10 Build 20H2

Trace Logs when the issue was present: https://gist.github.com/dylanlive/721854f7ef5ebd128f7b0b2106b1bbae

Time stamps of the delete request (outgoing and incoming response):

time="2020-12-11T18:50:31Z" level=info msg="-> /wd/hub/session/e8f77312-390b-4126-a7a6-bdd43ac8ed52"
time="2020-12-11T18:51:36Z" level=info msg="<- [200] | 1m4.916075737s | /wd/hub/session/e8f77312-390b-4126-a7a6-bdd43ac8ed52"

[dylanlive]

I'll see if I can step back some versions per your request (83b1), though this might take some time (I'm taking next week off, and holiday code freezes are coming up).

I kind of want to start with 82.0.3 to see if those (less frequent) timeouts are the same issue. Will report back.

[whimboo]

The recent log doesn't make sense. Are you running multiple checks in parallel, and all logging to the same file?

[whimboo]

But nevertheless it looks like a shutdown hang of Firefox. So getting the async shutdown log entries included would be pretty helpful.

[whimboo]

Btw what happens if you add a sleep in between the new session and delete? Does a delay of some seconds help? I could think of a startup/shutdown race condition here.

[dylanlive]

Not running multiple checks in parallel. Perhaps lines are slightly out of order when they get into my logging system. I'll see if I can grab the text file directly right after it occurs.

getting the async shutdown log entries included

Okay I'll try. Launching this via Selenium Grid so will need to see how to do that. To set the trace log level I'm currently requesting via selenium:

 {
    "desiredCapabilities": {
        "browserName": "firefox",
        "moz:firefoxOptions": {"log": {"level": "trace"}}
    }
}

what happens if you add a sleep in between the new session and delete

I shall try, thanks!

[dylanlive]

The recent log doesn't make sense

Here's direct from the log file from a 60 second delete request that just happened: https://gist.github.com/dylanlive/841bfe8ac97bad9ea376d03b0c00b92f

Still working on grabbing more data for you.

[whimboo]

One more thing that could be more helpful here would actually be a startup/shutdown profile as generated via the gecko profiler. See the following documentation: https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Profiling_with_the_Built-in_Profiler#Profiling_Firefox_Startup

Set both MOZ_PROFILER_STARTUP and MOZ_PROFILER_SHUTDOWN environment variables, and a JSON file will be created. You can upload that via profiler.firefox.com, and then make it public. Thanks.

[dylanlive]

@whimboo Noted, will give it a shot when I have a chance. This might take a few weeks due to the holidays.

For now, I do have some logs on Firefox 82.0.3 which just repo'd taking 1m4.93 to delete the session. https://gist.github.com/dylanlive/8f61da74014e2fa9a54809730e0b0c50

I replicated this 3/360 times on 82.0.3 - far less than 83.0, but replicable.

So the replication rate I've experienced:

• 82.0.3: 3/360
• 83.0: 33/360

[whimboo]

Ok, good to know. As such I think it would make more sense to use 83.0 to get the gecko profile. With that it should be pretty easy to see what's broken.

If someone else could run the steps as described in my last comment while @dylanlive is out I would appreciate.

[dylanlive]

It seems this may no longer be an issue with the latest Firefox. I upgraded to Firefox 84.0.2 and I'm not seeing errors anymore. I'll keep an eye on this.

Prior to the upgrade, I did get a chance to put in a 2 second sleep. That also helped with the issue.

[whimboo]

Good to hear that. @vovka3003 can you please re-check with Firefox 84 if you are still affected or if it's also fixed for you? Thanks.

[whimboo]

Marking as fixed given the recent comments and no further reply from @vovka3003.