Add MediaLog properties and events for use in HLS

Bug: 40057824
Change-Id: I7c75a59d24f5fab465a19d382810ae008c6f50b4
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/5983472
Reviewed-by: Eugene Zemtsov <eugene@chromium.org>
Commit-Queue: Ted (Chromium) Meyer <tmathmeyer@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1379191}
NOKEYCHECK=True
GitOrigin-RevId: a0d4ebc4ab1b701fc42a14ac19a3269d0ed462f8
diff --git a/base/media_log_events.h b/base/media_log_events.h
index a72b64a..79ec3e0 100644
--- a/base/media_log_events.h
+++ b/base/media_log_events.h
@@ -87,6 +87,9 @@
   // Triggered whenever WMPI handles a track change.
   kAudioTrackChange,
   kVideoTrackChange,
+
+  // Triggered when the media element starts and finishes fetching media data.
+  kHlsSegmentFetch,
 };
 
 // Sometimes URLs can have encoded data that can be exteremly large.
@@ -116,6 +119,11 @@
                            std::string,
                            "video_occlusion_state");
 
+MEDIA_LOG_EVENT_NAMED_DATA_OP(kHlsSegmentFetch,
+                              std::string,
+                              "hls_segment_url",
+                              TruncateUrlString);
+
 // Each type of buffering state gets a different name.
 MEDIA_LOG_EVENT_NAMED_DATA(
     kBufferingStateChanged,
diff --git a/base/media_log_properties.cc b/base/media_log_properties.cc
index 12569be..1040278 100644
--- a/base/media_log_properties.cc
+++ b/base/media_log_properties.cc
@@ -39,6 +39,7 @@
     STRINGIFY(kFramerate);
     STRINGIFY(kVideoPlaybackRoughness);
     STRINGIFY(kVideoPlaybackFreezing);
+    STRINGIFY(kHlsBufferedRanges);
   }
 #undef STRINGIFY
 }
diff --git a/base/media_log_properties.h b/base/media_log_properties.h
index ef075d5..51c01e9 100644
--- a/base/media_log_properties.h
+++ b/base/media_log_properties.h
@@ -102,6 +102,9 @@
   // A playback quality metric that tries to account for large pauses and/or
   // discontinuities during playback.
   kVideoPlaybackFreezing,
+
+  // Triggered when buffered ranges are changed.
+  kHlsBufferedRanges,
 };
 
 MEDIA_LOG_PROPERTY_SUPPORTS_TYPE(kResolution, gfx::Size);
@@ -130,6 +133,7 @@
 MEDIA_LOG_PROPERTY_SUPPORTS_TYPE(kFramerate, double);
 MEDIA_LOG_PROPERTY_SUPPORTS_TYPE(kVideoPlaybackRoughness, double);
 MEDIA_LOG_PROPERTY_SUPPORTS_TYPE(kVideoPlaybackFreezing, base::TimeDelta);
+MEDIA_LOG_PROPERTY_SUPPORTS_TYPE(kHlsBufferedRanges, Ranges<base::TimeDelta>);
 
 // Convert the enum to a string (used for the front-end enum matching).
 MEDIA_EXPORT std::string MediaLogPropertyKeyToString(MediaLogProperty property);
diff --git a/base/media_serializers.h b/base/media_serializers.h
index 1fba5ad..936ce9c 100644
--- a/base/media_serializers.h
+++ b/base/media_serializers.h
@@ -17,6 +17,7 @@
 #include "media/base/decoder.h"
 #include "media/base/media_serializers_base.h"
 #include "media/base/media_track.h"
+#include "media/base/ranges.h"
 #include "media/base/renderer.h"
 #include "media/base/status.h"
 #include "media/base/video_decoder_config.h"
@@ -567,6 +568,20 @@
   }
 };
 
+template <typename T>
+struct MediaSerializer<Ranges<T>> {
+  static inline base::Value Serialize(Ranges<T> ranges) {
+    base::Value::List result;
+    for (size_t i = 0; i < ranges.size(); i++) {
+      base::Value::List tuple;
+      tuple.Append(MediaSerializer<T>::Serialize(ranges.start(i)));
+      tuple.Append(MediaSerializer<T>::Serialize(ranges.end(i)));
+      result.Append(std::move(tuple));
+    }
+    return base::Value(std::move(result));
+  }
+};
+
 #undef FIELD_SERIALIZE
 
 }  // namespace media::internal
