1795687 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_silent_restart_windowless_flag_on_mac_os | application crashed [@ nsDebugImpl::Abort(char const*, int)]

Status: RESOLVED FIXED

(Toolkit :: Preferences, defect, P3)

Description

[Treeherder Bug Filer]

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

---

[task 2022-10-17T12:30:25.429Z] 12:30:25     INFO -  JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 149: Error: Wait is complete, cannot add further promises.
[task 2022-10-17T12:30:25.429Z] 12:30:25     INFO -  *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: region-update-timer
[task 2022-10-17T12:30:25.465Z] 12:30:25     INFO -  DEBUG: Completed blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-10-17T12:30:25.471Z] 12:30:25     INFO -  DEBUG: Completed blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-10-17T12:30:25.471Z] 12:30:25     INFO -  DEBUG: Completed blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-10-17T12:30:27.852Z] 12:30:27     INFO -  DEBUG: Completed blocker TerminatoryTelemetry: Waiting to submit telemetry for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2022-10-17T12:30:35.421Z] 12:30:35     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Sqlite.jsm shutdown blocker","state":{"description":"Waiting for connections to close","state":[{"name":"content-prefs.sqlite#0: waiting for shutdown","state":{"identifier":"content-prefs.sqlite#0","isCloseRequested":false,"hasDbConn":true,"initiatedTransaction":false,"pendingStatements":0,"statementCounter":0},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":335,"stack":["resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1408","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1195","resource://gre/modules/AsyncShutdown.jsm:observe:574"]}]},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":210,"stack":["resource://gre/modules/Sqlite.sys.mjs:null:210","resource://gre/modules/XPCOMUtils.sys.mjs:get:56","resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1408","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1195","resource://gre/modules/AsyncShutdown.jsm:observe:574"]}] Barrier: profile-before-change
[task 2022-10-17T12:30:35.482Z] 12:30:35     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"content-prefs.sqlite#0: waiting for shutdown","state":{"identifier":"content-prefs.sqlite#0","isCloseRequested":false,"hasDbConn":true,"initiatedTransaction":false,"pendingStatements":0,"statementCounter":0},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":335,"stack":["resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1408","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1195","resource://gre/modules/AsyncShutdown.jsm:observe:574"]}] Barrier: Sqlite.jsm: wait until all connections are closed
[task 2022-10-17T12:31:24.767Z] 12:31:24     INFO -  DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2022-10-17T12:31:24.768Z] 12:31:24     INFO -  DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2022-10-17T12:31:24.825Z] 12:31:24     INFO -  DEBUG: Completed blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2022-10-17T12:31:24.858Z] 12:31:24     INFO -  *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2022-10-17T12:31:26.496Z] 12:31:26     INFO -  FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"Sqlite.jsm shutdown blocker","state":{"description":"Waiting for connections to close","state":[{"name":"content-prefs.sqlite#0: waiting for shutdown","state":{"identifier":"content-prefs.sqlite#0","isCloseRequested":false,"hasDbConn":true,"initiatedTransaction":false,"pendingStatements":0,"statementCounter":0},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":335,"stack":["resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1408","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1195","resource://gre/modules/AsyncShutdown.jsm:observe:574"]}]},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":210,"stack":["resource://gre/modules/Sqlite.sys.mjs:null:210","resource://gre/modules/XPCOMUtils.sys.mjs:get:56","resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1408","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1195","resource://gre/modules/AsyncShutdown.jsm:observe:574"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2022-10-17T12:31:26.496Z] 12:31:26     INFO -  [Parent 1623, Main Thread] ###!!! ABORT: file resource://gre/modules/Sqlite.sys.mjs:210
[task 2022-10-17T12:31:26.496Z] 12:31:26     INFO -  #01: NS_DebugBreak[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x1b3aba]
[task 2022-10-17T12:31:26.497Z] 12:31:26     INFO -  #02: nsDebugImpl::Abort(char const*, int)[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x1b3bc8]
[task 2022-10-17T12:31:26.497Z] 12:31:26     INFO -  #03: NS_InvokeByIndex[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x32879e]
[task 2022-10-17T12:31:26.497Z] 12:31:26     INFO -  Hit MOZ_CRASH([Parent 1623, Main Thread] ###!!! ABORT: file resource://gre/modules/Sqlite.sys.mjs:210) at /builds/worker/checkouts/gecko/xpcom/base/nsDebugImpl.cpp:513
[task 2022-10-17T12:31:26.498Z] 12:31:26     INFO -  #01: NS_DebugBreak[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x1b3ad8]
[task 2022-10-17T12:31:26.498Z] 12:31:26     INFO -  #02: nsDebugImpl::Abort(char const*, int)[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x1b3bc8]
[task 2022-10-17T12:31:26.499Z] 12:31:26     INFO -  #03: NS_InvokeByIndex[/opt/worker/tasks/task_166600925739885/build/application/Firefox NightlyDebug.app/Contents/MacOS/XUL +0x32879e]
[task 2022-10-17T12:33:35.415Z] 12:33:35     INFO - mozcrash Copy/paste: /opt/worker/tasks/task_166600925739885/fetches/minidump-stackwalk/minidump-stackwalk --symbols-url=https://symbols.mozilla.org/ --human /var/folders/p4/p4h39g312nn2mrt_j3hjwm1h000014/T/tmps157d0ui.mozrunner/minidumps/FF3B1A7A-A659-4C13-B445-C0A6FDE0DF2D.dmp /opt/worker/tasks/task_166600925739885/build/symbols
[task 2022-10-17T12:33:43.027Z] 12:33:43     INFO - mozcrash Saved minidump as /opt/worker/tasks/task_166600925739885/build/blobber_upload_dir/FF3B1A7A-A659-4C13-B445-C0A6FDE0DF2D.dmp
[task 2022-10-17T12:33:43.027Z] 12:33:43     INFO - mozcrash Saved app info as /opt/worker/tasks/task_166600925739885/build/blobber_upload_dir/FF3B1A7A-A659-4C13-B445-C0A6FDE0DF2D.extra
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - PROCESS-CRASH | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_silent_restart_windowless_flag_on_mac_os | application crashed [@ nsDebugImpl::Abort(char const*, int)]
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Mozilla crash reason: [Parent 1623, Main Thread] ###!!! ABORT: file resource://gre/modules/Sqlite.sys.mjs:210
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Crash dump filename: /var/folders/p4/p4h39g312nn2mrt_j3hjwm1h000014/T/tmps157d0ui.mozrunner/minidumps/FF3B1A7A-A659-4C13-B445-C0A6FDE0DF2D.dmp
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Operating system: Mac OS X
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO -                   10.15.7 19H524
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - CPU: amd64
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO -      family 6 model 158 stepping 10
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO -      12 CPUs
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - 
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Crash reason:  EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Crash address: 0x0
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Mac Crash Info:
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - 
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Process uptime: 62 seconds
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - 
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO - Thread 0 MainThread (crashed)
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO -  0  XUL!NS_DebugBreak [nsDebugImpl.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 0 + 0x34]
[task 2022-10-17T12:33:43.397Z] 12:33:43     INFO -      rax = 0x0000000103d4ba40    rdx = 0x0000000000000000
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rcx = 0x000000010e9b1e6c    rbx = 0x00007fff95e71620
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rsi = 0x00000000000120a8    rdi = 0x00007fff95e70ca8
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rbp = 0x00007ffeebf82fb0    rsp = 0x00007ffeebf82880
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -       r8 = 0x00000000000130a8     r9 = 0x0000000000000000
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      r10 = 0x00007fff95e70cc8    r11 = 0x00007fff95e70cc0
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      r12 = 0x00007ffeebf82948    r13 = 0x00007ffeebf82c80
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      r14 = 0x00007ffeebf82900    r15 = 0x00007ffeebf82970
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rip = 0x000000010eb9fae2
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -     Found by: given as instruction pointer in context
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -  1  XUL!nsDebugImpl::Abort(char const*, int) [nsDebugImpl.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 129 + 0xd]
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf82fc0
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      rsp = 0x00007ffeebf82fc0    r12 = 0x0000000122ba2940
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      r13 = 0x0000000000000009    r14 = 0x00007ffeebf83068
[task 2022-10-17T12:33:43.398Z] 12:33:43     INFO -      r15 = 0x0000000000000001    rip = 0x000000010eb9fbc8
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -  2  XUL!NS_InvokeByIndex + 0x8d
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf82ff0
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      rsp = 0x00007ffeebf82fd0    r12 = 0x0000000122ba2940
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      r13 = 0x0000000000000009    r14 = 0x00007ffeebf83068
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      r15 = 0x0000000000000001    rip = 0x000000010ed1479e
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -  3  XUL!CallMethodHelper::Invoke() [XPCWrappedNative.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 1626]
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -  4  XUL!CallMethodHelper::Call() [XPCWrappedNative.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 1179 + 0x17]
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf83040
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83000    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      r13 = 0x0000000000000002    r14 = 0x00007ffeebf83068
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      r15 = 0x0000000000000001    rip = 0x000000010f7d5f00
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -  5  XUL!XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 1125 + 0x7]
[task 2022-10-17T12:33:43.399Z] 12:33:43     INFO -      rbx = 0x00007ffeebf83220    rbp = 0x00007ffeebf831b0
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83050    r12 = 0x000000011966fff8
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      r13 = 0x000000010e02a100    r14 = 0x00007ffeebf83058
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      r15 = 0x00007ffeebf83068    rip = 0x000000010f7d5ab9
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -  6  XUL!XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 965 + 0x7]
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      rbx = 0x00007ffeebf83220    rbp = 0x00007ffeebf832f0
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      rsp = 0x00007ffeebf831c0    r12 = 0x0000207740649a38
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      r13 = 0x000000010e02a100    r14 = 0x000000010e097180
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      r15 = 0x000000011966fb00    rip = 0x000000010f7d794d
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -  7  XUL!CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 459 + 0x5]
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      rbx = 0x0000035435e08160    rbp = 0x00007ffeebf83350
[task 2022-10-17T12:33:43.400Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83300    r12 = 0x000000010e02a100
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83530    r14 = 0x000000010f7d7590
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      r15 = 0x0000000000000000    rip = 0x0000000114f234b1
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -  8  XUL!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 547 + 0x10]
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      rbx = 0x000000010f7d7590    rbp = 0x00007ffeebf83410
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83360    r12 = 0x0000000119a12bc0
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      r13 = 0xfff8800000000000    r14 = 0x000000010e02a100
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      r15 = 0xffff800000000000    rip = 0x0000000114f22d34
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -  9  XUL!js::CallFromStack(JSContext*, JS::CallArgs const&, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 619]
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO - 10  XUL!Interpret(JSContext*, js::RunState&) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 3375 + 0x4]
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      rbx = 0x0000035435e08160    rbp = 0x00007ffeebf83890
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83420    r12 = 0xfff9800000000000
[task 2022-10-17T12:33:43.401Z] 12:33:43     INFO -      r13 = 0x0000000119ce52a8    r14 = 0x0000000000000074
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r15 = 0x0000000119a07ac0    rip = 0x0000000114f1924f
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO - 11  XUL!js::RunScript(JSContext*, js::RunState&) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 431 + 0xa]
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rbx = 0x0000000119ce52a8    rbp = 0x00007ffeebf838f0
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rsp = 0x00007ffeebf838a0    r12 = 0x000000010e02a100
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r13 = 0x0000000119ce5201    r14 = 0x00007ffeebf83950
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r15 = 0x0000000000000000    rip = 0x0000000114f0fd49
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO - 12  XUL!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 579 + 0x7]
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rbx = 0x000026569280bac0    rbp = 0x00007ffeebf839b0
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83900    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r13 = 0xfff8800000000000    r14 = 0x000000010e02a100
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r15 = 0xfff8800000000000    rip = 0x0000000114f22c68
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO - 13  XUL!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 646 + 0xc]
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf83a00
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      rsp = 0x00007ffeebf839c0    r12 = 0x00007ffeebf83b90
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83b70    r14 = 0x00007ffeebf83a20
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -      r15 = 0x000000010e02a100    rip = 0x0000000114f24053
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.402Z] 12:33:43     INFO - 14  XUL!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) [Interpreter.h:6f112c0942b01de66a02e232be737a1cac7251a9 : 116 + 0x13]
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rbx = 0x000000010e02a100    rbp = 0x00007ffeebf83a90
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83a10    r12 = 0x00007ffeebf83b90
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83b70    r14 = 0x00007ffeebf83b58
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r15 = 0x00000001187f3350    rip = 0x0000000114f88363
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO - 15  XUL!PromiseReactionJob(JSContext*, unsigned int, JS::Value*) [Promise.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 2240 + 0xa]
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rbx = 0x000026569280bac0    rbp = 0x00007ffeebf83bf0
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83aa0    r12 = 0x00007ffeebf83b58
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83b30    r14 = 0x00007ffeebf83b90
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r15 = 0x00007ffeebf83ad0    rip = 0x00000001151cd363
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO - 16  XUL!CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 459 + 0x5]
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rbx = 0x00002656928e0328    rbp = 0x00007ffeebf83c50
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83c00    r12 = 0x000000010e02a100
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83da0    r14 = 0x00000001151cc3e0
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r15 = 0x0000000000000000    rip = 0x0000000114f234b1
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO - 17  XUL!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 547 + 0x10]
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rbx = 0x00000001151cc3e0    rbp = 0x00007ffeebf83d10
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83c60    r12 = 0x0000000119a12bc0
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r13 = 0xfff8800000000000    r14 = 0x000000010e02a100
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r15 = 0xffff800000000000    rip = 0x0000000114f22d34
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO - 18  XUL!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 646 + 0xc]
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf83d60
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83d20    r12 = 0x00007ffeebf83f00
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83f10    r14 = 0x00007ffeebf83da0
[task 2022-10-17T12:33:43.403Z] 12:33:43     INFO -      r15 = 0x000000010e02a100    rip = 0x0000000114f24053
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 19  XUL!JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [CallAndConstruct.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 117 + 0x7]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf83ee0
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83d70    r12 = 0x00007ffeebf83f00
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83f10    r14 = 0x0000000000000000
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r15 = 0x000000010e02a100    rip = 0x000000011501bceb
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 20  XUL!mozilla::dom::PromiseJobCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::ErrorResult&) [PromiseBinding.cpp: : 83 + 0xe]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rbx = 0x00000001298de0c0    rbp = 0x00007ffeebf83f70
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83ef0    r12 = 0x00007ffeebf83f20
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r13 = 0x00007ffeebf83f10    r14 = 0x00007ffeebf84128
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r15 = 0x00000001187f3350    rip = 0x000000011092fdb4
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 21  XUL!mozilla::dom::PromiseJobCallback::Call(mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) [PromiseBinding.h: : 198 + 0x14]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rbx = 0x0000000118b49d16    rbp = 0x00007ffeebf84180
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rsp = 0x00007ffeebf83f80    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r13 = 0x00007ffeebf841a0    r14 = 0x0000000000000000
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r15 = 0x00000001298de0c0    rip = 0x000000010ebc955a
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 22  XUL!mozilla::dom::PromiseJobCallback::Call(char const*) [PromiseBinding.h: : 211]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 23  XUL!mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&) [CycleCollectedJSContext.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 213 + 0x35]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rbx = 0x000000012a76dd00    rbp = 0x00007ffeebf841f0
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rsp = 0x00007ffeebf84190    r12 = 0x00000001298de0c0
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r13 = 0x00007ffeebf841a0    r14 = 0x00007ffeebf8421c
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r15 = 0x0000000000000000    rip = 0x000000010ebc8796
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 24  XUL!mozilla::CycleCollectedJSContext::PerformMicroTaskCheckPoint(bool) [CycleCollectedJSContext.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 676 + 0x8]
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rbx = 0x0000000122bab8f0    rbp = 0x00007ffeebf84290
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      rsp = 0x00007ffeebf84200    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r13 = 0x0000000122ba5000    r14 = 0x0000000122bab920
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -      r15 = 0x0000000000000001    rip = 0x000000010ebb56cc
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.404Z] 12:33:43     INFO - 25  XUL!mozilla::CycleCollectedJSContext::AfterProcessTask(unsigned int) [CycleCollectedJSContext.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 463 + 0x6]
[task 2022-10-17T12:33:43.405Z] 12:33:43     INFO -      rbx = 0x0000000122ba5000    rbp = 0x00007ffeebf842b0
[task 2022-10-17T12:33:43.405Z] 12:33:43     INFO -      rsp = 0x00007ffeebf842a0    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.405Z] 12:33:43     INFO -      r13 = 0x000000010bef7900    r14 = 0x0000000000000001
[task 2022-10-17T12:33:43.405Z] 12:33:43     INFO -      r15 = 0x0000000122ba5000    rip = 0x000000010ebb61ba
[task 2022-10-17T12:33:43.405Z] 12:33:43     INFO -     Found by: call frame info
<...>
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO - 50  XUL!nsXREDirProvider::DoShutdown() [nsXREDirProvider.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 1007 + 0xb]
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      rbx = 0xaaaaaaaaaaaaaaaa    rbp = 0x00007ffeebf85bc0
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      rsp = 0x00007ffeebf85b90    r12 = 0x0000000103fc61c0
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      r13 = 0x0000000000000000    r14 = 0x00007ffeebf85d30
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      r15 = 0x00007ffeebf85cf0    rip = 0x0000000114df553d
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO - 51  XUL!ScopedXPCOMStartup::~ScopedXPCOMStartup() [nsAppRunner.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 2063 + 0xe]
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      rbx = 0xaaaaaaaaaaaaaaaa    rbp = 0x00007ffeebf85c50
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      rsp = 0x00007ffeebf85bd0    r12 = 0x0000000103fc61c0
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000103f11430
[task 2022-10-17T12:33:43.410Z] 12:33:43     INFO -      r15 = 0x00007ffeebf85cf0    rip = 0x0000000114dd7a96
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 52  XUL!ScopedXPCOMStartup::~ScopedXPCOMStartup() [nsAppRunner.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 2050]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 53  XUL!mozilla::DefaultDelete<ScopedXPCOMStartup>::operator()(ScopedXPCOMStartup*) const [UniquePtr.h:6f112c0942b01de66a02e232be737a1cac7251a9 : 459]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 54  XUL!mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::reset(ScopedXPCOMStartup*) [UniquePtr.h:6f112c0942b01de66a02e232be737a1cac7251a9 : 301]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 55  XUL!mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::operator=(std::nullptr_t) [UniquePtr.h:6f112c0942b01de66a02e232be737a1cac7251a9 : 271]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 56  XUL!XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 5937 + 0x18]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rbx = 0x0000000103f11430    rbp = 0x00007ffeebf85ce0
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rsp = 0x00007ffeebf85c60    r12 = 0x0000000103fc61c0
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000000780001
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r15 = 0x00007ffeebf85cf0    rip = 0x0000000114de5a55
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 57  XUL!XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 5972 + 0xf]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rbx = 0x0000000000000002    rbp = 0x00007ffeebf85e20
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rsp = 0x00007ffeebf85cf0    r12 = 0x00007ffeebf85cf0
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r13 = 0x0000000000000002    r14 = 0x00007ffeebf85e50
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r15 = 0x00007ffeebf862a0    rip = 0x0000000114de6295
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 58  firefox!do_main(int, char**, char**) [nsBrowserApp.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 226]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: inlining
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO - 59  firefox!main [nsBrowserApp.cpp:6f112c0942b01de66a02e232be737a1cac7251a9 : 428 + 0x108]
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rbx = 0x00007ffeebf865e9    rbp = 0x00007ffeebf86280
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      rsp = 0x00007ffeebf85e30    r12 = 0x0000000103c7b343
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r13 = 0x0000000000000002    r14 = 0x00007ffeebf862a0
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -      r15 = 0x0000000000000066    rip = 0x0000000103c78f4f
[task 2022-10-17T12:33:43.411Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO - 60  libdyld.dylib!start + 0x0
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO -      rbx = 0x0000000000000000    rbp = 0x00007ffeebf86290
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO -      rsp = 0x00007ffeebf86290    r12 = 0x0000000000000000
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000000000000
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO -      r15 = 0x0000000000000000    rip = 0x00007fff6f5c4cc9
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO -     Found by: call frame info
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO - 
[task 2022-10-17T12:33:43.412Z] 12:33:43     INFO - Thread 1 IPC I/O Parent

Comment 1

[Natalia Csoregi [:nataliaCs]]

First occurrence so far: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=os%2Cx%2C10.15%2Cwebrender%2Cdebug%2Ctest-macosx1015-64-qr%2Fdebug-marionette-swr%2Cmn-swr&tochange=6f112c0942b01de66a02e232be737a1cac7251a9&fromchange=3549afc9ae9392bd97f10982e0c3962d72d6a854&selectedTaskRun=VbTOu6CXQCix41gMIRAIdQ.0

Comment 2

[Intermittent Failures Robot]

20 failures in 2793 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• mozilla-central: 3
• try: 1

Platform and build breakdown:

• macosx1015-64-qr: 20
  • debug: 20

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

Comment 3

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

Since the crash volume is low (less than 5 per week), the severity is downgraded to S3. Feel free to change it back if you think the bug is still critical.

For more information, please visit auto_nag documentation.

Comment 4

[Intermittent Failures Robot]

18 failures in 3743 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 15
• mozilla-central: 3

Platform and build breakdown:

• macosx1015-64-qr: 18
  • debug: 18

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

Comment 5

[Intermittent Failures Robot]

24 failures in 3626 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 14
• mozilla-central: 7
• try: 3

Platform and build breakdown:

• macosx1015-64-qr: 24
  • debug: 24

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

Comment 6

[Intermittent Failures Robot]

22 failures in 3445 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 19
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 22
  • debug: 22

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

Comment 7

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

Nika, there are 40 failures so far within the last week. Would you mind having a look at this crash? Thanks!

Comment 8

[Andrew McCreight [:mccr8]]

It looks like this is a shutdown hang in Sqlite.sys.mjs, not an XPCOM issue per se.

Comment 9

[Intermittent Failures Robot]

44 failures in 3589 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #29 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-central: 12
• autoland: 31
• try: 1

Platform and build breakdown:

• macosx1015-64-qr: 44
  • debug: 44

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

Comment 10

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

The exact failure is:

[task 2022-11-20T22:11:53.865Z] 22:11:53     INFO -  FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"Sqlite.sys.mjs shutdown blocker","state":{"description":"Waiting for connections to close","state":[{"name":"content-prefs.sqlite#0: waiting for shutdown","state":{"identifier":"content-prefs.sqlite#0","isCloseRequested":false,"hasDbConn":true,"initiatedTransaction":false,"pendingStatements":0,"statementCounter":0},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":335,"stack":["resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1409","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1196","resource://gre/modules/AsyncShutdown.jsm:observe:560"]}]},"filename":"resource://gre/modules/Sqlite.sys.mjs","lineNumber":210,"stack":["resource://gre/modules/Sqlite.sys.mjs:null:210","resource://gre/modules/XPCOMUtils.sys.mjs:get:54","resource://gre/modules/Sqlite.sys.mjs:ConnectionData:335","resource://gre/modules/Sqlite.sys.mjs:OpenedConnection:1409","resource://gre/modules/Sqlite.sys.mjs:openConnection/</<:1196","resource://gre/modules/AsyncShutdown.jsm:observe:560"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2022-11-20T22:11:53.865Z] 22:11:53     INFO -  [Parent 2077, Main Thread] ###!!! ABORT: file resource://gre/modules/Sqlite.sys.mjs:210

Mak, could you please have a look why we are crashing here? Thanks

Comment 11

[Marco Bonardo [:mak]]

This is content-prefs.sqlite not resolving its shutdown blocker in 1 minute.
I think it's this blocker https://searchfox.org/mozilla-central/rev/83b86005c6913c2062419efb8aabdf2e683aa47f/toolkit/components/contentprefs/ContentPrefService2.jsm#1187, that means conn.close() is not resolving nor rejecting.
That's strange, especially "isCloseRequested":false, when the blocker itself is invoking close().

Though a few lines above I see

[task 2022-11-20T22:10:52.829Z] 22:10:52     INFO -  DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2022-11-20T22:10:52.831Z] 22:10:52     INFO -  JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 135: Error: Wait is complete, cannot add further promises.

That means ContentPrefs2 is indeed starting up and opening a connection during shutdown, and because we are over the maximum limit to add a blocker, the addBlocker call fails, and close() is not invoked, so Sqlite is correctly expecting for an open connection to be closed, but close() will never be invoked

The solution here is to change ContentPrefs to NOT try to start during shutdown... That may be done in many ways, it could check if shutdown started though nsIAppStartup.idl, or try/catch addBlocker and if it fails just close the connection, or try to addBlocker before the connection open and if it fails don't even try to start it (it could still close the connection in the blocker, it should just null check conn).

Apparently content-prefs is managed in Toolkit/Preferences, so moving it there.

Comment 12

[Marco Bonardo [:mak]]

We could also evaluate annotating somewhere in the AsyncShutdown metadata if a blocker failed to be added, I'll file a bug for that.

Comment 13

[Intermittent Failures Robot]

19 failures in 3888 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• try: 1
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 19
  • debug: 19

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

Comment 14

[:Gijs (he/him)]

Attachment: Bug 1795687 - disallow opening content prefs in shutdown, r?mak

This prevents the issue described in the bug in two ways:

• avoid attempting to start a connection in shutdown
• call connection.close() even if we fail to add a shutdown blocker.

It does both because if we did only the first, we would still have a potential race where
when _getConnection is called, we would not be in shutdown, but by the time
we try to close the connection, we could be. If we only did the second, we'd keep retrying
which is also bad.

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6

Platform and build breakdown:

• macosx1015-64-qr: 6
  • debug: 6

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

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4

Platform and build breakdown:

• macosx1015-64-qr: 4
  • debug: 4

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

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/27da6226c2a0
disallow opening content prefs in shutdown, r=mak

Comment 18

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/27da6226c2a0

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

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