Closed Bug 1370132 Opened 3 years ago Closed 8 months ago

Intermittent dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress" | Wrong event! - got "loadend", expected "load" etc

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla72
Tracking Status
firefox-esr68 --- wontfix
firefox70 --- wontfix
firefox71 --- wontfix
firefox72 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Priority: -- → P5
Duplicate of this bug: 1378936
There are 32 failures in the past 7 days. 
Platforms: most of them occur on windows10-64 debug and we have once on opt, and two occurrences on Windows 7 debug.
Recent log failure: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=170653910&lineNumber=14937
Relevant part of the log: 
20:36:29     INFO -  Buffered messages finished
20:36:29    ERROR -  1324 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
20:36:29     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
20:36:29     INFO -      logEvent@dom/base/test/test_bug435425.html:68:3
20:36:29     INFO -      start/xhr.upload.onload@dom/base/test/test_bug435425.html:149:9
20:36:29     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:147:5
20:36:29     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
20:36:29     INFO -      @SimpleTest/SimpleTest.js:676:1
20:36:29     INFO -  1325 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
20:36:29     INFO -  1326 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
20:36:29     INFO -  Not taking screenshot here: see the one that was previously logged
20:36:29    ERROR -  1327 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
:overholt Can you please take a look here?
Flags: needinfo?(overholt)
Next week I'll find someone to investigate. Keeping needinfo.
It looks like we end up in https://searchfox.org/mozilla-central/rev/4114ad2cfcbc511705c7865a4a34741812f9a2a9/dom/xhr/XMLHttpRequestMainThread.cpp#1875 with mProgressSinceLastProgressEvent being false, so we don't fire the progress event.
XMLHttpRequestMainThread::OnProgress is not called, so it doesn't set mProgressSinceLastProgressEvent to true.
(In reply to Peter Van der Beken [:peterv] from comment #47)
> XMLHttpRequestMainThread::OnProgress is not called, so it doesn't set
> mProgressSinceLastProgressEvent to true.

Do you/we know what should set this?
Flags: needinfo?(overholt) → needinfo?(peterv)
Priority: -- → P4
Over the last 7 days there are 33 failures on this bug.
These happen on windows10-64, Windows 7, linux64-qr, linux64-ccov

Here is the latest log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=175754722&lineNumber=14655

Here is a relevant part of that log:

16:29:12    ERROR -  1325 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
16:29:12     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
16:29:12     INFO -      logEvent@dom/base/test/test_bug435425.html:68:3
16:29:12     INFO -      start/xhr.upload.onload@dom/base/test/test_bug435425.html:149:9
16:29:12     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:147:5
16:29:12     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
16:29:12     INFO -      @SimpleTest/SimpleTest.js:676:1
16:29:12     INFO -  1326 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
16:29:12     INFO -  1327 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
16:29:12     INFO -  Not taking screenshot here: see the one that was previously logged
16:29:12    ERROR -  1328 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
16:29:12     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
16:29:12     INFO -      logEvent@dom/base/test/test_bug435425.html:68:3
16:29:12     INFO -      maybeStop@dom/base/test/test_bug435425.html:92:3
16:29:12     INFO -      start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:161:9
16:29:12     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:159:5
16:29:12     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
16:29:12     INFO -      @SimpleTest/SimpleTest.js:676:1
16:29:12     INFO -  1329 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
16:29:12     INFO -  1330 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
16:29:12     INFO -  Not taking screenshot here: see the one that was previously logged
16:29:12    ERROR -  1331 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
16:29:12     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
16:29:12     INFO -      logEvent@dom/base/test/test_bug435425.html:68:3
16:29:12     INFO -      start/xhr.onprogress@dom/base/test/test_bug435425.html:135:7
16:29:12     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:133:3
16:29:12     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
16:29:12     INFO -      @SimpleTest/SimpleTest.js:676:1
16:29:12     INFO -  Not taking screenshot here: see the one that was previously logged
16:29:12    ERROR -  1332 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],progress]!
16:29:12     INFO -      logEvent@dom/base/test/test_bug435425.html:69:3
16:29:12     INFO -      start/xhr.onprogress@dom/base/test/test_bug435425.html:135:7
16:29:12     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:133:3
16:29:12     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
16:29:12     INFO -      @SimpleTest/SimpleTest.js:676:1
16:29:12     INFO -  1333 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong responseText
16:29:12     INFO -  1334 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
16:29:12     INFO -  Not taking screenshot here: see the one that was previously logged
16:29:12    ERROR -  1335 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
16:29:12     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
16:29:12     INFO -      logEvent@dom/base/test/test_bug435425.html:68:3
16:29:12     INFO -      start/xhr.onload@dom/base/test/test_bug435425.html:115:7
16:29:12     INFO -      EventHandlerNonNull*start@dom/base/test/test_bug435425.html:110:3
16:29:12     INFO -      runTest@dom/base/test/test_bug435425.html:413:3
16:29:12     INFO -      @SimpleTest/SimpleTest.js:676:1
16:29:12     INFO -  1336 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],load]!
16:29:12     INFO -  1337 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
16:29:12     INFO -  Not taking screenshot here: see the one that was previously logged
16:29:12    ERROR -  1338 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
Flags: needinfo?(overholt)
Peter's been looking at this.
Assignee: nobody → peterv
Flags: needinfo?(overholt)
Priority: -- → P2
Component: DOM → DOM: Core & HTML

