Intermittent Assertion failed: (pInode->nLock==0), function unixFileLock, file /builds/worker/checkouts/gecko/third_party/sqlite3/src/sqlite3.c, line 35075.
Categories
(Toolkit :: Storage, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox-esr68 | --- | unaffected |
firefox-esr78 | --- | unaffected |
firefox78 | --- | unaffected |
firefox79 | --- | unaffected |
firefox80 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: mak)
References
(Regression)
Details
(Keywords: assertion, intermittent-failure, regression)
Attachments
(1 file)
Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=309609375&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BCgqin65SFap5NnwQgliKQ/runs/0/artifacts/public/logs/live_backing.log
INFO - TEST-PASS | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_rtl.js | Browser toolbox started
[task 2020-07-13T17:31:20.720Z] 17:31:20 INFO - -
[task 2020-07-13T17:31:20.720Z] 17:31:20 INFO - TEST-PASS | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_rtl.js | Has session state -
[task 2020-07-13T17:31:20.720Z] 17:31:20 INFO - Buffered messages logged at 17:25:24
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://gre/modules/subprocess/subprocess_common.jsm" line: 125}]
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Buffered messages logged at 17:26:50
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Buffered messages logged at 17:28:20
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Buffered messages logged at 17:29:50
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Buffered messages logged at 17:30:21
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Console message: [JavaScript Error: "Unknown Collection "main/messaging-experiments"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 159}]
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:159:5
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:468:13
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - async*get/this._importingPromise<@resource://services-settings/RemoteSettingsClient.jsm:397:24
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - async*get@resource://services-settings/RemoteSettingsClient.jsm:399:11
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - async*updateRecipes@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:142:49
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - setTimer/<@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:191:18
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - TM_notify/</<@resource://gre/modules/UpdateTimerManager.jsm:259:36
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - ChromeUtils::IdleDispatch handler*TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:257:25
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:292:7
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO -
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - Buffered messages finished
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - TEST-UNEXPECTED-FAIL | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_rtl.js | Test timed out -
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - TEST-PASS | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_rtl.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - GECKO(1200) | MEMORY STAT | vsize 7705MB | residentFast 403MB | heapAllocated 176MB
[task 2020-07-13T17:31:20.721Z] 17:31:20 INFO - TEST-OK | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_rtl.js | took 360376ms
[task 2020-07-13T17:31:20.752Z] 17:31:20 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x11680ec00 == 1 [pid = 1205] [id = {af94fa52-f3bf-d641-bc2b-67db512fe2b5}]
[task 2020-07-13T17:31:20.752Z] 17:31:20 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x11d7157d0) [pid = 1205] [serial = 11] [outer = 0x0]
[task 2020-07-13T17:31:20.753Z] 17:31:20 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x116816c00) [pid = 1205] [serial = 12] [outer = 0x11d7157d0]
[task 2020-07-13T17:31:20.812Z] 17:31:20 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x11d792c00) [pid = 1205] [serial = 13] [outer = 0x11d7157d0]
[task 2020-07-13T17:31:20.819Z] 17:31:20 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x11d795c00) [pid = 1205] [serial = 14] [outer = 0x11d7157d0]
[task 2020-07-13T17:31:20.819Z] 17:31:20 INFO - checking window state
[task 2020-07-13T17:31:20.935Z] 17:31:20 INFO - GECKO(1200) | [Parent 1200: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (0x128c5d800) [pid = 1200] [serial = 11] [outer = 0x10a1830e0]
[task 2020-07-13T17:31:20.937Z] 17:31:20 INFO - GECKO(1200) | [Parent 1200: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 12 (0x128c5d000) [pid = 1200] [serial = 12] [outer = 0x10a1830e0]
[task 2020-07-13T17:31:21.070Z] 17:31:21 INFO - GECKO(1200) | [Child 1203: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x11ac82400 == 0 [pid = 1203] [id = {86a32509-ab78-4a41-b0ed-a965095da352}] [url = about:blank]
[task 2020-07-13T17:31:21.352Z] 17:31:21 INFO - GECKO(1200) | [Child 1203: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x12287f400) [pid = 1203] [serial = 13] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:21.352Z] 17:31:21 INFO - GECKO(1200) | [Child 1203: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x122bef650) [pid = 1203] [serial = 11] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:21.870Z] 17:31:21 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x11d792c00) [pid = 1205] [serial = 13] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:21.870Z] 17:31:21 INFO - GECKO(1200) | [Child 1205: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x116816c00) [pid = 1205] [serial = 12] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:22.018Z] 17:31:22 INFO - GECKO(1200) | [Child 1204: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x12449ac00) [pid = 1204] [serial = 3] [outer = 0x0] [url = about:newtab]
[task 2020-07-13T17:31:22.019Z] 17:31:22 INFO - GECKO(1200) | [Child 1204: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x1244187d0) [pid = 1204] [serial = 1] [outer = 0x0] [url = about:newtab]
[task 2020-07-13T17:31:22.019Z] 17:31:22 INFO - GECKO(1200) | [Child 1204: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x1242a2800 == 0 [pid = 1204] [id = {3123dcc0-143a-954d-8a2f-ef5ffb95032f}] [url = about:newtab]
[task 2020-07-13T17:31:25.327Z] 17:31:25 INFO - GECKO(1200) | Completed ShutdownLeaks collections in process 1202
[task 2020-07-13T17:31:25.403Z] 17:31:25 INFO - GECKO(1200) | Completed ShutdownLeaks collections in process 1203
[task 2020-07-13T17:31:25.515Z] 17:31:25 INFO - GECKO(1200) | Completed ShutdownLeaks collections in process 1204
[task 2020-07-13T17:31:25.684Z] 17:31:25 INFO - GECKO(1200) | Completed ShutdownLeaks collections in process 1205
[task 2020-07-13T17:31:26.474Z] 17:31:26 INFO - GECKO(1200) | [Parent 1200: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x124f75800) [pid = 1200] [serial = 8] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:27.369Z] 17:31:27 INFO - GECKO(1200) | [1295, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-07-13T17:31:27.369Z] 17:31:27 INFO - GECKO(1200) | [1295, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-07-13T17:31:27.369Z] 17:31:27 INFO - GECKO(1200) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/tw/k7c56_tx5n36br3ybh37k1_0000017/T/tmpmdmTUj.mozrunner/runtests_leaks_tab_pid1295.log
[task 2020-07-13T17:31:27.369Z] 17:31:27 INFO - GECKO(1200) | [1295, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-07-13T17:31:27.369Z] 17:31:27 INFO - GECKO(1200) | [1295, MainThread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-07-13T17:31:27.370Z] 17:31:27 INFO - GECKO(1200) | [1295, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 245
[task 2020-07-13T17:31:30.692Z] 17:31:30 INFO - GECKO(1200) | [Parent 1200: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x128c5d800) [pid = 1200] [serial = 11] [outer = 0x0] [url = about:blank]
[task 2020-07-13T17:31:31.547Z] 17:31:31 INFO - GECKO(1200) | Completed ShutdownLeaks collections in process 1200
[task 2020-07-13T17:31:31.553Z] 17:31:31 INFO - TEST-START | Shutdown
[task 2020-07-13T17:31:31.553Z] 17:31:31 INFO - Browser Chrome Test Summary
[task 2020-07-13T17:31:31.554Z] 17:31:31 INFO - Passed: 31
[task 2020-07-13T17:31:31.554Z] 17:31:31 INFO - Failed: 1
[task 2020-07-13T17:31:31.554Z] 17:31:31 INFO - Todo: 0
[task 2020-07-13T17:31:31.554Z] 17:31:31 INFO - Mode: e10s
[task 2020-07-13T17:31:31.554Z] 17:31:31 INFO - *** End BrowserChrome Test Results ***
Updated•4 years ago
|
Assignee | ||
Comment 1•4 years ago
|
||
All the failures are on MacOS, the code is hit only for unix-excl, that is the same vfs we had before on MacOS, nothing should have changed there.
nLock is the number of outstanding file locks, the code checks if exclusive is active and there's no exclusive lock, then proceeds to check there's no lock but finds more than zero. The documentation clarifies in exclusive mode the only active lock should be the exclusive system lock and should be taken at the first locking attempt.
I wonder if it's a case where in the past we'd have failed to acquire a lock, now instead we continue and a later attempt to open the same file finds a lock when before we'd not have one.
Andrew, any idea on your side or why this may be happening for indexedDB (I suspect it's because these are open/closed more often than other dbs)?
Comment 2•4 years ago
|
||
Set release status flags based on info from the regressing bug 1650201
Comment 3•4 years ago
|
||
(In reply to Marco Bonardo [:mak] from comment #1)
I wonder if it's a case where in the past we'd have failed to acquire a lock, now instead we continue and a later attempt to open the same file finds a lock when before we'd not have one.
Andrew, any idea on your side or why this may be happening for indexedDB (I suspect it's because these are open/closed more often than other dbs)?
Your theory seems very right, apologies for not thinking of the IDB hacks. There are possibly 2 things going on:
- Bug 1541548 : IDB transferring ownership of a database across threads via a close and an open because of bug 1121282. I think this isn't as bad as it used to be; we used to dispatch the runnable that would do the open before calling close. Now I think close should complete before the open runnable is dispatched. So the problem might be:
- Bug 1541550 : IDB's book-keeping allows an open of a closing database to start before the closing competes.
As I understand the motivating problem, we're worried about external apps interfering with the cookie and/or places database. I don't think that's a problem for IDB at this time. The most expedient solution might be to not do the fallback path on file URI's (is it still only Quota Manager clients that use that) and then we can improve the mozStorage thread ownership invariant (which we already want to reduce the number of threads in use) and related IDB bugs.
Assignee | ||
Comment 4•4 years ago
|
||
SGTM, let's try the disabling for file uris.
Assignee | ||
Comment 5•4 years ago
|
||
Pushed by mak77@bonardo.net: https://hg.mozilla.org/integration/autoland/rev/b464e08444fb Disable mozStorage exclusive lock fallback for file URIs. r=asuth
Comment 7•4 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•4 years ago
|
Description
•