Open Bug 1448484 Opened 4 years ago Updated 2 years ago

Intermittent devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is "Unset" - Got undefined, expected Unset

Categories

(DevTools :: Storage Inspector, defect, P5)

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(2 files, 1 obsolete file)

Filed by: ncsoregi [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=169970387&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/Bn5cQ3Z6TCeHMSNM18Yuyw/runs/0/artifacts/public/logs/live_backing.log

20:07:23     INFO -  131 INFO TEST-START | devtools/client/storage/test/browser_storage_cookies_samesite.js
20:07:24     INFO -  TEST-INFO | started process screenshot
20:07:24     INFO -  TEST-INFO | screenshot: exit 0
20:07:24     INFO -  Buffered messages logged at 20:07:23
20:07:24     INFO -  132 INFO Entering test bound
20:07:24     INFO -  133 INFO Adding a new tab with URL: http://test1.example.org/browser/devtools/client/storage/test/storage-cookies-samesite.html
20:07:24     INFO -  Buffered messages logged at 20:07:24
20:07:24     INFO -  134 INFO Tab added and finished loading
20:07:24     INFO -  135 INFO Found a window: complete
20:07:24     INFO -  136 INFO Opening the storage inspector
20:07:24     INFO -  137 INFO Opening the toolbox
20:07:24     INFO -  138 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://devtools/content/storage/storage.xul" line: 0}]
20:07:24     INFO -  139 INFO Waiting for the stores to update
20:07:24     INFO -  140 INFO Making sure that the toolbox's frame is focused
20:07:24     INFO -  141 INFO Selecting tree item cookies > http://test1.example.org
20:07:24     INFO -  142 INFO "cookies,http://test1.example.org" is already selected, returning.
20:07:24     INFO -  143 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is correct number of rows in cookies > http://test1.example.org -
20:07:24     INFO -  144 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test1{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
20:07:24     INFO -  145 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test2{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
20:07:24     INFO -  146 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test3{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
20:07:24     INFO -  Buffered messages finished
20:07:24    ERROR -  147 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is "Unset" - Got undefined, expected Unset
20:07:24     INFO -  Stack trace:
20:07:24     INFO -  chrome://mochikit/content/browser-test.js:test_is:1280
20:07:24     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:32
20:07:24     INFO -  Not taking screenshot here: see the one that was previously logged
20:07:24    ERROR -  148 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite2 is "Lax" - Got undefined, expected Lax
20:07:24     INFO -  Stack trace:
20:07:24     INFO -  chrome://mochikit/content/browser-test.js:test_is:1280
20:07:24     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:33
20:07:24     INFO -  Not taking screenshot here: see the one that was previously logged
20:07:24    ERROR -  149 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite3 is "Strict" - Got undefined, expected Strict
Over the last 7 days this bug has 30 failures. These happen on windows10-64, windows7-32, linux64-nightly, linux64.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=179543506&repo=autoland&lineNumber=8838

19:40:50    ERROR -  664 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is "Unset" - Got undefined, expected Unset
19:40:50     INFO -  Stack trace:
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:test_is:1285
19:40:50     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:32
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1083
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1074
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:976
19:40:50     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
19:40:50     INFO -  Not taking screenshot here: see the one that was previously logged
19:40:50    ERROR -  665 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite2 is "Lax" - Got undefined, expected Lax
19:40:50     INFO -  Stack trace:
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:test_is:1285
19:40:50     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:33
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1083
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1074
19:40:50     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:976
19:40:50     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
19:40:50     INFO -  Not taking screenshot here: see the one that was previously logged
19:40:50    ERROR -  666 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite3 is "Strict" - Got undefined, expected Strict
Flags: needinfo?(mratcliffe)
We captured this bug and made it debuggable in the Pernosco debugger:
https://pernos.co/debug/WeSzQc6c7vmfckZ8CsVHaA/index.html
Admittedly it may be difficult to debug without actual JS support.
Access details here: https://mana.mozilla.org/wiki/display/TS/Debugging+with+Pernosco
Assignee: nobody → mratcliffe
Status: NEW → ASSIGNED
Flags: needinfo?(mratcliffe)
Comment on attachment 8979498 [details]
Bug 1448484 - Intermittent devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is Unset - Got undefined, expected Unset

https://reviewboard.mozilla.org/r/245670/#review252532

I don't know the storage inspector and its tests very well so I don't understand what onEdit races against. Can you explain the specifics?
In any case, the way we usually go about this is by emitting an event when some action is done in the tool and having tests wait on this event. Much more bullet-proof than waiting for some delay.
I see store-objects-edit is emitted already in the code, couldn't that be used?
Attachment #8979498 - Flags: review?(pbrosset)
(In reply to Patrick Brosset <:pbro> from comment #13)
> Comment on attachment 8979498 [details]
> Bug 1448484 - Intermittent
> devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1
> is Unset - Got undefined, expected Unset
> 
> https://reviewboard.mozilla.org/r/245670/#review252532
> 
> I don't know the storage inspector and its tests very well so I don't
> understand what onEdit races against. Can you explain the specifics?
> In any case, the way we usually go about this is by emitting an event when
> some action is done in the tool and having tests wait on this event. Much
> more bullet-proof than waiting for some delay.
> I see store-objects-edit is emitted already in the code, couldn't that be
> used?

Yes, we usually have an event to say that all the data is loaded. The problem with doing that in the storage inspector is that it is "live" so the data has never all been received. To work around this we set a 200ms timer every time a storage item is received and when a batch of objects finishes arriving we send the stores-update event.

The problem is that if the try servers are busy then there can easily be gaps of 200ms between receiving the cookies... then how many stores-update events should we listen for?

Still, I would like to try to get to the bottom of this particular case... maybe we need to add a new event to show that the table has been updated or move the store-objects-edit event.
Comment on attachment 8979498 [details]
Bug 1448484 - Intermittent devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is Unset - Got undefined, expected Unset

Now I can't even reproduce it, even when running --verify (I tried 10 runs).
Attachment #8979498 - Attachment is obsolete: true
The screenshots show that the Storage Inspector is reporting "There is no data for the selected host" when this happens.
There are a few interesting points of note:
1. Although the screenshot shows an empty storage inspector we report "There is correct number of rows in cookies."
2. The number of cookies is established by counting the items inside the TableWidget.
3. The items inside the TableWidget are set when they are pushed by ui.js::populateTable() and this happens before the "store-objects-updated" event.
4. The label.value property of the cells is being written in all of my testing but it seems that occasionally when we read it we get undefined.

I am beginning to suspect that some kind of silent error could be preventing the label.values being written.
Update:
 There were 44 failures in the last 7 days:
 - 4 failures on linux 32 opt
 - 7 failures on linux 64 opt/pgo
 - 4 failures on osx 10.10
 - 6 failures on windows 7x32 debug/pgo
 - 23 failures on windows 10x64 pgo
Example failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=180908606&repo=mozilla-inbound&lineNumber=11749 

13:45:10    ERROR -  8585 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is "Unset" - Got undefined, expected Unset
13:45:10     INFO -  Stack trace:
13:45:10     INFO -  chrome://mochikit/content/browser-test.js:test_is:1285
13:45:10     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:32
13:45:10     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1083
13:45:10     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1074
13:45:10     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:976
13:45:10     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
13:45:10     INFO -  Not taking screenshot here: see the one that was previously logged
Flags: needinfo?(mratcliffe)
Whiteboard: [stockwell needswork:owner]
Comment on attachment 8983331 [details] [diff] [review]
Skipped browser_storage_cookies_samesite.js for frequent failures on win 10 !debug

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

looks great
Attachment #8983331 - Flags: review?(jmaher) → review+
Keywords: checkin-needed
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by ebalazs@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e498ba8d51d8
disable browser_storage_cookies_samesite.js for frequent failures on win 10 !debug. r=jmaher
Keywords: checkin-needed
Flags: needinfo?(mratcliffe)
https://hg.mozilla.org/mozilla-central/rev/e498ba8d51d8
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 62
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Target Milestone: Firefox 62 → ---
Because I cannot reproduce this locally and looking at the source I don't see how this could happen I think the best thing we can do is add a lot of logging and re-enable the test... we need to find out where this is happening.
Product: Firefox → DevTools
In the last 7 days there have been 30 occurrences, most (19) on Windows 7 32 Opt and pgo. Also occurs on Linux 32& 64 and Os X opt and pgo. 


Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=190169279&repo=mozilla-inbound&lineNumber=3013

03:33:06     INFO -  638 INFO TEST-START | devtools/client/storage/test/browser_storage_cookies_samesite.js
03:33:06     INFO -  TEST-INFO | started process screenshot
03:33:07     INFO -  TEST-INFO | screenshot: exit 0
03:33:07     INFO -  Buffered messages logged at 03:33:06
03:33:07     INFO -  639 INFO Entering test bound
03:33:07     INFO -  640 INFO Adding a new tab with URL: http://test1.example.org/browser/devtools/client/storage/test/storage-cookies-samesite.html
03:33:07     INFO -  641 INFO Tab added and finished loading
03:33:07     INFO -  642 INFO Found a window: complete
03:33:07     INFO -  643 INFO Opening the storage inspector
03:33:07     INFO -  644 INFO Opening the toolbox
03:33:07     INFO -  645 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://devtools/content/storage/index.xul" line: 0}]
03:33:07     INFO -  646 INFO Waiting for the stores to update
03:33:07     INFO -  647 INFO Making sure that the toolbox's frame is focused
03:33:07     INFO -  648 INFO Selecting tree item cookies > http://test1.example.org
03:33:07     INFO -  649 INFO "cookies,http://test1.example.org" is already selected, returning.
03:33:07     INFO -  650 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is correct number of rows in cookies > http://test1.example.org -
03:33:07     INFO -  651 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test1{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
03:33:07     INFO -  652 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test2{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
03:33:07     INFO -  653 INFO TEST-PASS | devtools/client/storage/test/browser_storage_cookies_samesite.js | There is item with name 'test3{9d414cc5-8319-0a04-0586-c0a6ae01670a}test1.example.org{9d414cc5-8319-0a04-0586-c0a6ae01670a}/browser/devtools/client/storage/test/' in cookies > http://test1.example.org -
03:33:07     INFO -  Buffered messages finished
03:33:07    ERROR -  654 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite1 is "Unset" - Got undefined, expected Unset
03:33:07     INFO -  Stack trace:
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:test_is:1305
03:33:07     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:32
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1103
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1094
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:996
03:33:07     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
03:33:07     INFO -  Not taking screenshot here: see the one that was previously logged
03:33:07    ERROR -  655 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite2 is "Lax" - Got undefined, expected Lax
03:33:07     INFO -  Stack trace:
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:test_is:1305
03:33:07     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:33
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1103
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1094
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:996
03:33:07     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
03:33:07     INFO -  Not taking screenshot here: see the one that was previously logged
03:33:07    ERROR -  656 INFO TEST-UNEXPECTED-FAIL | devtools/client/storage/test/browser_storage_cookies_samesite.js | sameSite3 is "Strict" - Got undefined, expected Strict
03:33:07     INFO -  Stack trace:
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:test_is:1305
03:33:07     INFO -  chrome://mochitests/content/browser/devtools/client/storage/test/browser_storage_cookies_samesite.js:null:34
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1103
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1094
03:33:07     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:996
03:33:07     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
03:33:07     INFO -  657 INFO Removing tab.
03:33:07     INFO -  658 INFO Waiting for event: 'TabClose' on [object XULElement].
03:33:07     INFO -  659 INFO Got event: 'TabClose' on [object XULElement].
03:33:07     INFO -  660 INFO Tab removed and finished closing
03:33:07     INFO -  661 INFO Leaving test bound
03:33:07     INFO -  GECKO(3848) | MEMORY STAT | vsize 702MB | vsizeMaxContiguous 653MB | residentFast 210MB | heapAllocated 89MB
03:33:07     INFO -  662 INFO TEST-OK | devtools/client/storage/test/browser_storage_cookies_samesite.js | took 653ms
03:33:07     INFO -  663 INFO checking window state
03:33:07     INFO -  664 INFO TEST-START | devtools/client/storage/test/browser_storage_cookies_tab_navigation.js
03:33:08     INFO -  GECKO(3848) | MEMORY STAT | vsize 711MB | vsizeMaxContiguous 653MB | residentFast 212MB | heapAllocated 89MB
03:33:08     INFO -  665 INFO TEST-OK | devtools/client/storage/test/browser_storage_cookies_tab_navigation.js | took 889ms
Flags: needinfo?(mratcliffe)
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork]
I thought we had disabled this test. I will do that as soon as I get chance.
Flags: needinfo?(mratcliffe)
Comment on attachment 8995467 [details]
Bug 1448484 - Disable browser_storage_cookies_samesite.js due to intermittent failures

https://reviewboard.mozilla.org/r/259902/#review266942
Attachment #8995467 - Flags: review?(mratcliffe) → review+
Pushed by mratcliffe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b9c3e9ffe061
Disable browser_storage_cookies_samesite.js due to intermittent failures r=miker
Assignee: mratcliffe → nobody
Whiteboard: [stockwell disabled][stockwell needswork] → [stockwell disabled]
You need to log in before you can comment on or make changes to this bug.