Closed Bug 1593394 Opened Last month Closed Last month

New build of Firefox grinds to a halt with 200% CPU usage in main process when SOCKS proxy is enabled (OnSocketReady/EnsureNPNComplete + locks/polls)

Categories

(Core :: Networking, defect, P1, critical)

defect

Tracking

()

VERIFIED FIXED
mozilla72
Tracking Status
firefox-esr68 --- unaffected
firefox70 --- unaffected
firefox71 --- unaffected
firefox72 --- fixed

People

(Reporter: myfreeweb, Assigned: dragana)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [necko-triaged])

Attachments

(2 files)

Attached image flamegraph-npn.svg

Just rebuilt Firefox recently (last commit via git-cinnabar: fe67766efd3e9cea9e831363b2a6a4061d4bfa36, before that was on 7d3c846792621de8bfc4e3d8b49427a3c763b4da) and it's unusable, just opening a new tab / typing in the url bar is extremely slow and the main process is spinning with 200% CPU usage. Turning off SOCKSv5 proxy (tor) fixes the problem.

Flamegraph attached. Looks like two threads spinning (something like livelock?), a secondary one is endlessly getting ready/writable socket status and pinging the main thread, while the main thread just responds to these notifications (?) and does not really make progress.

Have not bisected yet. Maybe something to do with http3?

Checking out e0bc50caa10546b890c8d5a302b641484c77843c "Bug 1590868 - Don't crash if nsExtProtocolChannel::OnStartRequest is called, since it can happen with DocumentChannel process selection. r=mayhemer" — the commit right before the Http3 stuff — fixes the regression, so I'm pretty sure now that the regression is http3 related.

I can reproduce the issue.

MozRegression:

2019-11-03T19:58:10: INFO : Narrowed inbound regression window from [b19afbec, 0f08e0fe] (3 builds) to [380e2740, 0f08e0fe] (2 builds) (~1 steps left)
2019-11-03T19:58:10: DEBUG : Starting merge handling...
2019-11-03T19:58:10: DEBUG : Using url: https://hg.mozilla.org/integration/autoland/json-pushes?changeset=0f08e0fe895640a0260b979ca4977d954ac0f8b0&full=1
2019-11-03T19:58:17: DEBUG : Found commit message:
Bug 1581637 - Part 12 - Add extra-bindgen-flags r=glandium

Differential Revision: https://phabricator.services.mozilla.com/D47229

2019-11-03T19:58:17: DEBUG : Did not find a branch, checking all integration branches
2019-11-03T19:58:17: INFO : The bisection is done.
2019-11-03T19:58:18: INFO : Stopped

Severity: normal → critical
Status: UNCONFIRMED → NEW
Has Regression Range: --- → yes
Has STR: --- → yes
Ever confirmed: true
OS: FreeBSD → All
Regressed by: 1581637
Hardware: x86_64 → All
Version: unspecified → Trunk

I can reproduce the issue with network.http.http3.enabled is false/true and "network.proxy.socks" & "network.proxy.socks_port" is set in 72.0a1 (20191103094618) on Win10.

Duplicate of this bug: 1593503
Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
Priority: -- → P1
Whiteboard: [necko-triaged]
Duplicate of this bug: 1593774

While reorganizing code I moved a line to a wrong place:
we set proxyInfo to mProxyInfo. For the first nspr layer it will have value of mProxyInfo. In case of socks proxy the upper layer should not know about the proxy and therefor we set proxyInfo to nullptr. (I am wondering if there were a better way to do this, but my patch tried to only move code and not rewrite it to avoid regressions.)

Pushed by malexandru@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/59e6bca5ff47
Socks proxy is transparent and next layer should not know about it. r=mayhemer
Status: ASSIGNED → RESOLVED
Closed: Last month
Resolution: --- → FIXED
Target Milestone: --- → mozilla72

still not working
with any SOCKS5 proxy
all the same

