Closed Bug 1769350 Opened 3 years ago Closed 2 years ago

Intermittent LeakSanitizer | leak at NS_NewRunnableFunction, mozilla::dom::RemoteWorkerChild::ShutdownOnWorker, operator, decltype

Categories

(Core :: DOM: Service Workers, defect)

defect

Tracking

()

RESOLVED WORKSFORME

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])

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


[task 2022-05-14T02:20:08.755Z] 02:20:08     INFO - TEST-START | dom/serviceworkers/test/test_xslt.html
<...>
[task 2022-05-14T02:20:18.032Z] 02:20:18     INFO - GECKO(14105) | Waiting in WillDestroyCurrentMessageLoop for pid 17317
[task 2022-05-14T02:20:19.158Z] 02:20:19     INFO - GECKO(14105) | -----------------------------------------------------
[task 2022-05-14T02:20:19.160Z] 02:20:19     INFO - GECKO(14105) | Suppressions used:
[task 2022-05-14T02:20:19.160Z] 02:20:19     INFO - GECKO(14105) |   count      bytes template
[task 2022-05-14T02:20:19.161Z] 02:20:19     INFO - GECKO(14105) |       9        280 nsComponentManagerImpl
[task 2022-05-14T02:20:19.162Z] 02:20:19     INFO - GECKO(14105) |     633      18115 libfontconfig.so
[task 2022-05-14T02:20:19.162Z] 02:20:19     INFO - GECKO(14105) |       2         15 libglib-2.0.so
[task 2022-05-14T02:20:19.163Z] 02:20:19     INFO - GECKO(14105) |       2        416 mozJSComponentLoader
[task 2022-05-14T02:20:19.163Z] 02:20:19     INFO - GECKO(14105) | -----------------------------------------------------
[task 2022-05-14T02:20:19.260Z] 02:20:19     INFO - TEST-INFO | Main app process: exit 0
[task 2022-05-14T02:20:19.260Z] 02:20:19     INFO - TEST-INFO | LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2022-05-14T02:20:19.261Z] 02:20:19     INFO - TEST-INFO | LeakSanitizer | This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2022-05-14T02:20:19.261Z] 02:20:19    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at NS_NewRunnableFunction, mozilla::dom::RemoteWorkerChild::ShutdownOnWorker, operator, decltype
[task 2022-05-14T02:20:19.261Z] 02:20:19    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::SupportsThreadSafeWeakPtr, mozilla::dom::RemoteWorkerChild::RemoteWorkerChild, mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived
[task 2022-05-14T02:20:19.261Z] 02:20:19    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived, mozilla::ipc::MessageChannel::DispatchAsyncMessage, mozilla::ipc::MessageChannel::DispatchMessage
[task 2022-05-14T02:20:19.262Z] 02:20:19    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at detail::ProxyRelease, ProxyRelease, NS_ProxyRelease, operator
[task 2022-05-14T02:20:19.262Z] 02:20:19     INFO - runtests.py | Application ran for: 0:04:17.031723
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update:

There have been 33 failures* within the last 7 days, all of them on Linux 18.04 x64 WebRender asan opt.

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=399947841&repo=autoland&lineNumber=3945

Artur, as the owner of this component, can you help us assign the bug to someone?
Thank you.

Flags: needinfo?(aiunusov)
Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]
Assignee: nobody → aiunusov
Status: REOPENED → ASSIGNED
Flags: needinfo?(aiunusov)

My guess would be that this is another symptom of the remote worker leak that I think I saw Andrew is working on.

Flags: needinfo?(bugmail)

Yeah, this will be fixed by bug 1775784. At first glance, the leak signature seems to indicate that we're leaking a dispatch being sent to the already-shutdown RemoteWorkerService "Worker Launcher" thread, which I think is actually most of what all the signatures show. (The patch stack does a few things to clean up the lifecycle handling, though.)

Depends on: 1775784
Flags: needinfo?(bugmail)

There have been 39 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
[task 2023-01-22T13:17:24.271Z] 13:17:24     INFO - GECKO(5582) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-22T13:17:24.281Z] 13:17:24     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:24.281Z] 13:17:24     INFO - GECKO(5582) | Suppressions used:
[task 2023-01-22T13:17:24.282Z] 13:17:24     INFO - GECKO(5582) |   count      bytes template
[task 2023-01-22T13:17:24.282Z] 13:17:24     INFO - GECKO(5582) |       2        288 libfontconfig.so
[task 2023-01-22T13:17:24.283Z] 13:17:24     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:25.195Z] 13:17:25     INFO - GECKO(5582) | [Parent 5582, IPC I/O Parent] WARNING: Process 5729 may be hanging at shutdown; will wait for up to 40000ms: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc:180
[task 2023-01-22T13:17:25.249Z] 13:17:25     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:25.249Z] 13:17:25     INFO - GECKO(5582) | Suppressions used:
[task 2023-01-22T13:17:25.250Z] 13:17:25     INFO - GECKO(5582) |   count      bytes template
[task 2023-01-22T13:17:25.251Z] 13:17:25     INFO - GECKO(5582) |      14        448 nsComponentManagerImpl
[task 2023-01-22T13:17:25.252Z] 13:17:25     INFO - GECKO(5582) |       2        288 libfontconfig.so
[task 2023-01-22T13:17:25.252Z] 13:17:25     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:26.200Z] 13:17:26     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:26.200Z] 13:17:26     INFO - GECKO(5582) | Suppressions used:
[task 2023-01-22T13:17:26.201Z] 13:17:26     INFO - GECKO(5582) |   count      bytes template
[task 2023-01-22T13:17:26.201Z] 13:17:26     INFO - GECKO(5582) |       1         32 nsComponentManagerImpl
[task 2023-01-22T13:17:26.202Z] 13:17:26     INFO - GECKO(5582) |     633      18115 libfontconfig.so
[task 2023-01-22T13:17:26.210Z] 13:17:26     INFO - GECKO(5582) |       2      16393 libglib-2.0.so
[task 2023-01-22T13:17:26.210Z] 13:17:26     INFO - GECKO(5582) | -----------------------------------------------------
[task 2023-01-22T13:17:26.282Z] 13:17:26     INFO - TEST-INFO | Main app process: exit 0
[task 2023-01-22T13:17:26.283Z] 13:17:26     INFO - TEST-INFO | LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2023-01-22T13:17:26.283Z] 13:17:26     INFO - TEST-INFO | LeakSanitizer | This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2023-01-22T13:17:26.283Z] 13:17:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at NS_NewRunnableFunction, mozilla::dom::RemoteWorkerChild::ShutdownOnWorker, operator, decltype
[task 2023-01-22T13:17:26.284Z] 13:17:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at detail::ProxyRelease, ProxyRelease, NS_ProxyRelease, operator
[task 2023-01-22T13:17:26.284Z] 13:17:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived, mozilla::ipc::MessageChannel::DispatchAsyncMessage, mozilla::ipc::MessageChannel::DispatchMessage
[task 2023-01-22T13:17:26.285Z] 13:17:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::SupportsThreadSafeWeakPtr, mozilla::dom::RemoteWorkerChild::RemoteWorkerChild, mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived
[task 2023-01-22T13:17:26.286Z] 13:17:26     INFO - runtests.py | Application ran for: 0:02:01.406737

