1721503 - Intermittent SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 in mutexLock

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | dom/indexedDB/test/test_filehandle_workers.html
[task 2021-07-20T22:32:34.629Z] 22:32:34     INFO - GECKO(2094) | MEMORY STAT | vsize 130550499MB | residentFast 559MB
[task 2021-07-20T22:32:34.666Z] 22:32:34     INFO - TEST-OK | dom/indexedDB/test/test_filehandle_workers.html | took 468ms
[task 2021-07-20T22:32:34.726Z] 22:32:34     INFO - GECKO(2094) | ==================
[task 2021-07-20T22:32:34.726Z] 22:32:34     INFO - GECKO(2094) | WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=2160)
[task 2021-07-20T22:32:34.727Z] 22:32:34     INFO - GECKO(2094) |   Cycle in lock order graph: M777287891146785080 (0x000000000000) => M775880447543851648 (0x000000000000) => M777287891146785080
[task 2021-07-20T22:32:34.728Z] 22:32:34     INFO - GECKO(2094) |   Mutex M775880447543851648 acquired here while holding mutex M777287891146785080 in main thread:
[task 2021-07-20T22:32:34.729Z] 22:32:34     INFO - GECKO(2094) |     #0 pthread_mutex_lock /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/../sanitizer_common/sanitizer_common_interceptors.inc:4233:3 (firefox+0x755a6)
[task 2021-07-20T22:32:34.729Z] 22:32:34     INFO - GECKO(2094) |     #1 mutexLock /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 (firefox+0x12c76b)
[task 2021-07-20T22:32:34.729Z] 22:32:34     INFO - GECKO(2094) |     #2 mozilla::detail::MutexImpl::lock() /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:118:43 (firefox+0x12c76b)
[task 2021-07-20T22:32:34.729Z] 22:32:34     INFO - GECKO(2094) |     #3 Lock /builds/worker/workspace/obj-build/dist/include/mozilla/Mutex.h:63:23 (libxul.so+0x3b6d6ae)
<...>
INFO - GECKO(2094) |     #37 XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:742:34 (libxul.so+0x6b30799)
[task 2021-07-20T22:32:34.782Z] 22:32:34     INFO - GECKO(2094) |     #38 mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:67:12 (libxul.so+0x6b387b2)
[task 2021-07-20T22:32:34.783Z] 22:32:34     INFO - GECKO(2094) |     #39 content_process_main /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28 (firefox+0xc9fd1)
[task 2021-07-20T22:32:34.783Z] 22:32:34     INFO - GECKO(2094) |     #40 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327:18 (firefox+0xc9fd1)
[task 2021-07-20T22:32:34.784Z] 22:32:34     INFO - GECKO(2094) | SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) /builds/worker/checkouts/gecko/mozglue/misc/Mutex_posix.cpp:96:3 in mutexLock
[task 2021-07-20T22:32:34.784Z] 22:32:34     INFO - GECKO(2094) | ==================
[task 2021-07-20T22:32:34.964Z] 22:32:34    ERROR - GECKO(2094) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2021-07-20T22:32:35.311Z] 22:32:35     INFO - GECKO(2094) | 1626820355309	Marionette	TRACE	Received observer notification quit-application
[task 2021-07-20T22:32:35.313Z] 22:32:35     INFO - GECKO(2094) | 1626820355310	Marionette	INFO	Stopped listening on port 2828
[task 2021-07-20T22:32:35.315Z] 22:32:35     INFO - GECKO(2094) | 1626820355312	Marionette	DEBUG	Marionette stopped listening
[task 2021-07-20T22:32:35.520Z] 22:32:35     INFO - GECKO(2094) | JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-07-20T22:32:35.523Z] 22:32:35     INFO - GECKO(2094) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-20T22:32:35.524Z] 22:32:35     INFO - GECKO(2094) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-20T22:32:37.115Z] 22:32:37     INFO - GECKO(2094) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-20T22:32:43.748Z] 22:32:43     INFO - TEST-INFO | Main app process: exit 0
[task 2021-07-20T22:32:43.749Z] 22:32:43     INFO - runtests.py | Application ran for: 0:01:41.392147
[task 2021-07-20T22:32:43.749Z] 22:32:43     INFO - zombiecheck | Reading PID log: /tmp/tmprshe3td_pidlog
INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpcmivny0g.mozrunner
[task 2021-07-20T22:32:43.762Z] 22:32:43     INFO - runtests.py | Application pid: 2310
[task 2021-07-20T22:32:43.762Z] 22:32:43     INFO - TEST-INFO | started process GECKO(2310)
[task 2021-07-20T22:32:47.032Z] 22:32:47     INFO - GECKO(2310) | 1626820367030	Marionette	INFO	Marionette enabled
[task 2021-07-20T22:32:47.148Z] 22:32:47     INFO - GECKO(2310) | 1626820367147	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2021-07-20T22:32:47.150Z] 22:32:47     INFO - GECKO(2310) | 1626820367149	RemoteAgent	DEBUG	CDP enabled
[task 2021-07-20T22:32:52.908Z] 22:32:52     INFO - GECKO(2310) | 1626820372907	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-07-20T22:32:52.909Z] 22:32:52     INFO - GECKO(2310) | 1626820372908	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-07-20T22:32:53.047Z] 22:32:53     INFO - GECKO(2310) | 1626820373045	Marionette	TRACE	All scripts recorded.
[task 2021-07-20T22:32:53.056Z] 22:32:53     INFO - GECKO(2310) | 1626820373055	Marionette	INFO	Listening on port 2828
[task 2021-07-20T22:32:53.058Z] 22:32:53     INFO - GECKO(2310) | 1626820373057	Marionette	DEBUG	Marionette is listening
[task 2021-07-20T22:32:53.154Z] 22:32:53     INFO - GECKO(2310) | 1626820373153	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:40286
[task 2021-07-20T22:32:53.178Z] 22:32:53     INFO - GECKO(2310) | 1626820373177	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:40288
[task 2021-07-20T22:32:53.181Z] 22:32:53     INFO - GECKO(2310) | 1626820373180	Marionette	DEBUG	Closed connection 0
[task 2021-07-20T22:32:53.220Z] 22:32:53     INFO - GECKO(2310) | 1626820373219	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-07-20T22:32:53.296Z] 22:32:53     INFO - GECKO(2310) | 1626820373294	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"4da2bb31-27c6-45a5-89ac-7045f40736e8","capabilities":{"browserName":"firefox","browserVersion":"92.0a ... .mozrunner","moz:shutdownTimeout":360000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-07-20T22:32:53.366Z] 22:32:53     INFO - GECKO(2310) | 1626820373365	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmp9ntwp0_g.zip","temporary":false}]
[task 2021-07-20T22:32:53.502Z] 22:32:53     INFO - GECKO(2310) | 1626820373499	Marionette	TRACE	[37] MarionetteEvents actor created for window id 6442450946
[task 2021-07-20T22:32:53.580Z] 22:32:53     INFO - GECKO(2310) | 1626820373579	Marionette	TRACE	[38] MarionetteEvents actor created for window id 6442450947
[task 2021-07-20T22:32:54.036Z] 22:32:54     INFO - GECKO(2310) | 1626820374035	Marionette	TRACE	[39] MarionetteEvents actor created for window id 6442450948
[task 2021-07-20T22:32:54.386Z] 22:32:54     INFO - GECKO(2310) | 1626820374386	Marionette	DEBUG	1 <- [1,2,null,{"value":"[e-mail]"}]
[task 2021-07-20T22:32:54.564Z] 22:32:54     INFO - GECKO(2310) | 1626820374564	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpjzxbypfe.zip","temporary":false}]
[task 2021-07-20T22:32:54.792Z] 22:32:54     INFO - GECKO(2310) | 1626820374789	Marionette	TRACE	[42] MarionetteEvents actor created for window id 21
[task 2021-07-20T22:32:54.991Z] 22:32:54     INFO - GECKO(2310) | 1626820374990	Marionette	DEBUG	1 <- [1,3,null,{"value":"[e-mail]"}]
[task 2021-07-20T22:32:54.996Z] 22:32:54     INFO - GECKO(2310) | 1626820374995	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-07-20T22:32:54.998Z] 22:32:54     INFO - GECKO(2310) | 1626820374997	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2021-07-20T22:32:55.003Z] 22:32:55     INFO - GECKO(2310) | 1626820375002	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-07-20T22:32:55.005Z] 22:32:55     INFO - GECKO(2310) | 1626820375004	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2021-07-20T22:32:55.011Z] 22:32:55     INFO - GECKO(2310) | 1626820375010	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... ry=%2Ftmp&cleanupCrashes=true"}],"newSandbox":true,"sandbox":"default","line":1934,"filename":"tests/mochitest/runtests.py"}]
[task 2021-07-20T22:32:55.031Z] 22:32:55     INFO - GECKO(2310) | 1626820375030	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2021-07-20T22:32:55.081Z] 22:32:55     INFO - GECKO(2310) | 1626820375078	Marionette	TRACE	[32] MarionetteEvents actor created for window id 2147483649
[task 2021-07-20T22:32:55.089Z] 22:32:55     INFO - GECKO(2310) | 1626820375088	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2021-07-20T22:32:55.437Z] 22:32:55     INFO - GECKO(2310) | 1626820375436	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-07-20T22:32:55.439Z] 22:32:55     INFO - GECKO(2310) | 1626820375438	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2021-07-20T22:32:55.502Z] 22:32:55     INFO - GECKO(2310) | 1626820375501	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-07-20T22:32:55.515Z] 22:32:55     INFO - GECKO(2310) | 1626820375513	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2021-07-20T22:32:55.530Z] 22:32:55     INFO - GECKO(2310) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
INFO - runtests.py | Waiting for browser...
[task 2021-07-20T22:32:55.533Z] 22:32:55     INFO - GECKO(2310) | 1626820375532	Marionette	DEBUG	Closed connection 1
[task 2021-07-20T22:32:56.843Z] 22:32:56     INFO - GECKO(2310) | 1626820376842	Marionette	TRACE	[42] MarionetteEvents actor created for window id 4294967297
[task 2021-07-20T22:32:56.922Z] 22:32:56     INFO - GECKO(2310) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-07-20T22:32:57.672Z] 22:32:57     INFO - SimpleTest START
[task 2021-07-20T22:32:57.704Z] 22:32:57     INFO - TEST-START | dom/indexedDB/test/test_storage_manager_estimate.html

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721503&startday=2021-07-19&endday=2021-07-25&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 3

[Norisz Fay [:noriszfay]]

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

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Bug 1721503: Avoid possible lock-order inversion in shutting down RemoteLazyInputStreamChild r=#dom-storage-reviewers

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b113fb1e3622
Avoid possible lock-order inversion in shutting down RemoteLazyInputStreamChild r=dom-storage-reviewers,edenchuang

Comment 6

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/b113fb1e3622

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721503&startday=2021-12-20&endday=2021-12-26&tree=all