Closed Bug 1448484 Opened 7 years ago Closed 9 days 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)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, 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)
Status: ASSIGNED → RESOLVED
Closed: 6 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]
Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 6 years ago9 days ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: