nsHttpConnectionMgr::OnMsgReclaimConnection called with wrong connection entry
Categories
(Core :: Networking: HTTP, defect, P1)
Tracking
()
People
(Reporter: mayhemer, Assigned: mayhemer)
References
(Blocks 1 open bug, Regression)
Details
(Keywords: regression, Whiteboard: [necko-triaged][secure-proxy][skyline][http-conn])
Attachments
(1 file)
(deleted),
text/x-phabricator-request
|
pascalc
:
approval-mozilla-beta+
|
Details |
We are not able to remove closed connections to h2 proxies because of mixture of connection entries for anon and non-anon connections. I have a log where we create multiple connections to a proxy (note please that the limit is unreasonably 6, not 32 as it appears from the log...) where 1.1-forced and websocket CLOSED conns are not removed from the active list.
The reason is that we call OnMsgReclaimConnection with a different connection entry - we use only one entry for anonymus and onymous requests (we share them), while two entries (a- and not-a-) can coexist when using h2 (or h2 proxy).
Hence, we need to lookup the right entry at nsHttpConnectionMgr.cpp.
W/o it we just queue new requests for websockets indefinitely, when the proxy doesn't allow extended connect protocol, because here we return false: Http2Session.cpp - mozsearch
This is quite a racy thing to happen, apparently, as I discovered this only today.
Fallout from bug 1363284
Assignee | ||
Updated•5 years ago
|
Updated•5 years ago
|
Assignee | ||
Comment 1•5 years ago
|
||
STR (100%):
- run and setup the client for https://github.com/mayhemer/node_http2_proxy at default config
- go to https://www.websocket.org/echo.html (a simple web socket test)
- let fully load
- click [connect]
- click [send]
- expected: log shows connected and sent/received lines
- wait ~30 seconds
- ctrl-F5 reload the tab with the websocket test
- let fully load
- click [connect]
AR:
- no CONNECTED log, just nothing happens, after around 60s an error shows
ER:
- connected, and then you can send and receive messages as before the reload
Assignee | ||
Comment 2•5 years ago
|
||
Assignee | ||
Updated•5 years ago
|
Comment 5•5 years ago
|
||
Backed out changeset 27196ff54fd7 (Bug 1565242) for failing an assertion on nsHttpConnectionMgr.cpp
Backout link: https://hg.mozilla.org/integration/autoland/rev/bbfdc264f3e0ec3b5a6a19760fdb7bb7a82b8c94
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=256799409&repo=autoland&lineNumber=6700
[task 2019-07-16T19:54:14.843Z] 19:54:14 INFO - TEST-START | testing/firefox-ui/tests/functional/security/test_ssl_disabled_error_page.py TestSSLDisabledErrorPage.test_ssl_disabled_error_page
[task 2019-07-16T19:54:14.844Z] 19:54:14 INFO - 1563306854835 Marionette DEBUG 11 <- [1,150,null,{"value":null}]
[task 2019-07-16T19:54:14.848Z] 19:54:14 INFO - 1563306854845 Marionette DEBUG Accepted connection 12 from 127.0.0.1:48640
[task 2019-07-16T19:54:14.849Z] 19:54:14 INFO - 1563306854847 Marionette DEBUG Closed connection 11
[task 2019-07-16T19:54:14.853Z] 19:54:14 INFO - 1563306854851 Marionette DEBUG 12 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-07-16T19:54:14.861Z] 19:54:14 INFO - 1563306854858 Marionette TRACE [23622320129] Frame script loaded
[task 2019-07-16T19:54:15.160Z] 19:54:15 INFO - 1563306855154 Marionette TRACE [23622320129] Frame script registered
[task 2019-07-16T19:54:15.218Z] 19:54:15 INFO - 1563306855210 Marionette DEBUG 12 <- [1,1,null,{"sessionId":"d62eea47-a5f0-4939-a8dc-6da98b4276d2","capabilities":{"browserName":"firefox","browserVersion":"70.0a ... ld/tmp9fbkDc.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-07-16T19:54:15.219Z] 19:54:15 INFO - 1563306855213 Marionette DEBUG 12 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-07-16T19:54:15.221Z] 19:54:15 INFO - 1563306855214 Marionette DEBUG 12 <- [1,2,null,{"value":null}]
[task 2019-07-16T19:54:15.222Z] 19:54:15 INFO - 1563306855216 Marionette DEBUG 12 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-07-16T19:54:15.223Z] 19:54:15 INFO - 1563306855217 Marionette DEBUG 12 <- [1,3,null,{"value":null}]
[task 2019-07-16T19:54:15.224Z] 19:54:15 INFO - 1563306855221 Marionette DEBUG 12 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-07-16T19:54:15.226Z] 19:54:15 INFO - 1563306855224 Marionette DEBUG 12 <- [1,4,null,{"value":null}]
[task 2019-07-16T19:54:15.230Z] 19:54:15 INFO - 1563306855227 Marionette DEBUG 12 -> [0,5,"WebDriver:GetWindowHandles",{}]
[task 2019-07-16T19:54:15.231Z] 19:54:15 INFO - 1563306855228 Marionette DEBUG 12 <- [1,5,null,["23622320129"]]
[task 2019-07-16T19:54:15.231Z] 19:54:15 INFO - 1563306855229 Marionette DEBUG 12 -> [0,6,"WebDriver:GetWindowHandles",{}]
[task 2019-07-16T19:54:15.235Z] 19:54:15 INFO - 1563306855232 Marionette DEBUG 12 <- [1,6,null,["23622320129"]]
[task 2019-07-16T19:54:15.236Z] 19:54:15 INFO - 1563306855234 Marionette DEBUG 12 -> [0,7,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-07-16T19:54:15.236Z] 19:54:15 INFO - 1563306855234 Marionette DEBUG 12 <- [1,7,null,{"value":null}]
[task 2019-07-16T19:54:15.239Z] 19:54:15 INFO - 1563306855237 Marionette DEBUG 12 -> [0,8,"WebDriver:GetChromeWindowHandle",{}]
...
[task 2019-07-16T19:54:15.346Z] 19:54:15 INFO - 1563306855346 Marionette DEBUG 12 -> [0,35,"WebDriver:Navigate",{"url":"about:about"}]
[task 2019-07-16T19:54:15.362Z] 19:54:15 INFO - 1563306855358 Marionette TRACE [23622320129] Received DOM event beforeunload for https://extended-validation.badssl.com/
[task 2019-07-16T19:54:15.379Z] 19:54:15 INFO - ++DOCSHELL 0x7fdeb7c49000 == 11 [pid = 841] [id = {42c18136-32e7-4719-b7c1-511ed2885f29}]
[task 2019-07-16T19:54:15.379Z] 19:54:15 INFO - ++DOMWINDOW == 24 (0x7fdeb7eb5d40) [pid = 841] [serial = 36] [outer = (nil)]
[task 2019-07-16T19:54:15.380Z] 19:54:15 INFO - ++DOMWINDOW == 25 (0x7fdeb934dc00) [pid = 841] [serial = 37] [outer = 0x7fdeb7eb5d40]
[task 2019-07-16T19:54:15.401Z] 19:54:15 INFO - 1563306855398 Marionette TRACE [36] Frame script loaded
[task 2019-07-16T19:54:15.401Z] 19:54:15 INFO - 1563306855399 Marionette TRACE [36] Frame script registered
[task 2019-07-16T19:54:15.418Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.418Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.418Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.418Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.438Z] 19:54:15 INFO - 1563306855433 Marionette TRACE [23622320129] Received DOM event pagehide for https://extended-validation.badssl.com/
[task 2019-07-16T19:54:15.442Z] 19:54:15 INFO - 1563306855439 Marionette TRACE [23622320129] Received DOM event unload for https://extended-validation.badssl.com/
[task 2019-07-16T19:54:15.458Z] 19:54:15 INFO - 1563306855446 Marionette TRACE [23622320129] Received observer notification outer-window-destroyed
[task 2019-07-16T19:54:15.479Z] 19:54:15 INFO - 1563306855475 Marionette TRACE [36] Check readyState uninitialized for about:blank
[task 2019-07-16T19:54:15.486Z] 19:54:15 INFO - ++DOMWINDOW == 26 (0x7fdeb949dc00) [pid = 841] [serial = 38] [outer = 0x7fdeb7eb5d40]
[task 2019-07-16T19:54:15.503Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.503Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.503Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.503Z] 19:54:15 INFO - [Parent 841, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-16T19:54:15.612Z] 19:54:15 INFO - 1563306855604 Marionette TRACE [36] Received DOM event DOMContentLoaded for about:about
[task 2019-07-16T19:54:15.628Z] 19:54:15 INFO - 1563306855624 Marionette TRACE [36] Received DOM event pageshow for about:about
[task 2019-07-16T19:54:15.709Z] 19:54:15 INFO - 1563306855702 Marionette DEBUG 12 <- [1,35,null,{"value":null}]
[task 2019-07-16T19:54:15.711Z] 19:54:15 INFO - 1563306855708 Marionette DEBUG 12 -> [0,36,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-07-16T19:54:15.712Z] 19:54:15 INFO - 1563306855709 Marionette DEBUG 12 <- [1,36,null,{"value":null}]
[task 2019-07-16T19:54:15.717Z] 19:54:15 INFO - 1563306855713 Marionette DEBUG 12 -> [0,37,"Marionette:GetContext",{}]
[task 2019-07-16T19:54:15.718Z] 19:54:15 INFO - 1563306855714 Marionette DEBUG 12 <- [1,37,null,{"value":"chrome"}]
[task 2019-07-16T19:54:15.720Z] 19:54:15 INFO - 1563306855716 Marionette DEBUG 12 -> [0,38,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-07-16T19:54:15.720Z] 19:54:15 INFO - 1563306855717 Marionette DEBUG 12 <- [1,38,null,{"value":null}]
[task 2019-07-16T19:54:15.727Z] 19:54:15 INFO - 1563306855722 Marionette DEBUG 12 -> [0,39,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"sessions":true}],"filename":"../../ven ... lve(true);\n }, aError => {\n resolve(false);\n });","sandbox":"default","line":75}]
[task 2019-07-16T19:54:15.748Z] 19:54:15 INFO - --DOCSHELL 0x7f1a99bbd000 == 0 [pid = 1190] [id = {05e51b47-2d5f-44fb-a250-28d9e845ef40}] [url = https://extended-validation.badssl.com/]
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - Assertion failure: false (Active connection not found), at /builds/worker/workspace/build/src/netwerk/protocol/http/nsHttpConnectionMgr.cpp:2854
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - #01: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x11aae4f]
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - #02: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xd5f35e]
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - #03: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xd61899]
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - #04: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xe96b5c]
[task 2019-07-16T19:54:15.765Z] 19:54:15 INFO - #05: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xe975af]
[task 2019-07-16T19:54:15.766Z] 19:54:15 INFO - #06: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xd5f35e]
[task 2019-07-16T19:54:15.768Z] 19:54:15 INFO - #07: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xd61899]
[task 2019-07-16T19:54:15.769Z] 19:54:15 INFO - #08: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x12b5f07]
[task 2019-07-16T19:54:15.769Z] 19:54:15 INFO - #09: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x126b2ed]
[task 2019-07-16T19:54:15.771Z] 19:54:15 INFO - #10: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0x126b248]
[task 2019-07-16T19:54:15.771Z] 19:54:15 INFO - #11: ???[/builds/worker/workspace/build/application/firefox/libxul.so +0xd5cae2]
[task 2019-07-16T19:54:15.772Z] 19:54:15 INFO - #12: ???[/builds/worker/workspace/build/application/firefox/libnspr4.so +0x2b388]
[task 2019-07-16T19:54:15.773Z] 19:54:15 INFO - #13: ???[/lib/x86_64-linux-gnu/libpthread.so.0 +0x76ba]
[task 2019-07-16T19:54:15.773Z] 19:54:15 INFO - #14: clone[/lib/x86_64-linux-gnu/libc.so.6 +0x10741d]
[task 2019-07-16T19:54:15.774Z] 19:54:15 INFO - #15: ??? (???:???)
[task 2019-07-16T19:54:15.791Z] 19:54:15 INFO - ExceptionHandler::GenerateDump cloned child 1235
[task 2019-07-16T19:54:15.791Z] 19:54:15 INFO - ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-07-16T19:54:15.794Z] 19:54:15 INFO - ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-07-16T19:54:15.810Z] 19:54:15 INFO - 1563306855801 Marionette DEBUG 12 <- [1,39,null,{"value":true}]
[task 2019-07-16T19:54:15.847Z] 19:54:15 INFO - --DOMWINDOW == 2 (0x7f1a9abdfd40) [pid = 1190] [serial = 1] [outer = (nil)] [url = https://extended-validation.badssl.com/]
[task 2019-07-16T19:54:15.847Z] 19:54:15 INFO - --DOMWINDOW == 1 (0x7f1a9a1bf800) [pid = 1190] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-07-16T19:54:15.847Z] 19:54:15 INFO - --DOMWINDOW == 0 (0x7f1a9a1ce400) [pid = 1190] [serial = 3] [outer = (nil)] [url = https://extended-validation.badssl.com/]
[task 2019-07-16T19:54:15.883Z] 19:54:15 INFO - [Child 1190, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 194
[task 2019-07-16T19:54:15.883Z] 19:54:15 INFO - [Child 1190, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 194
[task 2019-07-16T19:54:15.883Z] 19:54:15 INFO - nsStringStats
[task 2019-07-16T19:54:15.886Z] 19:54:15 INFO - => mAllocCount: 9322
[task 2019-07-16T19:54:15.886Z] 19:54:15 INFO - => mReallocCount: 0
[task 2019-07-16T19:54:15.886Z] 19:54:15 INFO - => mFreeCount: 9322
[task 2019-07-16T19:54:15.887Z] 19:54:15 INFO - => mShareCount: 6970
[task 2019-07-16T19:54:15.888Z] 19:54:15 INFO - => mAdoptCount: 651
[task 2019-07-16T19:54:15.888Z] 19:54:15 INFO - => mAdoptFreeCount: 655
[task 2019-07-16T19:54:15.888Z] 19:54:15 INFO - => Process ID: 1190, Thread ID: 139752668866368
[task 2019-07-16T19:54:15.960Z] 19:54:15 INFO - Exiting due to channel error.
[task 2019-07-16T19:54:15.960Z] 19:54:15 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2019-07-16T19:54:15.960Z] 19:54:15 INFO - [Child 899, Chrome_ChildThread] WARNING: pipe error (3): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 358
[task 2019-07-16T19:54:15.960Z] 19:54:15 INFO - Exiting due to channel error.
Updated•5 years ago
|
Assignee | ||
Comment 6•5 years ago
|
||
Comment 8•5 years ago
|
||
bugherder |
Hi Honza, since 69 is marked as affected, could you please nominate an uplift of this fix to beta69? Thanks!
Assignee | ||
Comment 10•5 years ago
|
||
Comment on attachment 9077707 [details]
Bug 1565242 - Remove HTTP/2 connection (e2e or proxy) from the opposite (an)onymous connection entry in case it cannot be found in the entry the connection is associated with because of HTTP/2 (an)onymous connection pool sharing, r=kershaw!
Beta/Release Uplift Approval Request
- User impact if declined: indefinite connection hangs
- Is this code covered by automated tests?: No
- Has the fix been verified in Nightly?: Yes
- Needs manual test from QE?: Yes
- If yes, steps to reproduce: https://bugzilla.mozilla.org/show_bug.cgi?id=1565242#c1
- List of other uplifts needed: None
- Risk to taking this patch: Low
- Why is the change risky/not risky? (and alternatives if risky): just releases an unused connection and thus drops the active connection counter appropriately, I don't expect any problems here
- String changes made/needed:
Assignee | ||
Updated•5 years ago
|
Updated•5 years ago
|
Comment 11•5 years ago
|
||
Comment on attachment 9077707 [details]
Bug 1565242 - Remove HTTP/2 connection (e2e or proxy) from the opposite (an)onymous connection entry in case it cannot be found in the entry the connection is associated with because of HTTP/2 (an)onymous connection pool sharing, r=kershaw!
Low risk and affects skyline, uplift approved for 69 beta 12, thanks.
Comment 12•5 years ago
|
||
bugherder uplift |
Comment 13•5 years ago
|
||
Verified fixed on Firefox Beta 69.0b9(20190730004747) and Firefox Nightly 70.0a1(20190807215212) using Windows 10, MacOS 10.13.6 and Ubuntu 18.04.
Comment 14•5 years ago
|
||
Is this something we need on ESR68 or can we wontfix it?
Assignee | ||
Comment 15•5 years ago
|
||
(In reply to Ryan VanderMeulen [:RyanVM] from comment #14)
Is this something we need on ESR68 or can we wontfix it?
This mostly affects only h2 proxying under some specific conditions. I think this change is too sensitive to uplift just like that w/o baking it first.
Updated•5 years ago
|
Updated•3 years ago
|
Description
•