Closed Bug 1782181 Opened 2 years ago Closed 2 years ago

Intermittent LeakSanitizer | leak at NS_NewPipe2, mozilla::RemoteLazyInputStream::EnsureAsyncRemoteStream, operator, std::_Function_handler

Categories

(Core :: Storage: IndexedDB, defect, P5)

defect

Tracking

()

RESOLVED FIXED
105 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- fixed
firefox103 --- unaffected
firefox104 --- fixed
firefox105 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Attachments

(2 files, 1 obsolete file)

Filed by: bszekely [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=385764077&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/c-jJisELSOKU2WV5OGRZZg/runs/0/artifacts/public/logs/live_backing.log


[task 2022-07-29T06:29:32.723Z] 06:29:32     INFO - TEST-START | /IndexedDB/writer-starvation.htm
[task 2022-07-29T06:29:32.731Z] 06:29:32     INFO - Closing window f09edc37-5adf-41b8-abe2-50f965aaa9f3
[task 2022-07-29T06:29:33.786Z] 06:29:33     INFO - .
[task 2022-07-29T06:29:33.787Z] 06:29:33     INFO - TEST-OK | /IndexedDB/writer-starvation.htm | took 1066ms
[task 2022-07-29T06:29:33.789Z] 06:29:33     INFO - Restarting browser for new test group
[task 2022-07-29T06:29:33.790Z] 06:29:33     INFO - PID 1330 | 1659076173789	Marionette	INFO	Stopped listening on port 39522
[task 2022-07-29T06:29:34.185Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=619002fc8380 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3595
[task 2022-07-29T06:29:34.185Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=619002fc8380 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1799
[task 2022-07-29T06:29:34.189Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=6190027c7780 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3595
[task 2022-07-29T06:29:34.191Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=6190027c7780 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1799
[task 2022-07-29T06:29:34.194Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=61900250b780 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3595
[task 2022-07-29T06:29:34.196Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=61900250b780 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1799
[task 2022-07-29T06:29:34.219Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=619002fc8380 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1834
[task 2022-07-29T06:29:34.222Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=619002fc8380 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3697
[task 2022-07-29T06:29:34.226Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=6190027c7780 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1834
[task 2022-07-29T06:29:34.229Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=6190027c7780 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3697
[task 2022-07-29T06:29:34.237Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=61900250b780 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1834
[task 2022-07-29T06:29:34.239Z] 06:29:34     INFO - PID 1330 | [Parent 1330, Main Thread] WARNING: ContentParent: id=61900250b780 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3697
[task 2022-07-29T06:29:34.515Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.519Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.520Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.520Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.520Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.593Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.594Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.594Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.594Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.594Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.602Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.602Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.602Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.602Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.602Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.605Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.605Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.605Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.605Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.605Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.701Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.701Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.701Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.701Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.701Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.702Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.702Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.702Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.702Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.702Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.729Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.729Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.729Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.730Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.730Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.901Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:34.902Z] 06:29:34     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:34.903Z] 06:29:34     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:34.904Z] 06:29:34     INFO - PID 1330 |       2        288 libfontconfig.so
[task 2022-07-29T06:29:34.905Z] 06:29:34     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:37.278Z] 06:29:37     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:37.281Z] 06:29:37     INFO - PID 1330 | Suppressions used:
[task 2022-07-29T06:29:37.281Z] 06:29:37     INFO - PID 1330 |   count      bytes template
[task 2022-07-29T06:29:37.281Z] 06:29:37     INFO - PID 1330 |       1         32 nsComponentManagerImpl
[task 2022-07-29T06:29:37.282Z] 06:29:37     INFO - PID 1330 |     633      18115 libfontconfig.so
[task 2022-07-29T06:29:37.282Z] 06:29:37     INFO - PID 1330 |       2      16393 libglib-2.0.so
[task 2022-07-29T06:29:37.282Z] 06:29:37     INFO - PID 1330 |       1         32 XPCWrappedNativeJSOps
[task 2022-07-29T06:29:37.282Z] 06:29:37     INFO - PID 1330 | -----------------------------------------------------
[task 2022-07-29T06:29:37.381Z] 06:29:37     INFO - Browser exited with return code 0
[task 2022-07-29T06:29:37.382Z] 06:29:37     INFO - ERROR | LeakSanitizer | SUMMARY: AddressSanitizer: 5000 byte(s) leaked in 8 allocation(s).
[task 2022-07-29T06:29:37.385Z] 06:29:37     INFO - LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2022-07-29T06:29:37.385Z] 06:29:37     INFO - This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2022-07-29T06:29:37.385Z] 06:29:37     INFO - Allowed depth was 4
[task 2022-07-29T06:29:37.386Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at NS_NewPipe2, mozilla::RemoteLazyInputStream::EnsureAsyncRemoteStream, operator, std::_Function_handler
[task 2022-07-29T06:29:37.386Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at PR_NewMonitor, ReentrantMonitor, nsPipe::nsPipe, NS_NewPipe2
[task 2022-07-29T06:29:37.386Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::RemoteLazyInputStreamThread::GetOrCreate, mozilla::BindChildActor, mozilla::RemoteLazyInputStream::IPCRead, IPC::ParamTraits
[task 2022-07-29T06:29:37.386Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at already_AddRefed, NS_NewCancelableRunnableFunction, CallbackHolder::CallbackHolder, nsPipeInputStream::AsyncWait
[task 2022-07-29T06:29:37.386Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at nsSegmentedBuffer::AppendNewSegment, nsPipe::GetWriteSegment, nsPipeOutputStream::WriteSegments, nsStreamCopierOB::DoCopy
[task 2022-07-29T06:29:37.387Z] 06:29:37     INFO - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at Malloc, nsTArray_base, nsTArray_Impl, AppendElement
[task 2022-07-29T06:29:37.388Z] 06:29:37     INFO - Closing logging queue
[task 2022-07-29T06:29:37.389Z] 06:29:37     INFO - queue closed
[task 2022-07-29T06:29:37.430Z] 06:29:37     INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2022-07-29T06:29:37.437Z] 06:29:37     INFO - LSan enabled.
[task 2022-07-29T06:29:37.438Z] 06:29:37     INFO - INFO | runtests.py | ASan running in default memory configuration
[task 2022-07-29T06:29:37.438Z] 06:29:37     INFO - UBSan enabled.
[task 2022-07-29T06:29:37.439Z] 06:29:37     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpnbhn8m8u
[task 2022-07-29T06:29:37.448Z] 06:29:37     INFO - PID 1336 | 1659075305965	Marionette	INFO	Marionette enabled
[task 2022-07-29T06:29:37.449Z] 06:29:37     INFO - PID 1336 | 1659075305974	Marionette	INFO	Listening on port 44445
[task 2022-07-29T06:29:37.450Z] 06:29:37     INFO - PID 1336 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpeibx5vup/search.json.mozlz4", (void 0)))
[task 2022-07-29T06:29:37.450Z] 06:29:37     INFO - PID 1336 | 1659075695996	addons.xpi	ERROR	System addon update list error Error: Failed downloading XML, status: 0, reason: error
[task 2022-07-29T06:29:37.451Z] 06:29:37     INFO - Starting runner
[task 2022-07-29T06:29:38.572Z] 06:29:38     INFO - TEST-START | /content-security-policy/media-src/media-src-7_1_2.sub.html
See Also: → 1782349

(In reply to Natalia Csoregi [:nataliaCs] from comment #1)

Nika, could this and the leaks within this bug, Bug 1782176 and Bug 1782123 be from Bug 1780054 ?
These bugs contain the same leaks but in a different order throughout the log.

It's unfortunately definitely possible that this bug could be from bug 1780054, but unfortunately I'm not super confident how it could be related given the set of objects which were apparently leaked. Perhaps there were other leaked objects but they were suppressed or something like that...

Given the current set of leaked objects here, it looks vaguely like the notify dispatch from a nsPipe is waiting to eventually be delivered to the RemoteLazyInputStreamThread. It's unclear if the notify was dispatched and leaked due to the thread being dead, or if it was sticking around and waiting to be dispatched at all.

The main way the change could impact things is if there is a buggy nsIAsyncInputStream which doesn't pass the correct stream to OnInputStreamReady when it is notified, but I'm pretty sure RemoteLazyInputStream and nsPipe aren't broken in that way so it seems unlikely to cause this specific leak. The source stream being copied from could theoretically be a nsMultiplexInputStream but if that's the case, it shouldn't implement nsIAsyncInputStream, so the changes won't have any impact.

When scanning for buggy async streams, I only found nsPreloadedStream https://searchfox.org/mozilla-central/rev/12c2e38fdcc0bcbb9e689560c41ab68f9254413a/netwerk/base/nsPreloadedStream.cpp#111, which will report the wrong stream to the listener. This appears to never be used in a nsMultiplexInputStream, and is likely also never stored in a RemoteLazyInputStream (though it also appears to be a legacy stream which could easily be replaced by a nsMultiplexInputStream, so that might be worth doing to simplify things). I expect it is not the cause of this bug.

I also noticed a potential bug in nsMultiplexInputStream which could lead to AsyncWait callbacks not properly being cancelled, which is slightly more likely to be the cause of this bug, though it's still somewhat unlikely.

Assignee: nobody → nika
Flags: needinfo?(nika)
Regressed by: 1780054

(Nika, I assume all this means also that "Storage: IndexedDB" is most likely not the right component for this bug?)

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

(In reply to Jens Stutte [:jstutte] from comment #4)

(Nika, I assume all this means also that "Storage: IndexedDB" is most likely not the right component for this bug?)

There's a chance that it is, but it's not super clear yet. The issue seems more common when idb is involved, just like the old bug, but it could just be that it exercises stream code the most.

See Also: → 1782955

Previously nsMultiplexInputStream would not call AsyncWait again when the
callback was cleared, meaning that the underlying wait wouldn't actually be
cancelled. This patch changes the behaviour to more consistently forward the
cancelling call to the underlying stream.

There are still some cases where the call will not be cancelled if a read or
other event caused the stream cursor to advance before canceling, however those
should generally be uncommon.

When nsMultiplexInputStream calls AsyncWait from within
OnInputStreamReady, it is possible for those calls to fail. In that case, we
will fail to notify AsyncWait listeners, which could lead to leaks or stream
hangs. This patch changes the error handling in this situation to instead fire
a pending stream callback after an error when re-dispatching AsyncWait.

Depends on D153628

This is an API requirement of the nsIAsyncInputStream interface, and is
depended on by some streams such as nsMultiplexInputStream.

This is unlikely to have any substantial impact as nsPreloadedStream is only
used in very limited situations, but it may be used in more places in the
future.

Depends on D153629

See Also: → 1783057

Going to land parts 1 and 2 of this bug, and hope that it fixes the issue. My best bet for the cause right now is the one fixed by part 2.

Comment on attachment 9288337 [details]
Bug 1782181 - Part 3: Pass the correct stream to OnInputStreamReady in nsPreloadedStream, r=#necko-reviewers

Revision D153630 was moved to bug 1783057. Setting attachment 9288337 [details] to obsolete.

Attachment #9288337 - Attachment is obsolete: true
Pushed by nlayzell@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/40fd3f4eae4c Part 1: Support canceling AsyncWait in nsMultiplexInputStream, r=asuth https://hg.mozilla.org/integration/autoland/rev/2a06e0ff3633 Part 2: Notify nsMultiplexInputStream callbacks if AsyncWait fails, r=asuth
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 105 Branch

:nika can you please nominate this one for beta as well since it needs to go with bug 1780054?

Flags: needinfo?(nika)

Comment on attachment 9288336 [details]
Bug 1782181 - Part 2: Notify nsMultiplexInputStream callbacks if AsyncWait fails, r=asuth!

Beta/Release Uplift Approval Request

  • User impact if declined: Memory leaks
  • Is this code covered by automated tests?: No
  • Has the fix been verified in Nightly?: Yes
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: Bug 1780054
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Fairly minor improvements to the way that AsyncWait is handled in nsMultiplexInputStream which may help fix memory leaks caused by bug 1780054.
  • String changes made/needed: None
  • Is Android affected?: Yes

ESR Uplift Approval Request

  • If this is not a sec:{high,crit} bug, please state case for ESR consideration: Ride-along for bug 1780054
  • User impact if declined: Memory leaks
  • Fix Landed on Version: 105
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Fairly minor improvements to the way that AsyncWait is handled in nsMultiplexInputStream which may help fix memory leaks caused by bug 1780054.
Flags: needinfo?(nika)
Attachment #9288336 - Flags: approval-mozilla-esr102?
Attachment #9288336 - Flags: approval-mozilla-beta?
Attachment #9288335 - Flags: approval-mozilla-esr102? approval-mozilla-beta?

Comment on attachment 9288335 [details]
Bug 1782181 - Part 1: Support canceling AsyncWait in nsMultiplexInputStream, r=asuth!

Approved for 104.0b6

Attachment #9288335 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9288336 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Comment on attachment 9288335 [details]
Bug 1782181 - Part 1: Support canceling AsyncWait in nsMultiplexInputStream, r=asuth!

Approved for 102.2esr.

Attachment #9288335 - Flags: approval-mozilla-esr102? → approval-mozilla-esr102+
Attachment #9288336 - Flags: approval-mozilla-esr102? → approval-mozilla-esr102+

This is still happening on esr102: https://treeherder.mozilla.org/logviewer?job_id=392776072&repo=mozilla-esr102 , if this is the same issue.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: