MSE: Strictly verify expected MediaLog events in ChunkDemuxerTests

media/filters/chunk_demuxer_unittest.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/filters/chunk_demuxer.h"
 
 #include <stddef.h>
 #include <stdint.h>
 #include <algorithm>
 #include <utility>
 
 #include "base/bind.h"
 #include "base/macros.h"
 #include "base/message_loop/message_loop.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
 #include "media/base/audio_decoder_config.h"
 #include "media/base/decoder_buffer.h"
 #include "media/base/decrypt_config.h"
-#include "media/base/media_log.h"
 #include "media/base/mock_demuxer_host.h"
+#include "media/base/mock_media_log.h"
 #include "media/base/test_data_util.h"
 #include "media/base/test_helpers.h"
 #include "media/base/timestamp_constants.h"
 #include "media/formats/webm/cluster_builder.h"
+#include "media/formats/webm/webm_cluster_parser.h"
 #include "media/formats/webm/webm_constants.h"
 #include "media/media_features.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using ::testing::AnyNumber;
 using ::testing::Exactly;
 using ::testing::InSequence;
 using ::testing::NotNull;
 using ::testing::Return;
 using ::testing::SaveArg;
 using ::testing::SetArgumentPointee;
+using ::testing::StrictMock;
 using ::testing::_;
 
 namespace media {
 
 const uint8_t kTracksHeader[] = {
     0x16, 0x54, 0xAE, 0x6B,                          // Tracks ID
     0x01, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,  // tracks(size = 0)
 };
 
 // WebM Block bytes that represent a VP8 key frame.
@@ skipping 62 matching lines @@
   }
 }
 
 MATCHER_P(HasTimestamp, timestamp_in_ms, "") {
   return arg.get() && !arg->end_of_stream() &&
          arg->timestamp().InMilliseconds() == timestamp_in_ms;
 }
 
 MATCHER(IsEndOfStream, "") { return arg.get() && arg->end_of_stream(); }
 
+MATCHER(StreamParsingFailed, "") {
+  return CONTAINS_STRING(arg, "Append: stream parsing failed.");
+}
+
+MATCHER_P(FoundStream, stream_type_string, "") {
+  return CONTAINS_STRING(
+             arg, "found_" + std::string(stream_type_string) + "_stream") &&
+         CONTAINS_STRING(arg, "true");
+}
+
+MATCHER_P2(CodecName, stream_type_string, codec_string, "") {
+  return CONTAINS_STRING(arg,
+                         std::string(stream_type_string) + "_codec_name") &&
+         CONTAINS_STRING(arg, std::string(codec_string));
+}
+
+MATCHER_P2(InitSegmentMismatchesMimeType,
+           track_type_string_with_article,
+           mime_missing_track_type_bool,
+           "") {
+  return CONTAINS_STRING(
+      arg, "Initialization segment " +
+               std::string(mime_missing_track_type_bool ? "has "
+                                                        : "does not have ") +
+               std::string(track_type_string_with_article) +
+               " track, but the mimetype " +
+               std::string(mime_missing_track_type_bool ? "does not specify "
+                                                        : "specifies ") +
+               std::string(track_type_string_with_article) + " codec.");
+}
+
+MATCHER_P2(GeneratedSplice, duration_microseconds, time_microseconds, "") {
+  return CONTAINS_STRING(arg, "Generated splice of overlap duration " +
+                                  base::IntToString(duration_microseconds) +
+                                  "us into new buffer at " +
+                                  base::IntToString(time_microseconds) + "us.");
+}
+
+MATCHER_P2(SkippingSpliceAtOrBefore,
+           new_microseconds,
+           existing_microseconds,
+           "") {
+  return CONTAINS_STRING(
+      arg, "Skipping splice frame generation: first new buffer at " +
+               base::IntToString(new_microseconds) +
+               "us begins at or before existing buffer at " +
+               base::IntToString(existing_microseconds) + "us.");
+}
+
+MATCHER_P(SkippingSpliceAlreadySpliced, time_microseconds, "") {
+  return CONTAINS_STRING(
+      arg, "Skipping splice frame generation: overlapped buffers at " +
+               base::IntToString(time_microseconds) +
+               "us are in a previously buffered splice.");
+}
+
+MATCHER_P(WebMSimpleBlockDurationEstimated, estimated_duration_ms, "") {
+  return CONTAINS_STRING(arg, "Estimating WebM block duration to be " +
+                                  base::IntToString(estimated_duration_ms) +
+                                  "ms for the last (Simple)Block in the "
+                                  "Cluster for this Track. Use BlockGroups "
+                                  "with BlockDurations at the end of each "
+                                  "Track in a Cluster to avoid estimation.");
+}
+
+MATCHER_P(WebMNegativeTimecodeOffset, timecode_string, "") {
+  return CONTAINS_STRING(arg, "Got a block with negative timecode offset " +
+                                  std::string(timecode_string));
+}
+
+MATCHER(WebMOutOfOrderTimecode, "") {
+  return CONTAINS_STRING(
+      arg, "Got a block with a timecode before the previous block.");
+}
+
+MATCHER(WebMClusterBeforeFirstInfo, "") {
+  return CONTAINS_STRING(arg, "Found Cluster element before Info.");
+}

[xhwang, 2016/01/13 19:04:38]

I was a bit worried about the maintainability of these tests since every time we
change where we report these logs, or change the log text message, we need to
update these tests. But then on the other side these tests can make sure we
always report the correct text message in the right place, which is a good thing
:)

[wolenetz, 2016/01/15 02:14:48]

Acknowledged.

+
 static void OnReadDone(const base::TimeDelta& expected_time,
                        bool* called,
                        DemuxerStream::Status status,
                        const scoped_refptr<DecoderBuffer>& buffer) {
   EXPECT_EQ(status, DemuxerStream::kOk);
   EXPECT_EQ(expected_time, buffer->timestamp());
   *called = true;
 }
 
 static void OnReadDone_AbortExpected(
@@ skipping 33 matching lines @@
   // Default cluster to append after kDefaultFirstCluster()
   // has been appended. This cluster starts with blocks that
   // have timestamps consistent with the end times of the blocks
   // in kDefaultFirstCluster() so that these two clusters represent
   // a continuous region.
   scoped_ptr<Cluster> kDefaultSecondCluster() {
     return GenerateCluster(46, 66, 5);
   }
 
   ChunkDemuxerTest()
-      : append_window_end_for_next_append_(kInfiniteDuration()) {
+      : media_log_(new StrictMock<MockMediaLog>()),
+        append_window_end_for_next_append_(kInfiniteDuration()) {
     init_segment_received_cb_ =
         base::Bind(&ChunkDemuxerTest::InitSegmentReceived,
                    base::Unretained(this));
     CreateNewDemuxer();
   }
 
   void CreateNewDemuxer() {
     base::Closure open_cb =
         base::Bind(&ChunkDemuxerTest::DemuxerOpened, base::Unretained(this));
     Demuxer::EncryptedMediaInitDataCB encrypted_media_init_data_cb = base::Bind(
         &ChunkDemuxerTest::OnEncryptedMediaInitData, base::Unretained(this));
     demuxer_.reset(new ChunkDemuxer(open_cb, encrypted_media_init_data_cb,
-                                    scoped_refptr<MediaLog>(new MediaLog()),
-                                    true));
+                                    media_log_, true));
   }
 
   virtual ~ChunkDemuxerTest() {
     ShutdownDemuxer();
   }
 
   void CreateInitSegment(int stream_flags,
                          bool is_audio_encrypted,
                          bool is_video_encrypted,
                          scoped_ptr<uint8_t[]>* buffer,
@@ skipping 239 matching lines @@
     }
   };
 
   // |track_number| - The track number to place in
   // |block_descriptions| - A space delimited string of block info that
   //  is used to populate |blocks|. Each block info has a timestamp in
   //  milliseconds and optionally followed by a 'K' to indicate that a block
   //  should be marked as a key frame. For example "0K 30 60" should populate
   //  |blocks| with 3 BlockInfo objects: a key frame with timestamp 0 and 2
   //  non-key-frames at 30ms and 60ms.
+  //  Every block will be a SimpleBlock, with the exception that the last block
+  //  may have an optional duration delimited with a 'D' and appended to the
+  //  block info timestamp, prior to the optional keyframe 'K'. For example "0K
+  //  30 60D10K" indicates that the last block will be a keyframe BlockGroup
+  //  with duration 10ms.
   void ParseBlockDescriptions(int track_number,
                               const std::string block_descriptions,
                               std::vector<BlockInfo>* blocks) {
     std::vector<std::string> timestamps = base::SplitString(
         block_descriptions, " ", base::TRIM_WHITESPACE, base::SPLIT_WANT_ALL);
 
     for (size_t i = 0; i < timestamps.size(); ++i) {
       std::string timestamp_str = timestamps[i];
       BlockInfo block_info;
       block_info.track_number = track_number;
       block_info.flags = 0;
       block_info.duration = 0;
 
       if (base::EndsWith(timestamp_str, "K", base::CompareCase::SENSITIVE)) {
         block_info.flags = kWebMFlagKeyframe;
         // Remove the "K" off of the token.
         timestamp_str = timestamp_str.substr(0, timestamps[i].length() - 1);
       }
+
+      size_t duration_pos = timestamp_str.find('D');
+      const bool explicit_duration = duration_pos != std::string::npos;
+      const bool is_last_block = i == timestamps.size() - 1;
+      CHECK(!explicit_duration || is_last_block);
+      if (explicit_duration) {
+        CHECK(base::StringToInt(timestamp_str.substr(duration_pos + 1),
+                                &block_info.duration));
+        timestamp_str = timestamp_str.substr(0, duration_pos);
+      }
+
       CHECK(base::StringToInt(timestamp_str, &block_info.timestamp_in_ms));
 
       if (track_number == kTextTrackNum ||
           track_number == kAlternateTextTrackNum) {
         block_info.duration = kTextBlockDuration;
         ASSERT_EQ(kWebMFlagKeyframe, block_info.flags)
             << "Text block with timestamp " << block_info.timestamp_in_ms
             << " was not marked as a key frame."
             << " All text blocks must be key frames";
       }
@@ skipping 53 matching lines @@
   void AppendSingleStreamCluster(const std::string& source_id, int track_number,
                                  const std::string& block_descriptions) {
     std::vector<BlockInfo> blocks;
     ParseBlockDescriptions(track_number, block_descriptions, &blocks);
     AppendCluster(source_id, GenerateCluster(blocks, false));
   }
 
   struct MuxedStreamInfo {
     MuxedStreamInfo()
         : track_number(0),
-          block_descriptions("")
-    {}
+          block_descriptions(""),
+          last_blocks_estimated_duration(-1) {}
 
     MuxedStreamInfo(int track_num, const char* block_desc)
         : track_number(track_num),
-          block_descriptions(block_desc) {
-    }
+          block_descriptions(block_desc),
+          last_blocks_estimated_duration(-1) {}
+
+    MuxedStreamInfo(int track_num,
+                    const char* block_desc,
+                    int last_block_duration_estimate)
+        : track_number(track_num),
+          block_descriptions(block_desc),
+          last_blocks_estimated_duration(last_block_duration_estimate) {}
 
     int track_number;
     // The block description passed to ParseBlockDescriptions().
     // See the documentation for that method for details on the string format.
     const char* block_descriptions;
+
+    // If -1, no WebMSimpleBlockDurationEstimated MediaLog expectation is added
+    // when appending the resulting cluster. Otherwise, an expectation (in ms)
+    // is added.
+    int last_blocks_estimated_duration;
   };
 
   void AppendMuxedCluster(const MuxedStreamInfo& msi_1,
                           const MuxedStreamInfo& msi_2) {
     std::vector<MuxedStreamInfo> msi(2);
     msi[0] = msi_1;
     msi[1] = msi_2;
     AppendMuxedCluster(msi);
   }
 
   void AppendMuxedCluster(const MuxedStreamInfo& msi_1,
                           const MuxedStreamInfo& msi_2,
                           const MuxedStreamInfo& msi_3) {
     std::vector<MuxedStreamInfo> msi(3);
     msi[0] = msi_1;
     msi[1] = msi_2;
     msi[2] = msi_3;
     AppendMuxedCluster(msi);
   }
 
   void AppendMuxedCluster(const std::vector<MuxedStreamInfo> msi) {
     std::priority_queue<BlockInfo> block_queue;
     for (size_t i = 0; i < msi.size(); ++i) {
       std::vector<BlockInfo> track_blocks;
       ParseBlockDescriptions(msi[i].track_number, msi[i].block_descriptions,
                              &track_blocks);
 
-      for (size_t j = 0; j < track_blocks.size(); ++j)
+      for (size_t j = 0; j < track_blocks.size(); ++j) {
         block_queue.push(track_blocks[j]);
+      }
+
+      if (msi[i].last_blocks_estimated_duration != -1) {
+        EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(
+            msi[i].last_blocks_estimated_duration));
+      }
     }
 
     AppendCluster(kSourceId, GenerateCluster(block_queue, false));
   }
 
   void AppendData(const std::string& source_id,
                   const uint8_t* data,
                   size_t length) {
     EXPECT_CALL(host_, AddBufferedTimeRange(_, _)).Times(AnyNumber());
 
@@ skipping 76 matching lines @@
   enum StreamFlags {
     HAS_AUDIO = 1 << 0,
     HAS_VIDEO = 1 << 1,
     HAS_TEXT = 1 << 2
   };
 
   bool InitDemuxer(int stream_flags) {
     return InitDemuxerWithEncryptionInfo(stream_flags, false, false);
   }
 
+  void ExpectInitMediaLogs(int stream_flags) {
+    if (stream_flags & HAS_AUDIO) {
+      EXPECT_MEDIA_LOG(FoundStream("audio"));
+      EXPECT_MEDIA_LOG(CodecName("audio", "vorbis"));
+    }
+
+    if (stream_flags & HAS_VIDEO) {
+      EXPECT_MEDIA_LOG(FoundStream("video"));
+      EXPECT_MEDIA_LOG(CodecName("video", "vp8"));
+    }
+  }
+
   bool InitDemuxerWithEncryptionInfo(
       int stream_flags, bool is_audio_encrypted, bool is_video_encrypted) {
 
     PipelineStatus expected_status =
         (stream_flags != 0) ? PIPELINE_OK : PIPELINE_ERROR_DECODE;
 
     base::TimeDelta expected_duration = kNoTimestamp();
     if (expected_status == PIPELINE_OK)
       expected_duration = kDefaultDuration();
 
     EXPECT_CALL(*this, DemuxerOpened());
 
-    // Adding expectation prior to CreateInitDoneCB() here because InSequence
+    if (is_audio_encrypted || is_video_encrypted) {
+      DCHECK(!is_audio_encrypted || stream_flags & HAS_AUDIO);
+      DCHECK(!is_video_encrypted || stream_flags & HAS_VIDEO);
+
+      int need_key_count =
+          (is_audio_encrypted ? 1 : 0) + (is_video_encrypted ? 1 : 0);
+      EXPECT_CALL(*this, OnEncryptedMediaInitData(
+                             EmeInitDataType::WEBM,
+                             std::vector<uint8_t>(
+                                 kEncryptedMediaInitData,
+                                 kEncryptedMediaInitData +
+                                     arraysize(kEncryptedMediaInitData))))
+          .Times(Exactly(need_key_count));
+    }
+
+    // Adding expectations prior to CreateInitDoneCB() here because InSequence
     // tests require init segment received before duration set. Also, only
     // expect an init segment received callback if there is actually a track in
     // it.
-    if (stream_flags != 0)
+    if (stream_flags != 0) {
+      ExpectInitMediaLogs(stream_flags);
       EXPECT_CALL(*this, InitSegmentReceived());
+    } else {
+      // OnNewConfigs() requires at least one audio, video, or text track.
+      EXPECT_MEDIA_LOG(StreamParsingFailed());
+    }
 
     demuxer_->Initialize(
         &host_, CreateInitDoneCB(expected_duration, expected_status), true);
 
     if (AddId(kSourceId, stream_flags) != ChunkDemuxer::kOk)
       return false;
 
     AppendInitSegmentWithEncryptedInfo(
         kSourceId, stream_flags,
         is_audio_encrypted, is_video_encrypted);
@@ skipping 13 matching lines @@
       return false;
 
     int audio_flags = HAS_AUDIO;
     int video_flags = HAS_VIDEO;
 
     if (has_text) {
       audio_flags |= HAS_TEXT;
       video_flags |= HAS_TEXT;
     }
 
+    // Note: Unlike InitDemuxerWithEncryptionInfo, this method is currently
+    // incompatible with InSequence tests. Refactoring of the duration
+    // set expectation to not be added during CreateInitDoneCB() could fix this.
+    ExpectInitMediaLogs(audio_flags);
     EXPECT_CALL(*this, InitSegmentReceived());
     AppendInitSegmentWithSourceId(audio_id, audio_flags);
+
+    ExpectInitMediaLogs(video_flags);
     EXPECT_CALL(*this, InitSegmentReceived());
     AppendInitSegmentWithSourceId(video_id, video_flags);
     return true;
   }
 
   bool InitDemuxerAudioAndVideoSources(const std::string& audio_id,
                                        const std::string& video_id) {
     return InitDemuxerAudioAndVideoSourcesText(audio_id, video_id, false);
   }
 
@@ skipping 15 matching lines @@
   // bear-320x240.webm : [0-524)       [779-2736)
   // bear-640x360.webm :       [527-759)
   bool InitDemuxerWithConfigChangeData() {
     scoped_refptr<DecoderBuffer> bear1 = ReadTestDataFile("bear-320x240.webm");
     scoped_refptr<DecoderBuffer> bear2 = ReadTestDataFile("bear-640x360.webm");
 
     EXPECT_CALL(*this, DemuxerOpened());
 
     // Adding expectation prior to CreateInitDoneCB() here because InSequence
     // tests require init segment received before duration set.
+    ExpectInitMediaLogs(HAS_AUDIO | HAS_VIDEO);
     EXPECT_CALL(*this, InitSegmentReceived());
     demuxer_->Initialize(
         &host_, CreateInitDoneCB(base::TimeDelta::FromMilliseconds(2744),
                                  PIPELINE_OK), true);
 
     if (AddId(kSourceId, HAS_AUDIO | HAS_VIDEO) != ChunkDemuxer::kOk)
       return false;
 
     // Append the whole bear1 file.
+    EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2)).Times(7);
     // Expect duration adjustment since actual duration differs slightly from
     // duration in the init segment.
     EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(2746)));
     AppendData(bear1->data(), bear1->data_size());
     // Last audio frame has timestamp 2721 and duration 24 (estimated from max
     // seen so far for audio track).
     // Last video frame has timestamp 2703 and duration 33 (from TrackEntry
     // DefaultDuration for video track).
     CheckExpectedRanges(kSourceId, "{ [0,2736) }");
 
     // Append initialization segment for bear2.
     // Note: Offsets here and below are derived from
     // media/test/data/bear-640x360-manifest.js and
     // media/test/data/bear-320x240-manifest.js which were
     // generated from media/test/data/bear-640x360.webm and
     // media/test/data/bear-320x240.webm respectively.
     EXPECT_CALL(*this, InitSegmentReceived());
     AppendData(bear2->data(), 4340);
 
     // Append a media segment that goes from [0.527000, 1.014000).
+    EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2));
+    EXPECT_MEDIA_LOG(GeneratedSplice(20000, 527000));
     AppendData(bear2->data() + 55290, 18785);
     CheckExpectedRanges(kSourceId, "{ [0,1027) [1201,2736) }");
 
     // Append initialization segment for bear1 & fill gap with [779-1197)
     // segment.
     EXPECT_CALL(*this, InitSegmentReceived());
     AppendData(bear1->data(), 4370);
+    EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(23));
+    EXPECT_MEDIA_LOG(GeneratedSplice(26000, 779000));
     AppendData(bear1->data() + 72737, 28183);
     CheckExpectedRanges(kSourceId, "{ [0,2736) }");
 
     MarkEndOfStream(PIPELINE_OK);
     return true;
   }
 
   void ShutdownDemuxer() {
     if (demuxer_) {
       demuxer_->Shutdown();
@@ skipping 382 matching lines @@
     if (demuxer_->IsParsingMediaSegment(id))
       return false;
 
     timestamp_offset_map_[id] = timestamp_offset;
     return true;
   }
 
   base::MessageLoop message_loop_;
   MockDemuxerHost host_;
 
+  scoped_refptr<StrictMock<MockMediaLog>> media_log_;
+
   scoped_ptr<ChunkDemuxer> demuxer_;
   ChunkDemuxer::InitSegmentReceivedCB init_segment_received_cb_;
 
   base::TimeDelta append_window_start_for_next_append_;
   base::TimeDelta append_window_end_for_next_append_;
 
   // Map of source id to timestamp offset to use for the next AppendData()
   // operation for that source id.
   std::map<std::string, base::TimeDelta> timestamp_offset_map_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(ChunkDemuxerTest);
 };
 
 TEST_F(ChunkDemuxerTest, Init) {
+  InSequence s;
+
   // Test no streams, audio-only, video-only, and audio & video scenarios.
   // Audio and video streams can be encrypted or not encrypted.
   for (int i = 0; i < 16; i++) {
     bool has_audio = (i & 0x1) != 0;
     bool has_video = (i & 0x2) != 0;
     bool is_audio_encrypted = (i & 0x4) != 0;
     bool is_video_encrypted = (i & 0x8) != 0;
 
     // No test on invalid combination.
     if ((!has_audio && is_audio_encrypted) ||
         (!has_video && is_video_encrypted)) {
       continue;
     }
 
     CreateNewDemuxer();
 
-    if (is_audio_encrypted || is_video_encrypted) {
-      int need_key_count = (is_audio_encrypted ? 1 : 0) +
-                           (is_video_encrypted ? 1 : 0);
-      EXPECT_CALL(*this, OnEncryptedMediaInitData(
-                             EmeInitDataType::WEBM,
-                             std::vector<uint8_t>(
-                                 kEncryptedMediaInitData,
-                                 kEncryptedMediaInitData +
-                                     arraysize(kEncryptedMediaInitData))))
-          .Times(Exactly(need_key_count));
-    }
-
     int stream_flags = 0;
     if (has_audio)
       stream_flags |= HAS_AUDIO;
 
     if (has_video)
       stream_flags |= HAS_VIDEO;
 
     ASSERT_TRUE(InitDemuxerWithEncryptionInfo(
         stream_flags, is_audio_encrypted, is_video_encrypted));
 
@@ skipping 112 matching lines @@
       .WillOnce(DoAll(SaveArg<0>(&text_stream),
                       SaveArg<1>(&text_config)));
   ASSERT_TRUE(InitDemuxerWithEncryptionInfo(
       HAS_TEXT | HAS_AUDIO | HAS_VIDEO, false, false));
   DemuxerStream* audio_stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   DemuxerStream* video_stream = demuxer_->GetStream(DemuxerStream::VIDEO);
   ASSERT_TRUE(audio_stream);
   ASSERT_TRUE(video_stream);
   ASSERT_TRUE(text_stream);
 
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "0K 23K"),
-      MuxedStreamInfo(kVideoTrackNum, "0K 30"),
-      MuxedStreamInfo(kTextTrackNum, "10K"));
-  CheckExpectedRanges(kSourceId, "{ [0,46) }");
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "0K 23K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "0K 30", 30),
+                     MuxedStreamInfo(kTextTrackNum, "10K"));
+  CheckExpectedRanges("{ [0,46) }");
 
   scoped_ptr<uint8_t[]> info_tracks;
   int info_tracks_size = 0;
   CreateInitSegmentWithAlternateTextTrackNum(HAS_TEXT | HAS_AUDIO | HAS_VIDEO,
                                              false, false,
                                              &info_tracks, &info_tracks_size);
   EXPECT_CALL(*this, InitSegmentReceived());
   demuxer_->AppendData(kSourceId, info_tracks.get(), info_tracks_size,
                        append_window_start_for_next_append_,
                        append_window_end_for_next_append_,
                        &timestamp_offset_map_[kSourceId],
                        init_segment_received_cb_);
 
   AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "46K 69K"),
-      MuxedStreamInfo(kVideoTrackNum, "60K"),
+      MuxedStreamInfo(kAudioTrackNum, "46K 69K", 23),
+      MuxedStreamInfo(kVideoTrackNum, "60K",
+                      WebMClusterParser::kDefaultVideoBufferDurationInMs),
       MuxedStreamInfo(kAlternateTextTrackNum, "45K"));
 
   CheckExpectedRanges(kSourceId, "{ [0,92) }");
   CheckExpectedBuffers(audio_stream, "0K 23K 46K 69K");
   CheckExpectedBuffers(video_stream, "0K 30 60K");
   CheckExpectedBuffers(text_stream, "10K 45K");
 
   ShutdownDemuxer();
 }
 
 TEST_F(ChunkDemuxerTest, InitSegmentSetsNeedRandomAccessPointFlag) {
   // Tests that non-key-frames following an init segment are allowed
   // and dropped, as expected if the initialization segment received
   // algorithm correctly sets the needs random access point flag to true for all
   // track buffers. Note that the first initialization segment is insufficient
   // to fully test this since needs random access point flag initializes to
   // true.
   CreateNewDemuxer();
   DemuxerStream* text_stream = NULL;
   EXPECT_CALL(host_, AddTextStream(_, _))
       .WillOnce(SaveArg<0>(&text_stream));
   ASSERT_TRUE(InitDemuxerWithEncryptionInfo(
       HAS_TEXT | HAS_AUDIO | HAS_VIDEO, false, false));
   DemuxerStream* audio_stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   DemuxerStream* video_stream = demuxer_->GetStream(DemuxerStream::VIDEO);
   ASSERT_TRUE(audio_stream && video_stream && text_stream);
 
   AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "23K"),
-      MuxedStreamInfo(kVideoTrackNum, "0 30K"),
+      MuxedStreamInfo(kAudioTrackNum, "23K",
+                      WebMClusterParser::kDefaultAudioBufferDurationInMs),
+      MuxedStreamInfo(kVideoTrackNum, "0 30K", 30),
       MuxedStreamInfo(kTextTrackNum, "25K 40K"));
   CheckExpectedRanges(kSourceId, "{ [23,46) }");
 
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegment(HAS_TEXT | HAS_AUDIO | HAS_VIDEO);
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "46K 69K"),
-      MuxedStreamInfo(kVideoTrackNum, "60 90K"),
-      MuxedStreamInfo(kTextTrackNum, "80K 90K"));
-  CheckExpectedRanges(kSourceId, "{ [23,92) }");
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "46K 69K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "60 90K", 30),
+                     MuxedStreamInfo(kTextTrackNum, "80K 90K"));
+  CheckExpectedRanges("{ [23,92) }");
 
   CheckExpectedBuffers(audio_stream, "23K 46K 69K");
   CheckExpectedBuffers(video_stream, "30K 90K");
   CheckExpectedBuffers(text_stream, "25K 40K 80K 90K");
 }
 
 // Make sure that the demuxer reports an error if Shutdown()
 // is called before all the initialization segments are appended.
 TEST_F(ChunkDemuxerTest, Shutdown_BeforeAllInitSegmentsAppended) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(
           kDefaultDuration(), DEMUXER_ERROR_COULD_NOT_OPEN), true);
 
   EXPECT_EQ(AddId("audio", HAS_AUDIO), ChunkDemuxer::kOk);
   EXPECT_EQ(AddId("video", HAS_VIDEO), ChunkDemuxer::kOk);
 
+  ExpectInitMediaLogs(HAS_AUDIO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegmentWithSourceId("audio", HAS_AUDIO);
 
   ShutdownDemuxer();
 }
 
 TEST_F(ChunkDemuxerTest, Shutdown_BeforeAllInitSegmentsAppendedText) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(
           kDefaultDuration(), DEMUXER_ERROR_COULD_NOT_OPEN), true);
 
   EXPECT_EQ(AddId("audio", HAS_AUDIO), ChunkDemuxer::kOk);
   EXPECT_EQ(AddId("video_and_text", HAS_VIDEO), ChunkDemuxer::kOk);
 
   EXPECT_CALL(host_, AddTextStream(_, _))
       .Times(Exactly(1));
 
+  ExpectInitMediaLogs(HAS_VIDEO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegmentWithSourceId("video_and_text", HAS_VIDEO | HAS_TEXT);
 
   ShutdownDemuxer();
 }
 
 // Verifies that all streams waiting for data receive an end of stream
 // buffer when Shutdown() is called.
 TEST_F(ChunkDemuxerTest, Shutdown_EndOfStreamWhileWaitingForData) {
   DemuxerStream* text_stream = NULL;
@@ skipping 44 matching lines @@
   message_loop_.RunUntilIdle();
 
   Checkpoint(2);
 }
 
 // Test that parsing errors are handled for clusters appended after init.
 TEST_F(ChunkDemuxerTest, ErrorWhileParsingClusterAfterInit) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendCluster(kDefaultFirstCluster());
 
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   EXPECT_CALL(host_, OnDemuxerError(PIPELINE_ERROR_DECODE));
   AppendGarbage();
 }
 
 // Test the case where a Seek() is requested while the parser
 // is in the middle of cluster. This is to verify that the parser
 // does not reset itself on a seek.
 TEST_F(ChunkDemuxerTest, SeekWhileParsingCluster) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
@@ skipping 51 matching lines @@
                        base::TimeDelta::FromMilliseconds(0),
                        &video_read_done));
 
   EXPECT_TRUE(audio_read_done);
   EXPECT_TRUE(video_read_done);
 }
 
 TEST_F(ChunkDemuxerTest, OutOfOrderClusters) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendCluster(kDefaultFirstCluster());
+  EXPECT_MEDIA_LOG(GeneratedSplice(13000, 10000));
   AppendCluster(GenerateCluster(10, 4));
 
   // Make sure that AppendCluster() does not fail with a cluster that has
   // overlaps with the previously appended cluster.
+  EXPECT_MEDIA_LOG(SkippingSpliceAlreadySpliced(0));
   AppendCluster(GenerateCluster(5, 4));
 
   // Verify that AppendData() can still accept more data.
   scoped_ptr<Cluster> cluster_c(GenerateCluster(45, 2));
+  EXPECT_MEDIA_LOG(GeneratedSplice(6000, 45000));
   demuxer_->AppendData(kSourceId, cluster_c->data(), cluster_c->size(),
                        append_window_start_for_next_append_,
                        append_window_end_for_next_append_,
                        &timestamp_offset_map_[kSourceId],
                        init_segment_received_cb_);
 }
 
 TEST_F(ChunkDemuxerTest, NonMonotonicButAboveClusterTimecode) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendCluster(kDefaultFirstCluster());
 
   ClusterBuilder cb;
 
   // Test the case where block timecodes are not monotonically
   // increasing but stay above the cluster timecode.
   cb.SetClusterTimecode(5);
   AddSimpleBlock(&cb, kAudioTrackNum, 5);
   AddSimpleBlock(&cb, kVideoTrackNum, 10);
   AddSimpleBlock(&cb, kAudioTrackNum, 7);
   AddSimpleBlock(&cb, kVideoTrackNum, 15);
 
+  EXPECT_MEDIA_LOG(WebMOutOfOrderTimecode());
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   EXPECT_CALL(host_, OnDemuxerError(PIPELINE_ERROR_DECODE));
   AppendCluster(cb.Finish());
 
   // Verify that AppendData() ignores data after the error.
   scoped_ptr<Cluster> cluster_b(GenerateCluster(20, 2));
   demuxer_->AppendData(kSourceId, cluster_b->data(), cluster_b->size(),
                        append_window_start_for_next_append_,
                        append_window_end_for_next_append_,
                        &timestamp_offset_map_[kSourceId],
                        init_segment_received_cb_);
 }
 
 TEST_F(ChunkDemuxerTest, BackwardsAndBeforeClusterTimecode) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendCluster(kDefaultFirstCluster());
 
   ClusterBuilder cb;
 
   // Test timecodes going backwards and including values less than the cluster
   // timecode.
   cb.SetClusterTimecode(5);
   AddSimpleBlock(&cb, kAudioTrackNum, 5);
   AddSimpleBlock(&cb, kVideoTrackNum, 5);
   AddSimpleBlock(&cb, kAudioTrackNum, 3);
   AddSimpleBlock(&cb, kVideoTrackNum, 3);
 
+  EXPECT_MEDIA_LOG(WebMNegativeTimecodeOffset("-2"));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   EXPECT_CALL(host_, OnDemuxerError(PIPELINE_ERROR_DECODE));
   AppendCluster(cb.Finish());
 
   // Verify that AppendData() ignores data after the error.
   scoped_ptr<Cluster> cluster_b(GenerateCluster(6, 2));
   demuxer_->AppendData(kSourceId, cluster_b->data(), cluster_b->size(),
                        append_window_start_for_next_append_,
                        append_window_end_for_next_append_,
                        &timestamp_offset_map_[kSourceId],
                        init_segment_received_cb_);
 }
 
 
 TEST_F(ChunkDemuxerTest, PerStreamMonotonicallyIncreasingTimestamps) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendCluster(kDefaultFirstCluster());
 
   ClusterBuilder cb;
 
   // Test monotonic increasing timestamps on a per stream
   // basis.
-  cb.SetClusterTimecode(5);
+  cb.SetClusterTimecode(4);
   AddSimpleBlock(&cb, kAudioTrackNum, 5);
   AddSimpleBlock(&cb, kVideoTrackNum, 5);
   AddSimpleBlock(&cb, kAudioTrackNum, 4);
   AddSimpleBlock(&cb, kVideoTrackNum, 7);
 
+  EXPECT_MEDIA_LOG(WebMOutOfOrderTimecode());
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   EXPECT_CALL(host_, OnDemuxerError(PIPELINE_ERROR_DECODE));
   AppendCluster(cb.Finish());
 }
 
 // Test the case where a cluster is passed to AppendCluster() before
 // INFO & TRACKS data.
 TEST_F(ChunkDemuxerTest, ClusterBeforeInitSegment) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, NewExpectedStatusCB(PIPELINE_ERROR_DECODE), true);
 
   ASSERT_EQ(AddId(), ChunkDemuxer::kOk);
 
+  EXPECT_MEDIA_LOG(WebMClusterBeforeFirstInfo());
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   AppendCluster(GenerateCluster(0, 1));
 }
 
 // Test cases where we get an MarkEndOfStream() call during initialization.
 TEST_F(ChunkDemuxerTest, EOSDuringInit) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, NewExpectedStatusCB(DEMUXER_ERROR_COULD_NOT_OPEN), true);
   MarkEndOfStream(PIPELINE_OK);
 }
@@ skipping 197 matching lines @@
 }
 
 // Verify buffered range change behavior for audio/video/text tracks.
 TEST_F(ChunkDemuxerTest, EndOfStreamRangeChanges) {
   DemuxerStream* text_stream = NULL;
 
   EXPECT_CALL(host_, AddTextStream(_, _))
       .WillOnce(SaveArg<0>(&text_stream));
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO | HAS_TEXT));
 
-  AppendMuxedCluster(
-      MuxedStreamInfo(kVideoTrackNum, "0K 33"),
-      MuxedStreamInfo(kAudioTrackNum, "0K 23K"));
+  AppendMuxedCluster(MuxedStreamInfo(kVideoTrackNum, "0K 33", 33),
+                     MuxedStreamInfo(kAudioTrackNum, "0K 23K", 23));
 
   // Check expected ranges and verify that an empty text track does not
   // affect the expected ranges.
   CheckExpectedRanges(kSourceId, "{ [0,46) }");
 
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(66)));
   MarkEndOfStream(PIPELINE_OK);
 
   // Check expected ranges and verify that an empty text track does not
   // affect the expected ranges.
   CheckExpectedRanges(kSourceId, "{ [0,66) }");
 
   // Unmark end of stream state and verify that the ranges return to
   // their pre-"end of stream" values.
   demuxer_->UnmarkEndOfStream();
   CheckExpectedRanges(kSourceId, "{ [0,46) }");
 
   // Add text track data and verify that the buffered ranges don't change
   // since the intersection of all the tracks doesn't change.
+  EXPECT_MEDIA_LOG(SkippingSpliceAtOrBefore(0, 0));
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(200)));
-  AppendMuxedCluster(
-      MuxedStreamInfo(kVideoTrackNum, "0K 33"),
-      MuxedStreamInfo(kAudioTrackNum, "0K 23K"),
-      MuxedStreamInfo(kTextTrackNum, "0K 100K"));
-  CheckExpectedRanges(kSourceId, "{ [0,46) }");
+  AppendMuxedCluster(MuxedStreamInfo(kVideoTrackNum, "0K 33", 33),
+                     MuxedStreamInfo(kAudioTrackNum, "0K 23K", 23),
+                     MuxedStreamInfo(kTextTrackNum, "0K 100K"));
+  CheckExpectedRanges("{ [0,46) }");
 
   // Mark end of stream and verify that text track data is reflected in
   // the new range.
   MarkEndOfStream(PIPELINE_OK);
   CheckExpectedRanges(kSourceId, "{ [0,200) }");
 }
 
 // Make sure AppendData() will accept elements that span multiple calls.
 TEST_F(ChunkDemuxerTest, AppendingInPieces) {
   EXPECT_CALL(*this, DemuxerOpened());
@@ skipping 15 matching lines @@
   uint8_t* dst = buffer.get();
   memcpy(dst, info_tracks.get(), info_tracks_size);
   dst += info_tracks_size;
 
   memcpy(dst, cluster_a->data(), cluster_a->size());
   dst += cluster_a->size();
 
   memcpy(dst, cluster_b->data(), cluster_b->size());
   dst += cluster_b->size();
 
+  ExpectInitMediaLogs(HAS_AUDIO | HAS_VIDEO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendDataInPieces(buffer.get(), buffer_size);
 
   GenerateExpectedReads(0, 9);
 }
 
 TEST_F(ChunkDemuxerTest, WebMFile_AudioAndVideo) {
   struct BufferTimestamps buffer_timestamps[] = {
     {0, 0},
     {33, 3},
     {67, 6},
     {100, 9},
     {133, 12},
     {kSkip, kSkip},
   };
 
+  ExpectInitMediaLogs(HAS_AUDIO | HAS_VIDEO);
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2)).Times(7);
+
   // Expect duration adjustment since actual duration differs slightly from
   // duration in the init segment.
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(2746)));
 
   ASSERT_TRUE(ParseWebMFile("bear-320x240.webm", buffer_timestamps,
                             base::TimeDelta::FromMilliseconds(2744)));
   EXPECT_EQ(212949, demuxer_->GetMemoryUsage());
 }
 
 TEST_F(ChunkDemuxerTest, WebMFile_LiveAudioAndVideo) {
   struct BufferTimestamps buffer_timestamps[] = {
     {0, 0},
     {33, 3},
     {67, 6},
     {100, 9},
     {133, 12},
     {kSkip, kSkip},
   };
 
+  ExpectInitMediaLogs(HAS_AUDIO | HAS_VIDEO);
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2)).Times(7);
   ASSERT_TRUE(ParseWebMFile("bear-320x240-live.webm", buffer_timestamps,
                             kInfiniteDuration()));
 
   DemuxerStream* audio = demuxer_->GetStream(DemuxerStream::AUDIO);
   EXPECT_EQ(DemuxerStream::LIVENESS_LIVE, audio->liveness());
   DemuxerStream* video = demuxer_->GetStream(DemuxerStream::VIDEO);
   EXPECT_EQ(DemuxerStream::LIVENESS_LIVE, video->liveness());
   EXPECT_EQ(212949, demuxer_->GetMemoryUsage());
 }
 
 TEST_F(ChunkDemuxerTest, WebMFile_AudioOnly) {
   struct BufferTimestamps buffer_timestamps[] = {
     {kSkip, 0},
     {kSkip, 3},
     {kSkip, 6},
     {kSkip, 9},
     {kSkip, 12},
     {kSkip, kSkip},
   };
 
+  ExpectInitMediaLogs(HAS_AUDIO);
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2));
+
   // Expect duration adjustment since actual duration differs slightly from
   // duration in the init segment.
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(2746)));
 
   ASSERT_TRUE(ParseWebMFile("bear-320x240-audio-only.webm", buffer_timestamps,
                             base::TimeDelta::FromMilliseconds(2744),
                             HAS_AUDIO));
   EXPECT_EQ(18624, demuxer_->GetMemoryUsage());
 }
 
 TEST_F(ChunkDemuxerTest, WebMFile_VideoOnly) {
   struct BufferTimestamps buffer_timestamps[] = {
     {0, kSkip},
     {33, kSkip},
     {67, kSkip},
     {100, kSkip},
     {133, kSkip},
     {kSkip, kSkip},
   };
 
+  ExpectInitMediaLogs(HAS_VIDEO);
+
   // Expect duration adjustment since actual duration differs slightly from
   // duration in the init segment.
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(2736)));
 
   ASSERT_TRUE(ParseWebMFile("bear-320x240-video-only.webm", buffer_timestamps,
                             base::TimeDelta::FromMilliseconds(2703),
                             HAS_VIDEO));
   EXPECT_EQ(194325, demuxer_->GetMemoryUsage());
 }
 
 TEST_F(ChunkDemuxerTest, WebMFile_AltRefFrames) {
   struct BufferTimestamps buffer_timestamps[] = {
     {0, 0},
     {33, 3},
     {33, 6},
     {67, 9},
     {100, 12},
     {kSkip, kSkip},
   };
 
+  ExpectInitMediaLogs(HAS_AUDIO | HAS_VIDEO);
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2));
   ASSERT_TRUE(ParseWebMFile("bear-320x240-altref.webm", buffer_timestamps,
                             base::TimeDelta::FromMilliseconds(2767)));
 }
 
 // Verify that we output buffers before the entire cluster has been parsed.
 TEST_F(ChunkDemuxerTest, IncrementalClusterParsing) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
   AppendEmptyCluster(0);
 
   scoped_ptr<Cluster> cluster(GenerateCluster(0, 6));
@@ skipping 46 matching lines @@
 }
 
 TEST_F(ChunkDemuxerTest, ParseErrorDuringInit) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(
           kNoTimestamp(), PIPELINE_ERROR_DECODE), true);
 
   ASSERT_EQ(AddId(), ChunkDemuxer::kOk);
 
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   uint8_t tmp = 0;
   demuxer_->AppendData(kSourceId, &tmp, 1,
                        append_window_start_for_next_append_,
                        append_window_end_for_next_append_,
                        &timestamp_offset_map_[kSourceId],
                        init_segment_received_cb_);
 }
 
 TEST_F(ChunkDemuxerTest, AVHeadersWithAudioOnlyType) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kNoTimestamp(),
                                PIPELINE_ERROR_DECODE), true);
 
   std::vector<std::string> codecs(1);
   codecs[0] = "vorbis";
   ASSERT_EQ(demuxer_->AddId(kSourceId, "audio/webm", codecs),
             ChunkDemuxer::kOk);
 
+  // Video track is unexpected per mimetype.
+  EXPECT_MEDIA_LOG(InitSegmentMismatchesMimeType("a video", true));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   AppendInitSegment(HAS_AUDIO | HAS_VIDEO);
 }
 
 TEST_F(ChunkDemuxerTest, AVHeadersWithVideoOnlyType) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kNoTimestamp(),
                                PIPELINE_ERROR_DECODE), true);
 
   std::vector<std::string> codecs(1);
   codecs[0] = "vp8";
   ASSERT_EQ(demuxer_->AddId(kSourceId, "video/webm", codecs),
             ChunkDemuxer::kOk);
 
+  // Audio track is unexpected per mimetype.
+  EXPECT_MEDIA_LOG(InitSegmentMismatchesMimeType("an audio", true));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   AppendInitSegment(HAS_AUDIO | HAS_VIDEO);
 }
 
+TEST_F(ChunkDemuxerTest, AudioOnlyHeaderWithAVType) {
+  EXPECT_CALL(*this, DemuxerOpened());
+  demuxer_->Initialize(
+      &host_, CreateInitDoneCB(kNoTimestamp(), PIPELINE_ERROR_DECODE), true);
+
+  std::vector<std::string> codecs(2);
+  codecs[0] = "vorbis";
+  codecs[1] = "vp8";
+  ASSERT_EQ(demuxer_->AddId(kSourceId, "video/webm", codecs),
+            ChunkDemuxer::kOk);
+
+  // Video track is also expected per mimetype.
+  EXPECT_MEDIA_LOG(InitSegmentMismatchesMimeType("a video", false));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
+  AppendInitSegment(HAS_AUDIO);
+}
+
+TEST_F(ChunkDemuxerTest, VideoOnlyHeaderWithAVType) {
+  EXPECT_CALL(*this, DemuxerOpened());
+  demuxer_->Initialize(
+      &host_, CreateInitDoneCB(kNoTimestamp(), PIPELINE_ERROR_DECODE), true);
+
+  std::vector<std::string> codecs(2);
+  codecs[0] = "vorbis";
+  codecs[1] = "vp8";
+  ASSERT_EQ(demuxer_->AddId(kSourceId, "video/webm", codecs),
+            ChunkDemuxer::kOk);
+
+  // Audio track is also expected per mimetype.
+  EXPECT_MEDIA_LOG(InitSegmentMismatchesMimeType("an audio", false));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
+  AppendInitSegment(HAS_VIDEO);
+}
+
 TEST_F(ChunkDemuxerTest, MultipleHeaders) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
   AppendCluster(kDefaultFirstCluster());
 
   // Append another identical initialization segment.
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegment(HAS_AUDIO | HAS_VIDEO);
 
   AppendCluster(kDefaultSecondCluster());
@@ skipping 41 matching lines @@
       &host_, CreateInitDoneCB(kDefaultDuration(), PIPELINE_OK), true);
 
   std::string audio_id = "audio1";
   std::string video_id = "video1";
 
   ASSERT_EQ(AddId(audio_id, HAS_AUDIO), ChunkDemuxer::kOk);
 
   // Adding an id with audio/video should fail because we already added audio.
   ASSERT_EQ(AddId(), ChunkDemuxer::kReachedIdLimit);
 
+  ExpectInitMediaLogs(HAS_AUDIO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegmentWithSourceId(audio_id, HAS_AUDIO);
 
   // Adding an id after append should fail.
   ASSERT_EQ(AddId(video_id, HAS_VIDEO), ChunkDemuxer::kReachedIdLimit);
 }
 
 // Test that Read() calls after a RemoveId() return "end of stream" buffers.
 TEST_F(ChunkDemuxerTest, RemoveId) {
   std::string audio_id = "audio1";
@@ skipping 145 matching lines @@
   EXPECT_TRUE(video_read_done);
 }
 
 // Test that Seek() completes successfully when EndOfStream
 // is called before data is available for that seek point.
 // This scenario might be useful if seeking past the end of stream
 // of either audio or video (or both).
 TEST_F(ChunkDemuxerTest, EndOfStreamAfterPastEosSeek) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
-  AppendCluster(GenerateSingleStreamCluster(0, 120, kAudioTrackNum, 10));
-  AppendCluster(GenerateSingleStreamCluster(0, 100, kVideoTrackNum, 5));
+  AppendMuxedCluster(
+      MuxedStreamInfo(kAudioTrackNum,
+                      "0K 10K 20K 30K 40K 50K 60K 70K 80K 90K 100K 110K", 10),
+      MuxedStreamInfo(kVideoTrackNum, "0K 20K 40K 60K 80K", 20));
+  CheckExpectedRanges("{ [0,100) }");
 
   // Seeking past the end of video.
   // Note: audio data is available for that seek point.
   bool seek_cb_was_called = false;
   base::TimeDelta seek_time = base::TimeDelta::FromMilliseconds(110);
   demuxer_->StartWaitingForSeek(seek_time);
   demuxer_->Seek(seek_time,
                  base::Bind(OnSeekDone_OKExpected, &seek_cb_was_called));
   message_loop_.RunUntilIdle();
 
   EXPECT_FALSE(seek_cb_was_called);
 
   EXPECT_CALL(host_, SetDuration(
       base::TimeDelta::FromMilliseconds(120)));
   MarkEndOfStream(PIPELINE_OK);
   message_loop_.RunUntilIdle();
 
   EXPECT_TRUE(seek_cb_was_called);
 
   ShutdownDemuxer();
 }
 
 // Test that EndOfStream is ignored if coming during a pending seek
 // whose seek time is before some existing ranges.
 TEST_F(ChunkDemuxerTest, EndOfStreamDuringPendingSeek) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
-  AppendCluster(GenerateSingleStreamCluster(0, 120, kAudioTrackNum, 10));
-  AppendCluster(GenerateSingleStreamCluster(0, 100, kVideoTrackNum, 5));
-  AppendCluster(GenerateSingleStreamCluster(200, 300, kAudioTrackNum, 10));
-  AppendCluster(GenerateSingleStreamCluster(200, 300, kVideoTrackNum, 5));
+  AppendMuxedCluster(
+      MuxedStreamInfo(kAudioTrackNum,
+                      "0K 10K 20K 30K 40K 50K 60K 70K 80K 90K 100K 110K", 10),
+      MuxedStreamInfo(kVideoTrackNum, "0K 20K 40K 60K 80K", 20));
+  AppendMuxedCluster(
+      MuxedStreamInfo(kAudioTrackNum,
+                      "200K 210K 220K 230K 240K 250K 260K 270K 280K 290K", 10),
+      MuxedStreamInfo(kVideoTrackNum, "200K 220K 240K 260K 280K", 20));
 
   bool seek_cb_was_called = false;
   base::TimeDelta seek_time = base::TimeDelta::FromMilliseconds(160);
   demuxer_->StartWaitingForSeek(seek_time);
   demuxer_->Seek(seek_time,
                  base::Bind(OnSeekDone_OKExpected, &seek_cb_was_called));
   message_loop_.RunUntilIdle();
 
   EXPECT_FALSE(seek_cb_was_called);
 
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(300)));
   MarkEndOfStream(PIPELINE_OK);
   message_loop_.RunUntilIdle();
 
   EXPECT_FALSE(seek_cb_was_called);
 
   demuxer_->UnmarkEndOfStream();
 
