Closed Bug 982997 Opened 9 years ago Closed 9 years ago

Intermittent browser_storage_dynamic_windows.js | Host http://test1.example.org found | Test timed out | deleted object should have something if an added object does not have anything

Categories

(DevTools :: General, defect)

Product:
DevTools
Component:
General
Version:
28 Branch
Platform:
x86
Windows 8.1
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox29 unaffected, firefox30 fixed, firefox31 fixed, firefox-esr24 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 31
Tracking Flags:
Tracking Status
firefox29 --- unaffected
firefox30 --- fixed
firefox31 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: KWierso, Assigned: Optimizer)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

adding some logging
1.80 KB, patch
jwalker
: review+
Details | Diff | Splinter Review
patch
2.48 KB, patch
jwalker
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=36017040&tree=Mozilla-Inbound
slave: t-w864-ix-061



12:39:46     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for localStorage
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host http://sectest1.example.org found
12:39:46     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for sessionStorage
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host http://sectest1.example.org found
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Atleast some storage types should be present in deleted
12:39:46     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for cookies
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host test1.example.org found
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Item found - c1
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Item found - cs2
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Item found - c3
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Item found - uc1
12:39:46     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for localStorage
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host http://test1.example.org found
12:39:46     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for sessionStorage
12:39:46     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host http://test1.example.org found
12:39:47     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | in stores update of testReload
12:39:47  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | deleted object should have something if an added object does not have anything
12:39:47     INFO -  Stack trace:
12:39:47     INFO -      JS frame :: chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js :: testReload/onStoresUpdate :: line 117
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js :: emit :: line 96
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js :: Front<.onPacket :: line 1055
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm :: DebuggerClient.prototype.onPacket/< :: line 691
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 118
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 43
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 153
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm :: DebuggerClient.prototype.onPacket :: line 733
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/server/transport.js :: LDT_send/< :: line 258
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js :: makeInfallible/< :: line 80
12:39:47     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
12:39:47     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing if new iframe addition works properly
12:39:47     INFO -  ++DOCSHELL 2CBD7AA8 == 84 [pid = 2256] [id = 7975]
12:39:47     INFO -  ++DOMWINDOW == 203 (1B03D928) [pid = 2256] [serial = 20510] [outer = 00000000]
12:39:47     INFO -  ++DOMWINDOW == 204 (1B03FFF0) [pid = 2256] [serial = 20511] [outer = 1B035048]
12:39:47     INFO -  ++DOMWINDOW == 205 (1A6FAD90) [pid = 2256] [serial = 20512] [outer = 1B03D928]
12:39:47     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | checking if the hosts list is correct for this iframe addition
12:39:47     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Atleast some storage types should be present in deleted
12:39:47     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Testing for localStorage
12:39:47  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Host http://test1.example.org found
12:39:47     INFO -  Stack trace:
12:39:47     INFO -      JS frame :: chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js :: markOutMatched :: line 75
12:39:47     INFO -      JS frame :: chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js :: testAddIframe/onStoresUpdate :: line 164
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js :: emit :: line 96
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js :: Front<.onPacket :: line 1055
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm :: DebuggerClient.prototype.onPacket/< :: line 691
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 118
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 43
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 153
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm :: DebuggerClient.prototype.onPacket :: line 733
12:39:47     INFO -      JS frame :: resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/server/transport.js :: LDT_send/< :: line 258
12:39:47     INFO -      JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js :: makeInfallible/< :: line 80
12:39:47     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
12:39:47     INFO -  console.error:
12:39:47     INFO -    Message: TypeError: toBeEmptied[storageType][host] is undefined
12:39:47     INFO -    Stack:
12:39:47     INFO -      markOutMatched@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js:78:1
12:39:47     INFO -  testAddIframe/onStoresUpdate@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js:164:5
12:39:47     INFO -  emit@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js:96:9
12:39:47     INFO -  Front<.onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1055:7
12:39:47     INFO -  DebuggerClient.prototype.onPacket/<@resource://gre/modules/devtools/dbg-client.jsm:691:9
12:39:47     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:118:11
12:39:47     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:43:43
12:39:47     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:153:9
12:39:47     INFO -  DebuggerClient.prototype.onPacket@resource://gre/modules/devtools/dbg-client.jsm:733:1
12:39:47     INFO -  LDT_send/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/server/transport.js:258:11
12:39:47     INFO -  makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:80:7



A little later:



