Closed Bug 1656605 Opened 5 years ago Closed 5 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | bundles on the first transport and closes the second - Test timed out

Categories

(Core :: WebRTC, defect, P5)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2020-07-31T20:34:47.409Z] 20:34:47 INFO - TEST-START | /webrtc/protocol/bundle.https.html
[task 2020-07-31T20:34:47.447Z] 20:34:47 INFO - Setting pref media.navigator.permission.disabled (true)
[task 2020-07-31T20:34:47.486Z] 20:34:47 INFO - Setting pref media.navigator.streams.fake (true)
[task 2020-07-31T20:34:47.513Z] 20:34:47 INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter (false)
[task 2020-07-31T20:34:47.568Z] 20:34:47 INFO - Setting pref privacy.reduceTimerPrecision (false)
[task 2020-07-31T20:34:47.595Z] 20:34:47 INFO - Setting pref media.peerconnection.ice.trickle_grace_period (10000)
[task 2020-07-31T20:34:48.429Z] 20:34:48 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:324: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-07-31T20:34:48.429Z] 20:34:48 INFO - PID 2280 | (unknown/INFO) insert '' (registry) succeeded:
[task 2020-07-31T20:34:48.429Z] 20:34:48 INFO - PID 2280 | (registry/INFO) Initialized registry
[task 2020-07-31T20:34:48.432Z] 20:34:48 INFO - PID 2280 | [Parent 688: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-07-31T20:34:48.435Z] 20:34:48 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:324: PeerConnectionImpl: PeerConnectionImpl constructor for
[task 2020-07-31T20:34:48.438Z] 20:34:48 INFO - PID 2280 | [Parent 688: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2020-07-31T20:34:48.457Z] 20:34:48 INFO - PID 2280 | [Child 4320, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/checkouts/gecko/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1304
[task 2020-07-31T20:34:48.458Z] 20:34:48 INFO - PID 2280 | [Child 4320, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.video.test_latency", &mVideoLatencyTestEnable))', file /builds/worker/checkouts/gecko/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1306
[task 2020-07-31T20:34:48.458Z] 20:34:48 INFO - PID 2280 | [Child 4320, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.spatial", &temp))', file /builds/worker/checkouts/gecko/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1343
[task 2020-07-31T20:34:48.459Z] 20:34:48 INFO - PID 2280 | [Child 4320, Main Thread] WARNING: 'NS_FAILED(branch->GetIntPref( "media.peerconnection.video.svc.temporal", &temp))', file /builds/worker/checkouts/gecko/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1349
[task 2020-07-31T20:34:48.460Z] 20:34:48 INFO - PID 2280 | [Child 4320, Main Thread] WARNING: 'NS_FAILED(branch->GetBoolPref( "media.peerconnection.video.lock_scaling", &mLockScaling))', file /builds/worker/checkouts/gecko/media/webrtc/signaling/src/media-conduit/VideoConduit.cpp, line 1357
[task 2020-07-31T20:34:48.475Z] 20:34:48 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:73: OnStunAddrsAvailable: receiving (3) stun addrs
[task 2020-07-31T20:34:48.476Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice' (registry) succeeded: ice
[task 2020-07-31T20:34:48.477Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref' (registry) succeeded: ice.pref
[task 2020-07-31T20:34:48.477Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type' (registry) succeeded: ice.pref[Child 4320: Main Thread]: I/signaling [main|PeerConnectionMedia] PeerConnectionMedia.cpp:73: OnStunAddrsAvailable: receiving (3) stun addrs
[task 2020-07-31T20:34:48.478Z] 20:34:48 INFO - PID 2280 | .type
[task 2020-07-31T20:34:48.479Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64
[task 2020-07-31T20:34:48.479Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e
[task 2020-07-31T20:34:48.480Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e
[task 2020-07-31T20:34:48.481Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05
[task 2020-07-31T20:34:48.482Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.srv_rflx_tcp' (UCHAR) succeeded: 0x63
[task 2020-07-31T20:34:48.483Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.peer_rflx_tcp' (UCHAR) succeeded: 0x6d
[task 2020-07-31T20:34:48.483Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.host_tcp' (UCHAR) succeeded: 0x7d
[task 2020-07-31T20:34:48.484Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00
[task 2020-07-31T20:34:48.485Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'stun' (registry) succeeded: stun
[task 2020-07-31T20:34:48.486Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'stun.client' (registry) succeeded: stun.client
[task 2020-07-31T20:34:48.486Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'stun.client.maximum_transmits' (UINT4) succeeded: 7
[task 2020-07-31T20:34:48.486Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.trickle_grace_period' (UINT4) succeeded: 10000
[task 2020-07-31T20:34:48.487Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.tcp' (registry) succeeded: ice.tcp
[task 2020-07-31T20:34:48.487Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.tcp.so_sock_count' (INT4) succeeded: 0
[task 2020-07-31T20:34:48.487Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.tcp.listen_backlog' (INT4) succeeded: 10
[task 2020-07-31T20:34:48.488Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.tcp.disable' (char) succeeded: \000
[task 2020-07-31T20:34:48.488Z] 20:34:48 INFO - PID 2280 | (registry/INFO) insert 'ice.forced_interface_name' (string) succeeded:
[task 2020-07-31T20:34:48.503Z] 20:34:48 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0754D8E0

[task 2020-07-31T20:35:05.431Z] 20:35:05 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:05.470Z] 20:35:05 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:05.471Z] 20:35:05 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 37daa88e:f5463808a1152ea808fa76966f21c427)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:05.666Z] 20:35:05 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:05.666Z] 20:35:05 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 50c1f6b2:795b4f0e3dfc79126042b2230f05e258)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:06.389Z] 20:35:06 INFO - PID 2280 | [Child 4320: Socket Thread]: E/signaling [Socket Thread|WebrtcVideoSessionConduit] VideoConduit.cpp:206: Update for VideoConduit:0EBC52A0 RTT returned an error after previously succeeding.
[task 2020-07-31T20:35:06.432Z] 20:35:06 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:06.432Z] 20:35:06 INFO - PID 2280 | [Child 4320: Socket Thread]: E/signaling [Socket Thread|WebrtcAudioSessionConduit] AudioConduit.cpp:227: GetRTCPReceiverReport for AudioConduit:0E8F5000 RTT returned an error after previously succeeding.
[task 2020-07-31T20:35:07.431Z] 20:35:07 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:08.431Z] 20:35:08 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:09.430Z] 20:35:09 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:10.376Z] 20:35:10 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:10.376Z] 20:35:10 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 50c1f6b2:795b4f0e3dfc79126042b2230f05e258)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:10.435Z] 20:35:10 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:10.855Z] 20:35:10 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:10.855Z] 20:35:10 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 37daa88e:f5463808a1152ea808fa76966f21c427)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:11.440Z] 20:35:11 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:12.436Z] 20:35:12 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:13.431Z] 20:35:13 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:14.432Z] 20:35:14 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:15.092Z] 20:35:15 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:15.093Z] 20:35:15 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 37daa88e:f5463808a1152ea808fa76966f21c427)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:15.433Z] 20:35:15 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:15.552Z] 20:35:15 INFO - PID 2280 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-07-31T20:35:15.552Z] 20:35:15 INFO - PID 2280 | (ice/INFO) ICE(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 50c1f6b2:795b4f0e3dfc79126042b2230f05e258)/COMP(1): Consent refreshed
[task 2020-07-31T20:35:16.431Z] 20:35:16 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:17.431Z] 20:35:17 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:18.432Z] 20:35:18 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:18.482Z] 20:35:18 INFO -
[task 2020-07-31T20:35:18.482Z] 20:35:18 INFO - TEST-FAIL | /webrtc/protocol/bundle.https.html | not negotiating BUNDLE creates two separate ice and dtls transports - assert_not_equals: got disallowed value undefined
[task 2020-07-31T20:35:18.482Z] 20:35:18 INFO - @https://web-platform.test:8443/webrtc/protocol/bundle.https.html:47:20
[task 2020-07-31T20:35:18.482Z] 20:35:18 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | bundles on the first transport and closes the second - Test timed out
[task 2020-07-31T20:35:18.482Z] 20:35:18 INFO - TEST-INFO | expected FAIL
[task 2020-07-31T20:35:18.483Z] 20:35:18 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | expected OK
[task 2020-07-31T20:35:18.483Z] 20:35:18 INFO - TEST-INFO took 31073ms
[task 2020-07-31T20:35:18.506Z] 20:35:18 INFO - PID 2280 | 1596227718495 Marionette INFO Stopped listening on port 57152
[task 2020-07-31T20:35:19.128Z] 20:35:19 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2127: CloseInt: Closing PeerConnectionImpl ead4c524cb2e57e7; ending call
[task 2020-07-31T20:35:19.129Z] 20:35:19 INFO - PID 2280 | [Child 4320: Main Thread]: I/jsep [1596227689316000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html)]: stable -> closed
[task 2020-07-31T20:35:19.129Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.129Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.129Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.129Z] 20:35:19 INFO - PID 2280 | [Child 4320: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2761: GetStats: Found no pipelines matching selector.
[task 2020-07-31T20:35:19.130Z] 20:35:19 INFO - PID 2280 | [Child 4320: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2127: CloseInt: Closing PeerConnectionImpl b03a25825cbe9131; ending call
[task 2020-07-31T20:35:19.130Z] 20:35:19 INFO - PID 2280 | [Child 4320: Main Thread]: I/jsep [1596227689319000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html)]: stable -> closed
[task 2020-07-31T20:35:19.137Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.137Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.137Z] 20:35:19 INFO - PID 2280 | [Child 4320: WebRTCPD #3]: E/signaling [WebRTCPD #3|WebrtcAudioSessionConduit] AudioConduit.cpp:614: SendAudioFrame Engine not transmitting
[task 2020-07-31T20:35:19.152Z] 20:35:19 INFO - PID 2280 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

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

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