There are 27 total failures i the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-10&endday=2019-07-17&tree=trunk&bug=1370132

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=257030743&repo=autoland&lineNumber=3595

[task 2019-07-17T21:35:31.057Z] 21:35:31 INFO - 721 INFO TEST-START | dom/base/test/test_bug435425.html[task 2019-07-17T21:35:31.077Z] 21:35:31 INFO - 822 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - start/xhr.upload.onload@dom/base/test/test_bug435425.html:148:9
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - 823 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - 824 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - 825 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-17T21:35:31.078Z] 21:35:31 INFO - maybeStop@dom/base/test/test_bug435425.html:91:3
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:160:9
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - 826 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - 827 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - 828 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-17T21:35:31.079Z] 21:35:31 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:7

Flags: needinfo?(peterv)
Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]

Peter, any updates on this?

Flags: needinfo?(peterv)

There are 24 total failures in the last 7 days on android-em-7-0-x86_64 debug and 2 occurences on linux64-shippable-qr opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=258428353&repo=autoland&lineNumber=3472

[task 2019-07-26T01:46:50.668Z] 01:46:50 INFO - 627 INFO TEST-START | dom/base/test/test_bug435425.html
[task 2019-07-26T01:46:50.673Z] 01:46:50 INFO - <snipped 187 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-07-26T01:46:50.674Z] 01:46:50 INFO - Buffered messages logged at 01:46:48
[task 2019-07-26T01:46:50.674Z] 01:46:50 INFO - 628 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],error]!
[task 2019-07-26T01:46:50.674Z] 01:46:50 INFO - 629 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.674Z] 01:46:50 INFO - 630 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event!
[task 2019-07-26T01:46:50.674Z] 01:46:50 INFO - 631 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!

[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - 727 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - Buffered messages finished
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - 728 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - start/xhr.upload.onload@dom/base/test/test_bug435425.html:148:9
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - 729 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - 730 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - 731 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-07-26T01:46:50.687Z] 01:46:50 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - maybeStop@dom/base/test/test_bug435425.html:91:3
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:160:9
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 732 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 733 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 734 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:7
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 735 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],progress]!
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:68:3
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:7
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 736 INFO TEST-PASS | dom/base/test/test_bug435425.html | Progress should increase, got 4097 after 1440
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 737 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong responseText
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 738 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 739 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - start/xhr.onload@dom/base/test/test_bug435425.html:114:7
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 740 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],load]!
[task 2019-07-26T01:46:50.688Z] 01:46:50 INFO - 741 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - 742 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - logEvent@dom/base/test/test_bug435425.html:67:3
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - maybeStop@dom/base/test/test_bug435425.html:91:3
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - start/xhr.onloadend@dom/base/test/test_bug435425.html:126:7
[task 2019-07-26T01:46:50.689Z] 01:46:50 INFO - 743 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!
[task 2019-07-26T01:52:11.106Z] 01:52:11 INFO - 744 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Test timed out.
[task 2019-07-26T01:52:11.106Z] 01:52:11 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-07-26T01:52:11.106Z] 01:52:11 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-07-26T01:52:11.106Z] 01:52:11 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-07-26T01:52:11.106Z] 01:52:11 INFO - 745 INFO TEST-OK | dom/base/test/test_bug435425.html | took 315335ms

