Logging improvements to allow prettier displays in the server GUI.
[dcpomatic.git] / src / lib / writer.cc
index 58b2b8a91ae866034e7badad4ea51b97b906c89f..0653daa57b497c820f76f27fc9f59c4a63b70b1f 100644 (file)
 #include <boost/foreach.hpp>
 #include <fstream>
 #include <cerrno>
+#include <iostream>
 
 #include "i18n.h"
 
-#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
-#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE);
-#define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
-#define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_WARNING);
-#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_WARNING);
-#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_ERROR);
+#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL);
+#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL);
+#define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_DEBUG_ENCODE);
+#define LOG_TIMING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_TIMING);
+#define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING);
+#define LOG_WARNING(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_WARNING);
+#define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR);
 
 /* OS X strikes again */
 #undef set_key
@@ -73,6 +75,8 @@ using boost::shared_ptr;
 using boost::weak_ptr;
 using boost::dynamic_pointer_cast;
 
+int const Writer::_info_size = 48;
+
 Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
        : _film (film)
        , _job (j)
@@ -147,11 +151,15 @@ Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
                throw InvalidSignerError ();
        }
 
-       _thread = new boost::thread (boost::bind (&Writer::thread, this));
-
        job->sub (_("Encoding image data"));
 }
 
+void
+Writer::start ()
+{
+       _thread = new boost::thread (boost::bind (&Writer::thread, this));
+}
+
 Writer::~Writer ()
 {
        terminate_thread (false);
@@ -469,6 +477,7 @@ Writer::terminate_thread (bool can_throw)
        _full_condition.notify_all ();
        lock.unlock ();
 
+       DCPOMATIC_ASSERT (_thread->joinable ());
        _thread->join ();
        if (can_throw) {
                rethrow ();
@@ -487,38 +496,46 @@ Writer::finish ()
 
        terminate_thread (true);
 
-       _picture_asset_writer->finalize ();
-       if (_sound_asset_writer) {
-               _sound_asset_writer->finalize ();
+       if (!_picture_asset_writer->finalize ()) {
+               /* Nothing was written to the picture asset */
+               _picture_asset.reset ();
        }
 
-       /* Hard-link the video asset into the DCP */
-       boost::filesystem::path video_from = _picture_asset->file ();
+       if (_sound_asset_writer) {
+               if (!_sound_asset_writer->finalize ()) {
+                       /* Nothing was written to the sound asset */
+                       _sound_asset.reset ();
+               }
+       }
 
-       boost::filesystem::path video_to;
-       video_to /= _film->dir (_film->dcp_name());
-       video_to /= video_asset_filename (_picture_asset);
+       /* Hard-link any video asset file into the DCP */
+       if (_picture_asset) {
+               boost::filesystem::path video_from = _picture_asset->file ();
+               boost::filesystem::path video_to;
+               video_to /= _film->dir (_film->dcp_name());
+               video_to /= video_asset_filename (_picture_asset);
 
-       boost::system::error_code ec;
-       boost::filesystem::create_hard_link (video_from, video_to, ec);
-       if (ec) {
-               LOG_WARNING_NC ("Hard-link failed; copying instead");
-               boost::filesystem::copy_file (video_from, video_to, ec);
+               boost::system::error_code ec;
+               boost::filesystem::create_hard_link (video_from, video_to, ec);
                if (ec) {
-                       LOG_ERROR ("Failed to copy video file from %1 to %2 (%3)", video_from.string(), video_to.string(), ec.message ());
-                       throw FileError (ec.message(), video_from);
+                       LOG_WARNING_NC ("Hard-link failed; copying instead");
+                       boost::filesystem::copy_file (video_from, video_to, ec);
+                       if (ec) {
+                               LOG_ERROR ("Failed to copy video file from %1 to %2 (%3)", video_from.string(), video_to.string(), ec.message ());
+                               throw FileError (ec.message(), video_from);
+                       }
                }
-       }
 
-       _picture_asset->set_file (video_to);
+               _picture_asset->set_file (video_to);
+       }
 
        /* Move the audio asset into the DCP */
-
        if (_sound_asset) {
                boost::filesystem::path audio_to;
                audio_to /= _film->dir (_film->dcp_name ());
                audio_to /= audio_asset_filename (_sound_asset);
 
+               boost::system::error_code ec;
                boost::filesystem::rename (_film->file (audio_asset_filename (_sound_asset)), audio_to, ec);
                if (ec) {
                        throw FileError (
@@ -542,18 +559,43 @@ Writer::finish ()
 
        shared_ptr<dcp::Reel> reel (new dcp::Reel ());
 
-       shared_ptr<dcp::MonoPictureAsset> mono = dynamic_pointer_cast<dcp::MonoPictureAsset> (_picture_asset);
-       if (mono) {
-               reel->add (shared_ptr<dcp::ReelPictureAsset> (new dcp::ReelMonoPictureAsset (mono, 0)));
-       }
+       shared_ptr<dcp::ReelPictureAsset> reel_picture_asset;
+
+       if (_picture_asset) {
+               /* We have made a picture asset of our own.  Put it into the reel */
+               shared_ptr<dcp::MonoPictureAsset> mono = dynamic_pointer_cast<dcp::MonoPictureAsset> (_picture_asset);
+               if (mono) {
+                       reel_picture_asset.reset (new dcp::ReelMonoPictureAsset (mono, 0));
+               }
 
-       shared_ptr<dcp::StereoPictureAsset> stereo = dynamic_pointer_cast<dcp::StereoPictureAsset> (_picture_asset);
-       if (stereo) {
-               reel->add (shared_ptr<dcp::ReelPictureAsset> (new dcp::ReelStereoPictureAsset (stereo, 0)));
+               shared_ptr<dcp::StereoPictureAsset> stereo = dynamic_pointer_cast<dcp::StereoPictureAsset> (_picture_asset);
+               if (stereo && boost::filesystem::exists (stereo->file ())) {
+                       reel_picture_asset.reset (new dcp::ReelStereoPictureAsset (stereo, 0));
+               }
+       } else {
+               /* We don't have a picture asset of our own; maybe we need to reference one */
+               /* XXX: this is all a hack */
+               BOOST_FOREACH (shared_ptr<dcp::ReelAsset> i, _reel_assets) {
+                       shared_ptr<dcp::ReelPictureAsset> j = dynamic_pointer_cast<dcp::ReelPictureAsset> (i);
+                       if (j) {
+                               reel_picture_asset = j;
+                       }
+               }
        }
 
+       reel->add (reel_picture_asset);
+
        if (_sound_asset) {
+               /* We have made a sound asset of our own.  Put it into the reel */
                reel->add (shared_ptr<dcp::ReelSoundAsset> (new dcp::ReelSoundAsset (_sound_asset, 0)));
+       } else {
+               /* We don't have a sound asset of our own; maybe we need to reference one */
+               /* XXX: this is all a hack */
+               BOOST_FOREACH (shared_ptr<dcp::ReelAsset> i, _reel_assets) {
+                       if (dynamic_pointer_cast<dcp::ReelSoundAsset> (i)) {
+                               reel->add (i);
+                       }
+               }
        }
 
        if (_subtitle_asset) {
@@ -575,6 +617,13 @@ Writer::finish ()
                        boost::filesystem::create_directories (directory);
                        _subtitle_asset->write (directory / ("sub_" + _subtitle_asset->id() + ".xml"));
                } else {
+                       /* All our assets should be the same length; use the picture asset length here
+                          as a reference to set the subtitle one.
+                       */
+                       dynamic_pointer_cast<dcp::SMPTESubtitleAsset>(_subtitle_asset)->set_intrinsic_duration (
+                               reel_picture_asset->intrinsic_duration ()
+                               );
+
                        _subtitle_asset->write (
                                _film->dir (_film->dcp_name ()) / ("sub_" + _subtitle_asset->id() + ".mxf")
                                );
@@ -584,10 +633,18 @@ Writer::finish ()
                                   new dcp::ReelSubtitleAsset (
                                           _subtitle_asset,
                                           dcp::Fraction (_film->video_frame_rate(), 1),
-                                          _picture_asset->intrinsic_duration (),
+                                          reel_picture_asset->intrinsic_duration (),
                                           0
                                           )
                                   ));
+       } else {
+               /* We don't have a subtitle asset of our own; maybe we need to reference one */
+               /* XXX: this is all a hack */
+               BOOST_FOREACH (shared_ptr<dcp::ReelAsset> i, _reel_assets) {
+                       if (dynamic_pointer_cast<dcp::ReelSubtitleAsset> (i)) {
+                               reel->add (i);
+                       }
+               }
        }
 
        cpl->add (reel);
@@ -596,7 +653,9 @@ Writer::finish ()
        DCPOMATIC_ASSERT (job);
 
        job->sub (_("Computing image digest"));
-       _picture_asset->hash (boost::bind (&Job::set_progress, job.get(), _1, false));
+       if (_picture_asset) {
+               _picture_asset->hash (boost::bind (&Job::set_progress, job.get(), _1, false));
+       }
 
        if (_sound_asset) {
                job->sub (_("Computing audio digest"));
@@ -632,77 +691,73 @@ Writer::finish ()
                );
 }
 
-bool
-Writer::check_existing_picture_asset_frame (FILE* asset, int f, Eyes eyes)
-{
-       /* Read the frame info as written */
-       FILE* file = fopen_boost (_film->info_file (), "rb");
-       if (!file) {
-               LOG_GENERAL ("Existing frame %1 has no info file", f);
-               return false;
-       }
-
-       dcp::FrameInfo info = read_frame_info (file, f, eyes);
-       fclose (file);
-       if (info.size == 0) {
-               LOG_GENERAL ("Existing frame %1 has no info file", f);
-               return false;
-       }
-
-       /* Read the data from the asset and hash it */
-       dcpomatic_fseek (asset, info.offset, SEEK_SET);
-       Data data (info.size);
-       size_t const read = fread (data.data().get(), 1, data.size(), asset);
-       if (read != static_cast<size_t> (data.size ())) {
-               LOG_GENERAL ("Existing frame %1 is incomplete", f);
-               return false;
-       }
-
-       MD5Digester digester;
-       digester.add (data.data().get(), data.size());
-       if (digester.get() != info.hash) {
-               LOG_GENERAL ("Existing frame %1 failed hash check", f);
-               return false;
-       }
-
-       return true;
-}
-
 void
 Writer::check_existing_picture_asset ()
 {
        /* Try to open the existing asset */
-       FILE* asset = fopen_boost (_picture_asset->file(), "rb");
-       if (!asset) {
+       FILE* asset_file = fopen_boost (_picture_asset->file(), "rb");
+       if (!asset_file) {
                LOG_GENERAL ("Could not open existing asset at %1 (errno=%2)", _picture_asset->file().string(), errno);
                return;
        }
 
-       while (true) {
+       /* Offset of the last dcp::FrameInfo in the info file */
+       int const n = (boost::filesystem::file_size (_film->info_file ()) / _info_size) - 1;
+
+       FILE* info_file = fopen_boost (_film->info_file (), "rb");
+       if (!info_file) {
+               LOG_GENERAL_NC ("Could not open film info file");
+               fclose (asset_file);
+               return;
+       }
+
+       if (_film->three_d ()) {
+               /* Start looking at the last left frame */
+               _first_nonexistant_frame = n / 2;
+       } else {
+               _first_nonexistant_frame = n;
+       }
 
-               shared_ptr<Job> job = _job.lock ();
-               DCPOMATIC_ASSERT (job);
+       bool ok = false;
 
-               job->set_progress_unknown ();
+       while (!ok) {
+               /* Read the data from the info file; for 3D we just check the left
+                  frames until we find a good one.
+               */
+               dcp::FrameInfo info = read_frame_info (info_file, _first_nonexistant_frame, _film->three_d () ? EYES_LEFT : EYES_BOTH);
 
-               if (_film->three_d ()) {
-                       if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_LEFT)) {
-                               break;
-                       }
-                       if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_RIGHT)) {
-                               break;
-                       }
+               ok = true;
+
+               /* Read the data from the asset and hash it */
+               dcpomatic_fseek (asset_file, info.offset, SEEK_SET);
+               Data data (info.size);
+               size_t const read = fread (data.data().get(), 1, data.size(), asset_file);
+               if (read != static_cast<size_t> (data.size ())) {
+                       LOG_GENERAL ("Existing frame %1 is incomplete", _first_nonexistant_frame);
+                       ok = false;
                } else {
-                       if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_BOTH)) {
-                               break;
+                       MD5Digester digester;
+                       digester.add (data.data().get(), data.size());
+                       if (digester.get() != info.hash) {
+                               LOG_GENERAL ("Existing frame %1 failed hash check", _first_nonexistant_frame);
+                               ok = false;
                        }
                }
 
-               LOG_DEBUG_ENCODE ("Have existing frame %1", _first_nonexistant_frame);
+               if (!ok) {
+                       --_first_nonexistant_frame;
+               }
+       }
+
+       if (!_film->three_d ()) {
+               /* If we are doing 3D we might have found a good L frame with no R, so only
+                  do this if we're in 2D and we've just found a good B(oth) frame.
+               */
                ++_first_nonexistant_frame;
        }
 
-       fclose (asset);
+       fclose (asset_file);
+       fclose (info_file);
 }
 
 /** @param frame Frame index.
@@ -740,7 +795,9 @@ Writer::write (PlayerSubtitles subs)
                        s->set_content_title_text (_film->name ());
                        s->set_language (lang);
                        s->set_edit_rate (dcp::Fraction (_film->video_frame_rate (), 1));
+                       s->set_reel_number (1);
                        s->set_time_code_rate (_film->video_frame_rate ());
+                       s->set_start_time (dcp::Time ());
                        _subtitle_asset = s;
                }
        }
@@ -782,15 +839,13 @@ Writer::set_encoder_threads (int threads)
 long
 Writer::frame_info_position (int frame, Eyes eyes) const
 {
-       static int const info_size = 48;
-
        switch (eyes) {
        case EYES_BOTH:
-               return frame * info_size;
+               return frame * _info_size;
        case EYES_LEFT:
-               return frame * info_size * 2;
+               return frame * _info_size * 2;
        case EYES_RIGHT:
-               return frame * info_size * 2 + info_size;
+               return frame * _info_size * 2 + _info_size;
        default:
                DCPOMATIC_ASSERT (false);
        }
@@ -813,3 +868,9 @@ Writer::read_frame_info (FILE* file, int frame, Eyes eyes) const
 
        return info;
 }
+
+void
+Writer::write (shared_ptr<dcp::ReelAsset> asset)
+{
+       _reel_assets.push_back (asset);
+}