[go: nahoru, domu]
Open Bug 1762911 Opened 2 years ago Updated 8 days ago

Intermittent LeakSanitizer | leak at mozilla::net::AddStaticElement, AddStaticElement, InitializeStaticHeaders, mozilla::net::nvFIFO::nvFIFO

Categories

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

Product:
Core
Component:
Networking: HTTP
Type:
defect

Tracking

()

Status:
ASSIGNED
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox99 --- unaffected
firefox100 --- wontfix
firefox101 --- wontfix

People

(Reporter: intermittent-bug-filer, Assigned: valentin)

References

(Depends on 1 open bug, Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell unknown][necko-triaged])

Attachments

(2 obsolete files)

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=373266187&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KjgtngrmT_ydlCKUGoG7-Q/runs/0/artifacts/public/logs/live_backing.log

[task 2022-04-04T12:25:33.406Z] 12:25:33     INFO - PID 18606 | Direct leak of 32 byte(s) in 1 object(s) allocated from:
[task 2022-04-04T12:25:33.406Z] 12:25:33     INFO - PID 18606 |     #0 0x557fd54a2e6d in malloc /builds/worker/fetches/llvm-project/compiler-rt/lib/asan/asan_malloc_linux.cpp:129:3
[task 2022-04-04T12:25:33.407Z] 12:25:33     INFO - PID 18606 |     #1 0x557fd54ddd1d in moz_xmalloc /builds/worker/checkouts/gecko/memory/mozalloc/mozalloc.cpp:52:15
[task 2022-04-04T12:25:33.407Z] 12:25:33     INFO - PID 18606 |     #2 0x7fcc4c095999 in operator new /builds/worker/workspace/obj-build/dist/include/mozilla/cxxalloc.h:33:10
[task 2022-04-04T12:25:33.408Z] 12:25:33     INFO - PID 18606 |     #3 0x7fcc4c095999 in mozilla::net::AddStaticElement(nsTString<char> const&, nsTString<char> const&) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:96:18
[task 2022-04-04T12:25:33.408Z] 12:25:33     INFO - PID 18606 |     #4 0x7fcc4c0183af in InitializeStaticHeaders /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:115:5
[task 2022-04-04T12:25:33.409Z] 12:25:33     INFO - PID 18606 |     #5 0x7fcc4c0183af in mozilla::net::nvFIFO::nvFIFO() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:183:20
[task 2022-04-04T12:25:33.409Z] 12:25:33     INFO - PID 18606 |     #6 0x7fcc4c01b9d3 in mozilla::net::Http2BaseCompressor::Http2BaseCompressor() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:234:22
[task 2022-04-04T12:25:33.410Z] 12:25:33     INFO - PID 18606 |     #7 0x7fcc4c03aabd in mozilla::net::Http2Compressor::Http2Compressor() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.h:155:3
[task 2022-04-04T12:25:33.410Z] 12:25:33     INFO - PID 18606 |     #8 0x7fcc4c039ab5 in mozilla::net::Http2Session::Http2Session(nsISocketTransport*, mozilla::net::SpdyVersion, bool) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Session.cpp:110:15
[task 2022-04-04T12:25:33.411Z] 12:25:33     INFO - PID 18606 |     #9 0x7fcc4c0389db in mozilla::net::Http2Session::CreateSession(nsISocketTransport*, mozilla::net::SpdyVersion, bool) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Session.cpp:105:11
[task 2022-04-04T12:25:33.411Z] 12:25:33     INFO - PID 18606 |     #10 0x7fcc4c24347a in mozilla::net::nsHttpConnection::StartSpdy(nsISSLSocketControl*, mozilla::net::SpdyVersion) /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp:292:9
[task 2022-04-04T12:25:33.412Z] 12:25:33     INFO - PID 18606 |     #11 0x7fcc4c259c1f in mozilla::net::nsHttpConnection::HandshakeDoneInternal() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp
[task 2022-04-04T12:25:33.412Z] 12:25:33     INFO - PID 18606 |     #12 0x7fcc4c2c9a5a in operator() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp:2543:19
[task 2022-04-04T12:25:33.413Z] 12:25:33     INFO - PID 18606 |     #13 0x7fcc4c2c9a5a in mozilla::detail::RunnableFunction<mozilla::net::nsHttpConnection::HandshakeDone()::$_0>::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:531:5
[task 2022-04-04T12:25:33.413Z] 12:25:33     INFO - PID 18606 |     #14 0x7fcc4b4b41cf in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1181:16
[task 2022-04-04T12:25:33.413Z] 12:25:33     INFO - PID 18606 |     #15 0x7fcc4b4bd98c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:465:10
[task 2022-04-04T12:25:33.414Z] 12:25:33     INFO - PID 18606 |     #16 0x7fcc4b86f8f1 in mozilla::net::nsSocketTransportService::Run() /builds/worker/checkouts/gecko/netwerk/base/nsSocketTransportService2.cpp:1202:11
[task 2022-04-04T12:25:33.414Z] 12:25:33     INFO - PID 18606 |     #17 0x7fcc4b87154c in non-virtual thunk to mozilla::net::nsSocketTransportService::Run() /builds/worker/checkouts/gecko/netwerk/base/nsSocketTransportService2.cpp
[task 2022-04-04T12:25:33.415Z] 12:25:33     INFO - PID 18606 |     #18 0x7fcc4b4b41cf in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1181:16
[task 2022-04-04T12:25:33.415Z] 12:25:33     INFO - PID 18606 |     #19 0x7fcc4b4bd98c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:465:10
[task 2022-04-04T12:25:33.416Z] 12:25:33     INFO - PID 18606 |     #20 0x7fcc4c7978a8 in mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:300:20
[task 2022-04-04T12:25:33.416Z] 12:25:33     INFO - PID 18606 |     #21 0x7fcc4c6a3061 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:380:10
[task 2022-04-04T12:25:33.417Z] 12:25:33     INFO - PID 18606 |     #22 0x7fcc4c6a3061 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:373:3
[task 2022-04-04T12:25:33.417Z] 12:25:33     INFO - PID 18606 |     #23 0x7fcc4c6a3061 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:355:3
[task 2022-04-04T12:25:33.418Z] 12:25:33     INFO - PID 18606 |     #24 0x7fcc4b4ac6fc in nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:385:10
[task 2022-04-04T12:25:33.418Z] 12:25:33     INFO - PID 18606 |     #25 0x7fcc6cba0ade in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2022-04-04T12:25:33.418Z] 12:25:33     INFO - PID 18606 |     #26 0x7fcc6e85d6da in start_thread /tmp/glibc/nptl/pthread_create.c:463
[task 2022-04-04T12:25:33.419Z] 12:25:33     INFO - PID 18606 | -----------------------------------------------------
[task 2022-04-04T12:25:33.419Z] 12:25:33     INFO - PID 18606 | Suppressions used:
[task 2022-04-04T12:25:33.420Z] 12:25:33     INFO - PID 18606 |   count      bytes template
[task 2022-04-04T12:25:33.420Z] 12:25:33     INFO - PID 18606 |       9        280 nsComponentManagerImpl
[task 2022-04-04T12:25:33.421Z] 12:25:33     INFO - PID 18606 |     631      18073 libfontconfig.so
[task 2022-04-04T12:25:33.421Z] 12:25:33     INFO - PID 18606 |       4      16407 libglib-2.0.so
[task 2022-04-04T12:25:33.421Z] 12:25:33     INFO - PID 18606 |       1        192 mozJSComponentLoader
[task 2022-04-04T12:25:33.421Z] 12:25:33     INFO - PID 18606 |       2         48 XPCWrappedNativeJSOps
[task 2022-04-04T12:25:33.422Z] 12:25:33     INFO - PID 18606 | -----------------------------------------------------
[task 2022-04-04T12:25:33.422Z] 12:25:33     INFO - PID 18606 | 1649075132911	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2022-04-04T12:25:33.423Z] 12:25:33     INFO - PID 18606 | 1649075132911	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-04-04T12:25:33.423Z] 12:25:33     INFO - PID 18606 | 1649075132930	webdriver::server	DEBUG	-> GET /status
[task 2022-04-04T12:25:33.423Z] 12:25:33     INFO - PID 18606 | 1649075132930	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"","ready":true}}
[task 2022-04-04T12:25:33.424Z] 12:25:33     INFO - ERROR | LeakSanitizer | SUMMARY: AddressSanitizer: 1952 byte(s) leaked in 61 allocation(s).
[task 2022-04-04T12:25:33.424Z] 12:25:33     INFO - LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2022-04-04T12:25:33.424Z] 12:25:33     INFO - This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2022-04-04T12:25:33.424Z] 12:25:33     INFO - Allowed depth was 4
[task 2022-04-04T12:25:33.425Z] 12:25:33     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::net::AddStaticElement, AddStaticElement, InitializeStaticHeaders, mozilla::net::nvFIFO::nvFIFO
[task 2022-04-04T12:25:33.425Z] 12:25:33     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::net::AddStaticElement, InitializeStaticHeaders, mozilla::net::nvFIFO::nvFIFO, mozilla::net::Http2BaseCompressor::Http2BaseCompressor
[task 2022-04-04T12:25:33.426Z] 12:25:33     INFO - Closing logging queue
[task 2022-04-04T12:25:33.427Z] 12:25:33     INFO - queue closed
[task 2022-04-04T12:25:33.869Z] 12:25:33     INFO - PID 18921 | 1649075133367	geckodriver	INFO	Listening on 127.0.0.1:53319
[task 2022-04-04T12:25:33.869Z] 12:25:33     INFO - Starting runner
[task 2022-04-04T12:25:34.122Z] 12:25:34     INFO - TEST-START | /_mozilla/webdriver/take_full_screenshot/iframe.py
Severity: S4 → --
Priority: P5 → --

All failures here are on beta/try.

Regressed by: 1755767

Set release status flags based on info from the regressing bug 1755767

status-firefox100: --- → affected
status-firefox101: --- → affected
status-firefox99: --- → unaffected
status-firefox-esr91: --- → unaffected

:dragana, since you are the author of the regressor, bug 1755767, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(dd.mozilla)
Has Regression Range: --- → yes
Status: NEW → RESOLVED
Closed: 2 years ago
Flags: needinfo?(dd.mozilla)
Resolution: --- → FIXED

Dragana, when and where was it fixed? If you would have a reference that would be great. I'm asking because we recently had such a leak in a beta simulation for 107b12:

https://treeherder.mozilla.org/jobs?repo=try&revision=4cf345b958934c7a490bd1daddf217db9957e0a3&selectedTaskRun=M2aZJuB4Sm2XFYxw9eRf3g.0

Note that the wdspec issues are tracked via bug 1759310 whereby it's not happening that often anymore because we have exceptions for these leaks in place for now:

https://searchfox.org/mozilla-central/source/testing/web-platform/meta/webdriver/tests/__dir__.ini

Flags: needinfo?(dd.mozilla)

Reopening given that this is not fixed but only accepted via manifest files. Leaving needinfo for Dragana.

Status: RESOLVED → REOPENED
Resolution: FIXED → ---

