1755767 - Intermittent LeakSanitizer | leak at mozilla::net::nsHttpTransaction::SetSecurityCallbacks, mozilla::net::nsHttpChannel::UpdateAggregateCallbacks, SetNotificationCallbacks, mozilla::net::nsHttpChannel::SetNotificationCallbacks

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=368078508&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/M-Dff10pQcu8jLl-K1BiUQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 | Direct leak of 32 byte(s) in 1 object(s) allocated from:
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #0 0x55d6fef08d6d in malloc /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_malloc_linux.cpp:129:3
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #1 0x55d6fef43bed in moz_xmalloc /builds/worker/checkouts/gecko/memory/mozalloc/mozalloc.cpp:52:15
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #2 0x7f97ee863d89 in operator new /builds/worker/workspace/obj-build/dist/include/mozilla/cxxalloc.h:33:10
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #3 0x7f97ee863d89 in mozilla::net::AddStaticElement(nsTString<char> const&, nsTString<char> const&) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:96:18
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #4 0x7f97ee7b3596 in AddStaticElement /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:101:3
[task 2022-02-16T14:00:13.357Z] 14:00:13     INFO - PID 1007 |     #5 0x7f97ee7b3596 in InitializeStaticHeaders /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:126:5
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #6 0x7f97ee7b3596 in mozilla::net::nvFIFO::nvFIFO() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:183:20
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #7 0x7f97ee7b6363 in mozilla::net::Http2BaseCompressor::Http2BaseCompressor() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.cpp:234:22
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #8 0x7f97ee7cb21d in mozilla::net::Http2Compressor::Http2Compressor() /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Compression.h:155:3
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #9 0x7f97ee7ca245 in mozilla::net::Http2Session::Http2Session(nsISocketTransport*, mozilla::net::SpdyVersion, bool) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Session.cpp:108:15
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #10 0x7f97ee7c915b in mozilla::net::Http2Session::CreateSession(nsISocketTransport*, mozilla::net::SpdyVersion, bool) /builds/worker/checkouts/gecko/netwerk/protocol/http/Http2Session.cpp:103:11
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #11 0x7f97ee9c60bd in mozilla::net::nsHttpConnection::StartSpdy(nsISSLSocketControl*, mozilla::net::SpdyVersion) /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp:285:9
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #12 0x7f97ee9da0a8 in mozilla::net::nsHttpConnection::HandshakeDoneInternal() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp:2657:9
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #13 0x7f97ee9fbf6f in operator() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnection.cpp:2561:17
[task 2022-02-16T14:00:13.358Z] 14:00:13     INFO - PID 1007 |     #14 0x7f97ee9fbf6f in mozilla::detail::RunnableFunction<mozilla::net::nsHttpConnection::HandshakeDone()::$_49>::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:531:5
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #15 0x7f97edc73fbf in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1189:16
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #16 0x7f97edc7e85c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:467:10
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #17 0x7f97ee029681 in mozilla::net::nsSocketTransportService::Run() /builds/worker/checkouts/gecko/netwerk/base/nsSocketTransportService2.cpp:1190:11
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #18 0x7f97ee02b2dc in non-virtual thunk to mozilla::net::nsSocketTransportService::Run() /builds/worker/checkouts/gecko/netwerk/base/nsSocketTransportService2.cpp
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #19 0x7f97edc73fbf in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1189:16
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #20 0x7f97edc7e85c in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:467:10
[task 2022-02-16T14:00:13.359Z] 14:00:13     INFO - PID 1007 |     #21 0x7f97eee08708 in mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:300:20
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #22 0x7f97eed1a561 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:331:10
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #23 0x7f97eed1a561 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:324:3
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #24 0x7f97eed1a561 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:306:3
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #25 0x7f97edc6cd15 in nsThread::ThreadFunc(void*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:391:10
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #26 0x7f980edd8ade in _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     #27 0x7f9810ba76da in start_thread /tmp/glibc/nptl/pthread_create.c:463
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 | -----------------------------------------------------
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 | Suppressions used:
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |   count      bytes template
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |       9        280 nsComponentManagerImpl
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |     631      18073 libfontconfig.so
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |       2      16393 libglib-2.0.so
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |       1        192 mozJSComponentLoader
[task 2022-02-16T14:00:13.360Z] 14:00:13     INFO - PID 1007 |       2         48 XPCWrappedNativeJSOps
[task 2022-02-16T14:00:13.361Z] 14:00:13     INFO - PID 1007 | -----------------------------------------------------
[task 2022-02-16T14:00:13.361Z] 14:00:13     INFO - PID 1007 | 1645020012545	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2022-02-16T14:00:13.361Z] 14:00:13     INFO - PID 1007 | 1645020012546	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-02-16T14:00:13.361Z] 14:00:13     INFO - PID 1007 | 1645020012596	webdriver::server	DEBUG	-> GET /status
[task 2022-02-16T14:00:13.361Z] 14:00:13     INFO - PID 1007 | 1645020012597	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"","ready":true}}
[task 2022-02-16T14:00:13.362Z] 14:00:13     INFO - INFO | LeakSanitizer | SUMMARY: AddressSanitizer: 1952 byte(s) leaked in 61 allocation(s).
[task 2022-02-16T14:00:13.363Z] 14:00:13     INFO - LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2022-02-16T14:00:13.363Z] 14:00:13     INFO - This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2022-02-16T14:00:13.364Z] 14:00:13     INFO - Allowed depth was 4
[task 2022-02-16T14:00:13.364Z] 14:00:13     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::net::AddStaticElement, InitializeStaticHeaders, mozilla::net::nvFIFO::nvFIFO, mozilla::net::Http2BaseCompressor::Http2BaseCompressor
[task 2022-02-16T14:00:13.364Z] 14:00:13     INFO - INFO | LeakSanitizer | Frame mozilla::net::AddStaticElement matched a expected leak
[task 2022-02-16T14:00:13.365Z] 14:00:13     INFO - TEST-FAIL | LeakSanitizer | leak at mozilla::net::AddStaticElement, AddStaticElement, InitializeStaticHeaders, mozilla::net::nvFIFO::nvFIFO
[task 2022-02-16T14:00:13.365Z] 14:00:13     INFO - INFO | LeakSanitizer | Frame mozilla::net::AddStaticElement matched a expected leak
[task 2022-02-16T14:00:13.366Z] 14:00:13     INFO - Closing logging queue
[task 2022-02-16T14:00:13.366Z] 14:00:13     INFO - queue closed
[task 2022-02-16T14:00:13.367Z] 14:00:13     INFO - Starting runner
[task 2022-02-16T14:00:13.368Z] 14:00:13     INFO - PID 1398 | 1645020013282	geckodriver	INFO	Listening on 127.0.0.1:38240
[task 2022-02-16T14:00:13.641Z] 14:00:13     INFO - TEST-START | /webdriver/tests/bidi/session/new/connect.py

Comment 1

[Atila Butkovits]

Reported after: webdriver/tests/accept_alert/accept.py

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This leak looks to be network related. Valentin, is that already something known?

Comment 3

[Valentin Gosu [:valentin] (he/him)]

That's interesting. So, the static header object should get cleared during shutdown via nsNetShutdown, but my best guess is that we're reinitializing it again after nsNetShutdown has been called, leading to the leak.
It's possible this was a regression from bug 1382886 which touched nsHttpConnection::HandshakeDone().
Dragana, do you want to take this?

Comment 4

[Intermittent Failures Robot]

1 failures in 3281 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-02-14&endday=2022-02-20&tree=all

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This is nearly perma failing on mozilla-beta for wdspec jobs (see bug 1753888). Do we have a timeline when this gets investigated? Thanks.

Comment 7

[Intermittent Failures Robot]

19 failures in 535 pushes (0.036 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 11
• mozilla-beta: 8

Platform and build breakdown:

• linux1804-64-asan-qr: 19
  • opt: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-02-25&endday=2022-02-25&tree=all

Comment 8

[Intermittent Failures Robot]

70 failures in 2992 pushes (0.023 failures/push) were associated with this bug in the last 7 days.

This is the #6 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-beta: 55
• try: 15

Platform and build breakdown:

• linux1804-64-asan-qr: 70
  • opt: 70

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-02-21&endday=2022-02-27&tree=all

Comment 9

[Dragana Damjanovic [:dragana]]

I am not sure what is happening.
Bug 1382886 added some safeguards against this:
In nsHttpConnection::Close() function:

• mTlsHandshakeComplitionPending is set to false and
• ssl->SetHandshakeCallbackListener(nullptr) is called that resets the handshakeDone listener
  Therefore HandshakeDone will not be called and if a shutdown happens in between HandshakeDone call and execution of the runnable the unable will do nothing because mTlsHandshakeComplitionPending is set to false.

This is all happening on the SockettThread so there are no race issues.

The only thing I could think of is that this does not return the same securityInfo. I will make a patch to try to see if I can mitigate this.
If this is an issue with securityInfo, my work on refactoring nsHttpConnection for proxies will make this easier to reason about.

Comment 10

[Intermittent Failures Robot]

4 failures in 3063 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1
• try: 3

Platform and build breakdown:

• linux1804-64-asan-qr: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 12

[Intermittent Failures Robot]

68 failures in 2837 pushes (0.024 failures/push) were associated with this bug in the last 7 days.

This is the #9 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-beta: 45
• mozilla-release: 17
• try: 6

Platform and build breakdown:

• linux1804-64-asan-qr: 68
  • opt: 68

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-03-07&endday=2022-03-13&tree=all

Comment 14

[Intermittent Failures Robot]

29 failures in 668 pushes (0.043 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• try: 12
• mozilla-beta: 12
• mozilla-release: 5

Platform and build breakdown:

• linux1804-64-asan-qr: 29
  • opt: 29

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-03-15&endday=2022-03-15&tree=all

Comment 15

[Intermittent Failures Robot]

22 failures in 622 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 6
• mozilla-beta: 16

Platform and build breakdown:

• linux1804-64-asan-qr: 22
  • opt: 22

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-03-16&endday=2022-03-16&tree=all

Comment 16

[Intermittent Failures Robot]

34 failures in 694 pushes (0.049 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 13
• mozilla-beta: 15
• mozilla-release: 6

Platform and build breakdown:

• linux1804-64-asan-qr: 34
  • opt: 34

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-03-17&endday=2022-03-17&tree=all

Comment 17

[Narcis Beleuzu [:NarcisB]]

In the last 7 days, there are 68 failures on mozilla-beta.
All the failures are on linux1804-64-asan-qr/opt

Comment 18

[Intermittent Failures Robot]

110 failures in 3304 pushes (0.033 failures/push) were associated with this bug in the last 7 days.

This is the #5 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-beta: 68
• try: 31
• mozilla-release: 11

Platform and build breakdown:

• linux1804-64-asan-qr: 110
  • opt: 110

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-03-14&endday=2022-03-20&tree=all

Comment 19

[Donal Meehan [:dmeehan]]

:dragana has there been any progress on this?
Tomorrow we have the last beta build, before we carry these intermittent failures over to release next week

Comment 20

[Dragana Damjanovic [:dragana]]

Attachment: Make sure not to call HandshakeDone after Close() is calleed

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3eb685b55c41
Make sure not to call HandshakeDone after Close() is calleed r=necko-reviewers,kershaw

Comment 22

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/3eb685b55c41

Comment 23

[Donal Meehan [:dmeehan]]

:dragana could I get a beta approval request for this?

Comment 24

[Dragana Damjanovic [:dragana]]

Comment on attachment 9269207 [details]
Make sure not to call HandshakeDone after Close() is calleed

Beta/Release Uplift Approval Request

• User impact if declined: Currently, this is only happening in tests, but it is possible that it could happen during normal usage.
  We are finishing handshake after a connection was closed, what kind of impact this has is hard to say, the connection is for sure in a wrong state.
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): This adds just a simple check if a connection was closed.
• String changes made/needed:

Comment 25

[Donal Meehan [:dmeehan]]

Comment on attachment 9269207 [details]
Make sure not to call HandshakeDone after Close() is calleed

Approved for beta uplift, available on the beta channel with 99RC1. Thanks

Comment 26

[Donal Meehan [:dmeehan]]

https://hg.mozilla.org/releases/mozilla-beta/rev/d323e7417496

Comment 27

[Intermittent Failures Robot]

3 failures in 2922 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2
• mozilla-beta: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-04-04&endday=2022-04-10&tree=all

Comment 28

[Intermittent Failures Robot]

1 failures in 3289 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-04-25&endday=2022-05-01&tree=all

Comment 29

[Intermittent Failures Robot]

8 failures in 3317 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 5
• mozilla-release: 3

Platform and build breakdown:

• linux1804-64-asan-qr: 8
  • opt: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2022-05-09&endday=2022-05-15&tree=all

Comment 30

[Intermittent Failures Robot]

1 failures in 3863 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1755767&startday=2023-03-27&endday=2023-04-02&tree=all