1105803 - browser_storage_basic.js is going to permafail on debug builds when Gecko 35 merges from Aurora to Beta tomorrow

Status: RESOLVED FIXED

(DevTools :: Storage Inspector, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=53579973&tree=Try

22:17:59     INFO -  1 INFO checking window state
22:17:59     INFO -  2 INFO TEST-START | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js
22:17:59     INFO -  JavaScript strict warning: chrome://mochikit/content/tests/SimpleTest/TestRunner.js, line 275: ReferenceError: reference to undefined property message.level
22:18:02     INFO -  JavaScript strict warning: chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js, line 215: ReferenceError: reference to undefined property x.SpecialPowers_wrappedObject
22:18:07     INFO -  --DOCSHELL 10858C00 == 12 [pid = 2360] [id = 5]
22:18:14     INFO -  --DOMWINDOW == 30 (13EC2200) [pid = 2360] [serial = 19] [outer = 00000000] [url = about:blank]
22:18:14     INFO -  --DOMWINDOW == 29 (10895800) [pid = 2360] [serial = 9] [outer = 00000000] [url = about:blank]
22:18:14     INFO -  --DOMWINDOW == 28 (0CD80000) [pid = 2360] [serial = 2] [outer = 00000000] [url = about:blank]
22:18:14     INFO -  --DOMWINDOW == 27 (10894000) [pid = 2360] [serial = 8] [outer = 00000000] [url = about:blank]
22:18:19     INFO -  --DOMWINDOW == 26 (15501800) [pid = 2360] [serial = 26] [outer = 00000000] [url = about:blank]
22:18:19     INFO -  --DOMWINDOW == 25 (11BA7400) [pid = 2360] [serial = 13] [outer = 00000000] [url = about:blank]
22:18:19     INFO -  --DOMWINDOW == 24 (10811400) [pid = 2360] [serial = 12] [outer = 00000000] [url = about:blank]
22:18:27     INFO -  1417069107483	Browser.Experiments.Experiments	TRACE	Experiments #0::enabled=true, true
22:18:27     INFO -  1417069107487	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering instance with Addon Manager.
22:18:27     INFO -  1417069107488	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering previous experiment add-on provider.
22:18:27     INFO -  1417069107489	Browser.Experiments.Experiments	TRACE	PreviousExperimentProvider #0::startup()
22:18:27     INFO -  1417069107492	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadFromCache
22:18:27     INFO -  1417069107510	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadTask finished ok
22:18:27     INFO -  1417069107510	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
22:18:27     INFO -  1417069107512	Browser.Experiments.Experiments	TRACE	Experiments #0::_main iteration
22:18:27     INFO -  1417069107512	Browser.Experiments.Experiments	TRACE	Experiments #0::_evaluateExperiments
22:18:27     INFO -  1417069107519	Browser.Experiments.Experiments	TRACE	Experiments #0::_main finished, scheduling next run
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0xf76aef0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0xf76aef0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0xf76aef0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0xf76aef0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0xf76aef0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840ae0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840ae0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:18:59     INFO -  [2360] WARNING: 1 sort operation has occurred for the SQL statement '0x10840bb0'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
22:19:30     INFO -  TEST-INFO | screenshot: exit status 0
22:19:30     INFO -  3 INFO Adding a new tab with URL: 'http://test1.example.org/browser/browser/devtools/storage/test/storage-listings.html'
22:19:30     INFO -  4 INFO Console message: [JavaScript Warning: "ReferenceError: reference to undefined property params.referrerURI" {file: "chrome://browser/content/tabbrowser.xml" line: 1521}]
22:19:30     INFO -  5 INFO Console message: [JavaScript Warning: "ReferenceError: reference to undefined property message.level" {file: "chrome://mochikit/content/tests/SimpleTest/TestRunner.js" line: 275}]
22:19:30     INFO -  6 INFO URL 'http://test1.example.org/browser/browser/devtools/storage/test/storage-listings.html' loading complete
22:19:30     INFO -  7 INFO Opening the storage inspector
22:19:30     INFO -  8 INFO Opening the toolbox
22:19:30     INFO -  9 INFO Console message: [JavaScript Warning: "XUL box for vbox element contained an inline label child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/devtools/storage.xul" line: 0}]
22:19:30     INFO -  10 INFO Waiting for the stores to update
22:19:30     INFO -  11 INFO Making sure that the toolbox's frame is focused
22:19:30     INFO -  12 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item cookies,test1.example.org should be present in the storage tree
22:19:30     INFO -  13 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item cookies,sectest1.example.org should be present in the storage tree
22:19:30     INFO -  14 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item localStorage,http://test1.example.org should be present in the storage tree
22:19:30     INFO -  15 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item localStorage,http://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  16 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item localStorage,https://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  17 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item sessionStorage,http://test1.example.org should be present in the storage tree
22:19:30     INFO -  18 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item sessionStorage,http://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  19 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item sessionStorage,https://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  20 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org should be present in the storage tree
22:19:30     INFO -  21 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org,idb1 should be present in the storage tree
22:19:30     INFO -  22 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org,idb2 should be present in the storage tree
22:19:30     INFO -  23 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org,idb1,obj1 should be present in the storage tree
22:19:30     INFO -  24 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org,idb1,obj2 should be present in the storage tree
22:19:30     INFO -  25 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://test1.example.org,idb2,obj3 should be present in the storage tree
22:19:30     INFO -  26 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,http://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  27 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,https://sectest1.example.org should be present in the storage tree
22:19:30     INFO -  28 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,https://sectest1.example.org,idb-s1 should be present in the storage tree
22:19:30     INFO -  29 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,https://sectest1.example.org,idb-s2 should be present in the storage tree
22:19:30     INFO -  30 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,https://sectest1.example.org,idb-s1,obj-s1 should be present in the storage tree
22:19:30     INFO -  31 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Tree item indexedDB,https://sectest1.example.org,idb-s2,obj-s2 should be present in the storage tree
22:19:30     INFO -  32 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Table item c1 should be present
22:19:30     INFO -  33 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Table item cs2 should be present
22:19:30     INFO -  34 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Table item c3 should be present
22:19:30     INFO -  35 INFO TEST-PASS | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Table item uc1 should be present
22:19:30     INFO -  36 INFO Console message: [JavaScript Warning: "XUL box for h1 element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://global/content/bindings/popup.xml" line: 50}]
22:19:30     INFO -  37 INFO Console message: [JavaScript Warning: "ReferenceError: reference to undefined property x.SpecialPowers_wrappedObject" {file: "chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js" line: 215}]
22:19:30     INFO -  38 INFO Console message: 1417069107483	Browser.Experiments.Experiments	TRACE	Experiments #0::enabled=true, true
22:19:30     INFO -  39 INFO Console message: 1417069107487	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering instance with Addon Manager.
22:19:30     INFO -  40 INFO Console message: 1417069107488	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering previous experiment add-on provider.
22:19:30     INFO -  41 INFO Console message: 1417069107489	Browser.Experiments.Experiments	TRACE	PreviousExperimentProvider #0::startup()
22:19:30     INFO -  42 INFO Console message: 1417069107492	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadFromCache
22:19:30     INFO -  43 INFO Console message: 1417069107510	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadTask finished ok
22:19:30     INFO -  44 INFO Console message: 1417069107510	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
22:19:30     INFO -  45 INFO Console message: 1417069107512	Browser.Experiments.Experiments	TRACE	Experiments #0::_main iteration
22:19:30     INFO -  46 INFO Console message: 1417069107512	Browser.Experiments.Experiments	TRACE	Experiments #0::_evaluateExperiments
22:19:30     INFO -  47 INFO Console message: 1417069107519	Browser.Experiments.Experiments	TRACE	Experiments #0::_main finished, scheduling next run
22:19:30     INFO -  48 INFO Console message: 1417069138986	Services.HealthReport.HealthReporter	WARN	Saved state file does not exist.
22:19:30     INFO -  49 INFO Console message: 1417069138987	Services.HealthReport.HealthReporter	WARN	No prefs data found.
22:19:30     INFO -  50 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | Test timed out - expected PASS
22:19:30     INFO -  --DOCSHELL 15B67400 == 11 [pid = 2360] [id = 12]
22:19:30     INFO -  --DOCSHELL 16C86000 == 10 [pid = 2360] [id = 13]
22:19:30     INFO -  [2360] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:/builds/moz2_slave/try-w32-d-00000000000000000000/build/src/netwerk/base/src/nsSimpleURI.cpp, line 265
22:19:30     INFO -  51 INFO TEST-OK | chrome://mochitests/content/browser/browser/devtools/storage/test/browser_storage_basic.js | took 90328ms

Comment 1

[Ryan VanderMeulen [:RyanVM]]

Here's the patch used to simulate the uplift for local debugging:
https://hg.mozilla.org/try/raw-rev/48296352efb7

Comment 2

[[e-mail] (:bhearsum)]

So this is another patch we need to back out after the fact?

Comment 3

[Ryan VanderMeulen [:RyanVM]]

We're either going to need to get a fix landed on Trunk and Aurora today or we'll have to disable the test when it starts failing on Beta tomorrow.

Comment 4

[Ryan VanderMeulen [:RyanVM]]

Joe, can you please help find an owner for this urgent issue?

Comment 5

[Joe Walker [:jwalker]]

Will try to find an owner, but this isn't a problem that I think we can fix before tomorrow, so I think disabling the test is out best bet right now.

Comment 6

[Ryan VanderMeulen [:RyanVM]]

Thanks for the reply, Joe. With some testing on Try, I've verified that the only quick way to green is to disable the entire directory on debug builds.

Ben, I've gone ahead and disabled the tests on Aurora so you won't have to worry about it tomorrow amongst everything else going on.
https://hg.mozilla.org/releases/mozilla-aurora/rev/ce8e174af2f2

Comment 7

[Girish Sharma [:Optimizer]]

Is there any specific reason why this will suddenly be permafailing ? Due to E10S ?

Comment 8

[Joe Walker [:jwalker]]

(In reply to Girish Sharma [:Optimizer] from comment #7)
> Is there any specific reason why this will suddenly be permafailing ? Due to
> E10S ?

e10s is off in beta and aurora, so I don't see how that can be the cause. Whatever it is is caused by the patch in comment 1 [1], which looks like mostly obvious version number, channel changes that you'd expect in the merge aurora->beta. The only non-obvious change was some PGO additions (but it looks from comment 6 that this is debug only).

Paul and I looked through the tests that were failing and couldn't easily trace back to a route cause. My best guess was that we weren't processing updates as expected, possibly due to a timing issue, but it was fairly quickly obvious that a fix wasn't going to happen in a few hours, so I didn't spend a long time on it.

[1]: https://hg.mozilla.org/try/raw-rev/48296352efb7

Comment 9

[[e-mail] (:bhearsum)]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #6)
> Thanks for the reply, Joe. With some testing on Try, I've verified that the
> only quick way to green is to disable the entire directory on debug builds.
> 
> Ben, I've gone ahead and disabled the tests on Aurora so you won't have to
> worry about it tomorrow amongst everything else going on.
> https://hg.mozilla.org/releases/mozilla-aurora/rev/ce8e174af2f2

Thanks Ryan, much appreciated. Unblocking this from the merge bug, in that case.

Comment 10

[Ryan VanderMeulen [:RyanVM]]

[Tracking Requested - why for this release]: Permafail on merge day.

This affects later versions too as confirmed by my most recent uplift simulations on Try. Should I just disable these tests across all releases until someone has time to look into them? I'm not interested in doing this every 6 weeks indefinitely.

Comment 11

[Ryan VanderMeulen [:RyanVM]]

Planning to disable across all trees if I don't hear anything by tomorrow.

Comment 12

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

Optimizer: please feel free to look at this too and post your findings in this bug.

I will take a look as I need to get familiar with this source to remote it and get it E10S ready anyhow.

Here's hoping that this isn't a PGO error.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

It's debug-only and affects every platform. Not a pgo issue.

Comment 14

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

Attachment: Patch which should reproduce the problem

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #13)
> It's debug-only and affects every platform. Not a pgo issue.

Applying this rebased patch to a debug build and running the test works fine locally.

Seems like at some point his has been added to the mozconfigs:
  ac_add_options --enable-profiling

And this has been removed:
  ac_add_options --disable-elf-hack

Maybe that is why it now runs fine locally?

Try:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=636484d39a80
https://tbpl.mozilla.org/?tree=Try&rev=636484d39a80

Comment 15

[Ryan VanderMeulen [:RyanVM]]

I would think you could just build beta35 directly (with the tests re-enabled of course) to test this.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

And yes, those mozconfig changes are expected. Those legitimately changes for beta/release.

Comment 17

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=39512bf5ca89

Comment 18

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

Test runs fine on a local debug build of beta 35.

Pushing to try to try to find out what is going on... I strongly suspect a race condition:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=81118d5938ed
https://tbpl.mozilla.org/?tree=Try&rev=81118d5938ed

Comment 19

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

Seems like head.js uses scrollIntoView, which is async enough to fail on a loaded server... it is even worse on E10S builds:

```
// Sends a click event on the passed DOM node in an async manner
function click(node) {
  node.scrollIntoView()
  executeSoon(() => EventUtils.synthesizeMouseAtCenter(node, {}, gPanelWindow));
}
```

I have previously logged bug 1052109 about adding a "scrolled" event. I will take a quick look at our scrollIntoView() implementation and see if there is something we can do.

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Sorry, we're too close to the uplift. I'm disabling them for now. We can certainly re-enable them once you fix them up.
https://hg.mozilla.org/integration/fx-team/rev/866d1d62ea5c

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ffea282847b2

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/866d1d62ea5c

Comment 23

[Ryan VanderMeulen [:RyanVM]]

My latest Try run says this is failing on opt builds as well now starting with Gecko 38. Guess I'll need to disable it there as well soon :(

Comment 24

[Ryan VanderMeulen [:RyanVM]]

Mike, have you had a chance to look into this at all? I'm getting close to disabling this entire directory across the board.

Comment 25

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #24)
> Mike, have you had a chance to look into this at all? I'm getting close to
> disabling this entire directory across the board.

I am on vacation until Tuesday 10 Feb so I won't get chance to look at it until then. I am going to be working on the storage inspector when I get back but you are welcome to disable the tests and I will re-enable them when I have a fix.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

Disabled on Beta38.
https://hg.mozilla.org/releases/mozilla-beta/rev/b4b774124dee

Comment 27

[Ryan VanderMeulen [:RyanVM]]

These were fixed and re-enabled in bug 1175850.