Bug 211637 – SHOULD NEVER BE REACHED in WebKit::ResourceLoadStatisticsDatabaseStore::openAndUpdateSchemaIfNecessary

• Component: New Bugs
• Status: RESOLVED FIXED

[Ryan Haddad]

Even after https://trac.webkit.org/changeset/261146/webkit, we are still seeing assertion failures during iOS Debug test runs:

ERROR: SQLite database failed to set journal_mode to WAL, error: database is locked
./platform/sql/SQLiteDatabase.cpp(208) : void WebCore::SQLiteDatabase::useWALJournalMode()
ERROR: SQLite database failed to checkpoint: database is locked
./platform/sql/SQLiteDatabase.cpp(218) : void WebCore::SQLiteDatabase::useWALJournalMode()
ERROR: Unable to prepare statement to fetch schema for the ObservedDomains table.
/Volumes/Data/slave/ios-simulator-13-debug/build/Source/WebKit/NetworkProcess/Classifier/ResourceLoadStatisticsDatabaseStore.cpp(514) : void WebKit::ResourceLoadStatisticsDatabaseStore::openAndUpdateSchemaIfNecessary()
SHOULD NEVER BE REACHED
/Volumes/Data/slave/ios-simulator-13-debug/build/Source/WebKit/NetworkProcess/Classifier/ResourceLoadStatisticsDatabaseStore.cpp(515) : void WebKit::ResourceLoadStatisticsDatabaseStore::openAndUpdateSchemaIfNecessary()
1   0x1189d4b89 WTFCrash
2   0x103b5584b WTFCrashWithInfo(int, char const*, char const*, int)
3   0x104283eff WebKit::ResourceLoadStatisticsDatabaseStore::openAndUpdateSchemaIfNecessary()
4   0x104283a86 WebKit::ResourceLoadStatisticsDatabaseStore::ResourceLoadStatisticsDatabaseStore(WebKit::WebResourceLoadStatisticsStore&, WTF::WorkQueue&, WebKit::ShouldIncludeLocalhost, WTF::String const&, PAL::SessionID)
5   0x104284943 WebKit::ResourceLoadStatisticsDatabaseStore::ResourceLoadStatisticsDatabaseStore(WebKit::WebResourceLoadStatisticsStore&, WTF::WorkQueue&, WebKit::ShouldIncludeLocalhost, WTF::String const&, PAL::SessionID)
6   0x104335cec std::__1::__unique_if<WebKit::ResourceLoadStatisticsDatabaseStore>::__unique_single std::__1::make_unique<WebKit::ResourceLoadStatisticsDatabaseStore, WebKit::WebResourceLoadStatisticsStore&, WTF::Ref<WTF::WorkQueue, WTF::DumbPtrTraits<WTF::WorkQueue> >&, WebKit::ShouldIncludeLocalhost const&, WTF::String const&, PAL::SessionID const&>(WebKit::WebResourceLoadStatisticsStore&, WTF::Ref<WTF::WorkQueue, WTF::DumbPtrTraits<WTF::WorkQueue> >&, WebKit::ShouldIncludeLocalhost const&, WTF::String const&, PAL::SessionID const&)
7   0x1043358d3 decltype(auto) WTF::makeUnique<WebKit::ResourceLoadStatisticsDatabaseStore, WebKit::WebResourceLoadStatisticsStore&, WTF::Ref<WTF::WorkQueue, WTF::DumbPtrTraits<WTF::WorkQueue> >&, WebKit::ShouldIncludeLocalhost const&, WTF::String const&, PAL::SessionID const&>(WebKit::WebResourceLoadStatisticsStore&, WTF::Ref<WTF::WorkQueue, WTF::DumbPtrTraits<WTF::WorkQueue> >&, WebKit::ShouldIncludeLocalhost const&, WTF::String const&, PAL::SessionID const&)
8   0x104335626 WebKit::WebResourceLoadStatisticsStore::WebResourceLoadStatisticsStore(WebKit::NetworkSession&, WTF::String const&, WebKit::ShouldIncludeLocalhost, WebCore::ResourceLoadStatistics::IsEphemeral)::$_42::operator()() const
9   0x1043354de WTF::Detail::CallableWrapper<WebKit::WebResourceLoadStatisticsStore::WebResourceLoadStatisticsStore(WebKit::NetworkSession&, WTF::String const&, WebKit::ShouldIncludeLocalhost, WebCore::ResourceLoadStatistics::IsEphemeral)::$_42, void>::call()
10  0x103c48452 WTF::Function<void ()>::operator()() const
11  0x10430bd1e WebKit::WebResourceLoadStatisticsStore::postTask(WTF::Function<void ()>&&)::'lambda'()::operator()() const
12  0x10430bc4e WTF::Detail::CallableWrapper<WebKit::WebResourceLoadStatisticsStore::postTask(WTF::Function<void ()>&&)::'lambda'(), void>::call()
13  0x118a00072 WTF::Function<void ()>::operator()() const
14  0x118b0ae2e WTF::WorkQueue::dispatch(WTF::Function<void ()>&&)::$_0::operator()() const
15  0x118b0b022 WTF::BlockPtr<void ()> WTF::BlockPtr<void ()>::fromCallable<WTF::WorkQueue::dispatch(WTF::Function<void ()>&&)::$_0>(WTF::WorkQueue::dispatch(WTF::Function<void ()>&&)::$_0)::'lambda'(void*)::operator()(void*) const
16  0x118b0aff5 WTF::BlockPtr<void ()> WTF::BlockPtr<void ()>::fromCallable<WTF::WorkQueue::dispatch(WTF::Function<void ()>&&)::$_0>(WTF::WorkQueue::dispatch(WTF::Function<void ()>&&)::$_0)::'lambda'(void*)::__invoke(void*)
17  0x111a8f951 _dispatch_call_block_and_release
18  0x111a908cb _dispatch_client_callout
19  0x111a9660c _dispatch_lane_serial_drain
20  0x111a97044 _dispatch_lane_invoke
21  0x111aa10c4 _dispatch_workloop_worker_thread
22  0x111f17a3d _pthread_wqthread
23  0x111f16b77 start_wqthread

https://build.webkit.org/results/Apple%20iOS%2013%20Simulator%20Debug%20WK2%20(Tests)/r261385%20(3583)/results.html

[Radar WebKit Bug Importer]

<rdar://problem/63031185>

[Sihui Liu]

From the error log, "ERROR: SQLite database failed to set journal_mode to WAL, error: database is locked", it looks like there are conflicted transactions on the same database connection (https://www.sqlite.org/rescode.html#locked). 

As this is regression from r260791(?), it's possible a database connection is not closed properly, e.g. a connection will not be closed if there are unfinalized prepared statements(https://www.sqlite.org/c3ref/close.html).

Looking at r260791, it seems NetworkSession::recreateResourceLoadStatisticStore can be called consecutively, and m_resourceLoadStatistics will be set before task dispatched in WebResourceLoadStatisticsStore::flushAndDestroyPersistentStore is done. Not sure if this is an issue. Maybe verify by waiting in NetworkSession::recreateResourceLoadStatisticStore until the completion handler is called to see if this fixes the issue.

[Sihui Liu]

It may be helpful to add some logging about error code/message around the assertion.

[Kate Cheney]

(In reply to Sihui Liu from comment #2)

Thanks for taking a look at this.

> From the error log, "ERROR: SQLite database failed to set journal_mode to
> WAL, error: database is locked", it looks like there are conflicted
> transactions on the same database connection
> (https://www.sqlite.org/rescode.html#locked). 
> 
> As this is regression from r260791(?), it's possible a database connection
> is not closed properly, e.g. a connection will not be closed if there are
> unfinalized prepared statements(https://www.sqlite.org/c3ref/close.html).
> 

This could definitely be related. The statements are all prepared in ResourceLoadStatisticsDatabaseStore::prepareStatements(), but the unused ones are not finalized before closing.

> Looking at r260791, it seems
> NetworkSession::recreateResourceLoadStatisticStore can be called
> consecutively, and m_resourceLoadStatistics will be set before task
> dispatched in WebResourceLoadStatisticsStore::flushAndDestroyPersistentStore
> is done. Not sure if this is an issue. Maybe verify by waiting in
> NetworkSession::recreateResourceLoadStatisticStore until the completion
> handler is called to see if this fixes the issue.

Isn't this already occurring? m_resourceLoadStatistics is set in the completion handler of destroyResourceLoadStatistics, which gets passed to WebResourceLoadStatisticsStore::flushAndDestroyPersistentStore(), so it won't be set until that has finished.

[Kate Cheney]

Created attachment 399150 [details]
Patch

[Kate Cheney]

Still trying to reproduce to confirm this patch will fix the crashes, letting EWS run in the meantime.

[Kate Cheney]

Created attachment 399206 [details]
Patch

[Kate Cheney]

Still can't reproduce this crash, but this fix makes sense from a performance standpoint (we should not be recreating a memory store between two database tests).

[Kate Cheney]

(In reply to katherine_cheney from comment #8)
> Still can't reproduce this crash, but this fix makes sense from a
> performance standpoint (we should not be recreating a memory store between
> two database tests).

And, after talking with Sihui, I think it will likely fix the crash.

[Kate Cheney]

Created attachment 399263 [details]
Patch

[John Wilander]

Is testRunner.setUseITPDatabase() blocking so that the next statement after it guarantees that ITP is set up accordingly?

[Alex Christensen]

It uses WKWebsiteDataStoreSetUseITPDatabase which is waited for.  The actual implementation might not be waiting for everything it needs to, but waiting is happening.

[Kate Cheney]

(In reply to Alex Christensen from comment #12)
> It uses WKWebsiteDataStoreSetUseITPDatabase which is waited for.  The actual
> implementation might not be waiting for everything it needs to, but waiting
> is happening.

The goal of the patch is to make sure recreateResourceLoadStatisticsStore only gets called once. I don't think the call to setUseITPDatabase() waits for statisticsResetToConsisistentState() to be finished.

[EWS]

Committed r261659: <https://trac.webkit.org/changeset/261659>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 399263 [details].

[Chris Dumez]

Comment on attachment 399263 [details]
Patch

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

> Source/WebKit/UIProcess/API/C/WKWebsiteDataStoreRef.cpp:-663
> -    store.setUseITPDatabase(false, [callbackAggregator = callbackAggregator.copyRef()] { });

This change is wrong and is leading to flakiness in the tests... Now I have tests that give different output whether or not the test that runs right before it called testRunner.setUseITPDatabase(true) or not.

TestController::resetState() needs to resets ALL state. It is NEVER OK to rely on tests to reset state and has historically always led to flakiness. Please fix.

[Kate Cheney]

(In reply to Chris Dumez from comment #15)
> Comment on attachment 399263 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=399263&action=review
> 
> > Source/WebKit/UIProcess/API/C/WKWebsiteDataStoreRef.cpp:-663
> > -    store.setUseITPDatabase(false, [callbackAggregator = callbackAggregator.copyRef()] { });
> 
> This change is wrong and is leading to flakiness in the tests... Now I have
> tests that give different output whether or not the test that runs right
> before it called testRunner.setUseITPDatabase(true) or not.
> 
> TestController::resetState() needs to resets ALL state. It is NEVER OK to
> rely on tests to reset state and has historically always led to flakiness.
> Please fix.

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

Interesting, do you know why the flakiness was happening based on testRunner.setUseITPDatabase(true)? I thought the original implementation seemed more likely to cause flakiness if two database tests were occurring back to back. With the reset-to-memory-store implementation, this would destruct a database store, make a memory store, destruct the memory store, then make a new database store, which did not seem right, and seemed to be contributing to database locking.

[Chris Dumez]

(In reply to katherine_cheney from comment #16)
> (In reply to Chris Dumez from comment #15)
> > Comment on attachment 399263 [details]
> > Patch
> > 
> > View in context:
> > https://bugs.webkit.org/attachment.cgi?id=399263&action=review
> > 
> > > Source/WebKit/UIProcess/API/C/WKWebsiteDataStoreRef.cpp:-663
> > > -    store.setUseITPDatabase(false, [callbackAggregator = callbackAggregator.copyRef()] { });
> > 
> > This change is wrong and is leading to flakiness in the tests... Now I have
> > tests that give different output whether or not the test that runs right
> > before it called testRunner.setUseITPDatabase(true) or not.
> > 
> > TestController::resetState() needs to resets ALL state. It is NEVER OK to
> > rely on tests to reset state and has historically always led to flakiness.
> > Please fix.
> 
> fix: https://bugs.webkit.org/show_bug.cgi?id=212094
> 
> Interesting, do you know why the flakiness was happening based on
> testRunner.setUseITPDatabase(true)? I thought the original implementation
> seemed more likely to cause flakiness if two database tests were occurring
> back to back. With the reset-to-memory-store implementation, this would
> destruct a database store, make a memory store, destruct the memory store,
> then make a new database store, which did not seem right, and seemed to be
> contributing to database locking.

Well, yes I know. The flakiness is happening because the previous test is setting the ITP database to true and the new test is not setting it to false. I know you tried in this patch to update tests to set the ITP database to false but it looks like some were missed. In any case, it is terrible practice to rely on tests to do clean up at the end and will always lead to flakiness, one way or another. TestController::resetState() is the central way of resetting state between tests to avoid flakiness.