1256079 - Intermittent test_getUserMedia_loadedmetadata.html | Test timed out

Reporter

Description

•

8 years ago

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...

Maire Reavy [:mreavy]

Updated

•

8 years ago

Rank: 35

Priority: -- → P3

Comment hidden (Intermittent Failures Robot)

21 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 21

Platform breakdown:
* linux64: 21

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-23&endday=2016-09-23&tree=all

Randell Jesup [:jesup] (needinfo me)

Comment 2

•

8 years ago

achronop: Aryx noted that since bug 1286041, this bug has re-appeared and spiked (21 failures in a day).

Flags: needinfo?(achronop)

Comment hidden (Intermittent Failures Robot)

34 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 33
* try: 1

Platform breakdown:
* linux64: 34

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-19&endday=2016-09-25&tree=all

Comment hidden (Intermittent Failures Robot)

28 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 12
* try: 7
* autoland: 4
* fx-team: 3
* mozilla-central: 2

Platform breakdown:
* linux64: 28

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-26&endday=2016-09-26&tree=all

Andreas Pehrson [:pehrsons]

Comment 5

•

8 years ago

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.

Andreas Pehrson [:pehrsons]

Comment 6

•

8 years ago

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.

Alex Chronopoulos [:achronop]

Assignee

Comment 7

•

8 years ago

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 hidden (mozreview-request)

This will cover potential bugs where the direct track listener was added before
the track.

Worth noting also that we could end up in a limbo state if we add the listener
to a track that doesn't exist anymore (it ended!).

Review commit: https://reviewboard.mozilla.org/r/81450/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/81450/

Randell Jesup [:jesup] (needinfo me)

Comment 9

•

8 years ago

mozreview-review

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+

Ryan VanderMeulen [:RyanVM]

Reporter

Updated

•

8 years ago

status-firefox48: affected → wontfix

status-firefox49: --- → wontfix

status-firefox50: --- → ?

status-firefox51: --- → ?

status-firefox52: --- → affected

Comment hidden (Intermittent Failures Robot)

136 automation job failures were associated with this bug yesterday.

Repository breakdown:
* autoland: 72
* mozilla-inbound: 48
* fx-team: 10
* mozilla-central: 4
* try: 2

Platform breakdown:
* linux64: 136

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-27&endday=2016-09-27&tree=all

Andreas Pehrson [:pehrsons]

Comment 11

•

8 years ago

(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.

Andreas Pehrson [:pehrsons]

Updated

•

8 years ago

Attachment #8795390 - Attachment is obsolete: true

Andreas Pehrson [:pehrsons]

Updated

•

8 years ago

Comment 13

•

8 years ago

mozreview-review

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+

Comment hidden (mozreview-request)

Comment on attachment 8795671 [details]
Bug 1256079 - Append video element to the document.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/81640/diff/1-2/

Pulsebot

Comment 15

•

8 years ago

Pushed by achronop@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/caa8c095cf3f
Append video element to the document. r=pehrsons

Comment hidden (Intermittent Failures Robot)

120 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 81
* autoland: 21
* fx-team: 11
* mozilla-central: 4
* try: 3

Platform breakdown:
* linux64: 120

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-28&endday=2016-09-28&tree=all

Carsten Book [:Tomcat]

Comment 17

•

8 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/caa8c095cf3f

Status: NEW → RESOLVED

Closed: 8 years ago

status-firefox52: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla52

Andreas Pehrson [:pehrsons]

Updated

•

8 years ago

Assignee: nobody → achronop

status-firefox50: ? → affected

status-firefox51: ? → affected

Andreas Pehrson [:pehrsons]

Comment 18

•

8 years ago

Carsten, can you uplift this since it's test-only? No code changes in this test since 46.

Flags: needinfo?(cbook)

Carsten Book [:Tomcat]

Comment 19

•

8 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/869fcf93ccfe

status-firefox51: affected → fixed

Carsten Book [:Tomcat]

Comment 20

•

8 years ago

uplifted to aurora, andreas you want this also on other branches or ?

Flags: needinfo?(cbook)

Andreas Pehrson [:pehrsons]

Comment 21

•

8 years ago

Thanks! Beta is also eligible so if you could put it there as well that'd be great.

Flags: needinfo?(cbook)

Ryan VanderMeulen [:RyanVM]

Reporter

Updated

•

8 years ago

Flags: needinfo?(cbook)

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 22

•

8 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/95f2e9988c6b

status-firefox50: affected → fixed

Flags: in-testsuite+

Comment hidden (Intermittent Failures Robot)

44 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 34
* try: 6
* fx-team: 4

Platform breakdown:
* linux64: 44

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-29&endday=2016-09-29&tree=all

Comment hidden (Intermittent Failures Robot)

368 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 194
* autoland: 100
* try: 35
* fx-team: 29
* mozilla-central: 10

Platform breakdown:
* linux64: 368

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256079&startday=2016-09-26&endday=2016-10-02&tree=all

Bug 1256079 - Allow direct track listeners for tracks that don't exist yet. 8 years ago Andreas Pehrson [:pehrsons] 58 bytes, text/x-review-board-request	jesup : review+	Details
Bug 1256079 - Append video element to the document. 8 years ago Alex Chronopoulos [:achronop] 58 bytes, text/x-review-board-request	pehrsons : review+	Details