Media: Report HTMLMediaElement player errors to devtools console

Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout
test expectations. Bug 601086 tracks improving the quality of
some of the new messages.

BUG=472253, 600810, 600849, 601086

[wolenetz, 2016-04-04 23:08:08]

wolenetz@chromium.org changed reviewers:
+ pfeldman@chromium.org, philipj@opera.com

[wolenetz, 2016-04-04 23:08:08]

Please take a look. Getting at least some exposure to devtools console of reason
for HTMLMediaElement error has been a top ask from web authors. It has come up
repeatedly, and was asked about multiple times at FOMS/Demuxed 2015.

An example error log is (for example, from an MSE AppendBuffer of webm to
SourceBuffer that was created using mp4 mime-type):

PIPELINE_ERROR chunk demuxer: append failed, MEDIA_ERROR_LOG_ENTRY
{"error":"Append: stream parsing failed. Data size=18258 append_window_start=0
append_window_end=inf"}
(with devtools console showing this with the red X in a circle, and with
context: simplemse_player.html:1

A couple questions:
1) the line number in simplemse_player.html example, above, doesn't correspond
to the actual line number at which the append was invoked. How can this be
corrected?
2) Is JSMessageSource the right option for all player error messages, including
ones that might come from decoder pipeline or from regular src= playbacks? If
not, is OtherMessageSource more appropriate?

Note, this depends on first landing https://codereview.chromium.org/1850733003/

philipj@: All from HTMLMediaElement perspective
pfeldman@: All from devtools perspective. Note that transitions into non-null
m_error state gate the emission of these errors, and we only emit the most
recently gathered PIPELINE_ERROR and MEDIA_ERROR_LOG_ENTRY (if any), to limit
potential devtools spam. There's more detail available in
chrome://media-internals for the player.

[wolenetz, 2016-04-05 00:24:30]

The CQ bit was checked by wolenetz@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-04-05 00:25:09]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1858073002/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1858073002/1

[commit-bot: I haz the power, 2016-04-05 01:53:08]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-04-05 01:53:10]

Dry run: Try jobs failed on following builders:
  linux_chromium_rel_ng on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[philipj_slow, 2016-04-05 11:19:48]

lgtm

[wolenetz, 2016-04-05 18:24:55]

Thanks for review, Philip.

pfeldman@, friendly ping :) Please also see my previous questions.

Note that I'm currently rebasing some of the affected layout test expectations,
since there are now some newly emitted console messages that need to be part of
the expectations (hence the current bot failures.)

[wolenetz, 2016-04-05 23:15:40]

Description was changed from

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

BUG=472253
==========

to

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered during updating layout test expectations.

BUG=472253, 600810, 600849
==========

[wolenetz, 2016-04-05 23:15:59]

Description was changed from

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered during updating layout test expectations.

BUG=472253, 600810, 600849
==========

to

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout test expectations.

BUG=472253, 600810, 600849
==========

[wolenetz, 2016-04-05 23:17:07]

Patch set 2 should go better on the bots.
philipj@, please review the layout expectation changes since PS1.
pfeldman@: please review in the context of my original questions, above.

[wolenetz, 2016-04-05 23:17:17]

The CQ bit was checked by wolenetz@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-04-05 23:17:44]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1858073002/20001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1858073002/20001

[commit-bot: I haz the power, 2016-04-06 00:33:04]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-04-06 00:33:05]

Dry run: Try jobs failed on following builders:
  linux_blink_oilpan_rel on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_blink_oil...)

[philipj_slow, 2016-04-06 09:05:38]

LGTM, but better understanding the details of
https://bugs.chromium.org/p/chromium/issues/detail?id=600849 would be nice.

https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
File third_party/WebKit/LayoutTests/media/media-reparent.html (right):

https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
third_party/WebKit/LayoutTests/media/media-reparent.html:20: // flakily missing
console error log. If flakes recur, we may needxi
s/needxi/need/

[philipj_slow, 2016-04-06 09:13:29]

Also, some of the messages are very cryptic. Any change of making them
consistently formatted and without internal numeric codes?

[wolenetz, 2016-04-06 17:25:08]

On 2016/04/06 09:13:29, philipj wrote:
> Also, some of the messages are very cryptic. Any change of making them
> consistently formatted and without internal numeric codes?

I think there will be a bit of a longer tail to improving some of these internal
messages - some of them may come from ffmpeg or other obscure portions of the
pipeline.
However, there's certainly room for improvement. I've filed
https://crbug.com/601086 to track that clean-up.

[wolenetz, 2016-04-06 17:29:04]

Description was changed from

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout test expectations.