Joel, the assignee did not reply, could you redirect this to someone else?

Flags: needinfo?(jmaher)

Peter was looking at this testcase a year ago, lets ask :hsinyi to triage again.

Flags: needinfo?(jmaher) → needinfo?(htsai)

(In reply to Andrew Overholt [:overholt] from comment #49)

(In reply to Peter Van der Beken [:peterv] from comment #47)

XMLHttpRequestMainThread::OnProgress is not called, so it doesn't set
mProgressSinceLastProgressEvent to true.

Do you/we know what should set this?

Hi Nhi, do you know who may have the answer and can help us here? Thank you.

Flags: needinfo?(htsai) → needinfo?(nhnguyen)
Flags: needinfo?(nhnguyen) → needinfo?(kershaw)

I'll keep my eye on this.
The failure rate is not too high now.

Flags: needinfo?(kershaw)

There have been 27 failures in the last 7 days.

Affected platforms are:

android-em-7-0-x86_64 debug
windows10-64-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269549694&repo=autoland&lineNumber=3552

There are 21 total failures in the last 7 days on android-em-7-0-x86_64 debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=270706340&repo=autoland&lineNumber=3538

[task 2019-10-10T16:04:52.060Z] 16:04:52 INFO - 629 INFO TEST-START | dom/base/test/test_bug435425.html
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - <snipped 107 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - Buffered messages logged at 16:04:43
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 630 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],error]!
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 631 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 632 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event!
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 633 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!

[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 729 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - Buffered messages finished
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 730 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - start/xhr.upload.onload@dom/base/test/test_bug435425.html:148:17
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 731 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 732 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 733 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - maybeStop@dom/base/test/test_bug435425.html:91:11
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:160:18
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 734 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 735 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 736 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:15
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 737 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],progress]!
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:68:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:15
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 738 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong responseText
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 739 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 740 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - start/xhr.onload@dom/base/test/test_bug435425.html:114:15
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 741 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],load]!
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 742 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 743 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - maybeStop@dom/base/test/test_bug435425.html:91:11
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - start/xhr.onloadend@dom/base/test/test_bug435425.html:126:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 744 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - 745 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Test timed out.
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - 746 INFO TEST-OK | dom/base/test/test_bug435425.html | took 325928ms

Kershaw, can you please take a look when you're back?

Flags: needinfo?(kershaw)

(In reply to Andreea Pavel [:apavel] from comment #135)

There are 21 total failures in the last 7 days on android-em-7-0-x86_64 debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=270706340&repo=autoland&lineNumber=3538

[task 2019-10-10T16:04:52.060Z] 16:04:52 INFO - 629 INFO TEST-START | dom/base/test/test_bug435425.html
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - <snipped 107 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - Buffered messages logged at 16:04:43
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 630 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],error]!
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 631 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 632 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event!
[task 2019-10-10T16:04:52.064Z] 16:04:52 INFO - 633 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!

[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 729 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - Buffered messages finished
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 730 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - start/xhr.upload.onload@dom/base/test/test_bug435425.html:148:17
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 731 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 732 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - 733 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.072Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - maybeStop@dom/base/test/test_bug435425.html:91:11
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:160:18
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 734 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 735 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 736 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:15
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 737 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],progress]!
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:68:5
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - start/xhr.onprogress@dom/base/test/test_bug435425.html:134:15
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 738 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong responseText
[task 2019-10-10T16:04:52.073Z] 16:04:52 INFO - 739 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 740 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - start/xhr.onload@dom/base/test/test_bug435425.html:114:15
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 741 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],load]!
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 742 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 743 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - logEvent@dom/base/test/test_bug435425.html:67:5
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - maybeStop@dom/base/test/test_bug435425.html:91:11
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - start/xhr.onloadend@dom/base/test/test_bug435425.html:126:16
[task 2019-10-10T16:04:52.074Z] 16:04:52 INFO - 744 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - 745 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Test timed out.
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-10-10T16:10:10.762Z] 16:10:10 INFO - 746 INFO TEST-OK | dom/base/test/test_bug435425.html | took 325928ms

Kershaw, can you please take a look when you're back?

I'll try to fix this next week.

Flags: needinfo?(kershaw)

Thank you.

The failed log below shows that the progress event happens at the wrong time, which is after loadend event. Still have no clue about this.

