1569387 - Intermittent dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Valid rtp timestamp 1564197184396 >= 1564197184544 (

Status: RESOLVED DUPLICATE of bug 1568075

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=258608535&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/MODFuj2zR8G6NpQ03a5kbw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-07-27T03:13:03.252Z] 03:13:03 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html
[task 2019-07-27T03:13:03.339Z] 03:13:03 INFO - [1659, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-07-27T03:13:03.349Z] 03:13:03 INFO - GECKO(1672) | ++DOMWINDOW == 8 (0x150b16400) [pid = 1674] [serial = 519] [outer = 0x12776a3e0]
[task 2019-07-27T03:13:03.349Z] 03:13:03 INFO - GECKO(1672) | --DOCSHELL 0x11f753000 == 2 [pid = 1674] [id = {9eec7570-e6ae-5f47-8e09-e2ace8cc2ce8}] [url = about:blank]
[task 2019-07-27T03:13:03.377Z] 03:13:03 INFO - GECKO(1672) | ++DOCSHELL 0x11f753000 == 3 [pid = 1674] [id = {dc40b01d-9200-e64a-8fb1-110e73c211ba}]
[task 2019-07-27T03:13:03.378Z] 03:13:03 INFO - GECKO(1672) | ++DOMWINDOW == 9 (0x12776b6a0) [pid = 1674] [serial = 520] [outer = 0x0]
[task 2019-07-27T03:13:03.400Z] 03:13:03 INFO - GECKO(1672) | ++DOMWINDOW == 10 (0x150d85000) [pid = 1674] [serial = 521] [outer = 0x12776b6a0]
[task 2019-07-27T03:13:03.428Z] 03:13:03 INFO - GECKO(1672) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2019-07-27T03:13:03.428Z] 03:13:03 INFO - GECKO(1672) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2019-07-27T03:13:03.490Z] 03:13:03 INFO - GECKO(1672) | Timecard created 1564197181.664315

[task 2019-07-27T03:13:05.691Z] 03:13:05 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 2019-07-27T03:13:05.691Z] 03:13:05 INFO - Found transceiver that should be receiving RTP: mid=0 currentDirection=recvonly kind=audio track-id={9abd394d-67a0-834e-ae13-41b095160b40}
[task 2019-07-27T03:13:05.691Z] 03:13:05 INFO - waitForRtpFlow({9abd394d-67a0-834e-ae13-41b095160b40})
[task 2019-07-27T03:13:05.691Z] 03:13:05 INFO - Element remote{9abd394d-67a0-834e-ae13-41b095160b40} has enough data.
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - Checking for stats in [["inbound_rtp_audio_0",{"id":"inbound_rtp_audio_0","timestamp":1564197184109,"type":"inbound-rtp","kind":"audio","mediaType":"audio","ssrc":3979264843,"jitter":0,"packetsLost":0,"packetsReceived":12,"bytesReceived":2332,"nackCount":0,"remoteId":"inbound_rtcp_audio_0"}],["inbound_rtcp_audio_0",{"id":"inbound_rtcp_audio_0","timestamp":1564197184109,"type":"remote-outbound-rtp","kind":"audio","mediaType":"audio","ssrc":3979264843,"bytesSent":643,"packetsSent":3,"localId":"inbound_rtp_audio_0"}],["AFc2",{"id":"AFc2","timestamp":1564197184109,"type":"candidate-pair","bytesReceived":3379,"bytesSent":830,"componentId":1,"lastPacketReceivedTimestamp":1564197185220,"lastPacketSentTimestamp":1564197185046,"localCandidateId":"hUfB","nominated":true,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"FwAH","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["hUfB",{"id":"hUfB","timestamp":1564197184109,"type":"local-candidate","address":"10.51.56.205","candidateType":"host","port":64853,"priority":2122252543,"protocol":"udp"}],["eVYN",{"id":"eVYN","timestamp":1564197184109,"type":"local-candidate","address":"10.51.56.205","candidateType":"host","port":54133,"priority":2105524479,"protocol":"tcp"}],["FwAH",{"id":"FwAH","timestamp":1564197184109,"type":"remote-candidate","address":"10.51.56.205","candidateType":"host","port":54470,"priority":2122252543,"protocol":"udp"}]] for audio track {9abd394d-67a0-834e-ae13-41b095160b40}retry number 0
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - Should have RTP stats for track {9abd394d-67a0-834e-ae13-41b095160b40}
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - RTP stats: {"id":"inbound_rtp_audio_0","timestamp":1564197184109,"type":"inbound-rtp","kind":"audio","mediaType":"audio","ssrc":3979264843,"jitter":0,"packetsLost":0,"packetsReceived":12,"bytesReceived":2332,"nackCount":0,"remoteId":"inbound_rtcp_audio_0"}
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - Track {9abd394d-67a0-834e-ae13-41b095160b40} has 12 inbound-rtp RTP packets.
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | RTP flowing for audio track {9abd394d-67a0-834e-ae13-41b095160b40}
[task 2019-07-27T03:13:05.696Z] 03:13:05 INFO - Run step 39: PC_LOCAL_CHECK_STATS
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - PeerConnectionWrapper (pcLocal): Got stats: {}
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - Checking stats for outbound_rtp_audio_0 : [object Object]
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Coherent stats id
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - Buffered messages finished
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Valid rtp timestamp 1564197184396 >= 1564197184544 (
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - -148 ms)
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:275:18
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - checkStats@https://example.com/tests/dom/media/tests/mochitest/pc.js:2109:9
[task 2019-07-27T03:13:05.697Z] 03:13:05 INFO - PC_LOCAL_CHECK_STATS/<@https://example.com/tests/dom/media/tests/mochitest/templates.js:522:20
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - promise callbackPC_LOCAL_CHECK_STATS@https://example.com/tests/dom/media/tests/mochitest/templates.js:521:36
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - execute/</<@https://example.com/tests/dom/media/tests/mochitest/head.js:944:32
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - promise callbackexecute/<@https://example.com/tests/dom/media/tests/mochitest/head.js:942:21
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - execute@https://example.com/tests/dom/media/tests/mochitest/head.js:937:8
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - PeerConnectionTest.prototype.run@https://example.com/tests/dom/media/tests/mochitest/pc.js:574:6
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - @https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html:95:10
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - runNetworkTest/<@https://example.com/tests/dom/media/tests/mochitest/pc.js:2564:11
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - asyncrunTestWhenReady/<@https://example.com/tests/dom/media/tests/mochitest/head.js:492:22
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - promise callbackrunTestWhenReady@https://example.com/tests/dom/media/tests/mochitest/head.js:492:6
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - runNetworkTest@https://example.com/tests/dom/media/tests/mochitest/pc.js:2545:9
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - async*@https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html:15:3
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Valid rtp timestamp 1564197184396 <= 1564197185764 (
[task 2019-07-27T03:13:05.698Z] 03:13:05 INFO - -1368 ms)
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Outbound RTP stats has an ssrc.
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | SSRC is numeric
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | SSRC is within limits
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Rtp packetsSent
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Rtp bytesSent
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - No rtcp info received yet
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - Checking stats for o/Vl : [object Object]
[task 2019-07-27T03:13:05.699Z] 03:13:05 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Coherent stats id
[task 2019-07-27T03:13:05.700Z] 03:13:05 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-07-27T03:13:05.700Z] 03:13:05 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Valid rtp timestamp 1564197184396 >= 1564197184544 (

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1569387&startday=2019-07-22&endday=2019-07-28&tree=all