MSE: Increase log visibility when unfragmented MP4 causes parse failure (issue 1147453002 by wolenetz@chromium.org)

[wole...@chromium.org]

Reviewers: chcunningham, DaleCurtis,

Message:
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


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

Please review this at https://codereview.chromium.org/1147453002/

Base URL: https://chromium.googlesource.com/chromium/src.git@master

Affected files (+34, -14 lines):
M media/formats/mp4/box_definitions.h
M media/formats/mp4/box_definitions.cc
M media/formats/mp4/box_reader.h
M media/formats/mp4/box_reader.cc
M media/formats/mp4/rcheck.h


Index: media/formats/mp4/box_definitions.cc
diff --git a/media/formats/mp4/box_definitions.cc
b/media/formats/mp4/box_definitions.cc
index
a08cb26d560ca1b5e99ce066a269017af5d90a9e..93c1dd20266676ab2abdb7db5edd8e777cf34a74
100644
--- a/media/formats/mp4/box_definitions.cc
+++ b/media/formats/mp4/box_definitions.cc
@@ -657,12 +657,15 @@ Movie::~Movie() {}
FourCC Movie::BoxType() const { return FOURCC_MOOV; }

bool Movie::Parse(BoxReader* reader) {
- return reader->ScanChildren() &&
- reader->ReadChild(&header) &&
- reader->ReadChildren(&tracks) &&
- // Media Source specific: 'mvex' required
- reader->ReadChild(&extends) &&
- reader->MaybeReadChildren(&pssh);
+ RCHECK(reader->ScanChildren() && reader->ReadChild(&header) &&
+ reader->ReadChildren(&tracks));
+
+ RCHECK_MEDIA_LOGGED(reader->ReadChild(&extends), reader->log_cb(),
+ "Detected unfragmented MP4. Media Source Extensions "
+ "requires ISO BMFF moov to contain mvex to indicate
that "
+ "Movie Fragments are to be expected.");
+
+ return reader->MaybeReadChildren(&pssh);
}

TrackFragmentDecodeTime::TrackFragmentDecodeTime() : decode_time(0) {}
Index: media/formats/mp4/box_definitions.h
diff --git a/media/formats/mp4/box_definitions.h
b/media/formats/mp4/box_definitions.h
index
127140368985bfc83af94c556df7363a984dfce4..026effe6b5fbd3fe036e63426400c03f288802a5
100644
--- a/media/formats/mp4/box_definitions.h
+++ b/media/formats/mp4/box_definitions.h
@@ -11,6 +11,7 @@
#include "base/basictypes.h"
#include "base/compiler_specific.h"
#include "media/base/media_export.h"
+#include "media/base/media_log.h"
#include "media/formats/mp4/aac.h"
#include "media/formats/mp4/avc.h"
#include "media/formats/mp4/box_reader.h"
Index: media/formats/mp4/box_reader.cc
diff --git a/media/formats/mp4/box_reader.cc
b/media/formats/mp4/box_reader.cc
index
925859d20bda820f31caf76f7949d106cb432f33..978f17d68737a3d27a0cca0d703bc05e75ad4948
100644
--- a/media/formats/mp4/box_reader.cc
+++ b/media/formats/mp4/box_reader.cc
@@ -222,7 +222,8 @@ bool BoxReader::ReadHeader(bool* err) {
CHECK(Read4Into8(&size) && ReadFourCC(&type_));

if (size == 0) {
- // Media Source specific: we do not support boxes that run to EOS.
+ MEDIA_LOG(DEBUG, log_cb_) << "Media Source Extensions do not support
ISO "
+ "BMFF boxes that run to EOS";
*err = true;
return false;
} else if (size == 1) {
Index: media/formats/mp4/box_reader.h
diff --git a/media/formats/mp4/box_reader.h b/media/formats/mp4/box_reader.h
index
3360204ed5424a05d0a552633dfc076e22e2f713..6b59361612459d84e29448c3b19b43595ab98cce
100644
--- a/media/formats/mp4/box_reader.h
+++ b/media/formats/mp4/box_reader.h
@@ -22,7 +22,10 @@ class BoxReader;

struct MEDIA_EXPORT Box {
virtual ~Box();
+
+ // Parse errors may be logged using the BoxReader's log callback.
virtual bool Parse(BoxReader* reader) = 0;
+
virtual FourCC BoxType() const = 0;
};

Index: media/formats/mp4/rcheck.h
diff --git a/media/formats/mp4/rcheck.h b/media/formats/mp4/rcheck.h
index
fb0f8f27d4ec66f965f18609bcbaacd50186c7bf..c1ff7c36e0341dcc2521efd1c1f0f96ec44e1a18
100644
--- a/media/formats/mp4/rcheck.h
+++ b/media/formats/mp4/rcheck.h
@@ -6,13 +6,25 @@
#define MEDIA_FORMATS_MP4_RCHECK_H_

#include "base/logging.h"
+#include "media/base/media_log.h"

-#define RCHECK(x) \
- do { \
- if (!(x)) { \
- DLOG(ERROR) << "Failure while parsing MP4: " << #x; \
- return false; \
- } \
- } while (0)
+#define RCHECK_MEDIA_LOGGED(condition, log_cb, msg) \
+ do { \
+ if (!(condition)) { \
+ DLOG(ERROR) << "Failure while parsing MP4: " << #condition; \
+ MEDIA_LOG(ERROR, log_cb) << "Failure parsing MP4: " << (msg); \
+ return false; \
+ } \
+ } while (0)
+
+// TODO(wolenetz,chcunningham): Eliminate usage of this macro in favor of
+// RCHECK_MEDIA_LOGGED. See https://crbug.com/487410.
+#define RCHECK(condition) \
+ do { \
+ if (!(condition)) { \
+ DLOG(ERROR) << "Failure while parsing MP4: " << #condition; \
+ return false; \
+ } \
+ } while (0)

#endif // MEDIA_FORMATS_MP4_RCHECK_H_

[chcunn...@chromium.org]

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

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_definitions.cc#newcode664
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_reader.cc
File media/formats/mp4/box_reader.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reader.cc#newcode226
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#newcode14
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#newcode21
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?

https://codereview.chromium.org/1147453002/

[wole...@chromium.org]

Thanks for the comments, chcunningham.
PS2:

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

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_definitions.cc#newcode664
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/box_definitions.cc&l=646)
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/box_reader.h&rcl=1431689570&l=116).

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_reader.cc
File media/formats/mp4/box_reader.cc (right):

https://codereview.chromium.org/1147453002/diff/1/media/formats/mp4/box_reader.cc#newcode226
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#newcode14
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#newcode21
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.

https://codereview.chromium.org/1147453002/

[dalec...@chromium.org]

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/rcheck.h#newcode14

media/formats/mp4/rcheck.h:14: DLOG(ERROR) << "Failure while parsing
MP4: " #condition; \

<< before # ?

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

https://codereview.chromium.org/1147453002/

[wole...@chromium.org]

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#newcode14

https://codereview.chromium.org/1147453002/

[dalec...@chromium.org]

Ah, lgtm then.

https://codereview.chromium.org/1147453002/

[dalec...@chromium.org]

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

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

https://codereview.chromium.org/1147453002/

[wole...@chromium.org]

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

https://codereview.chromium.org/1147453002/diff/20001/media/formats/mp4/box_definitions.h#newcode14
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.

https://codereview.chromium.org/1147453002/

[chcunn...@chromium.org]

lgtm

https://codereview.chromium.org/1147453002/

[commi...@chromium.org]

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


https://codereview.chromium.org/1147453002/

[commi...@chromium.org]

Committed patchset #2 (id:20001)

https://codereview.chromium.org/1147453002/

[commi...@chromium.org]

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

https://codereview.chromium.org/1147453002/