BUG=472253, 600810, 600849
==========

to

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout
test expectations. Bug 601086 tracks improving the quality of
some of the new messages.

BUG=472253, 600810, 600849
==========

[wolenetz, 2016-04-06 17:29:19]

Description was changed from

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout
test expectations. Bug 601086 tracks improving the quality of
some of the new messages.

BUG=472253, 600810, 600849
==========

to

==========
Media: Report HTMLMediaElement player errors to devtools console

Upon transition into non-null |m_error| state, also logs any known
player error to the devtools console.

Includes updated layout test expectations including the new logs.

Bugs 600810 and 600849 discovered while updating layout
test expectations. Bug 601086 tracks improving the quality of
some of the new messages.

BUG=472253, 600810, 600849, 601086
==========

[wolenetz, 2016-04-06 20:16:04]

There's still some discrepancy on the bots vs my local build for 2 or 3 of the
layout tests. I'll be using some temporary extra logging in upcoming patch sets
to see what the bots are actually logging versus what my local build logs.

I've also noted some follow-up work to help reduce this fragility later at
https://bugs.chromium.org/p/chromium/issues/detail?id=599620#c1

https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
File third_party/WebKit/LayoutTests/media/media-reparent.html (right):

https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
third_party/WebKit/LayoutTests/media/media-reparent.html:20: // flakily missing
console error log. If flakes recur, we may needxi
On 2016/04/06 09:05:37, philipj wrote:
> s/needxi/need/

Done :)

[pfeldman, 2016-04-06 21:45:41]

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Layo...
File
third_party/WebKit/LayoutTests/compositing/video/video-controls-layer-creation-expected.txt
(right):

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Layo...
third_party/WebKit/LayoutTests/compositing/video/video-controls-layer-creation-expected.txt:1:
CONSOLE ERROR: MEDIA_ERROR_LOG_ENTRY {"error":"Failed loading buffered resource.
Error code=-6"}
Here and below: which resource? In which line of HTML or JavaScript was I trying
to load it?

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Sour...
File third_party/WebKit/Source/core/html/HTMLMediaElement.cpp (right):

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Sour...
third_party/WebKit/Source/core/html/HTMLMediaElement.cpp:1330:
document().addConsoleMessage(ConsoleMessage::create(JSMessageSource,
ErrorMessageLevel, message));
Looks more like OtherMessageSource to me.

[pfeldman, 2016-04-06 21:49:54]

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Sour...
File third_party/WebKit/Source/core/html/HTMLMediaElement.h (right):

https://codereview.chromium.org/1858073002/diff/60001/third_party/WebKit/Sour...
third_party/WebKit/Source/core/html/HTMLMediaElement.h:378: void
reportPlayerErrorToDevToolsConsole();
"ToDevToolsConsole" can be trimmed - what it does is adding it into the
"console". "reportPlayerError" would suffice.

But you obviously need more information about the resource (url). Then we can
try glue-ing the asynchronous stack to your error message.

[wolenetz, 2016-04-08 20:31:14]

The CQ bit was checked by wolenetz@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-04-08 20:31:44]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1858073002/80001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1858073002/80001

[wolenetz, 2016-04-08 20:38:22]

On 2016/04/06 20:16:04, wolenetz wrote:
> There's still some discrepancy on the bots vs my local build for 2 or 3 of the
> layout tests. I'll be using some temporary extra logging in upcoming patch
sets
> to see what the bots are actually logging versus what my local build logs.
> 
> I've also noted some follow-up work to help reduce this fragility later at
> https://bugs.chromium.org/p/chromium/issues/detail?id=599620#c1
> 
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> File third_party/WebKit/LayoutTests/media/media-reparent.html (right):
> 
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> third_party/WebKit/LayoutTests/media/media-reparent.html:20: // flakily
missing
> console error log. If flakes recur, we may needxi
> On 2016/04/06 09:05:37, philipj wrote:
> > s/needxi/need/
> 
> Done :)

Hmm. I'd already begun thinking that some of these layout test failures are
spurious flakes due to timing. fast/js/custom-constructors.html is one that's
showing such flakiness.
(Timing isn't the only variable that can cause flakiness, but it looks like it's
one that's impacting this CL already.)
A  solution that I might need to land as part of this is to update
testRunner/etc to support conditional inclusion of these new log messages.
Alternatively, I'd need to adjust the timing in various tests and test
maintainers will have extra overhead of making sure they include the appropriate
log messages and avoid timing flakes.
philipj@: WDYT about these two options?

pfedman@: thanks for your CR comments. Once I get the basics flake-free, then
I'll look into addressing your comments and associating more context with the
log messages.

[commit-bot: I haz the power, 2016-04-08 21:52:36]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-04-08 21:52:37]