-  AppendCluster(GenerateSingleStreamCluster(140, 180, kAudioTrackNum, 10));
-  AppendCluster(GenerateSingleStreamCluster(140, 180, kVideoTrackNum, 5));
+  AppendMuxedCluster(
+      MuxedStreamInfo(kAudioTrackNum, "140K 150K 160K 170K", 10),
+      MuxedStreamInfo(kVideoTrackNum, "140K 145K 150K 155K 160K 165K 170K 175K",
+                      20));
 
   message_loop_.RunUntilIdle();
 
   EXPECT_TRUE(seek_cb_was_called);
 
   ShutdownDemuxer();
 }
 
 // Test ranges in an audio-only stream.
 TEST_F(ChunkDemuxerTest, GetBufferedRanges_AudioIdOnly) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kDefaultDuration(), PIPELINE_OK), true);
 
   ASSERT_EQ(AddId(kSourceId, HAS_AUDIO), ChunkDemuxer::kOk);
+  ExpectInitMediaLogs(HAS_AUDIO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegment(HAS_AUDIO);
 
   // Test a simple cluster.
   AppendCluster(
       GenerateSingleStreamCluster(0, 92, kAudioTrackNum, kAudioBlockDuration));
 
   CheckExpectedRanges("{ [0,92) }");
 
   // Append a disjoint cluster to check for two separate ranges.
   AppendCluster(GenerateSingleStreamCluster(
       150, 219, kAudioTrackNum, kAudioBlockDuration));
 
   CheckExpectedRanges("{ [0,92) [150,219) }");
 }
 
 // Test ranges in a video-only stream.
 TEST_F(ChunkDemuxerTest, GetBufferedRanges_VideoIdOnly) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kDefaultDuration(), PIPELINE_OK), true);
 
   ASSERT_EQ(AddId(kSourceId, HAS_VIDEO), ChunkDemuxer::kOk);
+  ExpectInitMediaLogs(HAS_VIDEO);
   EXPECT_CALL(*this, InitSegmentReceived());
   AppendInitSegment(HAS_VIDEO);
 
   // Test a simple cluster.
   AppendCluster(
       GenerateSingleStreamCluster(0, 132, kVideoTrackNum, kVideoBlockDuration));
 
   CheckExpectedRanges("{ [0,132) }");
 
   // Append a disjoint cluster to check for two separate ranges.
@@ skipping 44 matching lines @@
 
   // Audio: 900 -> 970
   // Video: 920 -> 950
   // Buffered Range: 920 -> 950  (complete overlap, video)
   AppendCluster(GenerateSingleStreamCluster(900, 970, kAudioTrackNum, 70));
   AppendCluster(GenerateSingleStreamCluster(920, 950, kVideoTrackNum, 30));
 
   CheckExpectedRanges("{ [0,23) [320,400) [520,570) [720,750) [920,950) }");
 
   // Appending within buffered range should not affect buffered ranges.
-  AppendCluster(GenerateSingleStreamCluster(930, 950, kAudioTrackNum, 20));
-  CheckExpectedRanges("{ [0,23) [320,400) [520,570) [720,750) [920,950) }");

[chcunningham, 2016/01/14 19:11:23]

Did you mean to remove this CheckExpectedRanges?

[wolenetz, 2016/01/15 02:14:48]

Good catch. Fixed.

+  EXPECT_MEDIA_LOG(GeneratedSplice(40000, 930000));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "930D20K"),
+                     MuxedStreamInfo(kVideoTrackNum, "930D20K"));
 
   // Appending to single stream outside buffered ranges should not affect
   // buffered ranges.
   AppendCluster(GenerateSingleStreamCluster(1230, 1240, kVideoTrackNum, 10));
   CheckExpectedRanges("{ [0,23) [320,400) [520,570) [720,750) [920,950) }");
 }
 
 TEST_F(ChunkDemuxerTest, GetBufferedRanges_AudioVideoText) {
   EXPECT_CALL(host_, AddTextStream(_, _));
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO | HAS_TEXT));
 
   // Append audio & video data
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "0K 23K"),
-      MuxedStreamInfo(kVideoTrackNum, "0K 33"));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "0K 23K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "0K 33", 33));
 
   // Verify that a text track with no cues does not result in an empty buffered
   // range.
   CheckExpectedRanges("{ [0,46) }");
 
   // Add some text cues.
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "100K 123K"),
-      MuxedStreamInfo(kVideoTrackNum, "100K 133"),
-      MuxedStreamInfo(kTextTrackNum, "100K 200K"));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "100K 123K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "100K 133", 33),
+                     MuxedStreamInfo(kTextTrackNum, "100K 200K"));
 
   // Verify that the text cues are not reflected in the buffered ranges.
   CheckExpectedRanges("{ [0,46) [100,146) }");
 
   // Remove the buffered ranges.
   demuxer_->Remove(kSourceId, base::TimeDelta(),
                    base::TimeDelta::FromMilliseconds(250));
   CheckExpectedRanges("{ }");
 }
 
 // Once MarkEndOfStream() is called, GetBufferedRanges should not cut off any
 // over-hanging tails at the end of the ranges as this is likely due to block
 // duration differences.
 TEST_F(ChunkDemuxerTest, GetBufferedRanges_EndOfStream) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "0K 23K"),
-      MuxedStreamInfo(kVideoTrackNum, "0K 33"));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "0K 23K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "0K 33", 33));
 
   CheckExpectedRanges("{ [0,46) }");
 
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(66)));
   MarkEndOfStream(PIPELINE_OK);
 
   // Verify that the range extends to the end of the video data.
   CheckExpectedRanges("{ [0,66) }");
 
   // Verify that the range reverts to the intersection when end of stream
   // has been cancelled.
   demuxer_->UnmarkEndOfStream();
   CheckExpectedRanges("{ [0,46) }");
 
   // Append and remove data so that the 2 streams' end ranges do not overlap.
-
   EXPECT_CALL(host_, SetDuration(base::TimeDelta::FromMilliseconds(398)));
   AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "200K 223K"),
-      MuxedStreamInfo(kVideoTrackNum, "200K 233 266 299 332K 365"));
+      MuxedStreamInfo(kAudioTrackNum, "200K 223K", 23),
+      MuxedStreamInfo(kVideoTrackNum, "200K 233 266 299 332K 365", 33));
 
   // At this point, the per-stream ranges are as follows:
   // Audio: [0,46) [200,246)
   // Video: [0,66) [200,398)
   CheckExpectedRanges("{ [0,46) [200,246) }");
 
   demuxer_->Remove(kSourceId, base::TimeDelta::FromMilliseconds(200),
                    base::TimeDelta::FromMilliseconds(300));
 
   // At this point, the per-stream ranges are as follows:
   // Audio: [0,46)
   // Video: [0,66) [332,398)
   CheckExpectedRanges("{ [0,46) }");
 
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "200K 223K"),
-      MuxedStreamInfo(kVideoTrackNum, "200K 233"));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "200K 223K", 23),
+                     MuxedStreamInfo(kVideoTrackNum, "200K 233", 33));
 
   // At this point, the per-stream ranges are as follows:
   // Audio: [0,46) [200,246)
   // Video: [0,66) [200,266) [332,398)
   // NOTE: The last range on each stream do not overlap in time.
   CheckExpectedRanges("{ [0,46) [200,246) }");
 
   MarkEndOfStream(PIPELINE_OK);
 
   // NOTE: The last range on each stream gets extended to the highest
@@ skipping 393 matching lines @@
 
   // After ResetParserState(), parsing should no longer be in the middle of a
   // media segment.
   ASSERT_FALSE(demuxer_->IsParsingMediaSegment(kSourceId));
 }
 
 #if defined(USE_PROPRIETARY_CODECS)
 #if BUILDFLAG(ENABLE_MSE_MPEG2TS_STREAM_PARSER)
 TEST_F(ChunkDemuxerTest, EmitBuffersDuringAbort) {
   EXPECT_CALL(*this, DemuxerOpened());
+  EXPECT_MEDIA_LOG(FoundStream("audio"));
+  EXPECT_MEDIA_LOG(CodecName("audio", "aac"));
+  EXPECT_MEDIA_LOG(FoundStream("video"));
+  EXPECT_MEDIA_LOG(CodecName("video", "h264"));
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kInfiniteDuration(), PIPELINE_OK), true);
   EXPECT_EQ(ChunkDemuxer::kOk, AddIdForMp2tSource(kSourceId));
 
   // For info:
   // DTS/PTS derived using dvbsnoop -s ts -if bear-1280x720.ts -tssubdecode
   // Video: first PES:
   //        PTS: 126912 (0x0001efc0)  [= 90 kHz-Timestamp: 0:00:01.4101]
   //        DTS: 123909 (0x0001e405)  [= 90 kHz-Timestamp: 0:00:01.3767]
   // Audio: first PES:
@@ skipping 24 matching lines @@
       demuxer_->GetBufferedRanges(kSourceId);
 
   ASSERT_EQ(range_before_abort.size(), 1u);
   ASSERT_EQ(range_after_abort.size(), 1u);
   EXPECT_EQ(range_after_abort.start(0), range_before_abort.start(0));
   EXPECT_GT(range_after_abort.end(0), range_before_abort.end(0));
 }
 
 TEST_F(ChunkDemuxerTest, SeekCompleteDuringAbort) {
   EXPECT_CALL(*this, DemuxerOpened());
+  EXPECT_MEDIA_LOG(FoundStream("audio"));
+  EXPECT_MEDIA_LOG(CodecName("audio", "aac"));
+  EXPECT_MEDIA_LOG(FoundStream("video"));
+  EXPECT_MEDIA_LOG(CodecName("video", "h264"));
   demuxer_->Initialize(
       &host_, CreateInitDoneCB(kInfiniteDuration(), PIPELINE_OK), true);
   EXPECT_EQ(ChunkDemuxer::kOk, AddIdForMp2tSource(kSourceId));
 
   // For info:
   // DTS/PTS derived using dvbsnoop -s ts -if bear-1280x720.ts -tssubdecode
   // Video: first PES:
   //        PTS: 126912 (0x0001efc0)  [= 90 kHz-Timestamp: 0:00:01.4101]
   //        DTS: 123909 (0x0001e405)  [= 90 kHz-Timestamp: 0:00:01.3767]
   // Audio: first PES:
@@ skipping 235 matching lines @@
 TEST_F(ChunkDemuxerTest, SetMemoryLimitType) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
 
   // Set different memory limits for audio and video.
   demuxer_->SetMemoryLimits(DemuxerStream::AUDIO, 10 * kBlockSize);
   demuxer_->SetMemoryLimits(DemuxerStream::VIDEO, 5 * kBlockSize + 1);
 
   base::TimeDelta seek_time = base::TimeDelta::FromMilliseconds(1000);
 
   // Append data at the start that can be garbage collected:
-  AppendSingleStreamCluster(kSourceId, kAudioTrackNum, 0, 10);
-  AppendSingleStreamCluster(kSourceId, kVideoTrackNum, 0, 5);
+  AppendMuxedCluster(
+      MuxedStreamInfo(kAudioTrackNum,
+                      "0K 23K 46K 69K 92K 115K 138K 161K 184K 207K", 23),
+      MuxedStreamInfo(kVideoTrackNum, "0K 33K 66K 99K 132K", 33));
 
   // We should be right at buffer limit, should pass
   EXPECT_TRUE(demuxer_->EvictCodedFrames(
       kSourceId, base::TimeDelta::FromMilliseconds(0), 0));
 
   CheckExpectedRanges(DemuxerStream::AUDIO, "{ [0,230) }");
   CheckExpectedRanges(DemuxerStream::VIDEO, "{ [0,165) }");
 
   // Seek so we can garbage collect the data appended above.
   Seek(seek_time);
 
   // Append data at seek_time.
-  AppendSingleStreamCluster(kSourceId, kAudioTrackNum,
-                            seek_time.InMilliseconds(), 10);
-  AppendSingleStreamCluster(kSourceId, kVideoTrackNum,
-                            seek_time.InMilliseconds(), 5);
+  AppendMuxedCluster(
+      MuxedStreamInfo(
+          kAudioTrackNum,
+          "1000K 1023K 1046K 1069K 1092K 1115K 1138K 1161K 1184K 1207K", 23),
+      MuxedStreamInfo(kVideoTrackNum, "1000K 1033K 1066K 1099K 1132K", 33));
 
   // We should delete first append, and be exactly at buffer limit
   EXPECT_TRUE(demuxer_->EvictCodedFrames(kSourceId, seek_time, 0));
 
   // Verify that the old data, and nothing more, has been garbage collected.
   CheckExpectedRanges(DemuxerStream::AUDIO, "{ [1000,1230) }");
   CheckExpectedRanges(DemuxerStream::VIDEO, "{ [1000,1165) }");
 }
 
 TEST_F(ChunkDemuxerTest, GCDuringSeek_SingleRange_SeekForward) {
@@ skipping 203 matching lines @@
 
 TEST_F(ChunkDemuxerTest, AppendWindow_Video) {
   ASSERT_TRUE(InitDemuxer(HAS_VIDEO));
   DemuxerStream* stream = demuxer_->GetStream(DemuxerStream::VIDEO);
 
   // Set the append window to [50,280).
   append_window_start_for_next_append_ = base::TimeDelta::FromMilliseconds(50);
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(280);
 
   // Append a cluster that starts before and ends after the append window.
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(30));
   AppendSingleStreamCluster(kSourceId, kVideoTrackNum,
                             "0K 30 60 90 120K 150 180 210 240K 270 300 330K");
 
   // Verify that GOPs that start outside the window are not included
   // in the buffer. Also verify that buffers that start inside the
   // window and extend beyond the end of the window are not included.
   CheckExpectedRanges(kSourceId, "{ [120,270) }");
   CheckExpectedBuffers(stream, "120K 150 180 210 240K");
 
   // Extend the append window to [50,650).
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(650);
 
   // Append more data and verify that adding buffers start at the next
   // key frame.
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(30));
   AppendSingleStreamCluster(kSourceId, kVideoTrackNum,
                             "360 390 420K 450 480 510 540K 570 600 630K");
   CheckExpectedRanges(kSourceId, "{ [120,270) [420,630) }");
 }
 
 TEST_F(ChunkDemuxerTest, AppendWindow_Audio) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO));
   DemuxerStream* stream = demuxer_->GetStream(DemuxerStream::AUDIO);
 
   // Set the append window to [50,280).
   append_window_start_for_next_append_ = base::TimeDelta::FromMilliseconds(50);
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(280);
 
   // Append a cluster that starts before and ends after the append window.
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(30));
   AppendSingleStreamCluster(
       kSourceId, kAudioTrackNum,
       "0K 30K 60K 90K 120K 150K 180K 210K 240K 270K 300K 330K");
 
   // Verify that frames that end outside the window are not included
   // in the buffer. Also verify that buffers that start inside the
   // window and extend beyond the end of the window are not included.
   //
   // The first 50ms of the range should be truncated since it overlaps
   // the start of the append window.
   CheckExpectedRanges(kSourceId, "{ [50,280) }");
 
   // The "50P" buffer is the "0" buffer marked for complete discard.  The next
   // "50" buffer is the "30" buffer marked with 20ms of start discard.
   CheckExpectedBuffers(stream, "50KP 50K 60K 90K 120K 150K 180K 210K 240K");
 
   // Extend the append window to [50,650).
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(650);
 
   // Append more data and verify that a new range is created.
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(30));
   AppendSingleStreamCluster(
       kSourceId, kAudioTrackNum,
       "360K 390K 420K 450K 480K 510K 540K 570K 600K 630K");
   CheckExpectedRanges(kSourceId, "{ [50,280) [360,650) }");
 }
 
 TEST_F(ChunkDemuxerTest, AppendWindow_AudioOverlapStartAndEnd) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO));
 
   // Set the append window to [10,20).
   append_window_start_for_next_append_ = base::TimeDelta::FromMilliseconds(10);
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(20);
 
   // Append a cluster that starts before and ends after the append window.
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(
+      WebMClusterParser::kDefaultAudioBufferDurationInMs));
   AppendSingleStreamCluster(kSourceId, kAudioTrackNum, "0K");
 
   // Verify the append is clipped to the append window.
   CheckExpectedRanges(kSourceId, "{ [10,20) }");
 }
 
 TEST_F(ChunkDemuxerTest, AppendWindow_WebMFile_AudioOnly) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_,
       CreateInitDoneCB(base::TimeDelta::FromMilliseconds(2744), PIPELINE_OK),
       true);
   ASSERT_EQ(ChunkDemuxer::kOk, AddId(kSourceId, HAS_AUDIO));
 
   // Set the append window to [50,150).
   append_window_start_for_next_append_ = base::TimeDelta::FromMilliseconds(50);
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(150);
 
   // Read a WebM file into memory and send the data to the demuxer.  The chunk
   // size has been chosen carefully to ensure the preroll buffer used by the
   // partial append window trim must come from a previous Append() call.
   scoped_refptr<DecoderBuffer> buffer =
       ReadTestDataFile("bear-320x240-audio-only.webm");
+  ExpectInitMediaLogs(HAS_AUDIO);
   EXPECT_CALL(*this, InitSegmentReceived());
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2));
   AppendDataInPieces(buffer->data(), buffer->data_size(), 128);
 
   DemuxerStream* stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   CheckExpectedBuffers(stream, "50KP 50K 62K 86K 109K 122K 125K 128K");
 }
 
 TEST_F(ChunkDemuxerTest, AppendWindow_AudioConfigUpdateRemovesPreroll) {
   EXPECT_CALL(*this, DemuxerOpened());
   demuxer_->Initialize(
       &host_,
       CreateInitDoneCB(base::TimeDelta::FromMilliseconds(2744), PIPELINE_OK),
       true);
   ASSERT_EQ(ChunkDemuxer::kOk, AddId(kSourceId, HAS_AUDIO));
 
   // Set the append window such that the first file is completely before the
   // append window.
   // Expect duration adjustment since actual duration differs slightly from
   // duration in the init segment.
   const base::TimeDelta duration_1 = base::TimeDelta::FromMilliseconds(2746);
   append_window_start_for_next_append_ = duration_1;
 
   // Read a WebM file into memory and append the data.
   scoped_refptr<DecoderBuffer> buffer =
       ReadTestDataFile("bear-320x240-audio-only.webm");
+  ExpectInitMediaLogs(HAS_AUDIO);
   EXPECT_CALL(*this, InitSegmentReceived());
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(2));
   AppendDataInPieces(buffer->data(), buffer->data_size(), 512);
   CheckExpectedRanges(kSourceId, "{ }");
 
   DemuxerStream* stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   AudioDecoderConfig config_1 = stream->audio_decoder_config();
 
   // Read a second WebM with a different config in and append the data.
   scoped_refptr<DecoderBuffer> buffer2 =
       ReadTestDataFile("bear-320x240-audio-only-48khz.webm");
   EXPECT_CALL(*this, InitSegmentReceived());
