MSE: Verify MediaLog events created by existing WebM unit tests

media/formats/webm/webm_cluster_parser_unittest.cc

 // Copyright 2014 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 <algorithm>
 #include <cstdlib>
+#include <string>
 #include <vector>
 
 #include "base/bind.h"
 #include "base/logging.h"
+#include "base/strings/string_number_conversions.h"
 #include "media/base/audio_decoder_config.h"
 #include "media/base/decrypt_config.h"
+#include "media/base/mock_media_log.h"
 #include "media/formats/webm/cluster_builder.h"
 #include "media/formats/webm/opus_packet_builder.h"
 #include "media/formats/webm/webm_cluster_parser.h"
 #include "media/formats/webm/webm_constants.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
+using ::testing::HasSubstr;
 using ::testing::InSequence;
 using ::testing::Return;
+using ::testing::StrictMock;
 using ::testing::_;
 
 namespace media {
 
 typedef WebMTracksParser::TextTracks TextTracks;
 
+// Matchers for verifying common media log entry strings.
+#define CONTAINS_STRING(arg, x) (std::string::npos != (arg).find(x))
+
+MATCHER_P(OpusPacketDurationTooHigh, actual_duration_ms, "") {
+  return CONTAINS_STRING(
+      arg, "Warning, demuxed Opus packet with encoded duration: " +
+               base::IntToString(actual_duration_ms) +
+               "ms. Should be no greater than 120ms.");
+}
+
+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_P2(WebMBlockDurationMismatchesOpusDuration,
+           block_duration_ms,
+           opus_duration_ms,
+           "") {
+  return CONTAINS_STRING(
+      arg, "BlockDuration (" + base::IntToString(block_duration_ms) +
+               "ms) differs significantly from encoded duration (" +
+               base::IntToString(opus_duration_ms) + "ms).");
+}
+
 namespace {
 
-enum {
-  kTimecodeScale = 1000000,  // Timecode scale for millisecond timestamps.
-  kAudioTrackNum = 1,
-  kVideoTrackNum = 2,
-  kTextTrackNum = 3,
-  kTestAudioFrameDefaultDurationInMs = 13,
-  kTestVideoFrameDefaultDurationInMs = 17
-};
+// Timecode scale for millisecond timestamps.
+const int kTimecodeScale = 1000000;

[wolenetz, 2015/08/18 21:13:48]

This is just drive-by opportunistic style correction ;)

+
+const int kAudioTrackNum = 1;
+const int kVideoTrackNum = 2;
+const int kTextTrackNum = 3;
+const int kTestAudioFrameDefaultDurationInMs = 13;
+const int kTestVideoFrameDefaultDurationInMs = 17;
 
 // Test duration defaults must differ from parser estimation defaults to know
 // which durations parser used when emitting buffers.
 static_assert(
     static_cast<int>(kTestAudioFrameDefaultDurationInMs) !=
         static_cast<int>(WebMClusterParser::kDefaultAudioBufferDurationInMs),
     "test default is the same as estimation fallback audio duration");
 static_assert(
     static_cast<int>(kTestVideoFrameDefaultDurationInMs) !=
         static_cast<int>(WebMClusterParser::kDefaultVideoBufferDurationInMs),
@@ skipping 28 matching lines @@
     {kVideoTrackNum, 100, 33, false, NULL, 0},
 };
 
 const uint8_t kEncryptedFrame[] = {
     // Block is encrypted
     0x01,
 
     // IV
     0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08};
 
-// Helper that hard-codes some non-varying constructor parameters.
-WebMClusterParser* CreateParserHelper(
-    base::TimeDelta audio_default_duration,
-    base::TimeDelta video_default_duration,
-    const WebMTracksParser::TextTracks& text_tracks,
-    const std::set<int64>& ignored_tracks,
-    const std::string& audio_encryption_key_id,
-    const std::string& video_encryption_key_id,
-    const AudioCodec audio_codec) {
-  return new WebMClusterParser(
-      kTimecodeScale, kAudioTrackNum, audio_default_duration, kVideoTrackNum,
-      video_default_duration, text_tracks, ignored_tracks,
-      audio_encryption_key_id, video_encryption_key_id, audio_codec,
-      new MediaLog());
-}
-
-// Create a default version of the parser for test.
-WebMClusterParser* CreateDefaultParser() {
-  return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
-                            std::set<int64>(), std::string(), std::string(),
-                            kUnknownAudioCodec);
-}
-
-// Create a parser for test with custom audio and video default durations, and
-// optionally custom text tracks.
-WebMClusterParser* CreateParserWithDefaultDurationsAndOptionalTextTracks(
-    base::TimeDelta audio_default_duration,
-    base::TimeDelta video_default_duration,
-    const WebMTracksParser::TextTracks& text_tracks = TextTracks()) {
-  return CreateParserHelper(audio_default_duration, video_default_duration,
-                            text_tracks, std::set<int64>(), std::string(),
-                            std::string(), kUnknownAudioCodec);
-}
-
-// Create a parser for test with custom ignored tracks.
-WebMClusterParser* CreateParserWithIgnoredTracks(
-    std::set<int64>& ignored_tracks) {
-  return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
-                            ignored_tracks, std::string(), std::string(),
-                            kUnknownAudioCodec);
-}
-
-// Create a parser for test with custom encryption key ids and audio codec.
-WebMClusterParser* CreateParserWithKeyIdsAndAudioCodec(
-    const std::string& audio_encryption_key_id,
-    const std::string& video_encryption_key_id,
-    const AudioCodec audio_codec) {
-  return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
-                            std::set<int64>(), audio_encryption_key_id,
-                            video_encryption_key_id, audio_codec);
-}
-
 scoped_ptr<Cluster> CreateCluster(int timecode,
                                   const BlockInfo* block_info,
                                   int block_count) {
   ClusterBuilder cb;
   cb.SetClusterTimecode(0);
 
   uint8_t kDefaultBlockData[] = { 0x00 };
 
   for (int i = 0; i < block_count; i++) {
     const uint8_t* data;
@@ skipping 158 matching lines @@
   for (WebMClusterParser::BufferQueue::const_iterator itr = src.begin();
        itr != src.end(); ++itr) {
     dest->push_back(*itr);
   }
 }
 
 }  // namespace
 
 class WebMClusterParserTest : public testing::Test {
  public:
-  WebMClusterParserTest() : parser_(CreateDefaultParser()) {}
+  WebMClusterParserTest()
+      : media_log_(new StrictMock<MockMediaLog>()),
+        parser_(CreateDefaultParser()) {}
 
  protected:
   void ResetParserToHaveDefaultDurations() {
     base::TimeDelta default_audio_duration = base::TimeDelta::FromMilliseconds(
         kTestAudioFrameDefaultDurationInMs);
     base::TimeDelta default_video_duration = base::TimeDelta::FromMilliseconds(
         kTestVideoFrameDefaultDurationInMs);
     ASSERT_GE(default_audio_duration, base::TimeDelta());
     ASSERT_GE(default_video_duration, base::TimeDelta());
     ASSERT_NE(kNoTimestamp(), default_audio_duration);
     ASSERT_NE(kNoTimestamp(), default_video_duration);
 
     parser_.reset(CreateParserWithDefaultDurationsAndOptionalTextTracks(
         default_audio_duration, default_video_duration));
   }
 
+  // Helper that hard-codes some non-varying constructor parameters.

[wolenetz, 2015/08/18 21:13:48]

I moved these to be instance methods so they have access to |media_log_| without
adding yet another parameter to each of these functions.

+  WebMClusterParser* CreateParserHelper(
+      base::TimeDelta audio_default_duration,
+      base::TimeDelta video_default_duration,
+      const WebMTracksParser::TextTracks& text_tracks,
+      const std::set<int64>& ignored_tracks,
+      const std::string& audio_encryption_key_id,
+      const std::string& video_encryption_key_id,
+      const AudioCodec audio_codec) {
+    return new WebMClusterParser(
+        kTimecodeScale, kAudioTrackNum, audio_default_duration, kVideoTrackNum,
+        video_default_duration, text_tracks, ignored_tracks,
+        audio_encryption_key_id, video_encryption_key_id, audio_codec,
+        media_log_);
+  }
+
+  // Create a default version of the parser for test.
+  WebMClusterParser* CreateDefaultParser() {
+    return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
+                              std::set<int64>(), std::string(), std::string(),
+                              kUnknownAudioCodec);
+  }
+
+  // Create a parser for test with custom audio and video default durations, and
+  // optionally custom text tracks.
+  WebMClusterParser* CreateParserWithDefaultDurationsAndOptionalTextTracks(
+      base::TimeDelta audio_default_duration,
+      base::TimeDelta video_default_duration,
+      const WebMTracksParser::TextTracks& text_tracks = TextTracks()) {
+    return CreateParserHelper(audio_default_duration, video_default_duration,
+                              text_tracks, std::set<int64>(), std::string(),
+                              std::string(), kUnknownAudioCodec);
+  }
+
+  // Create a parser for test with custom ignored tracks.
+  WebMClusterParser* CreateParserWithIgnoredTracks(
+      std::set<int64>& ignored_tracks) {
+    return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
+                              ignored_tracks, std::string(), std::string(),
+                              kUnknownAudioCodec);
+  }
+
+  // Create a parser for test with custom encryption key ids and audio codec.
+  WebMClusterParser* CreateParserWithKeyIdsAndAudioCodec(
+      const std::string& audio_encryption_key_id,
+      const std::string& video_encryption_key_id,
+      const AudioCodec audio_codec) {
+    return CreateParserHelper(kNoTimestamp(), kNoTimestamp(), TextTracks(),
+                              std::set<int64>(), audio_encryption_key_id,
+                              video_encryption_key_id, audio_codec);
+  }
+
+  scoped_refptr<StrictMock<MockMediaLog>> media_log_;
   scoped_ptr<WebMClusterParser> parser_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(WebMClusterParserTest);
 };
 
 TEST_F(WebMClusterParserTest, HeldBackBufferHoldsBackAllTracks) {
   // If a buffer is missing duration and is being held back, then all other
   // tracks' buffers that have same or higher (decode) timestamp should be held
   // back too to keep the timestamps emitted for a cluster monotonically
   // non-decreasing and in same order as parsed.
   InSequence s;
 
   // Reset the parser to have 3 tracks: text, video (no default frame duration),
   // and audio (with a default frame duration).
   TextTracks text_tracks;
   text_tracks.insert(std::make_pair(TextTracks::key_type(kTextTrackNum),
                                     TextTrackConfig(kTextSubtitles, "", "",
                                                     "")));
   base::TimeDelta default_audio_duration =
       base::TimeDelta::FromMilliseconds(kTestAudioFrameDefaultDurationInMs);
   ASSERT_GE(default_audio_duration, base::TimeDelta());
   ASSERT_NE(kNoTimestamp(), default_audio_duration);
   parser_.reset(CreateParserWithDefaultDurationsAndOptionalTextTracks(
       default_audio_duration, kNoTimestamp(), text_tracks));
 
+  const int kExpectedLastVideoBufferEstimatedDurationInMs = 33;

[xhwang, 2015/08/19 00:25:05]

I am a bit lost here. Why this one is special and needs a constant while we
still use hardcoded numbers for others? Same question for 
kExpectedLastAudioBufferEstimatedDurationInMs and
kExpectedLastVideoBufferEstimatedDurationInMs below.

Also, the variable name is really long :(

[wolenetz, 2015/08/24 19:34:02]

I'll simplify the name. All 33ms hard-code for kVideoTrackNum frame duration
verification in kBlockInfo[] could be replaced with this identifier, but I
wanted to make it clear which frame, exactly, this 33ms estimate was to be
determined for, hence I used it only for the last video track block in
kBlockInfo[]. The previous video blocks' durations are derived from inter-block
timestamp deltas. This last block's duration is estimated based on previously
seen durations (which in this case, but not all the ones in this file, all are
33).

Since this CL adds media log string verification of the estimation calculation,
the last (video track in this case) buffer's duration expectation from
kBlockInfo is verified in two places now, so I added a named constant to help
future maintenance/readability of this test.

This same pattern is adhered to (sometimes for audio track) in other updated
tests in this CL.

+
   const BlockInfo kBlockInfo[] = {
       {kVideoTrackNum, 0, 33, true, NULL, 0},
       {kAudioTrackNum, 0, 23, false, NULL, 0},
       {kTextTrackNum, 10, 42, false, NULL, 0},
       {kAudioTrackNum, 23, kTestAudioFrameDefaultDurationInMs, true, NULL, 0},
       {kVideoTrackNum, 33, 33, true, NULL, 0},
       {kAudioTrackNum, 36, kTestAudioFrameDefaultDurationInMs, true, NULL, 0},
-      {kVideoTrackNum, 66, 33, true, NULL, 0},
+      {kVideoTrackNum, 66, kExpectedLastVideoBufferEstimatedDurationInMs, true,
+       NULL, 0},
       {kAudioTrackNum, 70, kTestAudioFrameDefaultDurationInMs, true, NULL, 0},
       {kAudioTrackNum, 83, kTestAudioFrameDefaultDurationInMs, true, NULL, 0},
   };
 
   const int kExpectedBuffersOnPartialCluster[] = {
     0,  // Video simple block without DefaultDuration should be held back
     0,  // Audio buffer ready, but not emitted because its TS >= held back video
     0,  // Text buffer ready, but not emitted because its TS >= held back video
     0,  // 2nd audio buffer ready, also not emitted for same reason as first
     4,  // All previous buffers emitted, 2nd video held back with no duration
@@ skipping 16 matching lines @@
       parser_->Reset();
     // Since we don't know exactly the offsets of each block in the full
     // cluster, build a cluster with exactly one additional block so that
     // parse of all but one byte should deterministically parse all but the
     // last full block. Don't |exceed block_count| blocks though.
     int blocks_in_cluster = std::min(i + 2, block_count);
     scoped_ptr<Cluster> cluster(CreateCluster(0, kBlockInfo,
                                               blocks_in_cluster));
     // Parse all but the last byte unless we need to parse the full cluster.
     bool parse_full_cluster = i == (block_count - 1);
+
+    if (parse_full_cluster) {
+      EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+          kExpectedLastVideoBufferEstimatedDurationInMs));
+    }
+
     int result = parser_->Parse(cluster->data(), parse_full_cluster ?
                                 cluster->size() : cluster->size() - 1);
     if (parse_full_cluster) {
       DVLOG(1) << "Verifying parse result of full cluster of "
                << blocks_in_cluster << " blocks";
       EXPECT_EQ(cluster->size(), result);
     } else {
       DVLOG(1) << "Verifying parse result of cluster of "
                << blocks_in_cluster << " blocks with last block incomplete";
       EXPECT_GT(cluster->size(), result);
@@ skipping 141 matching lines @@
       {kAudioTrackNum, 23, 23, true, NULL, 0},
       {kVideoTrackNum, 33, 34, true, NULL, 0},
       {kAudioTrackNum, 46, 23, true, NULL, 0},
       {kVideoTrackNum, 67, 34, true, NULL, 0},
   };
   int output_block_count = arraysize(kOutputBlockInfo);
 
   scoped_ptr<Cluster> cluster(
       CreateCluster(0, kInputBlockInfo, input_block_count));
 
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(23));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(34));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kOutputBlockInfo, output_block_count));
 }
 
 TEST_F(WebMClusterParserTest, ParseTextTracks) {
   TextTracks text_tracks;
 
   text_tracks.insert(std::make_pair(TextTracks::key_type(kTextTrackNum),
                                     TextTrackConfig(kTextSubtitles, "", "",
                                                     "")));
 
   parser_.reset(CreateParserWithDefaultDurationsAndOptionalTextTracks(
       kNoTimestamp(), kNoTimestamp(), text_tracks));
 
   const BlockInfo kInputBlockInfo[] = {
       {kAudioTrackNum, 0, 23, true, NULL, 0},
       {kAudioTrackNum, 23, 23, true, NULL, 0},
       {kVideoTrackNum, 33, 34, true, NULL, 0},
       {kTextTrackNum, 33, 42, false, NULL, 0},
       {kAudioTrackNum, 46, 23, true, NULL, 0},
       {kTextTrackNum, 55, 44, false, NULL, 0},
       {kVideoTrackNum, 67, 34, true, NULL, 0},
   };
   int input_block_count = arraysize(kInputBlockInfo);
 
   scoped_ptr<Cluster> cluster(
       CreateCluster(0, kInputBlockInfo, input_block_count));
 
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(23));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(34));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kInputBlockInfo, input_block_count));
 }
 
 TEST_F(WebMClusterParserTest, TextTracksSimpleBlock) {
   TextTracks text_tracks;
 
   text_tracks.insert(std::make_pair(TextTracks::key_type(kTextTrackNum),
                                     TextTrackConfig(kTextSubtitles, "", "",
@@ skipping 39 matching lines @@
       {kAudioTrackNum, 46, 23, true, NULL, 0},
       {kCaptionTextTrackNum, 55, 44, false, NULL, 0},
       {kVideoTrackNum, 67, 34, true, NULL, 0},
       {kSubtitleTextTrackNum, 67, 33, false, NULL, 0},
   };
   int input_block_count = arraysize(kInputBlockInfo);
 
   scoped_ptr<Cluster> cluster(
       CreateCluster(0, kInputBlockInfo, input_block_count));
 
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(23));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(34));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
 
   const WebMClusterParser::TextBufferQueueMap& text_map =
       parser_->GetTextBuffers();
   for (WebMClusterParser::TextBufferQueueMap::const_iterator itr =
            text_map.begin();
        itr != text_map.end();
        ++itr) {
     const TextTracks::const_iterator find_result =
         text_tracks.find(itr->first);
     ASSERT_TRUE(find_result != text_tracks.end());
     ASSERT_TRUE(VerifyTextBuffers(parser_, kInputBlockInfo, input_block_count,
                                   itr->first, itr->second));
   }
 }
 
 TEST_F(WebMClusterParserTest, ParseEncryptedBlock) {
   scoped_ptr<Cluster> cluster(CreateEncryptedCluster(sizeof(kEncryptedFrame)));
 
   parser_.reset(CreateParserWithKeyIdsAndAudioCodec(
       std::string(), "video_key_id", kUnknownAudioCodec));
+
+  // The encrypted cluster contains just one block, video.
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      WebMClusterParser::kDefaultVideoBufferDurationInMs));
+
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
   ASSERT_EQ(1UL, parser_->GetVideoBuffers().size());
   scoped_refptr<StreamParserBuffer> buffer = parser_->GetVideoBuffers()[0];
   VerifyEncryptedBuffer(buffer);
 }
 
 TEST_F(WebMClusterParserTest, ParseBadEncryptedBlock) {
   scoped_ptr<Cluster> cluster(
       CreateEncryptedCluster(sizeof(kEncryptedFrame) - 1));
@@ skipping 80 matching lines @@
 
 TEST_F(WebMClusterParserTest, ParseWithoutAnyDurationsSimpleBlocks) {
   InSequence s;
 
   // Absent DefaultDuration information, SimpleBlock durations are derived from
   // inter-buffer track timestamp delta if within the cluster. Duration for the
   // last block in a cluster is estimated independently for each track in the
   // cluster. For video tracks we use the maximum seen so far. For audio we use
   // the the minimum.
   // TODO(chcunningham): Move audio over to use the maximum.
+
+  const int kExpectedLastAudioBufferEstimatedDurationInMs = 22;
+  const int kExpectedLastVideoBufferEstimatedDurationInMs = 34;
   const BlockInfo kBlockInfo1[] = {
       {kAudioTrackNum, 0, 23, true, NULL, 0},
       {kAudioTrackNum, 23, 22, true, NULL, 0},
       {kVideoTrackNum, 33, 33, true, NULL, 0},
       {kAudioTrackNum, 45, 23, true, NULL, 0},
       {kVideoTrackNum, 66, 34, true, NULL, 0},
-      // Estimated from minimum audio dur
-      {kAudioTrackNum, 68, 22, true, NULL, 0},
-      // Estimated from maximum video dur
-      {kVideoTrackNum, 100, 34, true, NULL, 0},
+      {kAudioTrackNum, 68, kExpectedLastAudioBufferEstimatedDurationInMs, true,
+       NULL, 0},
+      {kVideoTrackNum, 100, kExpectedLastVideoBufferEstimatedDurationInMs, true,
+       NULL, 0},
   };
 
   int block_count1 = arraysize(kBlockInfo1);
   scoped_ptr<Cluster> cluster1(CreateCluster(0, kBlockInfo1, block_count1));
 
   // Send slightly less than the first full cluster so all but the last video
   // block is parsed. Verify the last fully parsed audio and video buffer are
   // both missing from the result (parser should hold them aside for duration
   // estimation prior to end of cluster detection in the absence of
   // DefaultDurations.)
   int result = parser_->Parse(cluster1->data(), cluster1->size() - 1);
   EXPECT_GT(result, 0);
   EXPECT_LT(result, cluster1->size());
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo1, block_count1 - 3));
   EXPECT_EQ(3UL, parser_->GetAudioBuffers().size());
   EXPECT_EQ(1UL, parser_->GetVideoBuffers().size());
 
   parser_->Reset();
 
   // Now parse the full first cluster and verify all the blocks are parsed.
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastAudioBufferEstimatedDurationInMs));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastVideoBufferEstimatedDurationInMs));
   result = parser_->Parse(cluster1->data(), cluster1->size());
   EXPECT_EQ(cluster1->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo1, block_count1));
 
   // Verify that the estimated frame duration is tracked across clusters for
   // each track.
   const BlockInfo kBlockInfo2[] = {
       // Estimate carries over across clusters
-      {kAudioTrackNum, 200, 22, true, NULL, 0},
+      {kAudioTrackNum, 200, kExpectedLastAudioBufferEstimatedDurationInMs, true,
+       NULL, 0},
       // Estimate carries over across clusters
-      {kVideoTrackNum, 201, 34, true, NULL, 0},
+      {kVideoTrackNum, 201, kExpectedLastVideoBufferEstimatedDurationInMs, true,
+       NULL, 0},
   };
 
   int block_count2 = arraysize(kBlockInfo2);
   scoped_ptr<Cluster> cluster2(CreateCluster(0, kBlockInfo2, block_count2));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastAudioBufferEstimatedDurationInMs));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastVideoBufferEstimatedDurationInMs));
   result = parser_->Parse(cluster2->data(), cluster2->size());
   EXPECT_EQ(cluster2->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo2, block_count2));
 }
 
 TEST_F(WebMClusterParserTest, ParseWithoutAnyDurationsBlockGroups) {
   InSequence s;
 
   // Absent DefaultDuration and BlockDuration information, BlockGroup block
   // durations are derived from inter-buffer track timestamp delta if within the
   // cluster. Duration for the last block in a cluster is estimated
   // independently for each track in the cluster. For video tracks we use the
   // maximum seen so far. For audio we use the the minimum.
   // TODO(chcunningham): Move audio over to use the maximum.
+
+  const int kExpectedLastAudioBufferEstimatedDurationInMs = 22;
+  const int kExpectedLastVideoBufferEstimatedDurationInMs = 34;
   const BlockInfo kBlockInfo1[] = {
       {kAudioTrackNum, 0, -23, false, NULL, 0},
       {kAudioTrackNum, 23, -22, false, NULL, 0},
       {kVideoTrackNum, 33, -33, false, NULL, 0},
       {kAudioTrackNum, 45, -23, false, NULL, 0},
       {kVideoTrackNum, 66, -34, false, NULL, 0},
-      // Estimated from minimum audio dur
-      {kAudioTrackNum, 68, -22, false, NULL, 0},
-      // Estimated from maximum video dur
-      {kVideoTrackNum, 100, -34, false, NULL, 0},
+      {kAudioTrackNum, 68, -kExpectedLastAudioBufferEstimatedDurationInMs,
+       false, NULL, 0},
+      {kVideoTrackNum, 100, -kExpectedLastVideoBufferEstimatedDurationInMs,
+       false, NULL, 0},
   };
 
   int block_count1 = arraysize(kBlockInfo1);
   scoped_ptr<Cluster> cluster1(CreateCluster(0, kBlockInfo1, block_count1));
 
   // Send slightly less than the first full cluster so all but the last video
   // block is parsed. Verify the last fully parsed audio and video buffer are
   // both missing from the result (parser should hold them aside for duration
   // estimation prior to end of cluster detection in the absence of
   // DefaultDurations.)
   int result = parser_->Parse(cluster1->data(), cluster1->size() - 1);
   EXPECT_GT(result, 0);
   EXPECT_LT(result, cluster1->size());
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo1, block_count1 - 3));
   EXPECT_EQ(3UL, parser_->GetAudioBuffers().size());
   EXPECT_EQ(1UL, parser_->GetVideoBuffers().size());
 
   parser_->Reset();
 
   // Now parse the full first cluster and verify all the blocks are parsed.
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastAudioBufferEstimatedDurationInMs));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastVideoBufferEstimatedDurationInMs));
   result = parser_->Parse(cluster1->data(), cluster1->size());
   EXPECT_EQ(cluster1->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo1, block_count1));
 
   // Verify that the estimated frame duration is tracked across clusters for
   // each track.
   const BlockInfo kBlockInfo2[] = {
-      {kAudioTrackNum, 200, -22, false, NULL, 0},
-      {kVideoTrackNum, 201, -34, false, NULL, 0},
+      {kAudioTrackNum, 200, -kExpectedLastAudioBufferEstimatedDurationInMs,
+       false, NULL, 0},
+      {kVideoTrackNum, 201, -kExpectedLastVideoBufferEstimatedDurationInMs,
+       false, NULL, 0},
   };
 
   int block_count2 = arraysize(kBlockInfo2);
   scoped_ptr<Cluster> cluster2(CreateCluster(0, kBlockInfo2, block_count2));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastAudioBufferEstimatedDurationInMs));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      kExpectedLastVideoBufferEstimatedDurationInMs));
   result = parser_->Parse(cluster2->data(), cluster2->size());
   EXPECT_EQ(cluster2->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo2, block_count2));
 }
 
 // TODO(wolenetz): Is parser behavior correct? See http://crbug.com/363433.
 TEST_F(WebMClusterParserTest,
        ParseWithDefaultDurationsBlockGroupsWithoutDurations) {
   InSequence s;
   ResetParserToHaveDefaultDurations();
@@ skipping 46 matching lines @@
     }, {
       kVideoTrackNum,
       0,
       WebMClusterParser::kDefaultVideoBufferDurationInMs,
       true
     },
   };
 
   int block_count = arraysize(kBlockInfo);
   scoped_ptr<Cluster> cluster(CreateCluster(0, kBlockInfo, block_count));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      WebMClusterParser::kDefaultAudioBufferDurationInMs));
+  EXPECT_MEDIA_LOG_STRING(WebMSimpleBlockDurationEstimated(
+      WebMClusterParser::kDefaultVideoBufferDurationInMs));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo, block_count));
 }
 
 TEST_F(WebMClusterParserTest,
        ParseDegenerateClusterWithDefaultDurationsYieldsDefaultDurations) {
   ResetParserToHaveDefaultDurations();
 
   const BlockInfo kBlockInfo[] = {
     { kAudioTrackNum, 0, kTestAudioFrameDefaultDurationInMs, true },
     { kVideoTrackNum, 0, kTestVideoFrameDefaultDurationInMs, true },
   };
 
   int block_count = arraysize(kBlockInfo);
   scoped_ptr<Cluster> cluster(CreateCluster(0, kBlockInfo, block_count));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo, block_count));
 }
 
 TEST_F(WebMClusterParserTest, ReadOpusDurationsSimpleBlockAtEndOfCluster) {
-  // Reset parser to expect Opus codec audio.
-  parser_.reset(CreateParserWithKeyIdsAndAudioCodec(std::string(),
-                                                    std::string(), kCodecOpus));
+  InSequence s;
 
   int loop_count = 0;
   for (const auto* packet_ptr : BuildAllOpusPackets()) {
+    // Get a new parser each iteration to prevent exceeding the media log cap.
+    parser_.reset(CreateParserWithKeyIdsAndAudioCodec(
+        std::string(), std::string(), kCodecOpus));
+
     const BlockInfo kBlockInfo[] = {{kAudioTrackNum,
                                      0,
                                      packet_ptr->duration_ms(),
                                      true,  // Make it a SimpleBlock.
                                      packet_ptr->data(),
                                      packet_ptr->size()}};
 
     int block_count = arraysize(kBlockInfo);
     scoped_ptr<Cluster> cluster(CreateCluster(0, kBlockInfo, block_count));
+    int duration_ms = packet_ptr->duration_ms();  // Casts from double.
+    if (duration_ms > 120) {
+      EXPECT_MEDIA_LOG_STRING(OpusPacketDurationTooHigh(duration_ms));
+    }
+
     int result = parser_->Parse(cluster->data(), cluster->size());
     EXPECT_EQ(cluster->size(), result);
     ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo, block_count));
     loop_count++;
   }
 
   // Test should minimally cover all the combinations of config and frame count.
   ASSERT_GE(loop_count, kNumPossibleOpusConfigs * kMaxOpusPacketFrameCount);
 }
 
 TEST_F(WebMClusterParserTest, PreferOpusDurationsOverBlockDurations) {
-  // Reset parser to expect Opus codec audio.
-  parser_.reset(CreateParserWithKeyIdsAndAudioCodec(std::string(),
-                                                    std::string(), kCodecOpus));
+  InSequence s;
 
   int loop_count = 0;
   for (const auto* packet_ptr : BuildAllOpusPackets()) {
+    // Get a new parser each iteration to prevent exceeding the media log cap.
+    parser_.reset(CreateParserWithKeyIdsAndAudioCodec(
+        std::string(), std::string(), kCodecOpus));
+
     // Setting BlockDuration != Opus duration to see which one the parser uses.
     int block_duration_ms = packet_ptr->duration_ms() + 10;
+    if (packet_ptr->duration_ms() > 120) {
+      EXPECT_MEDIA_LOG_STRING(
+          OpusPacketDurationTooHigh(packet_ptr->duration_ms()));
+    }
+
+    EXPECT_MEDIA_LOG_STRING(WebMBlockDurationMismatchesOpusDuration(
+        block_duration_ms, packet_ptr->duration_ms()));
 
     BlockInfo block_infos[] = {{kAudioTrackNum,
                                 0,
                                 block_duration_ms,
                                 false,  // Not a SimpleBlock.
                                 packet_ptr->data(),
                                 packet_ptr->size()}};
 
     int block_count = arraysize(block_infos);
     scoped_ptr<Cluster> cluster(CreateCluster(0, block_infos, block_count));
@@ skipping 34 matching lines @@
   int block_count = arraysize(kBlockInfo);
   scoped_ptr<Cluster> cluster(CreateCluster(0, kBlockInfo, block_count));
   int result = parser_->Parse(cluster->data(), cluster->size());
   EXPECT_EQ(cluster->size(), result);
 
   // Will verify that duration of buffer matches that of BlockDuration.
   ASSERT_TRUE(VerifyBuffers(parser_, kBlockInfo, block_count));
 }
 
 }  // namespace media