Dry run: Try jobs failed on following builders:
  win_chromium_rel_ng on tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_rel_...)

[philipj_slow, 2016-04-11 09:43:52]

On 2016/04/08 20:38:22, wolenetz wrote:
> On 2016/04/06 20:16:04, wolenetz wrote:
> > There's still some discrepancy on the bots vs my local build for 2 or 3 of
the
> > layout tests. I'll be using some temporary extra logging in upcoming patch
> sets
> > to see what the bots are actually logging versus what my local build logs.
> > 
> > I've also noted some follow-up work to help reduce this fragility later at
> > https://bugs.chromium.org/p/chromium/issues/detail?id=599620#c1
> > 
> >
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> > File third_party/WebKit/LayoutTests/media/media-reparent.html (right):
> > 
> >
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> > third_party/WebKit/LayoutTests/media/media-reparent.html:20: // flakily
> missing
> > console error log. If flakes recur, we may needxi
> > On 2016/04/06 09:05:37, philipj wrote:
> > > s/needxi/need/
> > 
> > Done :)
> 
> Hmm. I'd already begun thinking that some of these layout test failures are
> spurious flakes due to timing. fast/js/custom-constructors.html is one that's
> showing such flakiness.
> (Timing isn't the only variable that can cause flakiness, but it looks like
it's
> one that's impacting this CL already.)
> A  solution that I might need to land as part of this is to update
> testRunner/etc to support conditional inclusion of these new log messages.
> Alternatively, I'd need to adjust the timing in various tests and test
> maintainers will have extra overhead of making sure they include the
appropriate
> log messages and avoid timing flakes.
> philipj@: WDYT about these two options?

I would lean towards making the tests reliable if at all possible. If there are
errors triggered close to the end of the test, then waiting for the error event
ought to make it reliable. Do you think that covers most of the problem, or do
you know of cases where the error isn't triggered reliably at all, so that
prolonging the test doesn't help?

[pfeldman, 2016-07-22 18:13:58]

pfeldman@chromium.org changed reviewers:
- pfeldman@chromium.org

[wolenetz1, 2017-07-07 23:15:26]

On 2016/04/11 09:43:52, philipj_slow wrote:
> On 2016/04/08 20:38:22, wolenetz wrote:
> > On 2016/04/06 20:16:04, wolenetz wrote:
> > > There's still some discrepancy on the bots vs my local build for 2 or 3 of
> the
> > > layout tests. I'll be using some temporary extra logging in upcoming patch
> > sets
> > > to see what the bots are actually logging versus what my local build logs.
> > > 
> > > I've also noted some follow-up work to help reduce this fragility later at
> > > https://bugs.chromium.org/p/chromium/issues/detail?id=599620#c1
> > > 
> > >
> >
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> > > File third_party/WebKit/LayoutTests/media/media-reparent.html (right):
> > > 
> > >
> >
>
https://codereview.chromium.org/1858073002/diff/20001/third_party/WebKit/Layo...
> > > third_party/WebKit/LayoutTests/media/media-reparent.html:20: // flakily
> > missing
> > > console error log. If flakes recur, we may needxi
> > > On 2016/04/06 09:05:37, philipj wrote:
> > > > s/needxi/need/
> > > 
> > > Done :)
> > 
> > Hmm. I'd already begun thinking that some of these layout test failures are
> > spurious flakes due to timing. fast/js/custom-constructors.html is one
that's
> > showing such flakiness.
> > (Timing isn't the only variable that can cause flakiness, but it looks like
> it's
> > one that's impacting this CL already.)
> > A  solution that I might need to land as part of this is to update
> > testRunner/etc to support conditional inclusion of these new log messages.
> > Alternatively, I'd need to adjust the timing in various tests and test
> > maintainers will have extra overhead of making sure they include the
> appropriate
> > log messages and avoid timing flakes.
> > philipj@: WDYT about these two options?
> 
> I would lean towards making the tests reliable if at all possible. If there
are
> errors triggered close to the end of the test, then waiting for the error
event
> ought to make it reliable. Do you think that covers most of the problem, or do
> you know of cases where the error isn't triggered reliably at all, so that
> prolonging the test doesn't help?

I'm not sure of the value of this CL approach now that I've instead standardized
MediaError.message and landed it's implementation in Chrome. The point of the
console logging was to get the error message to developers who are debugging.
MediaError.message should now contain this info (though it's not automatically
logged to the console).

I'm considering abandoning the console logging approach unless y'all see some
value in it beyond MediaError.message.