Chrome Version: 70.0.3502.0

OS: All


In PipelineIntegrationTest.TrackStatusChangesAfterPipelineEnded, if enough time passes between disabling and enabling the audio track, the pipeline ends twice.

Specifically, for 100% reproduction you can add:

diff --git a/media/test/pipeline_integration_test.cc b/media/test/pipeline_integration_test.cc
index 74cd7eb1ef6..de5e05d9444 100644
--- a/media/test/pipeline_integration_test.cc
+++ b/media/test/pipeline_integration_test.cc
@@ -960,6 +960,12 @@ TEST_F(PipelineIntegrationTest, TrackStatusChangesAfterPipelineEnded) {
   std::vector<MediaTrack::Id> track_ids;
   // Disable audio track.
   OnEnabledAudioTracksChanged(track_ids);
+
+  base::RunLoop().Run();
+
   // Re-enable audio track.
   track_ids.push_back("2");
   OnEnabledAudioTracksChanged(track_ids);

And then the outcome of the test is:

[26908:775:0725/165416.267752:127772396573406:FATAL:pipeline_impl.cc(534)] Check failed: !renderer_ended_. 
0   libbase.dylib                       0x0000000109414a7e base::debug::StackTrace::StackTrace(unsigned long) + 174
1   libbase.dylib                       0x0000000109414b3d base::debug::StackTrace::StackTrace(unsigned long) + 29
2   libbase.dylib                       0x0000000108ff19dc base::debug::StackTrace::StackTrace() + 28
3   libbase.dylib                       0x000000010906cddc logging::LogMessage::~LogMessage() + 460
4   libbase.dylib                       0x000000010906ab45 logging::LogMessage::~LogMessage() + 21
5   libmedia.dylib                      0x000000010a412b77 media::PipelineImpl::RendererWrapper::OnEnded() + 871
6   libmedia.dylib                      0x000000010a7f18a2 media::RendererImpl::RunEndedCallbackIfNeeded() + 450
7   libmedia.dylib                      0x000000010a7f16b2 media::RendererImpl::OnRendererEnded(media::DemuxerStream::Type) + 1218
8   libmedia.dylib                      0x000000010a7f2f0f media::RendererImpl::RendererClientInternal::OnEnded() + 31
9   libmedia.dylib                      0x000000010a7c7d6f media::AudioRendererImpl::OnPlaybackEnded() + 399
10  libmedia.dylib                      0x000000010a7cf1df void base::internal::FunctorTraits<void (media::AudioRendererImpl::*)(), void>::Invoke<void (media::AudioRendererImpl::*)(), base::WeakPtr<media::AudioRendererImpl> const&>(void (media::AudioRendererImpl::*)(), base::WeakPtr<media::AudioRendererImpl> const&&&) + 127
11  libmedia.dylib                      0x000000010a7cf15a void base::internal::InvokeHelper<true, void>::MakeItSo<void (media::AudioRendererImpl::* const&)(), base::WeakPtr<media::AudioRendererImpl> const&>(void (media::AudioRendererImpl::* const&&&)(), base::WeakPtr<media::AudioRendererImpl> const&&&) + 90
12  libmedia.dylib                      0x000000010a7cf0f0 void base::internal::Invoker<base::internal::BindState<void (media::AudioRendererImpl::*)(), base::WeakPtr<media::AudioRendererImpl> >, void ()>::RunImpl<void (media::AudioRendererImpl::* const&)(), std::__1::tuple<base::WeakPtr<media::AudioRendererImpl> > const&, 0ul>(void (media::AudioRendererImpl::* const&&&)(), std::__1::tuple<base::WeakPtr<media::AudioRendererImpl> > const&&&, std::__1::integer_sequence<unsigned long, 0ul>) + 80
13  libmedia.dylib                      0x000000010a7cf08c base::internal::Invoker<base::internal::BindState<void (media::AudioRendererImpl::*)(), base::WeakPtr<media::AudioRendererImpl> >, void ()>::Run(base::internal::BindStateBase*) + 44
14  libbase.dylib                       0x0000000108f97e3c base::OnceCallback<void ()>::Run() && + 92
15  libbase.dylib                       0x0000000108ff3599 base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*) + 1033
16  libbase.dylib                       0x00000001090c6b1d base::MessageLoop::RunTask(base::PendingTask*) + 877

I wonder if this could happen in real-world usage.

In the original test, the flow is as shown in "TrackStatusChangesAfterPipelineEnded chr.pdf". The buffering change to HAVE_ENOUGH luckily arrives while another track change is pending, and it's effectively ignored.

The test is flaky if the Demuxer implementation (not FFmpegDemuxer) takes some time to process OnEnabledAudioTracksChanged() and does it asynchronously -- and that's how I noticed the problem. When it fails, it's because the flow is like "TrackStatusChangesAfterPipelineEnded gone bad.pdf". Notice how the buffering change gets to be processed before the renderer learns about the track change.

I'm not sure how to proceed with this. Assuming the various buffering state transitions are correct, I could make the test more robust wrt timing by doing what the browser does: WebMediaPlayerImpl::OnEnded() sets the playback rate to 0.0, thus stopping the audio renderer callback and preventing the second OnRendererEnded(). I believe adding pipeline_->SetPlaybackRate(0) to PipelineIntegrationTestBase::OnEnded() mirrors this behavior. However, it causes PipelineIntegrationTest.SeekWhilePlaying to stall, I have yet to figure out why.
 

Deleted: TrackStatusChangesAfterPipelineEnded chr.pdf 3.5 KB

TrackStatusChangesAfterPipelineEnded chr.pdf 3.5 KB Download

Deleted: TrackStatusChangesAfterPipelineEnded gone bad.pdf 3.7 KB

TrackStatusChangesAfterPipelineEnded gone bad.pdf 3.7 KB Download