1593184 - Intermittent dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 <= 1572572974885 (

Status: RESOLVED DUPLICATE of bug 1597254

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=274003575&repo=mozilla-beta
Full log: https://queue.taskcluster.net/v1/task/O4Z3M5K9TOC4hWHCc-Y0Wg/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-11-01T01:49:38.215Z] 01:49:38 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html
[task 2019-11-01T01:49:38.294Z] 01:49:38 INFO - GECKO(1697) | ++DOMWINDOW == 11 (0x10f262400) [pid = 1698] [serial = 100] [outer = 0x12033d5c0]
[task 2019-11-01T01:49:38.439Z] 01:49:38 INFO - GECKO(1697) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2019-11-01T01:49:38.439Z] 01:49:38 INFO - GECKO(1697) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2019-11-01T01:49:38.673Z] 01:49:38 INFO - GECKO(1697) | ++DOCSHELL 0x10f307800 == 5 [pid = 1698] [id = {5cc0d971-f294-0047-a93a-f33227ef55a4}]
[task 2019-11-01T01:49:38.673Z] 01:49:38 INFO - GECKO(1697) | ++DOMWINDOW == 12 (0x1217de7a0) [pid = 1698] [serial = 101] [outer = 0x0]
[task 2019-11-01T01:49:38.673Z] 01:49:38 INFO - GECKO(1697) | ++DOMWINDOW == 13 (0x10f282800) [pid = 1698] [serial = 102] [outer = 0x1217de7a0]
[task 2019-11-01T01:49:38.807Z] 01:49:38 INFO - GECKO(1697) | --DOMWINDOW == 12 (0x10f26cc00) [pid = 1698] [serial = 97] [outer = 0x0] [url = about:srcdoc]
[task 2019-11-01T01:49:38.807Z] 01:49:38 INFO - GECKO(1697) | --DOCSHELL 0x10f303000 == 4 [pid = 1698] [id = {db64a5f8-e000-5642-8942-72176b49145a}] [url = about:srcdoc]
[task 2019-11-01T01:49:38.899Z] 01:49:38 INFO - GECKO(1697) | --DOMWINDOW == 11 (0x10f1d3400) [pid = 1698] [serial = 98] [outer = 0x0] [url = about:srcdoc]
[task 2019-11-01T01:49:38.900Z] 01:49:38 INFO - GECKO(1697) | --DOMWINDOW == 10 (0x10f1d3c00) [pid = 1698] [serial = 99] [outer = 0x0] [url = https://example.com/tests/SimpleTest/iframe-between-tests.html]
[task 2019-11-01T01:49:38.900Z] 01:49:38 INFO - GECKO(1697) | --DOMWINDOW == 9 (0x1217de5c0) [pid = 1698] [serial = 96] [outer = 0x0] [url = about:srcdoc]
[task 2019-11-01T01:49:38.900Z] 01:49:38 INFO - GECKO(1697) | --DOMWINDOW == 8 (0x10f260000) [pid = 1698] [serial = 95] [outer = 0x0] [url = https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_trackEnded.html]
[task 2019-11-01T01:49:39.015Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:344: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2019-11-01T01:49:39.016Z] 01:49:39 INFO - GECKO(1697) | (unknown/INFO) insert '' (registry) succeeded:
[task 2019-11-01T01:49:39.016Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) Initialized registry
[task 2019-11-01T01:49:39.016Z] 01:49:39 INFO - GECKO(1697) | [Parent 1697: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2019-11-01T01:49:39.024Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:344: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2019-11-01T01:49:39.024Z] 01:49:39 INFO - GECKO(1697) | [Parent 1697: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2019-11-01T01:49:39.035Z] 01:49:39 INFO - GECKO(1697) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2019-11-01T01:49:39.035Z] 01:49:39 INFO - GECKO(1697) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2019-11-01T01:49:39.035Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice' (registry) succeeded: ice
[task 2019-11-01T01:49:39.035Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref' (registry) succeeded: ice.pref
[task 2019-11-01T01:49:39.035Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type' (registry) succeeded: ice.pref.type
[task 2019-11-01T01:49:39.036Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.srv_rflx_tcp' (UCHAR) succeeded: 0x63
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.peer_rflx_tcp' (UCHAR) succeeded: 0x6d
[task 2019-11-01T01:49:39.037Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.host_tcp' (UCHAR) succeeded: 0x7d
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'stun' (registry) succeeded: stun
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'stun.client' (registry) succeeded: stun.client
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'stun.client.maximum_transmits' (UINT4) succeeded: 14
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.trickle_grace_period' (UINT4) succeeded: 30000
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.tcp' (registry) succeeded: ice.tcp
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.tcp.so_sock_count' (INT4) succeeded: 0
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.tcp.listen_backlog' (INT4) succeeded: 10
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | (registry/INFO) insert 'ice.tcp.disable' (char) succeeded: \000
[task 2019-11-01T01:49:39.038Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:72: OnStunAddrsAvailable: receiving (6) stun addrs
[task 2019-11-01T01:49:39.039Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:72: OnStunAddrsAvailable: receiving (6) stun addrs
[task 2019-11-01T01:49:39.041Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1281
[task 2019-11-01T01:49:39.041Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1283
[task 2019-11-01T01:49:39.041Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.spatial", &temp))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1320
[task 2019-11-01T01:49:39.041Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.temporal", &temp))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1326
[task 2019-11-01T01:49:39.041Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.peerconnection.video.lock_scaling", &mLockScaling))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1334
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x10f20bc10
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/jsep [1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis]: stable -> have-local-offer
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x10f3d3120
[task 2019-11-01T01:49:39.127Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/jsep [1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis]: stable -> have-remote-offer
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1281
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1283
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.spatial", &temp))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1320
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.temporal", &temp))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1326
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.peerconnection.video.lock_scaling", &mLockScaling))', file /builds/worker/workspace/build/src/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1334
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:1453: SetRemoteDescription: pc = f706410cd658b744, asking JS to create transceiver
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-11-01T01:49:39.128Z] 01:49:39 INFO - GECKO(1697) | [Child 1698, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-11-01T01:49:39.152Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x10f3d7190
[task 2019-11-01T01:49:39.152Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/jsep [1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis]: have-remote-offer -> stable
[task 2019-11-01T01:49:39.152Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x10f3d73c0
[task 2019-11-01T01:49:39.153Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Main Thread]: I/jsep [1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis]: have-local-offer -> stable
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (generic/INFO) Exit UDP socket connected
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) /builds/worker/workspace/build/src/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): failed to create passive TCP host candidate: 3
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) /builds/worker/workspace/build/src/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): failed to create passive TCP host candidate: 3
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (generic/INFO) Exit UDP socket connected
[task 2019-11-01T01:49:39.194Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) /builds/worker/workspace/build/src/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): failed to create passive TCP host candidate: 3
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) has no stream matching stream PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0 - ab1d13cd:1a43d999663b6fe60ed3b9612100f0b7
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Setting up DTLS as client
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: E/mtransport Couldn't disable 'PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0':2
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no streams with non-empty check lists
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no streams with pre-answer requests
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no checks to start
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't start peer checks on PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis, assuming trickle ICE
[task 2019-11-01T01:49:39.195Z] 01:49:39 INFO - GECKO(1697) | (ice/WARNING) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) has no stream matching stream PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0 - 7ba7d943:2d8c8595c8559d144f6e31cc64c0315f
[task 2019-11-01T01:49:39.196Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Setting up DTLS as server
[task 2019-11-01T01:49:39.196Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no streams with non-empty check lists
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no streams with pre-answer requests
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | (ice/NOTICE) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) no checks to start
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't start peer checks on PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis, assuming trickle ICE
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:0 1 UDP 2122252543 10.51.56.212 50539 typ host
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0', no candidates.
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:50539/UDP)
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:1 1 TCP 2105524479 10.51.56.212 9 typ host tcptype active
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0', no candidates.
[task 2019-11-01T01:49:39.197Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:55319/TCP) active
[task 2019-11-01T01:49:39.198Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:0 2 UDP 2122252542 10.51.56.212 54998 typ host
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:54998/UDP)
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:1 2 TCP 2105524478 10.51.56.212 9 typ host tcptype active
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:54355/TCP) active
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE(PC:1572572979006843 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): All candidates initialized
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:0 1 UDP 2122252543 10.51.56.212 63462 typ host
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0', no candidates.
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:63462/UDP)
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport NrIceCtx(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): trickling candidate candidate:1 1 TCP 2105524479 10.51.56.212 9 typ host tcptype active
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0', no candidates.
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/ERR) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): peer (PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default) pairing local trickle ICE candidate host(IP4:10.51.56.212:53886/TCP) active
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0', no candidates.
[task 2019-11-01T01:49:39.201Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis): All candidates initialized
[task 2019-11-01T01:49:39.206Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE-PEER(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default)/CAND-PAIR(4/7e): setting pair to state FROZEN: 4/7e|IP4:10.51.56.212:63462/UDP|IP4:10.51.56.212:50539/UDP(host(IP4:10.51.56.212:63462/UDP)|candidate:0 1 UDP 2122252543 10.51.56.212 50539 typ host)
[task 2019-11-01T01:49:39.207Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis)/CAND-PAIR(4/7e): Pairing candidate IP4:10.51.56.212:63462/UDP (7e7f00ff):IP4:10.51.56.212:50539/UDP (7e7f00ff) priority=9115005270282338815 (7e7f00fffcfe01ff)
[task 2019-11-01T01:49:39.207Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE-PEER(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default)/ICE-STREAM(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis transport-id=transport_0 - ab1d13cd:1a43d999663b6fe60ed3b9612100f0b7): Starting check timer for stream.
[task 2019-11-01T01:49:39.207Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE-PEER(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default)/CAND-PAIR(4/7e): setting pair to state WAITING: 4/7e|IP4:10.51.56.212:63462/UDP|IP4:10.51.56.212:50539/UDP(host(IP4:10.51.56.212:63462/UDP)|candidate:0 1 UDP 2122252543 10.51.56.212 50539 typ host)
[task 2019-11-01T01:49:39.207Z] 01:49:39 INFO - GECKO(1697) | (ice/INFO) ICE-PEER(PC:1572572979013121 (id=2147483744 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExis:default)/CAND-PAIR(4/7e): setting pair to state IN_PROGRESS: 4/7e|IP4:10.51.56.212:63462/UDP|IP4:10.51.56.212:50539/UDP(host(IP4:10.51.56.212:63462/UDP)|candidate:0 1 UDP 2122252543 10.51.56.212 50539 typ host)
...
[task 2019-11-01T01:49:39.264Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Created SRTP flow!
[task 2019-11-01T01:49:39.264Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: ****** SSL handshake completed ******
[task 2019-11-01T01:49:39.264Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Selected ALPN string: webrtc
[task 2019-11-01T01:49:39.264Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Socket Thread]: D/mtransport Created SRTP flow!
[task 2019-11-01T01:49:39.264Z] 01:49:39 INFO - GECKO(1697) | [Child 1698: Unnamed thread 0x1216b6d90]: I/signaling [|WebrtcVideoSessionConduit] VideoStreamFactory.cpp:197: CreateEncoderStreams Input frame 320x240, RID scaling to 320x240
[task 2019-11-01T01:49:34.909Z] 01:49:34 INFO - TEST-INFO | started process screencapture
[task 2019-11-01T01:49:34.948Z] 01:49:34 INFO - TEST-INFO | screencapture: exit 0
[task 2019-11-01T01:49:34.948Z] 01:49:34 INFO - <snipped 196 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-11-01T01:49:34.948Z] 01:49:34 INFO - Buffered messages logged at 01:49:39
[task 2019-11-01T01:49:34.948Z] 01:49:34 INFO - PeerConnectionWrapper (pcRemote): adding ICE candidate {"candidate":"candidate:0 2 UDP 2122252542 10.51.56.212 54998 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"}
[task 2019-11-01T01:49:34.948Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | PeerConnectionWrapper (pcRemote) successfully added an ICE candidate
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - pcLocal: iceCandidate = {"candidate":"candidate:1 2 TCP 2105524478 10.51.56.212 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"}
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP mid not empty
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | usernameFragment not empty
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP MLine Index needs to exist
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - Received: {"candidate":"candidate:1 2 TCP 2105524478 10.51.56.212 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"} from pcLocal
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - PeerConnectionWrapper (pcRemote): adding ICE candidate {"candidate":"candidate:1 2 TCP 2105524478 10.51.56.212 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"}
[task 2019-11-01T01:49:34.949Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | PeerConnectionWrapper (pcRemote) successfully added an ICE candidate
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - pcLocal: iceCandidate = {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"}
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP mid not empty
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | usernameFragment not empty
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP MLine Index needs to exist
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - Received: {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"} from pcLocal
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - PeerConnectionWrapper (pcRemote): adding ICE candidate {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"7ba7d943"}
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | PeerConnectionWrapper (pcRemote) successfully added an ICE candidate
[task 2019-11-01T01:49:34.950Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | iceGetheringState should not be undefined
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - PeerConnectionWrapper (pcLocal): onicegatheringstatechange fired, new state is: complete
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - pcLocal: received end of trickle ICE event
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | ICE gathering state has reached complete
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - pcRemote: iceCandidate = {"candidate":"candidate:0 1 UDP 2122252543 10.51.56.212 63462 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ab1d13cd"}
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP mid not empty
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | usernameFragment not empty
[task 2019-11-01T01:49:34.951Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP MLine Index needs to exist
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - Received: {"candidate":"candidate:0 1 UDP 2122252543 10.51.56.212 63462 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ab1d13cd"} from pcRemote
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - PeerConnectionWrapper (pcLocal): adding ICE candidate {"candidate":"candidate:0 1 UDP 2122252543 10.51.56.212 63462 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ab1d13cd"}
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | PeerConnectionWrapper (pcLocal) successfully added an ICE candidate
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - pcRemote: iceCandidate = {"candidate":"candidate:1 1 TCP 2105524479 10.51.56.212 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ab1d13cd"}
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP mid not empty
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | usernameFragment not empty
[task 2019-11-01T01:49:34.952Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SDP MLine Index needs to exist
...
[task 2019-11-01T01:49:34.957Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | PeerConnectionWrapper (pcRemote) ICE gathering state is not 'new'
[task 2019-11-01T01:49:34.957Z] 01:49:34 INFO - Run step 37: PC_LOCAL_WAIT_FOR_MEDIA_FLOW
[task 2019-11-01T01:49:34.957Z] 01:49:34 INFO - Checking data flow for element: local{cc9048d2-a1b3-754e-87df-bc2aef38f70c}
[task 2019-11-01T01:49:34.957Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Element ended should be the inverse of the MediaStream's active state
[task 2019-11-01T01:49:34.957Z] 01:49:34 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - waitForRtpFlow({cc9048d2-a1b3-754e-87df-bc2aef38f70c})
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - Element local{cc9048d2-a1b3-754e-87df-bc2aef38f70c} has enough data.
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - Checking for stats in [["outbound_rtp_video_0",{"id":"outbound_rtp_video_0","timestamp":1572572979213,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":293597181,"bytesSent":0,"packetsSent":0,"bitrateMean":null,"bitrateStdDev":null,"droppedFrames":0,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesEncoded":0,"nackCount":0,"pliCount":0,"remoteId":""}],["GklO",{"id":"GklO","timestamp":1572572979213,"type":"candidate-pair","bytesReceived":779,"bytesSent":795,"componentId":1,"lastPacketReceivedTimestamp":1572572979209,"lastPacketSentTimestamp":1572572979212,"localCandidateId":"r/gP","nominated":true,"priority":7962083765675491000,"readable":true,"remoteCandidateId":"ms/Z","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["r/gP",{"id":"r/gP","timestamp":1572572979213,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":50539,"priority":2122252543,"protocol":"udp","proxied":"non-proxied"}],["ILMf",{"id":"ILMf","timestamp":1572572979213,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":55319,"priority":2105524479,"protocol":"tcp","proxied":"non-proxied"}],["ms/Z",{"id":"ms/Z","timestamp":1572572979213,"type":"remote-candidate","address":"10.51.56.212","candidateType":"prflx","port":63462,"priority":1853817087,"protocol":"udp","proxied":"non-proxied"}]] for video track {cc9048d2-a1b3-754e-87df-bc2aef38f70c}retry number 0
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - Should have RTP stats for track {cc9048d2-a1b3-754e-87df-bc2aef38f70c}
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - RTP stats: {"id":"outbound_rtp_video_0","timestamp":1572572979213,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":293597181,"bytesSent":0,"packetsSent":0,"bitrateMean":null,"bitrateStdDev":null,"droppedFrames":0,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesEncoded":0,"nackCount":0,"pliCount":0,"remoteId":""}
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - Track {cc9048d2-a1b3-754e-87df-bc2aef38f70c} has 0 outbound-rtp RTP packets.
[task 2019-11-01T01:49:34.958Z] 01:49:34 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - Checking for stats in [["outbound_rtp_video_0",{"id":"outbound_rtp_video_0","timestamp":1572572979799,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":293597181,"bytesSent":2849,"packetsSent":12,"bitrateMean":null,"bitrateStdDev":null,"droppedFrames":0,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesEncoded":0,"nackCount":0,"pliCount":0,"remoteId":""}],["GklO",{"id":"GklO","timestamp":1572572979799,"type":"candidate-pair","bytesReceived":859,"bytesSent":3936,"componentId":1,"lastPacketReceivedTimestamp":1572572979343,"lastPacketSentTimestamp":1572572979675,"localCandidateId":"r/gP","nominated":true,"priority":7962083765675491000,"readable":true,"remoteCandidateId":"ms/Z","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["r/gP",{"id":"r/gP","timestamp":1572572979799,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":50539,"priority":2122252543,"protocol":"udp","proxied":"non-proxied"}],["ILMf",{"id":"ILMf","timestamp":1572572979799,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":55319,"priority":2105524479,"protocol":"tcp","proxied":"non-proxied"}],["ms/Z",{"id":"ms/Z","timestamp":1572572979799,"type":"remote-candidate","address":"10.51.56.212","candidateType":"prflx","port":63462,"priority":1853817087,"protocol":"udp","proxied":"non-proxied"}]] for video track {cc9048d2-a1b3-754e-87df-bc2aef38f70c}retry number 1
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - Should have RTP stats for track {cc9048d2-a1b3-754e-87df-bc2aef38f70c}
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - RTP stats: {"id":"outbound_rtp_video_0","timestamp":1572572979799,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":293597181,"bytesSent":2849,"packetsSent":12,"bitrateMean":null,"bitrateStdDev":null,"droppedFrames":0,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesEncoded":0,"nackCount":0,"pliCount":0,"remoteId":""}
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - Track {cc9048d2-a1b3-754e-87df-bc2aef38f70c} has 12 outbound-rtp RTP packets.
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | RTP flowing for video track {cc9048d2-a1b3-754e-87df-bc2aef38f70c}
[task 2019-11-01T01:49:34.959Z] 01:49:34 INFO - Run step 38: PC_REMOTE_WAIT_FOR_MEDIA_FLOW
[task 2019-11-01T01:49:34.960Z] 01:49:34 INFO - Found transceiver that should be receiving RTP: mid=0 currentDirection=recvonly kind=video track-id={a236a037-06bc-b04f-bb2b-8d1d4f8023a2}
[task 2019-11-01T01:49:34.960Z] 01:49:34 INFO - Checking data flow for element: remote{a236a037-06bc-b04f-bb2b-8d1d4f8023a2}
[task 2019-11-01T01:49:34.960Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Element ended should be the inverse of the MediaStream's active state
[task 2019-11-01T01:49:34.962Z] 01:49:34 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2019-11-01T01:49:34.962Z] 01:49:34 INFO - Found transceiver that should be receiving RTP: mid=0 currentDirection=recvonly kind=video track-id={a236a037-06bc-b04f-bb2b-8d1d4f8023a2}
[task 2019-11-01T01:49:34.962Z] 01:49:34 INFO - waitForRtpFlow({a236a037-06bc-b04f-bb2b-8d1d4f8023a2})
[task 2019-11-01T01:49:34.963Z] 01:49:34 INFO - Element remote{a236a037-06bc-b04f-bb2b-8d1d4f8023a2} has enough data.
[task 2019-11-01T01:49:34.963Z] 01:49:34 INFO - Checking for stats in [["inbound_rtp_video_0",{"id":"inbound_rtp_video_0","timestamp":1572572979805,"type":"inbound-rtp","kind":"video","mediaType":"video","ssrc":0,"discardedPackets":0,"jitter":0,"packetsLost":0,"packetsReceived":12,"bitrateMean":null,"bitrateStdDev":null,"bytesReceived":2849,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesDecoded":0,"nackCount":0,"pliCount":0,"remoteId":"inbound_rtcp_video_0"}],["inbound_rtcp_video_0",{"id":"inbound_rtcp_video_0","timestamp":1572572979805,"type":"remote-outbound-rtp","kind":"video","mediaType":"video","ssrc":0,"bytesSent":0,"packetsSent":0,"localId":"inbound_rtp_video_0"}],["4/7e",{"id":"4/7e","timestamp":1572572979805,"type":"candidate-pair","bytesReceived":3936,"bytesSent":859,"componentId":1,"lastPacketReceivedTimestamp":1572572979676,"lastPacketSentTimestamp":1572572979343,"localCandidateId":"R/Hb","nominated":true,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"trSY","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["R/Hb",{"id":"R/Hb","timestamp":1572572979805,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":63462,"priority":2122252543,"protocol":"udp","proxied":"non-proxied"}],["TH/4",{"id":"TH/4","timestamp":1572572979805,"type":"local-candidate","address":"10.51.56.212","candidateType":"host","port":53886,"priority":2105524479,"protocol":"tcp","proxied":"non-proxied"}],["trSY",{"id":"trSY","timestamp":1572572979805,"type":"remote-candidate","address":"10.51.56.212","candidateType":"host","port":50539,"priority":2122252543,"protocol":"udp","proxied":"non-proxied"}],["PJ6o",{"id":"PJ6o","timestamp":1572572979805,"type":"remote-candidate","address":"10.51.56.212","candidateType":"host","port":9,"priority":2105524479,"protocol":"tcp","proxied":"non-proxied"}]] for video track {a236a037-06bc-b04f-bb2b-8d1d4f8023a2}retry number 0
[task 2019-11-01T01:49:34.971Z] 01:49:34 INFO - Should have RTP stats for track {a236a037-06bc-b04f-bb2b-8d1d4f8023a2}
[task 2019-11-01T01:49:34.971Z] 01:49:34 INFO - RTP stats: {"id":"inbound_rtp_video_0","timestamp":1572572979805,"type":"inbound-rtp","kind":"video","mediaType":"video","ssrc":0,"discardedPackets":0,"jitter":0,"packetsLost":0,"packetsReceived":12,"bitrateMean":null,"bitrateStdDev":null,"bytesReceived":2849,"firCount":0,"framerateMean":null,"framerateStdDev":null,"framesDecoded":0,"nackCount":0,"pliCount":0,"remoteId":"inbound_rtcp_video_0"}
[task 2019-11-01T01:49:34.971Z] 01:49:34 INFO - Track {a236a037-06bc-b04f-bb2b-8d1d4f8023a2} has 12 inbound-rtp RTP packets.
[task 2019-11-01T01:49:34.971Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | RTP flowing for video track {a236a037-06bc-b04f-bb2b-8d1d4f8023a2}
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - Buffered messages logged at 01:49:34
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - Run step 39: PC_LOCAL_CHECK_STATS
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - PeerConnectionWrapper (pcLocal): Got stats: {}
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - Checking stats for outbound_rtp_video_0 : [object Object]
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Coherent stats id
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 >= 1572572978744 (
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - 1185 ms)
[task 2019-11-01T01:49:34.972Z] 01:49:34 INFO - Buffered messages finished
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 <= 1572572974885 (
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - 5044 ms)
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - checkStats@https://example.com/tests/dom/media/tests/mochitest/pc.js:2106:11
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - PC_LOCAL_CHECK_STATS/<@https://example.com/tests/dom/media/tests/mochitest/templates.js:522:20
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Outbound RTP stats has an ssrc.
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SSRC is numeric
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | SSRC is within limits
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Rtp packetsSent
[task 2019-11-01T01:49:34.973Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Rtp bytesSent
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - No rtcp info received yet
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - Checking stats for GklO : [object Object]
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Coherent stats id
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 >= 1572572978744 (
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - 1185 ms)
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 <= 1572572974891 (
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - 5038 ms)
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - checkStats@https://example.com/tests/dom/media/tests/mochitest/pc.js:2106:11
[task 2019-11-01T01:49:34.974Z] 01:49:34 INFO - PC_LOCAL_CHECK_STATS/<@https://example.com/tests/dom/media/tests/mochitest/templates.js:522:20
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - Checking stats for r/gP : [object Object]
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Coherent stats id
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 >= 1572572978744 (
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - 1185 ms)
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 <= 1572572974892 (
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - 5037 ms)
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - checkStats@https://example.com/tests/dom/media/tests/mochitest/pc.js:2106:11
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - PC_LOCAL_CHECK_STATS/<@https://example.com/tests/dom/media/tests/mochitest/templates.js:522:20
[task 2019-11-01T01:49:34.975Z] 01:49:34 INFO - Checking stats for ILMf : [object Object]
[task 2019-11-01T01:49:34.976Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Coherent stats id
[task 2019-11-01T01:49:34.976Z] 01:49:34 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_addAudioTrackToExistingVideoStream.html | Valid rtp timestamp 1572572979929 >= 1572572978744 (
[task 2019-11-01T01:49:34.976Z] 01:49:34 INFO - 1185 ms)
[task 2019-11-01T01:49:34.976Z] 01:49:34 INFO - Not taking screenshot here: see the one that was previously logged

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• macosx1014-64: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows7-32-shippable: 1
• macosx1014-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1593184&startday=2019-11-11&endday=2019-11-17&tree=all