X-Git-Url: https://git.carlh.net/gitweb/?a=blobdiff_plain;f=src%2Flib%2Fwriter.cc;h=f126d5b62c010958ecc328996a4d14eec2c99774;hb=27867be66579551018c926ed3339624e463c1b08;hp=306f6d7f4968c387965014baf084e43668bee5f6;hpb=7f2e74604a51b984e4c8cbb5d5f4bb642677ec00;p=dcpomatic.git diff --git a/src/lib/writer.cc b/src/lib/writer.cc index 306f6d7f4..f126d5b62 100644 --- a/src/lib/writer.cc +++ b/src/lib/writer.cc @@ -17,34 +17,48 @@ */ -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include #include "writer.h" #include "compose.hpp" #include "film.h" #include "ratio.h" #include "log.h" -#include "dcp_video_frame.h" +#include "dcp_video.h" #include "dcp_content_type.h" -#include "player.h" #include "audio_mapping.h" #include "config.h" #include "job.h" #include "cross.h" #include "audio_buffers.h" +#include "md5_digester.h" +#include "encoded_data.h" +#include "version.h" +#include "font.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include #include "i18n.h" +#define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL); +#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_DEBUG(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG); +#define LOG_DEBUG_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_DEBUG); + /* OS X strikes again */ #undef set_key @@ -53,7 +67,6 @@ using std::pair; using std::string; using std::list; using std::cout; -using std::stringstream; using boost::shared_ptr; using boost::weak_ptr; using boost::dynamic_pointer_cast; @@ -77,7 +90,7 @@ Writer::Writer (shared_ptr f, weak_ptr j) boost::filesystem::remove_all (_film->dir (_film->dcp_name ())); shared_ptr job = _job.lock (); - assert (job); + DCPOMATIC_ASSERT (job); job->sub (_("Checking existing image data")); check_existing_picture_mxf (); @@ -118,6 +131,11 @@ Writer::Writer (shared_ptr f, weak_ptr j) _sound_mxf_writer = _sound_mxf->start_write (_film->directory() / _film->audio_mxf_filename(), _film->interop() ? dcp::INTEROP : dcp::SMPTE); } + /* Check that the signer is OK if we need one */ + if (_film->is_signed() && !Config::instance()->signer()->valid ()) { + throw InvalidSignerError (); + } + _thread = new boost::thread (boost::bind (&Writer::thread, this)); job->sub (_("Encoding image data")); @@ -134,6 +152,7 @@ Writer::write (shared_ptr encoded, int frame, Eyes eyes) boost::mutex::scoped_lock lock (_mutex); while (_queued_full_in_memory > _maximum_frames_in_memory) { + /* The queue is too big; wait until that is sorted out */ _full_condition.wait (lock); } @@ -155,7 +174,8 @@ Writer::write (shared_ptr encoded, int frame, Eyes eyes) _queue.push_back (qi); ++_queued_full_in_memory; } - + + /* Now there's something to do: wake anything wait()ing on _empty_condition */ _empty_condition.notify_all (); } @@ -165,6 +185,7 @@ Writer::fake_write (int frame, Eyes eyes) boost::mutex::scoped_lock lock (_mutex); while (_queued_full_in_memory > _maximum_frames_in_memory) { + /* The queue is too big; wait until that is sorted out */ _full_condition.wait (lock); } @@ -186,6 +207,7 @@ Writer::fake_write (int frame, Eyes eyes) _queue.push_back (qi); } + /* Now there's something to do: wake anything wait()ing on _empty_condition */ _empty_condition.notify_all (); } @@ -232,27 +254,54 @@ void Writer::thread () try { - while (1) + while (true) { boost::mutex::scoped_lock lock (_mutex); - while (1) { + /* This is for debugging only */ + bool done_something = false; + + while (true) { if (_finish || _queued_full_in_memory > _maximum_frames_in_memory || have_sequenced_image_at_queue_head ()) { + /* We've got something to do: go and do it */ break; } - TIMING (N_("writer sleeps with a queue of %1"), _queue.size()); + /* Nothing to do: wait until something happens which may indicate that we do */ + LOG_TIMING (N_("writer sleeps with a queue of %1"), _queue.size()); _empty_condition.wait (lock); - TIMING (N_("writer wakes with a queue of %1"), _queue.size()); + LOG_TIMING (N_("writer wakes with a queue of %1"), _queue.size()); } if (_finish && _queue.empty()) { return; } + /* We stop here if we have been asked to finish, and if either the queue + is empty or we do not have a sequenced image at its head (if this is the + case we will never terminate as no new frames will be sent once + _finish is true). + */ + if (_finish && (!have_sequenced_image_at_queue_head() || _queue.empty())) { + done_something = true; + /* (Hopefully temporarily) log anything that was not written */ + if (!_queue.empty() && !have_sequenced_image_at_queue_head()) { + LOG_WARNING (N_("Finishing writer with a left-over queue of %1:"), _queue.size()); + for (list::const_iterator i = _queue.begin(); i != _queue.end(); ++i) { + if (i->type == QueueItem::FULL) { + LOG_WARNING (N_("- type FULL, frame %1, eyes %2"), i->frame, i->eyes); + } else { + LOG_WARNING (N_("- type FAKE, size %1, frame %2, eyes %3"), i->size, i->frame, i->eyes); + } + } + LOG_WARNING (N_("Last written frame %1, last written eyes %2"), _last_written_frame, _last_written_eyes); + } + return; + } /* Write any frames that we can write; i.e. those that are in sequence. */ while (have_sequenced_image_at_queue_head ()) { + done_something = true; QueueItem qi = _queue.front (); _queue.pop_front (); if (qi.type == QueueItem::FULL && qi.encoded) { @@ -263,7 +312,7 @@ try switch (qi.type) { case QueueItem::FULL: { - _film->log()->log (String::compose (N_("Writer FULL-writes %1 to MXF"), qi.frame)); + LOG_GENERAL (N_("Writer FULL-writes %1 to MXF"), qi.frame); if (!qi.encoded) { qi.encoded.reset (new EncodedData (_film->j2c_path (qi.frame, qi.eyes, false))); } @@ -275,7 +324,7 @@ try break; } case QueueItem::FAKE: - _film->log()->log (String::compose (N_("Writer FAKE-writes %1 to MXF"), qi.frame)); + LOG_GENERAL (N_("Writer FAKE-writes %1 to MXF"), qi.frame); _picture_mxf_writer->fake_write (qi.size); _last_written[qi.eyes].reset (); ++_fake_written; @@ -287,7 +336,7 @@ try _last_written_eyes = qi.eyes; shared_ptr job = _job.lock (); - assert (job); + DCPOMATIC_ASSERT (job); int64_t total = _film->length().frames (_film->video_frame_rate ()); if (_film->three_d ()) { /* _full_written and so on are incremented for each eye, so we need to double the total @@ -301,6 +350,7 @@ try } while (_queued_full_in_memory > _maximum_frames_in_memory) { + done_something = true; /* Too many frames in memory which can't yet be written to the stream. Write some FULL frames to disk. */ @@ -312,18 +362,17 @@ try ++i; } - assert (i != _queue.rend()); + DCPOMATIC_ASSERT (i != _queue.rend()); QueueItem qi = *i; ++_pushed_to_disk; lock.unlock (); - _film->log()->log ( - String::compose ( - "Writer full (awaiting %1 [last eye was %2]); pushes %3 to disk", - _last_written_frame + 1, - _last_written_eyes, qi.frame) + LOG_GENERAL ( + "Writer full (awaiting %1 [last eye was %2]); pushes %3 to disk", + _last_written_frame + 1, + _last_written_eyes, qi.frame ); qi.encoded->write (_film, qi.frame, qi.eyes); @@ -332,6 +381,15 @@ try --_queued_full_in_memory; } + if (!done_something) { + LOG_DEBUG_NC ("Writer loop ran without doing anything"); + LOG_DEBUG ("_queued_full_in_memory=%1", _queued_full_in_memory); + LOG_DEBUG ("_queue_size=%1", _queue.size ()); + LOG_DEBUG ("_finish=%1", _finish); + LOG_DEBUG ("_last_written_frame=%1", _last_written_frame); + } + + /* The queue has probably just gone down a bit; notify anything wait()ing on _full_condition */ _full_condition.notify_all (); } } @@ -388,9 +446,12 @@ Writer::finish () boost::system::error_code ec; boost::filesystem::create_hard_link (video_from, video_to, ec); if (ec) { - /* hard link failed; copy instead */ - boost::filesystem::copy_file (video_from, video_to); - _film->log()->log ("Hard-link failed; fell back to copying"); + 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_mxf->set_file (video_to); @@ -441,11 +502,25 @@ Writer::finish () reel->add (shared_ptr (new dcp::ReelSoundAsset (_sound_mxf, 0))); dcp.add (_sound_mxf); } + + if (_subtitle_content) { + _subtitle_content->write_xml (_film->dir (_film->dcp_name ()) / _film->subtitle_xml_filename ()); + reel->add (shared_ptr ( + new dcp::ReelSubtitleAsset ( + _subtitle_content, + dcp::Fraction (_film->video_frame_rate(), 1), + _picture_mxf->intrinsic_duration (), + 0 + ) + )); + + dcp.add (_subtitle_content); + } cpl->add (reel); shared_ptr job = _job.lock (); - assert (job); + DCPOMATIC_ASSERT (job); job->sub (_("Computing image digest")); _picture_mxf->hash (boost::bind (&Job::set_progress, job.get(), _1, false)); @@ -455,13 +530,24 @@ Writer::finish () _sound_mxf->hash (boost::bind (&Job::set_progress, job.get(), _1, false)); } - dcp::XMLMetadata meta = Config::instance()->dcp_metadata (); + dcp::XMLMetadata meta; + meta.issuer = Config::instance()->dcp_issuer (); + meta.creator = String::compose ("DCP-o-matic %1 %2", dcpomatic_version, dcpomatic_git_commit); meta.set_issue_date_now (); - dcp.write_xml (_film->interop () ? dcp::INTEROP : dcp::SMPTE, meta, _film->is_signed() ? make_signer () : shared_ptr ()); + shared_ptr signer; + if (_film->is_signed ()) { + signer = Config::instance()->signer (); + /* We did check earlier, but check again here to be on the safe side */ + if (!signer->valid ()) { + throw InvalidSignerError (); + } + } + + dcp.write_xml (_film->interop () ? dcp::INTEROP : dcp::SMPTE, meta, signer); - _film->log()->log ( - String::compose (N_("Wrote %1 FULL, %2 FAKE, %3 pushed to disk"), _full_written, _fake_written, _pushed_to_disk) + LOG_GENERAL ( + N_("Wrote %1 FULL, %2 FAKE, %3 pushed to disk"), _full_written, _fake_written, _pushed_to_disk ); } @@ -471,14 +557,14 @@ Writer::check_existing_picture_mxf_frame (FILE* mxf, int f, Eyes eyes) /* Read the frame info as written */ FILE* ifi = fopen_boost (_film->info_path (f, eyes), "r"); if (!ifi) { - _film->log()->log (String::compose ("Existing frame %1 has no info file", f)); + LOG_GENERAL ("Existing frame %1 has no info file", f); return false; } dcp::FrameInfo info (ifi); fclose (ifi); if (info.size == 0) { - _film->log()->log (String::compose ("Existing frame %1 has no info file", f)); + LOG_GENERAL ("Existing frame %1 has no info file", f); return false; } @@ -487,13 +573,14 @@ Writer::check_existing_picture_mxf_frame (FILE* mxf, int f, Eyes eyes) EncodedData data (info.size); size_t const read = fread (data.data(), 1, data.size(), mxf); if (read != static_cast (data.size ())) { - _film->log()->log (String::compose ("Existing frame %1 is incomplete", f)); + LOG_GENERAL ("Existing frame %1 is incomplete", f); return false; } - - string const existing_hash = md5_digest (data.data(), data.size()); - if (existing_hash != info.hash) { - _film->log()->log (String::compose ("Existing frame %1 failed hash check", f)); + + MD5Digester digester; + digester.add (data.data(), data.size()); + if (digester.get() != info.hash) { + LOG_GENERAL ("Existing frame %1 failed hash check", f); return false; } @@ -509,7 +596,7 @@ Writer::check_existing_picture_mxf () p /= _film->internal_video_mxf_filename (); FILE* mxf = fopen_boost (p, "rb"); if (!mxf) { - _film->log()->log (String::compose ("Could not open existing MXF at %1 (errno=%2)", p.string(), errno)); + LOG_GENERAL ("Could not open existing MXF at %1 (errno=%2)", p.string(), errno); return; } @@ -518,10 +605,10 @@ Writer::check_existing_picture_mxf () ++N; } - while (1) { + while (true) { shared_ptr job = _job.lock (); - assert (job); + DCPOMATIC_ASSERT (job); if (N > 0) { job->set_progress (float (_first_nonexistant_frame) / N); @@ -540,7 +627,7 @@ Writer::check_existing_picture_mxf () } } - _film->log()->log (String::compose ("Have existing frame %1", _first_nonexistant_frame)); + LOG_GENERAL ("Have existing frame %1", _first_nonexistant_frame); ++_first_nonexistant_frame; } @@ -559,6 +646,39 @@ Writer::can_fake_write (int frame) const return (frame != 0 && frame < _first_nonexistant_frame); } +void +Writer::write (PlayerSubtitles subs) +{ + if (subs.text.empty ()) { + return; + } + + if (!_subtitle_content) { + _subtitle_content.reset (new dcp::InteropSubtitleContent (_film->name(), _film->subtitle_language ())); + } + + for (list::const_iterator i = subs.text.begin(); i != subs.text.end(); ++i) { + _subtitle_content->add (*i); + } +} + +void +Writer::write (list > fonts) +{ + if (fonts.empty ()) { + return; + } + + if (!_subtitle_content) { + _subtitle_content.reset (new dcp::InteropSubtitleContent (_film->name(), _film->subtitle_language ())); + } + + for (list >::const_iterator i = fonts.begin(); i != fonts.end(); ++i) { + /* XXX: this LiberationSans-Regular needs to be a path to a DCP-o-matic-distributed copy */ + _subtitle_content->add_font ((*i)->id, (*i)->file.get_value_or ("LiberationSans-Regular.ttf").leaf().string ()); + } +} + bool operator< (QueueItem const & a, QueueItem const & b) {