Valentin maybe you could help here? Thanks a lot.

Flags: needinfo?(valentin.gosu)

Dragana has an idea how to fix this.

Flags: needinfo?(valentin.gosu)

Currently, NSS calls the handshake completed callback function, HandshakeCallback from nsNSSCallbacks.cpp. HandshakeCallback calls nsNSSSocketInfo::SetHandshakeCompleted that calls TlsHandshaker::HandshakeDone. All of this is happening while NSS holds a lock. When a handshake is done, necko may need to finish setting up Http/2Session(in the nsHttpConnection::HandshakeDoneInternal) and for that it needs info from NSS, but NSS holds the lock and that is not possible. To resolve this problem necko sets TlsHandshakerTlsHandshaker::mTlsHandshakeComplitionPending to true and dispatches a runnable that will call nsHttpConnection::HandshakeDoneInternal). This dispatch causes bug 1762911, probably due to a shutdown happening just before the runnable is executed.

To resolve the issue and to better integrate HandshakeDoneInternal into necko we will do the following:
TlsHandshaker::HandshakeDone will set mTlsHandshakeComplitionPending to true and call nsHttpConnection::ForceSend. The nsHttpConnection::ForceSend function is a better way to force the handshake to be finished because it is taking already existing standard necko code paths.
nsHttpConnection::ForceSend calls nsHttoConnection::OnOutputStreamReady that will call TlsHandshaker::Ensure NPNComplete that will call nsHttpConnection::HandshakeDoneInternal.

Assignee: nobody → dd.mozilla

The patch I have created does not resolve the issue. The leak still exists, but this time the stack is called from nsSockettransportService while iterating through sockets that are ready to read or write. This stack shows that the original theory is not entirely correct.

I have landed the patch that I created anyway because I think the patch is the more appropriate way to deal with this case.

Marking the bug leave-open because the current patch does not fix the issue.

Keywords: leave-open

I will not have time to work on this bug, so I am unassigning myself.

Assignee: dd.mozilla → nobody
Pushed by ddamjanovic@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2c4c34f31021
Change how necko finishes TLS handshake r=necko-reviewers,kershaw

Valentin, would someone of the necko team be able to continue this work including a fix for the crash which caused Dragana's patch to get backed out?

Flags: needinfo?(dd.mozilla) → needinfo?(valentin.gosu)

Yes, I'll have a look.

Assignee: nobody → valentin.gosu
Severity: -- → S3
Flags: needinfo?(valentin.gosu)
Priority: -- → P1
Whiteboard: [stockwell unknown] → [stockwell unknown][necko-triaged]

Thanks!

Status: REOPENED → ASSIGNED
Attachment #9298055 - Attachment description: Change how necko finishes TLS handshake → Bug 1762911 - Change how necko finishes TLS handshake

mTlsHandshaker->EnsureNPNComplete() may change nsHttpConnection::mState.
Calling SendConnectRequest() requires that we are in the SETTING_UP_TUNNEL.
As such, we should move the call to EnsureNPNComplete, to ensure we never
call SendConnectRequest when mProxyConnectStream is null.

Depends on D159078

There are some r+ patches which didn't land and no activity in this bug for 2 weeks.
:valentin, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit auto_nag documentation.

Flags: needinfo?(valentin.gosu)
Flags: needinfo?(kershaw)
Flags: needinfo?(kershaw)
Depends on: 1801292

Comment on attachment 9298055 [details]
Bug 1762911 - Change how necko finishes TLS handshake

Revision D159078 was moved to bug 1801292. Setting attachment 9298055 [details] to obsolete.

Attachment #9298055 - Attachment is obsolete: true

Comment on attachment 9301295 [details]
Bug 1762911 - SendConnectRequest should only be called when mState==SETTING_UP_TUNNEL r=#necko

Revision D160892 was moved to bug 1801292. Setting attachment 9301295 [details] to obsolete.

Attachment #9301295 - Attachment is obsolete: true
Flags: needinfo?(valentin.gosu)
Duplicate of this bug: 1819132
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: