Bug 154657 – (Rare) storage/indexeddb/modern/autoincrement-abort.html flaky on mac-wk1

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore Misc.

[Ryan Haddad]

storage/indexeddb/modern/autoincrement-abort.html flaky on mac-wk1

The test is intermittently timing out on mac-wk1

Most recent timeout:
<https://build.webkit.org/builders/Apple%20El%20Capitan%20Release%20WK1%20(Tests)/builds/3755>

Flakiness dashboard:
<http://webkit-test-results.webkit.org/dashboards/flakiness_dashboard.html#showAllRuns=true&tests=storage%2Findexeddb%2Fmodern%2Fautoincrement-abort.html>

--- /Volumes/Data/slave/elcapitan-release-tests-wk1/build/layout-test-results/storage/indexeddb/modern/autoincrement-abort-expected.txt
+++ /Volumes/Data/slave/elcapitan-release-tests-wk1/build/layout-test-results/storage/indexeddb/modern/autoincrement-abort-actual.txt
@@ -1,3 +1,4 @@
+FAIL: Timed out waiting for notifyDone to be called
 This test creates a new database with an objectstore that autoincrements. It then puts some things in that object store, checking the keys that were used. But it then aborts that transaction. Then it opens a new one and puts something in it, double checking that the key generator was reverted when the above transaction was aborted.
 
 On success, you will see a series of "PASS" messages, followed by "TEST COMPLETE".
@@ -16,24 +17,4 @@
 Key used for put was 4
 Key used for put was 5
 Key used for put was 6
-readwrite transaction abort
-Opening readwrite transaction to make sure the key generator had successfully reverted
-Key used for put was 1
-Key used for put was 2
-Key used for put was 3
-Key used for put was 4
-Key used for put was 5
-Key used for put was 6
-readwrite transaction complete
-Opening readwrite transaction to make sure the key generator picks up where it should've left off
-Key used for put was 7
-Key used for put was 8
-Key used for put was 9
-Key used for put was 10
-Key used for put was 11
-Key used for put was 12
-readwrite transaction complete
-PASS successfullyParsed is true
 
-TEST COMPLETE
-

[Brady Eidson]

According to the dashboard, this timeout is fairly rare.

[Brady Eidson]

This is, indeed, rare. It happens on any given bot once every 2-3 weeks.

[Brady Eidson]

This test is super rare, indeed.

Hasn't occurred on a Mac bot since 5/21, which is before my 5/27 date where I expected a lot of tests to be much more reliable due to http://trac.webkit.org/changeset/201461

Occurred on EFL on 5/28 with 201492 :( weird...

[Brady Eidson]

Hasn't occurred on a Mac bot since 6/8, and that was the leaks bot.

The leaks bot timed out and actually gave us a logging dump that I'd implemented a long time ago.

Jumping to the end of the logging dump I see something *very* peculiar:

...
+UniqueIDBDatabaseConnection::didAbortTransaction -  - 140734713535744
+UniqueIDBDatabase::invokeOperationAndTransactionTimer()
+(main) UniqueIDBDatabase::operationAndTransactionTimerFired
+(main) UniqueIDBDatabase::handleDatabaseOperations - There are 1520145168 pending
...

Weird things:
1 - The didAbortTransaction line should have an IDBResourceIdentifier outputted, between the "-  -" dashes. It doesn't.
IDBResourceIdentifier can't actually output *nothing* like that - it's loggingString method has to print brackets. Bizarre.

2 - The transaction identifier - 140734713535744 - is *HUGE*.
Transaction ids start at 0. No way it got that huge.

3 - "handleDatabaseOperations - There are 1520145168 pending"
Nope, nope, nope. No way.

Something is getting into a bonkers state.

[Brady Eidson]

More weirdness in the logs:

+(main) UniqueIDBDatabase::handleDatabaseOperations - There are 1520149760 pending
+UniqueIDBDatabase::handleDatabaseOperations - Popped an operation, now there are 1520149760 pending

Nope - Can't start at a number, pop one off, then have the same number.  o_O

[Brady Eidson]

+IDBOpenDBRequest::onDeleteDatabaseSuccess() - current version is 140734713537488


Nope.

[Brady Eidson]

This hasn't happened on any of the Mac bots in a month.

Closing.