Closed Bug 1593394 Opened 5 years ago Closed 5 years ago

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)

Product:
Core
Component:
Networking
Type:
defect

Tracking

()

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

People

(Reporter: val, Assigned: dragana)

References

(Regression)

Details

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

Attachments

(2 files)

flamegraph-npn.svg
743.98 KB, image/svg+xml
Details
Socks proxy is transparent and next layer should not know about it. r=mayhemer
47 bytes, text/x-phabricator-request
Details | Review
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
status-firefox70: --- → unaffected
status-firefox71: --- → unaffected
status-firefox72: --- → affected
status-firefox-esr68: --- → unaffected
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.

Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
Priority: -- → P1
Whiteboard: [necko-triaged]

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

https://hg.mozilla.org/mozilla-central/rev/59e6bca5ff47

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox72: affected → fixed
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]

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

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

Attachment

General

Creator:
Created:
Updated:
Size: