+++ This bug was initially created as a clone of Bug #1735595 +++

Bug 1735595 landed a fix to not cache 408 responses.
Reporters indicate the problem is still happening (including with HTTP/2)
We'll use this bug to diagnose remaining issues.

https://firefox-source-docs.mozilla.org/networking/submitting_networking_bugs.html

@reporters: please take a look at the documentation above.
What would help in diagnosing these issues would be some HTTP logs when the bug happens:
https://firefox-source-docs.mozilla.org/networking/http/logging.html

I've upgraded to 98a1 and the issue happend.
Then i cleared all the cookies and caches.
No problem so far. I'll update if this happens again after the clearing.

The average user doesn't know that you should clear the cache after this fix so i suggest
to clear all the 408 responses from the cache when upgrading!

Thank you

Ok Issue still exists after clearing the cookies and cache too! (Firefox 98a1)

Thanks! To dianose the issue HTTP logging is required. Thanks!

Currently 1+ day with network.http.http3.enabled = false and facebook works without any freezing on static.xx.fbcdn.net.

I'll keep you updated!

Ok the only issue i found is on the comments (with http3 disabled)
It keeps loading in a loop ... (Chrome doesn't have this problem)

https://ibb.co/df1kbGM

It does this when you press the link to expand to more comments.

(In reply to Charalampos Michael from comment #7)

Ok the only issue i found is on the comments (with http3 disabled)
It keeps loading in a loop ... (Chrome doesn't have this problem)

https://ibb.co/df1kbGM

Chrome has the same issue, it's Facebook problem.

Please avoid adding any me too comments.
If you are able to provide any HTTP logs that would be quite helpful. Thanks!

(In reply to Valentin Gosu [:valentin] (he/him) from comment #11)

Please avoid adding any me too comments.
If you are able to provide any HTTP logs that would be quite helpful. Thanks!

I have the logs! Where can i send them ?

You can send them to necko@mozilla.com
Thanks!

This currently fixes the issue: network.http.http3.enabled = false
Previously, this setting also fixed the issue: browser.cache.disk.enable = false

As previously stated, Facebook comments are still effected with a spinning loading icon.
Workaround: click on "most relevant" to refresh.
Screenshot: https://bug1735595.bmoattachments.org/attachment.cgi?id=9256562

(In reply to Intrepid from comment #15)

As previously stated, Facebook comments are still effected with a spinning loading icon.
Workaround: click on "most relevant" to refresh.
Screenshot: https://bug1735595.bmoattachments.org/attachment.cgi?id=9256562

I had the same problem even with network.http.http3.enabled = false on the facebook comments.
It does this rarely though. Somebody said that Chrome has the same issue with the comments.
Maybe this is actually facebook problem ?

I'm giving up - something changed week ago and this no longer happens to me.

Last time it happened was week ago - https://bugzilla.mozilla.org/show_bug.cgi?id=1735595#c127 and I've seen it few times a day.

Over the last week I did noticed only two cases where sprites not loaded and one case with broken style - simple refresh fixed them all. Previously refreshes did not helped so it must be something different this time.

WORKSFORME?

After 1 week, I can confirm the following setting fixes this issue. When will this bug be fixed? It's been over 4 months (10-13-2021).

network.http.http3.enabled = false
OR
browser.cache.disk.enable = false

Please consult the Bugzilla etiquette when commenting.

(In reply to Valentin Gosu [:valentin] (he/him) from comment #4)

Thanks! To dianose the issue HTTP logging is required. Thanks!
OK, here are 15 logs for you. Thanks. https://bugzilla.mozilla.org/show_bug.cgi?id=1735595

OK, I think I know what can be happening on my side.

Today when I turned on my PC my LTE modem failed/froze and I experienced exactly the issue again.

It can be reproduced by blocking connection in dev tools:

• fresh Firefox profile
• open dev tools, network tab
• make sure "Disable cache" checkbox is not checked
• block *.jpg
• open https://old.reddit.com/r/uBlockOrigin/
• header background image on top will be blank (https://b.thumbs.redditmedia.com/QBMg3w5qjwPdbZtYVOA79jVUeP4wpbWiqqSgrrAv8hI.jpg)
• remove *.jpg block
• refresh by F5
• image will still be missing, no amount of F5 will help

(In reply to Valentin Gosu [:valentin] (he/him) from comment #0)

+++ This bug was initially created as a clone of Bug #1735595 +++

It's back. Maybe my connection issues triggered it, but it's like crazy today. Image disappears -> Ctrl+F5 -> it's back -> few minutes later is again missing.

I've send logs to your email. Look for https://b.thumbs.redditmedia.com/QBMg3w5qjwPdbZtYVOA79jVUeP4wpbWiqqSgrrAv8hI.jpg

With H1, the connection is restarted.
With H2 and H3, the channel gets NS_ERROR_ABORT from Http2Session::Shutdown

Depends on D139387

So, in trying to write a reproducible test case for this I found out that our retries for 408 with HTTP/2 don't work very well. See attachment 9265006 [details].

0:03.07 pid:3055415 2022-02-22 16:20:05.125874 UTC - [Parent 3055415: Socket Thread]: I/nsHttp http response [
 0:03.07 pid:3055415 2022-02-22 16:20:05.125879 UTC - [Parent 3055415: Socket Thread]: E/nsHttp   HTTP/2 408 Request Timeout
 0:03.07 pid:3055415 2022-02-22 16:20:05.125881 UTC - [Parent 3055415: Socket Thread]: E/nsHttp   date: Tue, 22 Feb 2022 16:20:05 GMT
 0:03.07 pid:3055415 2022-02-22 16:20:05.125882 UTC - [Parent 3055415: Socket Thread]: E/nsHttp   X-Firefox-Spdy: h2
 0:03.07 pid:3055415 2022-02-22 16:20:05.125884 UTC - [Parent 3055415: Socket Thread]: E/nsHttp     OriginalHeaders
 0:03.07 pid:3055415 2022-02-22 16:20:05.125886 UTC - [Parent 3055415: Socket Thread]: E/nsHttp   date: Tue, 22 Feb 2022 16:20:05 GMT
 0:03.07 pid:3055415 2022-02-22 16:20:05.125889 UTC - [Parent 3055415: Socket Thread]: E/nsHttp   X-Firefox-Spdy: h2
 0:03.07 pid:3055415 2022-02-22 16:20:05.125891 UTC - [Parent 3055415: Socket Thread]: I/nsHttp ]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125895 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpTransaction::CheckForStickyAuthScheme this=7fdc23812a00
 0:03.07 pid:3055415 2022-02-22 16:20:05.125900 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::OnHeadersAvailable [this=7fdc221cd900 trans=7fdc23812a00 response-head=7fdc21f70940]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125904 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::Close [this=7fdc221cd900 reason=804b0014]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125911 UTC - [Parent 3055415: Socket Thread]: V/nsHttp HttpTrafficAnalyzer::IncrementHttpConnection size=1 [this=7fdc25e8495d]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125914 UTC - [Parent 3055415: Socket Thread]: V/nsHttp HttpTrafficAnalyzer::IncrementHttpConnection [Y0_N1Sys] [this=7fdc25e8495d]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125918 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=7fdc23812f00 tlsfilter=0 socket=7fdc25e40018
 0:03.07 pid:3055415 2022-02-22 16:20:05.125961 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::Close drained 23 bytes
 0:03.07 pid:3055415 2022-02-22 16:20:05.125971 UTC - [Parent 3055415: Socket Thread]: V/nsHttp resetting transaction's response head
 0:03.07 pid:3055415 2022-02-22 16:20:05.125973 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpResponseHead::Reset
 0:03.07 pid:3055415 2022-02-22 16:20:05.125977 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7fdc221cd900 trans->ws rv=0 n=0 socketin=0
 0:03.07 pid:3055415 2022-02-22 16:20:05.125979 UTC - [Parent 3055415: Socket Thread]: I/nsHttp Http2Session::WriteSegments 7fdc23812f00 InternalState 1
 0:03.07 pid:3055415 2022-02-22 16:20:05.125982 UTC - [Parent 3055415: Socket Thread]: I/nsHttp Http2Session 7fdc23812f00 buffering frame header read failure 804b0014
 0:03.07 pid:3055415 2022-02-22 16:20:05.125984 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7fdc221cd900 trans->ws rv=804b0014 n=0 socketin=804b0014
 0:03.07 pid:3055415 2022-02-22 16:20:05.125987 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::CloseTransaction[this=7fdc221cd900 trans=7fdc23812f00 reason=804b0014]
 0:03.07 pid:3055415 2022-02-22 16:20:05.125991 UTC - [Parent 3055415: Socket Thread]: V/nsHttp nsHttpConnection::DontReuse 7fdc221cd900 spdysession=7fdc23812f00
 0:03.07 pid:3055415 2022-02-22 16:20:05.125994 UTC - [Parent 3055415: Socket Thread]: I/nsHttp Http2Session::DontReuse 7fdc23812f00
 0:03.07 pid:3055415 2022-02-22 16:20:05.125994 UTC - [Parent 3055415: Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7fdc221683a0 http:localhost:40887:P::.
 0:03.07 pid:3055415 2022-02-22 16:20:05.125997 UTC - [Parent 3055415: Socket Thread]: V/nsHttp   closing associated mTransaction
 0:03.07 pid:3055415 2022-02-22 16:20:05.126002 UTC - [Parent 3055415: Socket Thread]: I/nsHttp Http2Session::Close 7fdc23812f00 804B0014
 0:03.07 pid:3055415 2022-02-22 16:20:05.126002 UTC - [Parent 3055415: Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7fdc221683a0 MISS
 0:03.07 pid:3055415 2022-02-22 16:20:05.126005 UTC - [Parent 3055415: Socket Thread]: I/nsHttp Http2Session::CloseStream 7fdc23812f00 7fdc25ece200 0x11 80004004

Here we attempt to restart the transaction but calling Close(NS_ERROR_NET_RESET); causes the us to close the stream with NS_ERROR_ABORT in Http2Session::Shutdown.
I think we might want to move that to a separate bug.

Now, the HTTP/3 issue. That should be handled here

However, if we look at the logs, we'll notice that assuming mIsReused == true, PR_IntervalNow() - mHttp3Session->LastWriteTime() will be > 1000ms all the time. In this case 11.5 seconds.

2022-02-02 17:09:26.408000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Session::ProcessOutput reader=2eb7c674d40, [this=2eb80a30d00] <----- Last write here
...
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: I/nsHttp http response [
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   HTTP/3 408 Request Timeout
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   content-type: text/html; charset=utf-8
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   content-length: 2959
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   priority: u=3,i
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   date: Wed, 02 Feb 2022 17:09:37 GMT
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp     OriginalHeaders
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   content-type: text/html; charset=utf-8
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   content-length: 2959
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   priority: u=3,i
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp   date: Wed, 02 Feb 2022 17:09:37 GMT
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: I/nsHttp ]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpTransaction::CheckForStickyAuthScheme this=2eb8c306e00
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp HttpConnectionUDP::OnHeadersAvailable [this=2eb7c674d40 trans=2eb8c306e00 response-head=2eb7c5a00c0]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp nsHttpTransaction::HandleContent [this=2eb8c306e00 count=0 read=0 mContentRead=0 mContentLength=2959]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::WriteSegments rv=0x0 countWrittenSingle=0 socketin=0 [this=2eb8aeea710]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 2eb8c306e00
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=2eb8c306e00
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::OnWriteSegment [this=2eb8aeea710, state=3
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=2eb8c306e00 status=804b0006 progress=1277]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpTransaction::WritePipeSegment 2eb8c306e00 written=1147
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp nsHttpTransaction::ProcessData [this=2eb8c306e00 count=1147]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpTransaction::HandleContent [this=2eb8c306e00 count=1147]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: E/nsHttp nsHttpTransaction::HandleContent [this=2eb8c306e00 count=1147 read=1147 mContentRead=1147 mContentLength=2959]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::OnWriteSegment [this=2eb8aeea710, state=3
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: I/nsHttp Http3Session::ReadResponseData return an error 80470007 [this=2eb80a30d00] <---- Session
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::WriteSegments rv=0x0 countWrittenSingle=1147 socketin=80470007 [this=2eb8aeea710]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Session::ProcessEvents - DataReadable
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::WriteSegments [this=2eb8aeea710]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Main Thread]: V/nsHttp nsHttpChannel::OnStartRequest [this=2eb90a81a00 request=2eb7f9d9dc0 status=0]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 2eb8c306e00
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=2eb8c306e00
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Main Thread]: V/nsHttp nsHttpChannel::ProcessResponse [this=2eb90a81a00 httpStatus=408]
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Socket Thread]: V/nsHttp Http3Stream::OnWriteSegment [this=2eb8aeea710, state=3
2022-02-02 17:09:37.958000 UTC - [Parent 19848: Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=2eb90a81a40 event="http-on-examine-response"]

I'm not exactly sure what 1 second interval is supposed to fix.
I'll try to write a HTTP/3 unit test too.

I am thinking maybe we should handle 408 in nsHttpTransaction::HandleContentStart, which already has the logic to restart a transaction.
The benefit of handling 408 in transaction is that we can have the same behavior for Http/1, HTTP/2, and HTTP/3.

Depends on D139395

Depends on D139610

I am working on a patch. I should have one for a review today.

(In reply to Dragana Damjanovic [:dragana] from comment #33)

I am working on a patch. I should have one for a review today.

Let me know a build so i can test it!

Thanks

https://hg.mozilla.org/mozilla-central/rev/f65659ab8873
https://hg.mozilla.org/mozilla-central/rev/f26919359e7e

So i download the latest Firefox 100 build and the fix is there right ? (To test it)

Yes, the 2022-03-23 (ID: 20220323094932) Nightly or newer has the fixes from comment 38. Testing and feedback would be greatly appreciated!

My issue must be caused by something else, because still not fixed.

(In reply to gwarser from comment #41)

My issue must be caused by something else, because still not fixed.

Dragana, would updated logs be helpful for this or is more work still planned for this bug? It's a bit unclear to me with the current state of attachments on this bug.

(In reply to Ryan VanderMeulen [:RyanVM] from comment #40)

Yes, the 2022-03-23 (ID: 20220323094932) Nightly or newer has the fixes from comment 38. Testing and feedback would be greatly appreciated!

It's doesn't fix it and it's causing problems to facebook. See the screenshot:
https://ibb.co/FssDDmw

Can you make another http log with the new Firefox version:
https://firefox-source-docs.mozilla.org/networking/http/logging.html

FWIW, I had been able to hit this issue pretty consistently prior to the most recent patch landed and haven't been able to since.

Comment on attachment 9267356 [details]
Retry a request that failed with 408 if HTTP/2 is used.

Beta/Release Uplift Approval Request

• User impact if declined: Facebook may not load properly for some users.
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): The code change only retires requests if 408 is received. The retry code already exists only the trigger for 408 has been added.
• String changes made/needed:

Comment on attachment 9265006 [details]
Bug 1752270 - Test for receiving 408 response r=#necko

Approved for release uplift, available on the beta channel with 99RC1. Thanks

Comment on attachment 9267356 [details]
Retry a request that failed with 408 if HTTP/2 is used.

Approved for release uplift, available on the beta channel with 99RC1. Thanks

https://hg.mozilla.org/releases/mozilla-release/rev/9c0a476c5b5b
https://hg.mozilla.org/releases/mozilla-release/rev/1f1e28055e77

I've tried to reproduce this issue using an affected Nightly build 98.0a1 (20220127094620), on mac 11 and Win 10 x64. Unfortunately, I'm not hitting the bug after navigating for a while on facebook.com, the images are correctly displayed.

Charalampos, could you please do another check on latest Nightly 100 and 99RC1, and let us know if the issue is fixed?

Ok! I've updated to the latest nightly and i'll let you know!

No problems with facebook and the latest nightly 100.0a1 (2022-03-30) (64-bit).
I guess it's finally fixed! :)

Will you include this fix in firefox99 too ? The report says it's fixed on firefox 99.

Thank you

Yes, it was uplifted for the Fx99 RC build in comment 49.

(In reply to Charalampos Michael from comment #52)

No problems with facebook and the latest nightly 100.0a1 (2022-03-30) (64-bit).
I guess it's finally fixed! :)

Great, thanks for checking! Would you mind doing another check this time on Firefox 99 RC2, to make sure that everything works as expected there as well?

I updated to 99.0 today and the issue of not loading images appears to be worse. In 98 it would be a few here and there, with comments not always loading. Now it is most of the image content isn't loading.

(In reply to JC3 from comment #56)

I updated to 99.0 today and the issue of not loading images appears to be worse. In 98 it would be a few here and there, with comments not always loading. Now it is most of the image content isn't loading.

i had freezes again ... The first nightly (v100) releases with the fix were ok but after some updates they it broke again.

Thanks for your feedback, JC3 and Charalampos!

Hi dragana! Can you please take a look at the above comments? Although comment 57 looks to be a different issue than the one originally reported, comment 56 suggests that the initial issue is still reproducing.

What would be the best approach with the bug, should we reopen it, or file a follow up bug (in case there are plans to fix this on an upcoming Firefox 99.0.x build)?

I'm going to remove the qe+ flag, since there's nothing left here to do for QA.

99.0.1 is worse than 99, images don't load, when scrolling the page just stop loading. I know this is more of a me too comment, but I have nothing else to offer other than what I'm seeing on the site.

I agree! The first time you patched the 100 nightly solved the problem. After that as JC3 says it got worse and worse!
So look the changes in http code after the first time you applied this patch to 100 nightly.
Build 100.0a1 (2022-03-30) was ok!

May I ask you to create another HTTP log:
https://firefox-source-docs.mozilla.org/networking/http/logging.html

Thank you

May I ask you to create another HTTP log:

Is 99.01 ok for logs ?

The problem still remains with version 102/103.01! It freezes the connection for a long time!