Logging clarification for frame_helpers.

Bug: b/250447844
Change-Id: Ia52fad7d1e588c205d075cda7797bc2252efd95e
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/278628
Reviewed-by: Philip Eliasson <philipel@webrtc.org>
Commit-Queue: Rasmus Brandt <brandtr@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#38387}

modules/video_coding/BUILD.gn

@@ -1136,6 +1136,7 @@ if (rtc_include_tests) {
       "fec_controller_unittest.cc",
       "frame_buffer2_unittest.cc",
       "frame_dependencies_calculator_unittest.cc",
+      "frame_helpers_unittest.cc",
       "generic_decoder_unittest.cc",
       "h264_packet_buffer_unittest.cc",
       "h264_sprop_parameter_sets_unittest.cc",
@@ -1179,6 +1180,7 @@ if (rtc_include_tests) {
       ":encoded_frame",
       ":frame_buffer2",
       ":frame_dependencies_calculator",
+      ":frame_helpers",
       ":h264_packet_buffer",
       ":nack_requester",
       ":packet_buffer",

modules/video_coding/frame_buffer2.cc

@@ -254,8 +254,11 @@ std::unique_ptr<EncodedFrame> FrameBuffer::GetNextFrame() {
   absl::optional<Timestamp> render_time = first_frame.RenderTimestamp();
   int64_t receive_time_ms = first_frame.ReceivedTime();
   // Gracefully handle bad RTP timestamps and render time issues.
-  if (!render_time ||
-      FrameHasBadRenderTiming(*render_time, now, timing_->TargetVideoDelay())) {
+  if (!render_time || FrameHasBadRenderTiming(*render_time, now) ||
+      TargetVideoDelayIsTooLarge(timing_->TargetVideoDelay())) {
+    RTC_LOG(LS_WARNING) << "Resetting jitter estimator and timing module due "
+                           "to bad render timing for rtp_timestamp="
+                        << first_frame.Timestamp();
     jitter_estimator_.Reset();
     timing_->Reset();
     render_time = timing_->RenderTime(first_frame.Timestamp(), now);

modules/video_coding/frame_helpers.cc

@@ -16,9 +16,11 @@
 
 namespace webrtc {
 
-bool FrameHasBadRenderTiming(Timestamp render_time,
-                             Timestamp now,
-                             TimeDelta target_video_delay) {
+namespace {
+constexpr TimeDelta kMaxVideoDelay = TimeDelta::Millis(10000);
+}
+
+bool FrameHasBadRenderTiming(Timestamp render_time, Timestamp now) {
   // Zero render time means render immediately.
   if (render_time.IsZero()) {
     return false;
@@ -26,19 +28,23 @@ bool FrameHasBadRenderTiming(Timestamp render_time,
   if (render_time < Timestamp::Zero()) {
     return true;
   }
-  constexpr TimeDelta kMaxVideoDelay = TimeDelta::Millis(10000);
-  TimeDelta frame_delay = (render_time - now).Abs();
-  if (frame_delay > kMaxVideoDelay) {
-    RTC_LOG(LS_WARNING)
-        << "A frame about to be decoded is out of the configured "
-           "delay bounds ("
-        << frame_delay.ms() << " > " << kMaxVideoDelay.ms()
-        << "). Resetting the video jitter buffer.";
+  TimeDelta frame_delay = render_time - now;
+  if (frame_delay.Abs() > kMaxVideoDelay) {
+    RTC_LOG(LS_WARNING) << "Frame has bad render timing because it is out of "
+                           "the delay bounds (frame_delay_ms="
+                        << frame_delay.ms()
+                        << ", kMaxVideoDelay_ms=" << kMaxVideoDelay.ms() << ")";
     return true;
   }
+  return false;
+}
+
+bool TargetVideoDelayIsTooLarge(TimeDelta target_video_delay) {
   if (target_video_delay > kMaxVideoDelay) {
-    RTC_LOG(LS_WARNING) << "The video target delay has grown larger than "
-                        << kMaxVideoDelay.ms() << " ms.";
+    RTC_LOG(LS_WARNING)
+        << "Target video delay is too large. (target_video_delay_ms="
+        << target_video_delay.ms()
+        << ", kMaxVideoDelay_ms=" << kMaxVideoDelay.ms() << ")";
     return true;
   }
   return false;

modules/video_coding/frame_helpers.h

@@ -18,9 +18,9 @@
 
 namespace webrtc {
 
-bool FrameHasBadRenderTiming(Timestamp render_time,
-                             Timestamp now,
-                             TimeDelta target_video_delay);
+bool FrameHasBadRenderTiming(Timestamp render_time, Timestamp now);
+
+bool TargetVideoDelayIsTooLarge(TimeDelta target_video_delay);
 
 std::unique_ptr<EncodedFrame> CombineAndDeleteFrames(
     absl::InlinedVector<std::unique_ptr<EncodedFrame>, 4> frames);

modules/video_coding/frame_helpers_unittest.cc

@@ -0,0 +1,34 @@
+/*
+ *  Copyright (c) 2022 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "modules/video_coding/frame_helpers.h"
+
+#include "api/units/timestamp.h"
+#include "test/gtest.h"
+
+namespace webrtc {
+namespace {
+
+TEST(FrameHasBadRenderTimingTest, LargePositiveFrameDelayIsBad) {
+  Timestamp render_time = Timestamp::Seconds(12);
+  Timestamp now = Timestamp::Seconds(0);
+
+  EXPECT_TRUE(FrameHasBadRenderTiming(render_time, now));
+}
+
+TEST(FrameHasBadRenderTimingTest, LargeNegativeFrameDelayIsBad) {
+  Timestamp render_time = Timestamp::Seconds(12);
+  Timestamp now = Timestamp::Seconds(24);
+
+  EXPECT_TRUE(FrameHasBadRenderTiming(render_time, now));
+}
+
+}  // namespace
+}  // namespace webrtc

video/video_stream_buffer_controller.cc

@@ -206,7 +206,11 @@ void VideoStreamBufferController::OnFrameReady(
     keyframe_required_ = false;
 
   // Gracefully handle bad RTP timestamps and render time issues.
-  if (FrameHasBadRenderTiming(render_time, now, timing_->TargetVideoDelay())) {
+  if (FrameHasBadRenderTiming(render_time, now) ||
+      TargetVideoDelayIsTooLarge(timing_->TargetVideoDelay())) {
+    RTC_LOG(LS_WARNING) << "Resetting jitter estimator and timing module due "
+                           "to bad render timing for rtp_timestamp="
+                        << first_frame.Timestamp();
     jitter_estimator_.Reset();
     timing_->Reset();
     render_time = timing_->RenderTime(first_frame.Timestamp(), now);