Closed Bug 1565242 Opened 5 years ago Closed 5 years ago

nsHttpConnectionMgr::OnMsgReclaimConnection called with wrong connection entry

Categories

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

Product:
Core
Component:
Networking: HTTP
Type:
defect

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla70
Tracking Flags:
Tracking Status
firefox-esr60 --- wontfix
firefox-esr68 --- wontfix
firefox68 --- wontfix
firefox69 --- verified
firefox70 --- verified

People

(Reporter: mayhemer, Assigned: mayhemer)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [necko-triaged][secure-proxy][skyline][http-conn])

Attachments

(1 file)

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!
47 bytes, text/x-phabricator-request
pascalc
: approval-mozilla-beta+
Details | Review

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

Priority: -- → P1

STR (100%):

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: nobody → honzab.moz
Status: NEW → ASSIGNED

The patch fixes the STR from comment 1 for me.

Pushed by honzab.moz@firemni.cz:
https://hg.mozilla.org/integration/autoland/rev/27196ff54fd7
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

Backed out changeset 27196ff54fd7 (Bug 1565242) for failing an assertion on nsHttpConnectionMgr.cpp

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Cdebug%2Cfirefox%2Cfunctional%2Ctests%2C%28remote%29%2Ctest-linux64%2Fdebug-firefox-ui-functional-remote-e10s%2Cfxfn-r%28en-us%29&tochange=bbfdc264f3e0ec3b5a6a19760fdb7bb7a82b8c94&fromchange=71000a40a923067a32293ef3a01d515bbd864eed&selectedJob=256799409

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.

Flags: needinfo?(honzab.moz)
Whiteboard: [necko-triaged][secure-proxy-skyline][http-conn] → [necko-triaged][secure-proxy][skyline][http-conn]
Pushed by honzab.moz@firemni.cz:
https://hg.mozilla.org/integration/autoland/rev/687930978a2a
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

https://hg.mozilla.org/mozilla-central/rev/687930978a2a

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox70: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla70
Regressions: 1571405

Hi Honza, since 69 is marked as affected, could you please nominate an uplift of this fix to beta69? Thanks!

Flags: needinfo?(honzab.moz)

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:
Flags: needinfo?(honzab.moz)
Attachment #9077707 - Flags: approval-mozilla-beta?
Flags: qe-verify+
QA Whiteboard: [qa-triaged]

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.

Attachment #9077707 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

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.

Status: RESOLVED → VERIFIED
status-firefox69: fixed → verified
status-firefox70: fixed → verified
Flags: qe-verify+

Is this something we need on ESR68 or can we wontfix it?

Flags: needinfo?(honzab.moz)

(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.

Flags: needinfo?(honzab.moz)
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: