Closed Bug 1672590 Opened 11 months ago Closed 11 months ago

Intermittent dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.jitter is sane number for a local only test. value=455

Categories

(Core :: WebRTC, defect, P5)

defect

Tracking

()

RESOLVED FIXED
84 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox82 --- unaffected
firefox83 --- unaffected
firefox84 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: bwc)

References

(Regression)

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell:needsowner])

Attachments

(1 file)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=319324592&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eM88BmbzSFmF9OY-9LH-3g/runs/0/artifacts/public/logs/live_backing.log


[task 2020-10-22T02:12:45.241Z] 02:12:45 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html
[task 2020-10-22T02:12:45.764Z] 02:12:45 INFO - GECKO(2167) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-10-22T02:12:45.765Z] 02:12:45 INFO - GECKO(2167) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-10-22T02:12:45.962Z] 02:12:45 INFO - GECKO(2167) | Timecard created 1603332758.590578
[task 2020-10-22T02:12:45.962Z] 02:12:45 INFO - GECKO(2167) | Timestamp | Delta | Event | File | Function
[task 2020-10-22T02:12:45.962Z] 02:12:45 INFO - GECKO(2167) | ======================================================================================================================
[task 2020-10-22T02:12:45.962Z] 02:12:45 INFO - GECKO(2167) | 0.000085 | 0.000085 | Constructor Completed | PeerConnectionImpl.cpp:326 | PeerConnectionImpl
[task 2020-10-22T02:12:45.962Z] 02:12:45 INFO - GECKO(2167) | 0.002959 | 0.002874 | Initializing PC Ctx | PeerConnectionImpl.cpp:455 | Initialize
[task 2020-10-22T02:12:45.963Z] 02:12:45 INFO - GECKO(2167) | 0.407371 | 0.404412 | Create Offer | PeerConnectionImpl.cpp:1217 | CreateOffer
[task 2020-10-22T02:12:45.963Z] 02:12:45 INFO - GECKO(2167) | 0.431800 | 0.024429 | Set Local Description | PeerConnectionImpl.cpp:1286 | SetLocalDescription
[task 2020-10-22T02:12:45.964Z] 02:12:45 INFO - GECKO(2167) | 0.698966 | 0.267166 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2528 | IceGatheringStateChange
[task 2020-10-22T02:12:45.964Z] 02:12:45 INFO - GECKO(2167) | 0.745907 | 0.046941 | Ice gathering state: complete | PeerConnectionImpl.cpp:2531 | IceGatheringStateChange
[task 2020-10-22T02:12:45.965Z] 02:12:45 INFO - GECKO(2167) | 0.863725 | 0.117818 | Set Remote Description | PeerConnectionImpl.cpp:1386 | SetRemoteDescription
[task 2020-10-22T02:12:45.965Z] 02:12:45 INFO - GECKO(2167) | 0.913406 | 0.049681 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.965Z] 02:12:45 INFO - GECKO(2167) | 0.940877 | 0.027471 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.965Z] 02:12:45 INFO - GECKO(2167) | 0.941924 | 0.001047 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.946373 | 0.004449 | Ice state: checking | PeerConnectionImpl.cpp:2472 | IceConnectionStateChange
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.948330 | 0.001957 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.949578 | 0.001248 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.951029 | 0.001451 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.951087 | 0.000058 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.956954 | 0.005867 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.958092 | 0.001138 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.959883 | 0.001791 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.966Z] 02:12:45 INFO - GECKO(2167) | 0.959940 | 0.000057 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.967Z] 02:12:45 INFO - GECKO(2167) | 0.961276 | 0.001336 | Ice state: connected | PeerConnectionImpl.cpp:2475 | IceConnectionStateChange
[task 2020-10-22T02:12:45.967Z] 02:12:45 INFO - GECKO(2167) | 0.962074 | 0.000798 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.967Z] 02:12:45 INFO - GECKO(2167) | 0.963070 | 0.000996 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.967Z] 02:12:45 INFO - GECKO(2167) | 7.362808 | 6.399738 | Destructor Invoked | PeerConnectionImpl.cpp:335 | ~PeerConnectionImpl
[task 2020-10-22T02:12:45.967Z] 02:12:45 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:360: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for bfa559265606bd5d
[task 2020-10-22T02:12:45.968Z] 02:12:45 INFO - GECKO(2167) | Timecard created 1603332758.604263
[task 2020-10-22T02:12:45.969Z] 02:12:45 INFO - GECKO(2167) | Timestamp | Delta | Event | File | Function
[task 2020-10-22T02:12:45.969Z] 02:12:45 INFO - GECKO(2167) | ======================================================================================================================
[task 2020-10-22T02:12:45.969Z] 02:12:45 INFO - GECKO(2167) | 0.000091 | 0.000091 | Constructor Completed | PeerConnectionImpl.cpp:326 | PeerConnectionImpl
[task 2020-10-22T02:12:45.970Z] 02:12:45 INFO - GECKO(2167) | 0.002325 | 0.002234 | Initializing PC Ctx | PeerConnectionImpl.cpp:455 | Initialize
[task 2020-10-22T02:12:45.970Z] 02:12:45 INFO - GECKO(2167) | 0.462661 | 0.460336 | Set Remote Description | PeerConnectionImpl.cpp:1386 | SetRemoteDescription
[task 2020-10-22T02:12:45.970Z] 02:12:45 INFO - GECKO(2167) | 0.640141 | 0.177480 | Create Answer | PeerConnectionImpl.cpp:1248 | CreateAnswer
[task 2020-10-22T02:12:45.971Z] 02:12:45 INFO - GECKO(2167) | 0.747324 | 0.107183 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.971Z] 02:12:45 INFO - GECKO(2167) | 0.777056 | 0.029732 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.972Z] 02:12:45 INFO - GECKO(2167) | 0.778995 | 0.001939 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.972Z] 02:12:45 INFO - GECKO(2167) | 0.784668 | 0.005673 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.973Z] 02:12:45 INFO - GECKO(2167) | 0.787062 | 0.002394 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.973Z] 02:12:45 INFO - GECKO(2167) | 0.788788 | 0.001726 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.973Z] 02:12:45 INFO - GECKO(2167) | 0.790466 | 0.001678 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.974Z] 02:12:45 INFO - GECKO(2167) | 0.792325 | 0.001859 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.975Z] 02:12:45 INFO - GECKO(2167) | 0.793882 | 0.001557 | Add Ice Candidate | PeerConnectionImpl.cpp:1534 | AddIceCandidate
[task 2020-10-22T02:12:45.975Z] 02:12:45 INFO - GECKO(2167) | 0.796012 | 0.002130 | Set Local Description | PeerConnectionImpl.cpp:1286 | SetLocalDescription
[task 2020-10-22T02:12:45.976Z] 02:12:45 INFO - GECKO(2167) | 0.865240 | 0.069228 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.976Z] 02:12:45 INFO - GECKO(2167) | 0.865330 | 0.000090 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.976Z] 02:12:45 INFO - GECKO(2167) | 0.865401 | 0.000071 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.976Z] 02:12:45 INFO - GECKO(2167) | 0.865463 | 0.000062 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.977Z] 02:12:45 INFO - GECKO(2167) | 0.865514 | 0.000051 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.978Z] 02:12:45 INFO - GECKO(2167) | 0.865563 | 0.000049 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.978Z] 02:12:45 INFO - GECKO(2167) | 0.865609 | 0.000046 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.978Z] 02:12:45 INFO - GECKO(2167) | 0.865654 | 0.000045 | Look up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.978Z] 02:12:45 INFO - GECKO(2167) | 0.866931 | 0.001277 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2528 | IceGatheringStateChange
[task 2020-10-22T02:12:45.979Z] 02:12:45 INFO - GECKO(2167) | 0.887235 | 0.020304 | Ice gathering state: complete | PeerConnectionImpl.cpp:2531 | IceGatheringStateChange
[task 2020-10-22T02:12:45.979Z] 02:12:45 INFO - GECKO(2167) | 0.923385 | 0.036150 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.979Z] 02:12:45 INFO - GECKO(2167) | 0.923446 | 0.000061 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.980Z] 02:12:45 INFO - GECKO(2167) | 0.923478 | 0.000032 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.981Z] 02:12:45 INFO - GECKO(2167) | 0.923509 | 0.000031 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.981Z] 02:12:45 INFO - GECKO(2167) | 0.923674 | 0.000165 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.981Z] 02:12:45 INFO - GECKO(2167) | 0.923712 | 0.000038 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.982Z] 02:12:45 INFO - GECKO(2167) | 0.923743 | 0.000031 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.982Z] 02:12:45 INFO - GECKO(2167) | 0.923776 | 0.000033 | Done looking up mDNS name | PeerConnectionImpl.cpp:1822 | StampTimecard
[task 2020-10-22T02:12:45.983Z] 02:12:45 INFO - GECKO(2167) | 0.931853 | 0.008077 | Ice state: checking | PeerConnectionImpl.cpp:2472 | IceConnectionStateChange
[task 2020-10-22T02:12:45.983Z] 02:12:45 INFO - GECKO(2167) | 0.946567 | 0.014714 | Ice state: connected | PeerConnectionImpl.cpp:2475 | IceConnectionStateChange
[task 2020-10-22T02:12:45.984Z] 02:12:45 INFO - GECKO(2167) | 7.349912 | 6.403345 | Destructor Invoked | PeerConnectionImpl.cpp:335 | ~PeerConnectionImpl
[task 2020-10-22T02:12:45.985Z] 02:12:45 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:360: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 03742cabfbf6525a
[task 2020-10-22T02:12:46.262Z] 02:12:46 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:325: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-10-22T02:12:46.262Z] 02:12:46 INFO - GECKO(2167) | [Parent 2167: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-10-22T02:12:46.269Z] 02:12:46 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:325: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-10-22T02:12:46.270Z] 02:12:46 INFO - GECKO(2167) | [Parent 2167: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-10-22T02:12:46.313Z] 02:12:46 INFO - GECKO(2167) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-10-22T02:12:46.314Z] 02:12:46 INFO - GECKO(2167) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-10-22T02:12:46.330Z] 02:12:46 INFO - GECKO(2167) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-10-22T02:12:46.330Z] 02:12:46 INFO - GECKO(2167) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-10-22T02:12:46.342Z] 02:12:46 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:74: OnStunAddrsAvailable: receiving (5) stun addrs
[task 2020-10-22T02:12:46.342Z] 02:12:46 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:74: OnStunAddrsAvailable: receiving (5) stun addrs
[task 2020-10-22T02:12:47.005Z] 02:12:47 INFO - GECKO(2167) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-10-22T02:12:47.006Z] 02:12:47 INFO - GECKO(2167) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-10-22T02:12:47.009Z] 02:12:47 INFO - GECKO(2167) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-10-22T02:12:47.012Z] 02:12:47 INFO - GECKO(2167) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-10-22T02:12:47.028Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2769: GetStats: Found no pipelines matching selector.
[task 2020-10-22T02:12:47.353Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x7b1c00024d50
[task 2020-10-22T02:12:47.372Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/jsep [1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)]: stable -> have-local-offer
[task 2020-10-22T02:12:47.375Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x7b1c000b3360
[task 2020-10-22T02:12:47.382Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/jsep [1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)]: stable -> have-remote-offer
[task 2020-10-22T02:12:47.390Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.391Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.392Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.392Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.392Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.393Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.394Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.394Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.397Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.397Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.397Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.397Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.401Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.401Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.401Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.403Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.403Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:0 1 UDP 2122187007 172.17.0.4 55016 typ host
[task 2020-10-22T02:12:47.404Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0', no candidates.
[task 2020-10-22T02:12:47.405Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:1 1 UDP 2122252543 fd15:4ba5:5a2b:100a:0:242:ac11:4 52727 typ host
[task 2020-10-22T02:12:47.406Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0', no candidates.
[task 2020-10-22T02:12:47.407Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:2 1 TCP 2105458943 172.17.0.4 9 typ host tcptype active
[task 2020-10-22T02:12:47.407Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0', no candidates.
[task 2020-10-22T02:12:47.409Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:3 1 TCP 2105524479 fd15:4ba5:5a2b:100a:0:242:ac11:4 9 typ host tcptype active
[task 2020-10-22T02:12:47.409Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0', no candidates.
[task 2020-10-22T02:12:47.410Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:0 2 UDP 2122187006 172.17.0.4 49346 typ host
[task 2020-10-22T02:12:47.411Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:1 2 UDP 2122252542 fd15:4ba5:5a2b:100a:0:242:ac11:4 47186 typ host
[task 2020-10-22T02:12:47.412Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:2 2 TCP 2105458942 172.17.0.4 9 typ host tcptype active
[task 2020-10-22T02:12:47.413Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:3 2 TCP 2105524478 fd15:4ba5:5a2b:100a:0:242:ac11:4 9 typ host tcptype active
[task 2020-10-22T02:12:47.413Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:0 1 UDP 2122187007 172.17.0.4 40409 typ host
[task 2020-10-22T02:12:47.414Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_1', no candidates.
[task 2020-10-22T02:12:47.415Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:1 1 UDP 2122252543 fd15:4ba5:5a2b:100a:0:242:ac11:4 49686 typ host
[task 2020-10-22T02:12:47.416Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_1', no candidates.
[task 2020-10-22T02:12:47.416Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:2 1 TCP 2105458943 172.17.0.4 9 typ host tcptype active
[task 2020-10-22T02:12:47.416Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_1', no candidates.
[task 2020-10-22T02:12:47.417Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:3 1 TCP 2105524479 fd15:4ba5:5a2b:100a:0:242:ac11:4 9 typ host tcptype active
[task 2020-10-22T02:12:47.418Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Couldn't get default ICE candidate for 'PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_1', no candidates.
[task 2020-10-22T02:12:47.418Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:0 2 UDP 2122187006 172.17.0.4 39032 typ host
[task 2020-10-22T02:12:47.418Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:1 2 UDP 2122252542 fd15:4ba5:5a2b:100a:0:242:ac11:4 46366 typ host
[task 2020-10-22T02:12:47.420Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:2 2 TCP 2105458942 172.17.0.4 9 typ host tcptype active
[task 2020-10-22T02:12:47.420Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): trickling candidate candidate:3 2 TCP 2105524478 fd15:4ba5:5a2b:100a:0:242:ac11:4 9 typ host tcptype active
[task 2020-10-22T02:12:47.420Z] 02:12:47 INFO - GECKO(2167) | (ice/INFO) ICE(PC:1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): All candidates initialized
[task 2020-10-22T02:12:47.802Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0x7b1c000aca60
[task 2020-10-22T02:12:47.810Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/jsep [1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)]: have-remote-offer -> stable
[task 2020-10-22T02:12:47.812Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.812Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.813Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|WebrtcAudioSessionConduit] AudioConduit.cpp:270: SetDtmfPayloadType : setting dtmf payload 101
[task 2020-10-22T02:12:47.813Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) /builds/worker/checkouts/gecko/dom/media/webrtc/transport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3
[task 2020-10-22T02:12:47.813Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): failed to create passive TCP host candidate: 3
[task 2020-10-22T02:12:47.815Z] 02:12:47 INFO - GECKO(2167) | (ice/WARNING) ICE(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)): peer (PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html):default) has no stream matching stream PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0 - fb1e95e1:2dca5d4cc1e496ecdb6a4364b8c1fdc3
[task 2020-10-22T02:12:47.816Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Setting up DTLS as client
[task 2020-10-22T02:12:47.816Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport Setting DTLS1.3 supported_versions workaround
[task 2020-10-22T02:12:47.817Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: E/mtransport Couldn't disable 'PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0':2
[task 2020-10-22T02:12:47.817Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html))/STREAM(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0) : parsing trickle candidate candidate:0 1 UDP 2122187007 172.17.0.4 55016 typ host
[task 2020-10-22T02:12:47.820Z] 02:12:47 INFO - GECKO(2167) | [Child 2235: Socket Thread]: D/mtransport NrIceCtx(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html))/STREAM(PC:1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html) transport-id=transport_0) : parsing trickle candidate candidate:1 1 UDP 2122252543 fd15:4ba5:5a2b:100a:0:242:ac11:4 52727 typ host
<...>
[task 2020-10-22T02:13:05.950Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | local object has remote object as it's own remote object.
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.roundTripTime is sane withvalue of:0.016
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.packetsLost is a sane number for a short test. value=0
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - Buffered messages finished
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.jitter is sane number for a local only test. value=455
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - pedanticChecks/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html:537:9
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - pedanticChecks@https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html:323:10
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - PC_REMOTE_TEST_REMOTE_STATS/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html:815:19
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.packetsReceived is a sane number for a short test. value=442
[task 2020-10-22T02:13:05.951Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.bytesReceived is a sane number for a short test. value=70029
[task 2020-10-22T02:13:05.959Z] 02:13:05 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | remote-inbound-rtp.id was tested.
<...>
[task 2020-10-22T02:13:08.165Z] 02:13:08 INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-10-22T02:13:08.165Z] 02:13:08 INFO - Waiting for track {9e2965ca-d090-415b-b286-149f43cff579} (video) to end.
[task 2020-10-22T02:13:08.165Z] 02:13:08 INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-10-22T02:13:08.166Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2100: CloseInt: Closing PeerConnectionImpl bb43cea96c86c82e; ending call
[task 2020-10-22T02:13:08.166Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/jsep [1603332766256054 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)]: stable -> closed
[task 2020-10-22T02:13:08.181Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #4]: E/signaling [WebRTCPD #4|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.181Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #4]: E/signaling [WebRTCPD #4|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.200Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.204Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.204Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.219Z] 02:13:08 INFO - PeerConnectionWrapper (pcLocal): Closed connection.
[task 2020-10-22T02:13:08.227Z] 02:13:08 INFO - Waiting for track {748caf88-d030-4345-8c07-ca520bd540df} (audio) to end.
[task 2020-10-22T02:13:08.227Z] 02:13:08 INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-10-22T02:13:08.228Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.228Z] 02:13:08 INFO - Waiting for track {dd1687f9-f4a8-4702-84e2-6e9485ce8b39} (video) to end.
[task 2020-10-22T02:13:08.231Z] 02:13:08 INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-10-22T02:13:08.232Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.234Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #4]: E/signaling [WebRTCPD #4|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.254Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2100: CloseInt: Closing PeerConnectionImpl f65d2f102f03d7c3; ending call
[task 2020-10-22T02:13:08.254Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: Main Thread]: I/jsep [1603332766266444 (id=2147484229 url=https://example.com/tests/dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html)]: stable -> closed
[task 2020-10-22T02:13:08.254Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #4]: E/signaling [WebRTCPD #4|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.255Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.256Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #1]: E/signaling [WebRTCPD #1|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.256Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #1]: E/signaling [WebRTCPD #1|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.272Z] 02:13:08 INFO - PeerConnectionWrapper (pcRemote): Closed connection.
[task 2020-10-22T02:13:08.272Z] 02:13:08 INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-10-22T02:13:08.273Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.273Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #4]: E/signaling [WebRTCPD #4|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.274Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.274Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.274Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.275Z] 02:13:08 INFO - GECKO(2167) | [Child 2235: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:629: SendAudioFrame Engine not transmitting
[task 2020-10-22T02:13:08.278Z] 02:13:08 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | Event target should be the correct track
[task 2020-10-22T02:13:08.279Z] 02:13:08 INFO - PeerConnectionWrapper (pcLocal) ended fired for track {46c4cd73-6239-4296-afd0-f0c5d0a20706}
[task 2020-10-22T02:13:08.279Z] 02:13:08 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | Event target should be the correct track
[task 2020-10-22T02:13:08.279Z] 02:13:08 INFO - PeerConnectionWrapper (pcLocal) ended fired for track {9e2965ca-d090-415b-b286-149f43cff579}
[task 2020-10-22T02:13:08.307Z] 02:13:08 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | Event target should be the correct track
[task 2020-10-22T02:13:08.307Z] 02:13:08 INFO - PeerConnectionWrapper (pcRemote) ended fired for track {748caf88-d030-4345-8c07-ca520bd540df}
[task 2020-10-22T02:13:08.307Z] 02:13:08 INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | Event target should be the correct track
[task 2020-10-22T02:13:08.307Z] 02:13:08 INFO - PeerConnectionWrapper (pcRemote) ended fired for track {dd1687f9-f4a8-4702-84e2-6e9485ce8b39}
[task 2020-10-22T02:13:08.351Z] 02:13:08 INFO - GECKO(2167) | MEMORY STAT | vsize 130551920MB | residentFast 2387MB
[task 2020-10-22T02:13:08.540Z] 02:13:08 INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_peerConnection_stats.html | took 23306ms
[task 2020-10-22T02:13:08.697Z] 02:13:08 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_syncSetDescription.html

This fails frequently since media tests got enabled for Linux ThreadSanitizer in bug 1648192.

Dan, shall the test get disabled on tsan?

Flags: needinfo?(dminor)

Byron has been looking at the tsan stuff, so probably has a better idea than I do.

Flags: needinfo?(dminor) → needinfo?(docfaraday)

I'm going to guess this is a performance thing. It would be good to avoid disabling the entire test here, since it tests more than this particular sanity check. Is there a way to tell, within a mochitest, whether we're running a tsan build?

Flags: needinfo?(docfaraday) → needinfo?(ahal)
Regressed by: mochitest_media_tsan
Whiteboard: [retriggered]

Looks like we set the TSAN_OPTIONS environment variable when tsan is enabled:
https://searchfox.org/mozilla-central/source/testing/mozbase/mozrunner/mozrunner/utils.py#213

Though also looks like that variable can be used to disable tsan.. so not sure what exactly would be required to check it robustly. Maybe there's some platform API that can detect it? Maybe :decoder can shed some light.

Flags: needinfo?(ahal) → needinfo?(choller)

I think checking for TSan inside the test isn't the right approach here: This intermittent is not specific for TSan, it happens with other configurations as well (just much less frequently), and we will have the same problem with other, equally slow builds that try to run this test.

This test seems to have a non-deterministic component of some sort. Can we fix that component and test it properly, so it wouldn't cause intermittents, independent of the build performance? If not, can we isolate it from the rest, e.g. split the test into two tests?

Flags: needinfo?(choller) → needinfo?(docfaraday)

jitter is inherently non-deterministic, sadly. That's just the nature of the beast; we're measuring latency in real-time media, when we're at the mercy of factors like the OS scheduler, or heavy computation that is competing with packet flow. We already have lots of test code whose leniency depends on things like OS, for example. With a "perfect" scheduler, and unlimited CPU, this would be pretty predictable, but that is of course never going to happen. The intent of the test is to detect obvious regressions where the jitter value dramatically increases (indeed, this test hints that audio/video quality is likely to be extremely poor under TSan, which is nice to know).

We could try splitting the test I suppose.

Flags: needinfo?(docfaraday)
Assignee: nobody → docfaraday

Try looks good.

This bug failed 31 times in the last 7 days. Fails on linux1804-64-tsan on opt build types.

Recent log:
https://treeherder.mozilla.org/logviewer?job_id=321072183&repo=autoland&lineNumber=48232

Can you please take a futher look at this bug?

Flags: needinfo?(docfaraday)
Whiteboard: [retriggered] → [retriggered][stockwell:needsowner]

This just needs a review at this point.

Flags: needinfo?(docfaraday) → needinfo?(na-g)
Duplicate of this bug: 1675938
Pushed by bcampen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2650dab0cd7f
Move strict jitter sanity check into a separate test, and disable that test on TSan. r=ng
Status: NEW → RESOLVED
Closed: 11 months ago
Resolution: --- → FIXED
Target Milestone: --- → 84 Branch
Flags: needinfo?(na-g)
You need to log in before you can comment on or make changes to this bug.