Closed Bug 1821047 Opened 2 years ago Closed 1 year ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any<random test> | single tracking bug

Categories

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

defect

Tracking

()

RESOLVED INCOMPLETE
Tracking Status
firefox-esr102 --- unaffected
firefox110 --- unaffected
firefox111 --- unaffected
firefox112 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

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

Attachments

(1 file, 1 obsolete file)

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=408273436&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eDH2GFOeQrysC-N5GHmZ4A/runs/0/artifacts/public/logs/live_backing.log


[task 2023-03-08T13:15:56.483Z] 13:15:56     INFO - TEST-PASS | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.sharedworker.html?wpt_flags=h2 | bufferedAmount should not be updated during a sync XHR 
[task 2023-03-08T13:15:56.483Z] 13:15:56     INFO - TEST-UNEXPECTED-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.worker.html?wpt_flags=h2 | bufferedAmount should not be updated during a sync XHR - Test timed out
[task 2023-03-08T13:15:56.484Z] 13:15:56  WARNING - wptserve (38c5274b) Unexpected Error - 
[task 2023-03-08T13:15:56.484Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.487Z] 13:15:56  WARNING - wptserve (860124d1) Unexpected Error - 
[task 2023-03-08T13:15:56.487Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.488Z] 13:15:56  WARNING - wptserve (81256e90) Unexpected Error - 
[task 2023-03-08T13:15:56.488Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.489Z] 13:15:56  WARNING - wptserve (f8f6b77b) Unexpected Error - 
[task 2023-03-08T13:15:56.489Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.491Z] 13:15:56  WARNING - wptserve (a068b45a) Unexpected Error - 
[task 2023-03-08T13:15:56.491Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.494Z] 13:15:56  WARNING - wptserve (30f474d9) Unexpected Error - 
[task 2023-03-08T13:15:56.494Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.498Z] 13:15:56  WARNING - wptserve (5bcaf842) Unexpected Error - 
[task 2023-03-08T13:15:56.498Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.500Z] 13:15:56  WARNING - wptserve (aca54de9) Unexpected Error - 
[task 2023-03-08T13:15:56.500Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.502Z] 13:15:56  WARNING - wptserve (249772f2) Unexpected Error - 
[task 2023-03-08T13:15:56.502Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.504Z] 13:15:56  WARNING - wptserve (9b63c01b) Unexpected Error - 
[task 2023-03-08T13:15:56.504Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.506Z] 13:15:56  WARNING - wptserve (0771f3a5) Unexpected Error - 
[task 2023-03-08T13:15:56.506Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - wptserve (c430dbdb) Unexpected Error - 
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - wptserve (730b426f) Unexpected Error - 
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - wptserve (db5cbcd4) Unexpected Error - 
[task 2023-03-08T13:15:56.512Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.514Z] 13:15:56  WARNING - wptserve (37262221) Unexpected Error - 
[task 2023-03-08T13:15:56.514Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.516Z] 13:15:56  WARNING - wptserve (235ce423) Unexpected Error - 
[task 2023-03-08T13:15:56.516Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.521Z] 13:15:56  WARNING - wptserve (9379ec7e) Unexpected Error - 
[task 2023-03-08T13:15:56.521Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.524Z] 13:15:56  WARNING - wptserve (9f2313f4) Unexpected Error - 
[task 2023-03-08T13:15:56.524Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.525Z] 13:15:56  WARNING - wptserve (4064b213) Unexpected Error - 
[task 2023-03-08T13:15:56.525Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.530Z] 13:15:56  WARNING - wptserve (b6c49f59) Unexpected Error - 
[task 2023-03-08T13:15:56.530Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.530Z] 13:15:56  WARNING - wptserve (1b7800ab) Unexpected Error - 
[task 2023-03-08T13:15:56.530Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.532Z] 13:15:56  WARNING - wptserve (78d61339) Unexpected Error - 
[task 2023-03-08T13:15:56.532Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.533Z] 13:15:56  WARNING - wptserve (74c7af8b) Unexpected Error - 
[task 2023-03-08T13:15:56.533Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.538Z] 13:15:56  WARNING - wptserve (1dbb2d1a) Unexpected Error - 
[task 2023-03-08T13:15:56.538Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.540Z] 13:15:56  WARNING - wptserve (e811262d) Unexpected Error - 
[task 2023-03-08T13:15:56.540Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.542Z] 13:15:56  WARNING - wptserve (74e35236) Unexpected Error - 
[task 2023-03-08T13:15:56.542Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.546Z] 13:15:56  WARNING - wptserve (e256ca36) Unexpected Error - 
[task 2023-03-08T13:15:56.546Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.547Z] 13:15:56  WARNING - wptserve (9418f8c8) Unexpected Error - 
[task 2023-03-08T13:15:56.547Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.549Z] 13:15:56  WARNING - wptserve (b1d0f501) Unexpected Error - 
[task 2023-03-08T13:15:56.549Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.551Z] 13:15:56  WARNING - wptserve (f46ea59a) Unexpected Error - 
[task 2023-03-08T13:15:56.551Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.554Z] 13:15:56  WARNING - wptserve (26bd6aec) Unexpected Error - 
[task 2023-03-08T13:15:56.554Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.556Z] 13:15:56  WARNING - wptserve (b5c32910) Unexpected Error - 
[task 2023-03-08T13:15:56.556Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.558Z] 13:15:56  WARNING - wptserve (d158ca13) Unexpected Error - 
[task 2023-03-08T13:15:56.558Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.560Z] 13:15:56  WARNING - wptserve (b066bcfe) Unexpected Error - 
[task 2023-03-08T13:15:56.560Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.561Z] 13:15:56     INFO - TEST-KNOWN-INTERMITTENT-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.worker.html?wpt_flags=h2 | took 30917ms
[task 2023-03-08T13:15:56.565Z] 13:15:56  WARNING - wptserve (2f998b47) Unexpected Error - 
[task 2023-03-08T13:15:56.565Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.565Z] 13:15:56  WARNING - wptserve (97426e46) Unexpected Error - 
[task 2023-03-08T13:15:56.565Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
<...>
[task 2023-03-08T13:15:56.776Z] 13:15:56  WARNING - wptserve (879ecf96) Unexpected Error - 
[task 2023-03-08T13:15:56.776Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.778Z] 13:15:56  WARNING - wptserve (c7d8a625) Unexpected Error - 
[task 2023-03-08T13:15:56.778Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:56.985Z] 13:15:56     INFO - STDOUT: cleanup aborted: Unable to remount device
[task 2023-03-08T13:15:57.099Z] 13:15:57     INFO - STDOUT: cleanup aborted: Unable to remount device
[task 2023-03-08T13:15:57.101Z] 13:15:57     INFO - Closing logging queue
[task 2023-03-08T13:15:57.101Z] 13:15:57     INFO - queue closed
[task 2023-03-08T13:15:57.112Z] 13:15:57     INFO - Setting up ssl
[task 2023-03-08T13:15:57.132Z] 13:15:57     INFO - certutil | b''
[task 2023-03-08T13:15:57.152Z] 13:15:57     INFO - certutil | b''
[task 2023-03-08T13:15:57.165Z] 13:15:57     INFO - certutil | b'\nCertificate Nickname                                         Trust Attributes\n                                                             SSL,S/MIME,JAR/XPI\n\nweb-platform-tests                                           CT,, \n'
[task 2023-03-08T13:15:57.764Z] 13:15:57     INFO - adb Granting important runtime permissions to org.mozilla.geckoview.test_runner
[task 2023-03-08T13:15:58.993Z] 13:15:58     INFO - adb launch_application: am start -W -n org.mozilla.geckoview.test_runner/org.mozilla.geckoview.test_runner.TestRunnerActivity -a android.intent.action.MAIN --es env0 MOZ_CRASHREPORTER=1 --es env1 MOZ_CRASHREPORTER_NO_REPORT=1 --es env2 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env3 MOZ_HIDE_RESULTS_TABLE=1 --es env4 MOZ_IN_AUTOMATION=1 --es env5 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4 --es env6 R_LOG_LEVEL=6 --es env7 R_LOG_DESTINATION=stderr --es env8 R_LOG_VERBOSE=1 --es env9 MOZ_PROCESS_LOG=/tmp/tmp6tj1_ro3pidlog --es env10 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env11 STYLO_THREADS=1 --es arg0 -no-remote --es arg1 -profile --es arg2 /data/local/tmp/test_root/profile --es arg3 --marionette --es arg4 about:blank --ez use_multiprocess True
[task 2023-03-08T13:16:00.331Z] 13:16:00     INFO - Starting runner
[task 2023-03-08T13:16:03.217Z] 13:16:03     INFO - TEST-START | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.sharedworker.html
[task 2023-03-08T13:16:05.225Z] 13:16:05     INFO - TEST-OK | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.sharedworker.html | took 2008ms
See Also: → 1821067
See Also: → 1821132
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.worker.html?wpt_flags=h2 | bufferedAmount should not be updated during a sync XHR - Test timed out → Intermittent TEST-UNEXPECTED-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any<random test> | single tracking bug
Duplicate of this bug: 1821132
Duplicate of this bug: 1821110
Duplicate of this bug: 1821067

Hello! Could you please take a look at this bug? I think this is caused by Bug 1819280 but I'm not really sure. Range of retriggers and backfills.

Flags: needinfo?(oj)

I'm pretty sure it isn't as that bug and patch has nothing to do with these tests or HTTP2, I know there has been issues with intermittent WS WPT tests with that bug/patch which also weren't caused by it, so I'm guessing it's another intermittent issue. Please let me know if I could be of any more help.

Flags: needinfo?(oj)

First occurrence in the range of retriggers and backfills

Paul, can you check if Bug 1820685 has anything to do with this?
Thank you.

Flags: needinfo?(pbone)
Whiteboard: [retriggered]

That bug changes only code comments. It can't be responsible:

Flags: needinfo?(pbone)
Keywords: regression
Regressed by: 1820704

Set release status flags based on info from the regressing bug 1820704

Actually the most probable cause here is Bug 1819280 even tough there's an earlier wpt-sync in Bug 1820499 which changes some XHR stuff. We'll see how the failure rate is going and will likely end up in an expectation update.

No longer regressed by: 1820704
See Also: → 1821834
Assignee: nobody → csabou
Status: NEW → ASSIGNED

Bug 1819280 landed shortly before but could it even be responsible for these intermittent failures?

Flags: needinfo?(valentin.gosu)
Keywords: leave-open

Chipping in as author of the patch, it isn't related changes no, just tests are intermittent as far as we could tell. Just a coincidence afaik.

Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/110c6c876548 Mark some websockets tests as intermittent on different platforms. r=aryx

(In reply to Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout) from comment #14)

Bug 1819280 landed shortly before but could it even be responsible for these intermittent failures?

That's possible, but I'm also seeing h2 timeouts before bug 1819280 landed, so I'm not confident that's what's causing these failures.
From what I can see, the WPT h2 server is failing.

https://treeherder.mozilla.org/logviewer?job_id=408273436&repo=autoland&lineNumber=6413-6419

[task 2023-03-08T13:15:25.644Z] 13:15:25     INFO - TEST-START | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.worker.html?wpt_flags=h2
[task 2023-03-08T13:15:25.669Z] 13:15:25     INFO - Closing window e1f73f0d-fac7-4770-aef6-0b6cf3303980
[task 2023-03-08T13:15:26.588Z] 13:15:26  WARNING - wptserve (4dcb6b8e) Unexpected Error - 
[task 2023-03-08T13:15:26.588Z] 13:15:26  WARNING - Max outbound streams is 100, 0 open
[task 2023-03-08T13:15:26.601Z] 13:15:26  WARNING - wptserve (4dcb6b8e - 467) Stream Reset, Thread Closing
[task 2023-03-08T13:15:26.603Z] 13:15:26  WARNING - wptserve (4dcb6b8e - 477) Stream Reset, Thread Closing
[task 2023-03-08T13:15:26.616Z] 13:15:26  WARNING - wptserve (4dcb6b8e - 1029) Stream Reset, Thread Closing
[task 2023-03-08T13:15:26.621Z] 13:15:26  WARNING - wptserve (79566cd7) Unexpected Error - 
[task 2023-03-08T13:15:26.621Z] 13:15:26  WARNING - Invalid HTTP/2 preamble.
[task 2023-03-08T13:15:26.623Z] 13:15:26  WARNING - wptserve (0494175d) Unexpected Error - 
[task 2023-03-08T13:15:26.623Z] 13:15:26  WARNING - Invalid HTTP/2 preamble.
...
[task 2023-03-08T13:15:56.479Z] 13:15:56  WARNING - wptserve (0f0575fb) Unexpected Error - 
[task 2023-03-08T13:15:56.479Z] 13:15:56  WARNING - Invalid HTTP/2 preamble.

It's unclear to me if the wpt server failures are caused by something that Firefox is doing wrong, or if it has an implementation issue that's maybe triggered by bug 1819280.

Flags: needinfo?(valentin.gosu)

Code sheriff Cosmin ran 80 tasks before the changes from bug 1819280 and none encountered the issue. Setting this bug as having been started by bug 1819280.

Regressed by: 1819280
Priority: -- → P2
Whiteboard: [retriggered][stockwell needswork:owner] → [retriggered][stockwell needswork:owner][necko-triaged]
Assignee: csabou → nobody
Status: ASSIGNED → NEW
Whiteboard: [retriggered][stockwell needswork:owner][necko-triaged] → [retriggered][stockwell needswork:owner][necko-triaged][necko-priority-review]

Update:

There have been 38 failures within the last 7 days:

  • 4 failures on Android 7.0 x86-64 Lite WebRender opt
  • 4 failures on Android 7.0 x86-64 WebRender debug/opt
  • 3 failures on Linux 18.04 x64 WebRender debug
  • 2 failures on Linux 18.04 x64 WebRender tsan opt
  • 25 failures on OS X 10.15 WebRender opt/debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=411758230&repo=autoland&lineNumber=3795

[task 2023-04-08T12:23:40.820Z] 12:23:40     INFO - TEST-PASS | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.worker.html | bufferedAmount should not be updated during a sync XHR 
[task 2023-04-08T12:23:40.820Z] 12:23:40     INFO - TEST-PASS | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.html?wss | bufferedAmount should not be updated during a sync XHR 
[task 2023-04-08T12:23:40.820Z] 12:23:40     INFO - TEST-UNEXPECTED-TIMEOUT | /websockets/bufferedAmount-unchanged-by-sync-xhr.any.sharedworker.html?wpt_flags=h2 | bufferedAmount should not be updated during a sync XHR - Test timed out
[task 2023-04-08T12:23:40.821Z] 12:23:40  WARNING - wptserve (c82b2358) Unexpected Error - 
[task 2023-04-08T12:23:40.821Z] 12:23:40  WARNING - Invalid HTTP/2 preamble.
[task 2023-04-08T12:23:40.824Z] 12:23:40  WARNING - wptserve (8c271a1e) Unexpected Error - 
[task 2023-04-08T12:23:40.824Z] 12:23:40  WARNING - Invalid HTTP/2 preamble.
[task 2023-04-08T12:23:40.824Z] 12:23:40  WARNING - wptserve (1ee4422a) Unexpected Error - 
[task 2023-04-08T12:23:40.824Z] 12:23:40  WARNING - Invalid HTTP/2 preamble.
[task 2023-04-08T12:23:40.826Z] 12:23:40  WARNING - wptserve (fefbe871) Unexpected Error - 
[task 2023-04-08T12:23:40.826Z] 12:23:40  WARNING - Invalid HTTP/2 preamble.
[task 2023-04-08T12:23:40.828Z] 12:23:40  WARNING - wptserve (e28f99a4) Unexpected Error - 
[task 2023-04-08T12:23:40.828Z] 12:23:40  WARNING - Invalid HTTP/2 preamble.

Sunil, could you check what needs to be done here to handle these unexpected failures?

Flags: needinfo?(smayya)
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/152c6561e9e3 Mark subtest on bufferedAmount-unchanged-by-sync-xhr.any.js as intermittent after the wpt-sync. a=test-only
Whiteboard: [retriggered][necko-triaged][necko-priority-review][stockwell disable-recommended] → [retriggered][necko-triaged][necko-priority-review][stockwell needswork:owner]
Duplicate of this bug: 1828536
Flags: needinfo?(smayya)
Flags: needinfo?(edgul)

I think this started with 1819280 so it's probably a server bug. Not high priority

Priority: P2 → P3
Whiteboard: [retriggered][necko-triaged][necko-priority-review][stockwell unknown] → [retriggered][necko-triaged][stockwell unknown]
Attachment #9387034 - Attachment is obsolete: true
Flags: needinfo?(edgul)
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: