Fix processing of multiple stream status changes by renderer

Typically renderer needs to do Flush + StartPlaying in response to
stream status change (i.e. when stream gets enabled or disabled). But
since Flush is an async operation we might get another status change
of the same stream, while the renderer is still handling the previous
one. In the past renderer has simply ignored status changes while
another status change was processed. But that was problematic, since
we couldn't guarantee that the renderer status will be correct after
stream has been enabled/disabled very quickly a few times. This CL
fixes that issue by postponing status changes handling if necessary,
instead of dropping those notifications.

BUG=678031

Review-Url: https://codereview.chromium.org/2605473002
Cr-Commit-Position: refs/heads/master@{#442762}

media/renderers/renderer_impl.cc

@@ -214,28 +214,32 @@ void RendererImpl::StartPlayingFrom(base::TimeDelta time) {
     video_renderer_->StartPlayingFrom(time);
 }
 
-void RendererImpl::RestartStreamPlayback(DemuxerStream* stream,
+void RendererImpl::OnStreamStatusChanged(DemuxerStream* stream,
                                          bool enabled,
                                          base::TimeDelta time) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   DCHECK(stream);
   bool video = (stream->type() == DemuxerStream::VIDEO);
   DVLOG(1) << __func__ << (video ? " video" : " audio") << " stream=" << stream
-           << " enabled=" << stream->enabled() << " time=" << time.InSecondsF();
+           << " enabled=" << enabled << " time=" << time.InSecondsF();
   if ((state_ != STATE_PLAYING) || (audio_ended_ && video_ended_))
     return;
+  if (restarting_audio_ || restarting_video_) {
+    DVLOG(3) << __func__ << ": postponed stream " << stream
+             << " status change handling.";
+    pending_stream_status_notifications_.push_back(
+        base::Bind(&RendererImpl::OnStreamStatusChanged, weak_this_, stream,
+                   enabled, time));
+    return;
+  }
   if (stream->type() == DemuxerStream::VIDEO) {
     DCHECK(video_renderer_);
-    if (restarting_video_)
-      return;
     restarting_video_ = true;
     video_renderer_->Flush(
         base::Bind(&RendererImpl::RestartVideoRenderer, weak_this_, time));
   } else if (stream->type() == DemuxerStream::AUDIO) {
     DCHECK(audio_renderer_);
     DCHECK(time_source_);
-    if (restarting_audio_)
-      return;
     restarting_audio_ = true;
     // Stop ticking (transition into paused state) in audio renderer before
     // calling Flush, since after Flush we are going to restart playback by
@@ -386,7 +390,7 @@ void RendererImpl::InitializeAudioRenderer() {
   }
 
   audio_stream->SetStreamStatusChangeCB(base::Bind(
-      &RendererImpl::RestartStreamPlayback, weak_this_, audio_stream));
+      &RendererImpl::OnStreamStatusChanged, weak_this_, audio_stream));
 
   audio_renderer_client_.reset(
       new RendererClientInternal(DemuxerStream::AUDIO, this));
@@ -435,7 +439,7 @@ void RendererImpl::InitializeVideoRenderer() {
   }
 
   video_stream->SetStreamStatusChangeCB(base::Bind(
-      &RendererImpl::RestartStreamPlayback, weak_this_, video_stream));
+      &RendererImpl::OnStreamStatusChanged, weak_this_, video_stream));
 
   video_renderer_client_.reset(
       new RendererClientInternal(DemuxerStream::VIDEO, this));
