#[markdown(off)]
Filed by: hskupin [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=226972037&repo=try

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

The failure might be that the test has wrong assumptions because Fennec runs on a remote host and not localhost:

https://searchfox.org/mozilla-central/rev/5e3bffe964110b8d1885b4236b8abd5c94d8f609/testing/marionette/harness/marionette_harness/tests/unit/test_cookies.py#37

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.

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:

https://taskcluster-artifacts.net/HvN4L3IeRQWqwRq9bkS-TQ/0/public/test_info//logcat-emulator-5554.log

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.

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.

I tried 10 seconds here and got intermittent fails:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=3a7b9f04aa09531b9f947b5726f8e9f9d001b4a1

Will try larger increments...

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=fefba8069093e8b94c9a20e98b6d7e2505d8fd73

https://hg.mozilla.org/mozilla-central/rev/78b4a9446213