Bug 1525646 - Add debug logging to MoofParser. r=jya
authorBryce Van Dyk <bvandyk@mozilla.com>
Tue, 12 Feb 2019 21:59:42 +0000
changeset 458807 081476483f25
parent 458806 bd4a1f69d272
child 458808 cf6f7992935c
push id35548
push useropoprus@mozilla.com
push dateWed, 13 Feb 2019 09:48:26 +0000
treeherdermozilla-central@93e37c529818 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjya
bugs1525646
milestone67.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1525646 - Add debug logging to MoofParser. r=jya The MoofParser didn't have logging on its normal code paths. This patch implements such logging, covering entry and exit to many functions. Such verbose logs are helpful for diagnosing failures and the specific file structure leading to such failures. This should help improve our debugging experience if we can get logs from end users which is particularly useful for cases where they can't provide us with media due to geoblocking/proprietary media issues. Differential Revision: https://phabricator.services.mozilla.com/D19021
dom/media/mp4/MoofParser.cpp
--- a/dom/media/mp4/MoofParser.cpp
+++ b/dom/media/mp4/MoofParser.cpp
@@ -51,29 +51,37 @@ bool MoofParser::RebuildFragmentedIndex(
     *aCanEvict = true;
   } else {
     *aCanEvict = false;
   }
   return RebuildFragmentedIndex(aByteRanges);
 }
 
 bool MoofParser::RebuildFragmentedIndex(BoxContext& aContext) {
+  LOG_DEBUG(
+      Moof,
+      "Starting, mTrackParseMode=%s, track#=%" PRIu32
+      " (ignore if multitrack).",
+      mTrackParseMode.is<ParseAllTracks>() ? "multitrack" : "single track",
+      mTrackParseMode.is<ParseAllTracks>() ? 0
+                                           : mTrackParseMode.as<uint32_t>());
   bool foundValidMoof = false;
 
   for (Box box(&aContext, mOffset); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("moov") && mInitRange.IsEmpty()) {
       mInitRange = MediaByteRange(0, box.Range().mEnd);
       ParseMoov(box);
     } else if (box.IsType("moof")) {
       Moof moof(box, mTrackParseMode, mTrex, mMvhd, mMdhd, mEdts, mSinf,
                 &mLastDecodeTime, mIsAudio);
 
       if (!moof.IsValid() && !box.Next().IsAvailable()) {
         // Moof isn't valid abort search for now.
-        LOG_WARN(Moof, "Could not find valid moof.");
+        LOG_WARN(Moof,
+                 "Could not find valid moof, moof may not be complete yet.");
         break;
       }
 
       if (!mMoofs.IsEmpty()) {
         // Stitch time ranges together in the case of a (hopefully small) time
         // range gap between moofs.
         mMoofs.LastElement().FixRounding(moof);
       }
@@ -93,16 +101,18 @@ bool MoofParser::RebuildFragmentedIndex(
       }
     }
     mOffset = box.NextOffset();
   }
   MOZ_ASSERT(mTrackParseMode.is<ParseAllTracks>() ||
                  mTrex.mTrackId == mTrackParseMode.as<uint32_t>(),
              "If not parsing all tracks, mTrex should have the same track id "
              "as the track being parsed.");
+  LOG_DEBUG(Moof, "Done, foundValidMoof=%s.",
+            foundValidMoof ? "true" : "false");
   return foundValidMoof;
 }
 
 MediaByteRange MoofParser::FirstCompleteMediaHeader() {
   if (Moofs().IsEmpty()) {
     return MediaByteRange();
   }
   return Moofs()[0].mRange;
@@ -138,53 +148,61 @@ class BlockingStream : public ByteStream
 
   virtual bool Length(int64_t* size) override { return mStream->Length(size); }
 
  private:
   RefPtr<ByteStream> mStream;
 };
 
 bool MoofParser::BlockingReadNextMoof() {
+  LOG_DEBUG(Moof, "Starting.");
   int64_t length = std::numeric_limits<int64_t>::max();
   mSource->Length(&length);
   RefPtr<BlockingStream> stream = new BlockingStream(mSource);
   MediaByteRangeSet byteRanges(MediaByteRange(0, length));
 
   BoxContext context(stream, byteRanges);
   for (Box box(&context, mOffset); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("moof")) {
       MediaByteRangeSet parseByteRanges(
           MediaByteRange(mOffset, box.Range().mEnd));
       BoxContext parseContext(stream, parseByteRanges);
       if (RebuildFragmentedIndex(parseContext)) {
+        LOG_DEBUG(Moof, "Succeeded on RebuildFragmentedIndex, returning true.");
         return true;
       }
     }
   }
+  LOG_DEBUG(Moof, "Couldn't read next moof, returning false.");
   return false;
 }
 
 void MoofParser::ScanForMetadata(mozilla::MediaByteRange& aMoov) {
+  LOG_DEBUG(Moof, "Starting.");
   int64_t length = std::numeric_limits<int64_t>::max();
   mSource->Length(&length);
   MediaByteRangeSet byteRanges;
   byteRanges += MediaByteRange(0, length);
   RefPtr<BlockingStream> stream = new BlockingStream(mSource);
 
   BoxContext context(stream, byteRanges);
   for (Box box(&context, mOffset); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("moov")) {
       aMoov = box.Range();
       break;
     }
   }
   mInitRange = aMoov;
+  LOG_DEBUG(Moof,
+            "Done, mInitRange.mStart=%" PRIi64 ", mInitRange.mEnd=%" PRIi64,
+            mInitRange.mStart, mInitRange.mEnd);
 }
 
 already_AddRefed<mozilla::MediaByteBuffer> MoofParser::Metadata() {
+  LOG_DEBUG(Moof, "Starting.");
   MediaByteRange moov;
   ScanForMetadata(moov);
   CheckedInt<MediaByteBuffer::size_type> moovLength = moov.Length();
   if (!moovLength.isValid() || !moovLength.value()) {
     // No moov, or cannot be used as array size.
     LOG_WARN(Moof,
              "Did not get usable moov length while trying to parse Metadata.");
     return nullptr;
@@ -199,99 +217,116 @@ already_AddRefed<mozilla::MediaByteBuffe
   RefPtr<BlockingStream> stream = new BlockingStream(mSource);
   size_t read;
   bool rv = stream->ReadAt(moov.mStart, metadata->Elements(),
                            moovLength.value(), &read);
   if (!rv || read != moovLength.value()) {
     LOG_WARN(Moof, "Failed to read moov while trying to parse Metadata.");
     return nullptr;
   }
+  LOG_DEBUG(Moof, "Done, found metadata.");
   return metadata.forget();
 }
 
 MP4Interval<Microseconds> MoofParser::GetCompositionRange(
     const MediaByteRangeSet& aByteRanges) {
+  LOG_DEBUG(Moof, "Starting.");
   MP4Interval<Microseconds> compositionRange;
   BoxContext context(mSource, aByteRanges);
   for (size_t i = 0; i < mMoofs.Length(); i++) {
     Moof& moof = mMoofs[i];
     Box box(&context, moof.mRange.mStart);
     if (box.IsAvailable()) {
       compositionRange = compositionRange.Extents(moof.mTimeRange);
     }
   }
+  LOG_DEBUG(Moof,
+            "Done, compositionRange.start=%" PRIi64
+            ", compositionRange.end=%" PRIi64 ".",
+            compositionRange.start, compositionRange.end);
   return compositionRange;
 }
 
 bool MoofParser::ReachedEnd() {
   int64_t length;
   return mSource->Length(&length) && mOffset == length;
 }
 
 void MoofParser::ParseMoov(Box& aBox) {
+  LOG_DEBUG(Moof, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("mvhd")) {
       mMvhd = Mvhd(box);
     } else if (box.IsType("trak")) {
       ParseTrak(box);
     } else if (box.IsType("mvex")) {
       ParseMvex(box);
     }
   }
+  LOG_DEBUG(Moof, "Done.");
 }
 
 void MoofParser::ParseTrak(Box& aBox) {
+  LOG_DEBUG(Trak, "Starting.");
   Tkhd tkhd;
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("tkhd")) {
       tkhd = Tkhd(box);
     } else if (box.IsType("mdia")) {
       if (mTrackParseMode.is<ParseAllTracks>() ||
           tkhd.mTrackId == mTrackParseMode.as<uint32_t>()) {
         ParseMdia(box, tkhd);
       }
     } else if (box.IsType("edts") &&
                (mTrackParseMode.is<ParseAllTracks>() ||
                 tkhd.mTrackId == mTrackParseMode.as<uint32_t>())) {
       mEdts = Edts(box);
     }
   }
+  LOG_DEBUG(Trak, "Done.");
 }
 
 void MoofParser::ParseMdia(Box& aBox, Tkhd& aTkhd) {
+  LOG_DEBUG(Mdia, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("mdhd")) {
       mMdhd = Mdhd(box);
     } else if (box.IsType("minf")) {
       ParseMinf(box);
     }
   }
