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

RESOLVED FIXED in Firefox 43

Status

defect
RESOLVED FIXED
5 years ago
Last year

People

(Reporter: RyanVM, Assigned: miker)

Tracking

unspecified
Firefox 43
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox35 wontfix, firefox36- disabled, firefox37+ disabled, firefox38 disabled)

Details

Attachments

(1 attachment)

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
Here's the patch used to simulate the uplift for local debugging:
https://hg.mozilla.org/try/raw-rev/48296352efb7
So this is another patch we need to back out after the fact?
Blocks: 1097666
Flags: needinfo?(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.
Flags: needinfo?(ryanvm)
Joe, can you please help find an owner for this urgent issue?
Flags: needinfo?(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.
Flags: needinfo?(jwalker)
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
Is there any specific reason why this will suddenly be permafailing ? Due to E10S ?
(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
(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.
No longer blocks: 1097666
[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.
Flags: needinfo?(jwalker)
Planning to disable across all trees if I don't hear anything by tomorrow.
Flags: needinfo?(scrapmachines)
Flags: needinfo?(mratcliffe)
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.
Assignee: nobody → mratcliffe
Flags: needinfo?(mratcliffe)
It's debug-only and affects every platform. Not a pgo issue.
(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
I would think you could just build beta35 directly (with the tests re-enabled of course) to test this.
And yes, those mozconfig changes are expected. Those legitimately changes for beta/release.
See Also: → 1118258
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
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.
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
Whiteboard: [test disabled on debug][leave open]
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 :(
Mike, have you had a chance to look into this at all? I'm getting close to disabling this entire directory across the board.
Flags: needinfo?(mratcliffe)
(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.
Flags: needinfo?(mratcliffe)
Severity: blocker → normal
These were fixed and re-enabled in bug 1175850.
Status: NEW → RESOLVED
Closed: 4 years ago
Depends on: 1175850
Resolution: --- → FIXED
Whiteboard: [test disabled on debug][leave open]
Target Milestone: --- → Firefox 43
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.