X-Git-Url: https://main.carlh.net/gitweb/?a=blobdiff_plain;f=src%2Ftools%2Fdcpomatic_disk_writer.cc;h=66d38ec19b77ff8a32f35b53b9c3a3f36d4ab0be;hb=2370c03b83e1a074c6b7362885e69bc364553e49;hp=9518ac555a1f2afdabf2d4cef776f2c831c2f008;hpb=a16523af5f70b60f4890f198f6214177077a9c1d;p=dcpomatic.git diff --git a/src/tools/dcpomatic_disk_writer.cc b/src/tools/dcpomatic_disk_writer.cc index 9518ac555..66d38ec19 100644 --- a/src/tools/dcpomatic_disk_writer.cc +++ b/src/tools/dcpomatic_disk_writer.cc @@ -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 } +#include #endif #ifdef DCPOMATIC_LINUX @@ -68,6 +71,7 @@ extern "C" { #include #include #include +#include #include using std::cin; @@ -75,16 +79,18 @@ using std::min; using std::string; using std::runtime_error; using std::exception; +using std::vector; using boost::optional; #ifdef DCPOMATIC_LINUX static PolkitAuthority* polkit_authority = 0; #endif -static boost::filesystem::path dcp_path; -static std::string device; static uint64_t const block_size = 4096; static Nanomsg* nanomsg = 0; +#define SHORT_TIMEOUT 100 +#define LONG_TIMEOUT 2000 + static void count (boost::filesystem::path dir, uint64_t& total_bytes) @@ -118,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); @@ -147,7 +155,11 @@ write (boost::filesystem::path from, boost::filesystem::path to, uint64_t& total } remaining -= this_time; total_remaining -= this_time; - nanomsg->blocking_send(String::compose(DISK_WRITER_PROGRESS "\n%1\n", (1 - float(total_remaining) / total))); + + ++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); @@ -186,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->blocking_send(String::compose(DISK_WRITER_PROGRESS "\n%1\n", (1 - float(total_remaining) / total))); + nanomsg->send(String::compose(DISK_WRITER_VERIFY_PROGRESS "\n%1\n", (1 - float(total_remaining) / total)), SHORT_TIMEOUT); } ext4_fclose (&in); @@ -196,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& copied_files) { LOG_DISK ("Copy %1 -> %2", from.string(), to.generic_string()); @@ -216,30 +244,42 @@ 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 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); } } } + static void -write () +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; @@ -268,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); @@ -314,9 +355,9 @@ try } LOG_DISK_NC ("Opened partition"); - nanomsg->blocking_send(DISK_WRITER_FORMATTING "\n"); + 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); } @@ -337,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 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) { @@ -349,117 +401,172 @@ try } ext4_device_unregister("ext4_fs"); - nanomsg->blocking_send(DISK_WRITER_OK "\n"); + if (!nanomsg->send(DISK_WRITER_OK "\n", LONG_TIMEOUT)) { + throw CommunicationFailedError (); + } + + disk_write_finished (); } catch (CopyError& e) { - LOG_DISK("CopyError: %1 %2", e.message(), e.number()); - nanomsg->blocking_send(String::compose(DISK_WRITER_ERROR "\n%1\n%2\n", e.message(), e.number())); + 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); } catch (VerifyError& e) { - LOG_DISK("VerifyError: %1 %2", e.message(), e.number()); - nanomsg->blocking_send(String::compose(DISK_WRITER_ERROR "\n%1\n%2\n", e.message(), e.number())); + LOG_DISK("VerifyError (from write): %1 %2", e.message(), e.number()); + nanomsg->send(String::compose(DISK_WRITER_ERROR "\n%1\n%2\n", e.message(), e.number()), LONG_TIMEOUT); } catch (exception& e) { - LOG_DISK("Exception: %1", e.what()); - nanomsg->blocking_send(String::compose(DISK_WRITER_ERROR "\n%1\n0\n", e.what())); + LOG_DISK("Exception (from write): %1", e.what()); + nanomsg->send(String::compose(DISK_WRITER_ERROR "\n%1\n0\n", e.what()), LONG_TIMEOUT); } +struct Parameters +{ + boost::filesystem::path dcp_path; + std::string device; +}; + #ifdef DCPOMATIC_LINUX static void -polkit_callback (GObject *, GAsyncResult* res, gpointer) +polkit_callback (GObject *, GAsyncResult* res, gpointer data) { + Parameters* parameters = reinterpret_cast (data); PolkitAuthorizationResult* result = polkit_authority_check_authorization_finish (polkit_authority, res, 0); if (result && polkit_authorization_result_get_is_authorized(result)) { - write (); + write (parameters->dcp_path, parameters->device); } + delete parameters; if (result) { g_object_unref (result); } } #endif + bool idle () +try { using namespace boost::algorithm; - optional s = nanomsg->nonblocking_get (); + optional s = nanomsg->receive (0); if (!s) { return true; } + LOG_DISK("Writer receives command: %1", *s); + if (*s == DISK_WRITER_QUIT) { exit (EXIT_SUCCESS); + } else if (*s == DISK_WRITER_UNMOUNT) { + /* XXX: should do Linux polkit stuff here */ + optional xml_head = nanomsg->receive (LONG_TIMEOUT); + optional xml_body = nanomsg->receive (LONG_TIMEOUT); + if (!xml_head || !xml_body) { + LOG_DISK_NC("Failed to receive unmount request"); + 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 if (*s == DISK_WRITER_WRITE) { - dcp_path = nanomsg->blocking_get(); - device = nanomsg->blocking_get(); + optional dcp_path = nanomsg->receive (LONG_TIMEOUT); + optional device = nanomsg->receive (LONG_TIMEOUT); + if (!dcp_path || !device) { + LOG_DISK_NC("Failed to receive write request"); + throw CommunicationFailedError(); + } /* Do some basic sanity checks; this is a bit belt-and-braces but it can't hurt... */ #ifdef DCPOMATIC_OSX - if (!starts_with(device, "/dev/disk")) { - LOG_DISK ("Will not write to %1", device); - nanomsg->blocking_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n"); + if (!starts_with(*device, "/dev/disk")) { + LOG_DISK ("Will not write to %1", *device); + nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT); return true; } #endif #ifdef DCPOMATIC_LINUX - if (!starts_with(device, "/dev/sd") && !starts_with(device, "/dev/hd")) { - LOG_DISK ("Will not write to %1", device); - nanomsg->blocking_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n"); + if (!starts_with(*device, "/dev/sd") && !starts_with(*device, "/dev/hd")) { + LOG_DISK ("Will not write to %1", *device); + nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT); return true; } #endif #ifdef DCPOMATIC_WINDOWS - if (!starts_with(device, "\\\\.\\PHYSICALDRIVE")) { - LOG_DISK ("Will not write to %1", device); - nanomsg->blocking_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n"); + if (!starts_with(*device, "\\\\.\\PHYSICALDRIVE")) { + LOG_DISK ("Will not write to %1", *device); + nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT); return true; } #endif bool on_drive_list = false; bool mounted = false; - for (auto const& i: get_drives()) { - if (i.internal_name() == device) { + for (auto const& i: Drive::get()) { + if (i.device() == *device) { on_drive_list = true; mounted = i.mounted(); } } if (!on_drive_list) { - LOG_DISK ("Will not write to %1 as it's not recognised as a drive", device); - nanomsg->blocking_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n"); + LOG_DISK ("Will not write to %1 as it's not recognised as a drive", *device); + nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT); return true; } if (mounted) { - LOG_DISK ("Will not write to %1 as it's mounted", device); - nanomsg->blocking_send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n"); + LOG_DISK ("Will not write to %1 as it's mounted", *device); + nanomsg->send(DISK_WRITER_ERROR "\nRefusing to write to this drive\n1\n", LONG_TIMEOUT); return true; } - LOG_DISK ("Here we go writing %1 to %2", dcp_path, device); + LOG_DISK ("Here we go writing %1 to %2", *dcp_path, *device); #ifdef DCPOMATIC_LINUX polkit_authority = polkit_authority_get_sync (0, 0); - PolkitSubject* subject = polkit_unix_process_new (getppid()); + PolkitSubject* subject = polkit_unix_process_new_for_owner (getppid(), 0, -1); + Parameters* parameters = new Parameters; + parameters->dcp_path = *dcp_path; + parameters->device = *device; polkit_authority_check_authorization ( - polkit_authority, subject, "com.dcpomatic.write-drive", 0, POLKIT_CHECK_AUTHORIZATION_FLAGS_ALLOW_USER_INTERACTION, 0, polkit_callback, 0 + polkit_authority, subject, "com.dcpomatic.write-drive", 0, POLKIT_CHECK_AUTHORIZATION_FLAGS_ALLOW_USER_INTERACTION, 0, polkit_callback, parameters ); #else - write (); + write (*dcp_path, *device); #endif } + return true; +} catch (exception& e) { + LOG_DISK("Exception (from idle): %1", e.what()); return true; } 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);