+  LOG_DEBUG(Mdia, "Done.");
 }
 
 void MoofParser::ParseMvex(Box& aBox) {
+  LOG_DEBUG(Mvex, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("trex")) {
       Trex trex = Trex(box);
       if (mTrackParseMode.is<ParseAllTracks>() ||
           trex.mTrackId == mTrackParseMode.as<uint32_t>()) {
         mTrex = trex;
       }
     }
   }
+  LOG_DEBUG(Mvex, "Done.");
 }
 
 void MoofParser::ParseMinf(Box& aBox) {
+  LOG_DEBUG(Minf, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("stbl")) {
       ParseStbl(box);
     }
   }
+  LOG_DEBUG(Minf, "Done.");
 }
 
 void MoofParser::ParseStbl(Box& aBox) {
+  LOG_DEBUG(Stbl, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("stsd")) {
       ParseStsd(box);
     } else if (box.IsType("sgpd")) {
       Sgpd sgpd(box);
       if (sgpd.IsValid() && sgpd.mGroupingType == "seig") {
         mTrackSampleEncryptionInfoEntries.Clear();
         if (!mTrackSampleEncryptionInfoEntries.AppendElements(
@@ -307,28 +342,31 @@ void MoofParser::ParseStbl(Box& aBox) {
         if (!mTrackSampleToGroupEntries.AppendElements(sbgp.mEntries,
                                                        mozilla::fallible)) {
           LOG_ERROR(Stbl, "OOM");
           return;
         }
       }
     }
   }
+  LOG_DEBUG(Stbl, "Done.");
 }
 
 void MoofParser::ParseStsd(Box& aBox) {
+  LOG_DEBUG(Stsd, "Starting.");
   if (mTrackParseMode.is<ParseAllTracks>()) {
     // It is not a sane operation to try and map sample description boxes from
     // multiple tracks onto the parser, which is modeled around storing metadata
     // for a single track.
+    LOG_DEBUG(Stsd, "Early return due to multitrack parser.");
     return;
   }
   MOZ_ASSERT(
       mSampleDescriptions.IsEmpty(),
-      "Shouldn't have any sample descriptions when starting to parse stsd");
+      "Shouldn't have any sample descriptions yet when starting to parse stsd");
   uint32_t numberEncryptedEntries = 0;
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     SampleDescriptionEntry sampleDescriptionEntry{false};
     if (box.IsType("encv") || box.IsType("enca")) {
       ParseEncrypted(box);
       sampleDescriptionEntry.mIsEncryptedEntry = true;
       numberEncryptedEntries++;
     }
@@ -344,47 +382,60 @@ void MoofParser::ParseStsd(Box& aBox) {
              "shouldn't happen, as the spec requires one for each track!");
   }
   if (numberEncryptedEntries > 1) {
     LOG_WARN(Stsd,
              "More than one encrypted sample description entry found while "
              "parsing track! We don't expect this, and it will likely break "
              "during fragment look up!");
   }
+  LOG_DEBUG(Stsd,
+            "Done, numberEncryptedEntries=%" PRIu32
+            ", mSampleDescriptions.Length=%zu",
+            numberEncryptedEntries, mSampleDescriptions.Length());
 }
 
 void MoofParser::ParseEncrypted(Box& aBox) {
+  LOG_DEBUG(Moof, "Starting.");
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     // Some MP4 files have been found to have multiple sinf boxes in the same
     // enc* box. This does not match spec anyway, so just choose the first
     // one that parses properly.
     if (box.IsType("sinf")) {
       mSinf = Sinf(box);
 
       if (mSinf.IsValid()) {
         break;
       }
     }
   }
+  LOG_DEBUG(Moof, "Done.");
 }
 
 class CtsComparator {
  public:
   bool Equals(Sample* const aA, Sample* const aB) const {
     return aA->mCompositionRange.start == aB->mCompositionRange.start;
   }
   bool LessThan(Sample* const aA, Sample* const aB) const {
     return aA->mCompositionRange.start < aB->mCompositionRange.start;
   }
 };
 
 Moof::Moof(Box& aBox, const TrackParseMode& aTrackParseMode, Trex& aTrex,
            Mvhd& aMvhd, Mdhd& aMdhd, Edts& aEdts, Sinf& aSinf,
            uint64_t* aDecodeTime, bool aIsAudio)
     : mRange(aBox.Range()), mTfhd(aTrex), mMaxRoundingError(35000) {
+  LOG_DEBUG(
+      Moof,
+      "Starting, aTrackParseMode=%s, track#=%" PRIu32
+      " (ignore if multitrack).",
+      aTrackParseMode.is<ParseAllTracks>() ? "multitrack" : "single track",
+      aTrackParseMode.is<ParseAllTracks>() ? 0
+                                           : aTrackParseMode.as<uint32_t>());
   MOZ_ASSERT(aTrackParseMode.is<ParseAllTracks>() ||
                  aTrex.mTrackId == aTrackParseMode.as<uint32_t>(),
              "If not parsing all tracks, aTrex should have the same track id "
              "as the track being parsed.");
   nsTArray<Box> psshBoxes;
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("traf")) {
       ParseTraf(box, aTrackParseMode, aTrex, aMvhd, aMdhd, aEdts, aSinf,
@@ -450,35 +501,39 @@ Moof::Moof(Box& aBox, const TrackParseMo
         compositionDuration += sample.mCompositionRange.Length();
       }
       mTimeRange = MP4Interval<Microseconds>(
           ctsOrder[0]->mCompositionRange.start,
           ctsOrder.LastElement()->mCompositionRange.end);
     }
     ProcessCencAuxInfo(aSinf.mDefaultEncryptionType);
   }
