Closed Bug 1719578 Opened 4 years ago Closed 3 years ago

Intermittent dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1

Categories

(Core :: WebRTC: Audio/Video, defect, P5)

defect

Tracking

()

RESOLVED FIXED
97 Branch
Tracking Status
firefox-esr91 --- wontfix
firefox94 --- wontfix
firefox95 --- wontfix
firefox96 --- wontfix
firefox97 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(6 files)

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


[task 2021-07-07T22:42:37.503Z] 22:42:37     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_setSinkId.html
[task 2021-07-07T22:42:37.690Z] 22:42:37     INFO - GECKO(6069) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-07-07T22:42:37.691Z] 22:42:37     INFO - GECKO(6069) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-07-07T22:42:37.766Z] 22:42:37     INFO - GECKO(6069) | Timecard created 1625697748.576498
[task 2021-07-07T22:42:37.767Z] 22:42:37     INFO - GECKO(6069) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-07-07T22:42:37.767Z] 22:42:37     INFO - GECKO(6069) | ======================================================================================================================
[task 2021-07-07T22:42:37.768Z] 22:42:37     INFO - GECKO(6069) |     0.000124 |    0.000124 | Constructor Completed          | PeerConnectionImpl.cpp:332   | PeerConnectionImpl
[task 2021-07-07T22:42:37.768Z] 22:42:37     INFO - GECKO(6069) |     0.001221 |    0.001097 | Initializing PC Ctx            | PeerConnectionImpl.cpp:450   | Initialize
[task 2021-07-07T22:42:37.768Z] 22:42:37     INFO - GECKO(6069) |     0.102318 |    0.101097 | Create Offer                   | PeerConnectionImpl.cpp:1212  | CreateOffer
[task 2021-07-07T22:42:37.769Z] 22:42:37     INFO - GECKO(6069) |     0.125395 |    0.023077 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.769Z] 22:42:37     INFO - GECKO(6069) |     0.223820 |    0.098425 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2537  | IceGatheringStateChange
[task 2021-07-07T22:42:37.769Z] 22:42:37     INFO - GECKO(6069) |     0.241078 |    0.017258 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2540  | IceGatheringStateChange
[task 2021-07-07T22:42:37.770Z] 22:42:37     INFO - GECKO(6069) |     0.284328 |    0.043250 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.770Z] 22:42:37     INFO - GECKO(6069) |     0.310060 |    0.025732 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.771Z] 22:42:37     INFO - GECKO(6069) |     0.320609 |    0.010549 | Ice state: checking            | PeerConnectionImpl.cpp:2481  | IceConnectionStateChange
[task 2021-07-07T22:42:37.772Z] 22:42:37     INFO - GECKO(6069) |     0.321852 |    0.001243 | Ice state: connected           | PeerConnectionImpl.cpp:2484  | IceConnectionStateChange
[task 2021-07-07T22:42:37.773Z] 22:42:37     INFO - GECKO(6069) |     0.324855 |    0.003003 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.774Z] 22:42:37     INFO - GECKO(6069) |     0.343206 |    0.018351 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.774Z] 22:42:37     INFO - GECKO(6069) |     0.344551 |    0.001345 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.774Z] 22:42:37     INFO - GECKO(6069) |     0.345342 |    0.000791 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.775Z] 22:42:37     INFO - GECKO(6069) |     2.163595 |    1.818253 | Create Offer                   | PeerConnectionImpl.cpp:1212  | CreateOffer
[task 2021-07-07T22:42:37.776Z] 22:42:37     INFO - GECKO(6069) |     2.167711 |    0.004116 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.776Z] 22:42:37     INFO - GECKO(6069) |     2.215186 |    0.047475 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.777Z] 22:42:37     INFO - GECKO(6069) |     7.674710 |    5.459524 | Create Offer                   | PeerConnectionImpl.cpp:1212  | CreateOffer
[task 2021-07-07T22:42:37.777Z] 22:42:37     INFO - GECKO(6069) |     7.677006 |    0.002296 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.778Z] 22:42:37     INFO - GECKO(6069) |     7.713916 |    0.036910 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.778Z] 22:42:37     INFO - GECKO(6069) |     9.180294 |    1.466378 | Destructor Invoked             | PeerConnectionImpl.cpp:341   | ~PeerConnectionImpl
[task 2021-07-07T22:42:37.781Z] 22:42:37     INFO - GECKO(6069) | [Child 6148: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {e9b66283-68f0-434a-82e9-acaab3b68ea4}
[task 2021-07-07T22:42:37.781Z] 22:42:37     INFO - GECKO(6069) | Timecard created 1625697748.586243
[task 2021-07-07T22:42:37.782Z] 22:42:37     INFO - GECKO(6069) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-07-07T22:42:37.782Z] 22:42:37     INFO - GECKO(6069) | ======================================================================================================================
[task 2021-07-07T22:42:37.782Z] 22:42:37     INFO - GECKO(6069) |     0.001069 |    0.001069 | Constructor Completed          | PeerConnectionImpl.cpp:332   | PeerConnectionImpl
[task 2021-07-07T22:42:37.782Z] 22:42:37     INFO - GECKO(6069) |     0.002147 |    0.001078 | Initializing PC Ctx            | PeerConnectionImpl.cpp:450   | Initialize
[task 2021-07-07T22:42:37.783Z] 22:42:37     INFO - GECKO(6069) |     0.136083 |    0.133936 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.783Z] 22:42:37     INFO - GECKO(6069) |     0.204361 |    0.068278 | Create Answer                  | PeerConnectionImpl.cpp:1243  | CreateAnswer
[task 2021-07-07T22:42:37.783Z] 22:42:37     INFO - GECKO(6069) |     0.237534 |    0.033173 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.784Z] 22:42:37     INFO - GECKO(6069) |     0.247991 |    0.010457 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.784Z] 22:42:37     INFO - GECKO(6069) |     0.248703 |    0.000712 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.785Z] 22:42:37     INFO - GECKO(6069) |     0.249275 |    0.000572 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.786Z] 22:42:37     INFO - GECKO(6069) |     0.249856 |    0.000581 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.786Z] 22:42:37     INFO - GECKO(6069) |     0.250418 |    0.000562 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.787Z] 22:42:37     INFO - GECKO(6069) |     0.251101 |    0.000683 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.787Z] 22:42:37     INFO - GECKO(6069) |     0.252143 |    0.001042 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.788Z] 22:42:37     INFO - GECKO(6069) |     0.252841 |    0.000698 | Add Ice Candidate              | PeerConnectionImpl.cpp:1529  | AddIceCandidate
[task 2021-07-07T22:42:37.789Z] 22:42:37     INFO - GECKO(6069) |     0.253585 |    0.000744 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.789Z] 22:42:37     INFO - GECKO(6069) |     0.282719 |    0.029134 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2537  | IceGatheringStateChange
[task 2021-07-07T22:42:37.790Z] 22:42:37     INFO - GECKO(6069) |     0.290668 |    0.007949 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2540  | IceGatheringStateChange
[task 2021-07-07T22:42:37.791Z] 22:42:37     INFO - GECKO(6069) |     0.296038 |    0.005370 | Ice state: checking            | PeerConnectionImpl.cpp:2481  | IceConnectionStateChange
[task 2021-07-07T22:42:37.792Z] 22:42:37     INFO - GECKO(6069) |     0.311661 |    0.015623 | Ice state: connected           | PeerConnectionImpl.cpp:2484  | IceConnectionStateChange
[task 2021-07-07T22:42:37.793Z] 22:42:37     INFO - GECKO(6069) |     2.169499 |    1.857838 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.794Z] 22:42:37     INFO - GECKO(6069) |     2.181613 |    0.012114 | Create Answer                  | PeerConnectionImpl.cpp:1243  | CreateAnswer
[task 2021-07-07T22:42:37.797Z] 22:42:37     INFO - GECKO(6069) |     2.184582 |    0.002969 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.798Z] 22:42:37     INFO - GECKO(6069) |     7.675783 |    5.491201 | Set Remote Description         | PeerConnectionImpl.cpp:1381  | SetRemoteDescription
[task 2021-07-07T22:42:37.799Z] 22:42:37     INFO - GECKO(6069) |     7.689349 |    0.013566 | Create Answer                  | PeerConnectionImpl.cpp:1243  | CreateAnswer
[task 2021-07-07T22:42:37.800Z] 22:42:37     INFO - GECKO(6069) |     7.692626 |    0.003277 | Set Local Description          | PeerConnectionImpl.cpp:1281  | SetLocalDescription
[task 2021-07-07T22:42:37.801Z] 22:42:37     INFO - GECKO(6069) |     9.171173 |    1.478547 | Destructor Invoked             | PeerConnectionImpl.cpp:341   | ~PeerConnectionImpl
[task 2021-07-07T22:42:37.802Z] 22:42:37     INFO - GECKO(6069) | [Child 6148: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {7daa7650-29be-4804-b734-1222dc5de6d5}
[task 2021-07-07T22:42:37.877Z] 22:42:37     INFO - TEST-INFO | started process screentopng
[task 2021-07-07T22:42:38.193Z] 22:42:38     INFO - TEST-INFO | screentopng: exit 0
[task 2021-07-07T22:42:38.194Z] 22:42:38     INFO - Buffered messages logged at 22:42:37
[task 2021-07-07T22:42:38.195Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | A valid string reason is expected 
[task 2021-07-07T22:42:38.195Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Reason cannot be empty 
[task 2021-07-07T22:42:38.196Z] 22:42:38     INFO - Buffered messages finished
[task 2021-07-07T22:42:38.197Z] 22:42:38     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1
[task 2021-07-07T22:42:38.198Z] 22:42:38     INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-07-07T22:42:38.199Z] 22:42:38     INFO - @https://example.com/tests/dom/media/webrtc/tests/mochitests/test_setSinkId.html:34:7
[task 2021-07-07T22:42:38.201Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Initial value is empty string 
[task 2021-07-07T22:42:38.201Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Value is unchanged upon function return 
[task 2021-07-07T22:42:38.202Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | promise resolves with undefined 
[task 2021-07-07T22:42:38.202Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Sink device is set, id: 0LWHKsBndkKUOOz2ApydtaRj4fY2vG6jUr4mBw+J2xU= 
[task 2021-07-07T22:42:38.202Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Sink device is set for 2nd time for the same id: 0LWHKsBndkKUOOz2ApydtaRj4fY2vG6jUr4mBw+J2xU= 
[task 2021-07-07T22:42:38.203Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Set sink id expected to fail: NotFoundError: The object can not be found here. 
[task 2021-07-07T22:42:38.203Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Verify correct error 
[task 2021-07-07T22:42:38.327Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | MediaManager memory usage should be non-zero to store device ids after enumerateDevices 
[task 2021-07-07T22:42:38.327Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | sinkId after setSinkId("") return 
[task 2021-07-07T22:42:38.330Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | promise resolution value when sinkId parameter is empty 
[task 2021-07-07T22:42:38.331Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | sinkId after setSinkId("") resolution 
[task 2021-07-07T22:42:38.600Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Expect only one MediaManager to report in content processes. 
[task 2021-07-07T22:42:38.602Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | MediaManager memory usage should return to previous value after promise resolution 
[task 2021-07-07T22:42:38.615Z] 22:42:38     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Test must leave no active gUM streams behind. 
[task 2021-07-07T22:42:38.623Z] 22:42:38     INFO - GECKO(6069) | MEMORY STAT | vsize 20975714MB | residentFast 1844MB
[task 2021-07-07T22:42:38.648Z] 22:42:38     INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_setSinkId.html | took 1146ms
Summary: Intermittent dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1 → Intermittent [tier 2] dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1
Summary: Intermittent [tier 2] dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1 → Intermittent dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1
Regressed by: 1493982

Set release status flags based on info from the regressing bug 1493982

Set release status flags based on info from the regressing bug 1493982

See Also: → 1652294

There are 59 total failuresin the last 7 days on

[task 2021-12-28T23:48:23.378Z] 23:48:23     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_setSinkId.html
[task 2021-12-28T23:48:23.834Z] 23:48:23     INFO - GECKO(6250) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-12-28T23:48:23.837Z] 23:48:23     INFO - GECKO(6250) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-12-28T23:48:23.939Z] 23:48:23     INFO - GECKO(6250) | Timecard created 1640735291.309811
[task 2021-12-28T23:48:23.940Z] 23:48:23     INFO - GECKO(6250) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-12-28T23:48:23.941Z] 23:48:23     INFO - GECKO(6250) | ======================================================================================================================
[task 2021-12-28T23:48:23.942Z] 23:48:23     INFO - GECKO(6250) |     0.000288 |    0.000288 | Constructor Completed          | PeerConnectionImpl.cpp:333   | PeerConnectionImpl
[task 2021-12-28T23:48:23.944Z] 23:48:23     INFO - GECKO(6250) |     0.002807 |    0.002519 | Initializing PC Ctx            | PeerConnectionImpl.cpp:452   | Initialize
[task 2021-12-28T23:48:23.944Z] 23:48:23     INFO - GECKO(6250) |     0.465833 |    0.463026 | Create Offer                   | PeerConnectionImpl.cpp:1216  | CreateOffer
[task 2021-12-28T23:48:23.945Z] 23:48:23     INFO - GECKO(6250) |     0.515486 |    0.049653 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.945Z] 23:48:23     INFO - GECKO(6250) |     0.599963 |    0.084477 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2539  | IceGatheringStateChange
[task 2021-12-28T23:48:23.945Z] 23:48:23     INFO - GECKO(6250) |     0.638208 |    0.038245 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2542  | IceGatheringStateChange
[task 2021-12-28T23:48:23.946Z] 23:48:23     INFO - GECKO(6250) |     0.925029 |    0.286821 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.951Z] 23:48:23     INFO - GECKO(6250) |     0.971622 |    0.046593 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.048044 |    0.076422 | Ice state: checking            | PeerConnectionImpl.cpp:2483  | IceConnectionStateChange
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.053000 |    0.004956 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.061554 |    0.008554 | Ice state: connected           | PeerConnectionImpl.cpp:2486  | IceConnectionStateChange
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.068121 |    0.006567 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.100607 |    0.032486 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     1.105536 |    0.004929 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     2.990065 |    1.884529 | Create Offer                   | PeerConnectionImpl.cpp:1216  | CreateOffer
[task 2021-12-28T23:48:23.952Z] 23:48:23     INFO - GECKO(6250) |     3.008701 |    0.018636 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.956Z] 23:48:23     INFO - GECKO(6250) |     3.109659 |    0.100958 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.957Z] 23:48:23     INFO - GECKO(6250) |     9.527071 |    6.417412 | Create Offer                   | PeerConnectionImpl.cpp:1216  | CreateOffer
[task 2021-12-28T23:48:23.959Z] 23:48:23     INFO - GECKO(6250) |     9.534078 |    0.007007 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.966Z] 23:48:23     INFO - GECKO(6250) |     9.621443 |    0.087365 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.966Z] 23:48:23     INFO - GECKO(6250) |    12.625608 |    3.004165 | Destructor Invoked             | PeerConnectionImpl.cpp:342   | ~PeerConnectionImpl
[task 2021-12-28T23:48:23.966Z] 23:48:23     INFO - GECKO(6250) | [Child 6361: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:368: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {8925d047-a1dd-4809-a782-bf49e079aa83}
[task 2021-12-28T23:48:23.967Z] 23:48:23     INFO - GECKO(6250) | Timecard created 1640735291.322200
[task 2021-12-28T23:48:23.967Z] 23:48:23     INFO - GECKO(6250) |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2021-12-28T23:48:23.967Z] 23:48:23     INFO - GECKO(6250) | ======================================================================================================================
[task 2021-12-28T23:48:23.968Z] 23:48:23     INFO - GECKO(6250) |     0.000255 |    0.000255 | Constructor Completed          | PeerConnectionImpl.cpp:333   | PeerConnectionImpl
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.003432 |    0.003177 | Initializing PC Ctx            | PeerConnectionImpl.cpp:452   | Initialize
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.560268 |    0.556836 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.768285 |    0.208017 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.822818 |    0.054533 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.854640 |    0.031822 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.969Z] 23:48:23     INFO - GECKO(6250) |     0.859449 |    0.004809 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.970Z] 23:48:23     INFO - GECKO(6250) |     0.861936 |    0.002487 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.970Z] 23:48:23     INFO - GECKO(6250) |     0.864372 |    0.002436 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.971Z] 23:48:23     INFO - GECKO(6250) |     0.867008 |    0.002636 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.971Z] 23:48:23     INFO - GECKO(6250) |     0.869530 |    0.002522 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.971Z] 23:48:23     INFO - GECKO(6250) |     0.872808 |    0.003278 | Add Ice Candidate              | PeerConnectionImpl.cpp:1533  | AddIceCandidate
[task 2021-12-28T23:48:23.972Z] 23:48:23     INFO - GECKO(6250) |     0.876625 |    0.003817 | Create Answer                  | PeerConnectionImpl.cpp:1247  | CreateAnswer
[task 2021-12-28T23:48:23.972Z] 23:48:23     INFO - GECKO(6250) |     0.887149 |    0.010524 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.972Z] 23:48:23     INFO - GECKO(6250) |     0.933600 |    0.046451 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2539  | IceGatheringStateChange
[task 2021-12-28T23:48:23.972Z] 23:48:23     INFO - GECKO(6250) |     0.985682 |    0.052082 | Ice state: checking            | PeerConnectionImpl.cpp:2483  | IceConnectionStateChange
[task 2021-12-28T23:48:23.972Z] 23:48:23     INFO - GECKO(6250) |     1.027149 |    0.041467 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2542  | IceGatheringStateChange
[task 2021-12-28T23:48:23.973Z] 23:48:23     INFO - GECKO(6250) |     1.047811 |    0.020662 | Ice state: connected           | PeerConnectionImpl.cpp:2486  | IceConnectionStateChange
[task 2021-12-28T23:48:23.974Z] 23:48:23     INFO - GECKO(6250) |     3.017090 |    1.969279 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.975Z] 23:48:23     INFO - GECKO(6250) |     3.058129 |    0.041039 | Create Answer                  | PeerConnectionImpl.cpp:1247  | CreateAnswer
[task 2021-12-28T23:48:23.977Z] 23:48:23     INFO - GECKO(6250) |     3.069079 |    0.010950 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.977Z] 23:48:23     INFO - GECKO(6250) |     9.540816 |    6.471737 | Set Remote Description         | PeerConnectionImpl.cpp:1385  | SetRemoteDescription
[task 2021-12-28T23:48:23.978Z] 23:48:23     INFO - GECKO(6250) |     9.574633 |    0.033817 | Create Answer                  | PeerConnectionImpl.cpp:1247  | CreateAnswer
[task 2021-12-28T23:48:23.978Z] 23:48:23     INFO - GECKO(6250) |     9.584087 |    0.009454 | Set Local Description          | PeerConnectionImpl.cpp:1285  | SetLocalDescription
[task 2021-12-28T23:48:23.979Z] 23:48:23     INFO - GECKO(6250) |    12.614414 |    3.030327 | Destructor Invoked             | PeerConnectionImpl.cpp:342   | ~PeerConnectionImpl
task 2021-12-28T23:48:23.980Z] 23:48:23     INFO - GECKO(6250) | [Child 6361: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:368: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {726aca7f-d382-46cf-b50e-3addb9a03007}
[task 2021-12-28T23:48:24.681Z] 23:48:24     INFO - TEST-INFO | started process screentopng
[task 2021-12-28T23:48:24.925Z] 23:48:24     INFO - TEST-INFO | screentopng: exit 0
[task 2021-12-28T23:48:24.926Z] 23:48:24     INFO - Buffered messages logged at 23:48:23
[task 2021-12-28T23:48:24.926Z] 23:48:24     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | A valid string reason is expected 
[task 2021-12-28T23:48:24.927Z] 23:48:24     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Reason cannot be empty 
[task 2021-12-28T23:48:24.928Z] 23:48:24     INFO - Buffered messages finished
[task 2021-12-28T23:48:24.928Z] 23:48:24     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Number of output devices found - got 2, expected 1
[task 2021-12-28T23:48:24.929Z] 23:48:24     INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-12-28T23:48:24.929Z] 23:48:24     INFO - @https://example.com/tests/dom/media/webrtc/tests/mochitests/test_setSinkId.html:34:7
[task 2021-12-28T23:48:25.057Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Initial value is empty string 
[task 2021-12-28T23:48:25.059Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Value is unchanged upon function return 
[task 2021-12-28T23:48:25.207Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | promise resolves with undefined 
[task 2021-12-28T23:48:25.209Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Sink device is set, id: 3G6A/W7fCBXCX9xP4Fx2hhVIWDj7/k4KVUWNMaznzE0= 
[task 2021-12-28T23:48:25.211Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Sink device is set for 2nd time for the same id: 3G6A/W7fCBXCX9xP4Fx2hhVIWDj7/k4KVUWNMaznzE0= 
[task 2021-12-28T23:48:25.233Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Set sink id expected to fail: NotFoundError: The object can not be found here. 
[task 2021-12-28T23:48:25.238Z] 23:48:25     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Verify correct error 
[task 2021-12-28T23:48:26.367Z] 23:48:26     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | MediaManager memory usage should be non-zero to store device ids after enumerateDevices 
[task 2021-12-28T23:48:26.368Z] 23:48:26     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | sinkId after setSinkId("") return 
[task 2021-12-28T23:48:26.391Z] 23:48:26     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | promise resolution value when sinkId parameter is empty 
[task 2021-12-28T23:48:26.392Z] 23:48:26     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | sinkId after setSinkId("") resolution 
[task 2021-12-28T23:48:27.512Z] 23:48:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Expect only one MediaManager to report in content processes. 
[task 2021-12-28T23:48:27.513Z] 23:48:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | MediaManager memory usage should return to previous value after promise resolution 
[task 2021-12-28T23:48:27.548Z] 23:48:27     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_setSinkId.html | Test must leave no active gUM streams behind. 
[task 2021-12-28T23:48:27.575Z] 23:48:27     INFO - GECKO(6250) | MEMORY STAT | vsize 130560304MB | residentFast 2351MB
[task 2021-12-28T23:48:27.658Z] 23:48:27     INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_setSinkId.html | took 4278ms

Retriggers point to 1732409 : https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Ctsan%2Copt%2Cmochitests%2Cwith%2Csocket%2Cprocess%2Ctest-linux1804-64-tsan-qr%2Fopt-mochitest-media-spi-e10s%2Cmda2&tochange=2dcdc75fdf55f3b94b67f87b19fbac9b4711ff2c&fromchange=45e17ed872759e070c9354a39045e667e68a76fb&test_paths=dom%2Fmedia%2Fwebrtc%2Ftests%2Fmochitests&group_state=expanded&selectedTaskRun=aAUJxkRCQci6007y0UP00w.0

Karl, can you please take a look?

Flags: needinfo?(karlt)
Regressed by: 1732409
Whiteboard: [retriggered][stockwell needswork:owner]

I'll put some patches up for review, but Paul won't be available to review before next week.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=abf44ca6bd5de3a767762805cba0a8ebb9fda625

If this is causing trouble, then feel free to back out https://hg.mozilla.org/integration/autoland/rev/2dcdc75fdf55f3b94b67f87b19fbac9b4711ff2c and that will likely restore the previous timing, which usually averts the race.

Flags: needinfo?(karlt)
Regressed by: 1583996
Assignee: nobody → karlt
Status: NEW → ASSIGNED

Depends on D134805

This reduces some copying and fixes a race where AppendElements() could add
the set of devices to the end of mInputDevices and/or mOutputDevices multiple
times if multiple threads were in EnumerateAudioDevices() concurrently.

It will also facilitate passing a thread-safe reference to mInputDevices
and/or mOutputDevices for use within CubebDeviceEnumerator without the need to
hold the Mutex.

Depends on D134807

This removes some illusion that the mutex might be held throughout the duration
of the callers' execution.

Depends on D134808

This removes the possibility of overlooking the MutexAutoUnlock.

Depends on D134809

Blocks: 1650054
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/608f1fdfc6fe log cubeb speaker enumeration results in MediaEngineWebRTC r=padenot
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/7fff2667bfda remove unused DeviceInfoFromId() r=padenot https://hg.mozilla.org/integration/autoland/rev/68b050b9eaf9 remove unused DeviceInfoFromName() overload r=padenot https://hg.mozilla.org/integration/autoland/rev/ee7a45e58a88 use RefCountable for AudioDeviceInfo sets r=padenot https://hg.mozilla.org/integration/autoland/rev/3d3a2932b5bc move Mutex acquisition from caller to EnumerateAudioDevices() r=padenot https://hg.mozilla.org/integration/autoland/rev/72c0e803874a narrow Mutex acquisition in EnumerateAudioDevices() r=padenot
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]
No longer regressed by: 1732409, 1493982
Has Regression Range: --- → yes
No longer blocks: 1650054
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: