1798642 - High frequency OSX websocket related failures

Status: RESOLVED INCOMPLETE

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

Description

[Iulian Moraru]

We started to notice that there are frequent multiple failures related to websocket.
Here are some examples:

• Retriggers and backfills for mochitest plain
• Retriggers for bc
• Retriggers for mochites-chrome
• Retriggers and backfills for dt
• Retriggers for another type of websocket failure for mochitest plain
  Added some jobs here, Oct 18 retriggers and backfills they seem to go deeper than this.

Comment 1

[Iulian Moraru]

Few examples of failures:

• TEST-UNEXPECTED-FAIL | dom/security/test/csp/test_upgrade_insecure.html | upgrade all requests on toplevel https (result: websocket-unexpected-error) - didn't expect -1, but got it
• TEST-UNEXPECTED-FAIL | dom/security/test/sec-fetch/test_websocket.html | sanity: wssSocket onerror
• TEST-UNEXPECTED-FAIL | dom/security/test/https-only/browser_websocket_exceptions.js | sanity: websocket loaded - "onerror" == "onopen" - got "onerror", expected "onopen" (operator ==)
• TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_staticPartition_websocket.js | Websocket endpoint accepts connections. -
• TEST-UNEXPECTED-FAIL | dom/websocket/tests/test_event_listener_leaks.html | websocket error
  And I think this might also be related to the issue: TEST-UNEXPECTED-FAIL | toolkit/content/tests/chrome/test_about_networking.html | Test timed out. -
• TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net-ws-filter-freetext.js | Test timed out -
• TEST-UNEXPECTED-FAIL | dom/security/test/mixedcontentblocker/test_bug803225.html | resource with wss protocol did not load

All the failures seem OSX related...changing the bug summary accordingly.

Comment 2

[Iulian Moraru]

Hi Frederik! Can you please take a look in to this?
Thank you!

Comment 3

[Intermittent Failures Robot]

