Closed Bug 1745150 Opened 3 years ago Closed 3 years ago

random immediate connection failures

Categories

(Core :: Networking, defect, P2)

Product:
Core
Component:
Networking
Version:
Firefox 94
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
102 Branch
Tracking Flags:
Tracking Status
firefox102 --- fixed

People

(Reporter: vincent-moz, Assigned: kershaw)

Details

(Whiteboard: [necko-triaged])

Attachments

(1 file)

Bug 1745150 - Don't report DNS error for NS_BASE_STREAM_CLOSED, r=#necko
48 bytes, text/x-phabricator-request
Details | Review

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:94.0) Gecko/20100101 Firefox/94.0

Steps to reproduce:

Try to open a URL, at least a URL that has been opened recently (e.g. from a few minutes earlier to less than 24 hours earlier).

Actual results:

I sometimes get an immediate "Unable to connect" error. Reloading always works.

Expected results:

I shouldn't get an error.

Note: I've got this issue since at least Firefox 88 in July 2021. Firefox 92 and 94 are also affected. This issue occurs with various websites (e.g. my own website www.vinc17.net, but also lists.gnu.org and some Google search URL), and I could reproduce it with different local networks (SFR FTTH and Free via a mobile hotspot). But note that I'm not even sure that Firefox really attempts to connect. Each time, the failure is immediate, and a reload opens the page instantly.

I had reported the bug in the Debian BTS in July:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=991134

Also note that the page is sometimes opened, but the CSS styles are missing, probably due to the same issue. This can happen when doing "Back" a few minutes after following a link.

Is it happening with the debian package or the binary?

with the Debian package.

Could you please try if you can reproduce with the tarball? (or snap/flatpak)

We have significant differences in the build process.

The Bugbug bot thinks this bug should belong to the 'Firefox::Address Bar' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: Untriaged → Address Bar

This has just occurred with the firefox 99.0-1 Debian package on https://www.vinc17.net/ - the web page could be opened, but the CSS stylesheets were missing.

It is difficult to compare with some other FF binary as it can take weeks before the problem occurs again.

Component: Address Bar → Networking
Product: Firefox → Core

I am not sure how to diagnose the issue. it is happening very rarely, I do not think it is possible to collect HTTP logging instructions?

Logs may include personal information such as cookies. Try using a fresh Firefox profile to capture the logs. If that is not possible, you can also put them in a password-protected archive, or send them directly via email to necko@mozilla.com.

Flags: needinfo?(vincent-moz)

I've used the official tarball for a few weeks, and I couldn't reproduce the bug.

I'll try HTTP logging with Debian's package (in case that won't make the issue disappear). But 5 MB of logs are generated each minute, so I hope that this won't fill up my disk.

Flags: needinfo?(vincent-moz)

Well, it was quite fast to reproduce the problem with Debian's package.

Here's DNS information from the about:networking#dns page:

Hostname: www.vinc17.net
Family: ipv4
TRR: false
Addresses: 155.133.131.76 / 2001:4b99:1:3:216:3eff:fe20:ac98
Expires (Seconds): 108
Isolation Key: ^partitionKey=%28https%2Cvinc17.net%29
Extra flags: 0|0x2000|0|0|

Note that I was connecting from home, where I currently have only IPv4 working.

Before attaching more logs, I give some information I could find there, in case this is sufficient. I opened https://www.vinc17.net/cine/index.fr.html at 20:28:45 UTC, then followed the link https://www.vinc17.net/cine/watch.fr.html at 20:28:50 UTC, which failed. This is apparently due to IP address blocklisting. I can see:

[...]
2022-05-11 20:28:46.328515 UTC - [Parent 12: Main Thread]: V/nsHttp sending progress notification [this=7fda34d08300 status=804b0003 progress=0/0]
2022-05-11 20:28:46.328541 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::OnStatus [this=7fdb1dd81540 status=804b0003]
2022-05-11 20:28:46.328548 UTC - [Parent 12: Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.328579 UTC - [Parent 12: IPDL Background]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.328604 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=7fdb1ccecb30 bgParent=7fda34443b80]
2022-05-11 20:28:46.328613 UTC - [Parent 12: Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnChannelClosed [this=7fda34443b80]
2022-05-11 20:28:46.328627 UTC - [Parent 12: IPDL Background]: V/nsHttp HttpBackgroundChannelParent::DeleteRunnable [this=7fda34443b80]
2022-05-11 20:28:46.328677 UTC - [Parent 12: IPDL Background]: V/nsHttp HttpBackgroundChannelParent::ActorDestroy [this=7fda34443b80]
2022-05-11 20:28:46.328698 UTC - [Parent 12: Main Thread]: D/cache2 CacheEntry::InvokeAvailableCallback [this=7fda5232fd00, state=READY, cb=7fda34d088c0, r/o=0, n/w=0]
2022-05-11 20:28:46.328708 UTC - [Parent 12: Main Thread]: D/cache2 ready/has-meta, notifying OCEA with entry and NS_OK
2022-05-11 20:28:46.328720 UTC - [Parent 12: Main Thread]: D/cache2 CacheEntry::BackgroundOp this=7fda5232fd00 dipatch of 2
2022-05-11 20:28:46.328726 UTC - [Parent 12: Main Thread]: D/cache2 CacheFile::OnFetched() this=7fda242f0ee0
2022-05-11 20:28:46.328731 UTC - [Parent 12: Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7fda242f0ee0]
2022-05-11 20:28:46.328734 UTC - [Parent 12: Cache2 I/O]: D/cache2 CacheEntry FRECENCYUPDATE [this=7fda5232fd00, frecency=13259.5066512381]
2022-05-11 20:28:46.328740 UTC - [Parent 12: Main Thread]: D/cache2 New CacheEntryHandle 7fda5c01c8e0 for entry 7fda5232fd00
2022-05-11 20:28:46.328755 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=7fda34d08300 entry=7fda5c01c8e0 new=0 status=0]
2022-05-11 20:28:46.328762 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel::ReadFromCache [this=7fda34d08300] Using cached copy of: https://www.vinc17.net/graphics/favicon.png
2022-05-11 20:28:46.328766 UTC - [Parent 12: Main Thread]: V/nsHttp First response from cache
2022-05-11 20:28:46.328772 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpConnectionMgr::CancelTransaction [trans=7fda94de5910 reason=804b0002]
2022-05-11 20:28:46.328781 UTC - [Parent 12: Main Thread]: D/nsSocketTransport STS dispatch [7fda6058e700]
2022-05-11 20:28:46.328787 UTC - [Parent 12: Main Thread]: D/nsSocketTransport PollableEvent::Signal
2022-05-11 20:28:46.328792 UTC - [Parent 12: Main Thread]: D/nsSocketTransport PollableEvent::MarkFirstSignalTimestamp
2022-05-11 20:28:46.328803 UTC - [Parent 12: Main Thread]: D/nsSocketTransport PollableEvent::Signal PR_Write 1
2022-05-11 20:28:46.328816 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport ...returned after 2 milliseconds
2022-05-11 20:28:46.328824 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::AsyncWait() [this=7fdb1abd3c10, callback=7fda2df6f0e8, flags=0, requestedCount=0, eventTarget=7fdb50d2d200]
2022-05-11 20:28:46.328830 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda86f40800, timeout=65535s
2022-05-11 20:28:46.328851 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328841 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7fdb1abd3c10, releaseOnly=0]
2022-05-11 20:28:46.328860 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda226e8400, timeout=65535s
2022-05-11 20:28:46.328876 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328880 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda3459a400, timeout=65535s
2022-05-11 20:28:46.328872 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7fdb1abd3c10, idx=0]
2022-05-11 20:28:46.328902 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328905 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7fdb1abd3c10, mCallback=7fda2df6f0e8, mClosed=0, mStatus=0x00000000, mChunk=7fda5211d180, mListeningForChunk=-1, mWaitingForUpdate=0]
2022-05-11 20:28:46.328906 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda94f09400, timeout=65535s
2022-05-11 20:28:46.328915 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7fda5211d180]
2022-05-11 20:28:46.328924 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7fdb1abd3c10, canRead=1461]
2022-05-11 20:28:46.328924 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328936 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda95745c00, timeout=65535s
2022-05-11 20:28:46.328940 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328944 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda2eef3400, timeout=65535s
2022-05-11 20:28:46.328932 UTC - [Parent 12: Main Thread]: D/cache2 CacheFileInputStream::NotifyListener() [this=7fdb1abd3c10]
2022-05-11 20:28:46.328955 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328959 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fda3495dc00, timeout=65535s
2022-05-11 20:28:46.328962 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328960 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel::TriggerNetwork [this=7fda34d08300]
2022-05-11 20:28:46.328965 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=7fdad6620800, timeout=65535s
2022-05-11 20:28:46.328973 UTC - [Parent 12: Main Thread]: V/nsHttp network already triggered. Returning.
2022-05-11 20:28:46.328982 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport not engaged
2022-05-11 20:28:46.328986 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport PollableEvent::Clear
2022-05-11 20:28:46.328989 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport PollableEvent::Clear time to signal 0ms
2022-05-11 20:28:46.328994 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport PollableEvent::Clear PR_Read 1
2022-05-11 20:28:46.328998 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport STS dispatch [7fdb1f24f7f0]
2022-05-11 20:28:46.329002 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport OnDispatchedEvent Same Thread Skip Signal
2022-05-11 20:28:46.329007 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgCancelTransaction [trans=7fda94de5930]
2022-05-11 20:28:46.329017 UTC - [Parent 12: Socket Thread]: V/nsHttp DnsAndConnectSocket::Abandon [this=7fda5b65ef80 ent=www.vinc17.net] 7fdad6620818 0 7fdad6620ab0 0
2022-05-11 20:28:46.329021 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick armed=1 active=3
2022-05-11 20:28:46.329026 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport Reset callbacks for secinfo=7fda34aeea00 callbacks=7fda9369d370
2022-05-11 20:28:46.329033 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=7fdad6620ab0]
2022-05-11 20:28:46.329037 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::CloseWithStatus [this=7fdad6620ab0 reason=80470002]
2022-05-11 20:28:46.329040 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnMsgOutputClosed [this=7fdad6620800 reason=80470002]
2022-05-11 20:28:46.329043 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=7fdad6620ab0 cond=80470002]
2022-05-11 20:28:46.329047 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketInputStream::AsyncWait [this=7fdad6620a78]
2022-05-11 20:28:46.329047 UTC - [Parent 12: Main Thread]: V/nsHttp sending progress notification [this=7fda34d08300 status=804b000b progress=0/0]
2022-05-11 20:28:46.329058 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketInputStream::CloseWithStatus [this=7fdad6620a78 reason=80470002]
2022-05-11 20:28:46.329073 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::OnStatus [this=7fdb1dd81540 status=804b000b]
2022-05-11 20:28:46.329073 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnMsgInputClosed [this=7fdad6620800 reason=80470002]
2022-05-11 20:28:46.329082 UTC - [Parent 12: Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.329090 UTC - [Parent 12: Socket Thread]: V/nsHttp DnsAndConnectSocket::CancelBackupTimer()
2022-05-11 20:28:46.329100 UTC - [Parent 12: IPDL Background]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.329104 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQ [ci=.S.......[tlsflags0x00000000]www.vinc17.net:443^partitionKey=%28https%2Cvinc17.net%29]
2022-05-11 20:28:46.329112 UTC - [Parent 12: Main Thread]: V/nsHttp sending progress notification [this=7fda34d08300 status=804b0007 progress=0/0]
2022-05-11 20:28:46.329126 UTC - [Parent 12: Socket Thread]: V/nsHttp Init nsHttpConnectionInfo @7fdac4acdc40
2022-05-11 20:28:46.329126 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::OnStatus [this=7fdb1dd81540 status=804b0007]
2022-05-11 20:28:46.329138 UTC - [Parent 12: Main Thread]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.329146 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport STS dispatch [7fda5e6f3a00]
2022-05-11 20:28:46.329153 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport OnDispatchedEvent Same Thread Skip Signal
2022-05-11 20:28:46.329154 UTC - [Parent 12: IPDL Background]: V/nsHttp HttpBackgroundChannelParent::OnStatus [this=7fda51cc3200]
2022-05-11 20:28:46.329169 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=7fdb1dd82840 bgParent=0]
2022-05-11 20:28:46.329161 UTC - [Parent 12: Socket Thread]: V/nsHttp Destroying DnsAndConnectSocket [this=7fda5b65ef80]
2022-05-11 20:28:46.329181 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel [this=7fda34739300] SetWarningReporter [0]
2022-05-11 20:28:46.329192 UTC - [Parent 12: Main Thread]: D/nsHttp Destroying HttpChannelParent [this=7fdb1dd82840]
2022-05-11 20:28:46.329197 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=7fdb1dd82840 bgParent=0]
2022-05-11 20:28:46.329201 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgCancelTransaction [trans=7fda94de5900] removed from pending queue
2022-05-11 20:28:46.329202 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel [this=7fda34739300] SetWarningReporter [0]
2022-05-11 20:28:46.329210 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpTransaction::Close [this=7fda94de5900 reason=804b0002]
2022-05-11 20:28:46.329212 UTC - [Parent 12: Main Thread]: D/nsHttp ParentChannelListener::~ParentChannelListener 7fda51e78e80
2022-05-11 20:28:46.329237 UTC - [Parent 12: Main Thread]: D/cache2 CacheEntryHandle::Dismiss 7fda5bfbc7a0
2022-05-11 20:28:46.329243 UTC - [Parent 12: Main Thread]: D/cache2 already dropped
2022-05-11 20:28:46.329247 UTC - [Parent 12: Main Thread]: D/cache2 CacheEntryHandle::~CacheEntryHandle 7fda5bfbc7a0
2022-05-11 20:28:46.329253 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpTransaction::ShouldRestartOn0RttError [this=7fda94de5900, mEarlyDataWasAvailable=0 error=804b0002]
2022-05-11 20:28:46.329261 UTC - [Parent 12: Socket Thread]: V/nsHttp HttpTrafficAnalyzer::AccumulateHttpTransferredSize [Y1_N1] rb=0 sb=0 [this=7fdb3899f935]
2022-05-11 20:28:46.329266 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpTransaction::RemoveDispatchedAsBlocking this=7fda94de5900 not blocking
2022-05-11 20:28:46.329269 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpTransaction 7fda94de5900 request context set to null in ReleaseBlockingTransaction() - was 7fdb1dfc50b0
2022-05-11 20:28:46.329285 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpTransaction::DeleteSelfOnConsumerThread [this=7fda94de5900]
2022-05-11 20:28:46.329289 UTC - [Parent 12: Socket Thread]: V/nsHttp proxying delete to consumer thread...
2022-05-11 20:28:46.329305 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport STS poll iter
2022-05-11 20:28:46.329312 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [7] { handler=7fdad6620800 condition=80470002 pollflags=6 }
2022-05-11 20:28:46.329312 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=7fdb1dd812e0 bgParent=0]
2022-05-11 20:28:46.329318 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransportService::DetachSocket [handler=7fdad6620800]
2022-05-11 20:28:46.329329 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel [this=7fda3473b700] SetWarningReporter [0]
2022-05-11 20:28:46.329339 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketDetached [this=7fdad6620800 cond=80470002]
2022-05-11 20:28:46.329348 UTC - [Parent 12: Main Thread]: D/nsHttp Destroying HttpChannelParent [this=7fdb1dd812e0]
2022-05-11 20:28:46.329349 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::RecoverFromError [this=7fdad6620800 state=3 cond=80470002]
2022-05-11 20:28:46.329357 UTC - [Parent 12: Main Thread]: D/nsHttp HttpChannelParent::CleanupBackgroundChannel [this=7fdb1dd812e0 bgParent=0]
2022-05-11 20:28:46.329365 UTC - [Parent 12: Main Thread]: V/nsHttp nsHttpChannel [this=7fda3473b700] SetWarningReporter [0]
2022-05-11 20:28:46.329367 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Adding address to blocklist for host [www.vinc17.net], host record [7fda8d3ec500].used trr=0
2022-05-11 20:28:46.329373 UTC - [Parent 12: Main Thread]: D/nsHttp ParentChannelListener::~ParentChannelListener 7fda5cdd7b20
2022-05-11 20:28:46.329378 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Successfully adding address [155.133.131.76] to blocklist for host [www.vinc17.net].
[...]

