Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py CookieTest.test_adding_a_cookie_that_expired_in_the_past | AssertionError: 0 != 1
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Tracking
(firefox67 fixed)
Tracking | Status | |
---|---|---|
firefox67 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: gbrown)
References
Details
(Keywords: intermittent-failure)
Attachments
(1 file)
(deleted),
patch
|
whimboo
:
review+
|
Details | Diff | Splinter Review |
#[markdown(off)]
Filed by: hskupin [at] mozilla.com
https://treeherder.mozilla.org/logviewer.html#?job_id=226972037&repo=try
Comment 1•6 years ago
|
||
The failure might be that the test has wrong assumptions because Fennec runs on a remote host and not localhost:
cookie["expiry"] = calendar.timegm(time.gmtime()) - 1
With that code I assume we simply hit a condition where the datetime in the emulator is different than the one on the host. Maybe we should simply replace -1
with something larger to prevent something like that.
On the other side it could also mean that there is a datetime problem with the x86 emulator.
Geoff, it would be good if we could compare the times.
![]() |
Assignee | |
Comment 2•6 years ago
|
||
Thanks for filing these bugs!
We don't do anything special to set the emulator time, except setting up the avd such that the emulator (should) use the host's time and time zone.
Actual host vs device times can be compared by comparing the test log (from the host) with the logcat (from the emulator).
Test log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=226972037&repo=try&lineNumber=2647-2649
[task 2019-02-07T22:25:36.453Z] 22:25:36 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py CookieTest.test_add_cookie
[task 2019-02-07T22:25:36.643Z] 22:25:36 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py CookieTest.test_add_cookie | took 191ms
[task 2019-02-07T22:25:36.851Z] 22:25:36 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py CookieTest.test_adding_a_cookie_that_expired_in_the_past
Logcat:
Parts that mention "test_cookies.py":
02-07 22:25:33.984 2384 2400 I Gecko : 1549578333984 Marionette DEBUG 646 -> [0,6,"WebDriver:AddCookie",{"cookie":{"path":"/","name":"foo","value":"bar","secure":false}}]
02-07 22:25:33.984 2384 2400 I Gecko : 1549578333984 Marionette DEBUG 646 <- [1,6,null,{"value":null}]
02-07 22:25:33.984 2384 2400 I Gecko : 1549578333984 Marionette DEBUG 646 -> [0,7,"WebDriver:ExecuteScript",{"script":"return document.cookie","newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py","sandbox":"default","line":32}]
...
02-07 22:25:36.504 2384 2400 I Gecko : 1549578336504 Marionette DEBUG 652 <- [1,5,null,{"value":null}]
02-07 22:25:36.504 2384 2400 I Gecko : 1549578336504 Marionette DEBUG 652 -> [0,6,"WebDriver:ExecuteScript",{"script":"document.cookie = arguments[0] + '=set';","newSandbox":true,"args":["key_8372293"],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py","sandbox":"default","line":71}]
02-07 22:25:36.504 2384 2400 I Gecko : 1549578336504 Marionette DEBUG 652 <- [1,6,null,{"value":null}]
02-07 22:25:36.504 2384 2400 I Gecko : 1549578336504 Marionette DEBUG 652 -> [0,7,"WebDriver:GetCookies",{}]
02-07 22:25:36.504 2384 2400 I Gecko : 1549578336504 Marionette DEBUG 652 <- [1,7,null,[{"name":"key_8372293","value":"set","path":"/","domain":"172.17.0.8","secure":false,"httpOnly":false}]]
02-07 22:25:36.514 2384 2400 I Gecko : 1549578336514 Marionette DEBUG 652 -> [0,8,"WebDriver:DeleteAllCookies",{}]
02-07 22:25:36.524 2384 2400 I Gecko : 1549578336524 Marionette DEBUG 652 <- [1,8,null,{"value":null}]
02-07 22:25:36.524 2384 2400 I Gecko : 1549578336524 Marionette DEBUG 652 -> [0,9,"WebDriver:DeleteSession",{}]
02-07 22:25:36.524 2384 2400 I Gecko : 1549578336524 Marionette DEBUG 652 <- [1,9,null,{"value":null}]
02-07 22:25:36.524 2384 2400 I Gecko : 1549578336524 Marionette DEBUG Closed connection 652
It looks like the clocks are similar, but perhaps the device is about 3 seconds behind the host at this point.
Making the test more flexible (allow for 5 seconds difference?) seems like the right solution.
Comment 3•6 years ago
|
||
When we look for test_cookies.py then I see the following in the log:
[task 2019-02-07T22:25:36.453Z] 22:25:36 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py CookieTest.test_add_cookie
The first action this test does is to create a new session:
02-07 22:25:33.924 2384 2400 I Gecko : 1549578333924 Marionette DEBUG 646 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
As you can see we have a difference of about 3s between the Android system running in the emulator and the host system.
For current Android Mn jobs the difference is also there but a bit lower, which doesn't explain why it doesn't currently fail.
Given that this test is about adding an expired cookie I'm even happy to subtract a full day from the current time. With only 5s we would still have some intermittents as I could believe.
![]() |
Assignee | |
Comment 4•6 years ago
|
||
I tried 10 seconds here and got intermittent fails:
Will try larger increments...
Updated•6 years ago
|
Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/78b4a9446213 In Mn test_cookies.py allow for some clock difference between host and device; r=whimboo
![]() |
||
Comment 7•6 years ago
|
||
bugherder |
Updated•6 years ago
|
Updated•6 years ago
|
Updated•2 years ago
|
Comment 8•2 years ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Description
•