Treeherder Bug Filer Reporter
	Description • 8 years ago
treeherder

Filed by: philringnalda@gmail.com

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

http://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-win32/1467330920/mozilla-inbound_xp_ix_test-web-platform-tests-1-bm112-tests1-windows-build7.txt.gz

	Thomas Wisniewski Assignee
	Comment 1 • 8 years ago

This would have been "caused" by bug 1280454, but I'm not sure why the failure is happening. The three lines of JS in the test that are involved are:

    var lastModified = Math.floor(new Date(client.responseXML.lastModified).getTime() / 1000); // gets 1467336919
    var now = Math.floor(new Date().getTime() / 1000); // gets 1467336918
    assert_less_than_equal(lastModified, now); // fails since 1467336919 <= 1467336918 is false.

The first line ends up calling nsIDocument::GetLastModified, which returns this as the value:
    GetFormattedTimeString(PR_Now(), aLastModified);

I have no idea why the next line of JS would end up getting an earlier time, however. It strikes me as iffy to just fuzz the test to account for this, and I'm not sure who to needinfo to help get to the bottom of this.

And although it's not the actual problem here, I'm not sure if nsIDocument::GetLastModified should even be returning a fresh value every time it's called (if it has not been explicitly set). Should the value not be explicitly set when the document is parsed, rather than returning "now" each time the property is accessed?

	Jonas Sicking (:sicking) No longer reading bugmail consistently
	Comment 2 • 8 years ago

Sounds like the problem here is that calling `PR_Now()` and then calling `new Date().getTime()` can return values where the latter returns an earlier time, despite being called later.

I don't know what the state of the art for timing APIs is in gecko these days. Possibly checking with the JS team is the way to go here. I'd suggest pinging someone in the #jsapi irc channel.

	Boris Zbarsky [:bzbarsky]
	Comment 3 • 8 years ago

> I have no idea why the next line of JS would end up getting an earlier time, however.

Because computers' wall-clock time can run backwards, if nothing else.  This is why we have monotonic clocks like performance.now() that explicitly don't do that.

	Thomas Wisniewski Assignee
	Comment 4 • 8 years ago

Alright, this should be fixed now. I tweaked the test as part of a patch in bug 1286439, as that also had a test that could have the same issue.

	Thomas Wisniewski Assignee
	Comment 7 • 8 years ago

All of those intermittent failures are clock-skew related and off by one, so it should be sufficient to just fuzz the tests a bit more, as per this patch.

> 23:13:53 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1472541232 but got 1472541233 
> 18:20:46 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1472692845 but got 1472692846 
> 11:41:22 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1472931681 but got 1472931682 
> 17:17:49 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1473207468 but got 1473207469 
> 21:11:06 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1473221465 but got 1473221466 
> 23:57:19 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_less_than_equal: expected a number less than or equal to 1473317838 but got 1473317839 
>    
> 13:17:05 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_greater_than_equal: expected a number greater than or equal to 1473452225 but got 1473452224
> 00:09:49 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_greater_than_equal: expected a number greater than or equal to 1472713789 but got 1472713788 
> 13:29:03 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_greater_than_equal: expected a number greater than or equal to 1473024543 but got 1473024542 
> 08:35:29 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/responsexml-document-properties.htm | lastModified set to time of response if no HTTP header provided - assert_greater_than_equal: expected a number greater than or equal to 1473176129 but got 1473176128

	Thomas Wisniewski Assignee
	Comment 8 • 8 years ago

Thanks Anne. Requesting check-in.

	Pulsebot
	Comment 9 • 8 years ago

Pushed by kwierso@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/13e73ff5d5d4
Follow-up: allow more fuzz in the test for clock-skew. r=annevk

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 10 • 8 years ago
bugherder landing

https://hg.mozilla.org/integration/mozilla-inbound/rev/13e73ff5d5d4

	Carsten Book [:Tomcat]
	Comment 11 • 8 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/13e73ff5d5d4

	Ryan VanderMeulen [:RyanVM]
	Comment 12 • 8 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/9f8472060b5e