@@ -556,6 +560,7 @@ void RendererImpl::OnStatisticsUpdate(const PipelineStatistics& stats) {
 bool RendererImpl::HandleRestartedStreamBufferingChanges(
     DemuxerStream::Type type,
     BufferingState new_buffering_state) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
   // When restarting playback we want to defer the BUFFERING_HAVE_NOTHING for
   // the stream being restarted, to allow continuing uninterrupted playback on
   // the other stream.
@@ -563,7 +568,9 @@ bool RendererImpl::HandleRestartedStreamBufferingChanges(
     if (new_buffering_state == BUFFERING_HAVE_ENOUGH) {
       DVLOG(1) << __func__ << " Got BUFFERING_HAVE_ENOUGH for video stream,"
                               " resuming playback.";
-      restarting_video_ = false;
+      task_runner_->PostTask(
+          FROM_HERE,
+          base::Bind(&RendererImpl::OnStreamRestartCompleted, weak_this_));
       if (state_ == STATE_PLAYING &&
           !deferred_video_underflow_cb_.IsCancelled()) {
         // If deferred_video_underflow_cb_ wasn't triggered, then audio should
@@ -608,12 +615,24 @@ bool RendererImpl::HandleRestartedStreamBufferingChanges(
       // Now that we have decoded enough audio, pause playback momentarily to
       // ensure video renderer is synchronised with audio.
       PausePlayback();
-      restarting_audio_ = false;
+      task_runner_->PostTask(
+          FROM_HERE,
+          base::Bind(&RendererImpl::OnStreamRestartCompleted, weak_this_));
     }
   }
   return false;
 }
 
+void RendererImpl::OnStreamRestartCompleted() {
+  DCHECK(restarting_audio_ || restarting_video_);
+  restarting_audio_ = false;
+  restarting_video_ = false;
+  if (!pending_stream_status_notifications_.empty()) {
+    pending_stream_status_notifications_.front().Run();
+    pending_stream_status_notifications_.pop_front();
+  }
+}
+
 void RendererImpl::OnBufferingStateChange(DemuxerStream::Type type,
                                           BufferingState new_buffering_state) {
   DCHECK((type == DemuxerStream::AUDIO) || (type == DemuxerStream::VIDEO));

media/renderers/renderer_impl.h

@@ -5,6 +5,7 @@
 #ifndef MEDIA_RENDERERS_RENDERER_IMPL_H_
 #define MEDIA_RENDERERS_RENDERER_IMPL_H_
 
+#include <list>
 #include <memory>
 #include <vector>
 
@@ -60,7 +61,7 @@ class MEDIA_EXPORT RendererImpl : public Renderer {
   void SetVolume(float volume) final;
   base::TimeDelta GetMediaTime() final;
 
-  void RestartStreamPlayback(DemuxerStream* stream,
+  void OnStreamStatusChanged(DemuxerStream* stream,
                              bool enabled,
                              base::TimeDelta time);
 
@@ -146,6 +147,8 @@ class MEDIA_EXPORT RendererImpl : public Renderer {
   void OnVideoNaturalSizeChange(const gfx::Size& size);
   void OnVideoOpacityChange(bool opaque);
 
+  void OnStreamRestartCompleted();
+
   State state_;
 
   // Task runner used to execute pipeline tasks.
@@ -197,6 +200,7 @@ class MEDIA_EXPORT RendererImpl : public Renderer {
 
   bool restarting_audio_ = false;
   bool restarting_video_ = false;
+  std::list<base::Closure> pending_stream_status_notifications_;
 
   base::WeakPtr<RendererImpl> weak_this_;
   base::WeakPtrFactory<RendererImpl> weak_factory_;

media/renderers/renderer_impl_unittest.cc

@@ -12,6 +12,7 @@
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
 #include "base/test/simple_test_tick_clock.h"
+#include "base/threading/thread_task_runner_handle.h"
 #include "media/base/gmock_callback_support.h"
 #include "media/base/mock_filters.h"
 #include "media/base/test_helpers.h"
@@ -25,6 +26,7 @@ using ::testing::Mock;
 using ::testing::Return;
 using ::testing::SaveArg;
 using ::testing::StrictMock;
+using ::testing::WithArg;
 
 namespace media {
 
@@ -38,6 +40,15 @@ ACTION_P2(SetError, renderer_client, error) {
   (*renderer_client)->OnError(error);
 }
 
+ACTION(PostCallback) {
+  base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE, arg0);
+}
+
+ACTION(PostQuitWhenIdle) {
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE, base::MessageLoop::QuitWhenIdleClosure());
+}
+
 class RendererImplTest : public ::testing::Test {
  public:
   // Used for setting expectations on pipeline callbacks. Using a StrictMock
@@ -753,15 +764,91 @@ TEST_F(RendererImplTest, StreamStatusNotificationHandling) {
 
   // Verify that DemuxerStream status changes cause the corresponding
   // audio/video renderer to be flushed and restarted.
-  base::TimeDelta time0;
   EXPECT_CALL(time_source_, StopTicking());
   EXPECT_CALL(*audio_renderer_, Flush(_)).WillOnce(RunClosure<0>());
-  EXPECT_CALL(*audio_renderer_, StartPlaying()).Times(1);
-  audio_stream_status_change_cb.Run(false, time0);
+  EXPECT_CALL(*audio_renderer_, StartPlaying())
+      .Times(1)
+      .WillOnce(
+          SetBufferingState(&audio_renderer_client_, BUFFERING_HAVE_ENOUGH));
+  audio_stream_status_change_cb.Run(false, base::TimeDelta());
 
   EXPECT_CALL(*video_renderer_, Flush(_)).WillOnce(RunClosure<0>());
-  EXPECT_CALL(*video_renderer_, StartPlayingFrom(_)).Times(1);
-  video_stream_status_change_cb.Run(false, time0);
+  EXPECT_CALL(*video_renderer_, StartPlayingFrom(_))
+      .Times(1)
+      .WillOnce(DoAll(
+          SetBufferingState(&video_renderer_client_, BUFFERING_HAVE_ENOUGH),
+          PostQuitWhenIdle()));
+
+  video_stream_status_change_cb.Run(false, base::TimeDelta());
+  base::RunLoop().Run();
+}
+
+// Stream status changes are handled asynchronously by the renderer and may take
+// some time to process. This test verifies that all status changes are
+// processed correctly by the renderer even if status changes of the stream
+// happen much faster than the renderer can process them. In that case the
+// renderer may postpone processing status changes, but still must process all
+// of them eventually.
+TEST_F(RendererImplTest, PostponedStreamStatusNotificationHandling) {
+  CreateAudioAndVideoStream();
+
+  DemuxerStream::StreamStatusChangeCB audio_stream_status_change_cb;
+  DemuxerStream::StreamStatusChangeCB video_stream_status_change_cb;
+  EXPECT_CALL(*audio_stream_, SetStreamStatusChangeCB(_))
+      .WillOnce(SaveArg<0>(&audio_stream_status_change_cb));
+  EXPECT_CALL(*video_stream_, SetStreamStatusChangeCB(_))
+      .WillOnce(SaveArg<0>(&video_stream_status_change_cb));
+  SetAudioRendererInitializeExpectations(PIPELINE_OK);
+  SetVideoRendererInitializeExpectations(PIPELINE_OK);
+  InitializeAndExpect(PIPELINE_OK);
+  Play();
+
+  EXPECT_CALL(callbacks_, OnBufferingStateChange(BUFFERING_HAVE_ENOUGH))
+      .Times(2);
+
+  EXPECT_CALL(time_source_, StopTicking()).Times(2);
+  EXPECT_CALL(time_source_, StartTicking()).Times(2);
+  EXPECT_CALL(*audio_renderer_, Flush(_))
+      .Times(2)
+      .WillRepeatedly(DoAll(
+          SetBufferingState(&audio_renderer_client_, BUFFERING_HAVE_NOTHING),
+          WithArg<0>(PostCallback())));
+  EXPECT_CALL(*audio_renderer_, StartPlaying())
+      .Times(2)
+      .WillOnce(
+          SetBufferingState(&audio_renderer_client_, BUFFERING_HAVE_ENOUGH))
+      .WillOnce(DoAll(
+          SetBufferingState(&audio_renderer_client_, BUFFERING_HAVE_ENOUGH),
+          PostQuitWhenIdle()));
+  // The first stream status change will be processed immediately. Each status
+  // change processing involves Flush + StartPlaying when the Flush is done. The
+  // Flush operation is async in this case, so the second status change will be
+  // postponed by renderer until after processing the first one is finished. But
+  // we must still get two pairs of Flush/StartPlaying calls eventually.
+  audio_stream_status_change_cb.Run(false, base::TimeDelta());
+  audio_stream_status_change_cb.Run(true, base::TimeDelta());
+  base::RunLoop().Run();
+
+  EXPECT_CALL(*video_renderer_, Flush(_))
+      .Times(2)
+      .WillRepeatedly(DoAll(
+          SetBufferingState(&video_renderer_client_, BUFFERING_HAVE_NOTHING),
+          WithArg<0>(PostCallback())));
+  EXPECT_CALL(*video_renderer_, StartPlayingFrom(base::TimeDelta()))
+      .Times(2)
+      .WillOnce(
+          SetBufferingState(&video_renderer_client_, BUFFERING_HAVE_ENOUGH))
+      .WillOnce(DoAll(
+          SetBufferingState(&video_renderer_client_, BUFFERING_HAVE_ENOUGH),
+          PostQuitWhenIdle()));
+  // The first stream status change will be processed immediately. Each status
+  // change processing involves Flush + StartPlaying when the Flush is done. The
+  // Flush operation is async in this case, so the second status change will be
+  // postponed by renderer until after processing the first one is finished. But
+  // we must still get two pairs of Flush/StartPlaying calls eventually.
+  video_stream_status_change_cb.Run(false, base::TimeDelta());
+  video_stream_status_change_cb.Run(true, base::TimeDelta());
+  base::RunLoop().Run();
 }
 
 }  // namespace media