Fix sound corruption with multiple sound files (#2368).

last_push_end would be initialised to the position of the content,
meaning that content at (for example) 60s into the project would
be treated as the leader, and content much earlier would then be
considered finished by the code which checks ignore_streams_behind
(as its last push was more then 5s before the leader).

This caused audio corruption, shown up by the test here.

diff --git a/src/lib/player.cc b/src/lib/player.cc
index 732493f3b065d1c51bbbe339f315552229fd65e5..80b972dbe6a4d5ca2c600ce0bdeed3d9b89a1feb 100644 (file)
--- a/src/lib/player.cc
+++ b/src/lib/player.cc
@@ -369,7 +369,7 @@ Player::setup_pieces ()
        for (auto i: _pieces) {
                if (i->content->audio) {
                        for (auto j: i->content->audio->streams()) {
-                               _stream_states[j] = StreamState (i, i->content->position ());
+                               _stream_states[j] = StreamState(i);
                        }
                }
        }
@@ -800,21 +800,25 @@ Player::pass ()
 
        using state_pair = std::pair<AudioStreamPtr, StreamState>;
 
+       /* Find streams that have pushed */
+       std::vector<state_pair> have_pushed;
+       std::copy_if(_stream_states.begin(), _stream_states.end(), std::back_inserter(have_pushed), [](state_pair const& a) { return static_cast<bool>(a.second.last_push_end); });
+
        /* Find the 'leading' stream (i.e. the one that pushed data most recently) */
        auto latest_last_push_end = std::max_element(
-               _stream_states.begin(),
-               _stream_states.end(),
-               [](state_pair const& a, state_pair const& b) { return a.second.last_push_end < b.second.last_push_end; }
+               have_pushed.begin(),
+               have_pushed.end(),
+               [](state_pair const& a, state_pair const& b) { return a.second.last_push_end.get() < b.second.last_push_end.get(); }
                );
 
-       if (latest_last_push_end != _stream_states.end()) {
-               LOG_DEBUG_PLAYER("Leading audio stream is in %1 at %2", latest_last_push_end->second.piece->content->path(0), to_string(latest_last_push_end->second.last_push_end));
+       if (latest_last_push_end != have_pushed.end()) {
+               LOG_DEBUG_PLAYER("Leading audio stream is in %1 at %2", latest_last_push_end->second.piece->content->path(0), to_string(latest_last_push_end->second.last_push_end.get()));
        }
 
        /* Now make a list of those streams that are less than ignore_streams_behind behind the leader */
        std::map<AudioStreamPtr, StreamState> alive_stream_states;
        for (auto const& i: _stream_states) {
-               if ((latest_last_push_end->second.last_push_end - i.second.last_push_end) < dcpomatic::DCPTime::from_seconds(ignore_streams_behind)) {
+               if (!i.second.last_push_end || (latest_last_push_end->second.last_push_end.get() - i.second.last_push_end.get()) < dcpomatic::DCPTime::from_seconds(ignore_streams_behind)) {
                        alive_stream_states.insert(i);
                } else {
                        LOG_DEBUG_PLAYER("Ignoring stream %1 because it is too far behind", i.second.piece->content->path(0));
@@ -823,8 +827,9 @@ Player::pass ()
 
        auto pull_to = _playback_length.load();
        for (auto const& i: alive_stream_states) {
-               if (!i.second.piece->done && i.second.last_push_end < pull_to) {
-                       pull_to = i.second.last_push_end;
+               auto position = i.second.last_push_end.get_value_or(i.second.piece->content->position());
+               if (!i.second.piece->done && position < pull_to) {
+                       pull_to = position;
                }
        }
        if (!_silent.done() && _silent.position() < pull_to) {
@@ -1079,10 +1084,10 @@ Player::audio (weak_ptr<Piece> weak_piece, AudioStreamPtr stream, ContentAudio c
 
        /* Compute time in the DCP */
        auto time = resampled_audio_to_dcp (piece, content_audio.frame);
-       LOG_DEBUG_PLAYER("Received audio frame %1 at %2", content_audio.frame, to_string(time));
 
        /* And the end of this block in the DCP */
        auto end = time + DCPTime::from_frames(content_audio.audio->frames(), rfr);
+       LOG_DEBUG_PLAYER("Received audio frame %1 covering %2 to %3 (%4)", content_audio.frame, to_string(time), to_string(end), piece->content->path(0).filename());
 
        /* Remove anything that comes before the start or after the end of the content */
        if (time < piece->content->position()) {

diff --git a/src/lib/player.h b/src/lib/player.h
index 0add90e97c82aedc9d34c45eea2d1899a4296714..45dcd9900c256bce1996e3b92f4ec4699dfe83bd 100644 (file)
--- a/src/lib/player.h
+++ b/src/lib/player.h
@@ -227,13 +227,12 @@ private:
        public:
                StreamState () {}
 
-               StreamState (std::shared_ptr<Piece> p, dcpomatic::DCPTime l)
+               explicit StreamState(std::shared_ptr<Piece> p)
                        : piece(p)
-                       , last_push_end(l)
                {}
 
                std::shared_ptr<Piece> piece;
-               dcpomatic::DCPTime last_push_end;
+               boost::optional<dcpomatic::DCPTime> last_push_end;
        };
        std::map<AudioStreamPtr, StreamState> _stream_states;
 

diff --git a/test/player_test.cc b/test/player_test.cc
index 6b29cbc309fda2adeaaff586a16320dd09d59123..1cab293f17d47462f1956dada63d73c57faaa56c 100644 (file)
--- a/test/player_test.cc
+++ b/test/player_test.cc
@@ -28,10 +28,12 @@
 #include "lib/audio_buffers.h"
 #include "lib/butler.h"
 #include "lib/compose.hpp"
+#include "lib/config.h"
 #include "lib/content_factory.h"
 #include "lib/cross.h"
 #include "lib/dcp_content.h"
 #include "lib/dcp_content_type.h"
+#include "lib/dcpomatic_log.h"
 #include "lib/ffmpeg_content.h"
 #include "lib/film.h"
 #include "lib/image_content.h"
@@ -538,3 +540,20 @@ BOOST_AUTO_TEST_CASE (interleaved_subtitle_are_emitted_correctly)
        while (!player.pass()) {}
 }
 
+
+BOOST_AUTO_TEST_CASE(multiple_sound_files_bug)
+{
+       Config::instance()->set_log_types(Config::instance()->log_types() | LogEntry::TYPE_DEBUG_PLAYER);
+
+       auto A = content_factory(TestPaths::private_data() / "kook" / "1.wav").front();
+       auto B = content_factory(TestPaths::private_data() / "kook" / "2.wav").front();
+       auto C = content_factory(TestPaths::private_data() / "kook" / "3.wav").front();
+
+       auto film = new_test_film2("multiple_sound_files_bug", { A, B, C });
+       C->set_position(film, DCPTime(3840000));
+
+       make_and_verify_dcp(film, { dcp::VerificationNote::Code::MISSING_CPL_METADATA });
+
+       check_mxf_audio_file(TestPaths::private_data() / "kook" / "reference.mxf", dcp_file(film, "pcm_"));
+}
+