Closed Bug 1566214 Opened 5 years ago Closed 2 years ago

Intermittent /xhr/event-load.any.worker.html | XMLHttpRequest: The send() method: Fire an event named load (synchronous flag is unset) - assert_unreached: Didn't get load event within 4ms of readystatechange==4 Reached unreachable code

Categories

(Core :: DOM: Networking, defect, P3)

Product:
Core
Component:
DOM: Networking
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1785347

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [necko-triaged])

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=256581042&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/BRHRq2a6QiS_eXIy6drAuQ/runs/0/artifacts/public/logs/live_backing.log

[task 2019-07-15T20:11:09.236Z] 20:11:09 INFO - TEST-OK | /xhr/event-error.sub.any.html | took 571ms
[task 2019-07-15T20:11:09.236Z] 20:11:09 INFO - TEST-START | /xhr/event-load.any.worker.html
[task 2019-07-15T20:11:09.239Z] 20:11:09 INFO - Closing window 2147483962
[task 2019-07-15T20:11:09.504Z] 20:11:09 INFO -
[task 2019-07-15T20:11:09.504Z] 20:11:09 INFO - TEST-UNEXPECTED-FAIL | /xhr/event-load.any.worker.html | XMLHttpRequest: The send() method: Fire an event named load (synchronous flag is unset) - assert_unreached: Didn't get load event within 4ms of readystatechange==4 Reached unreachable code
[task 2019-07-15T20:11:09.504Z] 20:11:09 INFO - client.onreadystatechange</<@http://web-platform.test:8000/xhr/event-load.any.js:16:7
[task 2019-07-15T20:11:09.505Z] 20:11:09 INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1652:22
[task 2019-07-15T20:11:09.505Z] 20:11:09 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1594:25
[task 2019-07-15T20:11:09.505Z] 20:11:09 INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1618:35
[task 2019-07-15T20:11:09.726Z] 20:11:09 INFO - TEST-OK | /xhr/event-load.any.worker.html | took 489ms
[task 2019-07-15T20:11:10.691Z] 20:11:10 INFO - Closing logging queue
[task 2019-07-15T20:11:10.693Z] 20:11:10 INFO - queue closed
[task 2019-07-15T20:11:10.710Z] 20:11:10 INFO - Setting up ssl
[task 2019-07-15T20:11:10.740Z] 20:11:10 INFO - certutil |
[task 2019-07-15T20:11:10.761Z] 20:11:10 INFO - certutil |
[task 2019-07-15T20:11:10.778Z] 20:11:10 INFO - certutil |
[task 2019-07-15T20:11:10.778Z] 20:11:10 INFO - Certificate Nickname Trust Attributes
[task 2019-07-15T20:11:10.778Z] 20:11:10 INFO - SSL,S/MIME,JAR/XPI
[task 2019-07-15T20:11:10.778Z] 20:11:10 INFO -
[task 2019-07-15T20:11:10.778Z] 20:11:10 INFO - web-platform-tests CT,,
[task 2019-07-15T20:11:10.779Z] 20:11:10 INFO -
[task 2019-07-15T20:11:12.526Z] 20:11:12 INFO - adb Granting important runtime permissions to org.mozilla.geckoview.test
[task 2019-07-15T20:11:14.083Z] 20:11:14 INFO - adb launch_application: am start -W -n org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity -a android.intent.action.MAIN --es env9 MOZ_CRASHREPORTER_NO_REPORT=1 --es env8 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es args "-no-remote -profile /sdcard/tests/profile --marionette about:blank" --es env3 MOZ_HIDE_RESULTS_TABLE=1 --es env2 R_LOG_VERBOSE=1 --es env1 MOZ_WEBRENDER=0 --es env0 MOZ_CRASHREPORTER=1 --es env7 R_LOG_DESTINATION=stderr --es env6 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env5 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4 --es env4 STYLO_THREADS=4 --ez use_multiprocess True --es env11 R_LOG_LEVEL=6 --es env10 MOZ_PROCESS_LOG=/tmp/tmp4p0caNpidlog
[task 2019-07-15T20:11:16.149Z] 20:11:16 INFO - Starting runner
[task 2019-07-15T20:11:16.633Z] 20:11:16 INFO - TEST-START | /xhr/event-load.any.html

depend on time is racy - this is probably a faulty WPT test?

Flags: needinfo?(james)

Yes, it looks highly likely that this test is racy since it puts a 4ms(!) limit on the time to get a load event after readyStateChange fires. Having said that, the spec says to fire an even called readystatechange and then immediately fire an event named load. So I think it's not possible for the event loop to spin between the two events being fired, so a callback setTimeout in the readystatechange handler will always occur after the load event is fired because it can't happen until the event loop spins. If that's correct then the test seems right?

Flags: needinfo?(james)
Priority: P5 → P3
Whiteboard: [necko-triaged]

(In reply to James Graham [:jgraham] from comment #2)

Yes, it looks highly likely that this test is racy since it puts a 4ms(!) limit on the time to get a load event after readyStateChange fires. Having said that, the spec says to fire an even called readystatechange and then immediately fire an event named load. So I think it's not possible for the event loop to spin between the two events being fired, so a callback setTimeout in the readystatechange handler will always occur after the load event is fired because it can't happen until the event loop spins. If that's correct then the test seems right?

Thanks for the explanation. I agree.

Bulk closing some old intermittents.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=378951813&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.