1700123 - Intermittent dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Error in test execution: Error: Element _remote_{6d6d999b-b815-4771-b0ba-d9cb82b61221} should progress currentTime timeout/<@https://example.com/tests/dom/media/webrtc/te

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html
[task 2021-03-22T14:13:26.530Z] 14:13:26     INFO - GECKO(420) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-03-22T14:13:26.530Z] 14:13:26     INFO - GECKO(420) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-03-22T14:13:26.568Z] 14:13:26     INFO - GECKO(420) | Timecard created 1616422402.865000
[task 2021-03-22T14:13:26.568Z] 14:13:26     INFO - GECKO(420) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-03-22T14:13:26.569Z] 14:13:26     INFO - GECKO(420) | ======================================================================================================================
[task 2021-03-22T14:13:26.569Z] 14:13:26     INFO - GECKO(420) |     0.000000 |    0.000000 | Constructor Completed          | PeerConnectionImpl.cpp:326   | PeerConnectionImpl
[task 2021-03-22T14:13:26.569Z] 14:13:26     INFO - GECKO(420) |     0.001000 |    0.001000 | Initializing PC Ctx            | PeerConnectionImpl.cpp:444   | Initialize
[task 2021-03-22T14:13:26.569Z] 14:13:26     INFO - GECKO(420) |     0.187000 |    0.186000 | Create Offer                   | PeerConnectionImpl.cpp:1206  | CreateOffer
[task 2021-03-22T14:13:26.570Z] 14:13:26     INFO - GECKO(420) |     0.214000 |    0.027000 | Set Local Description          | PeerConnectionImpl.cpp:1275  | SetLocalDescription
[task 2021-03-22T14:13:26.570Z] 14:13:26     INFO - GECKO(420) |     0.351000 |    0.137000 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2523  | IceGatheringStateChange
[task 2021-03-22T14:13:26.571Z] 14:13:26     INFO - GECKO(420) |     0.373000 |    0.022000 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2526  | IceGatheringStateChange
[task 2021-03-22T14:13:26.571Z] 14:13:26     INFO - GECKO(420) |     0.439000 |    0.066000 | Set Remote Description         | PeerConnectionImpl.cpp:1375  | SetRemoteDescription
[task 2021-03-22T14:13:26.572Z] 14:13:26     INFO - GECKO(420) |     0.474000 |    0.035000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1523  | AddIceCandidate
[task 2021-03-22T14:13:26.572Z] 14:13:26     INFO - GECKO(420) |     0.490000 |    0.016000 | Look up mDNS name              | PeerConnectionImpl.cpp:1811  | StampTimecard
[task 2021-03-22T14:13:26.572Z] 14:13:26     INFO - GECKO(420) |     0.491000 |    0.001000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1523  | AddIceCandidate
[task 2021-03-22T14:13:26.572Z] 14:13:26     INFO - GECKO(420) |     0.492000 |    0.001000 | Look up mDNS name              | PeerConnectionImpl.cpp:1811  | StampTimecard
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     0.493000 |    0.001000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1523  | AddIceCandidate
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     0.495000 |    0.002000 | Done looking up mDNS name      | PeerConnectionImpl.cpp:1811  | StampTimecard
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     0.495000 |    0.000000 | Done looking up mDNS name      | PeerConnectionImpl.cpp:1811  | StampTimecard
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     0.518000 |    0.023000 | Ice state: checking            | PeerConnectionImpl.cpp:2467  | IceConnectionStateChange
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     0.552000 |    0.034000 | Ice state: connected           | PeerConnectionImpl.cpp:2470  | IceConnectionStateChange
[task 2021-03-22T14:13:26.573Z] 14:13:26     INFO - GECKO(420) |     3.696000 |    3.144000 | Destructor Invoked             | PeerConnectionImpl.cpp:335   | ~PeerConnectionImpl
[task 2021-03-22T14:13:26.574Z] 14:13:26     INFO - GECKO(420) | [Child 8240: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:360: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {78054cf4-33f6-41cf-8637-cfa53e21cfd2}
[task 2021-03-22T14:13:26.574Z] 14:13:26     INFO - GECKO(420) | Timecard created 1616422402.870000
<...>
INFO - Run step 32: PC_REMOTE_WAIT_FOR_ICE_CONNECTED
[task 2021-03-22T14:14:27.750Z] 14:14:27     INFO - PeerConnectionWrapper (pcRemote): ICE connection state log: new,checking,connected
[task 2021-03-22T14:14:27.751Z] 14:14:27     INFO - Run step 33: PC_LOCAL_VERIFY_ICE_GATHERING
[task 2021-03-22T14:14:27.751Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | PeerConnectionWrapper (pcLocal) received local trickle ICE candidates 
[task 2021-03-22T14:14:27.751Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | PeerConnectionWrapper (pcLocal) ICE gathering state is not 'new' 
[task 2021-03-22T14:14:27.752Z] 14:14:27     INFO - Run step 34: PC_REMOTE_VERIFY_ICE_GATHERING
[task 2021-03-22T14:14:27.752Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | PeerConnectionWrapper (pcRemote) received local trickle ICE candidates 
[task 2021-03-22T14:14:27.752Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | PeerConnectionWrapper (pcRemote) ICE gathering state is not 'new' 
[task 2021-03-22T14:14:27.752Z] 14:14:27     INFO - Run step 35: PC_LOCAL_WAIT_FOR_MEDIA_FLOW
[task 2021-03-22T14:14:27.752Z] 14:14:27     INFO - Found transceiver that should be receiving RTP: mid=0 currentDirection=sendrecv kind=audio track-id={6d6d999b-b815-4771-b0ba-d9cb82b61221}
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - Checking data flow for element: _local_{3f2a7993-0cfd-4476-96c0-503abf91a318}
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Element ended should be the inverse of the MediaStream's active state 
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - Checking data flow for element: _remote_{6d6d999b-b815-4771-b0ba-d9cb82b61221}
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Element ended should be the inverse of the MediaStream's active state 
[task 2021-03-22T14:14:27.753Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.754Z] 14:14:27     INFO - _waitForRtpFlow({6d6d999b-b815-4771-b0ba-d9cb82b61221}, inbound-rtp)
[task 2021-03-22T14:14:27.754Z] 14:14:27     INFO - Checking inbound-rtp for audio track {6d6d999b-b815-4771-b0ba-d9cb82b61221} try 0
[task 2021-03-22T14:14:27.754Z] 14:14:27     INFO - _waitForRtpFlow({3f2a7993-0cfd-4476-96c0-503abf91a318}, outbound-rtp)
[task 2021-03-22T14:14:27.754Z] 14:14:27     INFO - Checking outbound-rtp for audio track {3f2a7993-0cfd-4476-96c0-503abf91a318} try 0
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Element _local_{3f2a7993-0cfd-4476-96c0-503abf91a318} has enough data.
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Element _remote_{6d6d999b-b815-4771-b0ba-d9cb82b61221} has enough data.
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Track {6d6d999b-b815-4771-b0ba-d9cb82b61221} has 0 packetsReceived.
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Track {3f2a7993-0cfd-4476-96c0-503abf91a318} has 0 packetsSent.
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Checking inbound-rtp for audio track {6d6d999b-b815-4771-b0ba-d9cb82b61221} try 1
[task 2021-03-22T14:14:27.755Z] 14:14:27     INFO - Track {6d6d999b-b815-4771-b0ba-d9cb82b61221} has 41 packetsReceived.
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | RTP flowing for audio track {6d6d999b-b815-4771-b0ba-d9cb82b61221} 
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - Checking outbound-rtp for audio track {3f2a7993-0cfd-4476-96c0-503abf91a318} try 1
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - Track {3f2a7993-0cfd-4476-96c0-503abf91a318} has 40 packetsSent.
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | RTP flowing for audio track {3f2a7993-0cfd-4476-96c0-503abf91a318} 
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - Buffered messages finished
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Error in test execution: Error: Element _remote_{6d6d999b-b815-4771-b0ba-d9cb82b61221} should progress currentTime timeout/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:633:42 ...  
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-03-22T14:14:27.756Z] 14:14:27     INFO - execute/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:959:11
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - Closing peer connections
INFO - Waiting for track {6d6d999b-b815-4771-b0ba-d9cb82b61221} (audio) to end.
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - GECKO(420) | [Child 8240: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2095: CloseInt: Closing PeerConnectionImpl {dd99ea47-3807-4760-bc41-f4f782ad68af}; ending call
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - GECKO(420) | [Child 8240: Main Thread]: I/jsep [{dd99ea47-3807-4760-bc41-f4f782ad68af} 1616422406800000 (id=2147484021 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> closed
[task 2021-03-22T14:14:27.757Z] 14:14:27     INFO - PeerConnectionWrapper (pcLocal): Closed connection.
[task 2021-03-22T14:14:27.758Z] 14:14:27     INFO - Waiting for track {522e2163-39e6-485b-962e-dee20e7f4ed1} (audio) to end.
[task 2021-03-22T14:14:27.758Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.758Z] 14:14:27     INFO - GECKO(420) | [Child 8240: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2095: CloseInt: Closing PeerConnectionImpl {e06f67c2-fc39-4966-b271-7ab4df988f97}; ending call
[task 2021-03-22T14:14:27.758Z] 14:14:27     INFO - GECKO(420) | [Child 8240: Main Thread]: I/jsep [{e06f67c2-fc39-4966-b271-7ab4df988f97} 1616422406804000 (id=2147484021 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> closed
[task 2021-03-22T14:14:27.758Z] 14:14:27     INFO - PeerConnectionWrapper (pcRemote): Closed connection.
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Event target should be the correct track 
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - PeerConnectionWrapper (pcLocal) ended fired for track {6d6d999b-b815-4771-b0ba-d9cb82b61221}
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | Event target should be the correct track 
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - PeerConnectionWrapper (pcRemote) ended fired for track {522e2163-39e6-485b-962e-dee20e7f4ed1}
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - GECKO(420) | MEMORY STAT | vsize 19405963MB | vsizeMaxContiguous 77498832MB | residentFast 1428MB
[task 2021-03-22T14:14:27.759Z] 14:14:27     INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_peerConnection_insertDTMF.html | took 61400ms
[task 2021-03-22T14:14:27.797Z] 14:14:27     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_localReofferRollback.html```

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • asan: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • opt: 1

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

Comment 3

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

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

Comment 4

[Alexandru Michis [:malexandru]]

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1700123&startday=2021-05-03&endday=2021-05-09&tree=all

Comment 6

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

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