Closed Bug 1608737 Opened 5 years ago Closed 5 years ago

Intermittent dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Error in test execution: Error: Element _local_{something} should progress currentTime timeout/<@https://*/mochitest/head.js:657:42 ...

Categories

(Core :: WebRTC, defect, P5)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=284594158&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/e2LJVttWS7KKez8bd7xfhA/runs/0/artifacts/public/logs/live_backing.log

...
[task 2020-01-12T23:35:17.966Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | ICE gathering state has reached complete
[task 2020-01-12T23:35:17.966Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.967Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: checking
[task 2020-01-12T23:35:17.967Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote): legal ICE state transition from new to checking
[task 2020-01-12T23:35:17.968Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.968Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: checking
[task 2020-01-12T23:35:17.968Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal): legal ICE state transition from new to checking
[task 2020-01-12T23:35:17.968Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.968Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: connected
[task 2020-01-12T23:35:17.969Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote): legal ICE state transition from checking to connected
[task 2020-01-12T23:35:17.969Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.969Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: connected
[task 2020-01-12T23:35:17.969Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal): legal ICE state transition from checking to connected
[task 2020-01-12T23:35:17.969Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): ICE connection state log: new,checking,connected
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - Run step 34: PC_REMOTE_WAIT_FOR_ICE_CONNECTED
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): ICE connection state log: new,checking,connected
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - Run step 35: PC_LOCAL_VERIFY_ICE_GATHERING
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal) received local trickle ICE candidates
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal) ICE gathering state is not 'new'
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - Run step 36: PC_REMOTE_VERIFY_ICE_GATHERING
[task 2020-01-12T23:35:17.970Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote) received local trickle ICE candidates
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote) ICE gathering state is not 'new'
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - Run step 37: PC_LOCAL_WAIT_FOR_MEDIA_FLOW
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - Checking data flow for element: local{23844939-9ed4-4a7f-b677-c341c75e91e9}
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Element ended should be the inverse of the MediaStream's active state
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - waitForRtpFlow({23844939-9ed4-4a7f-b677-c341c75e91e9})
[task 2020-01-12T23:35:17.971Z] 23:35:17 INFO - Element local{23844939-9ed4-4a7f-b677-c341c75e91e9} has enough data.
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Checking for stats in [["62bedcab",{"id":"62bedcab","timestamp":1578872057526,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"18a9986","nominated":false,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"51360be7","selected":false,"state":"cancelled","transportId":"transport_0","writable":true}],["57bc11c0",{"id":"57bc11c0","timestamp":1578872057526,"type":"candidate-pair","bytesReceived":189,"bytesSent":725,"lastPacketReceivedTimestamp":338443769671,"lastPacketSentTimestamp":338443769677,"localCandidateId":"18a9986","nominated":true,"priority":7962083765675491000,"readable":true,"remoteCandidateId":"b29ad657","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["18a9986",{"id":"18a9986","timestamp":1578872057526,"type":"local-candidate","address":"10.143.22.225","candidateType":"host","port":53427,"priority":2122252543,"protocol":"udp"}],["db7ef0bc",{"id":"db7ef0bc","timestamp":1578872057526,"type":"local-candidate","address":"10.143.22.225","candidateType":"host","port":62485,"priority":2105524479,"protocol":"tcp"}],["b29ad657",{"id":"b29ad657","timestamp":1578872057526,"type":"remote-candidate","address":"10.143.22.225","candidateType":"prflx","port":53430,"priority":1853817087,"protocol":"udp"}],["51360be7",{"id":"51360be7","timestamp":1578872057526,"type":"remote-candidate","address":"10.143.22.225","candidateType":"host","port":53430,"priority":2122252543,"protocol":"udp"}],["c6cdce",{"id":"c6cdce","timestamp":1578872057526,"type":"remote-candidate","address":"10.143.22.225","candidateType":"host","port":9,"priority":2105524479,"protocol":"tcp"}],["2e0c7ae1",{"id":"2e0c7ae1","timestamp":1578872057526,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":1078219557,"bytesSent":0,"packetsSent":0,"nackCount":0}]] for audio track {23844939-9ed4-4a7f-b677-c341c75e91e9}retry number 0
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Should have RTP stats for track {23844939-9ed4-4a7f-b677-c341c75e91e9}
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - RTP stats: {"id":"2e0c7ae1","timestamp":1578872057526,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":1078219557,"bytesSent":0,"packetsSent":0,"nackCount":0}
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Track {23844939-9ed4-4a7f-b677-c341c75e91e9} has 0 outbound-rtp RTP packets.
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Buffered messages logged at 23:34:18
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Checking for stats in [["62bedcab",{"id":"62bedcab","timestamp":1578872058034,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"18a9986","nominated":false,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"51360be7","selected":false,"state":"cancelled","transportId":"transport_0","writable":true}],["57bc11c0",{"id":"57bc11c0","timestamp":1578872058034,"type":"candidate-pair","bytesReceived":784,"bytesSent":2399,"lastPacketReceivedTimestamp":338443769695,"lastPacketSentTimestamp":338443769769,"localCandidateId":"18a9986","nominated":true,"priority":7962083765675491000,"readable":true,"remoteCandidateId":"b29ad657","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["18a9986",{"id":"18a9986","timestamp":1578872058034,"type":"local-candidate","address":"10.143.22.225","candidateType":"host","port":53427,"priority":2122252543,"protocol":"udp"}],["db7ef0bc",{"id":"db7ef0bc","timestamp":1578872058034,"type":"local-candidate","address":"10.143.22.225","candidateType":"host","port":62485,"priority":2105524479,"protocol":"tcp"}],["b29ad657",{"id":"b29ad657","timestamp":1578872058034,"type":"remote-candidate","address":"10.143.22.225","candidateType":"prflx","port":53430,"priority":1853817087,"protocol":"udp"}],["51360be7",{"id":"51360be7","timestamp":1578872058034,"type":"remote-candidate","address":"10.143.22.225","candidateType":"host","port":53430,"priority":2122252543,"protocol":"udp"}],["c6cdce",{"id":"c6cdce","timestamp":1578872058034,"type":"remote-candidate","address":"10.143.22.225","candidateType":"host","port":9,"priority":2105524479,"protocol":"tcp"}],["2e0c7ae1",{"id":"2e0c7ae1","timestamp":1578872058034,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":1078219557,"bytesSent":1427,"packetsSent":7,"nackCount":0}]] for audio track {23844939-9ed4-4a7f-b677-c341c75e91e9}retry number 1
[task 2020-01-12T23:35:17.972Z] 23:35:17 INFO - Should have RTP stats for track {23844939-9ed4-4a7f-b677-c341c75e91e9}
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - RTP stats: {"id":"2e0c7ae1","timestamp":1578872058034,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":1078219557,"bytesSent":1427,"packetsSent":7,"nackCount":0}
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - Track {23844939-9ed4-4a7f-b677-c341c75e91e9} has 7 outbound-rtp RTP packets.
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | RTP flowing for audio track {23844939-9ed4-4a7f-b677-c341c75e91e9}
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - Buffered messages finished
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Error in test execution: Error: Element local{23844939-9ed4-4a7f-b677-c341c75e91e9} should progress currentTime timeout/<@https://example.com/tests/dom/media/tests/mochitest/head.js:657:42 ...
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - execute/<@https://example.com/tests/dom/media/tests/mochitest/head.js:953:11
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - Closing peer connections
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - Waiting for track {7f75ff21-e4cc-4d54-a9a5-c09d74bebb4e} (audio) to end.
[task 2020-01-12T23:35:17.973Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: closed
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal): legal ICE state transition from connected to closed
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2876: GetStats: Found no pipelines matching selector.
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2192: CloseInt: Closing PeerConnectionImpl 4213026fcb977961; ending call
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: I/jsep [1578872057397000 (id=2147484310 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRen]: stable -> closed
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): "onsignalingstatechange" event fired
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | signalingState is closed
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcLocal): legal signaling state transition from stable to closed
[task 2020-01-12T23:35:17.974Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal): Closed connection.
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - Waiting for track {a35dd32b-fa58-49c2-a524-e679b24ea26f} (audio) to end.
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | iceConnectionState should not be undefined
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: closed
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote): legal ICE state transition from connected to closed
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2863: GetStats: Found no pipelines matching selector.
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2192: CloseInt: Closing PeerConnectionImpl 44d9b6b427e9923a; ending call
[task 2020-01-12T23:35:17.975Z] 23:35:17 INFO - GECKO(7816) | [Child 10508: Main Thread]: I/jsep [1578872057401000 (id=2147484310 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRen]: stable -> closed
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): "onsignalingstatechange" event fired
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | signalingState is closed
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | PeerConnectionWrapper (pcRemote): legal signaling state transition from stable to closed
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote): Closed connection.
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Event target should be the correct track
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - PeerConnectionWrapper (pcLocal) ended fired for track {7f75ff21-e4cc-4d54-a9a5-c09d74bebb4e}
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Event target should be the correct track
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - PeerConnectionWrapper (pcRemote) ended fired for track {a35dd32b-fa58-49c2-a524-e679b24ea26f}
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - GECKO(7816) | MEMORY STAT | vsize 19406131MB | vsizeMaxContiguous 70980974MB | residentFast 1832MB
[task 2020-01-12T23:35:17.976Z] 23:35:17 INFO - TEST-OK | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | took 60860ms
[task 2020-01-12T23:35:17.977Z] 23:35:17 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_verifyDescriptions.html

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

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.