There have been 44 total failures in the last 7 days.
All failures are on the linux1804-64-asan-qr.

Recent failure log.

[task 2023-02-05T20:45:23.402Z] 20:45:23     INFO - GECKO(2929) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-05T20:45:24.576Z] 20:45:24     INFO - GECKO(2929) | -----------------------------------------------------
[task 2023-02-05T20:45:24.578Z] 20:45:24     INFO - GECKO(2929) | Suppressions used:
[task 2023-02-05T20:45:24.578Z] 20:45:24     INFO - GECKO(2929) |   count      bytes template
[task 2023-02-05T20:45:24.580Z] 20:45:24     INFO - GECKO(2929) |      14        448 nsComponentManagerImpl
[task 2023-02-05T20:45:24.580Z] 20:45:24     INFO - GECKO(2929) |       2        288 libfontconfig.so
[task 2023-02-05T20:45:24.582Z] 20:45:24     INFO - GECKO(2929) | -----------------------------------------------------
[task 2023-02-05T20:45:25.972Z] 20:45:25     INFO - GECKO(2929) | -----------------------------------------------------
[task 2023-02-05T20:45:25.973Z] 20:45:25     INFO - GECKO(2929) | Suppressions used:
[task 2023-02-05T20:45:25.974Z] 20:45:25     INFO - GECKO(2929) |   count      bytes template
[task 2023-02-05T20:45:25.975Z] 20:45:25     INFO - GECKO(2929) |       1         32 nsComponentManagerImpl
[task 2023-02-05T20:45:25.975Z] 20:45:25     INFO - GECKO(2929) |     633      18115 libfontconfig.so
[task 2023-02-05T20:45:25.976Z] 20:45:25     INFO - GECKO(2929) |       2      16393 libglib-2.0.so
[task 2023-02-05T20:45:25.976Z] 20:45:25     INFO - GECKO(2929) | -----------------------------------------------------
[task 2023-02-05T20:45:26.058Z] 20:45:26     INFO - TEST-INFO | Main app process: exit 0
[task 2023-02-05T20:45:26.058Z] 20:45:26     INFO - TEST-INFO | LeakSanitizer | To show the addresses of leaked objects add report_objects=1 to LSAN_OPTIONS
[task 2023-02-05T20:45:26.059Z] 20:45:26     INFO - TEST-INFO | LeakSanitizer | This can be done in testing/mozbase/mozrunner/mozrunner/utils.py
[task 2023-02-05T20:45:26.059Z] 20:45:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived, mozilla::ipc::MessageChannel::DispatchAsyncMessage, mozilla::ipc::MessageChannel::DispatchMessage
[task 2023-02-05T20:45:26.061Z] 20:45:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at NS_NewRunnableFunction, mozilla::dom::RemoteWorkerChild::ShutdownOnWorker, operator, decltype
[task 2023-02-05T20:45:26.061Z] 20:45:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at detail::ProxyRelease, ProxyRelease, NS_ProxyRelease, operator
[task 2023-02-05T20:45:26.062Z] 20:45:26    ERROR - TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::SupportsThreadSafeWeakPtr, mozilla::dom::RemoteWorkerChild::RemoteWorkerChild, mozilla::ipc::BackgroundChildImpl::AllocPRemoteWorkerChild, mozilla::ipc::PBackgroundChild::OnMessageReceived
[task 2023-02-05T20:45:26.062Z] 20:45:26     INFO - runtests.py | Application ran for: 0:02:46.789803
Whiteboard: [stockwell disable-recommended]

There have been 43 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended]

There have been 118 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-asan-qr
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended]

The fix from bug 1775784 reached the nightlies with this merge , and orange factor shows that the occurrences from the 15th-17th of March are on try/release branches(e.g. beta).

*note: occurrences on autoland are earlier than the time of the patch landing.

Looks like it was fixed on integration.

Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended]

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

Looks like it was fixed on integration.

Fix seems to be confirmed by the data.

Status: ASSIGNED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.