Remove rather wordy debug for #953, not seen for a while.
[dcpomatic.git] / src / lib / reel_writer.cc
1 /*
2     Copyright (C) 2012-2016 Carl Hetherington <cth@carlh.net>
3
4     This file is part of DCP-o-matic.
5
6     DCP-o-matic is free software; you can redistribute it and/or modify
7     it under the terms of the GNU General Public License as published by
8     the Free Software Foundation; either version 2 of the License, or
9     (at your option) any later version.
10
11     DCP-o-matic is distributed in the hope that it will be useful,
12     but WITHOUT ANY WARRANTY; without even the implied warranty of
13     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
14     GNU General Public License for more details.
15
16     You should have received a copy of the GNU General Public License
17     along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
18
19 */
20
21 #include "reel_writer.h"
22 #include "film.h"
23 #include "cross.h"
24 #include "job.h"
25 #include "log.h"
26 #include "digester.h"
27 #include "font.h"
28 #include "compose.hpp"
29 #include "audio_buffers.h"
30 #include <dcp/mono_picture_asset.h>
31 #include <dcp/stereo_picture_asset.h>
32 #include <dcp/sound_asset.h>
33 #include <dcp/sound_asset_writer.h>
34 #include <dcp/reel.h>
35 #include <dcp/reel_mono_picture_asset.h>
36 #include <dcp/reel_stereo_picture_asset.h>
37 #include <dcp/reel_sound_asset.h>
38 #include <dcp/reel_subtitle_asset.h>
39 #include <dcp/dcp.h>
40 #include <dcp/cpl.h>
41 #include <dcp/certificate_chain.h>
42 #include <dcp/interop_subtitle_asset.h>
43 #include <dcp/smpte_subtitle_asset.h>
44 #include <dcp/raw_convert.h>
45 #include <boost/foreach.hpp>
46
47 #include "i18n.h"
48
49 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL);
50 #define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL);
51 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING);
52 #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR);
53
54 using std::list;
55 using std::string;
56 using std::cout;
57 using boost::shared_ptr;
58 using boost::optional;
59 using boost::dynamic_pointer_cast;
60 using dcp::Data;
61 using dcp::raw_convert;
62
63 int const ReelWriter::_info_size = 48;
64
65 ReelWriter::ReelWriter (
66         shared_ptr<const Film> film, DCPTimePeriod period, shared_ptr<Job> job, int reel_index, int reel_count, optional<string> content_summary
67         )
68         : _film (film)
69         , _period (period)
70         , _last_written_video_frame (-1)
71         , _last_written_eyes (EYES_RIGHT)
72         , _reel_index (reel_index)
73         , _reel_count (reel_count)
74         , _content_summary (content_summary)
75 {
76         /* Create our picture asset in a subdirectory, named according to those
77            film's parameters which affect the video output.  We will hard-link
78            it into the DCP later.
79         */
80
81         dcp::Standard const standard = _film->interop() ? dcp::INTEROP : dcp::SMPTE;
82
83         if (_film->three_d ()) {
84                 _picture_asset.reset (new dcp::StereoPictureAsset (dcp::Fraction (_film->video_frame_rate(), 1), standard));
85         } else {
86                 _picture_asset.reset (new   dcp::MonoPictureAsset (dcp::Fraction (_film->video_frame_rate(), 1), standard));
87         }
88
89         _picture_asset->set_size (_film->frame_size ());
90
91         if (_film->encrypted ()) {
92                 _picture_asset->set_key (_film->key ());
93                 _picture_asset->set_context_id (_film->context_id ());
94         }
95
96         _picture_asset->set_file (
97                 _film->internal_video_asset_dir() / _film->internal_video_asset_filename(_period)
98                 );
99
100         job->sub (_("Checking existing image data"));
101         _first_nonexistant_frame = check_existing_picture_asset ();
102
103         _picture_asset_writer = _picture_asset->start_write (
104                 _film->internal_video_asset_dir() / _film->internal_video_asset_filename(_period),
105                 _first_nonexistant_frame > 0
106                 );
107
108         if (_film->audio_channels ()) {
109                 _sound_asset.reset (
110                         new dcp::SoundAsset (dcp::Fraction (_film->video_frame_rate(), 1), _film->audio_frame_rate (), _film->audio_channels (), standard)
111                         );
112
113                 if (_film->encrypted ()) {
114                         _sound_asset->set_key (_film->key ());
115                 }
116
117                 DCPOMATIC_ASSERT (_film->directory());
118
119                 /* Write the sound asset into the film directory so that we leave the creation
120                    of the DCP directory until the last minute.
121                 */
122                 _sound_asset_writer = _sound_asset->start_write (
123                         _film->directory().get() / audio_asset_filename (_sound_asset, _reel_index, _reel_count, _content_summary)
124                         );
125         }
126 }
127
128 /** @param frame reel-relative frame */
129 void
130 ReelWriter::write_frame_info (Frame frame, Eyes eyes, dcp::FrameInfo info) const
131 {
132         FILE* file = 0;
133         boost::filesystem::path info_file = _film->info_file (_period);
134
135         bool const read = boost::filesystem::exists (info_file);
136
137         if (read) {
138                 file = fopen_boost (info_file, "r+b");
139         } else {
140                 file = fopen_boost (info_file, "wb");
141         }
142         if (!file) {
143                 throw OpenFileError (info_file, errno, read);
144         }
145         dcpomatic_fseek (file, frame_info_position (frame, eyes), SEEK_SET);
146         fwrite (&info.offset, sizeof (info.offset), 1, file);
147         fwrite (&info.size, sizeof (info.size), 1, file);
148         fwrite (info.hash.c_str(), 1, info.hash.size(), file);
149         fclose (file);
150 }
151
152 dcp::FrameInfo
153 ReelWriter::read_frame_info (FILE* file, Frame frame, Eyes eyes) const
154 {
155         dcp::FrameInfo info;
156         dcpomatic_fseek (file, frame_info_position (frame, eyes), SEEK_SET);
157         fread (&info.offset, sizeof (info.offset), 1, file);
158         fread (&info.size, sizeof (info.size), 1, file);
159
160         char hash_buffer[33];
161         fread (hash_buffer, 1, 32, file);
162         hash_buffer[32] = '\0';
163         info.hash = hash_buffer;
164
165         return info;
166 }
167
168 long
169 ReelWriter::frame_info_position (Frame frame, Eyes eyes) const
170 {
171         switch (eyes) {
172         case EYES_BOTH:
173                 return frame * _info_size;
174         case EYES_LEFT:
175                 return frame * _info_size * 2;
176         case EYES_RIGHT:
177                 return frame * _info_size * 2 + _info_size;
178         default:
179                 DCPOMATIC_ASSERT (false);
180         }
181
182         DCPOMATIC_ASSERT (false);
183 }
184
185 Frame
186 ReelWriter::check_existing_picture_asset ()
187 {
188         DCPOMATIC_ASSERT (_picture_asset->file());
189         boost::filesystem::path asset = _picture_asset->file().get();
190
191         /* If there is an existing asset, break any hard links to it as we are about to change its contents
192            (if only by changing the IDs); see #1126.
193         */
194
195         if (boost::filesystem::exists(asset) && boost::filesystem::hard_link_count(asset) > 1) {
196                 boost::filesystem::copy_file (asset, asset.string() + ".tmp");
197                 boost::filesystem::remove (asset);
198                 boost::filesystem::rename (asset.string() + ".tmp", asset);
199         }
200
201         /* Try to open the existing asset */
202         FILE* asset_file = fopen_boost (asset, "rb");
203         if (!asset_file) {
204                 LOG_GENERAL ("Could not open existing asset at %1 (errno=%2)", asset.string(), errno);
205                 return 0;
206         } else {
207                 LOG_GENERAL ("Opened existing asset at %1", asset.string());
208         }
209
210         /* Offset of the last dcp::FrameInfo in the info file */
211         int const n = (boost::filesystem::file_size (_film->info_file(_period)) / _info_size) - 1;
212         LOG_GENERAL ("The last FI is %1; info file is %2, info size %3", n, boost::filesystem::file_size (_film->info_file(_period)), _info_size);
213
214         FILE* info_file = fopen_boost (_film->info_file(_period), "rb");
215         if (!info_file) {
216                 LOG_GENERAL_NC ("Could not open film info file");
217                 fclose (asset_file);
218                 return 0;
219         }
220
221         Frame first_nonexistant_frame;
222         if (_film->three_d ()) {
223                 /* Start looking at the last left frame */
224                 first_nonexistant_frame = n / 2;
225         } else {
226                 first_nonexistant_frame = n;
227         }
228
229         while (!existing_picture_frame_ok(asset_file, info_file, first_nonexistant_frame) && first_nonexistant_frame > 0) {
230                 --first_nonexistant_frame;
231         }
232
233         if (!_film->three_d() && first_nonexistant_frame > 0) {
234                 /* If we are doing 3D we might have found a good L frame with no R, so only
235                    do this if we're in 2D and we've just found a good B(oth) frame.
236                 */
237                 ++first_nonexistant_frame;
238         }
239
240         LOG_GENERAL ("Proceeding with first nonexistant frame %1", first_nonexistant_frame);
241
242         fclose (asset_file);
243         fclose (info_file);
244
245         return first_nonexistant_frame;
246 }
247
248 void
249 ReelWriter::write (optional<Data> encoded, Frame frame, Eyes eyes)
250 {
251         dcp::FrameInfo fin = _picture_asset_writer->write (encoded->data().get (), encoded->size());
252         write_frame_info (frame, eyes, fin);
253         _last_written[eyes] = encoded;
254         _last_written_video_frame = frame;
255         _last_written_eyes = eyes;
256 }
257
258 void
259 ReelWriter::fake_write (Frame frame, Eyes eyes, int size)
260 {
261         _picture_asset_writer->fake_write (size);
262         _last_written_video_frame = frame;
263         _last_written_eyes = eyes;
264 }
265
266 void
267 ReelWriter::repeat_write (Frame frame, Eyes eyes)
268 {
269         dcp::FrameInfo fin = _picture_asset_writer->write (
270                 _last_written[eyes]->data().get(),
271                 _last_written[eyes]->size()
272                 );
273         write_frame_info (frame, eyes, fin);
274         _last_written_video_frame = frame;
275         _last_written_eyes = eyes;
276 }
277
278 void
279 ReelWriter::finish ()
280 {
281         if (!_picture_asset_writer->finalize ()) {
282                 /* Nothing was written to the picture asset */
283                 LOG_GENERAL ("Nothing was written to reel %1 of %2", _reel_index, _reel_count);
284                 _picture_asset.reset ();
285         }
286
287         if (_sound_asset_writer && !_sound_asset_writer->finalize ()) {
288                 /* Nothing was written to the sound asset */
289                 _sound_asset.reset ();
290         }
291
292         /* Hard-link any video asset file into the DCP */
293         if (_picture_asset) {
294                 DCPOMATIC_ASSERT (_picture_asset->file());
295                 boost::filesystem::path video_from = _picture_asset->file().get();
296                 boost::filesystem::path video_to;
297                 video_to /= _film->dir (_film->dcp_name());
298                 video_to /= video_asset_filename (_picture_asset, _reel_index, _reel_count, _content_summary);
299
300                 boost::system::error_code ec;
301                 boost::filesystem::create_hard_link (video_from, video_to, ec);
302                 if (ec) {
303                         LOG_WARNING_NC ("Hard-link failed; copying instead");
304                         boost::filesystem::copy_file (video_from, video_to, ec);
305                         if (ec) {
306                                 LOG_ERROR ("Failed to copy video file from %1 to %2 (%3)", video_from.string(), video_to.string(), ec.message ());
307                                 throw FileError (ec.message(), video_from);
308                         }
309                 }
310
311                 _picture_asset->set_file (video_to);
312         }
313
314         /* Move the audio asset into the DCP */
315         if (_sound_asset) {
316                 boost::filesystem::path audio_to;
317                 audio_to /= _film->dir (_film->dcp_name ());
318                 string const aaf = audio_asset_filename (_sound_asset, _reel_index, _reel_count, _content_summary);
319                 audio_to /= aaf;
320
321                 boost::system::error_code ec;
322                 boost::filesystem::rename (_film->file (aaf), audio_to, ec);
323                 if (ec) {
324                         throw FileError (
325                                 String::compose (_("could not move audio asset into the DCP (%1)"), ec.value ()), aaf
326                                 );
327                 }
328
329                 _sound_asset->set_file (audio_to);
330         }
331 }
332
333 shared_ptr<dcp::Reel>
334 ReelWriter::create_reel (list<ReferencedReelAsset> const & refs, list<shared_ptr<Font> > const & fonts)
335 {
336         shared_ptr<dcp::Reel> reel (new dcp::Reel ());
337
338         shared_ptr<dcp::ReelPictureAsset> reel_picture_asset;
339
340         if (_picture_asset) {
341                 /* We have made a picture asset of our own.  Put it into the reel */
342                 shared_ptr<dcp::MonoPictureAsset> mono = dynamic_pointer_cast<dcp::MonoPictureAsset> (_picture_asset);
343                 if (mono) {
344                         reel_picture_asset.reset (new dcp::ReelMonoPictureAsset (mono, 0));
345                 }
346
347                 shared_ptr<dcp::StereoPictureAsset> stereo = dynamic_pointer_cast<dcp::StereoPictureAsset> (_picture_asset);
348                 if (stereo) {
349                         reel_picture_asset.reset (new dcp::ReelStereoPictureAsset (stereo, 0));
350                 }
351         } else {
352                 LOG_GENERAL ("no picture asset of our own; look through %1", refs.size());
353                 /* We don't have a picture asset of our own; hopefully we have one to reference */
354                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
355                         shared_ptr<dcp::ReelPictureAsset> k = dynamic_pointer_cast<dcp::ReelPictureAsset> (j.asset);
356                         if (k) {
357                                 LOG_GENERAL ("candidate picture asset period is %1-%2", j.period.from.get(), j.period.to.get());
358                         }
359                         if (k && j.period == _period) {
360                                 reel_picture_asset = k;
361                         }
362                 }
363         }
364
365         LOG_GENERAL ("create_reel for %1-%2; %3 of %4", _period.from.get(), _period.to.get(), _reel_index, _reel_count);
366
367         Frame const period_duration = _period.duration().frames_round(_film->video_frame_rate());
368
369         DCPOMATIC_ASSERT (reel_picture_asset);
370         if (reel_picture_asset->duration() != period_duration) {
371                 throw ProgrammingError (
372                         __FILE__, __LINE__,
373                         String::compose ("%1 vs %2", reel_picture_asset->duration(), period_duration)
374                         );
375         }
376         reel->add (reel_picture_asset);
377
378         /* If we have a hash for this asset in the CPL, assume that it is correct */
379         if (reel_picture_asset->hash()) {
380                 reel_picture_asset->asset_ref()->set_hash (reel_picture_asset->hash().get());
381         }
382
383         shared_ptr<dcp::ReelSoundAsset> reel_sound_asset;
384
385         if (_sound_asset) {
386                 /* We have made a sound asset of our own.  Put it into the reel */
387                 reel_sound_asset.reset (new dcp::ReelSoundAsset (_sound_asset, 0));
388         } else {
389                 /* We don't have a sound asset of our own; hopefully we have one to reference */
390                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
391                         shared_ptr<dcp::ReelSoundAsset> k = dynamic_pointer_cast<dcp::ReelSoundAsset> (j.asset);
392                         if (k && j.period == _period) {
393                                 reel_sound_asset = k;
394                                 /* If we have a hash for this asset in the CPL, assume that it is correct */
395                                 if (k->hash()) {
396                                         k->asset_ref()->set_hash (k->hash().get());
397                                 }
398                         }
399                 }
400         }
401
402         DCPOMATIC_ASSERT (reel_sound_asset);
403         if (reel_sound_asset->duration() != period_duration) {
404                 LOG_ERROR (
405                         "Reel sound asset has length %1 but reel period is %2",
406                         reel_sound_asset->duration(),
407                         period_duration
408                         );
409                 if (reel_sound_asset->duration() != period_duration) {
410                         throw ProgrammingError (
411                                 __FILE__, __LINE__,
412                                 String::compose ("%1 vs %2", reel_sound_asset->duration(), period_duration)
413                                 );
414                 }
415
416         }
417         reel->add (reel_sound_asset);
418
419         shared_ptr<dcp::ReelSubtitleAsset> reel_subtitle_asset;
420
421         if (_subtitle_asset) {
422
423                 boost::filesystem::path liberation_normal;
424                 try {
425                         liberation_normal = shared_path() / "LiberationSans-Regular.ttf";
426                         if (!boost::filesystem::exists (liberation_normal)) {
427                                 /* Hack for unit tests */
428                                 liberation_normal = shared_path() / "fonts" / "LiberationSans-Regular.ttf";
429                         }
430                 } catch (boost::filesystem::filesystem_error& e) {
431
432                 }
433
434                 if (!boost::filesystem::exists(liberation_normal)) {
435                         liberation_normal = "/usr/share/fonts/truetype/liberation/LiberationSans-Regular.ttf";
436                 }
437
438                 /* Add all the fonts to the subtitle content */
439                 BOOST_FOREACH (shared_ptr<Font> j, fonts) {
440                         _subtitle_asset->add_font (j->id(), j->file(FontFiles::NORMAL).get_value_or(liberation_normal));
441                 }
442
443                 if (dynamic_pointer_cast<dcp::InteropSubtitleAsset> (_subtitle_asset)) {
444                         boost::filesystem::path directory = _film->dir (_film->dcp_name ()) / _subtitle_asset->id ();
445                         boost::filesystem::create_directories (directory);
446                         _subtitle_asset->write (directory / ("sub_" + _subtitle_asset->id() + ".xml"));
447                 } else {
448
449                         /* All our assets should be the same length; use the picture asset length here
450                            as a reference to set the subtitle one.  We'll use the duration rather than
451                            the intrinsic duration; we don't care if the picture asset has been trimmed, we're
452                            just interested in its presentation length.
453                         */
454                         dynamic_pointer_cast<dcp::SMPTESubtitleAsset>(_subtitle_asset)->set_intrinsic_duration (
455                                 reel_picture_asset->duration ()
456                                 );
457
458                         _subtitle_asset->write (
459                                 _film->dir (_film->dcp_name ()) / ("sub_" + _subtitle_asset->id() + ".mxf")
460                                 );
461                 }
462
463                 reel_subtitle_asset.reset (
464                         new dcp::ReelSubtitleAsset (
465                                 _subtitle_asset,
466                                 dcp::Fraction (_film->video_frame_rate(), 1),
467                                 reel_picture_asset->duration(),
468                                 0
469                                 )
470                         );
471         } else {
472                 /* We don't have a subtitle asset of our own; hopefully we have one to reference */
473                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
474                         shared_ptr<dcp::ReelSubtitleAsset> k = dynamic_pointer_cast<dcp::ReelSubtitleAsset> (j.asset);
475                         if (k && j.period == _period) {
476                                 reel_subtitle_asset = k;
477                                 /* If we have a hash for this asset in the CPL, assume that it is correct */
478                                 if (k->hash()) {
479                                         k->asset_ref()->set_hash (k->hash().get());
480                                 }
481                         }
482                 }
483         }
484
485         if (reel_subtitle_asset) {
486                 if (reel_subtitle_asset->duration() != period_duration) {
487                         throw ProgrammingError (
488                                 __FILE__, __LINE__,
489                                 String::compose ("%1 vs %2", reel_subtitle_asset->duration(), period_duration)
490                                 );
491                 }
492                 reel->add (reel_subtitle_asset);
493         }
494
495         return reel;
496 }
497
498 void
499 ReelWriter::calculate_digests (boost::function<void (float)> set_progress)
500 {
501         if (_picture_asset) {
502                 _picture_asset->hash (set_progress);
503         }
504
505         if (_sound_asset) {
506                 _sound_asset->hash (set_progress);
507         }
508 }
509
510 Frame
511 ReelWriter::start () const
512 {
513         return _period.from.frames_floor (_film->video_frame_rate());
514 }
515
516
517 void
518 ReelWriter::write (shared_ptr<const AudioBuffers> audio)
519 {
520         if (!_sound_asset_writer) {
521                 return;
522         }
523
524         DCPOMATIC_ASSERT (audio);
525         _sound_asset_writer->write (audio->data(), audio->frames());
526 }
527
528 void
529 ReelWriter::write (PlayerSubtitles subs)
530 {
531         if (!_subtitle_asset) {
532                 string lang = _film->subtitle_language ();
533                 if (lang.empty ()) {
534                         lang = "Unknown";
535                 }
536                 if (_film->interop ()) {
537                         shared_ptr<dcp::InteropSubtitleAsset> s (new dcp::InteropSubtitleAsset ());
538                         s->set_movie_title (_film->name ());
539                         s->set_language (lang);
540                         s->set_reel_number (raw_convert<string> (_reel_index + 1));
541                         _subtitle_asset = s;
542                 } else {
543                         shared_ptr<dcp::SMPTESubtitleAsset> s (new dcp::SMPTESubtitleAsset ());
544                         s->set_content_title_text (_film->name ());
545                         s->set_language (lang);
546                         s->set_edit_rate (dcp::Fraction (_film->video_frame_rate (), 1));
547                         s->set_reel_number (_reel_index + 1);
548                         s->set_time_code_rate (_film->video_frame_rate ());
549                         s->set_start_time (dcp::Time ());
550                         if (_film->encrypted ()) {
551                                 s->set_key (_film->key ());
552                         }
553                         _subtitle_asset = s;
554                 }
555         }
556
557         BOOST_FOREACH (SubtitleString i, subs.text) {
558                 i.set_in  (i.in()  - dcp::Time (_period.from.seconds(), i.in().tcr));
559                 i.set_out (i.out() - dcp::Time (_period.from.seconds(), i.out().tcr));
560                 _subtitle_asset->add (i);
561         }
562 }
563
564 bool
565 ReelWriter::existing_picture_frame_ok (FILE* asset_file, FILE* info_file, Frame frame) const
566 {
567         LOG_GENERAL ("Checking existing picture frame %1", frame);
568
569         /* Read the data from the info file; for 3D we just check the left
570            frames until we find a good one.
571         */
572         dcp::FrameInfo const info = read_frame_info (info_file, frame, _film->three_d () ? EYES_LEFT : EYES_BOTH);
573
574         bool ok = true;
575
576         /* Read the data from the asset and hash it */
577         dcpomatic_fseek (asset_file, info.offset, SEEK_SET);
578         Data data (info.size);
579         size_t const read = fread (data.data().get(), 1, data.size(), asset_file);
580         LOG_GENERAL ("Read %1 bytes of asset data; wanted %2", read, info.size);
581         if (read != static_cast<size_t> (data.size ())) {
582                 LOG_GENERAL ("Existing frame %1 is incomplete", frame);
583                 ok = false;
584         } else {
585                 Digester digester;
586                 digester.add (data.data().get(), data.size());
587                 LOG_GENERAL ("Hash %1 vs %2", digester.get(), info.hash);
588                 if (digester.get() != info.hash) {
589                         LOG_GENERAL ("Existing frame %1 failed hash check", frame);
590                         ok = false;
591                 }
592         }
593
594         return ok;
595 }