diff --git a/filters/hls_manifest_demuxer_engine.cc b/filters/hls_manifest_demuxer_engine.cc
index 1776333..c96d739 100644
--- a/filters/hls_manifest_demuxer_engine.cc
+++ b/filters/hls_manifest_demuxer_engine.cc
@@ -808,7 +808,8 @@
   host_->SetSequenceMode(parse_info.role, true);
 
   auto rendition = HlsRendition::CreateRendition(
-      host_, this, parse_info.role, std::move(playlist), parse_info.uri);
+      host_, this, parse_info.role, std::move(playlist), parse_info.uri,
+      media_log_.get());
 
   if (parse_info.role == kPrimary) {
     auto duration_or_live = rendition->GetDuration();
diff --git a/filters/hls_manifest_demuxer_engine_unittest.cc b/filters/hls_manifest_demuxer_engine_unittest.cc
index a6b819e..590da84 100644
--- a/filters/hls_manifest_demuxer_engine_unittest.cc
+++ b/filters/hls_manifest_demuxer_engine_unittest.cc
@@ -226,27 +226,32 @@
 template <typename T>
 class CallbackEnforcer {
  public:
-  explicit CallbackEnforcer(T expected)
-      : expected_(std::move(expected)), was_called_(false) {}
+  explicit CallbackEnforcer(
+      T expected,
+      const base::Location& from = base::Location::Current())
+      : expected_(std::move(expected)), created_(from) {}
 
   base::OnceCallback<void(T)> GetCallback() {
     return base::BindOnce(
-        [](bool* writeback, T expected, T actual) {
+        [](size_t line, bool* writeback, T expected, T actual) {
           *writeback = true;
-          ASSERT_EQ(actual, expected);
+          ASSERT_EQ(actual, expected)
+              << "Callback at line:" << line << " called with wrong parameter";
         },
-        &was_called_, expected_);
+        created_.line_number(), &was_called_, expected_);
   }
 
   // This method is move only, so it must be std::moved.
   void AssertAndReset(base::test::TaskEnvironment& env) && {
     env.RunUntilIdle();
-    ASSERT_TRUE(was_called_);
+    ASSERT_TRUE(was_called_)
+        << "Callback at line:" << created_.line_number() << " never called";
   }
 
  private:
   T expected_;
   bool was_called_ = false;
+  base::Location created_;
 };
 
 class HlsManifestDemuxerEngineTest : public testing::Test {
@@ -505,9 +510,11 @@
       .WillOnce(Return(after_seg_a))                // After appending segment A
       .WillOnce(Return(after_seg_a))                // Second CheckState
       .WillOnce(Return(after_seg_b))                // After appending segment B
+      .WillOnce(Return(after_seg_b))                // MediaLog
       .WillOnce(Return(after_seg_b))                // Third CheckState
       .WillOnce(Return(after_seg_b))                // Fourth CheckState
       .WillOnce(Return(after_seg_c))                // After appending segment C
+      .WillOnce(Return(after_seg_c))                // MediaLog
       .WillOnce(Return(after_seg_c))                // Fifth CheckState
       ;
 
diff --git a/filters/hls_rendition.cc b/filters/hls_rendition.cc
index e1082ae..e673f88 100644
--- a/filters/hls_rendition.cc
+++ b/filters/hls_rendition.cc
@@ -41,11 +41,12 @@
     HlsRenditionHost* rendition_host,
     std::string role,
     scoped_refptr<hls::MediaPlaylist> playlist,
-    GURL uri) {
+    GURL uri,
+    MediaLog* media_log) {
   auto duration = GetPlaylistDuration(playlist.get());
   return std::make_unique<HlsRenditionImpl>(
       engine_host, rendition_host, std::move(role), std::move(playlist),
-      duration, std::move(uri));
+      duration, std::move(uri), media_log);
 }
 
 }  // namespace media
diff --git a/filters/hls_rendition.h b/filters/hls_rendition.h
index 531b787..8f97f1f 100644
--- a/filters/hls_rendition.h
+++ b/filters/hls_rendition.h
@@ -74,7 +74,8 @@
       HlsRenditionHost* rendition_host,
       std::string role,
       scoped_refptr<hls::MediaPlaylist> playlist,
-      GURL uri);
+      GURL uri,
+      MediaLog* media_log);
 };
 
 }  // namespace media
diff --git a/filters/hls_rendition_impl.cc b/filters/hls_rendition_impl.cc
index 45dea50..deca92d 100644
--- a/filters/hls_rendition_impl.cc
+++ b/filters/hls_rendition_impl.cc
@@ -26,7 +26,8 @@
                                    std::string role,
                                    scoped_refptr<hls::MediaPlaylist> playlist,
                                    std::optional<base::TimeDelta> duration,
-                                   GURL media_playlist_uri)
+                                   GURL media_playlist_uri,
+                                   MediaLog* media_log)
     : engine_host_(engine_host),
       rendition_host_(rendition_host),
       segments_(std::make_unique<hls::SegmentStream>(
@@ -35,7 +36,8 @@
       role_(std::move(role)),
       duration_(duration),
       media_playlist_uri_(std::move(media_playlist_uri)),
-      last_download_time_(base::TimeTicks::Now()) {}
+      last_download_time_(base::TimeTicks::Now()),
+      media_log_(media_log->Clone()) {}
 
 std::optional<base::TimeDelta> HlsRenditionImpl::GetDuration() {
   return duration_;
@@ -338,6 +340,9 @@
     engine_host_->Remove(role_, base::TimeDelta(), remove_until);
   }
 
+  auto ranges = engine_host_->GetBufferedRanges(role_);
+  media_log_->SetProperty<MediaLogProperty::kHlsBufferedRanges>(ranges);
+
   return base::TimeTicks::Now() - removal_start;
 }
 
@@ -365,6 +370,8 @@
   if (auto enc = segment->GetEncryptionData()) {
     is_fetching_new_key = enc->NeedsKeyFetch();
   }
+  media_log_->AddEvent<MediaLogEvent::kHlsSegmentFetch>(
+      segment->GetUri().PathForRequest());
   rendition_host_->ReadMediaSegment(
       *segment, /*read_chunked=*/false, include_init,
       base::BindOnce(&HlsRenditionImpl::OnSegmentData,
@@ -476,6 +483,8 @@
   // for the seek to complete. In this case, we just keep fetching until
   // the seek time is loaded.
   auto ranges = engine_host_->GetBufferedRanges(role_);
+  media_log_->SetProperty<MediaLogProperty::kHlsBufferedRanges>(ranges);
+
   if (ranges.size() && ranges.contains(ranges.size() - 1, required_time)) {
     std::move(cb).Run();
     return;
diff --git a/filters/hls_rendition_impl.h b/filters/hls_rendition_impl.h
index fb18e7d..a34a79c 100644
--- a/filters/hls_rendition_impl.h
+++ b/filters/hls_rendition_impl.h
@@ -24,7 +24,8 @@
                    std::string role,
                    scoped_refptr<hls::MediaPlaylist> playlist,
                    std::optional<base::TimeDelta> duration,
-                   GURL media_playlist_uri);
+                   GURL media_playlist_uri,
+                   MediaLog* media_log);
 
   // `HlsRendition` implementation
   std::optional<base::TimeDelta> GetDuration() override;
@@ -117,6 +118,8 @@
   std::unique_ptr<crypto::Encryptor> decryptor_;
   scoped_refptr<hls::MediaSegment> segment_with_key_;
 
+  std::unique_ptr<MediaLog> media_log_;
+
   // toggleable bool flags.
   bool set_stream_end_ = false;
   bool is_stopped_for_shutdown_ = false;
diff --git a/filters/hls_rendition_impl_unittest.cc b/filters/hls_rendition_impl_unittest.cc
index e525346..63d9091 100644
--- a/filters/hls_rendition_impl_unittest.cc
+++ b/filters/hls_rendition_impl_unittest.cc
@@ -8,6 +8,7 @@
 
 #include "base/test/gmock_callback_support.h"
 #include "base/test/task_environment.h"
+#include "media/base/mock_media_log.h"
 #include "media/base/test_helpers.h"
 #include "media/filters/hls_network_access_impl.h"
 #include "media/filters/hls_test_helpers.h"
@@ -144,6 +145,7 @@
 
 using testing::_;
 using testing::ElementsAreArray;
+using testing::NiceMock;
 using testing::Return;
 
 MATCHER_P(MediaSegmentHasUrl, urlstr, "MediaSegment has provided URL") {
@@ -152,6 +154,7 @@
 
 class HlsRenditionImplUnittest : public testing::Test {
  protected:
+  std::unique_ptr<MediaLog> media_log_;
   std::unique_ptr<MockManifestDemuxerEngineHost> mock_mdeh_;
   std::unique_ptr<MockHlsRenditionHost> mock_hrh_;
   base::test::TaskEnvironment task_environment_{
@@ -167,9 +170,11 @@
     }
     auto playlist = std::move(parsed).value();
     auto duration = playlist->GetComputedDuration();
+    media_log_ = std::make_unique<NiceMock<media::MockMediaLog>>();
+
     return std::make_unique<HlsRenditionImpl>(mock_mdeh_.get(), mock_hrh_.get(),
                                               "test", std::move(playlist),
-                                              duration, uri);
+                                              duration, uri, media_log_.get());
   }
 
   std::unique_ptr<HlsRenditionImpl> MakeLiveRendition(
@@ -181,9 +186,10 @@
       LOG(ERROR) << MediaSerialize(std::move(parsed).error());
       return nullptr;
     }
-    return std::make_unique<HlsRenditionImpl>(mock_mdeh_.get(), mock_hrh_.get(),
-                                              "test", std::move(parsed).value(),
-                                              std::nullopt, uri);
+    media_log_ = std::make_unique<NiceMock<media::MockMediaLog>>();
+    return std::make_unique<HlsRenditionImpl>(
+        mock_mdeh_.get(), mock_hrh_.get(), "test", std::move(parsed).value(),
+        std::nullopt, uri, media_log_.get());
   }
 
   MOCK_METHOD(void, CheckStateComplete, (base::TimeDelta delay), ());
@@ -217,7 +223,7 @@
       ranges.Add(start, end);
     }
     EXPECT_CALL(*mock_mdeh_, GetBufferedRanges("test"))
-        .WillOnce(Return(ranges));
+        .WillRepeatedly(Return(ranges));
   }
 
   void RespondWithRangeTwice(base::TimeDelta A,
@@ -444,7 +450,8 @@
   Ranges<base::TimeDelta> loaded_ranges;
   loaded_ranges.Add(base::Seconds(0), base::Seconds(12));
   EXPECT_CALL(*mock_mdeh_, GetBufferedRanges(_))
-      .WillOnce(Return(loaded_ranges));
+      .Times(2)
+      .WillRepeatedly(Return(loaded_ranges));
   // Old data will try to be removed. Since media time is 0, there is nothing
   // to do. Then there will be an attempt to fetch a new manifest, which won't
   // have any work to do either, instead just posting the delay_cb back.
@@ -466,7 +473,8 @@
   Ranges<base::TimeDelta> loaded_ranges;
   loaded_ranges.Add(base::Seconds(0), base::Seconds(12));
   EXPECT_CALL(*mock_mdeh_, GetBufferedRanges(_))
-      .WillOnce(Return(loaded_ranges));
+      .Times(2)
+      .WillRepeatedly(Return(loaded_ranges));
   // Old data will try to be removed. Since media time is 0, there is nothing
   // to do. Then there will be an attempt to fetch a new manifest, which will
   // get an update.
@@ -496,7 +504,8 @@
   Ranges<base::TimeDelta> loaded_ranges;
   loaded_ranges.Add(base::Seconds(0), base::Seconds(32));
   EXPECT_CALL(*mock_mdeh_, GetBufferedRanges(_))
-      .WillOnce(Return(loaded_ranges));
+      .Times(2)
+      .WillRepeatedly(Return(loaded_ranges));
   // Old data will try to be removed. Since media time is 15, there are 5
   // seconds of old data to delete. There will be no new fetch and parse for
   // manifest updates.