1614627 - Intermittent dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | Unexpected event 'message' fired with message = 'DataChannelWrapper (pcRemote_channel_2)' at: ["createOneShotEventWrapper@https://example.com/tests/dom/media/tests/

Status: RESOLVED INCOMPLETE

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-11T11:16:55.652Z] 11:16:55 INFO - TEST-START | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html
[task 2020-02-11T11:16:56.214Z] 11:16:56 INFO - GECKO(1676) | [Child 1761, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 64
[task 2020-02-11T11:16:56.431Z] 11:16:56 INFO - GECKO(1676) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-02-11T11:16:56.431Z] 11:16:56 INFO - GECKO(1676) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-02-11T11:16:56.581Z] 11:16:56 INFO - GECKO(1676) | Timecard created 1581419809.832813
[task 2020-02-11T11:16:56.582Z] 11:16:56 INFO - GECKO(1676) | Timestamp | Delta | Event | File | Function
[task 2020-02-11T11:16:56.582Z] 11:16:56 INFO - GECKO(1676) | ======================================================================================================================
[task 2020-02-11T11:16:56.583Z] 11:16:56 INFO - GECKO(1676) | 0.000046 | 0.000046 | Constructor Completed | PeerConnectionImpl.cpp:330 | PeerConnectionImpl
[task 2020-02-11T11:16:56.583Z] 11:16:56 INFO - GECKO(1676) | 0.000996 | 0.000950 | Initializing PC Ctx | PeerConnectionImpl.cpp:456 | Initialize
[task 2020-02-11T11:16:56.584Z] 11:16:56 INFO - GECKO(1676) | 1.561075 | 1.560079 | Create Offer | PeerConnectionImpl.cpp:1252 | CreateOffer
[task 2020-02-11T11:16:56.585Z] 11:16:56 INFO - GECKO(1676) | 1.700311 | 0.139236 | Set Local Description | PeerConnectionImpl.cpp:1321 | SetLocalDescription
[task 2020-02-11T11:16:56.585Z] 11:16:56 INFO - GECKO(1676) | 1.746579 | 0.046268 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2588 | IceGatheringStateChange
[task 2020-02-11T11:16:56.585Z] 11:16:56 INFO - GECKO(1676) | 1.903513 | 0.156934 | Ice gathering state: complete | PeerConnectionImpl.cpp:2591 | IceGatheringStateChange
[task 2020-02-11T11:16:56.585Z] 11:16:56 INFO - GECKO(1676) | 2.640123 | 0.736610 | Set Remote Description | PeerConnectionImpl.cpp:1408 | SetRemoteDescription
[task 2020-02-11T11:16:56.585Z] 11:16:56 INFO - GECKO(1676) | 3.099115 | 0.458992 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.586Z] 11:16:56 INFO - GECKO(1676) | 3.132559 | 0.033444 | Ice state: checking | PeerConnectionImpl.cpp:2488 | IceConnectionStateChange
[task 2020-02-11T11:16:56.587Z] 11:16:56 INFO - GECKO(1676) | 3.137202 | 0.004643 | Ice state: connected | PeerConnectionImpl.cpp:2491 | IceConnectionStateChange
[task 2020-02-11T11:16:56.587Z] 11:16:56 INFO - GECKO(1676) | 3.200916 | 0.063714 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.588Z] 11:16:56 INFO - GECKO(1676) | 3.372448 | 0.171532 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.588Z] 11:16:56 INFO - GECKO(1676) | 3.377738 | 0.005290 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.590Z] 11:16:56 INFO - GECKO(1676) | 3.382741 | 0.005003 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.590Z] 11:16:56 INFO - GECKO(1676) | 6.739822 | 3.357081 | Destructor Invoked | PeerConnectionImpl.cpp:339 | ~PeerConnectionImpl
[task 2020-02-11T11:16:56.591Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:364: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for f5180cfffa8ad3f4
[task 2020-02-11T11:16:56.591Z] 11:16:56 INFO - GECKO(1676) | Timecard created 1581419809.840386
[task 2020-02-11T11:16:56.592Z] 11:16:56 INFO - GECKO(1676) | Timestamp | Delta | Event | File | Function
[task 2020-02-11T11:16:56.592Z] 11:16:56 INFO - GECKO(1676) | ======================================================================================================================
[task 2020-02-11T11:16:56.594Z] 11:16:56 INFO - GECKO(1676) | 0.000041 | 0.000041 | Constructor Completed | PeerConnectionImpl.cpp:330 | PeerConnectionImpl
[task 2020-02-11T11:16:56.595Z] 11:16:56 INFO - GECKO(1676) | 0.000855 | 0.000814 | Initializing PC Ctx | PeerConnectionImpl.cpp:456 | Initialize
[task 2020-02-11T11:16:56.595Z] 11:16:56 INFO - GECKO(1676) | 1.728917 | 1.728062 | Set Remote Description | PeerConnectionImpl.cpp:1408 | SetRemoteDescription
[task 2020-02-11T11:16:56.596Z] 11:16:56 INFO - GECKO(1676) | 2.243842 | 0.514925 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.599Z] 11:16:56 INFO - GECKO(1676) | 2.322902 | 0.079060 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.599Z] 11:16:56 INFO - GECKO(1676) | 2.377666 | 0.054764 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.605Z] 11:16:56 INFO - GECKO(1676) | 2.382824 | 0.005158 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.606Z] 11:16:56 INFO - GECKO(1676) | 2.384033 | 0.001209 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate[task 2020-02-11T11:16:56.606Z] 11:16:56 INFO - GECKO(1676) | 2.388195 | 0.004162 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.607Z] 11:16:56 INFO - GECKO(1676) | 2.391990 | 0.003795 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.607Z] 11:16:56 INFO - GECKO(1676) | 2.395501 | 0.003511 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.608Z] 11:16:56 INFO - GECKO(1676) | 2.401702 | 0.006201 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.608Z] 11:16:56 INFO - GECKO(1676) | 2.402800 | 0.001098 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.608Z] 11:16:56 INFO - GECKO(1676) | 2.404302 | 0.001502 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.608Z] 11:16:56 INFO - GECKO(1676) | 2.407578 | 0.003276 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.609Z] 11:16:56 INFO - GECKO(1676) | 2.410703 | 0.003125 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.610Z] 11:16:56 INFO - GECKO(1676) | 2.413828 | 0.003125 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.610Z] 11:16:56 INFO - GECKO(1676) | 2.415542 | 0.001714 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.611Z] 11:16:56 INFO - GECKO(1676) | 2.419541 | 0.003999 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.611Z] 11:16:56 INFO - GECKO(1676) | 2.422081 | 0.002540 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.612Z] 11:16:56 INFO - GECKO(1676) | 2.425164 | 0.003083 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.612Z] 11:16:56 INFO - GECKO(1676) | 2.428814 | 0.003650 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.612Z] 11:16:56 INFO - GECKO(1676) | 2.431828 | 0.003014 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.613Z] 11:16:56 INFO - GECKO(1676) | 2.432920 | 0.001092 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.613Z] 11:16:56 INFO - GECKO(1676) | 2.434351 | 0.001431 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.613Z] 11:16:56 INFO - GECKO(1676) | 2.435653 | 0.001302 | Add Ice Candidate | PeerConnectionImpl.cpp:1541 | AddIceCandidate
[task 2020-02-11T11:16:56.614Z] 11:16:56 INFO - GECKO(1676) | 2.437339 | 0.001686 | Create Answer | PeerConnectionImpl.cpp:1283 | CreateAnswer
[task 2020-02-11T11:16:56.614Z] 11:16:56 INFO - GECKO(1676) | 2.466475 | 0.029136 | Set Local Description | PeerConnectionImpl.cpp:1321 | SetLocalDescription
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | 2.659914 | 0.193439 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2588 | IceGatheringStateChange
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | 2.712950 | 0.053036 | Ice gathering state: complete | PeerConnectionImpl.cpp:2591 | IceGatheringStateChange
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | 2.720237 | 0.007287 | Ice state: checking | PeerConnectionImpl.cpp:2488 | IceConnectionStateChange
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | 3.128936 | 0.408699 | Ice state: connected | PeerConnectionImpl.cpp:2491 | IceConnectionStateChange
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | 6.732633 | 3.603697 | Destructor Invoked | PeerConnectionImpl.cpp:339 | ~PeerConnectionImpl
[task 2020-02-11T11:16:56.615Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:364: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for fc5a7e453feb3b2f
[task 2020-02-11T11:16:56.903Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28a0f6df0: Close()ing 0x7fe28b1f1e50
[task 2020-02-11T11:16:56.903Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28a0f6190: Close()ing 0x7fe28b1df940
[task 2020-02-11T11:16:56.903Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28a0f60e0: Close()ing 0x7fe28b1ce790
[task 2020-02-11T11:16:56.904Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28b4da710: Close()ing 0x7fe28e18c8b0
[task 2020-02-11T11:16:56.904Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28c7e7500: Close()ing 0x7fe28c023d30[task 2020-02-11T11:16:56.905Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28c3f0be0: Close()ing 0x7fe28c023ca0
[task 2020-02-11T11:16:56.906Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28c3f0660: Close()ing 0x7fe28c0239d0
[task 2020-02-11T11:16:56.907Z] 11:16:56 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel 0x7fe28f4770e0: Close()ing 0x7fe28c367ca0
[task 2020-02-11T11:16:57.063Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:329: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-02-11T11:16:57.064Z] 11:16:57 INFO - GECKO(1676) | [Parent 1676: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-02-11T11:16:57.071Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:329: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-02-11T11:16:57.071Z] 11:16:57 INFO - GECKO(1676) | [Parent 1676: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-02-11T11:16:57.091Z] 11:16:57 INFO - GECKO(1676) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-02-11T11:16:57.092Z] 11:16:57 INFO - GECKO(1676) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-02-11T11:16:57.099Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:69: OnStunAddrsAvailable: receiving (5) stun addrs
[task 2020-02-11T11:16:57.100Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:69: OnStunAddrsAvailable: receiving (5) stun addrs
[task 2020-02-11T11:16:57.156Z] 11:16:57 INFO - GECKO(1676) | JavaScript error: resource:///actors/WebRTCChild.jsm, line 183: TypeError: can't access property "navigator", contentWindow is null
[task 2020-02-11T11:16:57.174Z] 11:16:57 INFO - GECKO(1676) | [Parent 1676, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2020-02-11T11:16:57.174Z] 11:16:57 INFO - GECKO(1676) | (firefox:1676): Gtk-CRITICAL **: 11:16:57.168: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2020-02-11T11:16:57.174Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 1284
[task 2020-02-11T11:16:57.175Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 1286
[task 2020-02-11T11:16:57.176Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 1323
[task 2020-02-11T11:16:57.176Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 1329
[task 2020-02-11T11:16:57.180Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 1337
[task 2020-02-11T11:16:57.268Z] 11:16:57 INFO - GECKO(1676) | [Parent 1676, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2020-02-11T11:16:57.268Z] 11:16:57 INFO - GECKO(1676) | (firefox:1676): Gtk-CRITICAL **: 11:16:57.266: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2020-02-11T11:16:57.345Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 2020-02-11T11:16:57.366Z] 11:16:57 INFO - GECKO(1676) | [Child 1761, 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 2020-02-11T11:16:57.422Z] 11:16:57 INFO - GECKO(1676) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-02-11T11:16:57.430Z] 11:16:57 INFO - GECKO(1676) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-02-11T11:16:57.450Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2907: GetStats: Found no pipelines matching selector.
[task 2020-02-11T11:16:57.466Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2894: GetStats: Found no pipelines matching selector.
[task 2020-02-11T11:16:57.467Z] 11:16:57 INFO - GECKO(1676) | [Child 1761: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2907: GetStats: Found no pipelines matching selector.
[task 2020-02-11T11:16:57.568Z] 11:16:57 INFO - GECKO(1676) | [Parent 1676, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3135
[task 2020-02-11T11:16:57.716Z] 11:16:57 INFO - GECKO(1676) | [GLX] window 2200058 has VisualID 0x1ab
[task 2020-02-11T11:16:57.724Z] 11:16:57 INFO - GECKO(1676) | [GPU 1708, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/workspace/build/src/gfx/gl/GLContextFeatures.cpp, line 623
[task 2020-02-11T11:16:57.725Z] 11:16:57 INFO - GECKO(1676) | [GPU 1708, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/workspace/build/src/gfx/gl/GLContext.cpp, line 978
[task 2020-02-11T11:16:57.725Z] 11:16:57 INFO - GECKO(1676) | [GPU 1708, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/workspace/build/src/gfx/gl/GLContextFeatures.cpp, line 623
[task 2020-02-11T11:16:58.126Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.127Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.127Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.127Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.128Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.128Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.129Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.129Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.131Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.131Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.135Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.142Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.142Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.143Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.143Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.143Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.144Z] 11:16:58 INFO - GECKO(1676) | [GPU 1708, Compositor] WARNING: Shmem was deallocated: file /builds/worker/workspace/build/src/ipc/glue/Shmem.cpp, line 343
[task 2020-02-11T11:16:58.144Z] 11:16:58 INFO - GECKO(1676) | ###!!! [Parent][DispatchAsyncMessage] Error: SHMEM_CREATED_MESSAGE Payload error: message could not be deserialized
[task 2020-02-11T11:16:58.183Z] 11:16:58 INFO - GECKO(1676) | JavaScript error: resource:///actors/WebRTCChild.jsm, line 183: TypeError: can't access property "navigator", contentWindow is null
[task 2020-02-11T11:16:58.190Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 1284
[task 2020-02-11T11:16:58.191Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 1286
[task 2020-02-11T11:16:58.191Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 1323
[task 2020-02-11T11:16:58.193Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 1329
[task 2020-02-11T11:16:58.193Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 1337
[task 2020-02-11T11:16:58.290Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 2020-02-11T11:16:58.291Z] 11:16:58 INFO - GECKO(1676) | [Child 1761, 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 2020-02-11T11:16:58.348Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Maximum message size (outgoing data): 2147483637 (set=no, enforced=yes)
[task 2020-02-11T11:16:58.348Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Setting number of SCTP streams to 256, was 10/2048
[task 2020-02-11T11:16:58.348Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Registered 0x7fe28b4a8800 within the SCTP stack.
[task 2020-02-11T11:16:58.350Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel DC Open: label channel_0/, type 0, inorder 1, prValue 0, listener (nil), context (nil), external: false, stream 65535
[task 2020-02-11T11:16:58.350Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Inserting channel 65535 : 0x7fe28c0474c0
[task 2020-02-11T11:16:58.351Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Queuing channel 0x7fe28c0474c0 (65535) to finish open
[task 2020-02-11T11:16:58.352Z] 11:16:58 INFO - GECKO(1676) | [Child 1761: Main Thread]: D/DataChannel Init: origin = https://example.com[task 2020-02-11T11:17:02.915Z] 11:17:02 INFO - PeerConnectionWrapper (pcRemote): Create data channel 'channel_2
[task 2020-02-11T11:17:02.915Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | initial readyState is 'connecting'
[task 2020-02-11T11:17:02.916Z] 11:17:02 INFO - Creating DataChannelWrapper (pcRemote_channel_2)
[task 2020-02-11T11:17:02.917Z] 11:17:02 INFO - TEST-FAIL | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts
[task 2020-02-11T11:17:02.917Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | data channel is 'open' after 'onopen'
[task 2020-02-11T11:17:02.918Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) is of binary type 'blob'
[task 2020-02-11T11:17:02.919Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) id is:5
[task 2020-02-11T11:17:02.920Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) protocol is:foo/bar
[task 2020-02-11T11:17:02.926Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) reliable is:false
[task 2020-02-11T11:17:02.927Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) ordered is:false
[task 2020-02-11T11:17:02.927Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) maxRetransmits is:500
[task 2020-02-11T11:17:02.929Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) maxPacketLifeTime is:null
[task 2020-02-11T11:17:02.929Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) is of binary type 'blob'
[task 2020-02-11T11:17:02.931Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) id is:5
[task 2020-02-11T11:17:02.931Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) protocol is:foo/bar
[task 2020-02-11T11:17:02.939Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) reliable is:false
[task 2020-02-11T11:17:02.940Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) ordered is:false
[task 2020-02-11T11:17:02.940Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) maxRetransmits is:500
[task 2020-02-11T11:17:02.941Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) maxPacketLifeTime is:null
[task 2020-02-11T11:17:02.942Z] 11:17:02 INFO - Run step 56: SEND_MESSAGE_THROUGH_LAST_OPENED_CHANNEL2
[task 2020-02-11T11:17:02.942Z] 11:17:02 INFO - Sending message:I am the walrus; Goo goo g'joob
[task 2020-02-11T11:17:02.943Z] 11:17:02 INFO - DataChannelWrapper (pcLocal_channel_2): Sending data 'I am the walrus; Goo goo g'joob'
[task 2020-02-11T11:17:02.944Z] 11:17:02 INFO - TEST-PASS | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | Buffered amount should be 31
[task 2020-02-11T11:17:02.945Z] 11:17:02 INFO - DataChannelWrapper (pcRemote_channel_2): "onmessage" event fired
[task 2020-02-11T11:17:02.947Z] 11:17:02 INFO - Buffered messages finished
[task 2020-02-11T11:17:02.949Z] 11:17:02 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html | Unexpected event 'message' fired with message = 'DataChannelWrapper (pcRemote_channel_2)' at: ["createOneShotEventWrapper@https://example.com/tests/dom/media/tests/mochitest/head.js:819:35","DataChannelWrapper@https://example.com/tests/dom/media/tests/mochitest/pc.js:713:28","createDataChannel@https://example.com/tests/dom/media/tests/mochitest/pc.js:1277:19","PeerConnectionTest.prototype.createDataChannel/remotePromise<@https://example.com/tests/dom/media/tests/mochitest/pc.js:344:41","promise callbackPeerConnectionTest.prototype.createDataChannel@https://example.com/tests/dom/media/tests/mochitest/pc.js:341:34","CREATE_NEGOTIATED_DATA_CHANNEL_MAX_RETRANSMITS@https://example.com/tests/dom/media/tests/mochitest/dataChannel.js:149:17","execute/</<@https://example.com/tests/dom/media/tests/mochitest/head.js:949:32","promise callbackexecute/<@https://example.com/tests/dom/media/tests/mochitest/head.js:947:21","execute@https://example.com/tests/dom/media/tests/mochitest/head.js:942:8","PeerConnectionTest.prototype.run@https://example.com/tests/dom/media/tests/mochitest/pc.js:568:6","@https://example.com/tests/dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html:20:10","runNetworkTest/<@https://example.com/tests/dom/media/tests/mochitest/pc.js:2547:11","asyncrunTestWhenReady/<@https://example.com/tests/dom/media/tests/mochitest/head.js:497:30","promise callbackrunTestWhenReady@https://example.com/tests/dom/media/tests/mochitest/head.js:497:6","runNetworkTest@https://example.com/tests/dom/media/tests/mochitest/pc.js:2528:9","async*@https://example.com/tests/dom/media/tests/mochitest/test_dataChannel_basicAudioVideoCombined.html:15:17",""]

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1614627&startday=2020-02-10&endday=2020-02-16&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1614627&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

New occurrence: https://treeherder.mozilla.org/logviewer?job_id=324665865&repo=try

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1614627&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 7

[Iulian Moraru]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=347887773&repo=mozilla-central&lineNumber=20399

[task 2021-08-09T22:07:33.271Z] 22:07:33     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html
[task 2021-08-09T22:07:33.856Z] 22:07:33     INFO - GECKO(6436) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-08-09T22:07:33.859Z] 22:07:33     INFO - GECKO(6436) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-08-09T22:07:34.048Z] 22:07:34     INFO - GECKO(6436) | Timecard created 1628546845.842061
[task 2021-08-09T22:07:34.049Z] 22:07:34     INFO - GECKO(6436) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-08-09T22:07:34.054Z] 22:07:34     INFO - GECKO(6436) | ======================================================================================================================
[task 2021-08-09T22:07:34.054Z] 22:07:34     INFO - GECKO(6436) |     0.000290 |    0.000290 | Constructor Completed          | PeerConnectionImpl.cpp:332   | PeerConnectionImpl
[task 2021-08-09T22:07:34.055Z] 22:07:34     INFO - GECKO(6436) |     0.003003 |    0.002713 | Initializing PC Ctx            | PeerConnectionImpl.cpp:450   | Initialize
[task 2021-08-09T22:07:34.055Z] 22:07:34     INFO - GECKO(6436) |     1.123927 |    1.120924 | Create Offer                   | PeerConnectionImpl.cpp:1212  | CreateOffer
[task 2021-08-09T22:07:34.058Z] 22:07:34     INFO - GECKO(6436) |     1.197622 |    0.073695 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-08-09T22:07:34.058Z] 22:07:34     INFO - GECKO(6436) |     1.510915 |    0.313293 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2537  | IceGatheringStateChange
[task 2021-08-09T22:07:34.059Z] 22:07:34     INFO - GECKO(6436) |     1.632866 |    0.121951 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2540  | IceGatheringStateChange
[task 2021-08-09T22:07:34.059Z] 22:07:34     INFO - GECKO(6436) |     1.846819 |    0.213953 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-08-09T22:07:34.059Z] 22:07:34     INFO - GECKO(6436) |     2.530376 |    0.683557 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-08-09T22:07:34.060Z] 22:07:34     INFO - GECKO(6436) |     2.607229 |    0.076853 | Ice state: checking            | PeerConnectionImpl.cpp:2481  | IceConnectionStateChange
[task 2021-08-09T22:07:34.060Z] 22:07:34     INFO - GECKO(6436) |     2.611767 |    0.004538 | Ice state: connected           | PeerConnectionImpl.cpp:2484  | IceConnectionStateChange
[task 2021-08-09T22:07:34.060Z] 22:07:34     INFO - GECKO(6436) |     2.762690 |    0.150923 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-08-09T22:07:34.061Z] 22:07:34     INFO - GECKO(6436) |     3.084718 |    0.322028 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-08-09T22:07:34.061Z] 22:07:34     INFO - GECKO(6436) |     3.401239 |    0.316521 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-08-09T22:07:34.062Z] 22:07:34     INFO - GECKO(6436) |     3.497881 |    0.096642 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-08-09T22:07:34.062Z] 22:07:34     INFO - GECKO(6436) |     8.205035 |    4.707154 | Destructor Invoked             | PeerConnectionImpl.cpp:341   | ~PeerConnectionImpl
[task 2021-08-09T22:07:34.063Z] 22:07:34     INFO - GECKO(6436) | [Child 6522: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {e7d327d3-fc90-444e-9fb3-4807ee7a9fed}
[task 2021-08-09T22:07:34.063Z] 22:07:34     INFO - GECKO(6436) | Timecard created 1628546845.858964
<...>
[task 2021-08-09T22:07:40.162Z] 22:07:40     INFO - Creating DataChannelWrapper (pcRemote_channel_2)
[task 2021-08-09T22:07:40.162Z] 22:07:40     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-09T22:07:40.162Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | data channel is 'open' after 'onopen' 
[task 2021-08-09T22:07:40.162Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) is of binary type 'blob' 
[task 2021-08-09T22:07:40.162Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) id is:5 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) protocol is:foo/bar 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) reliable is:false 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) ordered is:false 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) maxRetransmits is:500 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcLocal_channel_2) maxPacketLifeTime is:null 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) is of binary type 'blob' 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) id is:5 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) protocol is:foo/bar 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) reliable is:false 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) ordered is:false 
[task 2021-08-09T22:07:40.163Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) maxRetransmits is:500 
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | DataChannelWrapper (pcRemote_channel_2) maxPacketLifeTime is:null 
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - Run step 54: SEND_MESSAGE_THROUGH_LAST_OPENED_CHANNEL2
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - Sending message:I am the walrus; Goo goo g'joob
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - DataChannelWrapper (pcLocal_channel_2): Sending data 'I am the walrus; Goo goo g'joob'
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | Buffered amount should be 31 
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - DataChannelWrapper (pcRemote_channel_2): "onmessage" event fired
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - Buffered messages finished
[task 2021-08-09T22:07:40.164Z] 22:07:40     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | Unexpected event 'message' fired with message = 'DataChannelWrapper (pcRemote_channel_2)' at: ["createOneShotEventWrapper@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:801:35","DataChannelWrapper@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:696:28","createDataChannel@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:1260:19","PeerConnectionTest.prototype.createDataChannel/remotePromise<@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:342:41",""] 
[task 2021-08-09T22:07:40.165Z] 22:07:40     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-08-09T22:07:40.165Z] 22:07:40     INFO - unexpectedEvent/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:780:7
[task 2021-08-09T22:07:40.165Z] 22:07:40     INFO - createOneShotEventWrapper/obj[onx]@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:806:17
[task 2021-08-09T22:07:40.165Z] 22:07:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-08-09T22:07:40.167Z] 22:07:40     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | Error in test execution: Error: Unexpected event 'message' fired with message = 'DataChannelWrapper (pcRemote_channel_2)' at: ["createOneShotEventWrapper@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:801:35","DataChannelWrapper@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:696:28","createDataChannel@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:1260:19","PeerConnectionTest.prototype.createDataChannel/remotePromise<@https://example.com/tests/dom/media/webrtc/tests/mochitests/pc.js:342:41",""] unexpectedEvent/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:781:28 ... createOneShotEventWrapper/obj[onx]@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:806:17 ...  
[task 2021-08-09T22:07:40.167Z] 22:07:40     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-08-09T22:07:40.167Z] 22:07:40     INFO - execute/<@https://example.com/tests/dom/media/webrtc/tests/mochitests/head.js:1007:11
[task 2021-08-09T22:07:40.170Z] 22:07:40     INFO - closeDataChannels called with index: 0
[task 2021-08-09T22:07:40.170Z] 22:07:40     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-09T22:07:40.171Z] 22:07:40     INFO - DataChannelWrapper (pcRemote_channel_0): Closing channel
[task 2021-08-09T22:07:40.171Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00/Channel 7b340001e850: Closing stream 1
[task 2021-08-09T22:07:40.172Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Resetting outgoing stream 1
[task 2021-08-09T22:07:40.172Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Sending outgoing stream reset for 1 streams
[task 2021-08-09T22:07:40.173Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel DataChannelConnection labeled channel_0(7b340001e850) (stream 1) changing ready state OPEN -> CLOSING
[task 2021-08-09T22:07:40.173Z] 22:07:40     INFO - closeDataChannels called with index: 1
[task 2021-08-09T22:07:40.174Z] 22:07:40     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-09T22:07:40.174Z] 22:07:40     INFO - DataChannelWrapper (pcRemote_channel_1): Closing channel
[task 2021-08-09T22:07:40.175Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00/Channel 7b340001f620: Closing stream 3
[task 2021-08-09T22:07:40.175Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Resetting outgoing stream 3
[task 2021-08-09T22:07:40.176Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Sending outgoing stream reset for 1 streams
[task 2021-08-09T22:07:40.176Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel DataChannelConnection labeled channel_1(7b340001f620) (stream 3) changing ready state OPEN -> CLOSING
[task 2021-08-09T22:07:40.177Z] 22:07:40     INFO - closeDataChannels called with index: 2
[task 2021-08-09T22:07:40.177Z] 22:07:40     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-09T22:07:40.178Z] 22:07:40     INFO - DataChannelWrapper (pcRemote_channel_2): Closing channel
[task 2021-08-09T22:07:40.178Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00/Channel 7b34000818b0: Closing stream 5
[task 2021-08-09T22:07:40.179Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Resetting outgoing stream 5
[task 2021-08-09T22:07:40.179Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel Connection 7b58000e0d00: Sending outgoing stream reset for 1 streams
[task 2021-08-09T22:07:40.180Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel DataChannelConnection labeled channel_2(7b34000818b0) (stream 5) changing ready state OPEN -> CLOSING
[task 2021-08-09T22:07:40.180Z] 22:07:40     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-09T22:07:40.181Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel operator(): sending BUFFER_LOW_THRESHOLD for channel_2/foo/bar: 5
[task 2021-08-09T22:07:40.181Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel 7b2c00066860(7b3400081640): OnBufferLow - Dispatching
[task 2021-08-09T22:07:40.182Z] 22:07:40     INFO - DataChannelWrapper (pcLocal_channel_2): "onbufferedamountlow" event fired
[task 2021-08-09T22:07:40.182Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel operator(): sending NO_LONGER_BUFFERED for channel_2/foo/bar: 5
[task 2021-08-09T22:07:40.183Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel In receive_cb, ulp_info=5
[task 2021-08-09T22:07:40.183Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel In ReceiveCallback
[task 2021-08-09T22:07:40.184Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel Incoming: Channel 1  closed
[task 2021-08-09T22:07:40.184Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel Removing channel 1 : 7b340005c110
<...>
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel Sending 2 pending resets
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Socket Thread]: D/DataChannel Connection 7b580002f400: Sending outgoing stream reset for 2 streams
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel DataChannelConnection labeled channel_0(7b340005c110) (stream 1) changing ready state OPEN -> CLOSED
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel operator(): sending ON_CHANNEL_CLOSED for channel_0/: 1
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - GECKO(6436) | [Child 6522: Main Thread]: D/DataChannel 7b2c000aec10(7b340005c110): OnChannelClosed - Dispatching
[task 2021-08-09T22:07:40.202Z] 22:07:40     INFO - DataChannelWrapper (pcLocal_channel_0): "onclose" event fired
[task 2021-08-09T22:07:40.203Z] 22:07:40     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html | /tests/dom/media/webrtc/tests/mochitests/test_dataChannel_basicAudioVideoCombined.html channel 0 closed

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1614627&startday=2021-08-09&endday=2021-08-15&tree=all

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

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