1668828 - Active connections to site higher than network.http.max-persistent-connections-per-server , website no longer works until restart of Firefox

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect, P2)

Description

[ericj]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36 Edg/84.0.522.63

Steps to reproduce:

Firefox 80.0 on openSUSE Leap 15.1 x86_64.

At random times, a specific site (internal to my company, not going through a proxy), becomes unresponsive. The page loading spinner (on the top of the tab) will just sit there and spin. Only a restart of Firefox will fix it. The website is on an Apache HTTPD server (2.4.33).

Actual results:

Site hangs, when clicking a link on the site, the spinner on the tab will just spin forever. However, after investigating further, about:networking shows 8 active connections. But the network.http.max-persistent-connections-per-server is set to 6. So it is exceeding that max.

from about:networking (HTTP tab):
Port: 8444
HTTP version: HTTP <=1.1
SSL: true
Active: 8
Idle: 0

netstat does not show any active connections to the web server. The web server logs do no show any hits.

Expected results:

about:networking should show it not exceeding the maximum connections per server. The browser should not hang.

Note: This issue is not new for Firefox 80. It has been happening for many versions in the past.

Comment 1

[ericj]

Additional information: You can still use other tabs in the same browser instance to successfully visit other sites. Closing the tab on the hanging site and opening it up in a new tab still does not allow you to view the affected website (it just hangs). You have to close Firefox completely to recover from this.

Comment 2

[ericj]

UPDATE: the website is utilizing kerberos for authentication. The problem is triggered when the user authenticates with their kerberos ticket and downloads a file (a PDF file and a text file was used in our testing, right click link and perform Save Link As). Each download increases the active connection count. So after 6 downloads, it no longer works as it has reached the max. Running kdestroy on the client causes the browser to fail back to basic auth and the problem does not occur in this scenario.

Comment 3

[Kershaw Chang [:kershaw]]

We have urgent connection that can allow us to open more than 6 connections. This could explain why you see 8 active connections in about:networking.

Looking at comment #2, it seems the problem is why the authentication is not finished, so all active connections are blocked.
Could you try to get the http log? Do you probably know why the authentication is failed?

Comment 4

[ericj]

Attachment: about:networking logs

Started the log after 5th download (5th connection eaten up).
Performed the 6th download of a file.
At that point, log is at 2020-10-05 19:09:13.233953
Then I attempted to download the 7th download which just hangs. Download manager shows unknown time left.

Comment 5

[ericj]

Additional info: Firefox on Windows with Kerberos authentication (against this same website) is also having the same issue. I have also tested Firefox 81.0 on Linux and the problem still exists on that version as well.

Comment 6

[Kershaw Chang [:kershaw]]

From the log, I can see the active connection for 6th download is not become an idle one after the download is done.
This is weird. ni myself for taking a deeper look.

Comment 7

[Kershaw Chang [:kershaw]]

(In reply to Kershaw Chang [:kershaw] from comment #6)

From the log, I can see the active connection for 6th download is not become an idle one after the download is done.
This is weird. ni myself for taking a deeper look.

I think I've figured out why the connection is not released.
See the log below. The transaction 0x7f9522f66800 is added back to active transactions after nsHttpTransaction::Close() is called, so this transaction's connection is never be released. At the end, the max connection limit is reached.

2020-10-05 19:08:55.345702 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpTransaction::Close [this=0x7f9522f66800 reason=0]
2020-10-05 19:08:55.345706 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::RemoveActiveTransaction t=0x7f9522f66800 tabid=0(0) thr=0

2020-10-05 19:08:55.348605 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgUpdateClassOfServiceOnTransaction [trans=0x7f9522f66830]
2020-10-05 19:08:55.348608 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::UpdateActiveTransaction ENTER t=0x7f9522f66800
2020-10-05 19:08:55.348623 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::AddActiveTransaction    t=0x7f9522f66800 tabid=0(0) thr=1
2020-10-05 19:08:55.348627 UTC - [Parent 38111: Socket Thread]: V/nsHttp Active transactions +[0,0,0,6]
2020-10-05 19:08:55.348629 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::TouchThrottlingTimeWindow
2020-10-05 19:08:55.348632 UTC - [Parent 38111: Socket Thread]: V/nsHttp nsHttpConnectionMgr::UpdateActiveTransaction EXIT t=0x7f9522f66800

Comment 8

[Kershaw Chang [:kershaw]]

Attachment: Bug 1668828 - Don't set cos flag if transaction is already closed

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3bbdaba33c6e
Don't set cos flag if transaction is already closed r=necko-reviewers,valentin

Comment 10

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/3bbdaba33c6e

Comment 11

[drJeckyll]

mozregression brings me here, because I have a issue with recent FF 84.0a1 (2020-10-21) (64-bit) on Gentoo Linux which started yesterday. It was working fine with FF from 2020-10-20.

Running mozregression with network.stricttransportsecurity.preloadlist set to off I can't anymore open my local addresses like something.dev which point to 127.0.0.1 set in hosts file. Page stay empty with hourglass icon on tab. In console I can see GET http://something.dev/ request which never complete.

Not sure if this is right bug, but ...

Comment 12

[Kershaw Chang [:kershaw]]

(In reply to drJeckyll from comment #11)

mozregression brings me here, because I have a issue with recent FF 84.0a1 (2020-10-21) (64-bit) on Gentoo Linux which started yesterday. It was working fine with FF from 2020-10-20.

Running mozregression with network.stricttransportsecurity.preloadlist set to off I can't anymore open my local addresses like something.dev which point to 127.0.0.1 set in hosts file. Page stay empty with hourglass icon on tab. In console I can see GET http://something.dev/ request which never complete.

Not sure if this is right bug, but ...

Could you file another new bug?
Could also try to get the http log?

Thanks.

Comment 13

[drJeckyll]

(In reply to Kershaw Chang [:kershaw] from comment #12)

(In reply to drJeckyll from comment #11)

mozregression brings me here, because I have a issue with recent FF 84.0a1 (2020-10-21) (64-bit) on Gentoo Linux which started yesterday. It was working fine with FF from 2020-10-20.

Running mozregression with network.stricttransportsecurity.preloadlist set to off I can't anymore open my local addresses like something.dev which point to 127.0.0.1 set in hosts file. Page stay empty with hourglass icon on tab. In console I can see GET http://something.dev/ request which never complete.

Not sure if this is right bug, but ...

Could you file another new bug?
Could also try to get the http log?

Thanks.

Actually after couple of updates of nightly it is back to normal. Not sure what was wrong, since I didn't change anything on my side.

Comment 14

[James Ralston]

Thanks all for unraveling this.

I've been burned by this bug, multiple times per day, stretching back to at least Firefox 7x. A sure-fire reproducer is to…

• use Atlassian productions extensively (which load approximately one billion URLs per each page viewed),
• with GSSAPI (Kerberos) authentication,
• over a higher-latency connection (e.g., a VPN).

I'm entering this comment using Firefox 83.0, with a tab open to a “stuck” server, and sure enough, about:networking shows 8 active connections to the stuck server, despite the fact that the underlying OS (Fedora Linux 31) shows 0 active TCP connections to the host:

$ ss -aort | grep wiki-int || echo 'oh noes!!1!'
oh noes!!1!

I will go kick the tires on 84.0b8 and see if I can reproduce the bug.

I hit this bug many times per day, so if I can no longer reproduce it with 84.0b8, then I can assert with a high degree of confidence that the bug is truly squashed.

Comment 15

[James Ralston]

After using Firefox 84.0b8 all of yesterday afternoon/evening, I was unable to reproduce the bug.

As an added bonus, Atlassian web sites load much more quickly now, as Firefox is properly releasing connections after each connection closes, so all connections (up to network.http.max-persistent-connections-per-server + network.http.max-urgent-start-excessive-connections-per-host) can be used at all times. (Under the buggy behavior, non-properly-released connections slowly filled up the network.http.max-persistent-connections-per-server limit.)

I will continue testing with 84.0b8, but at this point, I am confident the bug is truly squashed. Thank you!

Comment 16

[James Ralston]

Alas, I spoke too soon. This bug is not fixed; I just reproduced the problem with 84.0b8.

Specifically, at this moment, all of my connections to servicedesk.example.org are now hung in Firefox.

These are my relevant about:config settings:

setting	value
network.http.max-persistent-connections-per-server	12
network.http.max-urgent-start-excessive-connections-per-host	3

Currently, about:networking shows:

Hostname	Port	HTTP Version	SSL	Active	Idle
servicedesk.example.org	443	HTTP <= 1.1	true	13	0

The networking stack (Fedora Linux 31) shows:

State	Recv-Q	Send-Q	Local Address:Port	Peer Address:Port	Process
CLOSE-WAIT	32	0	client.example.org:53980	servicedesk.example.org:https	timer:(keepalive,7min59sec,0)
CLOSE-WAIT	32	0	client.example.org:54026	servicedesk.example.org:https	timer:(keepalive,8min6sec,0)
CLOSE-WAIT	32	0	client.example.org:53982	servicedesk.example.org:https	timer:(keepalive,8min,0)
CLOSE-WAIT	32	0	client.example.org:53986	servicedesk.example.org:https	timer:(keepalive,8min,0)

After waiting 10 minutes, the network stack on client.example.org now shows no active connections to servicedesk.example.org:

$ ss -aort | grep servicedesk || echo 'oh noes!!1!'
oh noes!!1!

But about:networking is unchanged:

Hostname	Port	HTTP Version	SSL	Active	Idle
servicedesk.example.org	443	HTTP <= 1.1	true	13	0

I do think it is at least slightly better than it was before, as it took longer to reproduce the problem this time.

What specific information do you need in order to troubleshoot this problem further?

I am happy to download beta and/or development snapshots to help with testing.

Comment 17

[James Ralston]

I do not appear to have permissions to reopen this bug.

OP (ericj), can you reopen, please?

Thanks.

Comment 18

[James Ralston]

I can trivially reproduce this now. All I have to do is open a ticket in servicedesk.example.org and modify any field that does dynamic autocomplete while typing, such as adding a participant to a ticket (which attempts to offer autocompletion candidates as you type).

After doing this, about:networking asserts 4 active connections to servicedesk.example.org, but the operating system shows 4 connections in CLOSE-WAIT, not ESTABLISHED.

After waiting for the operating system to reach the timeout for the CLOSE-WAIT connections and tear them down, about:networking still shows 4 active connections.

If I poke the auto-complete field again, I get two more CLOSE-WAIT TCP connections, and about:networking now shows 6 active connections. So clearly, this will just keep happening until network.http.max-persistent-connections-per-server is exceeded, and then the web site in question is dead to Firefox until a quit/restart.

Again, I can reproduce this reliably in about 30 seconds from launching Firefox. Just tell me what specific information you need me to log in order to help track it down.

Comment 19

[ericj]

(In reply to James Ralston from comment #17)

I do not appear to have permissions to reopen this bug.

OP (ericj), can you reopen, please?

Thanks.

Did you try the GA version of 84.0 ? They released it today.. http://releases.mozilla.org/pub/firefox/releases/84.0/

I deployed 84.0 today and verified the bug I was experiencing is indeed fixed.

Comment 20

[James Ralston]

Attachment: http log when Firefox mismanages sockets

(In reply to ericj from comment #19)

I deployed 84.0 today and verified the bug I was experiencing is indeed fixed.

I just tested 84.0 final, and I can trivially reproduce the bug with it, the same as with 84.0b8.

So that leaves at least two possibilities:

1. There are multiple code paths that can trigger the bug, and the code path for which you were experiencing the bug is fixed.
2. What I am experiencing is a different but similar bug.

Right now, I am leaning towards #1, as the manifestation of the bug is identical to what you reported.

From the operating system point-of-view, it looks like Firefox is simply not paying attention to the socket that was closed. Here's one of the dead sockets:

COMMAND      PID     USER   FD      TYPE             DEVICE SIZE/OFF     NODE NAME
firefox-b 165689 username  143u     IPv4            2064858      0t0      TCP client.example.org:45516->wiki-int.example.org:https (CLOSE_WAIT)

After the operating system times out on waiting for Firefox to close the socket, it sends the FIN on Firefox's behalf, which moves the socked to the CLOSED state from the operating system point-of-view. At that point, Firefox still has the socket open, but it's not connected to anything:

$ lsof -p 165689 | grep 'protocol: TCP'
COMMAND      PID     USER   FD      TYPE             DEVICE SIZE/OFF     NODE NAME
firefox-b 165689 username   34u     sock                0,8      0t0  2065927 protocol: TCP
firefox-b 165689 username  136u     sock                0,8      0t0  2058604 protocol: TCP
firefox-b 165689 username  141u     sock                0,8      0t0  2057817 protocol: TCP
firefox-b 165689 username  143u     sock                0,8      0t0  2064858 protocol: TCP
firefox-b 165689 username  146u     sock                0,8      0t0  2055956 protocol: TCP
firefox-b 165689 username  151u     sock                0,8      0t0  2058619 protocol: TCP
firefox-b 165689 username  153u     sock                0,8      0t0  2055958 protocol: TCP

These are the same seven sockets that about:networking shows as active.

If it were the case that Firefox somehow missed that the sockets had pending data (the EOF generated by the server sending the FIN packet), then eventually a timeout (e.g., maybe network.http.response.timeout) would cause Firefox to reap the socket. But this never happens.

I've attached a compressed http log, with hostnames and IP addresses sanitized. I generated it using the following procedure:

1. I opened the landing page of our internal wiki, waited for the page to completely load, and then waited for Firefox to close all sockets.
2. I started http logging in networking:config.
3. I clicked on Search on the wiki, which brought up a search pane. I typed gibberish into the search bar, then pressed Esc to close the search bar.
4. I waited until all sockets to the wiki were closed by the operating system.
5. I stopped the http log.

This test generated 7 dead sockets (ones Firefox reports as active, but which are closed from the operating system point-of-view).

Kershaw, if you need more detailed logging information, let me know.

Also, if you would prefer that I open a new bug report instead of piling on to this one, that's fine; just let me know. Thanks!

Comment 21

[ericj]

I had access to re-open the bugzilla. I will continue to test 84.0 on my end as well and let you know if the bug reoccurs for me. Perhaps once users start playing with it, it will reoccur for them.

I do want to point out that after the download of the file completed, the connection under about:networking was still active for a few seconds but then it did go down to 0.

Comment 22

[Kershaw Chang [:kershaw]]

Could you try to get the http log?
Thanks.

Comment 23

[James Ralston]

(In reply to Kershaw Chang [:kershaw] from comment #22)

Could you try to get the http log?

Per comment #20, I already attached a log file; it's the http log when Firefox mismanages sockets attachment.

Is that not what you want? If you need more information, could you tell me the specific log settings you want me to use when I capture the log?

Thanks.

Comment 24

[Kershaw Chang [:kershaw]]

(In reply to James Ralston from comment #23)

(In reply to Kershaw Chang [:kershaw] from comment #22)

Could you try to get the http log?

Per comment #20, I already attached a log file; it's the http log when Firefox mismanages sockets attachment.

Is that not what you want? If you need more information, could you tell me the specific log settings you want me to use when I capture the log?

Thanks.

Sorry, I was not aware of the already uploaded log. I think what you provided in comment #20 is enough. I'll take a look. Thanks!

Comment 25

[Kershaw Chang [:kershaw]]

Hi James,

After looking into the log you provided, I think this is a different problem, so I'd like to close this bug and open a new one (bug 1683176).
I assume that the platform you are using is linux. If so, could you try to download the test build and see if you can still reproduce this problem?
If you are using osx, you could find the build here.

Thanks.

Comment 26

[James Ralston]

(In reply to Kershaw Chang [:kershaw] from comment #25)

After looking into the log you provided, I think this is a different problem, so I'd like to close this bug and open a new one (bug 1683176).

That's fine; I followed up on bug 1683176. Thanks!