408 failures in 733 pushes (0.557 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 311
• mozilla-central: 44
• try: 23
• mozilla-beta: 30

Platform and build breakdown:

• macosx1015-64-shippable-qr: 137
  • opt: 137
• macosx1015-64-qr: 252
  • debug: 152
  • opt: 100
• macosx1015-64-devedition-qr: 15
  • opt: 15
• linux1804-64-shippable-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • opt: 1
• linux1804-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-02&endday=2022-11-02&tree=all

Comment 4

[Intermittent Failures Robot]

87 failures in 686 pushes (0.127 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 26
• mozilla-central: 61

Platform and build breakdown:

• macosx1015-64-qr: 63
  • debug: 52
  • opt: 11
• macosx1015-64-shippable-qr: 23
  • opt: 23
• windows7-32-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-03&endday=2022-11-03&tree=all

Comment 5

[Kershaw Chang [:kershaw]]

I tried to debug this a bit by running websocket tests with log enabled in this try run.
The log shows that after the ssl tunnel established, the websocket server returns some weird data.

[task 2022-11-03T18:58:31.332Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 128fa0300 ReadSegments returned [rv=0 read=509 sock-cond=0 again=1]
[task 2022-11-03T18:58:31.332Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp   writing transaction request stream
[task 2022-11-03T18:58:31.332Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpTransaction::ReadSegments 13a681900
[task 2022-11-03T18:58:31.333Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 128fa0300 ReadSegments returned [rv=0 read=0 sock-cond=0 again=1]
[task 2022-11-03T18:58:31.333Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=13a681900 status=804b000a progress=0]
[task 2022-11-03T18:58:31.334Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=128fa0300]
[task 2022-11-03T18:58:31.334Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Main Thread]: D/nsWebSocket WebSocketChannel::GetInterface() 128f5d500
[task 2022-11-03T18:58:31.335Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable [this=128fa0300]
[task 2022-11-03T18:58:31.335Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 13a681900
[task 2022-11-03T18:58:31.336Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=13a681900
[task 2022-11-03T18:58:31.336Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Main Thread]: D/nsWebSocket WebSocketChannelParent::GetInterface() 128fedd60
[task 2022-11-03T18:58:31.337Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 128fa0300 trans->ws rv=0 n=0 socketin=80470002
[task 2022-11-03T18:58:31.337Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnection::CloseTransaction[this=128fa0300 trans=13a681900 reason=80470002]
[task 2022-11-03T18:58:31.338Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp   closing associated mTransaction
[task 2022-11-03T18:58:31.338Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpTransaction::Close [this=13a681900 reason=0]
[task 2022-11-03T18:58:31.339Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpConnectionMgr::RemoveActiveTransaction t=13a681900 tabid=d(1) thr=0
[task 2022-11-03T18:58:31.339Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp Active transactions -[0,0,0,0]
[task 2022-11-03T18:58:31.340Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpTransaction::ParseHead [count=1]
[task 2022-11-03T18:58:31.340Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpResponseHead::ParseVersion [version=]
[task 2022-11-03T18:58:31.340Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp looks like a HTTP/0.9 response
[task 2022-11-03T18:58:31.341Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp response status line needs default reason phrase
[task 2022-11-03T18:58:31.341Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: E/nsHttp Have status line [version=9 status=200 statusText=OK]
[task 2022-11-03T18:58:31.342Z] 18:58:31     INFO - GECKO(31929) | [Parent 31929: Socket Thread]: V/nsHttp nsHttpTransaction::Close 13a681900 0 Byte 0.9 Response

The normal case should be that we receive 101 response from the server as below:

 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 141e4cd00 ReadSegments returned [rv=0 read=509 sock-cond=0 again=1]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp   writing transaction request stream
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpTransaction::ReadSegments 1387abb00
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 141e4cd00 ReadSegments returned [rv=0 read=0 sock-cond=0 again=1]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=1387abb00 status=804b000a progress=0]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=141e4cd00]
 0:08.04 GECKO(40178) [Parent 40178: Main Thread]: D/nsWebSocket WebSocketChannel::GetInterface() 141d1ca00
 0:08.04 GECKO(40178) [Parent 40178: Main Thread]: D/nsWebSocket WebSocketChannelParent::GetInterface() 138fe9d00
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable [this=141e4cd00]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 1387abb00
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=1387abb00
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: E/nsHttp nsHttpTransaction::OnSocketStatus [this=1387abb00 status=804b0006 progress=225]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpTransaction::WritePipeSegment 1387abb00 written=175
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: E/nsHttp nsHttpTransaction::ProcessData [this=1387abb00 count=175]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpTransaction::ParseHead [count=175]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: E/nsHttp nsHttpTransaction::ParseLine [HTTP/1.1 101 Switching Protocols]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: V/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 101 Switching Protocols]
 0:08.04 GECKO(40178) [Parent 40178: Socket Thread]: E/nsHttp Have status line [version=11 status=101 statusText=Switching Protocols]

Note that in both cases, Firefox received 509 bytes, but in the failed case, the data was obviously wrong.
Still not sure which part is wrong.

Comment 6

[Valentin Gosu [:valentin] (he/him)]

Looking at Bug 1784824 - Intermittent toolkit/content/tests/chrome/test_about_networking.html | single tracking bug which seems to also be failing because of the websocket server,

I see this in the log:

[task 2022-07-20T08:57:35.143Z] 08:57:35     INFO - TEST-START | toolkit/content/tests/chrome/test_about_networking.html
[task 2022-07-20T08:57:36.215Z] 08:57:36     INFO -   could not open connection to the real server
[task 2022-07-20T08:58:00.178Z] 08:58:00     INFO - GECKO(1983) | 2022-07-20 08:58:00.177 firefox[1983:28845] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
[task 2022-07-20T09:02:36.197Z] 09:02:36     INFO - TEST-INFO | started process screencapture
[task 2022-07-20T09:02:36.326Z] 09:02:36     INFO - TEST-INFO | screencapture: exit 0
[task 2022-07-20T09:02:36.326Z] 09:02:36     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/chrome/test_about_networking.html | Test timed out. - 

That string is coming from here
I assume that just the websocket server isn't up, and ssltunnel is returning an error?

I'll take a look if we can check exactly what the WSserver is doing.

Comment 7

[Intermittent Failures Robot]

238 failures in 686 pushes (0.347 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 26
• autoland: 121
• try: 27
• mozilla-release: 1
• mozilla-beta: 63

Platform and build breakdown:

• macosx1015-64-shippable-qr: 86
  • opt: 86
• macosx1015-64-qr: 120
  • debug: 74
  • opt: 46
• linux1804-64-tsan-qr: 2
  • opt: 2
• macosx1015-64-devedition-qr: 30
  • opt: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-04&endday=2022-11-04&tree=all

Comment 8

[Intermittent Failures Robot]

209 failures in 157 pushes (1.331 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 156
• mozilla-central: 31
• try: 12
• mozilla-beta: 10

Platform and build breakdown:

• macosx1015-64-qr: 141
  • debug: 82
  • opt: 59
• macosx1015-64-shippable-qr: 61
  • opt: 61
• macosx1015-64-devedition-qr: 5
  • opt: 5
• windows10-64-2004-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-05&endday=2022-11-05&tree=all

Comment 9

[Intermittent Failures Robot]

1086 failures in 3626 pushes (0.3 failures/push) were associated with this bug in the last 7 days.

This is the #1 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 739
• mozilla-central: 174
• try: 62
• mozilla-beta: 110
• mozilla-release: 1

Platform and build breakdown:

• macosx1015-64-qr: 698
  • debug: 469
  • opt: 229
• macosx1015-64-shippable-qr: 328
  • opt: 328
• macosx1015-64-devedition-qr: 51
  • opt: 51
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows10-64-2004-qr: 2
  • opt: 2
• linux1804-64-qr: 2
  • debug: 2
• windows7-32-shippable-qr: 1
  • opt: 1
• linux1804-64-tsan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-10-31&endday=2022-11-06&tree=all

Comment 10

[Intermittent Failures Robot]

257 failures in 691 pushes (0.372 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 148
• mozilla-central: 51
• try: 39
• mozilla-beta: 13
• mozilla-release: 1
• mozilla-esr102: 5

Platform and build breakdown:

• macosx1015-64-qr: 190
  • debug: 131
  • opt: 59
• macosx1015-64-shippable-qr: 56
  • opt: 56
• macosx1100-64-shippable-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • opt: 1
• macosx1015-64-devedition-qr: 8
  • opt: 8
• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-07&endday=2022-11-07&tree=all

Comment 11

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The issue has also been observed with test tasks which got added to pushes from October and failed for these. Either the machine environment or an artifact used for test execution changed.

Comment 12

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Only one failure in the last ~12 hours. Resolved by fixing the reboots in bug 1797816 comment 15.

Please close the bug if no further work is planned.

Comment 13

[Valentin Gosu [:valentin] (he/him)]

Thanks! Glad to see this resolved. Most of the bugs in the see also list also seem to show reduced failure rates.

Comment 14

[Intermittent Failures Robot]

258 failures in 3445 pushes (0.075 failures/push) were associated with this bug in the last 7 days.

This is the #2 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 149
• mozilla-central: 51
• try: 39
• mozilla-beta: 13
• mozilla-esr102: 5
• mozilla-release: 1

Platform and build breakdown:

• macosx1015-64-qr: 191
  • debug: 131
  • opt: 60
• macosx1015-64-shippable-qr: 56
  • opt: 56
• windows10-64-2004-qr: 1
  • opt: 1
• macosx1100-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-devedition-qr: 8
  • opt: 8
• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-07&endday=2022-11-13&tree=all

Comment 15

[Intermittent Failures Robot]

1 failures in 3589 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr102: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1798642&startday=2022-11-14&endday=2022-11-20&tree=all

Comment 16

[Valentin Gosu [:valentin] (he/him)]

We are still seeing a lot of failures on OSX websocket tests. Could you take a look?
Should we reopen bug 1797816 or is this a different problem?

Comment 17

[Andrew Erickson [:aerickson]]

The latest intermittent failures robot posts are from 3 months ago. Is it still a problem?

The configuration issue has been resolved (unless there are workers that haven't been updated - which could happen).

Michelle, as an FYI. In Bug 1797816 we had a g-w config issue that caused the hosts to not exit and reboot after running one job (they're run forever). Not sure if r8 009 is still quarantined, but may want to note in inventory.

Comment 18

[Valentin Gosu [:valentin] (he/him)]

We're still seeing some websocket tests intermittently failing only on OSX:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1777102&startday=2023-02-13&endday=2023-02-19&tree=all
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1801420&startday=2023-02-13&endday=2023-02-19&tree=all

No failures since the 16th as far as I can tell. Will ping back next week if we see any more happening.

Comment 19

[Michelle Goossens [:masterwayz]]

-009 isn't quarantined anymore and looking at recent jobs it is working properly
Let's hope we get no more failures.

Comment 20

[Valentin Gosu [:valentin] (he/him)]

https://bugzilla.mozilla.org/show_bug.cgi?id=1777102#c30
https://bugzilla.mozilla.org/show_bug.cgi?id=1801420#c14

There are still some OSX failures.

Comment 21

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.