Bug 174354 – REGRESSION(r219298): RELEASE_ASSERT(!m_owningPointerForClose) fails in WebCore::IDBServer::UniqueIDBDatabase::scheduleShutdownForClose

• Component: WebKitGTK
• Status: RESOLVED FIXED

[Charlie Turner]

Looks like r219298 "Cleanup lifetime issues of UniqueIDBDatabase and IDBBackingStore." was responsible for this one.
I can't reproduce locally, but it's failing fairly often on the bots,

[r219272-r219291]             NOERROR
[r219292-r219294]             UNKNOWN
r219295                       NOERROR
[r219296-r219299]             UNKNOWN
[r219300-r219301]             CRASH (Expected: PASS)
[r219302-r219305]             UNKNOWN
r219306                       CRASH (Expected: PASS)
r219307                       UNKNOWN
r219308                       NOERROR
r219309                       UNKNOWN
r219310                       CRASH (Expected: PASS)
r219311                       UNKNOWN
r219312                       CRASH (Expected: PASS)
r219313                       UNKNOWN
r219314                       CRASH (Expected: PASS)
[r219315-r219316]             UNKNOWN
[r219317-r219319]             CRASH (Expected: PASS)
[r219320-r219322]             UNKNOWN
[r219323-r219324]             CRASH (Expected: PASS)

Will mark this as flaky.

[Charlie Turner]

Created attachment 315091 [details]
Patch

[Michael Catanzaro]

Comment on attachment 315091 [details]
Patch

Is there a stacktrace on the bots that you could post here?

It's also a good idea to CC the developer who made the change that broke the test as an FYI.

[Michael Catanzaro]

Oh, that reminds me: there is one problem with using commit-queue to land gardening patches. commit-queue will close this bug once your patch lands. But we want the bug to remain open for as long as the test expectation exists. So we have to remember to reopen this bug after commit-queue lands it.

Sometimes it is hard to remember. :)

[Charlie Turner]

Just noticed imported/w3c/IndexedDB-private-browsing/idbfactory_open12.html crashes on WPE occasionally as well.

[Brady Eidson]

Lots of talk about crashes in here...  but no actual backtraces.

A little help, please? ;)

[Charlie Turner]

Brady, I wouldn't have CC'd you before I got some more info, unfortunately at the moment I can't reproduce locally to give you good information and can't get the stacktrace of our buildbot. I'll update the ticket when I can get this information.

[Brady Eidson]

(In reply to Charlie Turner from comment #6)
> Brady, I wouldn't have CC'd you before I got some more info, unfortunately
> at the moment I can't reproduce locally to give you good information and
> can't get the stacktrace of our buildbot. I'll update the ticket when I can
> get this information.


👍👍👍

[Carlos Alberto Lopez Perez]

(In reply to Charlie Turner from comment #6)
> Brady, I wouldn't have CC'd you before I got some more info, unfortunately
> at the moment I can't reproduce locally to give you good information and
> can't get the stacktrace of our buildbot. I'll update the ticket when I can
> get this information.

If you know which revision crashed, you can find the backtrace here:

https://build.webkit.org/results/GTK%20Linux%2064-bit%20Release%20(Tests)/

Open the folder that matches the revision and then the results.html file and the crashlog will be there.

In this case is this one:

https://build.webkit.org/results/GTK%20Linux%2064-bit%20Release%20(Tests)/r219324%20%282103%29/imported/w3c/IndexedDB-private-browsing/idbfactory_open-crash-log.txt

Due to a GDB bug the symbols are unmangled, Use this to demangle them:

$ curl -s 'https://build.webkit.org/results/GTK%20Linux%2064-bit%20Release%20(Tests)/r219324%20%282103%29/imported/w3c/IndexedDB-private-browsing/idbfactory_open-crash-log.txt'|c++filt

Result: http://sprunge.us/bjYL

[Carlos Alberto Lopez Perez]

Even better, there is also a crash log from the debug bot:

https://build.webkit.org/results/GTK%20Linux%2064-bit%20Debug%20%28Tests%29/r219327%20%281172%29/imported/w3c/IndexedDB-private-browsing/idbfactory_open-crash-log.txt

demangled: http://sprunge.us/CAXi

On the debug bot its hitting an assertion

[Brady Eidson]

(In reply to Carlos Alberto Lopez Perez from comment #8)
> 
> Result: http://sprunge.us/bjYL

This one is bizarre. Is "Thread 1" the main thread for a GTK process? Because this "Thread 1" is executing background thread stuff.

[Brady Eidson]

(In reply to Carlos Alberto Lopez Perez from comment #9)
> Even better, there is also a crash log from the debug bot:
> 
> https://build.webkit.org/results/GTK%20Linux%2064-bit%20Debug%20%28Tests%29/
> r219327%20%281172%29/imported/w3c/IndexedDB-private-browsing/idbfactory_open-
> crash-log.txt
> 
> demangled: http://sprunge.us/CAXi
> 
> On the debug bot its hitting an assertion

Yikes.

So... You're running database thread code on the main thread.

That's not good. I'm not sure how anything is working.

[Brady Eidson]

(In reply to Brady Eidson from comment #11)
> (In reply to Carlos Alberto Lopez Perez from comment #9)
> > Even better, there is also a crash log from the debug bot:
> > 
> > https://build.webkit.org/results/GTK%20Linux%2064-bit%20Debug%20%28Tests%29/
> > r219327%20%281172%29/imported/w3c/IndexedDB-private-browsing/idbfactory_open-
> > crash-log.txt
> > 
> > demangled: http://sprunge.us/CAXi
> > 
> > On the debug bot its hitting an assertion
> 
> Yikes. 
> So... You're running database thread code on the main thread.
> That's not good. I'm not sure how anything is working.


Nevermind, I misread things. That's main thread code.

[Brady Eidson]

So a UniqueIDBDatabase that has already been taken from the IDBServer set and scheduled to be destroyed... is trying to take itself from the IDBServer set a second time.

Since the UniqueIBDDatabase's operationAndTransactionTimer is firing, we can assuming it has not yet been destroyed (otherwise the operationAndTransactionTimer would have been cancelled when it was destroyed.)

So... that's weird.

In Apple-land we're not seeing this in Debug, Release, ASAN... anything. So I'm at a loss why you'd be seeing it.

[WebKit Commit Bot]

Comment on attachment 315091 [details]
Patch

Clearing flags on attachment: 315091

Committed r219349: <http://trac.webkit.org/changeset/219349>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Michael Catanzaro]

Reopening, was a gardening commit.

[Charlie Turner]

Brady, there's some crash logs in the iOS simulator attached by the Buildbot to this bug report,

https://bugs.webkit.org/show_bug.cgi?id=174363

Not sure why it's attached that report, looks like a race that got triggered on GTK/WPE ports sooner than Apple ones.

[Brady Eidson]

Also seeing Mac crashes here - https://bugs.webkit.org/show_bug.cgi?id=174435#c15

Exploring.

[Brady Eidson]

The problem is we're trying to take the database from the set twice.

closeAndTakeUniqueIDBDatabase is called from only a few places:

UniqueIDBDatabase::scheduleShutdownForClose() from inside UniqueIDBDatabase::operationAndTransactionTimerFired()

UniqueIDBDatabase::scheduleShutdownForClose() from inside UniqueIDBDatabase::transactionCompleted()

UniqueIDBDatabase::didDeleteBackingStore()

UniqueIDBDatabase::immediateCloseForUserDelete()

[Brady Eidson]

immediateCloseForUserDelete is clearly the one at odds with all the others here. It's the operation that "behaves a little differently" than normal database ops.

Namely, one of the other "shutdownForClose" paths has already been called, and the unique_ptr is floating around in the background thread machinery, but the immediate close operation tries to reschedule for user delete.

I need to clean up all of the different ways the owning pointer can be removed for deletion and protect around how immediateCloseForUserDelete behaves differently.

But we also need to allow for the "user delete" part of the immediate close to happen, even if the backing store and queues are in the process of being shutdown right then on the background thread.

More assertions will be involved, too. :)

[Brady Eidson]

<rdar://problem/33294987>

[Brady Eidson]

Created attachment 315381 [details]
Patch

[Brady Eidson]

This patch still triggered an ASSERT in DRT locally

Application Specific Information:
CRASHING TEST: http://localhost:8800/IndexedDB/request-event-ordering.html

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   com.apple.JavaScriptCore      	0x00000001096c4374 WTFCrash + 36 (Assertions.cpp:293)
1   com.apple.WebCore             	0x00000001141d07af WebCore::IDBServer::UniqueIDBDatabase::maybeFinishHardClose()::$_2::operator()() const + 79 (UniqueIDBDatabase.cpp:1785)
2   com.apple.WebCore             	0x00000001141d0739 WTF::Function<void ()>::CallableWrapper<WebCore::IDBServer::UniqueIDBDatabase::maybeFinishHardClose()::$_2>::call() + 25 (Function.h:102)
3   com.apple.JavaScriptCore      	0x00000001096f4ace WTF::Function<void ()>::operator()() const + 94 (Function.h:56)
4   com.apple.JavaScriptCore      	0x00000001096f4704 WTF::dispatchFunctionsFromMainThread() + 324 (MainThread.cpp:128)
5   com.apple.JavaScriptCore      	0x00000001096f65f5 -[JSWTFMainThreadCaller call] + 21 (MainThreadMac.mm:54)

Feel free to review, but I'll be exploring that too.

[Build Bot]

Comment on attachment 315381 [details]
Patch

Attachment 315381 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/4115808

New failing tests:
imported/w3c/IndexedDB-private-browsing/idbfactory_open12.html

[Build Bot]

Created attachment 315387 [details]
Archive of layout-test-results from ews123 for ios-simulator-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews123  Port: ios-simulator-wk2  Platform: Mac OS X 10.12.5

[Michael Catanzaro]

(In reply to Build Bot from comment #24)
> Comment on attachment 315381 [details]
> Patch
> 
> Attachment 315381 [details] did not pass ios-sim-ews (ios-simulator-wk2):
> Output: http://webkit-queues.webkit.org/results/4115808
> 
> New failing tests:
> imported/w3c/IndexedDB-private-browsing/idbfactory_open12.html

Goodness gracious, it's a commit-queue failure that's not a false positive! :D

[Brady Eidson]

(In reply to Michael Catanzaro from comment #26)
> (In reply to Build Bot from comment #24)
> > Comment on attachment 315381 [details]
> > Patch
> > 
> > Attachment 315381 [details] did not pass ios-sim-ews (ios-simulator-wk2):
> > Output: http://webkit-queues.webkit.org/results/4115808
> > 
> > New failing tests:
> > imported/w3c/IndexedDB-private-browsing/idbfactory_open12.html
> 
> Goodness gracious, it's a commit-queue failure that's not a false positive!
> :D

That happens occasionally? ;)

That said, I'd already known about this one and am tweaking locally to fix it.

[Brady Eidson]

*** Bug 174447 has been marked as a duplicate of this bug. ***

[Brady Eidson]

*** Bug 174520 has been marked as a duplicate of this bug. ***

[WebKit Commit Bot]

The commit-queue just saw storage/indexeddb/modern/new-database-after-user-delete.html flake (DumpRenderTree crashed) while processing attachment 315479 [details] on bug 174426.
Bot: webkit-cq-01  Port: <class 'webkitpy.common.config.ports.MacPort'>  Platform: Mac OS X 10.11.6

[WebKit Commit Bot]

Created attachment 315483 [details]
Archive of layout-test-results from webkit-cq-01

[Brady Eidson]

Got delayed by even more pressing work, but I'll definitely get back to this as soon as I can.

[WebKit Commit Bot]

The commit-queue just saw storage/indexeddb/modern/new-database-after-user-delete.html flake (DumpRenderTree crashed) while processing attachment 315594 [details] on bug 174540.
Bot: webkit-cq-03  Port: <class 'webkitpy.common.config.ports.MacPort'>  Platform: Mac OS X 10.11.6

[WebKit Commit Bot]

Created attachment 315603 [details]
Archive of layout-test-results from webkit-cq-03

[WebKit Commit Bot]

The commit-queue just saw storage/indexeddb/modern/new-database-after-user-delete.html flake (DumpRenderTree crashed) while processing attachment 315651 [details] on bug 174578.
Bot: webkit-cq-01  Port: <class 'webkitpy.common.config.ports.MacPort'>  Platform: Mac OS X 10.11.6

[WebKit Commit Bot]

Created attachment 315652 [details]
Archive of layout-test-results from webkit-cq-01

[WebKit Commit Bot]

The commit-queue just saw storage/websql/database-lock-after-reload.html flake (DumpRenderTree crashed) while processing attachment 315651 [details] on bug 174578.
Bot: webkit-cq-01  Port: <class 'webkitpy.common.config.ports.MacPort'>  Platform: Mac OS X 10.11.6

[WebKit Commit Bot]

Created attachment 315655 [details]
Archive of layout-test-results from webkit-cq-01

[WebKit Commit Bot]

The commit-queue just saw storage/indexeddb/modern/new-database-after-user-delete.html flake (DumpRenderTree crashed) while processing attachment 315714 [details] on bug 174585.
Bot: webkit-cq-01  Port: <class 'webkitpy.common.config.ports.MacPort'>  Platform: Mac OS X 10.11.6

[WebKit Commit Bot]

Created attachment 315721 [details]
Archive of layout-test-results from webkit-cq-01

[Brady Eidson]

I have this figured out (I think)

New patch en route

[Brady Eidson]

Created attachment 315724 [details]
Patch for EWS then maybe landing

[Brady Eidson]

(In reply to Brady Eidson from comment #42)
> Created attachment 315724 [details]
> Patch for EWS then maybe landing

I'm also hammering on this patch in particularly gnarly ways locally - I think this does it.

[WebKit Commit Bot]

Comment on attachment 315724 [details]
Patch for EWS then maybe landing

Clearing flags on attachment: 315724

Committed r219591: <http://trac.webkit.org/changeset/219591>

[Michael Catanzaro]

This should be closed now, right?

[Charlie Turner]

I still see a crash on GTK bot http://sprunge.us/PhXg

[Michael Catanzaro]

OK :(

[Brady Eidson]

(In reply to Charlie Turner from comment #46)
> I still see a crash on GTK bot http://sprunge.us/PhXg

Which test is that - Do we still know that it's the test in the bug title?

I'm going to assume the assert is the release assert because that is your main thread, right?

I could reproduce this on Mac easily before 219591, but not after =/

[Charlie Turner]

Indeed it is the test from the bug title. I saw the crash in this log,

https://build.webkit.org/builders/GTK%20Linux%2064-bit%20Release%20%28Tests%29/builds/2291/steps/layout-test/logs/stdio

Which tested revision r219868

[Charlie Turner]

Not complete sure I understand what a release assert is :( but it's a WTFCrash on our main thread yes :)

[Brady Eidson]

(In reply to Charlie Turner from comment #50)
> Not complete sure I understand what a release assert is :( but it's a
> WTFCrash on our main thread yes :)

RELEASE_ASSERT means an assertion that is compiled and enabled even in release builds.

ASSERT() is debug-build only.

Both crash the process with WTFCrash.

[Charlie Turner]

Gotcha, this is a release build bot, so RELEASE_ASSERT.

[Charlie Turner]

Brady, are you still looking at this, or is it still not reproducible for you? 

The crashes are consistent on GTK.
http://sprunge.us/DSJN   <-- the familiar RELEASE_ASSERT in idbfactory_open12
http://sprunge.us/ODBc   <-- SEGV in  idbcursor_iterating_index
http://sprunge.us/idIM   <-- Similar SEGV in idbcursor_iterating

If these can't be resolved soon, I'll mark them as expected crashes :/

[Michael Catanzaro]

(In reply to Charlie Turner from comment #53)
> If these can't be resolved soon, I'll mark them as expected crashes :/

Since it made a bunch of tests flaky, I would roll it out.

[Michael Catanzaro]

*** Bug 174949 has been marked as a duplicate of this bug. ***

[Michael Catanzaro]

I'm going to mark some WPE tests against this bug as well.

[Michael Catanzaro]

(In reply to Charlie Turner from comment #0)
> Looks like r219298 "Cleanup lifetime issues of UniqueIDBDatabase and
> IDBBackingStore." was responsible for this one.

And I know it's been over half a year, so we can't easily roll this out now, but at this point I think it was a mistake not to have done so....

[Michael Catanzaro]

*** Bug 179758 has been marked as a duplicate of this bug. ***

[Darin Adler]

Is there someone who knows how to fix this?

[Michael Catanzaro]

Note, current backtraces are hidden in comment #53:

(In reply to Charlie Turner from comment #53)
> Brady, are you still looking at this, or is it still not reproducible for
> you? 
> 
> The crashes are consistent on GTK.
> http://sprunge.us/DSJN   <-- the familiar RELEASE_ASSERT in idbfactory_open12
> http://sprunge.us/ODBc   <-- SEGV in  idbcursor_iterating_index
> http://sprunge.us/idIM   <-- Similar SEGV in idbcursor_iterating
> 
> If these can't be resolved soon, I'll mark them as expected crashes :/

[Fujii Hironori]

Created attachment 333063 [details]
WIP patch

This is a diagram showing what is happening:

> UniqueIDBDatabase::handleCurrentOperation
>   UniqueIDBDatabase::performCurrentDeleteOperation
>     UniqueIDBDatabase::didDeleteBackingStore
>       m_owningPointerForClose = m_server.closeAndTakeUniqueIDBDatabase(*this);
>   UniqueIDBDatabase::invokeOperationAndTransactionTimer
> 
> UniqueIDBDatabase::operationAndTransactionTimerFired
>   UniqueIDBDatabase::scheduleShutdownForClose

1) handleCurrentOperation calls performCurrentDeleteOperation
2) performCurrentDeleteOperation calls didDeleteBackingStore
3) m_owningPointerForClose is set in didDeleteBackingStore
4) handleCurrentOperation calls invokeOperationAndTransactionTimer
5) operationAndTransactionTimerFired is dispatched
6) scheduleShutdownForClose is called
7) RELEASE_ASSERT(!m_owningPointerForClose) fails

[Fujii Hironori]

Created attachment 333136 [details]
Patch

[Fujii Hironori]

Comment on attachment 333136 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=333136&action=review

> LayoutTests/ChangeLog:18
> [phone]  Fujii Hironori  <[e-mail]>

Duplicated ChangeLog entry.

[Michael Catanzaro]

Comment on attachment 333136 [details]
Patch

Awesome, thank you Fujii! It looks like this was a tough one.

I'm sure Brady will want to review this.

[Michael Catanzaro]

Let's land these IDB patches; it's been broken for too long. Not exactly sure about the code changes, but I'm encouraged that it fixes tests and doesn't break any on EWS. And this has been a particularly-annoying crasher.

[Fujii Hironori]

Created attachment 334129 [details]
Patch

Thank you for r+, Michael.

[WebKit Commit Bot]

Comment on attachment 334129 [details]
Patch

Clearing flags on attachment: 334129

Committed r228609: <https://trac.webkit.org/changeset/228609>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.