Closed Bug 1283720 Opened 4 years ago Closed 3 years ago

Intermittent /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 1467336918 but got 1467336919

Categories

(Testing :: web-platform-tests, defect)

Version 3
defect
Not set

Tracking

(firefox50 fixed, firefox51 fixed)

RESOLVED FIXED
mozilla51
Tracking Status
firefox50 --- fixed
firefox51 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: wisniewskit)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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?
Flags: needinfo?(jonas)
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.
Flags: needinfo?(jonas)
> 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.
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.
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
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
Assignee: nobody → wisniewskit
Status: RESOLVED → REOPENED
Attachment #8790272 - Flags: review?(annevk)
Resolution: FIXED → ---
Attachment #8790272 - Flags: review?(annevk) → review+
Thanks Anne. Requesting check-in.
Keywords: checkin-needed
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
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/13e73ff5d5d4
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla51
You need to log in before you can comment on or make changes to this bug.