+  LOG_DEBUG(Moof, "Done.");
 }
 
 bool Moof::GetAuxInfo(AtomType aType,
                       FallibleTArray<MediaByteRange>* aByteRanges) {
+  LOG_DEBUG(Moof, "Starting.");
   aByteRanges->Clear();
 
   Saiz* saiz = nullptr;
   for (int i = 0;; i++) {
     if (i == mSaizs.Length()) {
+      LOG_DEBUG(Moof, "Could not find saiz matching aType. Returning false.");
       return false;
     }
     if (mSaizs[i].mAuxInfoType == aType) {
       saiz = &mSaizs[i];
       break;
     }
   }
   Saio* saio = nullptr;
   for (int i = 0;; i++) {
     if (i == mSaios.Length()) {
+      LOG_DEBUG(Moof, "Could not find saio matching aType. Returning false.");
       return false;
     }
     if (mSaios[i].mAuxInfoType == aType) {
       saio = &mSaios[i];
       break;
     }
   }
 
@@ -493,16 +548,19 @@ bool Moof::GetAuxInfo(AtomType aType,
       if (!aByteRanges->AppendElement(
               MediaByteRange(offset, offset + saiz->mSampleInfoSize[i]),
               mozilla::fallible)) {
         LOG_ERROR(Moof, "OOM");
         return false;
       }
       offset += saiz->mSampleInfoSize[i];
     }
+    LOG_DEBUG(
+        Moof,
+        "Saio has 1 entry. aByteRanges populated accordingly. Returning true.");
     return true;
   }
 
   if (saio->mOffsets.Length() == saiz->mSampleInfoSize.Length()) {
     if (!aByteRanges->SetCapacity(saiz->mSampleInfoSize.Length(),
                                   mozilla::fallible)) {
       LOG_ERROR(Moof, "OOM");
       return false;
@@ -511,37 +569,53 @@ bool Moof::GetAuxInfo(AtomType aType,
       uint64_t offset = mRange.mStart + saio->mOffsets[i];
       if (!aByteRanges->AppendElement(
               MediaByteRange(offset, offset + saiz->mSampleInfoSize[i]),
               mozilla::fallible)) {
         LOG_ERROR(Moof, "OOM");
         return false;
       }
     }
+    LOG_DEBUG(
+        Moof,
+        "Saio and saiz have same number of entries. aByteRanges populated "
+        "accordingly. Returning true.");
     return true;
   }
 
+  LOG_DEBUG(Moof,
+            "Moof::GetAuxInfo could not find any Aux info, returning false.");
   return false;
 }
 
 bool Moof::ProcessCencAuxInfo(AtomType aScheme) {
+  LOG_DEBUG(Moof, "Starting.");
   FallibleTArray<MediaByteRange> cencRanges;
   if (!GetAuxInfo(aScheme, &cencRanges) ||
       cencRanges.Length() != mIndex.Length()) {
+    LOG_DEBUG(Moof, "Couldn't find cenc aux info.");
     return false;
   }
   for (int i = 0; i < cencRanges.Length(); i++) {
     mIndex[i].mCencRange = cencRanges[i];
   }
+  LOG_DEBUG(Moof, "Found cenc aux info and stored on index.");
   return true;
 }
 
 void Moof::ParseTraf(Box& aBox, const TrackParseMode& aTrackParseMode,
                      Trex& aTrex, Mvhd& aMvhd, Mdhd& aMdhd, Edts& aEdts,
                      Sinf& aSinf, uint64_t* aDecodeTime, bool aIsAudio) {
+  LOG_DEBUG(
+      Traf,
+      "Starting, aTrackParseMode=%s, track#=%" PRIu32
+      " (ignore if multitrack).",
+      aTrackParseMode.is<ParseAllTracks>() ? "multitrack" : "single track",
+      aTrackParseMode.is<ParseAllTracks>() ? 0
+                                           : aTrackParseMode.as<uint32_t>());
   MOZ_ASSERT(aDecodeTime);
   MOZ_ASSERT(aTrackParseMode.is<ParseAllTracks>() ||
                  aTrex.mTrackId == aTrackParseMode.as<uint32_t>(),
              "If not parsing all tracks, aTrex should have the same track id "
              "as the track being parsed.");
   Tfdt tfdt;
 
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
@@ -583,16 +657,20 @@ void Moof::ParseTraf(Box& aBox, const Tr
           LOG_ERROR(Moof, "OOM");
           return;
         }
       }
     }
   }
   if (aTrackParseMode.is<uint32_t>() &&
       mTfhd.mTrackId != aTrackParseMode.as<uint32_t>()) {
+    LOG_DEBUG(Traf,
+              "Early return as not multitrack parser and track id didn't match "
+              "mTfhd.mTrackId=%" PRIu32,
+              mTfhd.mTrackId);
     return;
   }
   // Now search for TRUN boxes.
   uint64_t decodeTime =
       tfdt.IsValid() ? tfdt.mBaseMediaDecodeTime : *aDecodeTime;
   for (Box box = aBox.FirstChild(); box.IsAvailable(); box = box.Next()) {
     if (box.IsType("trun")) {
       if (ParseTrun(box, aMvhd, aMdhd, aEdts, &decodeTime, aIsAudio).isOk()) {
@@ -600,28 +678,30 @@ void Moof::ParseTraf(Box& aBox, const Tr
       } else {
         LOG_WARN(Moof, "ParseTrun failed");
         mValid = false;
         break;
       }
     }
   }
   *aDecodeTime = decodeTime;
+  LOG_DEBUG(Traf, "Done, setting aDecodeTime=%." PRIu64 ".", decodeTime);
 }
 
 void Moof::FixRounding(const Moof& aMoof) {
   Microseconds gap = aMoof.mTimeRange.start - mTimeRange.end;
   if (gap > 0 && gap <= mMaxRoundingError) {
     mTimeRange.end = aMoof.mTimeRange.start;
   }
 }
 
 Result<Ok, nsresult> Moof::ParseTrun(Box& aBox, Mvhd& aMvhd, Mdhd& aMdhd,
                                      Edts& aEdts, uint64_t* aDecodeTime,
                                      bool aIsAudio) {
+  LOG_DEBUG(Trun, "Starting.");
   if (!mTfhd.IsValid() || !aMvhd.IsValid() || !aMdhd.IsValid() ||
       !aEdts.IsValid()) {
     LOG_WARN(
         Moof, "Invalid dependencies: mTfhd(%d) aMvhd(%d) aMdhd(%d) aEdts(%d)",
         mTfhd.IsValid(), aMvhd.IsValid(), aMdhd.IsValid(), !aEdts.IsValid());
     return Err(NS_ERROR_FAILURE);
   }
 
@@ -635,16 +715,17 @@ Result<Ok, nsresult> Moof::ParseTrun(Box
 
   if (!reader->CanReadType<uint32_t>()) {
     LOG_WARN(Moof, "Incomplete Box (missing sampleCount)");
     return Err(NS_ERROR_FAILURE);
   }
   uint32_t sampleCount;
   MOZ_TRY_VAR(sampleCount, reader->ReadU32());
   if (sampleCount == 0) {
+    LOG_DEBUG(Trun, "Trun with no samples, returning.");
     return Ok();
   }
 
   uint64_t offset = mTfhd.mBaseDataOffset;
   if (flags & 0x01) {
     uint32_t tmp;
     MOZ_TRY_VAR(tmp, reader->ReadU32());
     offset += tmp;
@@ -709,16 +790,17 @@ Result<Ok, nsresult> Moof::ParseTrun(Box
     decodeTime += sampleDuration;
   }
   Microseconds roundTime;
   MOZ_TRY_VAR(roundTime, aMdhd.ToMicroseconds(sampleCount));
   mMaxRoundingError += roundTime;
 
   *aDecodeTime = decodeTime;
 
+  LOG_DEBUG(Trun, "Done.");
   return Ok();
 }
 
 Tkhd::Tkhd(Box& aBox) : mTrackId(0) {
   mValid = Parse(aBox).isOk();
   if (!mValid) {
     LOG_WARN(Tkhd, "Parse failed");
   }