1707963 - Intermittent Storage connection not closed: permissions.sqliteHit MOZ_CRASH() at /builds/worker/checkouts/gecko/storage/mozStorageService.cpp:712

Status: RESOLVED FIXED

(Core :: Permission Manager, defect, P3)

Description

[Tyson Smith [:tsmith]]

This was found while attempting to reproduce a different issue with m-c 20210426-15253a3168d2.

Hit MOZ_CRASH() at src/storage/mozStorageService.cpp:712

#0 0x426e1de8ebab in mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*) src/storage/mozStorageService.cpp:712:9
#1 0x426e1ba52e10 in nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) src/xpcom/ds/nsObserverList.cpp:70:19
#2 0x426e1ba6b864 in nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) src/xpcom/ds/nsObserverService.cpp:288:19
#3 0x426e1b955e1a in mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) src/xpcom/base/AppShutdown.cpp:332:21
#4 0x426e1b956147 in mozilla::AppShutdown::AdvanceShutdownPhase(mozilla::ShutdownPhase, char16_t const*, nsCOMPtr<nsISupports> const&) src/xpcom/base/AppShutdown.cpp:351:3
#5 0x426e1bc3636e in mozilla::ShutdownXPCOM(nsIServiceManager*) src/xpcom/build/XPCOMInit.cpp:622:5
#6 0x426e1bc360f4 in NS_ShutdownXPCOM src/xpcom/build/XPCOMInit.cpp:565:10
#7 0x426e269c8d39 in ScopedXPCOMStartup::~ScopedXPCOMStartup() src/toolkit/xre/nsAppRunner.cpp:1668:5
#8 0x426e269dfd3a in mozilla::DefaultDelete<ScopedXPCOMStartup>::operator()(ScopedXPCOMStartup*) const src/objdir-ff-debug/dist/include/mozilla/UniquePtr.h:463:5
#9 0x426e269dfcbc in mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::reset(ScopedXPCOMStartup*) src/objdir-ff-debug/dist/include/mozilla/UniquePtr.h:305:7
#10 0x426e269dd9c6 in mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::operator=(std::nullptr_t) src/objdir-ff-debug/dist/include/mozilla/UniquePtr.h:275:5
#11 0x426e269d7a75 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) src/toolkit/xre/nsAppRunner.cpp:5556:16
#12 0x426e269d7d18 in XRE_main(int, char**, mozilla::BootstrapConfig const&) src/toolkit/xre/nsAppRunner.cpp:5598:21
#13 0x426e269f2526 in mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) src/toolkit/xre/Bootstrap.cpp:45:12
#14 0x558b828e1eb6 in do_main(int, char**, char**) src/browser/app/nsBrowserApp.cpp:220:22
#15 0x558b828e184c in main src/browser/app/nsBrowserApp.cpp:347:16
#16 0x5cdd641b2bf6 in __libc_start_main /build/glibc-S9d2JN/glibc-2.27/csu/../csu/libc-start.c:310
#17 0x558b828bf739 in _start (src/objdir-ff-debug/dist/bin/firefox+0xcd739)

Comment 1

[Tyson Smith [:tsmith]]

A Pernosco session is available here: https://pernos.co/debug/ba9Pt0oA4iKDJfurbqup9w/index.html

Comment 2

[Marco Bonardo [:mak]]

"Storage connection not closed: permissions.sqlite"

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-qr: 2
  • debug: 2

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4

Platform and build breakdown:

• windows10-64-qr: 3
  • debug: 3
• windows10-32-qr: 1
  • debug: 1

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-32-qr: 1
  • debug: 1
• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-07-26&endday=2021-08-01&tree=all

Comment 7

[Intermittent Failures Robot]

25 failures in 2829 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 18
• mozilla-central: 6
• mozilla-esr91: 1

Platform and build breakdown:

• windows10-64-2004-qr: 24
  • debug: 24
• windows10-32-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-08-02&endday=2021-08-08&tree=all

Comment 8

[Intermittent Failures Robot]

25 failures in 3025 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 17
• mozilla-central: 8

Platform and build breakdown:

• windows10-64-2004-qr: 24
  • debug: 24
• windows10-32-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-08-09&endday=2021-08-15&tree=all

Comment 9

[Intermittent Failures Robot]

12 failures in 2899 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 10
  • debug: 10
• windows10-32-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-08-16&endday=2021-08-22&tree=all

Comment 10

[Intermittent Failures Robot]

25 failures in 2580 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 18
• mozilla-central: 5
• mozilla-esr91: 1
• comm-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 22
  • debug: 22
• windows10-32-qr: 2
  • debug: 2
• windows10-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-08-23&endday=2021-08-29&tree=all

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 17
• mozilla-central: 3

Platform and build breakdown:

• windows10-64-2004-qr: 18
  • debug: 18
• windows10-32-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-08-30&endday=2021-09-05&tree=all

Comment 13

[Intermittent Failures Robot]

13 failures in 3266 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4
• autoland: 9

Platform and build breakdown:

• windows10-64-2004-qr: 9
  • debug: 9
• windows10-32-2004-qr: 4
  • debug: 4

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

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 12
• mozilla-central: 10
• try: 1

Platform and build breakdown:

• windows10-32-2004-qr: 14
  • debug: 14
• windows10-64-2004-qr: 9
  • debug: 9

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

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Jens, this is hitting a lot since we migrated Win10 testing over to version 2004. Can you help find someone to investigate?

Comment 16

[Jens Stutte [:jstutte]]

Looking at this after a while I noticed in Service::Observe:

    SpinEventLoopUntil([&]() -> bool {
      // We must wait until all the closing connections are closed.
      nsTArray<RefPtr<Connection>> connections;
      getConnections(connections);
      for (auto& conn : connections) {
        if (conn->isClosing()) {   <<<<< this is not the inverse condition of isClosed() !!!!
          return false;
        }
      }
      return true;
    });

