Intermittent test_getUserMedia_loadedmetadata.html | Test timed out

RESOLVED FIXED in Firefox 50

Status

()

defect
P3
normal
Rank:
35
RESOLVED FIXED
4 years ago
3 years ago

People

(Reporter: RyanVM, Assigned: achronop)

Tracking

({crash, intermittent-failure})

Trunk
mozilla52
Unspecified
macOS
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox48 wontfix, firefox49 wontfix, firefox50 fixed, firefox51 fixed, firefox52 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

https://treeherder.mozilla.org/logviewer.html#?job_id=3465623&repo=mozilla-central

11:09:25     INFO -  1889 INFO TEST-START | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html
11:09:25     INFO -  TEST DEVICES: No test devices found (in media.{audio,video}_loopback_dev, using fake streams.
11:14:40     INFO -  TEST-INFO | started process screencapture
11:14:40     INFO -  TEST-INFO | screencapture: exit 0
11:14:40     INFO -  1890 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | A valid string reason is expected
11:14:40     INFO -  1891 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Reason cannot be empty
11:14:40     INFO -  1892 INFO Call getUserMedia for {"video":true,"audio":true}
11:14:40     INFO -  1893 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Test timed out.
11:14:40     INFO -      reportError@SimpleTest/TestRunner.js:114:7
11:14:40     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:134:7
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:155:5
11:14:40     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:366:5
11:14:40     INFO -      RunSet.runtests@SimpleTest/setup.js:186:3
11:14:40     INFO -      RunSet.runall@SimpleTest/setup.js:165:5
11:14:40     INFO -      hookupTests@SimpleTest/setup.js:258:5
11:14:40     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
11:14:40     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
11:14:40     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
11:14:40     INFO -      hookup@SimpleTest/setup.js:238:5
11:14:40     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2Fhw%2F_ylr8d0j0wd8qb404l04fbrh00000w%2FT:11:1
11:14:41     INFO -  MEMORY STAT | vsize 3268MB | residentFast 263MB | heapAllocated 59MB
11:14:41     INFO -  1894 INFO TEST-OK | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | took 315442ms

etc...
Rank: 35
Priority: -- → P3
achronop: Aryx noted that since bug 1286041, this bug has re-appeared and spiked (21 failures in a day).
Flags: needinfo?(achronop)
Here's a huge log showing the error: https://public-artifacts.taskcluster.net/MDn0xGOqTfad6KgDXQMADg/0/public/logs/live_backing.log

The interesting bits:
> [task 2016-09-27T13:26:42.159462Z] 13:26:42     INFO -  2006 INFO TEST-START | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html
> [task 2016-09-27T13:26:42.317593Z] 13:26:42     INFO -  TEST DEVICES: Using media devices:
> [task 2016-09-27T13:26:42.317803Z] 13:26:42     INFO -  audio: Sine source at 440 Hz
> [task 2016-09-27T13:26:42.317992Z] 13:26:42     INFO -  video: Dummy video device (0x0000)
> [task 2016-09-27T13:26:42.706360Z] 13:26:42     INFO -  [Main Thread]: D/MediaManager Can't stop gUM track 1 (video), exists=1, stopped=1
> [task 2016-09-27T13:26:42.706460Z] 13:26:42     INFO -  [Main Thread]: D/MediaManager Can't stop gUM track 2 (audio), exists=1, stopped=1
> [task 2016-09-27T13:26:42.710304Z] 13:26:42     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 SuspendOrResumeElement(pause=0, suspendEvents=0) hidden=0
> [task 2016-09-27T13:26:42.835535Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Audio config: aec: 1, agc: -1, noise: 1, delay: 50
> [task 2016-09-27T13:26:42.835640Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager AllocChannel: sampling rate 32000
> [task 2016-09-27T13:26:42.837442Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Audio device 0 allocated
> [task 2016-09-27T13:26:42.837592Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager virtual nsresult mozilla::MediaEngineRemoteVideoSource::Allocate(const mozilla::dom::MediaTrackConstraints&, const mozilla::MediaEnginePrefs&, const nsString&, const nsACString_internal&, mozilla::MediaEngineSource::AllocationHandle**, const char**)
> [task 2016-09-27T13:26:42.838091Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager ChooseCapability: prefs: 640x480 @30-10fps
> [task 2016-09-27T13:26:42.838188Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Constraints: width: { min: -2147483647, max: 2147483647 }
> [task 2016-09-27T13:26:42.838286Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager              height: { min: -2147483647, max: 2147483647 }
> [task 2016-09-27T13:26:42.839022Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager              frameRate: { min: -inf, max: inf, ideal: 30.000000 }
> [task 2016-09-27T13:26:42.841164Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Capability:  320 x  240 x 30 maxFps, YUY2, Unknown codec. Distance = 0
> [task 2016-09-27T13:26:42.841493Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Chosen capability:  320 x  240 x 30 maxFps, YUY2, Unknown codec. Distance = 0
> [task 2016-09-27T13:26:42.842387Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Video device 4097 allocated for http://mochi.test:8888
> [task 2016-09-27T13:26:42.843043Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Start audio for stream 7f9d3636edc0
> [task 2016-09-27T13:26:42.843743Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager virtual nsresult mozilla::MediaEngineRemoteVideoSource::Start(mozilla::SourceMediaStream*, mozilla::TrackID, const PrincipalHandle&)
> [task 2016-09-27T13:26:42.844603Z] 13:26:42     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager started all sources
> [task 2016-09-27T13:26:42.854815Z] 13:26:42     INFO -  [Cameras IPC]: D/MediaManager MediaEngineRemoteVideoSource Video FrameSizeChange: 320x240
> [task 2016-09-27T13:26:43.708115Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph interval[932133; 936711] state[937856; 941568] (frames: 3629) (durationMS: 82) (duration ticks: 3712)
> [task 2016-09-27T13:26:43.708780Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3001fc00 is blocked due to being finished
> [task 2016-09-27T13:26:43.708895Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3636f180 is blocked due to being finished
> [task 2016-09-27T13:26:43.708977Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b0d8080 is blocked due to being finished
> [task 2016-09-27T13:26:43.709092Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b48fb60 is blocked due to being finished
> [task 2016-09-27T13:26:43.711519Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3258b6e0 is blocked due to being finished
> [task 2016-09-27T13:26:43.711885Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b492080 is blocked due to being finished
> [task 2016-09-27T13:26:43.712273Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3001fc00 bufferStartTime=18.776236 blockedTime=0.084172
> [task 2016-09-27T13:26:43.714355Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3636f180 bufferStartTime=20.830748 blockedTime=0.084172
> [task 2016-09-27T13:26:43.715076Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b0d8080 bufferStartTime=18.776236 blockedTime=0.084172
> [task 2016-09-27T13:26:43.715791Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b48fb60 bufferStartTime=18.776236 blockedTime=0.084172
> [task 2016-09-27T13:26:43.719002Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3258b6e0 bufferStartTime=20.651247 blockedTime=0.084172
> [task 2016-09-27T13:26:43.719791Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b492080 bufferStartTime=20.651247 blockedTime=0.084172
> [task 2016-09-27T13:26:43.720666Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph interval[936711; 940596] state[941568; 949760] (frames: 8184) (durationMS: 185) (duration ticks: 8192)
> [task 2016-09-27T13:26:43.721474Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph CloseInput: output present (AudioCallback)
> [task 2016-09-27T13:26:43.722212Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph AudioCallbackDriver ctor for graph 7f9d325b9500
> [task 2016-09-27T13:26:43.723082Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3b492080 from graph 7f9d325b9500, count 5
> [task 2016-09-27T13:26:43.723798Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3258b6e0 from graph 7f9d325b9500, count 4
> [task 2016-09-27T13:26:43.724558Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3636f180 from graph 7f9d325b9500, count 3
> [task 2016-09-27T13:26:43.726206Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3b48fb60 from graph 7f9d325b9500, count 2
> [task 2016-09-27T13:26:43.728481Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3b0d8080 from graph 7f9d325b9500, count 1
> [task 2016-09-27T13:26:43.729239Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3001fc00 from graph 7f9d325b9500, count 0
> [task 2016-09-27T13:26:43.729967Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding media stream 7f9d3636edc0 to graph 7f9d325b9500, count 1
> [task 2016-09-27T13:26:43.731082Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding media stream 7f9d3258f280 to graph 7f9d325b9500, count 2
> [task 2016-09-27T13:26:43.732972Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding MediaInputPort 7f9d30162380 (from 7f9d3636edc0 to 7f9d3258f280) to the graph
> [task 2016-09-27T13:26:43.733812Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding media stream 7f9d3b490d60 to graph 7f9d325b9500, count 3
> [task 2016-09-27T13:26:43.734602Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding MediaInputPort 7f9d301ad1c0 (from 7f9d3258f280 to 7f9d3b490d60) to the graph
> [task 2016-09-27T13:26:43.736432Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph AudioCallbackDriver ctor for graph 7f9d325b9500
> [task 2016-09-27T13:26:43.737240Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph OpenAudioInput: starting new AudioCallbackDriver(input) 7f9d3e358000
> [task 2016-09-27T13:26:43.738010Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph Calling NotifyPull aStream=7f9d3636edc0 t=0.185760 current end=0.000000
> [task 2016-09-27T13:26:43.740415Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph SourceMediaStream 7f9d3636edc0 creating track 1, start 0, initial end 8192
> [task 2016-09-27T13:26:43.745175Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph SourceMediaStream 7f9d3636edc0 creating track 2, start 0, initial end 0
> [task 2016-09-27T13:26:43.746308Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3636edc0 bufferStartTime=21.536508 blockedTime=0.185760
> [task 2016-09-27T13:26:43.747281Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3258f280 bufferStartTime=21.350748 blockedTime=0.000000
> [task 2016-09-27T13:26:43.749221Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b490d60 bufferStartTime=21.350748 blockedTime=0.000000
> [task 2016-09-27T13:26:43.749898Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Switching to system driver.
> [task 2016-09-27T13:26:43.751709Z] 13:26:43     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Setting previous driver: 7f9d30e95000 (AudioCallbackDriver)
> [task 2016-09-27T13:26:43.779691Z] 13:26:43     INFO -  [Main Thread]: D/MediaManager Returning success for getUserMedia()
> [task 2016-09-27T13:26:43.780585Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 Network state changed to NO_SOURCE
> [task 2016-09-27T13:26:43.781382Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 ChangeDelayLoadStatus(1) doc=0x0
> [task 2016-09-27T13:26:43.782191Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 Network state changed to LOADING
> [task 2016-09-27T13:26:43.822105Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement MediaElement 7f9d16a53000 MediaStream tracks available
> [task 2016-09-27T13:26:43.823256Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 SuspendOrResumeElement(pause=0, suspendEvents=0) hidden=0
> [task 2016-09-27T13:26:43.824131Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 Network state changed to IDLE
> [task 2016-09-27T13:26:43.824205Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement 7f9d16a53000 ChangeDelayLoadStatus(0) doc=0x7f9d36f10000
> [task 2016-09-27T13:26:43.824724Z] 13:26:43     INFO -  [Main Thread]: D/nsMediaElement MediaElement 7f9d16a53000 UpdateReadyStateInternal() Stream waiting for video
> [task 2016-09-27T13:26:48.038509Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager virtual nsresult mozilla::MediaEngineRemoteVideoSource::Stop(mozilla::SourceMediaStream*, mozilla::TrackID)
> [task 2016-09-27T13:26:48.039341Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager virtual nsresult mozilla::MediaEngineRemoteVideoSource::Deallocate(mozilla::MediaEngineSource::AllocationHandle*)
> [task 2016-09-27T13:26:48.068203Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Video device 4097 deallocated
> [task 2016-09-27T13:26:48.069063Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258bec0]: D/MediaManager Audio device 0 deallocated
> [task 2016-09-27T13:26:48.272822Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph AudioCallbackDriver State: 2
> [task 2016-09-27T13:26:48.273681Z] 13:26:48     INFO -  [CubebOperation #24]: D/MediaStreamGraph AudioCallbackDriver State: 1
> [task 2016-09-27T13:26:48.274315Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph interval[940596; 947927] state[949760; 951168] (frames: 1360) (durationMS: 30) (duration ticks: 1408)
> [task 2016-09-27T13:26:48.274407Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph Calling NotifyPull aStream=7f9d3636edc0 t=0.031927 current end=0.000000
> [task 2016-09-27T13:26:48.275292Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph MediaStream 7f9d3636edc0 will finish
> [task 2016-09-27T13:26:48.275894Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3636edc0 is finished, but not blocked yet (end at 199457891.660023, with blocking at 21.722268)
> [task 2016-09-27T13:26:48.278087Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3636edc0 bufferStartTime=21.536508 blockedTime=0.000000
> [task 2016-09-27T13:26:48.279589Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3258f280 bufferStartTime=21.350748 blockedTime=0.000000
> [task 2016-09-27T13:26:48.281068Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph MediaStream 7f9d3b490d60 bufferStartTime=21.350748 blockedTime=0.000000
> [task 2016-09-27T13:26:48.282448Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph MediaStream 7f9d3636edc0 track 1, principalHandle changed in VideoChunk with duration 8192
> [task 2016-09-27T13:26:48.284478Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph MediaStream 7f9d3258f280 track 1, principalHandle changed in VideoChunk with duration 1408
> [task 2016-09-27T13:26:48.286374Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph MediaStream 7f9d3b490d60 track 1, principalHandle changed in VideoChunk with duration 1408
> [task 2016-09-27T13:26:48.287958Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: V/MediaStreamGraph interval[947927; 950519] state[951168; 959360] (frames: 8184) (durationMS: 185) (duration ticks: 8192)
> [task 2016-09-27T13:26:48.289280Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Adding direct track listener 7f9d3daf0eb0 bound to track 1 to source stream 7f9d3636edc0
> [task 2016-09-27T13:26:48.290747Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: W/MediaStreamGraph Couldn't find source track for direct track listener 7f9d3daf0eb0
> [task 2016-09-27T13:26:48.291995Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3b490d60 from graph 7f9d325b9500, count 2
> [task 2016-09-27T13:26:48.293536Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3258f280 from graph 7f9d325b9500, count 1
> [task 2016-09-27T13:26:48.295188Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph Removed media stream 7f9d3636edc0 from graph 7f9d325b9500, count 0
> [task 2016-09-27T13:26:48.296740Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph CloseInput: no output present (SystemClockCallback)
> [task 2016-09-27T13:26:48.298063Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph MediaStreamGraph 7f9d325b9500 waiting for main thread cleanup
> [task 2016-09-27T13:26:48.299644Z] 13:26:48     INFO -  [CubebOperation #24]: D/MediaStreamGraph AudioCallbackDriver State: 0
> [task 2016-09-27T13:26:48.300886Z] 13:26:48     INFO -  [CubebOperation #24]: D/MediaStreamGraph AudioCallbackDriver started.
> [task 2016-09-27T13:26:48.302177Z] 13:26:48     INFO -  [Main Thread]: D/MediaManager Listener removed by DOM Destroy(), mFinished = 0
> [task 2016-09-27T13:26:48.303667Z] 13:26:48     INFO -  [Main Thread]: D/MediaManager Sent recording-window-ended for window 116 (outer 12)
> [task 2016-09-27T13:26:48.703183Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: D/MediaStreamGraph AudioCallbackDriver State: 2
> [task 2016-09-27T13:26:48.705066Z] 13:26:48     INFO -  [CubebOperation #24]: D/MediaStreamGraph AudioCallbackDriver State: 1
> [task 2016-09-27T13:26:48.706934Z] 13:26:48     INFO -  [Main Thread]: D/MediaStreamGraph MediaStreamGraph 7f9d325b9500 destroyed
> [task 2016-09-27T13:31:48.284788Z] 13:31:48     INFO -  TEST-INFO | started process screentopng
> [task 2016-09-27T13:31:48.728325Z] 13:31:48     INFO -  TEST-INFO | screentopng: exit 0
> [task 2016-09-27T13:31:48.729197Z] 13:31:48     INFO -  2007 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | A valid string reason is expected
> [task 2016-09-27T13:31:48.729772Z] 13:31:48     INFO -  2008 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Reason cannot be empty
> [task 2016-09-27T13:31:48.730332Z] 13:31:48     INFO -  2009 INFO Call getUserMedia for {"video":true,"audio":true}
> [task 2016-09-27T13:31:48.730892Z] 13:31:48     INFO -  2010 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | One audio track shall be present
> [task 2016-09-27T13:31:48.731439Z] 13:31:48     INFO -  2011 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Track kind should be audio
> [task 2016-09-27T13:31:48.731969Z] 13:31:48     INFO -  2012 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Track id should be defined
> [task 2016-09-27T13:31:48.732601Z] 13:31:48     INFO -  2013 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | One video track shall be present
> [task 2016-09-27T13:31:48.733135Z] 13:31:48     INFO -  2014 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Track kind should be video
> [task 2016-09-27T13:31:48.733709Z] 13:31:48     INFO -  2015 INFO TEST-PASS | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Track id should be defined
> [task 2016-09-27T13:31:48.733813Z] 13:31:48     INFO -  2016 INFO TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_loadedmetadata.html | Test timed out.

Some of it is probably from old tests so it's a bit hard to read, but this is very interesting:
> [task 2016-09-27T13:26:48.290747Z] 13:26:48     INFO -  [Unnamed thread 0x7f9d3258e080]: W/MediaStreamGraph Couldn't find source track for direct track listener 7f9d3daf0eb0

I think that could be the MediaStreamSizeListener from HTMLMediaElement. Since it's never installed (and we never assert that it is, just ignore!) we wait forever for that first frame that can make the media element go to HAVE_METADATA.

I'm not 100% convinced since gUM should for tracks to become available before notifying content - i.e., the test which then sets up the media element. I still think this is a hole big enough to fix, especially now that VideoStreamSinks rely on direct track listeners.
Ok, the stream 7f9d3636edc0 gave it away here. It's the stream we're getting from gUM according to the log, and it's the stream we're finishing later on (together with stopping the MediaStreamTracks).

I think we're being GCed.
This is a new try push without MSG log activated: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ffe8095f8150

Also this is a 2nd try push without logs but does a document.body.appendChild(v) in mochitest: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a8d6010fd0e4
Flags: needinfo?(achronop)
Comment on attachment 8795390 [details]
Bug 1256079 - Allow direct track listeners for tracks that don't exist yet.

https://reviewboard.mozilla.org/r/81450/#review80054
Attachment #8795390 - Flags: review?(rjesup) → review+
(In reply to Randell Jesup [:jesup] from comment #9)
> Comment on attachment 8795390 [details]
> Bug 1256079 - Allow direct track listeners for tracks that don't exist yet.
> 
> https://reviewboard.mozilla.org/r/81450/#review80054

I've been thinking more about this and I don't think this is the right way now.

This will only help when a direct track listener is added directly to a SourceMediaStream - TrackUnionStreams already wait for the track to become available before forwarding to the right input. This the only time the installation of the listener can fail because the track was not found at the source is when the track existed but has ended.

I'll file another bug to try to land a default implementation to the installation callback which asserts that it was successful.
Comment on attachment 8795671 [details]
Bug 1256079 - Append video element to the document.

https://reviewboard.mozilla.org/r/81640/#review80240
Attachment #8795671 - Flags: review?(pehrson) → review+
Pushed by achronop@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/caa8c095cf3f
Append video element to the document. r=pehrsons
https://hg.mozilla.org/mozilla-central/rev/caa8c095cf3f
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
Carsten, can you uplift this since it's test-only? No code changes in this test since 46.
Flags: needinfo?(cbook)
uplifted to aurora, andreas you want this also on other branches or ?
Flags: needinfo?(cbook)
Thanks! Beta is also eligible so if you could put it there as well that'd be great.
Flags: needinfo?(cbook)
Flags: needinfo?(cbook)
You need to log in before you can comment on or make changes to this bug.