and about the connection to https://www.vinc17.net/cine/watch.fr.html I get:

[...]
2022-05-11 20:28:50.756854 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Checking unusable list for host [www.vinc17.net], host record [7fda8d3ec500].
2022-05-11 20:28:50.756862 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Address [155.133.131.76] is blocklisted for host [www.vinc17.net].
2022-05-11 20:28:50.756867 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Checking unusable list for host [www.vinc17.net], host record [7fda8d3ec500].
2022-05-11 20:28:50.756880 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::InitiateSocket [this=7fda34599000]
2022-05-11 20:28:50.756886 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::BuildSocket [this=7fda34599000]
2022-05-11 20:28:50.756891 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport pushing io layer [0:ssl]
2022-05-11 20:28:50.757026 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport [secinfo=7fda6059de00 callbacks=7fda1b3dfe20]
2022-05-11 20:28:50.757047 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AttachSocket [handler=7fda34599000]
2022-05-11 20:28:50.757053 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AddToIdleList [handler=7fda34599000]
2022-05-11 20:28:50.757058 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active=7 idle=1
2022-05-11 20:28:50.757063 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport advancing to STATE_CONNECTING
2022-05-11 20:28:50.757068 UTC - [Parent 12: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=7fda34599000 status=804b0007]
2022-05-11 20:28:50.757073 UTC - [Parent 12: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=7fda94de5900 status=804b0007 progress=0]
2022-05-11 20:28:50.757088 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport trying address: 2001:4b99:1:3:216:3eff:fe20:ac98
2022-05-11 20:28:50.757111 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport ErrorAccordingToNSPR [in=-5980 out=804b000d]
2022-05-11 20:28:50.757118 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport after event [this=7fda34599000 cond=804b000d]
2022-05-11 20:28:50.757127 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport STS poll iter
2022-05-11 20:28:50.757133 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [6] { handler=7fda3495dc00 condition=0 pollflags=5 }
2022-05-11 20:28:50.757137 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda3495dc00
2022-05-11 20:28:50.757141 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757146 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [5] { handler=7fda2eef3400 condition=0 pollflags=5 }
2022-05-11 20:28:50.757151 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda2eef3400
2022-05-11 20:28:50.757155 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757160 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [4] { handler=7fda95745c00 condition=0 pollflags=5 }
2022-05-11 20:28:50.757164 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda95745c00
2022-05-11 20:28:50.757168 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757172 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [3] { handler=7fda94f09400 condition=0 pollflags=5 }
2022-05-11 20:28:50.757177 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda94f09400
2022-05-11 20:28:50.757180 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757185 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [2] { handler=7fda3459a400 condition=0 pollflags=5 }
2022-05-11 20:28:50.757189 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda3459a400
2022-05-11 20:28:50.757193 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757198 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [1] { handler=7fda226e8400 condition=0 pollflags=5 }
2022-05-11 20:28:50.757203 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda226e8400
2022-05-11 20:28:50.757206 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757218 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport active [0] { handler=7fda86f40800 condition=0 pollflags=5 }
2022-05-11 20:28:50.757222 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=7fda86f40800
2022-05-11 20:28:50.757227 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport engaging
2022-05-11 20:28:50.757232 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport idle [0] { handler=7fda34599000 condition=804b000d pollflags=0 }
2022-05-11 20:28:50.757237 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransportService::DetachSocket [handler=7fda34599000]
2022-05-11 20:28:50.757242 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketDetached [this=7fda34599000 cond=804b000d]
2022-05-11 20:28:50.757248 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketTransport::RecoverFromError [this=7fda34599000 state=3 cond=804b000d]
2022-05-11 20:28:50.757254 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Adding address to blocklist for host [www.vinc17.net], host record [7fda8d3ec500].used trr=0
2022-05-11 20:28:50.757261 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Successfully adding address [2001:4b99:1:3:216:3eff:fe20:ac98] to blocklist for host [www.vinc17.net].
[...]