+  EXPECT_MEDIA_LOG(WebMSimpleBlockDurationEstimated(21));
   EXPECT_CALL(host_, SetDuration(_)).Times(AnyNumber());
   ASSERT_TRUE(SetTimestampOffset(kSourceId, duration_1));
   AppendDataInPieces(buffer2->data(), buffer2->data_size(), 512);
   CheckExpectedRanges(kSourceId, "{ [2746,5519) }");
 
   Seek(duration_1);
   ExpectConfigChanged(DemuxerStream::AUDIO);
   ASSERT_FALSE(config_1.Matches(stream->audio_decoder_config()));
   CheckExpectedBuffers(stream, "2746K 2767K 2789K 2810K");
 }
 
 TEST_F(ChunkDemuxerTest, AppendWindow_Text) {
   DemuxerStream* text_stream = NULL;
   EXPECT_CALL(host_, AddTextStream(_, _))
       .WillOnce(SaveArg<0>(&text_stream));
   ASSERT_TRUE(InitDemuxer(HAS_VIDEO | HAS_TEXT));
   DemuxerStream* video_stream = demuxer_->GetStream(DemuxerStream::VIDEO);
 
   // Set the append window to [20,280).
   append_window_start_for_next_append_ = base::TimeDelta::FromMilliseconds(20);
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(280);
 
   // Append a cluster that starts before and ends after the append
   // window.
   AppendMuxedCluster(
       MuxedStreamInfo(kVideoTrackNum,
-                      "0K 30 60 90 120K 150 180 210 240K 270 300 330K"),
-      MuxedStreamInfo(kTextTrackNum, "0K 100K 200K 300K" ));
+                      "0K 30 60 90 120K 150 180 210 240K 270 300 330K", 30),
+      MuxedStreamInfo(kTextTrackNum, "0K 100K 200K 300K"));
 
   // Verify that text cues that start outside the window are not included
   // in the buffer. Also verify that cues that extend beyond the
   // window are not included.
   CheckExpectedRanges(kSourceId, "{ [100,270) }");
   CheckExpectedBuffers(video_stream, "120K 150 180 210 240K");
   CheckExpectedBuffers(text_stream, "100K");
 
   // Extend the append window to [20,650).
   append_window_end_for_next_append_ = base::TimeDelta::FromMilliseconds(650);
 
   // Append more data and verify that a new range is created.
   AppendMuxedCluster(
       MuxedStreamInfo(kVideoTrackNum,
-                      "360 390 420K 450 480 510 540K 570 600 630K"),
-      MuxedStreamInfo(kTextTrackNum, "400K 500K 600K 700K" ));
-  CheckExpectedRanges(kSourceId, "{ [100,270) [400,630) }");
+                      "360 390 420K 450 480 510 540K 570 600 630K", 30),
+      MuxedStreamInfo(kTextTrackNum, "400K 500K 600K 700K"));
+  CheckExpectedRanges("{ [100,270) [400,630) }");
 
   // Seek to the new range and verify that the expected buffers are returned.
   Seek(base::TimeDelta::FromMilliseconds(420));
   CheckExpectedBuffers(video_stream, "420K 450 480 510 540K 570 600");
   CheckExpectedBuffers(text_stream, "400K 500K");
 }
 
 TEST_F(ChunkDemuxerTest, StartWaitingForSeekAfterParseError) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO));
+  EXPECT_MEDIA_LOG(StreamParsingFailed());
   EXPECT_CALL(host_, OnDemuxerError(PIPELINE_ERROR_DECODE));
   AppendGarbage();
   base::TimeDelta seek_time = base::TimeDelta::FromSeconds(50);
   demuxer_->StartWaitingForSeek(seek_time);
 }
 
 TEST_F(ChunkDemuxerTest, Remove_AudioVideoText) {
   DemuxerStream* text_stream = NULL;
   EXPECT_CALL(host_, AddTextStream(_, _))
       .WillOnce(SaveArg<0>(&text_stream));
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO | HAS_VIDEO | HAS_TEXT));
 
   DemuxerStream* audio_stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   DemuxerStream* video_stream = demuxer_->GetStream(DemuxerStream::VIDEO);
 
   AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "0K 20K 40K 60K 80K 100K 120K 140K"),
-      MuxedStreamInfo(kVideoTrackNum, "0K 30 60 90 120K 150 180"),
+      MuxedStreamInfo(kAudioTrackNum, "0K 20K 40K 60K 80K 100K 120K 140K", 20),
+      MuxedStreamInfo(kVideoTrackNum, "0K 30 60 90 120K 150 180", 30),
       MuxedStreamInfo(kTextTrackNum, "0K 100K 200K"));
 
   CheckExpectedBuffers(audio_stream, "0K 20K 40K 60K 80K 100K 120K 140K");
   CheckExpectedBuffers(video_stream, "0K 30 60 90 120K 150 180");
   CheckExpectedBuffers(text_stream, "0K 100K 200K");
 
   // Remove the buffers that were added.
   demuxer_->Remove(kSourceId, base::TimeDelta(),
                    base::TimeDelta::FromMilliseconds(300));
 
   // Verify that all the appended data has been removed.
   CheckExpectedRanges(kSourceId, "{ }");
 
   // Append new buffers that are clearly different than the original
   // ones and verify that only the new buffers are returned.
   AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "1K 21K 41K 61K 81K 101K 121K 141K"),
-      MuxedStreamInfo(kVideoTrackNum, "1K 31 61 91 121K 151 181"),
+      MuxedStreamInfo(kAudioTrackNum, "1K 21K 41K 61K 81K 101K 121K 141K", 20),
+      MuxedStreamInfo(kVideoTrackNum, "1K 31 61 91 121K 151 181", 30),
       MuxedStreamInfo(kTextTrackNum, "1K 101K 201K"));
 
   Seek(base::TimeDelta());
   CheckExpectedBuffers(audio_stream, "1K 21K 41K 61K 81K 101K 121K 141K");
   CheckExpectedBuffers(video_stream, "1K 31 61 91 121K 151 181");
   CheckExpectedBuffers(text_stream, "1K 101K 201K");
 }
 
 TEST_F(ChunkDemuxerTest, Remove_StartAtDuration) {
   ASSERT_TRUE(InitDemuxer(HAS_AUDIO));
   DemuxerStream* audio_stream = demuxer_->GetStream(DemuxerStream::AUDIO);
 
   // Set the duration to something small so that the append that
   // follows updates the duration to reflect the end of the appended data.
   EXPECT_CALL(host_, SetDuration(
       base::TimeDelta::FromMilliseconds(1)));
   demuxer_->SetDuration(0.001);
 
   EXPECT_CALL(host_, SetDuration(
       base::TimeDelta::FromMilliseconds(160)));
   AppendSingleStreamCluster(kSourceId, kAudioTrackNum,
-                            "0K 20K 40K 60K 80K 100K 120K 140K");
+                            "0K 20K 40K 60K 80K 100K 120K 140D20K");
 
   CheckExpectedRanges(kSourceId, "{ [0,160) }");
   CheckExpectedBuffers(audio_stream, "0K 20K 40K 60K 80K 100K 120K 140K");
 
   demuxer_->Remove(kSourceId,
                    base::TimeDelta::FromSecondsD(demuxer_->GetDuration()),
                    kInfiniteDuration());
 
   Seek(base::TimeDelta());
   CheckExpectedRanges(kSourceId, "{ [0,160) }");
@@ skipping 22 matching lines @@
   EXPECT_FALSE(seek_cb_was_called);
 
   bool text_read_done = false;
   text_stream->Read(base::Bind(&OnReadDone,
                                base::TimeDelta::FromMilliseconds(225),
                                &text_read_done));
 
   // Append audio & video data so the seek completes.
   AppendMuxedCluster(
       MuxedStreamInfo(kAudioTrackNum,
-                      "0K 20K 40K 60K 80K 100K 120K 140K 160K 180K 200K"),
-      MuxedStreamInfo(kVideoTrackNum, "0K 30 60 90 120K 150 180 210"));
+                      "0K 20K 40K 60K 80K 100K 120K 140K 160K 180K 200K", 20),
+      MuxedStreamInfo(kVideoTrackNum, "0K 30 60 90 120K 150 180 210", 30));
 
   message_loop_.RunUntilIdle();
   EXPECT_TRUE(seek_cb_was_called);
   EXPECT_FALSE(text_read_done);
 
   // Read some audio & video buffers to further verify seek completion.
   CheckExpectedBuffers(audio_stream, "120K 140K");
   CheckExpectedBuffers(video_stream, "120K 150");
 
   EXPECT_FALSE(text_read_done);
 
   // Append text cues that start after the seek point and verify that
   // they are returned by Read() calls.
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, "220K 240K 260K 280K"),
-      MuxedStreamInfo(kVideoTrackNum, "240K 270 300 330"),
-      MuxedStreamInfo(kTextTrackNum, "225K 275K 325K"));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, "220K 240K 260K 280K", 20),
+                     MuxedStreamInfo(kVideoTrackNum, "240K 270 300 330", 30),
+                     MuxedStreamInfo(kTextTrackNum, "225K 275K 325K"));
 
   message_loop_.RunUntilIdle();
   EXPECT_TRUE(text_read_done);
 
   // NOTE: we start at 275 here because the buffer at 225 was returned
   // to the pending read initiated above.
   CheckExpectedBuffers(text_stream, "275K 325K");
 
   // Verify that audio & video streams continue to return expected values.
   CheckExpectedBuffers(audio_stream, "160K 180K");
@@ skipping 39 matching lines @@
   demuxer_->SetMemoryLimits(DemuxerStream::AUDIO, 10 * kBlockSize);
   demuxer_->SetMemoryLimits(DemuxerStream::VIDEO, 15 * kBlockSize);
   DemuxerStream* audio_stream = demuxer_->GetStream(DemuxerStream::AUDIO);
   DemuxerStream* video_stream = demuxer_->GetStream(DemuxerStream::VIDEO);
 
   const char* kAudioStreamInfo = "0K 40K 80K 120K 160K 200K 240K 280K";
   const char* kVideoStreamInfo = "0K 10 20K 30 40K 50 60K 70 80K 90 100K "
       "110 120K 130 140K";
   // Append 8 blocks (80 bytes) of data to audio stream and 15 blocks (150
   // bytes) to video stream.
-  AppendMuxedCluster(
-      MuxedStreamInfo(kAudioTrackNum, kAudioStreamInfo),
-      MuxedStreamInfo(kVideoTrackNum, kVideoStreamInfo));
+  AppendMuxedCluster(MuxedStreamInfo(kAudioTrackNum, kAudioStreamInfo, 40),
+                     MuxedStreamInfo(kVideoTrackNum, kVideoStreamInfo, 10));
   CheckExpectedBuffers(audio_stream, kAudioStreamInfo);
   CheckExpectedBuffers(video_stream, kVideoStreamInfo);
 
   // If we want to append 80 more blocks of muxed a+v data and the current
   // position is 0, that will fail, because EvictCodedFrames won't remove the
   // data after the current playback position.
   ASSERT_FALSE(demuxer_->EvictCodedFrames(kSourceId,
                                           base::TimeDelta::FromMilliseconds(0),
                                           80));
   // EvictCodedFrames has failed, so data should be unchanged.
@@ skipping 17 matching lines @@
   // audio size is 80 bytes, new data is 28 bytes, we need to remove just one 10
   // byte block to stay under 100 bytes memory limit after append
   // 80 - 10 + 28 = 98).
   // For video stream 150 + 52 = 202. Video limit is 150 bytes. We need to
   // remove at least 6 blocks to stay under limit.
   CheckExpectedBuffers(audio_stream, "40K 80K 120K 160K 200K 240K 280K");
   CheckExpectedBuffers(video_stream, "60K 70 80K 90 100K 110 120K 130 140K");
 }
 
 }  // namespace media