Add some debugging logs for #953.
[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 <boost/foreach.hpp>
45
46 #include "i18n.h"
47
48 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_GENERAL);
49 #define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_GENERAL);
50 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, LogEntry::TYPE_WARNING);
51 #define LOG_ERROR(...) _film->log()->log (String::compose (__VA_ARGS__), LogEntry::TYPE_ERROR);
52
53 using std::list;
54 using std::string;
55 using std::cout;
56 using boost::shared_ptr;
57 using boost::optional;
58 using boost::dynamic_pointer_cast;
59 using dcp::Data;
60
61 int const ReelWriter::_info_size = 48;
62
63 ReelWriter::ReelWriter (
64         shared_ptr<const Film> film, DCPTimePeriod period, shared_ptr<Job> job, int reel_index, int reel_count, optional<string> content_summary
65         )
66         : _film (film)
67         , _period (period)
68         , _first_nonexistant_frame (0)
69         , _last_written_video_frame (-1)
70         , _last_written_eyes (EYES_RIGHT)
71         , _total_written_audio_frames (0)
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         if (_film->three_d ()) {
82                 _picture_asset.reset (new dcp::StereoPictureAsset (dcp::Fraction (_film->video_frame_rate (), 1)));
83         } else {
84                 _picture_asset.reset (new dcp::MonoPictureAsset (dcp::Fraction (_film->video_frame_rate (), 1)));
85         }
86
87         _picture_asset->set_size (_film->frame_size ());
88
89         if (_film->encrypted ()) {
90                 _picture_asset->set_key (_film->key ());
91         }
92
93         _picture_asset->set_file (
94                 _film->internal_video_asset_dir() / _film->internal_video_asset_filename(_period)
95                 );
96
97         job->sub (_("Checking existing image data"));
98         check_existing_picture_asset ();
99
100         _picture_asset_writer = _picture_asset->start_write (
101                 _film->internal_video_asset_dir() / _film->internal_video_asset_filename(_period),
102                 _film->interop() ? dcp::INTEROP : dcp::SMPTE,
103                 _first_nonexistant_frame > 0
104                 );
105
106         if (_film->audio_channels ()) {
107                 _sound_asset.reset (
108                         new dcp::SoundAsset (dcp::Fraction (_film->video_frame_rate(), 1), _film->audio_frame_rate (), _film->audio_channels ())
109                         );
110
111                 if (_film->encrypted ()) {
112                         _sound_asset->set_key (_film->key ());
113                 }
114
115                 DCPOMATIC_ASSERT (_film->directory());
116
117                 /* Write the sound asset into the film directory so that we leave the creation
118                    of the DCP directory until the last minute.
119                 */
120                 _sound_asset_writer = _sound_asset->start_write (
121                         _film->directory().get() / audio_asset_filename (_sound_asset, _reel_index, _reel_count, _content_summary),
122                         _film->interop() ? dcp::INTEROP : dcp::SMPTE
123                         );
124         }
125 }
126
127 /** @param frame reel-relative frame */
128 void
129 ReelWriter::write_frame_info (Frame frame, Eyes eyes, dcp::FrameInfo info) const
130 {
131         FILE* file = 0;
132         boost::filesystem::path info_file = _film->info_file (_period);
133
134         bool const read = boost::filesystem::exists (info_file);
135         LOG_GENERAL (
136                 "Checked %1 (exists %2) length is %3 perms are %4",
137                 info_file, read ? 1 : 0, boost::filesystem::file_size (info_file), int(boost::filesystem::status(info_file).permissions())
138                 );
139
140         if (read) {
141                 file = fopen_boost (info_file, "r+b");
142         } else {
143                 file = fopen_boost (info_file, "wb");
144         }
145         if (!file) {
146                 throw OpenFileError (info_file, errno, read);
147         }
148         dcpomatic_fseek (file, frame_info_position (frame, eyes), SEEK_SET);
149         fwrite (&info.offset, sizeof (info.offset), 1, file);
150         fwrite (&info.size, sizeof (info.size), 1, file);
151         fwrite (info.hash.c_str(), 1, info.hash.size(), file);
152         fclose (file);
153 }
154
155 dcp::FrameInfo
156 ReelWriter::read_frame_info (FILE* file, Frame frame, Eyes eyes) const
157 {
158         dcp::FrameInfo info;
159         dcpomatic_fseek (file, frame_info_position (frame, eyes), SEEK_SET);
160         fread (&info.offset, sizeof (info.offset), 1, file);
161         fread (&info.size, sizeof (info.size), 1, file);
162
163         char hash_buffer[33];
164         fread (hash_buffer, 1, 32, file);
165         hash_buffer[32] = '\0';
166         info.hash = hash_buffer;
167
168         return info;
169 }
170
171 long
172 ReelWriter::frame_info_position (Frame frame, Eyes eyes) const
173 {
174         switch (eyes) {
175         case EYES_BOTH:
176                 return frame * _info_size;
177         case EYES_LEFT:
178                 return frame * _info_size * 2;
179         case EYES_RIGHT:
180                 return frame * _info_size * 2 + _info_size;
181         default:
182                 DCPOMATIC_ASSERT (false);
183         }
184
185         DCPOMATIC_ASSERT (false);
186 }
187
188 void
189 ReelWriter::check_existing_picture_asset ()
190 {
191         /* Try to open the existing asset */
192         DCPOMATIC_ASSERT (_picture_asset->file());
193         FILE* asset_file = fopen_boost (_picture_asset->file().get(), "rb");
194         if (!asset_file) {
195                 LOG_GENERAL ("Could not open existing asset at %1 (errno=%2)", _picture_asset->file()->string(), errno);
196                 return;
197         } else {
198                 LOG_GENERAL ("Opened existing asset at %1", _picture_asset->file()->string());
199         }
200
201         /* Offset of the last dcp::FrameInfo in the info file */
202         int const n = (boost::filesystem::file_size (_film->info_file(_period)) / _info_size) - 1;
203         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);
204
205         FILE* info_file = fopen_boost (_film->info_file(_period), "rb");
206         if (!info_file) {
207                 LOG_GENERAL_NC ("Could not open film info file");
208                 fclose (asset_file);
209                 return;
210         }
211
212         if (_film->three_d ()) {
213                 /* Start looking at the last left frame */
214                 _first_nonexistant_frame = n / 2;
215         } else {
216                 _first_nonexistant_frame = n;
217         }
218
219         while (!existing_picture_frame_ok(asset_file, info_file) && _first_nonexistant_frame > 0) {
220                 --_first_nonexistant_frame;
221         }
222
223         if (!_film->three_d() && _first_nonexistant_frame > 0) {
224                 /* If we are doing 3D we might have found a good L frame with no R, so only
225                    do this if we're in 2D and we've just found a good B(oth) frame.
226                 */
227                 ++_first_nonexistant_frame;
228         }
229
230         LOG_GENERAL ("Proceeding with first nonexistant frame %1", _first_nonexistant_frame);
231
232         fclose (asset_file);
233         fclose (info_file);
234 }
235
236 void
237 ReelWriter::write (optional<Data> encoded, Frame frame, Eyes eyes)
238 {
239         dcp::FrameInfo fin = _picture_asset_writer->write (encoded->data().get (), encoded->size());
240         write_frame_info (frame, eyes, fin);
241         _last_written[eyes] = encoded;
242         _last_written_video_frame = frame;
243         _last_written_eyes = eyes;
244 }
245
246 void
247 ReelWriter::fake_write (Frame frame, Eyes eyes, int size)
248 {
249         _picture_asset_writer->fake_write (size);
250         _last_written_video_frame = frame;
251         _last_written_eyes = eyes;
252 }
253
254 void
255 ReelWriter::repeat_write (Frame frame, Eyes eyes)
256 {
257         dcp::FrameInfo fin = _picture_asset_writer->write (
258                 _last_written[eyes]->data().get(),
259                 _last_written[eyes]->size()
260                 );
261         write_frame_info (frame, eyes, fin);
262         _last_written_video_frame = frame;
263         _last_written_eyes = eyes;
264 }
265
266 void
267 ReelWriter::finish ()
268 {
269         if (!_picture_asset_writer->finalize ()) {
270                 /* Nothing was written to the picture asset */
271                 _picture_asset.reset ();
272         }
273
274         if (_sound_asset_writer && !_sound_asset_writer->finalize ()) {
275                 /* Nothing was written to the sound asset */
276                 _sound_asset.reset ();
277         }
278
279         /* Hard-link any video asset file into the DCP */
280         if (_picture_asset) {
281                 DCPOMATIC_ASSERT (_picture_asset->file());
282                 boost::filesystem::path video_from = _picture_asset->file().get();
283                 boost::filesystem::path video_to;
284                 video_to /= _film->dir (_film->dcp_name());
285                 video_to /= video_asset_filename (_picture_asset, _reel_index, _reel_count, _content_summary);
286
287                 boost::system::error_code ec;
288                 boost::filesystem::create_hard_link (video_from, video_to, ec);
289                 if (ec) {
290                         LOG_WARNING_NC ("Hard-link failed; copying instead");
291                         boost::filesystem::copy_file (video_from, video_to, ec);
292                         if (ec) {
293                                 LOG_ERROR ("Failed to copy video file from %1 to %2 (%3)", video_from.string(), video_to.string(), ec.message ());
294                                 throw FileError (ec.message(), video_from);
295                         }
296                 }
297
298                 _picture_asset->set_file (video_to);
299         }
300
301         /* Move the audio asset into the DCP */
302         if (_sound_asset) {
303                 boost::filesystem::path audio_to;
304                 audio_to /= _film->dir (_film->dcp_name ());
305                 string const aaf = audio_asset_filename (_sound_asset, _reel_index, _reel_count, _content_summary);
306                 audio_to /= aaf;
307
308                 boost::system::error_code ec;
309                 boost::filesystem::rename (_film->file (aaf), audio_to, ec);
310                 if (ec) {
311                         throw FileError (
312                                 String::compose (_("could not move audio asset into the DCP (%1)"), ec.value ()), aaf
313                                 );
314                 }
315
316                 _sound_asset->set_file (audio_to);
317         }
318 }
319
320 shared_ptr<dcp::Reel>
321 ReelWriter::create_reel (list<ReferencedReelAsset> const & refs, list<shared_ptr<Font> > const & fonts)
322 {
323         shared_ptr<dcp::Reel> reel (new dcp::Reel ());
324
325         shared_ptr<dcp::ReelPictureAsset> reel_picture_asset;
326
327         if (_picture_asset) {
328                 /* We have made a picture asset of our own.  Put it into the reel */
329                 shared_ptr<dcp::MonoPictureAsset> mono = dynamic_pointer_cast<dcp::MonoPictureAsset> (_picture_asset);
330                 if (mono) {
331                         reel_picture_asset.reset (new dcp::ReelMonoPictureAsset (mono, 0));
332                 }
333
334                 shared_ptr<dcp::StereoPictureAsset> stereo = dynamic_pointer_cast<dcp::StereoPictureAsset> (_picture_asset);
335                 if (stereo) {
336                         reel_picture_asset.reset (new dcp::ReelStereoPictureAsset (stereo, 0));
337                 }
338         } else {
339                 /* We don't have a picture asset of our own; hopefully we have one to reference */
340                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
341                         shared_ptr<dcp::ReelPictureAsset> k = dynamic_pointer_cast<dcp::ReelPictureAsset> (j.asset);
342                         if (k && j.period == _period) {
343                                 reel_picture_asset = k;
344                         }
345                 }
346         }
347
348         DCPOMATIC_ASSERT (reel_picture_asset);
349         reel->add (reel_picture_asset);
350
351         /* If we have a hash for this asset in the CPL, assume that it is correct */
352         if (reel_picture_asset->hash()) {
353                 reel_picture_asset->asset_ref()->set_hash (reel_picture_asset->hash().get());
354         }
355
356         if (_sound_asset) {
357                 /* We have made a sound asset of our own.  Put it into the reel */
358                 reel->add (shared_ptr<dcp::ReelSoundAsset> (new dcp::ReelSoundAsset (_sound_asset, 0)));
359         } else {
360                 /* We don't have a sound asset of our own; hopefully we have one to reference */
361                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
362                         shared_ptr<dcp::ReelSoundAsset> k = dynamic_pointer_cast<dcp::ReelSoundAsset> (j.asset);
363                         if (k && j.period == _period) {
364                                 reel->add (k);
365                                 /* If we have a hash for this asset in the CPL, assume that it is correct */
366                                 if (k->hash()) {
367                                         k->asset_ref()->set_hash (k->hash().get());
368                                 }
369                         }
370                 }
371         }
372
373         if (_subtitle_asset) {
374
375                 boost::filesystem::path liberation_normal;
376                 try {
377                         liberation_normal = shared_path() / "LiberationSans-Regular.ttf";
378                         if (!boost::filesystem::exists (liberation_normal)) {
379                                 /* Hack for unit tests */
380                                 liberation_normal = shared_path() / "fonts" / "LiberationSans-Regular.ttf";
381                         }
382                 } catch (boost::filesystem::filesystem_error& e) {
383
384                 }
385
386                 if (!boost::filesystem::exists(liberation_normal)) {
387                         liberation_normal = "/usr/share/fonts/truetype/liberation/LiberationSans-Regular.ttf";
388                 }
389
390                 /* Add all the fonts to the subtitle content */
391                 BOOST_FOREACH (shared_ptr<Font> j, fonts) {
392                         _subtitle_asset->add_font (j->id(), j->file(FontFiles::NORMAL).get_value_or(liberation_normal));
393                 }
394
395                 if (dynamic_pointer_cast<dcp::InteropSubtitleAsset> (_subtitle_asset)) {
396                         boost::filesystem::path directory = _film->dir (_film->dcp_name ()) / _subtitle_asset->id ();
397                         boost::filesystem::create_directories (directory);
398                         _subtitle_asset->write (directory / ("sub_" + _subtitle_asset->id() + ".xml"));
399                 } else {
400
401                         /* All our assets should be the same length; use the picture asset length here
402                            as a reference to set the subtitle one.
403                         */
404                         dynamic_pointer_cast<dcp::SMPTESubtitleAsset>(_subtitle_asset)->set_intrinsic_duration (
405                                 reel_picture_asset->intrinsic_duration ()
406                                 );
407
408                         _subtitle_asset->write (
409                                 _film->dir (_film->dcp_name ()) / ("sub_" + _subtitle_asset->id() + ".mxf")
410                                 );
411                 }
412
413                 reel->add (shared_ptr<dcp::ReelSubtitleAsset> (
414                                    new dcp::ReelSubtitleAsset (
415                                            _subtitle_asset,
416                                            dcp::Fraction (_film->video_frame_rate(), 1),
417                                            reel_picture_asset->intrinsic_duration (),
418                                            0
419                                            )
420                                    ));
421         } else {
422                 /* We don't have a subtitle asset of our own; hopefully we have one to reference */
423                 BOOST_FOREACH (ReferencedReelAsset j, refs) {
424                         shared_ptr<dcp::ReelSubtitleAsset> k = dynamic_pointer_cast<dcp::ReelSubtitleAsset> (j.asset);
425                         if (k && j.period == _period) {
426                                 reel->add (k);
427                                 /* If we have a hash for this asset in the CPL, assume that it is correct */
428                                 if (k->hash()) {
429                                         k->asset_ref()->set_hash (k->hash().get());
430                                 }
431                         }
432                 }
433         }
434
435         return reel;
436 }
437
438 void
439 ReelWriter::calculate_digests (boost::function<void (float)> set_progress)
440 {
441         if (_picture_asset) {
442                 _picture_asset->hash (set_progress);
443         }
444
445         if (_sound_asset) {
446                 _sound_asset->hash (set_progress);
447         }
448 }
449
450 Frame
451 ReelWriter::start () const
452 {
453         return _period.from.frames_floor (_film->video_frame_rate());
454 }
455
456
457 void
458 ReelWriter::write (shared_ptr<const AudioBuffers> audio)
459 {
460         if (!_sound_asset_writer) {
461                 return;
462         }
463
464         if (audio) {
465                 _sound_asset_writer->write (audio->data(), audio->frames());
466         }
467
468         ++_total_written_audio_frames;
469 }
470
471 void
472 ReelWriter::write (PlayerSubtitles subs)
473 {
474         if (!_subtitle_asset) {
475                 string lang = _film->subtitle_language ();
476                 if (lang.empty ()) {
477                         lang = "Unknown";
478                 }
479                 if (_film->interop ()) {
480                         shared_ptr<dcp::InteropSubtitleAsset> s (new dcp::InteropSubtitleAsset ());
481                         s->set_movie_title (_film->name ());
482                         s->set_language (lang);
483                         s->set_reel_number ("1");
484                         _subtitle_asset = s;
485                 } else {
486                         shared_ptr<dcp::SMPTESubtitleAsset> s (new dcp::SMPTESubtitleAsset ());
487                         s->set_content_title_text (_film->name ());
488                         s->set_language (lang);
489                         s->set_edit_rate (dcp::Fraction (_film->video_frame_rate (), 1));
490                         s->set_reel_number (1);
491                         s->set_time_code_rate (_film->video_frame_rate ());
492                         s->set_start_time (dcp::Time ());
493                         if (_film->encrypted ()) {
494                                 s->set_key (_film->key ());
495                         }
496                         _subtitle_asset = s;
497                 }
498         }
499
500         BOOST_FOREACH (SubtitleString i, subs.text) {
501                 i.set_in  (i.in()  - dcp::Time (_period.from.seconds(), i.in().tcr));
502                 i.set_out (i.out() - dcp::Time (_period.from.seconds(), i.out().tcr));
503                 _subtitle_asset->add (i);
504         }
505 }
506
507 bool
508 ReelWriter::existing_picture_frame_ok (FILE* asset_file, FILE* info_file) const
509 {
510         LOG_GENERAL ("Checking existing picture frame %1", _first_nonexistant_frame);
511
512         /* Read the data from the info file; for 3D we just check the left
513            frames until we find a good one.
514         */
515         dcp::FrameInfo const info = read_frame_info (info_file, _first_nonexistant_frame, _film->three_d () ? EYES_LEFT : EYES_BOTH);
516
517         bool ok = true;
518
519         /* Read the data from the asset and hash it */
520         dcpomatic_fseek (asset_file, info.offset, SEEK_SET);
521         Data data (info.size);
522         size_t const read = fread (data.data().get(), 1, data.size(), asset_file);
523         LOG_GENERAL ("Read %1 bytes of asset data; wanted %2", read, info.size);
524         if (read != static_cast<size_t> (data.size ())) {
525                 LOG_GENERAL ("Existing frame %1 is incomplete", _first_nonexistant_frame);
526                 ok = false;
527         } else {
528                 Digester digester;
529                 digester.add (data.data().get(), data.size());
530                 LOG_GENERAL ("Hash %1 vs %2", digester.get(), info.hash);
531                 if (digester.get() != info.hash) {
532                         LOG_GENERAL ("Existing frame %1 failed hash check", _first_nonexistant_frame);
533                         ok = false;
534                 }
535         }
536
537         return ok;
538 }