So it seems that because the IPv4 address 155.133.131.76 is blocklisted (why???), Firefox tries the IPv6 address (which is then blocklisted, perhaps because it is not working).

This may be the same as bug 1640212 ("Missing elements of a web page until page reload"), where it also seems to be related to non-working IPv6. The logs also show blocklisted IP addresses.

The log shows that we put an IPV4 address into a blocked list:

2022-05-11 20:28:46.329378 UTC - [Parent 12: Socket Thread]: D/nsHostResolver Successfully adding address [155.133.131.76] to blocklist for host [www.vinc17.net].

But, the socket is closed because a transaction is cancelled.

2022-05-11 20:28:46.329007 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgCancelTransaction [trans=7fda94de5930]
2022-05-11 20:28:46.329017 UTC - [Parent 12: Socket Thread]: V/nsHttp DnsAndConnectSocket::Abandon [this=7fda5b65ef80 ent=www.vinc17.net] 7fdad6620818 0 7fdad6620ab0 0
2022-05-11 20:28:46.329021 UTC - [Parent 12: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick armed=1 active=3
2022-05-11 20:28:46.329026 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport Reset callbacks for secinfo=7fda34aeea00 callbacks=7fda9369d370
2022-05-11 20:28:46.329033 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=7fdad6620ab0]
2022-05-11 20:28:46.329037 UTC - [Parent 12: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::CloseWithStatus [this=7fdad6620ab0 reason=80470002]

The error code 80470002(NS_BASE_STREAM_CLOSED) is from here

I think we should not block an IP address when the error code is NS_BASE_STREAM_CLOSED.

Assignee: nobody → kershaw
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Severity: -- → S3
Priority: -- → P2
Whiteboard: [necko-triaged]
Pushed by kjang@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/7c6ff1348751 Don't report DNS error for NS_BASE_STREAM_CLOSED, r=necko-reviewers,dragana

https://hg.mozilla.org/mozilla-central/rev/7c6ff1348751

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox102: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 102 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: