1710564 - Intermittent dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | Error in test execution: Error: Checking stats for track {96f5d03e-06f6-4e5d-8fba-3ef7812b9c35} timed out after 30000 ms _waitForRtpFlow@https://exam

Status: RESOLVED DUPLICATE of bug 1710829

(Core :: WebRTC: Audio/Video, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-05-11T06:06:20.112Z] 06:06:20     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html
[task 2021-05-11T06:06:20.128Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-11T06:06:20.185Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-11T06:06:20.199Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-11T06:06:20.237Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-05-11T06:06:20.238Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-05-11T06:06:20.334Z] 06:06:20     INFO - GECKO(8664) | Timecard created 1620713177.041000
<...>
[task 2021-05-11T06:06:20.379Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {cbbcb393-bfa0-4bc5-ad2d-aa17515bc859}
[task 2021-05-11T06:06:20.453Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.453Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.454Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.454Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.457Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.458Z] 06:06:20     INFO - GECKO(8664) | [Child 4024, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7499
[task 2021-05-11T06:06:20.713Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:331: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2021-05-11T06:06:20.715Z] 06:06:20     INFO - GECKO(8664) | [Parent 10552: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2021-05-11T06:06:20.716Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:331: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2021-05-11T06:06:20.718Z] 06:06:20     INFO - GECKO(8664) | [Parent 10552: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2021-05-11T06:06:20.727Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-05-11T06:06:20.727Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-05-11T06:06:20.729Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:75: OnStunAddrsAvailable: receiving (3) stun addrs
[task 2021-05-11T06:06:20.729Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:75: OnStunAddrsAvailable: receiving (3) stun addrs
[task 2021-05-11T06:06:20.773Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-05-11T06:06:20.773Z] 06:06:20     INFO - GECKO(8664) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-05-11T06:06:20.829Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 28daf47f740
[task 2021-05-11T06:06:20.830Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/jsep [{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> have-local-offer
[task 2021-05-11T06:06:20.831Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 28daf4a32e0
[task 2021-05-11T06:06:20.832Z] 06:06:20     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/jsep [{140be116-98b1-46a8-9d28-66978938c6db} 1620713180716000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> have-remote-offer
[task 2021-05-11T06:06:20.836Z] 06:06:20     INFO - GECKO(8664) | (generic/EMERG) Exit UDP socket connected
[task 2021-05-11T06:06:20.840Z] 06:06:20     INFO - GECKO(8664) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media
[task 2021-05-11T06:06:20.842Z] 06:06:20     INFO - GECKO(8664) | /webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:625 functio
[task 2021-05-11T06:06:20.842Z] 06:06:20     INFO - GECKO(8664) | n nr_socket_multi_tcp_listen failed with error 3
[task 2021-05-11T06:06:20.843Z] 06:06:20     INFO - GECKO(8664) | (ice/WARNING) ICE(PC:{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc): failed to create passive TCP host candidate: 3
[task 2021-05-11T06:06:20.844Z] 06:06:20     INFO - GECKO(8664) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:625 function nr_socket_multi_tcp_listen failed with error 3
[task 2021-05-11T06:06:20.845Z] 06:06:20     INFO - GECKO(8664) | (ice/WARNING) ICE(PC:{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc): failed to create passive TCP host candidate: 3
<...>
[task 2021-05-11T06:06:50.448Z] 06:06:50     INFO - GECKO(8664) | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2021-05-11T06:06:50.449Z] 06:06:50     INFO - GECKO(8664) | (ice/INFO) IC
[task 2021-05-11T06:06:50.452Z] 06:06:50     INFO - GECKO(8664) | E(PC:{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc)/STREAM(PC:{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc transport-id=transport_0 - 4368c594:a4df1b5e8fc452f902574909524f6d16)/COMP(1): Consent refreshed
[task 2021-05-11T06:06:51.392Z] 06:06:51     INFO - TEST-INFO | started process screenshot
[task 2021-05-11T06:06:51.466Z] 06:06:51     INFO - TEST-INFO | screenshot: exit 0
[task 2021-05-11T06:06:51.467Z] 06:06:51     INFO - <snipped 547 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2021-05-11T06:06:51.467Z] 06:06:51     INFO - Buffered messages logged at 06:06:42
[task 2021-05-11T06:06:51.468Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-05-11T06:06:51.468Z] 06:06:51     INFO - Checking outbound-rtp for audio track {89e580c1-8999-408f-a53f-7286abc0c28c} try 43
[task 2021-05-11T06:06:51.469Z] 06:06:51     INFO - Track {89e580c1-8999-408f-a53f-7286abc0c28c} has 0 packetsSent.
[task 2021-05-11T06:06:51.470Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-05-11T06:06:51.470Z] 06:06:51     INFO - Buffered messages logged at 06:06:43
[task 2021-05-11T06:06:51.471Z] 06:06:51     INFO - Checking inbound-rtp for audio track {96f5d03e-06f6-4e5d-8fba-3ef7812b9c35} try 44
[task 2021-05-11T06:06:51.471Z] 06:06:51     INFO - Track {96f5d03e-06f6-4e5d-8fba-3ef7812b9c35} has 0 packetsReceived.
[task 2021-05-11T06:06:51.472Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
<...>
[task 2021-05-11T06:06:51.525Z] 06:06:51     INFO - Checking outbound-rtp for audio track {89e580c1-8999-408f-a53f-7286abc0c28c} try 59
[task 2021-05-11T06:06:51.525Z] 06:06:51     INFO - Track {89e580c1-8999-408f-a53f-7286abc0c28c} has 0 packetsSent.
[task 2021-05-11T06:06:51.526Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-05-11T06:06:51.526Z] 06:06:51     INFO - Buffered messages finished
[task 2021-05-11T06:06:51.528Z] 06:06:51     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | Error in test execution: Error: Checking stats for track {96f5d03e-06f6-4e5d-8fba-3ef7812b9c35} timed out after 30000 ms _waitForRtpFlow@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:1808:11 ...  
[task 2021-05-11T06:06:51.528Z] 06:06:51     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-05-11T06:06:51.528Z] 06:06:51     INFO - execute/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:958:11
[task 2021-05-11T06:06:51.528Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-05-11T06:06:51.529Z] 06:06:51     INFO - Closing peer connections
[task 2021-05-11T06:06:51.529Z] 06:06:51     INFO - Waiting for track {96f5d03e-06f6-4e5d-8fba-3ef7812b9c35} (audio) to end.
[task 2021-05-11T06:06:51.530Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-05-11T06:06:51.531Z] 06:06:51     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2102: CloseInt: Closing PeerConnectionImpl {2d650b3c-be91-49d8-88a7-9866617db2e9}; ending call
[task 2021-05-11T06:06:51.532Z] 06:06:51     INFO - GECKO(8664) | [Child 4024: Main Thread]: I/jsep [{2d650b3c-be91-49d8-88a7-9866617db2e9} 1620713180713000 (id=2147483949 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> closed
[task 2021-05-11T06:06:51.532Z] 06:06:51     INFO - PeerConnectionWrapper (pcLocal): Closed connection.
[task 2021-05-11T06:06:51.533Z] 06:06:51     INFO - Waiting for track {878042c2-bcb1-47a6-afb4-b18b058051a6} (audio) to end.
[task 2021-05-11T06:06:51.533Z] 06:06:51     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_removeThenAddAudioTrackNoBundle.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
<...>```