1421830 - test_peerConnection_scaleResolution.html sometimes generates log chatter until shutdown

Status: RESOLVED FIXED

(Core :: WebRTC, defect)

Description

[Geoff Brown [:gbrown]]

In some test logs, I see frequent logging related to test_peerConnection_scaleResolution, well after the test has finished.

https://public-artifacts.taskcluster.net/bkcCO46hSjKOzCVQXrq3xQ/0/public/logs/live_backing.log

[task 2017-11-28T15:35:17.947Z] 15:35:17     INFO - TEST-OK | dom/media/tests/mochitest/test_peerConnection_scaleResolution.html | took 32037ms
[task 2017-11-28T15:35:18.017Z] 15:35:18     INFO - GECKO(3145) | [Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:3132: CloseInt: Closing PeerConnectionImpl 07ea34df62d41ab0; ending call
[task 2017-11-28T15:35:18.018Z] 15:35:18     INFO - GECKO(3145) | [Main Thread]: I/jsep [1511883290396953 (id=2147484016 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_scaleResolution.]: stable -> closed
[task 2017-11-28T15:35:18.018Z] 15:35:18     INFO - GECKO(3145) | [Socket Thread]: W/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:1170: Dropping incoming RTCP packet; filtered out
[task 2017-11-28T15:35:18.020Z] 15:35:18     INFO - GECKO(3145) | [Socket Thread]: I/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:925: Transport closed for flow RTP/RTCP mux
[task 2017-11-28T15:35:18.022Z] 15:35:18     INFO - GECKO(3145) | [Socket Thread]: E/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:1027: Discarding incoming packet; pipeline not open
[task 2017-11-28T15:35:18.023Z] 15:35:18     INFO - GECKO(3145) | [Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:3132: CloseInt: Closing PeerConnectionImpl 73a2356321f98015; ending call
[task 2017-11-28T15:35:18.024Z] 15:35:18     INFO - GECKO(3145) | [Main Thread]: I/jsep [1511883290415428 (id=2147484016 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_scaleResolution.]: stable -> closed

...

[task 2017-11-28T16:14:44.857Z] 16:14:44     INFO - GECKO(3145) | [Socket Thread]: E/mtransport Couldn't send media on '0-1511883286455130 (id=2147484016 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_scaleResolution. aLevel=0'


I don't know if this extra logging is "harmful", but it is annoying.

Comment 1

[Geoff Brown [:gbrown]]

Attachment: close RTCPeerConnections

I see similar logging if I run the test locally, by itself:

mach mochitest dom/media/tests/mochitest/test_peerConnection_scaleResolution.html

After the test finishes, but as long as the browser remains open, there's output chatter.

If I explicitly close the RTCPeerConnection instances at the end of the test, all's well (extra output stops when test ends).

Comment 2

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Comment on attachment 8933116 [details] [diff] [review]
close RTCPeerConnections

Review of attachment 8933116 [details] [diff] [review]:
-----------------------------------------------------------------

Good idea! We should do this on all tests.

Comment 3

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

That said, I don't fully understand why that happens, as I'd expect the pcs to close OnNavigation [1]. 

Doesn't each test run in a separate page?

[1] https://searchfox.org/mozilla-central/rev/be78e6ea9b10b1f5b2b3b013f01d86e1062abb2b/dom/media/PeerConnection.js#165,167

Comment 4

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

I think I answered my own question: the bfcache.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4a5a454ab6c7
In test_peerConnection_scaleResolution.html, close RTCPeerConnections; r=jib

Comment 6

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

https://hg.mozilla.org/mozilla-central/rev/4a5a454ab6c7