[task 2019-10-24T15:14:21.395Z] 15:14:21     INFO -  384 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-24T15:14:21.395Z] 15:14:21     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-24T15:14:21.395Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:69:5
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      start/xhr.upload.onload@dom/base/test/test_bug435425.html:150:17
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  385 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],load]!
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  386 INFO testCount=24, evt.type=loadend, currentEvents.type=load
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  387 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  388 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:69:5
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      maybeStop@dom/base/test/test_bug435425.html:93:11
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      start/xhr.upload.onloadend@dom/base/test/test_bug435425.html:162:18
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  389 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequestUpload],loadend]!
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  390 INFO testCount=24, evt.type=progress, currentEvents.type=loadend
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  391 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -  392 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "progress", expected "loadend"
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-24T15:14:21.396Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:69:5
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -      start/xhr.onprogress@dom/base/test/test_bug435425.html:136:15
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -  393 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],progress]!
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:70:5
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -      start/xhr.onprogress@dom/base/test/test_bug435425.html:136:15
[task 2019-10-24T15:14:21.397Z] 15:14:21     INFO -  394 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong responseText
[task 2019-10-24T15:14:21.398Z] 15:14:21     INFO -  395 INFO testCount=24, evt.type=load, currentEvents.type=progress
[task 2019-10-24T15:14:21.398Z] 15:14:21     INFO -  396 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  397 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "load", expected "progress"
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:69:5
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      start/xhr.onload@dom/base/test/test_bug435425.html:116:15
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  398 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],load]!
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  399 INFO testCount=24, evt.type=loadend, currentEvents.type=load
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  400 INFO TEST-PASS | dom/base/test/test_bug435425.html | Extra or wrong event?
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  401 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Wrong event! - got "loadend", expected "load"
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      logEvent@dom/base/test/test_bug435425.html:69:5
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      maybeStop@dom/base/test/test_bug435425.html:93:11
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -      start/xhr.onloadend@dom/base/test/test_bug435425.html:128:16
[task 2019-10-24T15:14:21.399Z] 15:14:21     INFO -  402 INFO TEST-PASS | dom/base/test/test_bug435425.html | Wrong event target [[object XMLHttpRequest],loadend]!
[task 2019-10-24T15:19:12.735Z] 15:19:12     INFO -  403 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug435425.html | Test timed out.

I think I've figured out the root cause of this.

  1. This test dom/base/test/test_bug435425.html expects that we should get a progress event after loadstart but we get load instead.
  2. The progress event is triggered at XMLHttpRequestMainThread::OnProgress and the load event is at XMLHttpRequestMainThread::OnStartRequest.
  3. Which means that HttpChannelChild::OnProgress should be called before HttpChannelChild::DoOnStartRequest.
  4. In parent process, the log did shows that HttpChannelParent::OnProgress happened before HttpChannelParent::OnStartRequest.
  5. The problem is that OnProgress event is dispatched to background thread and sent by PBackground and OnStartRequest is sent on main thread. So, this could cause that child process get OnStartRequest before OnProgress.

I think maybe we should send OnProgress and OnStatus IPC events by main thread to make sure the event order is not changed.
We can also save one time event dispatch since HttpChannelChild::OnProgress and HttpChannelChild::OnStatus are expected to be called on main thread.
Honza, what do you think?

Flags: needinfo?(peterv) → needinfo?(honzab.moz)

If the final consumer is on the main thread, then there is no need to send via PBck to a bck thread. Yes, I agree with what you suggest. Let's try how it goes, but please make sure, or at least keep an eye on, that there is no major perf regression with this. You know that adhoc reordering of events may always break stuff.

Thanks!

Flags: needinfo?(honzab.moz)

Set the correct component for this bug and take this from Peter.

Assignee: peterv → kershaw
Component: DOM: Core & HTML → DOM: Networking
Whiteboard: [stockwell unknown] → [stockwell unknown][necko-triaged]
Pushed by btara@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/582ee0d10d0c
Refactor how we send OnStatus and OnProgress events r=mayhemer
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla72 → ---
Pushed by kjang@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6f4bbb1c5e93
Refactor how we send OnStatus and OnProgress events r=mayhemer
Flags: needinfo?(kershaw)
Status: REOPENED → RESOLVED
Closed: 8 months ago8 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72
You need to log in before you can comment on or make changes to this bug.