Add KDMWithMetadataPtr typedef
[dcpomatic.git] / src / tools / dcpomatic_disk_writer.cc
index 4a93cba98b85ef974f6adb8c521c344740255a81..bac5f90840ea4dd91730b858a1506939c8dba3a7 100644 (file)
@@ -18,6 +18,7 @@
 
 */
 
+#include "lib/version.h"
 #include "lib/disk_writer_messages.h"
 #include "lib/compose.hpp"
 #include "lib/exceptions.h"
@@ -42,10 +43,12 @@ extern "C" {
 #endif
 
 #ifdef DCPOMATIC_OSX
+#include "lib/stdout_log.h"
 #undef nil
 extern "C" {
 #include <lwext4/file_dev.h>
 }
+#include <xpc/xpc.h>
 #endif
 
 #ifdef DCPOMATIC_LINUX
@@ -68,6 +71,7 @@ extern "C" {
 #include <sys/types.h>
 #include <boost/filesystem.hpp>
 #include <boost/algorithm/string.hpp>
+#include <boost/foreach.hpp>
 #include <iostream>
 
 using std::cin;
@@ -75,6 +79,7 @@ using std::min;
 using std::string;
 using std::runtime_error;
 using std::exception;
+using std::vector;
 using boost::optional;
 
 #ifdef DCPOMATIC_LINUX
@@ -119,6 +124,8 @@ write (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total
        uint8_t* buffer = new uint8_t[block_size];
        Digester digester;
 
+       int progress_frequency = 5000;
+       int progress_count = 0;
        uint64_t remaining = file_size (from);
        while (remaining > 0) {
                uint64_t const this_time = min(remaining, block_size);
@@ -148,7 +155,11 @@ write (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total
                }
                remaining -= this_time;
                total_remaining -= this_time;
-               nanomsg->send(String::compose(DISK_WRITER_PROGRESS "\n%1\n", (1 - float(total_remaining) / total)), SHORT_TIMEOUT);
+
+               ++progress_count;
+               if ((progress_count % progress_frequency) == 0) {
+                       nanomsg->send(String::compose(DISK_WRITER_COPY_PROGRESS "\n%1\n", (1 - float(total_remaining) / total)), SHORT_TIMEOUT);
+               }
        }
 
        fclose (in);
@@ -187,7 +198,7 @@ read (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total_
                digester.add (buffer, this_time);
                remaining -= this_time;
                total_remaining -= this_time;
-               nanomsg->send(String::compose(DISK_WRITER_PROGRESS "\n%1\n", (1 - float(total_remaining) / total)), SHORT_TIMEOUT);
+               nanomsg->send(String::compose(DISK_WRITER_VERIFY_PROGRESS "\n%1\n", (1 - float(total_remaining) / total)), SHORT_TIMEOUT);
        }
 
        ext4_fclose (&in);
@@ -197,12 +208,28 @@ read (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total_
 }
 
 
+class CopiedFile
+{
+public:
+       CopiedFile (boost::filesystem::path from_, boost::filesystem::path to_, string write_digest_)
+               : from (from_)
+               , to (to_)
+               , write_digest (write_digest_)
+       {}
+
+       boost::filesystem::path from;
+       boost::filesystem::path to;
+       /** digest calculated from data as it was read from the source during write */
+       string write_digest;
+};
+
+
 /** @param from File to copy from.
  *  @param to Directory to copy to.
  */
 static
 void
-copy (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total_remaining, uint64_t total)
+copy (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total_remaining, uint64_t total, vector<CopiedFile>& copied_files)
 {
        LOG_DISK ("Copy %1 -> %2", from.string(), to.generic_string());
 
@@ -217,14 +244,25 @@ copy (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total_
                }
 
                for (directory_iterator i = directory_iterator(from); i != directory_iterator(); ++i) {
-                       copy (i->path(), cr, total_remaining, total);
+                       copy (i->path(), cr, total_remaining, total, copied_files);
                }
        } else {
                string const write_digest = write (from, cr, total_remaining, total);
                LOG_DISK ("Wrote %1 %2 with %3", from.string(), cr.generic_string(), write_digest);
-               string const read_digest = read (from, cr, total_remaining, total);
-               LOG_DISK ("Read %1 %2 with %3", from.string(), cr.generic_string(), write_digest);
-               if (write_digest != read_digest) {
+               copied_files.push_back (CopiedFile(from, cr, write_digest));
+       }
+}
+
+
+static
+void
+verify (vector<CopiedFile> const& copied_files, uint64_t total)
+{
+       uint64_t total_remaining = total;
+       BOOST_FOREACH (CopiedFile const& i, copied_files) {
+               string const read_digest = read (i.from, i.to, total_remaining, total);
+               LOG_DISK ("Read %1 %2 was %3 on write, now %4", i.from.string(), i.to.generic_string(), i.write_digest, read_digest);
+               if (read_digest != i.write_digest) {
                        throw VerifyError ("Hash of written data is incorrect", 0);
                }
        }
@@ -236,12 +274,12 @@ void
 write (boost::filesystem::path dcp_path, string device)
 try
 {
-//     ext4_dmask_set (DEBUG_ALL);
+       ext4_dmask_set (DEBUG_ALL);
 
        /* We rely on static initialization for these */
        static struct ext4_fs fs;
        static struct ext4_mkfs_info info;
-       info.block_size = 1024;
+       info.block_size = 4096;
        info.inode_size = 128;
        info.journal = false;
 
@@ -270,22 +308,23 @@ try
 
        /* XXX: not sure if disk_id matters */
        int r = ext4_mbr_write (bd, &parts, 0);
-
        if (r) {
                throw CopyError ("Failed to write MBR", r);
        }
        LOG_DISK_NC ("Wrote MBR");
 
-#ifdef DCPOMATIC_WINDOWS
        struct ext4_mbr_bdevs bdevs;
        r = ext4_mbr_scan (bd, &bdevs);
        if (r != EOK) {
                throw CopyError ("Failed to read MBR", r);
        }
 
+#ifdef DCPOMATIC_WINDOWS
        file_windows_partition_set (bdevs.partitions[0].part_offset, bdevs.partitions[0].part_size);
 #endif
 
+       LOG_DISK ("Writing to partition at %1 size %2; bd part size is %3", bdevs.partitions[0].part_offset, bdevs.partitions[0].part_size, bd->part_size);
+
 #ifdef DCPOMATIC_LINUX
        /* Re-read the partition table */
        int fd = open(device.c_str(), O_RDONLY);
@@ -318,7 +357,7 @@ try
 
        nanomsg->send(DISK_WRITER_FORMATTING "\n", SHORT_TIMEOUT);
 
-       r = ext4_mkfs(&fs, bd, &info, F_SET_EXT4);
+       r = ext4_mkfs(&fs, bd, &info, F_SET_EXT2);
        if (r != EOK) {
                throw CopyError ("Failed to make filesystem", r);
        }
@@ -339,11 +378,22 @@ try
        uint64_t total_bytes = 0;
        count (dcp_path, total_bytes);
 
-       /* XXX: this is a hack.  We are going to "treat" every byte twice; write it, and then verify it.  Double the
-        * bytes totals so that progress works itself out (assuming write is the same speed as read).
-        */
-       total_bytes *= 2;
-       copy (dcp_path, "/mp", total_bytes, total_bytes);
+       uint64_t total_remaining = total_bytes;
+       vector<CopiedFile> copied_files;
+       copy (dcp_path, "/mp", total_remaining, total_bytes, copied_files);
+
+       /* Unmount and re-mount to make sure the write has finished */
+       r = ext4_umount("/mp/");
+       if (r != EOK) {
+               throw CopyError ("Failed to unmount device", r);
+       }
+       r = ext4_mount("ext4_fs", "/mp/", false);
+       if (r != EOK) {
+               throw CopyError ("Failed to mount device", r);
+       }
+       LOG_DISK_NC ("Re-mounted device");
+
+       verify (copied_files, total_bytes);
 
        r = ext4_umount("/mp/");
        if (r != EOK) {
@@ -354,6 +404,8 @@ try
        if (!nanomsg->send(DISK_WRITER_OK "\n", LONG_TIMEOUT)) {
                throw CommunicationFailedError ();
        }
+
+       disk_write_finished ();
 } catch (CopyError& e) {
        LOG_DISK("CopyError (from write): %1 %2", e.message(), e.number().get_value_or(0));
        nanomsg->send(String::compose(DISK_WRITER_ERROR "\n%1\n%2\n", e.message(), e.number().get_value_or(0)), LONG_TIMEOUT);
@@ -388,6 +440,7 @@ polkit_callback (GObject *, GAsyncResult* res, gpointer data)
 }
 #endif
 
+
 bool
 idle ()
 try
@@ -399,6 +452,8 @@ try
                return true;
        }
 
+       LOG_DISK("Writer receives command: %1", *s);
+
        if (*s == DISK_WRITER_QUIT) {
                exit (EXIT_SUCCESS);
        } else if (*s == DISK_WRITER_UNMOUNT) {
@@ -406,21 +461,19 @@ try
                optional<string> xml_head = nanomsg->receive (LONG_TIMEOUT);
                optional<string> xml_body = nanomsg->receive (LONG_TIMEOUT);
                if (!xml_head || !xml_body) {
+                       LOG_DISK_NC("Failed to receive unmount request");
                        throw CommunicationFailedError ();
                }
-               if (Drive(*xml_head + *xml_body).unmount()) {
-                       if (!nanomsg->send (DISK_WRITER_OK "\n", LONG_TIMEOUT)) {
-                               throw CommunicationFailedError();
-                       }
-               } else {
-                       if (!nanomsg->send (DISK_WRITER_ERROR "\n", LONG_TIMEOUT)) {
-                               throw CommunicationFailedError();
-                       }
+               bool const success = Drive(*xml_head + *xml_body).unmount();
+               if (!nanomsg->send (success ? (DISK_WRITER_OK "\n") : (DISK_WRITER_ERROR "\n"), LONG_TIMEOUT)) {
+                       LOG_DISK_NC("CommunicationFailedError in unmount_finished");
+                       throw CommunicationFailedError ();
                }
-       } else {
-               optional<string> dcp_path = nanomsg->receive(LONG_TIMEOUT);
-               optional<string> device = nanomsg->receive(LONG_TIMEOUT);
+       } else if (*s == DISK_WRITER_WRITE) {
+               optional<string> dcp_path = nanomsg->receive (LONG_TIMEOUT);
+               optional<string> device = nanomsg->receive (LONG_TIMEOUT);
                if (!dcp_path || !device) {
+                       LOG_DISK_NC("Failed to receive write request");
                        throw CommunicationFailedError();
                }
 
@@ -429,7 +482,7 @@ try
 #ifdef DCPOMATIC_OSX
                if (!starts_with(*device, "/dev/disk")) {
                        LOG_DISK ("Will not write to %1", *device);
-                       nanomsg->try_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT);
+                       nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT);
                        return true;
                }
 #endif
@@ -443,7 +496,7 @@ try
 #ifdef DCPOMATIC_WINDOWS
                if (!starts_with(*device, "\\\\.\\PHYSICALDRIVE")) {
                        LOG_DISK ("Will not write to %1", *device);
-                       nanomsg->try_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT);
+                       nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT);
                        return true;
                }
 #endif
@@ -493,11 +546,27 @@ try
 int
 main ()
 {
+#ifdef DCPOMATIC_OSX
+       /* On macOS this is running as root, so config_path() will be somewhere in root's
+        * home.  Instead, just write to stdout as the macOS process control stuff will
+        * redirect this to a file in /var/log
+        */
+       dcpomatic_log.reset(new StdoutLog(LogEntry::TYPE_DISK));
+       LOG_DISK("dcpomatic_disk_writer %1 started", dcpomatic_git_commit);
+#else
        /* XXX: this is a hack, but I expect we'll need logs and I'm not sure if there's
         * a better place to put them.
         */
        dcpomatic_log.reset(new FileLog(config_path() / "disk_writer.log", LogEntry::TYPE_DISK));
        LOG_DISK_NC("dcpomatic_disk_writer started");
+#endif
+
+#ifdef DCPOMATIC_OSX
+       /* I *think* this confumes the notifyd event that we used to start the process, so we only
+        * get started once per notification.
+        */
+        xpc_set_event_stream_handler("com.apple.notifyd.matching", DISPATCH_TARGET_QUEUE_DEFAULT, ^(xpc_object_t event) {});
+#endif
 
        try {
                nanomsg = new Nanomsg (false);