(In reply to nordix.zett from comment #10)

still not working
with any SOCKS5 proxy
all the same
a LITTLE PART of log file: (created 166mb text file in FEW SECONDS)

2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: V/nsHttp nsHttpConnectionMgr::SpeculativeConnect [ci=.S......[tlsflags0x00000000]e.mail.ru:443 (socks:127.0.0.1:9050)[:]{TPRH}]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsHttp NulHttpTransaction::NullHttpTransaction() mActivityDistributor is active [this=000000001229CBD0, e.mail.ru]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsSocketTransport STS dispatch [00000000284DDF60]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsSocketTransport PollableEvent::Signal
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsSocketTransport PollableEvent::MarkFirstSignalTimestamp
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsSocketTransport PollableEvent::Signal PR_Write 1
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport ...returned after 1697 milliseconds
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/nsHttp nsHttpChannel::OpenCacheEntry [this=0000000012344000]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheStorageService::GetCacheIndexEntryAttrs [uri=https://e.mail.ru/messages/inbox/, eid=, contextKey=]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheIndex::HasEntry() [key=:https://e.mail.ru/messages/inbox/]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheIndex::HasEntry() - result is 1
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Clear
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheStorageService::AddStorageEntry [entryKey=:https://e.mail.ru/messages/inbox/, contextKey=]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Clear time to signal 0ms
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheEntry::CacheEntry [this=000000001248C020]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheStorageService::RecordMemoryOnlyEntry [entry=000000001248C020, memory=0, overwrite=1]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Clear PR_Read 1
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 RemoveExactEntry [entry=000000001248C020 already gone]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Clear PR_Read -1
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 new entry 000000001248C020 for :https://e.mail.ru/messages/inbox/
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport STS dispatch [00000000232C2400]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 New CacheEntryHandle 00000000122DE980 for entry 000000001248C020
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Signal
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheEntry::AsyncOpen [this=000000001248C020, state=NOTLOADED, flags=20, callback=0000000012344728]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::MarkFirstSignalTimestamp
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheEntry::RememberCallback [this=000000001248C020, cb=0000000012344728, state=NOTLOADED]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheEntry::Load [this=000000001248C020, trunc=0]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheIndex::HasEntry() [key=:https://e.mail.ru/messages/inbox/]
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport PollableEvent::Signal PR_Write 1
2019-11-05 19:34:26.997000 UTC - [Parent 3924: Main Thread]: D/cache2 CacheIndex::HasEntry() - result is 1
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BA800] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=00000000279B9800 tlsfilter=0000000000000000 socket=00000000279BA418
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=00000000279B9800 status=804b000c progress=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BA800 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=00000000279BA6B0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=0000000026096800
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0000000026096800 outFlags=2]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=0000000026096AB0 cond=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BD000] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=000000001229D8E0 tlsfilter=0000000000000000 socket=0000000026096818
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BD000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0000000026096AB0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport STS poll iter
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [5] { handler=0000000026096800 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096800
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [4] { handler=00000000279BA400 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=00000000279BA400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [3] { handler=0000000026096400 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [2] { handler=000000002602FC00 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=000000002602FC00
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [1] { handler=0000000026025400 condition=0 pollflags=5 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026025400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [0] { handler=0000000026026400 condition=0 pollflags=5 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026026400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport calling PR_Poll [active=6 idle=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=000000002602FC00, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=00000000279BA400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096800, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport poll timeout: none
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport timeout = -1 milliseconds
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport ...returned after 0 milliseconds
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=000000002602FC00
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000000002602FC00 outFlags=2]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=000000002602FEB0 cond=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=0000000026039000] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=000000002602E400 tlsfilter=0000000000000000 socket=000000002602FC18
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=000000002602E400 status=804b000c progress=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 0000000026039000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=000000002602FEB0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=0000000026096400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0000000026096400 outFlags=2]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=00000000260966B0 cond=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=0000000014D45000] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=0000000026095400 tlsfilter=0000000000000000 socket=0000000026096418
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0000000026095400 status=804b000c progress=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 0000000014D45000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=00000000260966B0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=00000000279BA400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=00000000279BA400 outFlags=2]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=00000000279BA6B0 cond=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BA800] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=00000000279B9800 tlsfilter=0000000000000000 socket=00000000279BA418
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=00000000279B9800 status=804b000c progress=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BA800 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=00000000279BA6B0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=0000000026096800
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0000000026096800 outFlags=2]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=0000000026096AB0 cond=0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BD000] host=e.mail.ru
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=000000001229D8E0 tlsfilter=0000000000000000 socket=0000000026096818
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BD000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0000000026096AB0]
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport STS poll iter
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [5] { handler=0000000026096800 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096800
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [4] { handler=00000000279BA400 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=00000000279BA400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [3] { handler=0000000026096400 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [2] { handler=000000002602FC00 condition=0 pollflags=7 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=000000002602FC00
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [1] { handler=0000000026025400 condition=0 pollflags=5 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026025400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [0] { handler=0000000026026400 condition=0 pollflags=5 }
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026026400
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.320000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport calling PR_Poll [active=6 idle=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=000000002602FC00, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=00000000279BA400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096800, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport poll timeout: none
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport timeout = -1 milliseconds
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport ...returned after 1 milliseconds
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=000000002602FC00
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000000002602FC00 outFlags=2]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=000000002602FEB0 cond=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=0000000026039000] host=e.mail.ru
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=000000002602E400 tlsfilter=0000000000000000 socket=000000002602FC18
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=000000002602E400 status=804b000c progress=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 0000000026039000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=000000002602FEB0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=0000000026096400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0000000026096400 outFlags=2]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=00000000260966B0 cond=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=0000000014D45000] host=e.mail.ru
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=0000000026095400 tlsfilter=0000000000000000 socket=0000000026096418
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=0000000026095400 status=804b000c progress=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 0000000014D45000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=00000000260966B0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=00000000279BA400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=00000000279BA400 outFlags=2]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=00000000279BA6B0 cond=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BA800] host=e.mail.ru
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=00000000279B9800 tlsfilter=0000000000000000 socket=00000000279BA418
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=00000000279B9800 status=804b000c progress=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BA800 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=00000000279BA6B0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=0000000026096800
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0000000026096800 outFlags=2]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=0000000026096AB0 cond=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=00000000279BD000] host=e.mail.ru
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=000000001229D8E0 tlsfilter=0000000000000000 socket=0000000026096818
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 00000000279BD000 ReadSegments returned [rv=0 read=0 sock-cond=80470007 again=1]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0000000026096AB0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport STS poll iter
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [5] { handler=0000000026096800 condition=0 pollflags=7 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096800
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [4] { handler=00000000279BA400 condition=0 pollflags=7 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=00000000279BA400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [3] { handler=0000000026096400 condition=0 pollflags=7 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026096400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [2] { handler=000000002602FC00 condition=0 pollflags=7 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=000000002602FC00
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [1] { handler=0000000026025400 condition=0 pollflags=5 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026025400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport active [0] { handler=0000000026026400 condition=0 pollflags=5 }
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::EnsureTimeout socket=0000000026026400
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport engaging
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport calling PR_Poll [active=6 idle=0]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=000000002602FC00, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=00000000279BA400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026096800, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport poll timeout: none
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport timeout = -1 milliseconds
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport ...returned after 0 milliseconds
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026026400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=0000000026025400, timeout=65535s
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport not engaged
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=000000002602FC00
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000000002602FC00 outFlags=2]
2019-11-05 19:34:29.321000 UTC - [Parent 3924: Socket Thread]: D/nsSocketTransport nsSocketOutputStream::OnSocketReady [this=000000002602FEB0 cond=0]

Duplicate of this bug: 1594171

I can verify that this seems to have been fixed in the latest nightly (20191106095742) on macOS.

Status: RESOLVED → VERIFIED
Duplicate of this bug: 1593885
Duplicate of this bug: 1594262
You need to log in before you can comment on or make changes to this bug.