12:40:09     INFO -  --DOMWINDOW == 37 (52CDE478) [pid = 2256] [serial = 20488] [outer = 00000000] [url = http://mochi.test:8888/browser/toolkit/content/tests/browser/data/post_form_inner.sjs]
12:40:09     INFO -  --DOMWINDOW == 36 (52CDA498) [pid = 2256] [serial = 20485] [outer = 00000000] [url = http://mochi.test:8888/browser/toolkit/content/tests/browser/data/post_form_outer.sjs]
12:40:09     INFO -  --DOMWINDOW == 35 (52CE9420) [pid = 2256] [serial = 20487] [outer = 00000000] [url = http://mochi.test:8888/browser/toolkit/content/tests/browser/data/post_form_inner.sjs]
12:40:09     INFO -  --DOMWINDOW == 34 (300CD7B8) [pid = 2256] [serial = 20414] [outer = 00000000] [url = about:blank]
12:40:09     INFO -  --DOMWINDOW == 33 (30090E30) [pid = 2256] [serial = 20408] [outer = 00000000] [url = about:blank]
12:40:09     INFO -  --DOMWINDOW == 32 (43A4A018) [pid = 2256] [serial = 20420] [outer = 00000000] [url = about:blank]
12:40:15  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | Test timed out
12:40:15     INFO -  [Parent 2256] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\m-in-w32-d-0000000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
12:40:15     INFO -  --DOCSHELL 2CBDBD10 == 15 [pid = 2256] [id = 7974]
12:40:15     INFO -  --DOCSHELL 2CBD7AA8 == 14 [pid = 2256] [id = 7975]
12:40:15     INFO -  TEST-INFO | MEMORY STAT vsize after test: 1615290368
12:40:15     INFO -  TEST-INFO | MEMORY STAT vsizeMaxContiguous after test: 1893662720
12:40:15     INFO -  TEST-INFO | MEMORY STAT residentFast after test: 572706816
12:40:15     INFO -  INFO TEST-END | chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_storage_dynamic_windows.js | finished in 30253ms
This is really weird. But I know what exactly is happening. The update packet for reload is coming empty the first time (or I hope so, have to add a but more logging for that) and then the actual update packet for reload is coming at the time of iframe added, (its too much delayed).

Adding a quick one-two liner patch to get more info.
Assignee: nobody → scrapmachines
Status: NEW → ASSIGNED
Just adding some logging to see something.
Attachment #8390669 - Flags: review?(jwalker)
Attachment #8390669 - Attachment is patch: true
Comment on attachment 8390669 [details] [diff] [review]
adding some logging

Review of attachment 8390669 [details] [diff] [review]:
-----------------------------------------------------------------

How are you going to remember to take these out? They could cause significant log spam...
Attachment #8390669 - Flags: review?(jwalker) → review+
I am not going to close this bug until the intermittent is gone :)
You could also just push to try with the extra logging.
I couldn't reproduce it on try :( tried many many retriggers
Keywords: checkin-needed
Whiteboard: [leave-open]
this bug is failing more often on split chunks of browser-chrome while running on ec2:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&showall=1&jobname=Ubuntu%20VM%2012.04%20x64%20mozilla-inbound%20debug%20test%20mochitest-browser-chrome-3

I am not sure if we have a method for doing that on try server.  Next week we are planning to switch from running on hardware to ec2 slaves for the debug browser chrome tests.

Thanks for having a patch/fix for this already.
(In reply to Joel Maher (:jmaher) from comment #11)
> this bug is failing more often on split chunks of browser-chrome while
> running on ec2:
> https://tbpl.mozilla.org/?tree=Mozilla-
> Inbound&showall=1&jobname=Ubuntu%20VM%2012.04%20x64%20mozilla-
> inbound%20debug%20test%20mochitest-browser-chrome-3

This link loads a blank run info for me. Just lists the pushes, no builds or tests.
https://hg.mozilla.org/integration/fx-team/rev/b4c5df7b0c5a
Keywords: checkin-needed
Whiteboard: [leave-open] → [leave-open][fixed-in-fx-team]
sorry Optimizer, you would have needed to scroll down a bit, here is a test log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=36132192&tree=Mozilla-Inbound, from this tbpl push: https://tbpl.mozilla.org/?tree=Mozilla-Inbound&showall=1&jobname=Ubuntu%20VM%2012.04%20x64%20mozilla-inbound%20debug%20test%20mochitest-browser-chrome-3&rev=aa60e2265dde

when this landed patch makes it to inbound we should be able to see if it is fixed or dramatically reduced.
(In reply to Joel Maher (:jmaher) from comment #14)
> sorry Optimizer, you would have needed to scroll down a bit, here is a test
> log:
> https://tbpl.mozilla.org/php/getParsedLog.php?id=36132192&tree=Mozilla-
> Inbound, from this tbpl push:
> https://tbpl.mozilla.org/?tree=Mozilla-
> Inbound&showall=1&jobname=Ubuntu%20VM%2012.04%20x64%20mozilla-
> inbound%20debug%20test%20mochitest-browser-chrome-3&rev=aa60e2265dde
> 
> when this landed patch makes it to inbound we should be able to see if it is
> fixed or dramatically reduced.

The patches are just some extra logging . So nothing should be fixed for now.
Summary: Intermittent browser_storage_dynamic_windows.js | Host http://test1.example.org found | Test timed out → Intermittent browser_storage_dynamic_windows.js | Host http://test1.example.org found | Test timed out | deleted object should have something if an added object does not have anything
Attached patch patch — — Splinter Review 
I think this is the best solution to the problem, given that we cannot speed up slow machines, better not assume that the first update will have at least data.added.

try push : https://tbpl.mozilla.org/?tree=Try&rev=cfae675bbf29
Attachment #8398627 - Flags: review?(jwalker)
Attachment #8398627 - Flags: review?(jwalker) → review+
(lots of intermittent in the try, but all from other tests)
Keywords: checkin-needed
Whiteboard: [leave-open]
https://hg.mozilla.org/mozilla-central/rev/1ef1a2608f45
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 31
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.