MSE: Increase log visibility when unfragmented MP4 causes parse failure

MSE: Increase log visibility when unfragmented MP4 causes parse failure

Adds an error log entry to chrome://media-internals when MSE's
MP4 stream parser detects an unfragmented MP4. This error log should
help make it more clear why the parse fails in this unfortunately common
case.

BUG=487410
R=dalecurtis,chcunningham
TEST=Manually verified the log entry occurs for the repro in bug 487410.

Committed: https://crrev.com/4d8bd581421979e7698a419638bff2a354c7e416
Cr-Commit-Position: refs/heads/master@{#330178}

[wolenetz, 2015-05-15 00:45:42]

Please take a look.

Using the repro steps from the bug with the unfragmented mp4,
chrome://media-internals shows the following with PS1 applied:

Timestamp	Property	Value
00:00:00 00	pipeline_state	kCreated
00:00:00 00	EVENT	PIPELINE_CREATED
00:00:00 00	EVENT	WEBMEDIAPLAYER_CREATED
00:00:00
03	url	blob:http%3A//fiddle.jshell.net/31cbd5c4-4c82-4b38-af79-a781d5ec4866
00:00:00 04	pipeline_state	kInitDemuxer
00:00:00 39	debug	Skipping unrecognized top-level box: ftyp
00:00:00 41	info	Video codec: avc1.4d401e
00:00:00 44	info	Audio codec: mp4a.40.2
00:00:00 45	error	Failure parsing MP4: Detected unfragmented MP4. Media Source
Extensions requires ISO BMFF moov to contain mvex to indicate that Movie
Fragments are to be expected.
00:00:00 45	error	Append: stream parsing failed. Data size=131072
append_window_start=0 append_window_end=inf
00:00:00 45	pipeline_error	pipeline: decode error
00:00:00 46	pipeline_state	kStopping
00:00:00 46	pipeline_state	kStopped

[chcunningham, 2015-05-15 17:19:34]

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_defin...
File media/formats/mp4/box_definitions.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_defin...
media/formats/mp4/box_definitions.cc:664: "Detected unfragmented MP4. Media
Source Extensions "
Do we know that all scenarios of returning false for ReadChild are due to
missing mvex? It seems like we might give this error message for other
categories of parsing errors. I looked for a place in Reader where we check
specifically for the mvex, but I did not find one. Is there such a place? Can we
put the error there instead?

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reade...
File media/formats/mp4/box_reader.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reade...
media/formats/mp4/box_reader.cc:226: "BMFF boxes that run to EOS";
I don't know what this means. Why is size 0?

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h
File media/formats/mp4/rcheck.h (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h#...
media/formats/mp4/rcheck.h:14: DLOG(ERROR) << "Failure while parsing MP4: " <<
#condition;   \
Noob c++ question. What is the value of #condition? Does this somehow stringify
the condition, so we get some output like

"Failure while parsing MP4: a() && b() || c()"

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h#...
media/formats/mp4/rcheck.h:21: // RCHECK_MEDIA_LOGGED. See
https://crbug.com/487410.
Do we really want to Elminate? Basically, are you saying that *all* of the
dvlogs that would be emitted here should be replaced with the combined
media_log/dvlog from RCHECK_MEDIA_LOGGED?

[wolenetz, 2015-05-15 18:16:25]

Thanks for the comments, chcunningham.
PS2:

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_defin...
File media/formats/mp4/box_definitions.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_defin...
media/formats/mp4/box_definitions.cc:664: "Detected unfragmented MP4. Media
Source Extensions "
On 2015/05/15 17:19:33, chcunningham wrote:
> Do we know that all scenarios of returning false for ReadChild are due to
> missing mvex? It seems like we might give this error message for other
> categories of parsing errors. I looked for a place in Reader where we check
> specifically for the mvex, but I did not find one. Is there such a place? Can
we
> put the error there instead?

ReadChild() inspects the passed parameter's overridden Box::BoxType() (which is
an mvex
(https://code.google.com/p/chromium/codesearch#chromium/src/media/formats/mp4/...)
in the case of passing &extends here) to find what kind of child it is expected
to find and read. If it fails to find or read that child, it returns false. This
is documented in ReadChild()'s declaration
(https://code.google.com/p/chromium/codesearch#chromium/src/media/formats/mp4/...).

This change doesn't change the behavior that a MVEX is required to be read here.
It just introduces a log if (finding or) reading that box fails.

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reade...
File media/formats/mp4/box_reader.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reade...
media/formats/mp4/box_reader.cc:226: "BMFF boxes that run to EOS";
On 2015/05/15 17:19:33, chcunningham wrote:
> I don't know what this means. Why is size 0? 

:) I was simply log-ifying the previous comment in a drive-by.
I also believe both the previous comment and the log-ified version are correct:
As I understand it from the ISO IEC 14497-12 (2012) spec, section 4.2 (Object
Structure, which describes the pertinent common box header stuff that is parsed
here), there is very specific code in the spec describing that "if (size==0) {
// box extends to end of file }". MSE does not support such boxes in ISO BMFF.
My guess about a use case for something like a box extending to EOS might be an
MDAT containing media data, and whose end is signaled by reaching the end of
media data, rather than the end of the box. This is similar to webm "unknown
cluster lengths" (which *are* supported by MSE due to the nature of block
sequence with Clusters being required to be muxed in DTS sequence, unlike MDAT
in ISO BMFF).

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h
File media/formats/mp4/rcheck.h (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h#...
media/formats/mp4/rcheck.h:14: DLOG(ERROR) << "Failure while parsing MP4: " <<
#condition;   \
On 2015/05/15 17:19:33, chcunningham wrote:
> Noob c++ question. What is the value of #condition? Does this somehow
stringify
> the condition, so we get some output like
> 
> "Failure while parsing MP4: a() && b() || c()"

Yep. Exactly. See https://gcc.gnu.org/onlinedocs/cpp/Stringification.html
For example, see https://code.google.com/p/chromium/issues/detail?id=487410#c5
demonstrating the DLOG behavior prior to this change for a failed RCHECK.
[1:1:0514/131527:ERROR:box_reader.cc(197)] Failure while parsing MP4: itr !=
children_.end()
Also, I don't think stringified code fragments are appropriate for
chrome://media-internals, hence I've added the msg parameter. So we get DLOG
detail still in debug builds, plus a user-readable error message in
chrome://media-internals in all builds.

See also DCHECK that does similar stringification
(https://code.google.com/p/chromium/codesearch#chromium/src/base/logging.h&l=644).

However, I'll remove the unneccessary << since the compiler can concat these
strings statically.

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h#...
media/formats/mp4/rcheck.h:21: // RCHECK_MEDIA_LOGGED. See
https://crbug.com/487410.
On 2015/05/15 17:19:33, chcunningham wrote:
> Do we really want to Elminate? Basically, are you saying that *all* of the
> dvlogs that would be emitted here should be replaced with the combined
> media_log/dvlog from RCHECK_MEDIA_LOGGED? 

Yeah, my wording was too strong. I'll relax it. There are RCHECKs all over the
place, not all of which might have a usable log message. There are other places
(nearer to mp4_stream_parser) where RCHECKs aren't used, but log messages would
be good to add.

[DaleCurtis, 2015-05-15 18:45:38]

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rcheck.h
File media/formats/mp4/rcheck.h (right):

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rchec...
media/formats/mp4/rcheck.h:14: DLOG(ERROR) << "Failure while parsing MP4: "
#condition;      \
<< before # ?

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rchec...
media/formats/mp4/rcheck.h:25: DLOG(ERROR) << "Failure while parsing MP4: "
#condition; \
Ditto

[wolenetz, 2015-05-15 18:49:04]

On 2015/05/15 18:45:38, DaleCurtis wrote:
>
https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rcheck.h
> File media/formats/mp4/rcheck.h (right):
> 
>
https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rchec...
> media/formats/mp4/rcheck.h:14: DLOG(ERROR) << "Failure while parsing MP4: "
> #condition;      \
> << before # ?
> 
>
https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/rchec...
> media/formats/mp4/rcheck.h:25: DLOG(ERROR) << "Failure while parsing MP4: "
> #condition; \
> Ditto

I was following DCHECK's example here,
https://code.google.com/p/chromium/codesearch#chromium/src/base/logging.h&l=644
and removed the unneccessary << since the compiler can concat these
strings statically.
See also my earlier comment reply that included this reasoning:
https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/rcheck.h#...

[DaleCurtis, 2015-05-15 18:58:47]

Ah, lgtm then.

[DaleCurtis, 2015-05-15 18:59:16]

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
File media/formats/mp4/box_definitions.h (right):

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
media/formats/mp4/box_definitions.h:14: #include "media/base/media_log.h"
Is this necessary?

[wolenetz, 2015-05-15 19:02:27]

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
File media/formats/mp4/box_definitions.h (right):

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
media/formats/mp4/box_definitions.h:14: #include "media/base/media_log.h"
On 2015/05/15 18:59:16, DaleCurtis wrote:
> Is this necessary?

Only for style. LogCB was previously used, below, but was not explicitly
included. IIUC, correct style requires explicit inclusion even in cases where
transitive inclusion may occur already.

[chcunningham, 2015-05-15 19:52:18]

On 2015/05/15 19:02:27, wolenetz wrote:
>
https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
> File media/formats/mp4/box_definitions.h (right):
> 
>
https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_d...
> media/formats/mp4/box_definitions.h:14: #include "media/base/media_log.h"
> On 2015/05/15 18:59:16, DaleCurtis wrote:
> > Is this necessary?
> 
> Only for style. LogCB was previously used, below, but was not explicitly
> included. IIUC, correct style requires explicit inclusion even in cases where
> transitive inclusion may occur already.

lgtm

[wolenetz, 2015-05-15 19:52:47]

The CQ bit was checked by wolenetz@chromium.org

[commit-bot: I haz the power, 2015-05-15 19:55:06]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1147453002/20001

[commit-bot: I haz the power, 2015-05-15 20:02:52]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2015-05-15 20:04:57]

Patchset 2 (id:??) landed as
https://crrev.com/4d8bd581421979e7698a419638bff2a354c7e416
Cr-Commit-Position: refs/heads/master@{#330178}