Closed Bug 1547177 Opened 6 years ago Closed 6 years ago

Intermittent dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | Error in test execution: Error: Timeout checking for stats for track {d9b82546-e204-4124-a15e-56f93182c443} after at least30000ms waitForRtpFlow@http://mochi.test

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, regression)

#[markdown(off)]
Filed by: opoprus [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=242761069&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/LCKLZ6y_TqumQ27E4zEXnw/runs/0/artifacts/public/logs/live_backing.log

00:46:47 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html

00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:18 INFO - Checking for stats in [["outbound_rtp_audio_0",{"id":"outbound_rtp_audio_0","timestamp":1556239638269,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":3865433489,"bytesSent":0,"packetsSent":0,"nackCount":0,"remoteId":""}],["QRWL",{"id":"QRWL","timestamp":1556239638269,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"componentId":1,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"/r1N","nominated":false,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"JFyB","selected":false,"state":"cancelled","transportId":"transport_0","writable":true}],["CJMr",{"id":"CJMr","timestamp":1556239638269,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"componentId":1,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"Pnbl","nominated":false,"priority":9043088413699310000,"readable":true,"remoteCandidateId":"t+1p","selected":false,"state":"cancelled","transportId":"transport_0","writable":true}],["AA5U",{"id":"AA5U","timestamp":1556239638269,"type":"candidate-pair","bytesReceived":946,"bytesSent":935,"componentId":1,"lastPacketReceivedTimestamp":315811346774,"lastPacketSentTimestamp":315811347846,"localCandidateId":"/r1N","nominated":true,"priority":7962083765675491000,"readable":true,"remoteCandidateId":"GMCf","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["/r1N",{"id":"/r1N","timestamp":1556239638269,"type":"local-candidate","address":"10.145.68.105","candidateType":"host","port":63986,"priority":2122252543,"protocol":"udp"}],["Wlj1",{"id":"Wlj1","timestamp":1556239638269,"type":"local-candidate","address":"10.145.68.105","candidateType":"host","port":65107,"priority":2105508095,"protocol":"tcp"}],["Pnbl",{"id":"Pnbl","timestamp":1556239638269,"type":"local-candidate","address":"10.145.68.105","candidateType":"host","port":61368,"priority":2105524479,"protocol":"tcp"}],["GMCf",{"id":"GMCf","timestamp":1556239638269,"type":"remote-candidate","address":"10.145.68.105","candidateType":"prflx","port":63990,"priority":1853817087,"protocol":"udp"}],["JFyB",{"id":"JFyB","timestamp":1556239638269,"type":"remote-candidate","address":"10.145.68.105","candidateType":"host","port":63990,"priority":2122252543,"protocol":"udp"}],["t+1p",{"id":"t+1p","timestamp":1556239638269,"type":"remote-candidate","address":"10.145.68.105","candidateType":"host","port":53600,"priority":2105508095,"protocol":"tcp"}],["4g1a",{"id":"4g1a","timestamp":1556239638269,"type":"remote-candidate","address":"10.145.68.105","candidateType":"host","port":9,"priority":2105524479,"protocol":"tcp"}]] for audio track {816ad6a1-7bba-4e8d-893e-a42e6aa4a727}retry number 60
00:47:18 INFO - Should have RTP stats for track {816ad6a1-7bba-4e8d-893e-a42e6aa4a727}
00:47:18 INFO - RTP stats: {"id":"outbound_rtp_audio_0","timestamp":1556239638269,"type":"outbound-rtp","kind":"audio","mediaType":"audio","ssrc":3865433489,"bytesSent":0,"packetsSent":0,"nackCount":0,"remoteId":""}
00:47:18 INFO - Track {816ad6a1-7bba-4e8d-893e-a42e6aa4a727} has 0 outbound-rtp RTP packets.
00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:18 INFO - Buffered messages finished
00:47:18 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | Error in test execution: Error: Timeout checking for stats for track {d9b82546-e204-4124-a15e-56f93182c443} after at least30000ms waitForRtpFlow@http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1582:11 ... async*waitForMediaFlow/<@http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1634:63 ... waitForMediaFlow@http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1634:45 ... PC_LOCAL_WAIT_FOR_MEDIA_FLOW@http://mochi.test:8888/tests/dom/media/tests/mochitest/templates.js:372:25 ... execute/</<@http://mochi.test:8888/tests/dom/media/tests/mochitest/head.js:852:31 ...
00:47:18 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
00:47:18 INFO - execute/<@dom/media/tests/mochitest/head.js:856:14
00:47:18 INFO - promise callback*execute@dom/media/tests/mochitest/head.js:855:8
00:47:18 INFO - PeerConnectionTest.prototype.run@dom/media/tests/mochitest/pc.js:486:21
00:47:18 INFO - @dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:66:10
00:47:18 INFO - runNetworkTest/<@dom/media/tests/mochitest/pc.js:2180:13
00:47:18 INFO - async*runTestWhenReady/<@dom/media/tests/mochitest/head.js:473:41
00:47:18 INFO - promise callback*runTestWhenReady@dom/media/tests/mochitest/head.js:473:25
00:47:18 INFO - runNetworkTest@dom/media/tests/mochitest/pc.js:2162:9
00:47:18 INFO - async*@dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:15:3
00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:18 INFO - Closing peer connections
00:47:18 INFO - Waiting for track {d9b82546-e204-4124-a15e-56f93182c443} (audio) to end.
00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | iceConnectionState should not be undefined
00:47:18 INFO - PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: closed
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | PeerConnectionWrapper (pcLocal): legal ICE state transition from connected to closed
00:47:18 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2275: CloseInt: Closing PeerConnectionImpl 1ccbc7610b4d7875; ending call
00:47:18 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/jsep [1556239607420000 (id=6442451512 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_restartIceLocalR]: stable -> closed
00:47:18 INFO - PeerConnectionWrapper (pcLocal): "onsignalingstatechange" event fired
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | signalingState is closed
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | PeerConnectionWrapper (pcLocal): legal signaling state transition from stable to closed
00:47:18 INFO - PeerConnectionWrapper (pcLocal): Closed connection.
00:47:18 INFO - Waiting for track {3873185b-adcb-4c30-8374-a229016b866d} (audio) to end.
00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | iceConnectionState should not be undefined
00:47:18 INFO - PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: closed
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | PeerConnectionWrapper (pcRemote): legal ICE state transition from connected to closed
00:47:18 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2275: CloseInt: Closing PeerConnectionImpl 308a4643fa2c5854; ending call
00:47:18 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/jsep [1556239607423000 (id=6442451512 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_restartIceLocalR]: stable -> closed
00:47:18 INFO - PeerConnectionWrapper (pcRemote): "onsignalingstatechange" event fired
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | signalingState is closed
00:47:18 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | PeerConnectionWrapper (pcRemote): legal signaling state transition from stable to closed
00:47:18 INFO - PeerConnectionWrapper (pcRemote): Closed connection.
00:47:18 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
00:47:23 INFO - GECKO(7076) | Timecard created 1556239607.419000
00:47:23 INFO - GECKO(7076) | Timestamp | Delta | Event | File | Function
00:47:23 INFO - GECKO(7076) | ======================================================================================================================
00:47:23 INFO - GECKO(7076) | 0.001000 | 0.001000 | Constructor Completed | PeerConnectionImpl.cpp:341 | PeerConnectionImpl
00:47:23 INFO - GECKO(7076) | 0.001000 | 0.000000 | Initializing PC Ctx | PeerConnectionImpl.cpp:468 | Initialize
00:47:23 INFO - GECKO(7076) | 0.110000 | 0.109000 | Create Offer | PeerConnectionImpl.cpp:1269 | CreateOffer
00:47:23 INFO - GECKO(7076) | 0.112000 | 0.002000 | Set Local Description | PeerConnectionImpl.cpp:1339 | SetLocalDescription
00:47:23 INFO - GECKO(7076) | 0.143000 | 0.031000 | Set Remote Description | PeerConnectionImpl.cpp:1431 | SetRemoteDescription
00:47:23 INFO - GECKO(7076) | 0.176000 | 0.033000 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2627 | IceGatheringStateChange
00:47:23 INFO - GECKO(7076) | 0.177000 | 0.001000 | Ice gathering state: complete | PeerConnectionImpl.cpp:2630 | IceGatheringStateChange
00:47:23 INFO - GECKO(7076) | 0.324000 | 0.147000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.355000 | 0.031000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.391000 | 0.036000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.423000 | 0.032000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.489000 | 0.066000 | Ice state: checking | PeerConnectionImpl.cpp:2582 | IceConnectionStateChange
00:47:23 INFO - GECKO(7076) | 0.568000 | 0.079000 | Ice state: connected | PeerConnectionImpl.cpp:2585 | IceConnectionStateChange
00:47:23 INFO - GECKO(7076) | 36.525000 | 35.957000 | Destructor Invoked | PeerConnectionImpl.cpp:350 | ~PeerConnectionImpl
00:47:23 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:375: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 1ccbc7610b4d7875
00:47:23 INFO - GECKO(7076) | Timecard created 1556239607.423000
00:47:23 INFO - GECKO(7076) | Timestamp | Delta | Event | File | Function
00:47:23 INFO - GECKO(7076) | ======================================================================================================================
00:47:23 INFO - GECKO(7076) | 0.000000 | 0.000000 | Constructor Completed | PeerConnectionImpl.cpp:341 | PeerConnectionImpl
00:47:23 INFO - GECKO(7076) | 0.000000 | 0.000000 | Initializing PC Ctx | PeerConnectionImpl.cpp:468 | Initialize
00:47:23 INFO - GECKO(7076) | 0.112000 | 0.112000 | Set Remote Description | PeerConnectionImpl.cpp:1431 | SetRemoteDescription
00:47:23 INFO - GECKO(7076) | 0.132000 | 0.020000 | Create Answer | PeerConnectionImpl.cpp:1301 | CreateAnswer
00:47:23 INFO - GECKO(7076) | 0.134000 | 0.002000 | Set Local Description | PeerConnectionImpl.cpp:1339 | SetLocalDescription
00:47:23 INFO - GECKO(7076) | 0.173000 | 0.039000 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2627 | IceGatheringStateChange
00:47:23 INFO - GECKO(7076) | 0.212000 | 0.039000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.215000 | 0.003000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.231000 | 0.016000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.243000 | 0.012000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.258000 | 0.015000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.270000 | 0.012000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.282000 | 0.012000 | Add Ice Candidate | PeerConnectionImpl.cpp:1591 | AddIceCandidate
00:47:23 INFO - GECKO(7076) | 0.422000 | 0.140000 | Ice gathering state: complete | PeerConnectionImpl.cpp:2630 | IceGatheringStateChange
00:47:23 INFO - GECKO(7076) | 0.422000 | 0.000000 | Ice state: checking | PeerConnectionImpl.cpp:2582 | IceConnectionStateChange
00:47:23 INFO - GECKO(7076) | 0.564000 | 0.142000 | Ice state: connected | PeerConnectionImpl.cpp:2585 | IceConnectionStateChange
00:47:23 INFO - GECKO(7076) | 36.528000 | 35.964000 | Destructor Invoked | PeerConnectionImpl.cpp:350 | ~PeerConnectionImpl
00:47:23 INFO - GECKO(7076) | [Child 9728: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:375: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 308a4643fa2c5854
00:48:08 INFO - Not taking screenshot here: see the one that was previously logged
00:48:08 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | ended never fired for track {d9b82546-e204-4124-a15e-56f93182c443}
00:48:08 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
00:48:08 INFO - closeIt/promise</<@dom/media/tests/mochitest/pc.js:156:25
00:48:08 INFO - promise callback*closeIt/promise<@dom/media/tests/mochitest/pc.js:152:14
00:48:08 INFO - closeIt@dom/media/tests/mochitest/pc.js:148:10
00:48:08 INFO - PeerConnectionTest.prototype.closePC@dom/media/tests/mochitest/pc.js:165:5
00:48:08 INFO - PeerConnectionTest.prototype.close/<@dom/media/tests/mochitest/pc.js:178:22
00:48:08 INFO - promise callback*PeerConnectionTest.prototype.close@dom/media/tests/mochitest/pc.js:178:6
00:48:08 INFO - PeerConnectionTest.prototype.run/<@dom/media/tests/mochitest/pc.js:487:22
00:48:08 INFO - promise callback*PeerConnectionTest.prototype.run@dom/media/tests/mochitest/pc.js:487:6
00:48:08 INFO - @dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:66:10
00:48:08 INFO - runNetworkTest/<@dom/media/tests/mochitest/pc.js:2180:13
00:48:08 INFO - async*runTestWhenReady/<@dom/media/tests/mochitest/head.js:473:41
00:48:08 INFO - promise callback*runTestWhenReady@dom/media/tests/mochitest/head.js:473:25
00:48:08 INFO - runNetworkTest@dom/media/tests/mochitest/pc.js:2162:9
00:48:08 INFO - async*@dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:15:3
00:48:08 INFO - Not taking screenshot here: see the one that was previously logged
00:48:08 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | ended never fired for track {3873185b-adcb-4c30-8374-a229016b866d}
00:48:08 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
00:48:08 INFO - closeIt/promise</<@dom/media/tests/mochitest/pc.js:156:25
00:48:08 INFO - promise callback*closeIt/promise<@dom/media/tests/mochitest/pc.js:152:14
00:48:08 INFO - closeIt@dom/media/tests/mochitest/pc.js:148:10
00:48:08 INFO - PeerConnectionTest.prototype.closePC@dom/media/tests/mochitest/pc.js:166:5
00:48:08 INFO - PeerConnectionTest.prototype.close/<@dom/media/tests/mochitest/pc.js:178:22
00:48:08 INFO - promise callback*PeerConnectionTest.prototype.close@dom/media/tests/mochitest/pc.js:178:6
00:48:08 INFO - PeerConnectionTest.prototype.run/<@dom/media/tests/mochitest/pc.js:487:22
00:48:08 INFO - promise callback*PeerConnectionTest.prototype.run@dom/media/tests/mochitest/pc.js:487:6
00:48:08 INFO - @dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:66:10
00:48:08 INFO - runNetworkTest/<@dom/media/tests/mochitest/pc.js:2180:13
00:48:08 INFO - async*runTestWhenReady/<@dom/media/tests/mochitest/head.js:473:41
00:48:08 INFO - promise callback*runTestWhenReady@dom/media/tests/mochitest/head.js:473:25
00:48:08 INFO - runNetworkTest@dom/media/tests/mochitest/pc.js:2162:9
00:48:08 INFO - async*@dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html:15:3
00:48:08 INFO - GECKO(7076) | MEMORY STAT | vsize 2104075MB | vsizeMaxContiguous 70429110MB | residentFast 153MB | heapAllocated 21MB
00:48:08 INFO - TEST-OK | dom/media/tests/mochitest/test_peerConnection_restartIceLocalRollback.html | took 81796ms

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

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