#ifdef DEBUG
    nsTArray<RefPtr<Connection>> connections;
    getConnections(connections);
    for (uint32_t i = 0, n = connections.Length(); i < n; i++) {
      if (!connections[i]->isClosed()) {
        // getFilename is only the leaf name for the database file,
        // so it shouldn't contain privacy-sensitive information.
        CrashReporter::AnnotateCrashReport(
            CrashReporter::Annotation::StorageConnectionNotClosed,
            connections[i]->getFilename());
        printf_stderr("Storage connection not closed: %s",
                      connections[i]->getFilename().get());
        MOZ_CRASH();
      }
    }
#endif

that we spin the event loop with different conditions:

bool Connection::isClosing() {
  MutexAutoLock lockedScope(sharedAsyncExecutionMutex);
  return mAsyncExecutionThreadShuttingDown && !mConnectionClosed;
}

bool Connection::isClosed() {
  MutexAutoLock lockedScope(sharedAsyncExecutionMutex);
  return mConnectionClosed;
}

If (for whatever reason) we reach here with a connection that does not have mAsyncExecutionThreadShuttingDown set, we would break (or not even enter) the SpinEventLoopUntil but then potentially crash.

Comment 17

[Jens Stutte [:jstutte]]

I am not sure though if this indicates a problem with the SpinEventLoopUntil or just with the crash condition. Andrew, you reviewed some of the patches there?

Comment 18

[Marco Bonardo [:mak]]

The scope of that code is to detect cases where we shutdown with a non-closed connection. If we reach that point with mAsyncExecutionThreadShuttingDown = false, it means there wasn't an attempt to close the connection. That would normally indicate a bug in how the component handles shutdown, maybe something failed in the component shutdown process and it didn't reach the point where it explicitly closes the connection.
IIRC (some time has passed) isClosing is when the consumer asked to close, but the closing is not complete yet, so we spin to wait for closing to be complete.

Comment 19

[Jens Stutte [:jstutte]]

(In reply to Marco Bonardo [:mak] from comment #18)

The scope of that code is to detect cases where we shutdown with a non-closed connection. If we reach that point with mAsyncExecutionThreadShuttingDown = false, it means there wasn't an attempt to close the connection. That would normally indicate a bug in how the component handles shutdown, maybe something failed in the component shutdown process and it didn't reach the point where it explicitly closes the connection.
IIRC (some time has passed) isClosing is when the consumer asked to close, but the closing is not complete yet, so we spin to wait for closing to be complete.

OK, and otherwise (if it was the same condition) we would never had exited the SpinEventLoopUntil such that the assert could never be reached. Thanks for the clarification and sorry for the noise.

So we are still just looking for a "permissions.sqlite" connection that was never attempted to close.

Comment 20

[Marco Bonardo [:mak]]

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

So we are still just looking for a "permissions.sqlite" connection that was never attempted to close.

Modulo mozStorage bugs that of course I cannot exclude, otherwise we'd have the best code in the world, I think so!

Comment 21

[Jens Stutte [:jstutte]]

Attachment: notebookt.PNG

I looked at the old pernosco trace and from there it seems, that the "PermissionManager::CloseDB" message is dispatched correctly during "profile-before-change" but then the permission thread seems to sleep until we reached "xpcom-shutdown-threads" on the main thread, which makes us crash (and then the permission thread unblocks and runs the "PermissionManager::CloseDB" event).

Is there anything that can delay the dispatch of a message to another thread on our side or should we assume, that the Windows task scheduler just forgot to give some slice to the permission thread for a while?

Comment 22

[Andrew Sutherland [:asuth] (he/him)]

The failures happening that Ryan linked to are all xpcshell test failures so it seems like the problem is that even though the permission manager seems to have a shutdown blocker, it does expect to sometimes see profile-before-change without the blocker added, and in that case it just YOLOs the close and hopes it happens fast enough.

It seems like maybe the permission manager needs to fail to initialize if it's too late to add a shutdown blocker, creating an invariant that the shutdown blocker is always added or the service won't start up.

Aside: It's worth calling out that one of the few downsides to pernosco runs is that rr doesn't allow for any parallelism so all execution needs to be limited to a single thread/core which can result in some weird schedulings even if not enabling the chaos modes.

Comment 23

[Jens Stutte [:jstutte]]

Thanks! Looking again at the pernosco session, the case there is similar but not the same. We arrive way before any shutdown phase started inside PermissionManager::Init but when we try to add the shutdown blocker, the nsIAsyncShutdownClient interface is not available and thus we do not add any blocker, resulting in a similar situation as you described.

My take would be: If we cannot guarantee a proper shutdown, probably we should not even arrive at InitDB ? Or there might be process types / test harnesses that break ?

Comment 24

[Marco Bonardo [:mak]]

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

when we try to add the shutdown blocker, the nsIAsyncShutdownClient interface is not available

This doesn't sound good, it may also be a bug in async shutdown. What "not available" means here, is do_GetService failing, or failing to return the barrier? Any idea where are we at that time, early startup, late shutdown?

As Andrew said, it seems the classical case where we try to init a service too late, but you said we arrive way before any shutdown phase, that excludes that.
Another case I saw frequently, was services closing a connection and then reopening it during shutdown, because some API was invoked late and all the methods were trying to open the connection if it was not available. In that case we just made the methods fail after shutdown was initiated.
I'm sort-of throwing out ideas, not knowing well how this code evolved, hopefully we can understand the problem in a less empyrical way, but maybe ideas give some hint for debugging.

Comment 25

[Jens Stutte [:jstutte]]

(In reply to Marco Bonardo [:mak] from comment #24)

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

when we try to add the shutdown blocker, the nsIAsyncShutdownClient interface is not available

This doesn't sound good, it may also be a bug in async shutdown. What "not available" means here, is do_GetService failing, or failing to return the barrier?

It is do_GetService inside GetShutdownPhase that returns nullptr such that we do not even try to add the blocker. (BTW, GetShutdownPhase sounds like a bad name for a function that just returns the nsIAsyncShutdownClient interface.)

Any idea where are we at that time, early startup, late shutdown?

We are in early startup, apparently. I did not check if we make any attempt before to start the AsyncShutdown service.

As Andrew said, it seems the classical case where we try to init a service too late, but you said we arrive way before any shutdown phase, that excludes that.

At least in that specific pernosco session this is not the case (but it might not be representative for the cases in the wild, of course).

Another case I saw frequently, was services closing a connection and then reopening it during shutdown, because some API was invoked late and all the methods were trying to open the connection if it was not available. In that case we just made the methods fail after shutdown was initiated.

This is a common pattern and yes, we should probably proof-read the initialization code if it is safe against such a late re-surrection. AppShutdown::IsInOrBeyond can help here now.

I'm sort-of throwing out ideas, not knowing well how this code evolved, hopefully we can understand the problem in a less empyrical way, but maybe ideas give some hint for debugging.

Appreciated, and it is basically what I do, too ;-). I am far from understanding that code in detail.

Comment 26

[Jens Stutte [:jstutte]]

OK, I made a fun test. I added:

    nsCOMPtr<nsIAsyncShutdownClient> asc = GetShutdownPhase();
    MOZ_ASSERT(asc);   <<<< added
    if (asc) {

in PermissionManager::Init and Firefox just crashes on startup this way. I assume, this means the AsyncShutdownBlocker for "PermissionManager: Flushing data" was never active and we just were lucky that most of the times the SpinEventLoopUntil in mozStorage Service::Observe did the trick for us later in shutdown than expected.

I think we should:

• redesign PermissionManager to allow for a lazy initialization of the DB such that we can expect the async shutdown service to be active
• do some assertion if the SpinEventLoopUntilfrom mozStorage finds some unclosed connection before it starts spinning (assuming that this is not what we want to see)

Comment 27

[Jens Stutte [:jstutte]]

It seems we did some change 3 years ago here on purpose in order to protect against late initialization? See bug 1541934 which explicitly avoids the lazy initialization. I would think that there are better ways to protect against resurrection?

I assume, a way forward here would be then to

• revert "intelligently" (it's not just a backout) the changes from bug 1541934
• add some AppShutdown::IsInOrBeyond check in the initialization code
• add some explicit or implicit (assert) test if all this works

asuth, wdyt?

Comment 28

[Andrew Sutherland [:asuth] (he/him)]

Yes, that makes sense. My understanding from my restating comment in the review is that our rationale for explicitly initiating startup early was that we had no easy way to know when we were already in shutdown and the fix was a band-aid. You (:jstutte) have since added such functionality, so the hack to compel startup at layout statics isn't necessary.

I vaguely remember that in some other cases with similar problems that we'd hooked up the initialization of things that are reading data from disk to "profile-after-change". I see that there is an observer notification for "profile-do-change" which is a step earlier (and likely appropriate for a core component), so that seems reasonable and like it should cover the initialization. Also, the good news is that although invoking profile_do_change() with its default false argument for notifyProfileAfterChange won't fire "profile-after-change", it DOES fire "profile-do-change", so there should be minimal breakage for xpcshell tests from this. (And it also suggests maybe I should have been recommending "profile-do-change" more those times I suggested "profile-after-change"...)

Tim, you're module owner of this code, what are your thoughts/preference?

Comment 29

[Intermittent Failures Robot]

23 failures in 2873 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5
• autoland: 12
• try: 2
• mozilla-esr91: 4

Platform and build breakdown:

• windows10-32-2004-qr: 13
  • debug: 13
• windows10-64-2004-qr: 10
  • debug: 10

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

Comment 31

[Tim Huang[:timhuang] (PTO 8/25 ~ 9/2)]

Yes, the proposal in comment 27 looks promising to me. Given that we can check the shutdown phase via AppShutdown::IsInOrBeyond, we can move back to lazy initialization. And it will also help with the performance of the startup.

Comment 32

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 10
• mozilla-central: 6

Platform and build breakdown:

• windows10-32-2004-qr: 10
  • debug: 10
• windows10-64-2004-qr: 6
  • debug: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-09-27&endday=2021-10-03&tree=all

Comment 33

[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: 13
• mozilla-central: 8
• elm: 2
• try: 1

Platform and build breakdown:

• windows10-64-2004-qr: 12
  • debug: 12
• windows10-32-2004-qr: 12
  • debug: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-10-04&endday=2021-10-10&tree=all

Comment 34

[Jens Stutte [:jstutte]]

Hi Tim, would you be able to find someone to work on this? I will not be able to do this any time soon, I fear.

Comment 35

[Intermittent Failures Robot]

36 failures in 3315 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #31 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:

• autoland: 18
• mozilla-central: 13
• elm: 5

Platform and build breakdown:

• windows10-32-2004-qr: 17
  • debug: 17
• windows10-64-2004-qr: 19
  • debug: 19

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

Comment 36

[Iulian Moraru]

Update:
There have been 44 failures within the last 7 days:
• 23 failures on Windows 10 x86 2004 WebRender debug
• 21 failures on Windows 10 x64 2004 WebRender debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355826724&repo=mozilla-central&lineNumber=1985

[task 2021-10-23T11:40:27.889Z] 11:40:27     INFO -  TEST-PASS | toolkit/components/cleardata/tests/unit/test_storage_permission.js | test_deleteUserInteractionForClearingHistory - [test_deleteUserInteractionForClearingHistory : 386] 1 == 1
[task 2021-10-23T11:40:27.889Z] 11:40:27     INFO -  (xpcshell/head.js) | test run_next_test 4 pending (2)
[task 2021-10-23T11:40:27.890Z] 11:40:27     INFO -  (xpcshell/head.js) | test test_deleteUserInteractionForClearingHistory finished (2)
[task 2021-10-23T11:40:27.890Z] 11:40:27     INFO -  (xpcshell/head.js) | test run_next_test 4 finished (1)
[task 2021-10-23T11:40:27.890Z] 11:40:27     INFO -  exiting test
[task 2021-10-23T11:40:27.890Z] 11:40:27     INFO -  PID 13476 | Storage connection not closed: permissions.sqliteHit MOZ_CRASH() at /builds/worker/checkouts/gecko/storage/mozStorageService.cpp:730
[task 2021-10-23T11:40:27.891Z] 11:40:27     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2021-10-23T11:40:37.551Z] 11:40:37     INFO -  PID 13476 | #01: mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*) [storage/mozStorageService.cpp:730]
[task 2021-10-23T11:40:37.563Z] 11:40:37     INFO -  PID 13476 | #02: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverList.cpp:69]
[task 2021-10-23T11:40:37.563Z] 11:40:37     INFO -  PID 13476 | #03: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverService.cpp:295]
[task 2021-10-23T11:40:37.563Z] 11:40:37     INFO -  PID 13476 | #04: mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) [xpcom/base/AppShutdown.cpp:363]
[task 2021-10-23T11:40:37.564Z] 11:40:37     INFO -  PID 13476 | #05: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:624]
[task 2021-10-23T11:40:37.564Z] 11:40:37     INFO -  PID 13476 | #06: XRE_XPCShellMain(int, char**, char**, XREShellData const*) [js/xpconnect/src/XPCShellImpl.cpp:1432]
[task 2021-10-23T11:40:37.609Z] 11:40:37     INFO -  PID 13476 | #07: NS_internal_main(int, char**, char**) [js/xpconnect/shell/xpcshell.cpp:82]
[task 2021-10-23T11:40:37.612Z] 11:40:37     INFO -  PID 13476 | #08: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:131]
[task 2021-10-23T11:40:37.613Z] 11:40:37     INFO -  PID 13476 | #09: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/js/xpconnect/shell/d:/agent/_work/1/s/src/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2021-10-23T11:40:37.621Z] 11:40:37     INFO -  fix-stacks: error: failed to read debug info file `wkernel32.pdb` for `C:\Windows\System32\KERNEL32.DLL`
[task 2021-10-23T11:40:37.621Z] 11:40:37     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-10-23T11:40:37.622Z] 11:40:37     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-10-23T11:40:37.622Z] 11:40:37     INFO -  PID 13476 | #10: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x17034]
[task 2021-10-23T11:40:37.635Z] 11:40:37     INFO -  fix-stacks: error: failed to read debug info file `wntdll.pdb` for `C:\Windows\SYSTEM32\ntdll.dll`
[task 2021-10-23T11:40:37.635Z] 11:40:37     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-10-23T11:40:37.635Z] 11:40:37     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-10-23T11:40:37.635Z] 11:40:37     INFO -  PID 13476 | #11: RtlUserThreadStart [C:\Windows\SYSTEM32\ntdll.dll + 0x52651]
[task 2021-10-23T11:40:37.635Z] 11:40:37     INFO -  <<<<<<<
[task 2021-10-23T11:40:44.751Z] 11:40:44  WARNING -  PROCESS-CRASH | toolkit/components/cleardata/tests/unit/test_storage_permission.js | application crashed [@ nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*)]
[task 2021-10-23T11:40:44.763Z] 11:40:44     INFO -  Mozilla crash reason: MOZ_CRASH()
[task 2021-10-23T11:40:44.763Z] 11:40:44     INFO -  Crash dump filename: C:\Users\task_163498736079922\AppData\Local\Temp\xpc-other-jd07wzty\4edf4f3c-2f6d-44f7-ba7a-b0032c95d91a.dmp
[task 2021-10-23T11:40:44.763Z] 11:40:44     INFO -  Operating system: Windows NT
[task 2021-10-23T11:40:44.763Z] 11:40:44     INFO -                    10.0.19041
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -  CPU: amd64
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -       family 6 model 85 stepping 7
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -       8 CPUs
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -  GPU: UNKNOWN
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
[task 2021-10-23T11:40:44.764Z] 11:40:44     INFO -  Crash address: 0x414d0b00
[task 2021-10-23T11:40:44.765Z] 11:40:44     INFO -  Process uptime: 0 seconds
[task 2021-10-23T11:40:44.765Z] 11:40:44     INFO -  Thread 0 tid 7616 (crashed) - GeckoMain 0  xul.dll!mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*) [mozStorageService.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 730 + 0x0]
[task 2021-10-23T11:40:44.765Z] 11:40:44     INFO -      rax = 0x00007ff948d12a4e   rdx = 0x0000000000000000
[task 2021-10-23T11:40:44.765Z] 11:40:44     INFO -      rcx = 0x00007ff952e1c978   rbx = 0x0000004c9dbff000
[task 2021-10-23T11:40:44.766Z] 11:40:44     INFO -      rsi = 0x0000004c9dbff000   rdi = 0x0000000000000000
[task 2021-10-23T11:40:44.766Z] 11:40:44     INFO -      rbp = 0x0000000000000001   rsp = 0x0000004c9dbfef40
[task 2021-10-23T11:40:44.766Z] 11:40:44     INFO -       r8 = 0x0000004c9dbffb30    r9 = 0x00007ff97db30000
[task 2021-10-23T11:40:44.766Z] 11:40:44     INFO -      r10 = 0x00007ff97db82651   r11 = 0x0000004c9dbfe900
[task 2021-10-23T11:40:44.766Z] 11:40:44     INFO -      r12 = 0x000001ca2e162a00   r13 = 0x0000000000000008
[task 2021-10-23T11:40:44.767Z] 11:40:44     INFO -      r14 = 0x000001ca2e113010   r15 = 0x00007ff948d76610
[task 2021-10-23T11:40:44.767Z] 11:40:44     INFO -      rip = 0x00007ff9414d0b00
[task 2021-10-23T11:40:44.767Z] 11:40:44     INFO -      Found by: given as instruction pointer in context
[task 2021-10-23T11:40:44.767Z] 11:40:44     INFO -   1  xul.dll!nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverList.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 70 + 0x16]
[task 2021-10-23T11:40:44.768Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.768Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff180   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.768Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.768Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff94034563a
[task 2021-10-23T11:40:44.768Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.769Z] 11:40:44     INFO -   2  xul.dll!nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverService.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 292 + 0x11]
[task 2021-10-23T11:40:44.769Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.769Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff1e0   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.769Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.769Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff940350ec3
[task 2021-10-23T11:40:44.770Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.770Z] 11:40:44     INFO -   3  xul.dll!mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) [AppShutdown.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 361 + 0x13]
[task 2021-10-23T11:40:44.770Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.770Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff390   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff9402ba7ac
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -   4  xul.dll!mozilla::ShutdownXPCOM(nsIServiceManager*) [XPCOMInit.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 624 + 0xc]
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.771Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff3f0   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.772Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.772Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff940463140
[task 2021-10-23T11:40:44.772Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.772Z] 11:40:44     INFO -   5  xul.dll!XRE_XPCShellMain(int, char**, char**, XREShellData const*) [XPCShellImpl.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 1432 + 0x7]
[task 2021-10-23T11:40:44.772Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.773Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff4e0   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.773Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.773Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff941447b4a
[task 2021-10-23T11:40:44.773Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -   6  xpcshell.exe!NS_internal_main(int, char**, char**) [xpcshell.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 82 + 0x22]
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff920   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff75fca12b6
[task 2021-10-23T11:40:44.774Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -   7  xpcshell.exe!wmain(int, wchar_t**) [nsWindowsWMain.cpp:54d250f01e8ba17a8526c1a64b21157da65d9619 : 131 + 0x13]
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -      rsp = 0x0000004c9dbff990   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff75fca11b4
[task 2021-10-23T11:40:44.775Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -   8  xpcshell.exe!__scrt_common_main_seh() [exe_common.inl : 288 + 0x22]
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -      rsp = 0x0000004c9dbffa40   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff75fd1eec8
[task 2021-10-23T11:40:44.776Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.777Z] 11:40:44     INFO -   9  kernel32.dll + 0x17034
[task 2021-10-23T11:40:44.777Z] 11:40:44     INFO -      rbx = 0x0000004c9dbff000   rbp = 0x0000000000000001
[task 2021-10-23T11:40:44.777Z] 11:40:44     INFO -      rsp = 0x0000004c9dbffa80   r12 = 0x000001ca2e162a00
[task 2021-10-23T11:40:44.777Z] 11:40:44     INFO -      r13 = 0x0000000000000008   r14 = 0x000001ca2e113010
[task 2021-10-23T11:40:44.777Z] 11:40:44     INFO -      r15 = 0x00007ff948d76610   rip = 0x00007ff97ce17034
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -      Found by: call frame info
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -  10  ntdll.dll + 0x52651
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -      rsp = 0x0000004c9dbffab0   rip = 0x00007ff97db82651
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -      Found by: stack scanning
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -  11  KERNELBASE.dll + 0x10c160
[task 2021-10-23T11:40:44.778Z] 11:40:44     INFO -      rsp = 0x0000004c9dbffb00   rip = 0x00007ff97b64c160
[task 2021-10-23T11:40:44.779Z] 11:40:44     INFO -      Found by: stack scanning

Comment 37

[Intermittent Failures Robot]

43 failures in 3186 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #12 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:

• autoland: 25
• mozilla-central: 18

Platform and build breakdown:

• windows10-32-2004-qr: 22
  • debug: 22
• windows10-64-2004-qr: 21
  • debug: 21

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

Comment 38

[Intermittent Failures Robot]

27 failures in 2845 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #26 most frequent failure this week.

Repository breakdown:

• autoland: 21
• try: 1
• mozilla-central: 5

Platform and build breakdown:

• windows10-32-2004-qr: 15
  • debug: 15
• windows10-64-2004-qr: 12
  • debug: 12

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

Comment 39

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 32 failures within the last 7 days:

• 13 failures on Windows 10 x64 2004 WebRender debug
• 19 failures on Windows 10 x86 2004 WebRender debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=357062947&repo=mozilla-central&lineNumber=1985

Comment 40

[Intermittent Failures Robot]

46 failures in 3030 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #25 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:

• elm: 2
• autoland: 31
• mozilla-central: 11
• mozilla-esr91: 1
• try: 1

Platform and build breakdown:

• windows10-64-2004-qr: 22
  • debug: 22
• windows10-32-2004-qr: 24
  • debug: 24

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

Comment 41

[Atila Butkovits]

There have been 44 failures in the last 7 days.

Happens on:
-windows10-32-2004-qr debug
-windows10-64-2004-qr debug.

Recent failure log

Comment 42

[Intermittent Failures Robot]

35 failures in 2723 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #17 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:

• autoland: 24
• mozilla-central: 9
• mozilla-esr91: 2

Platform and build breakdown:

• windows10-64-2004-qr: 13
  • debug: 13
• windows10-32-2004-qr: 21
  • debug: 21
• windows10-64-2004-shippable-qr: 1
  • opt: 1

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

Comment 43

[Intermittent Failures Robot]

43 failures in 3259 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #16 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:

• autoland: 29
• mozilla-esr91: 2
• mozilla-central: 12

Platform and build breakdown:

• windows10-32-2004-qr: 22
  • debug: 22
• windows10-64-2004-qr: 21
  • debug: 21

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

Comment 44

[Jens Stutte [:jstutte]]

Attachment: Bug 1707963: Let the PermissionManager be initialized lazily but not after shutdown started. r?#permissions-reviewers,asuth

Comment 45

[Jens Stutte [:jstutte]]

Attachment: Bug 1707963: Assert for unexpected open connections before we do a last attempt to close them. r?mak

Depends on D132088

Comment 46

[Jens Stutte [:jstutte]]

Attachment: Bug 1707963: Avoid a potential race on permission manager singleton creation. r=asuth

Depends on D132143

Comment 47

[Intermittent Failures Robot]

39 failures in 2819 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #30 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: 13
• autoland: 21
• mozilla-esr91: 5

Platform and build breakdown:

• windows10-32-2004-qr: 24
  • debug: 24
• windows10-64-2004-qr: 15
  • debug: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2021-11-22&endday=2021-11-28&tree=all

Comment 49

[Andreea Pavel [:apavel]]

There are 48 total failures in the last 7 days on windows10-32-2004-qr debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=360189827&repo=mozilla-central&lineNumber=2020

[task 2021-12-04T22:33:31.427Z] 22:33:31     INFO -  TEST-START | extensions/permissions/test/unit/test_permmanager_cleardata.js
[task 2021-12-04T22:33:31.846Z] 22:33:31  WARNING -  TEST-UNEXPECTED-FAIL | extensions/permissions/test/unit/test_permmanager_cleardata.js | xpcshell return code: 1
[task 2021-12-04T22:33:31.852Z] 22:33:31     INFO -  TEST-INFO took 419ms
[task 2021-12-04T22:33:31.852Z] 22:33:31     INFO -  >>>>>>>
[task 2021-12-04T22:33:31.852Z] 22:33:31     INFO -  PID 13204 | DLL blocklist was unable to intercept AppInit DLLs.
[task 2021-12-04T22:33:31.852Z] 22:33:31     INFO -  PID 13204 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2021-12-04T22:33:31.853Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:120
[task 2021-12-04T22:33:31.853Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:120
[task 2021-12-04T22:33:31.853Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:120
[task 2021-12-04T22:33:31.853Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2964
[task 2021-12-04T22:33:31.854Z] 22:33:31     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-12-04T22:33:31.854Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002 (NS_NOINTERFACE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:560
[task 2021-12-04T22:33:31.854Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 29] 0 == 0
[task 2021-12-04T22:33:31.855Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 40] 1 == 1
[task 2021-12-04T22:33:31.855Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 29] 0 == 0
[task 2021-12-04T22:33:31.855Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 40] 1 == 1
[task 2021-12-04T22:33:31.855Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 52] 0 == 0
[task 2021-12-04T22:33:31.855Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 52] 0 == 0
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 29] 0 == 0
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 40] 1 == 1
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 29] 0 == 0
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 40] 1 == 1
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 52] 1 == 1
[task 2021-12-04T22:33:31.856Z] 22:33:31     INFO -  TEST-PASS | extensions/permissions/test/unit/test_permmanager_cleardata.js | test - [test : 52] 0 == 0
[task 2021-12-04T22:33:31.857Z] 22:33:31     INFO -  (xpcshell/head.js) | test MAIN run_test finished (1)
[task 2021-12-04T22:33:31.857Z] 22:33:31     INFO -  exiting test
[task 2021-12-04T22:33:31.857Z] 22:33:31     INFO -  PID 13204 | [Parent 13204, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:387
[task 2021-12-04T22:33:31.857Z] 22:33:31     INFO -  PID 13204 | Storage connection not closed: permissions.sqliteHit MOZ_CRASH() at /builds/worker/checkouts/gecko/storage/mozStorageService.cpp:730
[task 2021-12-04T22:33:31.857Z] 22:33:31     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2021-12-04T22:33:42.768Z] 22:33:42     INFO -  PID 13204 | #01: mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*) [storage/mozStorageService.cpp:730]
[task 2021-12-04T22:33:42.772Z] 22:33:42     INFO -  PID 13204 | #02: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverList.cpp:69]
[task 2021-12-04T22:33:42.772Z] 22:33:42     INFO -  PID 13204 | #03: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverService.cpp:295]
[task 2021-12-04T22:33:42.772Z] 22:33:42     INFO -  PID 13204 | #04: mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) [xpcom/base/AppShutdown.cpp:362]
[task 2021-12-04T22:33:42.773Z] 22:33:42     INFO -  PID 13204 | #05: static mozilla::AppShutdown::AdvanceShutdownPhase(mozilla::ShutdownPhase, char16_t const*, nsCOMPtr<nsISupports> const&) [xpcom/base/AppShutdown.cpp:379]
[task 2021-12-04T22:33:42.773Z] 22:33:42     INFO -  PID 13204 | #06: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:624]
[task 2021-12-04T22:33:42.773Z] 22:33:42     INFO -  PID 13204 | #07: XRE_XPCShellMain(int, char**, char**, XREShellData const*) [js/xpconnect/src/XPCShellImpl.cpp:1434]
[task 2021-12-04T22:33:42.773Z] 22:33:42     INFO -  PID 13204 | #08: mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) [toolkit/xre/Bootstrap.cpp:54]
[task 2021-12-04T22:33:42.816Z] 22:33:42     INFO -  PID 13204 | #09: NS_internal_main(int, char**, char**) [js/xpconnect/shell/xpcshell.cpp:82]
[task 2021-12-04T22:33:42.822Z] 22:33:42     INFO -  PID 13204 | #10: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:147]
[task 2021-12-04T22:33:42.822Z] 22:33:42     INFO -  PID 13204 | #11: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/js/xpconnect/shell/d:/agent/_work/3/s/src/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2021-12-04T22:33:42.824Z] 22:33:42     INFO -  fix-stacks: error: failed to read debug info file `wkernel32.pdb` for `C:\Windows\System32\KERNEL32.DLL`
[task 2021-12-04T22:33:42.824Z] 22:33:42     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-12-04T22:33:42.825Z] 22:33:42     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-12-04T22:33:42.825Z] 22:33:42     INFO -  PID 13204 | #12: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x1fa29]
[task 2021-12-04T22:33:42.828Z] 22:33:42     INFO -  fix-stacks: error: failed to read debug info file `wntdll.pdb` for `C:\Windows\SYSTEM32\ntdll.dll`
[task 2021-12-04T22:33:42.828Z] 22:33:42     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-12-04T22:33:42.828Z] 22:33:42     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-12-04T22:33:42.829Z] 22:33:42     INFO -  PID 13204 | #13: RtlGetAppContainerNamedObjectPath [C:\Windows\SYSTEM32\ntdll.dll + 0x67a9e]
[task 2021-12-04T22:33:42.829Z] 22:33:42     INFO -  PID 13204 | #14: RtlGetAppContainerNamedObjectPath [C:\Windows\SYSTEM32\ntdll.dll + 0x67a6e]
[task 2021-12-04T22:33:42.829Z] 22:33:42     INFO -  <<<<<<<
[task 2021-12-04T22:33:46.328Z] 22:33:46  WARNING -  PROCESS-CRASH | extensions/permissions/test/unit/test_permmanager_cleardata.js | application crashed [@ mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*)]
[task 2021-12-04T22:33:46.329Z] 22:33:46     INFO -  Mozilla crash reason: MOZ_CRASH()
[task 2021-12-04T22:33:46.336Z] 22:33:46     INFO -   7  xul.dll!mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) [Bootstrap.cpp:edcfdb2bbe36f9c40c96ac5b8201aaa1e956eca6 : 54 + 0x8]
[task 2021-12-04T22:33:46.336Z] 22:33:46     INFO -      eip = 0x6c2c2903   esp = 0x00bff728   ebp = 0x00bff738   ebx = 0x04f60250
[task 2021-12-04T22:33:46.336Z] 22:33:46     INFO -      esi = 0x06f070a8   edi = 0x6c2c28f0
[task 2021-12-04T22:33:46.336Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.336Z] 22:33:46     INFO -   8  xpcshell.exe!NS_internal_main(int, char**, char**) [xpcshell.cpp:edcfdb2bbe36f9c40c96ac5b8201aaa1e956eca6 : 82 + 0x1e]
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -      eip = 0x00e413be   esp = 0x00bff740   ebp = 0x00bff76c   ebx = 0x04f60250
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -      esi = 0x06f070a8   edi = 0x6c2c28f0
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -   9  xpcshell.exe!wmain(int, wchar_t**) [nsWindowsWMain.cpp:edcfdb2bbe36f9c40c96ac5b8201aaa1e956eca6 : 147 + 0xe]
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -      eip = 0x00e412d0   esp = 0x00bff774   ebp = 0x00bff9e8   ebx = 0x06f04a00
[task 2021-12-04T22:33:46.337Z] 22:33:46     INFO -      esi = 0x0000001c   edi = 0x06f04e00
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -  10  xpcshell.exe!__scrt_common_main_seh() [exe_common.inl : 288 + 0x1b]
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -      eip = 0x00eb1eb9   esp = 0x00bff9f0   ebp = 0x00bffa30   ebx = 0x0096c000
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -      esi = 0x76ad12f0   edi = 0x04f623f0
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.338Z] 22:33:46     INFO -  11  kernel32.dll!BaseThreadInitThunk + 0x18
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      eip = 0x75ccfa29   esp = 0x00bffa38   ebp = 0x00bffa40   ebx = 0x0096c000
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      esi = 0x76ad12f0   edi = 0x04f623f0
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -  12  ntdll.dll!_RtlUserThreadStart + 0x2e
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      eip = 0x77177a9e   esp = 0x00bffa48   ebp = 0x00bffa9c   ebx = 0x0096c000
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      esi = 0x76ad12f0   edi = 0x04f623f0
[task 2021-12-04T22:33:46.339Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -  13  ntdll.dll!_RtlUserThreadStart + 0x1a
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -      eip = 0x77177a6e   esp = 0x00bffaa4   ebp = 0x00bffaac   ebx = 0x0096c000
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -      esi = 0x76ad12f0   edi = 0x04f623f0
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -  Thread 1
[task 2021-12-04T22:33:46.340Z] 22:33:46     INFO -   0  ntdll.dll!NtWaitForWorkViaWorkerFactory + 0xc
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      eip = 0x7718470c   esp = 0x0523fa08   ebp = 0x0523fbc4   ebx = 0x04f4da78
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      esi = 0x04f4da78   edi = 0x04f4c4f0   eax = 0x00000000   ecx = 0x00000000
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      edx = 0x00000000   efl = 0x00000202
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      Found by: given as instruction pointer in context
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -   1  ntdll.dll!TppWorkerThread + 0x29f
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      eip = 0x77145ba0   esp = 0x0523fa0c   ebp = 0x0523fbc4   ebx = 0x04f4da78
[task 2021-12-04T22:33:46.341Z] 22:33:46     INFO -      esi = 0x04f4da78   edi = 0x04f4c4f0
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -   2  kernel32.dll!BaseThreadInitThunk + 0x18
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -      eip = 0x75ccfa29   esp = 0x0523fbcc   ebp = 0x0523fbd4   ebx = 0x04f4da78
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -      esi = 0x04f4da78   edi = 0x04f4c4f0
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.342Z] 22:33:46     INFO -   3  ntdll.dll!_RtlUserThreadStart + 0x2e
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      eip = 0x77177a9e   esp = 0x0523fbdc   ebp = 0x0523fc30   ebx = 0x04f4da78
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      esi = 0x04f4da78   edi = 0x04f4c4f0
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      Found by: call frame info
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -   4  ntdll.dll!_RtlUserThreadStart + 0x1a
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      eip = 0x77177a6e   esp = 0x0523fc38   ebp = 0x0523fc40   ebx = 0x04f4da78
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      esi = 0x04f4da78   edi = 0x04f4c4f0
[task 2021-12-04T22:33:46.343Z] 22:33:46     INFO -      Found by: call frame info

Comment 50

[Intermittent Failures Robot]

52 failures in 3170 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #15 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:

• autoland: 34
• mozilla-central: 14
• try: 3
• mozilla-esr91: 1

Platform and build breakdown:

• windows10-32-2004-qr: 31
  • debug: 31
• windows10-64-2004-qr: 21
  • debug: 21

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

Comment 51

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5d86acaf84da
Let the PermissionManager be initialized lazily but not after shutdown started. r=permissions-reviewers,timhuang,janv
https://hg.mozilla.org/integration/autoland/rev/4e7eac659186
Avoid a potential race on permission manager singleton creation. r=permissions-reviewers,timhuang

Comment 52

[Alexandru Michis [:malexandru]]

Backed out 2 changesets (Bug 1707963) for causing bc failures in browser_xpcom_graph_wait.js
Backout link: https://hg.mozilla.org/integration/autoland/rev/3f29a100ee068bd1396863ff58be989140badd3d
Push with failures, failure log.

Comment 53

[Intermittent Failures Robot]

27 failures in 3319 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #43 most frequent failure this week.

Repository breakdown:

• autoland: 21
• mozilla-central: 3
• mozilla-esr91: 3

Platform and build breakdown:

• windows10-64-2004-qr: 11
  • debug: 11
• windows10-32-2004-qr: 16
  • debug: 16

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

Comment 54

[Jens Stutte [:jstutte]]

So this confirms the doubt I had that ShutdownPhase::XPCOMWillShutdown is quite late in the progress for this shutdown blocker. In fact the failing test seems to assume, that all XPCOM components have been unloaded before it runs and the test itself runs during the same shutdown phase we registered the blocker for and thus race (or things are executed simply always in the wrong order).

The next earlier phase would be ShutdownPhase::AppShutdownTelemetry which is kind of unrelated, but might help. We could also try with ShutdownPhase::AppShutdownQM which is at least storage related and might be late enough to not interfere with other things during shutdown.

I'll do some try in that sense.

Comment 55

[Jens Stutte [:jstutte]]

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

So this confirms the doubt I had that ShutdownPhase::XPCOMWillShutdown is quite late in the progress for this shutdown blocker. In fact the failing test seems to assume, that all XPCOM components have been unloaded before it runs and the test itself runs during the same shutdown phase we registered the blocker for and thus race (or things are executed simply always in the wrong order).

The next earlier phase would be ShutdownPhase::AppShutdownTelemetry which is kind of unrelated, but might help. We could also try with ShutdownPhase::AppShutdownQM which is at least storage related and might be late enough to not interfere with other things during shutdown.

I'll do some try in that sense.

Anticipating is actually not solving the issue. Reading through browser_xpcom_graph_wait.js my understanding is now that this test has an allowlist that basically matches the services we start in nsLayoutStatics::Initialize and we should just remove the permission manager from this list.

Comment 56

[Jens Stutte [:jstutte]]

Attachment: Bug 1707963: Remove permission manager from browser_xpcom_graph_wait.js. r?mossop

Once we allow lazy initialization for the permission manager, we do not launch it at startup in any kind of process. We thus need to update the allowlist of this test.

Depends on D132215

Comment 57

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2ed465311a9e
Let the PermissionManager be initialized lazily but not after shutdown started. r=permissions-reviewers,timhuang,janv
https://hg.mozilla.org/integration/autoland/rev/b7acc9075f56
Avoid a potential race on permission manager singleton creation. r=permissions-reviewers,timhuang
https://hg.mozilla.org/integration/autoland/rev/a186b32ae27e
Remove permission manager from browser_xpcom_graph_wait.js. r=mossop

Comment 58

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/2ed465311a9e
https://hg.mozilla.org/mozilla-central/rev/b7acc9075f56
https://hg.mozilla.org/mozilla-central/rev/a186b32ae27e

Comment 59

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

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

Comment 60

[Intermittent Failures Robot]

11 failures in 3263 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• try: 1
• mozilla-central: 4
• mozilla-esr91: 2

Platform and build breakdown:

• windows10-64-2004-qr: 7
  • debug: 7
• windows10-32-2004-qr: 4
  • debug: 4

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

Comment 61

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr91: 4

Platform and build breakdown:

• windows10-64-2004-qr: 4
  • debug: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1707963&startday=2022-01-03&endday=2022-01-09&tree=all

Comment 62

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr91: 1

Platform and build breakdown:

• windows10-32-2004-qr: 1
  • debug: 1

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

Comment 63

[Ryan VanderMeulen [:RyanVM]]

Hi Jens, this is still hitting ESR91 on a pretty regular basis. The patches graft cleanly there, so what are your thoughts about nominating for uplift?

Comment 64

[Jens Stutte [:jstutte]]

Comment on attachment 9252385 [details]
Bug 1707963: Let the PermissionManager be initialized lazily but not after shutdown started. r?#permissions-reviewers,asuth

ESR Uplift Approval Request

• If this is not a sec:{high,crit} bug, please state case for ESR consideration: This is causing frequent failures in our CI.
• User impact if declined: This might prevent from some shutdown hangs, though it might just move them to happen earlier during the shutdown sequence.
• Fix Landed on Version: 97
• Risk to taking this patch: Medium
• Why is the change risky/not risky? (and alternatives if risky): These patches are simple but change the order of when things happen quite a lot. But it is now active for quite a while and we do not know about regressions.
  If we want to just moot the assertions, we could remove this snippet instead.

Comment 65

[Jens Stutte [:jstutte]]

Please note that removing those assertions could affect also other mozStorage clients than just the permission manager and should be considered a temporary fix only (until the next major ESR release).

Comment 66

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9252385 [details]
Bug 1707963: Let the PermissionManager be initialized lazily but not after shutdown started. r?#permissions-reviewers,asuth

Approved for 91.6esr, thanks.

Comment 67

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr91/rev/e0fa9174c0fd
https://hg.mozilla.org/releases/mozilla-esr91/rev/91cf145c3df0
https://hg.mozilla.org/releases/mozilla-esr91/rev/65c98abf6c50