1811827 - Intermittent /webrtc/protocol/bundle.https.html | single tracking bug

Status: RESOLVED INCOMPLETE

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-01-23T11:09:54.027Z] 11:09:54     INFO - TEST-OK | /webrtc/protocol/RTCPeerConnection-payloadTypes.html | took 561ms
[task 2023-01-23T11:09:54.027Z] 11:09:54     INFO - TEST-START | /webrtc/protocol/bundle.https.html
[task 2023-01-23T11:09:54.029Z] 11:09:54     INFO - Setting pref media.navigator.permission.disabled to true
[task 2023-01-23T11:09:54.035Z] 11:09:54     INFO - Setting pref media.navigator.streams.fake to true
[task 2023-01-23T11:09:54.046Z] 11:09:54     INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter to true
[task 2023-01-23T11:09:54.054Z] 11:09:54     INFO - Setting pref privacy.reduceTimerPrecision to true
[task 2023-01-23T11:09:54.063Z] 11:09:54     INFO - Setting pref media.peerconnection.ice.trickle_grace_period to 5000
[task 2023-01-23T11:09:54.074Z] 11:09:54     INFO - Setting pref media.peerconnection.ice.obfuscate_host_addresses to true
[task 2023-01-23T11:09:54.084Z] 11:09:54     INFO - Setting pref media.peerconnection.allow_old_setParameters to true
[task 2023-01-23T11:09:54.097Z] 11:09:54     INFO - Setting pref media.navigator.permission.disabled to true
[task 2023-01-23T11:09:54.109Z] 11:09:54     INFO - Setting pref media.navigator.streams.fake to true
[task 2023-01-23T11:09:54.119Z] 11:09:54     INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter to false
[task 2023-01-23T11:09:54.129Z] 11:09:54     INFO - Setting pref privacy.reduceTimerPrecision to false
[task 2023-01-23T11:09:54.142Z] 11:09:54     INFO - Setting pref media.peerconnection.ice.trickle_grace_period to 10000
[task 2023-01-23T11:09:54.159Z] 11:09:54     INFO - Setting pref media.peerconnection.ice.obfuscate_host_addresses to false
[task 2023-01-23T11:09:54.173Z] 11:09:54     INFO - Setting pref media.peerconnection.allow_old_setParameters to false
[task 2023-01-23T11:09:54.184Z] 11:09:54     INFO - Closing window 9cab4b5b-fff1-4b03-a66c-fd2ab676d598
[task 2023-01-23T11:10:01.400Z] 11:10:01     INFO - PID 25632 | Timecard created 1674472193.932379
[task 2023-01-23T11:10:01.401Z] 11:10:01     INFO - PID 25632 |  Timestamp   | Delta       | Event                                  | File                         | Function
[task 2023-01-23T11:10:01.402Z] 11:10:01     INFO - PID 25632 | ====================================[Child 25944: Socket Thread]: I/mtransport NrIceCtx(PC:{541cab4b-73e5-43f8-9749-dcc6e211dafa} 1674472193940997 (id=6442450950 url=http://web-platform.test:8000/webrtc/protocol/RTCPee): Destroy
[task 2023-01-23T11:10:01.403Z] 11:10:01     INFO - PID 25632 | =====================================================================================
[task 2023-01-23T11:10:01.403Z] 11:10:01     INFO - PID 25632 |     0.001665 |    0.001665 | Constructor Completed                  | PeerConnectionImpl.cpp:367   | PeerConnectionImpl
[task 2023-01-23T11:10:01.404Z] 11:10:01     INFO - PID 25632 |     0.008662 |    0.006997 | Initializing PC Ctx                    | PeerConnectionImpl.cpp:456   | Initialize
[task 2023-01-23T11:10:01.404Z] 11:10:01     INFO - PID 25632 |     0.056986 |    0.048324 | Create Offer                           | PeerConnectionImpl.cpp:1531  | CreateOffer
[task 2023-01-23T11:10:01.405Z] 11:10:01     INFO - PID 25632 |     0.077106 |    0.020120 | Close                                  | PeerConnectionImpl.cpp:2236  | Close
[task 2023-01-23T11:10:01.405Z] 11:10:01     INFO - PID 25632 |     7.467530 |    7.390424 | Destructor Invoked                     | PeerConnectionImpl.cpp:384   | ~PeerConnectionImpl
[task 2023-01-23T11:10:01.406Z] 11:10:01     INFO - PID 25632 |     7.467530 |    0.000000 | {541cab4b-73e5-43f8-9749-dcc6e211dafa} | PeerConnectionImpl.cpp:385   | ~PeerConnectionImpl
[task 2023-01-23T11:10:01.406Z] 11:10:01     INFO - PID 25632 | [Child 25944: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:392: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {541cab4b-73e5-43f8-9749-dcc6e211dafa}
[task 2023-01-23T11:10:29.028Z] 11:10:29     INFO - Got timeout in harness
[task 2023-01-23T11:10:29.029Z] 11:10:29     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | TestRunner hit external timeout (this may indicate a hang)
[task 2023-01-23T11:10:29.030Z] 11:10:29     INFO - TEST-INFO took 35003ms
[task 2023-01-23T11:11:40.093Z] 11:11:40     INFO - Browser exited with return code -15
[task 2023-01-23T11:11:40.133Z] 11:11:40 CRITICAL - Loading initial page https://web-platform.test:8443/testharness_runner.html failed. Ensure that the there are no other programs bound to this port and that your firewall rules or network setup does not prevent access.
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL - Traceback (most recent call last):
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 166, in load_runner
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     self.dismiss_alert(lambda: self.marionette.navigate(url))
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 214, in dismiss_alert
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     f()
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 166, in <lambda>
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     self.dismiss_alert(lambda: self.marionette.navigate(url))
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1592, in navigate
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     self._send_message("WebDriver:Navigate", {"url": url})
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     m._handle_socket_failure()
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 707, in _handle_socket_failure
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     reraise(exc_cls, exc, tb)
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/third_party/six/six.py", line 703, in reraise
[task 2023-01-23T11:11:40.134Z] 11:11:40 CRITICAL -     raise value
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -     return func(*args, **kwargs)
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 656, in _send_message
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -     msg = self.client.request(name, params)
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 381, in request
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -     return self.receive()
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 228, in receive
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL -     raise socket.error("No data received over socket")
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL - OSError: No data received over socket
[task 2023-01-23T11:11:40.135Z] 11:11:40 CRITICAL - 
[task 2023-01-23T11:11:40.137Z] 11:11:40  WARNING - Traceback (most recent call last):
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/base.py", line 300, in run_test
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     self.on_environment_change(test.environment)
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 910, in on_environment_change
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     self.protocol.testharness.load_runner(new_environment["protocol"])
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 166, in load_runner
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     self.dismiss_alert(lambda: self.marionette.navigate(url))
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 214, in dismiss_alert
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     f()
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 166, in <lambda>
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     self.dismiss_alert(lambda: self.marionette.navigate(url))
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1592, in navigate
[task 2023-01-23T11:11:40.138Z] 11:11:40  WARNING -     self._send_message("WebDriver:Navigate", {"url": url})
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     m._handle_socket_failure()
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 707, in _handle_socket_failure
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     reraise(exc_cls, exc, tb)
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/third_party/six/six.py", line 703, in reraise
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     raise value
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     return func(*args, **kwargs)
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 656, in _send_message
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     msg = self.client.request(name, params)
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 381, in request
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     return self.receive()
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 228, in receive
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING -     raise socket.error("No data received over socket")
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING - OSError: No data received over socket
[task 2023-01-23T11:11:40.139Z] 11:11:40  WARNING - 
[task 2023-01-23T11:11:40.140Z] 11:11:40  WARNING - Command left in command_queue during cleanup: 'test_ended', (<wptrunner.wpttest.TestharnessTest /webrtc/protocol/bundle.https.html>, (<wptrunner.wpttest.TestharnessResult INTERNAL-ERROR>, []))
[task 2023-01-23T11:11:40.140Z] 11:11:40     INFO - Closing logging queue
[task 2023-01-23T11:11:40.141Z] 11:11:40     INFO - queue closed
[task 2023-01-23T11:11:40.158Z] 11:11:40     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpocj2ro60
[task 2023-01-23T11:11:40.199Z] 11:11:40     INFO - PID 25976 | [CodeCoverage] Setting handlers for process 25976.
[task 2023-01-23T11:11:40.199Z] 11:11:40     INFO - PID 25976 | 1674472193538	Marionette	INFO	Marionette enabled
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | 1674472193543	Marionette	INFO	Listening on port 60441
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.error: ({})
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmp_z2fhohr/search.json.mozlz4", (void 0)))
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - PID 25976 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-01-23T11:11:40.200Z] 11:11:40     INFO - Starting runner

Comment 1

[Iulian Moraru]

First occurrence, so far: backfill range and retriggers.

Comment 2

[Intermittent Failures Robot]

7 failures in 3914 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 6

Platform and build breakdown:

• linux1804-64-ccov-qr: 1
  • opt: 1
• linux1804-64-qr: 2
  • debug: 1
  • opt: 1
• macosx1015-64-qr: 2
  • debug: 1
  • opt: 1
• linux1804-64-tsan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-01-23&endday=2023-01-29&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-02-06&endday=2023-02-12&tree=all

Comment 4

[Byron Campen [:bwc]]

I've spent some time digging into this, and timeouts in this test case are always preceded with an error from ALSA:

https://treeherder.mozilla.org/logviewer?job_id=406426694&repo=try&lineNumber=2430

When this happens, it is immediately after we feed the first video frame into MediaTrackGraph (I'm guessing that this would still break sometimes for audio-only, but that's the next thing I'll try).

Comment 5

[Byron Campen [:bwc]]

While looking at this, I noticed bug 1818127, and fixing that seems to bring the intermittent rate way down. Not totally sure why.

Comment 6

[Byron Campen [:bwc]]

I should note that webrtc/protocol/rtp-demuxing.html also times out (bug 1785390) while waiting for the loadedmetadata event, and it also opens two video elements and attaches the same stream to both, although in this case it is deliberate. I think there's some sort of bug with firing loadedmetadata when we have duplicate video elements like this.

Comment 7

[Intermittent Failures Robot]

2 failures in 3643 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• linux1804-64-tsan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-02-20&endday=2023-02-26&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-03-06&endday=2023-03-12&tree=all

Comment 9

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

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

Comment 10

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=416654667&repo=autoland

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-05-22&endday=2023-05-28&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

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

Comment 13

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

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

Comment 14

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=423495681&repo=autoland

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1811827&startday=2023-07-17&endday=2023-07-23&tree=all

Comment 16

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

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