1624081 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | not negotiating BUNDLE creates two separate ice and dtls transports - Test timed out

Status: RESOLVED DUPLICATE of bug 1818127

(Core :: WebRTC, defect, P2)

Description

[Treeherder Bug Filer]

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

---

[task 2020-03-21T00:44:27.924Z] 00:44:27 INFO - TEST-START | /webrtc/protocol/bundle.https.html

[task 2020-03-21T00:44:44.270Z] 00:44:44 INFO - PID 9980 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-03-21T00:44:44.275Z] 00:44:44 INFO - PID 9980 | (ice/INFO) ICE(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 96a53e7e:8e016b99a91bf8cc2646abf3df7556e3)/COMP(1): Consent refreshed
[task 2020-03-21T00:44:44.293Z] 00:44:44 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:44.696Z] 00:44:44 INFO - PID 9980 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-03-21T00:44:44.696Z] 00:44:44 INFO - PID 9980 | (ice/INFO) ICE(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_1 - 96a53e7e:8e016b99a91bf8cc2646abf3df7556e3)/COMP(1): Consent refreshed
[task 2020-03-21T00:44:44.776Z] 00:44:44 INFO - PID 9980 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-03-21T00:44:44.776Z] 00:44:44 INFO - PID 9980 | (ice/INFO) ICE(PC:1584751469280000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1584751469280000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 04512e56:a12889cae2adefa352ae6e97cf4188c0)/COMP(1): Consent refreshed
[task 2020-03-21T00:44:45.284Z] 00:44:45 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:45.505Z] 00:44:45 INFO - PID 9980 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-03-21T00:44:45.507Z] 00:44:45 INFO - PID 9980 | (ice/INFO) ICE(PC:1584751469280000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1584751469280000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_1 - 04512e56:a12889cae2adefa352ae6e97cf4188c0)/COMP(1): Consent refreshed
[task 2020-03-21T00:44:46.291Z] 00:44:46 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:47.286Z] 00:44:47 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:48.282Z] 00:44:48 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:49.276Z] 00:44:49 INFO - PID 9980 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2020-03-21T00:44:49.276Z] 00:44:49 INFO - PID 9980 | (ice/INFO) ICE(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html))/STREAM(PC:1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html) transport-id=transport_0 - 96a53e7e:8e016b99a91bf8cc2646abf3df7556e3)/COMP(1): Consent refreshed
[task 2020-03-21T00:44:49.286Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:49.295Z] 00:44:49 INFO -
[task 2020-03-21T00:44:49.295Z] 00:44:49 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | not negotiating BUNDLE creates two separate ice and dtls transports - Test timed out
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO - TEST-INFO | expected FAIL
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO -
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/protocol/bundle.https.html | bundles on the first transport and closes the second - expected FAIL
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO - TEST-INFO | expected FAIL
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/protocol/bundle.https.html | expected OK
[task 2020-03-21T00:44:49.296Z] 00:44:49 INFO - TEST-INFO took 21372ms
[task 2020-03-21T00:44:49.326Z] 00:44:49 INFO - PID 9980 | 1584751489316 Marionette INFO Stopped listening on port 57613
[task 2020-03-21T00:44:49.513Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2113: CloseInt: Closing PeerConnectionImpl 00ffc9118f738f02; ending call
[task 2020-03-21T00:44:49.513Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: I/jsep [1584751469280000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html)]: stable -> closed
[task 2020-03-21T00:44:49.518Z] 00:44:49 INFO - PID 9980 | [Child 3580: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:597: SendAudioFrame Engine not transmitting
[task 2020-03-21T00:44:49.518Z] 00:44:49 INFO - PID 9980 | [Child 3580: WebRTCPD #1]: E/signaling [WebRTCPD #1|WebrtcAudioSessionConduit] AudioConduit.cpp:597: SendAudioFrame Engine not transmitting
[task 2020-03-21T00:44:49.523Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2711: GetStats: Found no pipelines matching selector.
[task 2020-03-21T00:44:49.523Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2113: CloseInt: Closing PeerConnectionImpl c98080ae0779ff47; ending call
[task 2020-03-21T00:44:49.524Z] 00:44:49 INFO - PID 9980 | [Child 3580: Main Thread]: I/jsep [1584751469290000 (id=2147483651 url=https://web-platform.test:8443/webrtc/protocol/bundle.https.html)]: stable -> closed
[task 2020-03-21T00:44:49.524Z] 00:44:49 INFO - PID 9980 | [Child 3580: WebRTCPD #2]: E/signaling [WebRTCPD #2|WebrtcAudioSessionConduit] AudioConduit.cpp:597: SendAudioFrame Engine not transmitting
[task 2020-03-21T00:44:49.562Z] 00:44:49 INFO - PID 9980 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-21T00:44:49.562Z] 00:44:49 INFO - PID 9980 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-21T00:44:49.613Z] 00:44:49 INFO - PID 9980 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-21T00:44:49.636Z] 00:44:49 INFO - PID 9980 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-03-21T00:44:49.655Z] 00:44:49 INFO - PID 9980 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

Comment 1

[Intermittent Failures Robot]

8 failures in 4955 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 8

Platform breakdown:

• windows10-64-ccov: 8

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

Comment 2

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

This fails frequently on Windows ccov since last Friday. Triggered by bug 1616875?

Comment 3

[Byron Campen [:bwc]]

This is a brand new test, landed on 3/13, but we don't see failures start until 3/20? Are we just missing some classifications?

Comment 4

[Byron Campen [:bwc]]

Hmm, failures do indeed seem to start on 3/20. Looking closer.

Comment 5

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f0573c0894606db8a040258a755de5e912e4a492

Comment 6

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7d0130a140c27630efe56dd5f22bb5e4dce06cfa

Comment 7

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=51cdab75400ba2f7fe913c682e820fef42f7567c

Comment 8

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1268370ff74641808a81c3367054ef16b65b8378

Comment 9

[Byron Campen [:bwc]]

Ok, this is weird. The test works fine when run by itself, or with the full set of webrtc tests. But, when run using the normal chunking, it times out.

Comment 10

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b3b43e498f075bd0eca3ffdb183cd511c6f3917e

Comment 11

[Byron Campen [:bwc]]

As far as I can tell, this failure only happens due to an earlier test (that isn't related to webrtc) running in the chunk.

Comment 12

[Byron Campen [:bwc]]

It looks like this test is timing out here, waiting for a "loadedmetadata" event.

https://searchfox.org/mozilla-central/rev/4d9cd186767978a99dafe77eb536a9525980e118/testing/web-platform/tests/webrtc/protocol/bundle.https.html#43

Bryce, is there anything that landed on the 20th that might effect this in some way?

Comment 13

[Byron Campen [:bwc]]

Actually, this test looks flawed. We are setting up the |metadataToBeLoaded| promise here, in ontrack:

https://searchfox.org/mozilla-central/rev/4d9cd186767978a99dafe77eb536a9525980e118/testing/web-platform/tests/webrtc/protocol/bundle.https.html#26

However, we expect to get ontrack twice, once each for audio and video. The order in which we get these should depend on the order of the addTrack calls, but I'm not sure what that is going to be.

Comment 14

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=639f70a8de068c8e984b3d66bbdd72f6b4155aba

Comment 16

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Bryce, is there anything that landed on the 20th that might effect this in some way?

Sounds like you've got a plan. I had a look at all the commits landed under dom/media and didn't see anything that jumped out at me. If you don't get any traction, let me know and I can fine tooth comb the changes.

Comment 17

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=edcbf3d565eba353aaf121e8d461871662736979

Comment 18

[Intermittent Failures Robot]

28 failures in 4773 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 28

Platform breakdown:

• windows10-64-ccov: 28

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624081&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 19

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=21389f629722af4781c764c18b6a1a4fd7eed707

Comment 20

[Intermittent Failures Robot]

28 failures in 5015 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 23
• autoland: 4
• try: 1

Platform breakdown:

• windows10-64-ccov: 20
• windows7-32-shippable: 2
• windows10-64-shippable: 4
• windows7-32: 1
• windows10-64-shippable-qr: 1

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

Comment 21

[Byron Campen [:bwc]]

Looks like this has spread beyond ccov to other windows builds, starting on the 31st.

Comment 22

[Byron Campen [:bwc]]

Hang on, those look misclassified to me. Those are cases where we do not timeout as expected, because the .ini file changed.

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 11
• autoland: 6
• mozilla-beta: 1
• try: 3

Platform breakdown:

• windows10-64-ccov: 7
• windows10-64-shippable: 8
• windows10-64-qr: 1
• windows7-32-shippable: 1
• windows10-64-shippable-qr: 2
• windows7-32: 2

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

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

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

Comment 25

[Intermittent Failures Robot]

3 failures in 5458 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• autoland: 1

Platform breakdown:

• windows10-64-ccov: 2
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1624081&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 26

[Intermittent Failures Robot]

3 failures in 4275 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform breakdown:

• windows7-32: 3

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

Comment 27

[Intermittent Failures Robot]

69 failures in 651 pushes (0.106 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 69

Platform breakdown:

• linux64-shippable-qr: 1
• android-hw-p2-8-0-android-aarch64-shippable: 34
• android-hw-g5-7-0-arm7-api-16-shippable: 34

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

Comment 28

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64: 1

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