diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 0ba541d..d386b92 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -2,7 +2,7 @@ name: build on: push: - branches: [main] + branches: [main, dev] pull_request: workflow_dispatch: diff --git a/Cargo.lock b/Cargo.lock index 97e3faa..9225792 100755 --- a/Cargo.lock +++ b/Cargo.lock @@ -87,7 +87,7 @@ checksum = "c4512299f36f043ab09a583e57bceb5a5aab7a73db1805848e8fef3c9e8c78b3" [[package]] name = "bufusb" -version = "0.2.5" +version = "0.2.6" dependencies = [ "anyhow", "clap", @@ -321,7 +321,7 @@ dependencies = [ [[package]] name = "libbuf" -version = "0.2.5" +version = "0.2.6" dependencies = [ "anyhow", "chrono", diff --git a/Install/PKGBUILD b/Install/PKGBUILD index 33a0a0d..39476c0 100644 --- a/Install/PKGBUILD +++ b/Install/PKGBUILD @@ -1,7 +1,7 @@ # Maintainer: Bryson Kelly pkgname=bufusb-cli _binname=bufusb -pkgver=0.2.5 +pkgver=0.2.6 pkgrel=1 _srcdir="bufusb-$pkgver" pkgdesc="A fast, safe bootable USB image flasher" diff --git a/Install/install.iss b/Install/install.iss index 1a5583d..03c54fd 100644 --- a/Install/install.iss +++ b/Install/install.iss @@ -1,4 +1,4 @@ -#define BufAppVersion "0.2.5" +#define BufAppVersion "0.2.6" #ifndef Arch #define Arch "x64" #endif diff --git a/buf-cli/Cargo.toml b/buf-cli/Cargo.toml index 795c8c6..6777158 100755 --- a/buf-cli/Cargo.toml +++ b/buf-cli/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "bufusb" -version = "0.2.5" +version = "0.2.6" edition = "2021" description = "A fast, safe bootable USB flasher" diff --git a/buf-cli/src/main.rs b/buf-cli/src/main.rs index 13732de..2053543 100755 --- a/buf-cli/src/main.rs +++ b/buf-cli/src/main.rs @@ -19,14 +19,14 @@ use anyhow::{bail, Context, Result}; use clap::{ArgAction, Parser}; -use libbuf::Mode; +use libbuf::{say, Mode}; use log::{debug, error, info, warn}; #[derive(Parser, Debug)] #[command( name = "bufusb", - version = "0.2.5", - long_version = "0.2.5\n Copyright (C) 2026 Bryson Kelly\n This program comes with ABSOLUTELY NO WARRANTY; for details, visit: https://github.com/brysonak/bufusb/blob/main/LICENSE\n This is free software, and you are welcome to redistribute it\n under certain conditions.", + version = "0.2.6", + long_version = "0.2.6\n Copyright (C) 2026 Bryson Kelly\n This program comes with ABSOLUTELY NO WARRANTY; for details, visit: https://github.com/brysonak/bufusb/blob/main/LICENSE\n This is free software, and you are welcome to redistribute it\n under certain conditions.", author = "Bryson Kelly", about = "A fast, safe bootable USB image flasher", long_about = None, @@ -120,7 +120,7 @@ struct Cli { #[arg( long = "log-path", value_name = "PATH", - help = "Write the log file to this path (default path is the HOME/user directory)" + help = "Write the log file to this path (default: a timestamped file in the per-user log directory, see docs)" )] log_path: Option, @@ -136,45 +136,45 @@ struct Cli { fn main() { let cli = Cli::parse(); - if let Err(e) = run(cli) { - error!("{:#}", e); - eprintln!("\n Error: {:#}\n", e); + if cli.no_logging && cli.log_path.is_some() { + eprintln!("error: --log-path and --no-logging cannot be used together"); std::process::exit(1); } + + let custom_log_path = cli.log_path.as_deref().map(|p| { + std::env::current_dir().map(|d| d.join(p)).unwrap_or_else(|_| p.into()) + }); + + let file_logging = !cli.no_logging && (!cli.list || custom_log_path.is_some()); + let log_path = libbuf::init_logger(file_logging, cli.verbose, custom_log_path); + if let Some(ref path) = log_path { + println!("Logging to: {}", path.display()); + } + libbuf::logger::log_context(); + debug!("Parsed CLI args: {:?}", cli); + + let start = std::time::Instant::now(); + let result = run(cli, log_path.as_deref()); + match result { + Ok(()) => info!("Finished OK after {:.1?}", start.elapsed()), + Err(e) => { + error!("{:#}", e); + info!("Failed after {:.1?}", start.elapsed()); + if let Some(p) = log_path { + eprintln!("The full log is at {}", p.display()); + } + std::process::exit(1); + } + } } -fn run(cli: Cli) -> Result<()> { +fn run(cli: Cli, log_path: Option<&std::path::Path>) -> Result<()> { if cli.list { let devices = libbuf::list_drives()?; libbuf::print_device_table(&devices); return Ok(()); } - if cli.no_logging && cli.log_path.is_some() { - bail!("Fatal: --log-path and --no-logging cannot be run at the same time. Stopping..."); - } - - // Absolute before elevation - let custom_log_path = cli - .log_path - .as_deref() - .map(|p| std::env::current_dir().map(|d| d.join(p))) - .transpose() - .context("Could not resolve --log-path")?; - - let log_path = libbuf::init_logger(!cli.no_logging, cli.verbose, custom_log_path.clone()) - .unwrap_or_else(|e| { - eprintln!("Warning: could not initialise logger: {}", e); - None - }); - - if let Some(ref path) = log_path { - println!("Logging to: {}", path.display()); - } - - info!("bufusb started"); - debug!("Parsed CLI args: {:?}", cli); - let source = cli .source .clone() @@ -188,9 +188,7 @@ fn run(cli: Cli) -> Result<()> { // Parse --mode early. If the user asked for both dd and copy at once, stop before we prompt for elevation or touch the device let requested = parse_modes(&cli.mode)?; if requested.len() >= 2 { - error!("User requested both dd and copy modes at once"); - eprintln!("Fatal: Cannot use both dd and copy modes at the same time, stopping..."); - std::process::exit(1); + bail!("Fatal: Cannot use both dd and copy modes at the same time, stopping..."); } let requested: Option = requested.first().copied(); @@ -217,9 +215,11 @@ fn run(cli: Cli) -> Result<()> { .with_context(|| format!("Could not resolve target path: {}", target))? .to_string_lossy() .into_owned(); + info!("Source: {}", source); + info!("Target: {}", target); if !libbuf::is_privileged() { - warn!("Not running as root/Administrator"); + info!("Not running as root/Administrator, relaunching elevated"); let mut argv = vec![ "--source".to_string(), source.clone(), "--target".to_string(), target.clone(), @@ -233,7 +233,7 @@ fn run(cli: Cli) -> Result<()> { if cli.offset != 0 { argv.extend(["--offset".to_string(), cli.offset.to_string()]); } - if let Some(ref p) = custom_log_path { + if let Some(p) = log_path { argv.extend(["--log-path".to_string(), p.to_string_lossy().into_owned()]); } if let Some(ref l) = cli.label { @@ -246,21 +246,32 @@ fn run(cli: Cli) -> Result<()> { libbuf::elevate_or_warn(&argv)?; } + log_target_device(&target); + // Sniff the image and settle on a single mode let caps = libbuf::ImageCaps::sniff(std::path::Path::new(&source)) .with_context(|| format!("Could not read source header: {}", source))?; + info!( + "Source image: {} bytes, {:?}", + std::fs::metadata(&source).map(|m| m.len()).unwrap_or(0), + caps + ); let mode = match requested { Some(m) => { - if libbuf::mode::mode_risky(m, caps) && !cli.force { + let risky = libbuf::mode::mode_risky(m, caps); + info!("Write mode: {} (forced with --mode, mismatched with image: {})", m, risky); + if risky && !cli.force { confirm_risky_mode()?; } m } - // No --mode given, auto-detect. Hybrids default to copy, dd only raw - // images get dd, extract-only ISOs get copy - None => libbuf::mode::auto(caps)?, + // No --mode given, auto-detect. Hybrids and raw images get dd, extract-only ISOs get copy + None => { + let m = libbuf::mode::auto(caps)?; + info!("Write mode: {} (auto-detected)", m); + m + } }; - info!("Write mode: {}", mode); match mode { Mode::Dd => write_dd(&cli, &source, &target), @@ -268,9 +279,22 @@ fn run(cli: Cli) -> Result<()> { } } +fn log_target_device(target: &str) { + match libbuf::list_drives() { + Ok(drives) => match drives.iter().find(|d| d.path.eq_ignore_ascii_case(target)) { + Some(d) => info!( + "Target device: {} | {} | {} ({} bytes) | removable={}", + d.path, d.model, d.size_human, d.size_bytes, d.removable + ), + None => info!("Target {} is not in the drive list (image file, or a filtered device)", target), + }, + Err(e) => info!("Could not enumerate drives to describe the target: {:#}", e), + } +} + fn write_dd(cli: &Cli, source: &str, target: &str) -> Result<()> { if cli.label.is_some() { - println!("Warning: Flag(s) --label is not usable in dd mode, ignoring..."); + warn!("--label is not usable in dd mode, ignoring"); } let block_size = parse_size(&cli.block_size) @@ -289,31 +313,24 @@ fn write_dd(cli: &Cli, source: &str, target: &str) -> Result<()> { offset: cli.offset, }; - println!("\n Validating source and target..."); + say!("\n Validating source and target..."); let (source_size, target_file) = libbuf::validate(¶ms)?; - println!(" Validation passed."); - info!("Validation passed, source size {} bytes", source_size); + say!(" Validation passed."); if cli.dry_run { - println!("\n --dry-run: all checks passed. Nothing was written.\n"); - info!("Dry-run complete, exiting without writing"); + say!("\n --dry-run: all checks passed. Nothing was written.\n"); return Ok(()); } if !cli.force { confirm(source, target, source_size)?; } else { - warn!("--force set, skipping confirmation prompt"); - println!("\n --force: skipping confirmation, {} -> {}", source, target); + say!("\n --force: skipping confirmation, {} -> {}", source, target); } - println!("\n Writing {} -> {}...\n", source, target); - info!("Starting write: {} -> {}", source, target); - + say!("\n Writing {} -> {}...\n", source, target); libbuf::write(¶ms, source_size, target_file)?; - - info!("Write completed successfully"); - println!("Write completed successfully."); + say!("Write completed successfully."); Ok(()) } @@ -335,10 +352,7 @@ fn write_copy(cli: &Cli, source: &str, target: &str, caps: libbuf::ImageCaps) -> irrelevant.push("--block-size"); } if !irrelevant.is_empty() { - println!( - "Warning: Flag(s) {} is not usable in copy mode, ignoring...", - irrelevant.join(", ") - ); + warn!("{} not usable in copy mode, ignoring", irrelevant.join(", ")); } if cli.dry_run { @@ -349,13 +363,10 @@ fn write_copy(cli: &Cli, source: &str, target: &str, caps: libbuf::ImageCaps) -> let iso_len = std::fs::metadata(source).map(|m| m.len()).unwrap_or(0); confirm(source, target, iso_len)?; } else { - warn!("--force set, skipping confirmation prompt"); - println!("\n --force: skipping confirmation, copy {} -> {}", source, target); + say!("\n --force: skipping confirmation, copy {} -> {}", source, target); } - println!("\n Copying {} -> {} (ISO mode)...\n", source, target); - info!("Starting copy: {} -> {}", source, target); - + say!("\n Copying {} -> {} (ISO mode)...\n", source, target); libbuf::copy::run(source, target, false, cli.label.as_deref()) } @@ -400,6 +411,7 @@ fn confirm_risky_mode() -> Result<()> { let mut input = String::new(); io::stdin().read_line(&mut input)?; + info!("Risky mode prompt answered {:?}", input.trim()); if input.trim().to_ascii_lowercase() != "y" { bail!("Aborted by user."); } diff --git a/docs/docs.md b/docs/docs.md index eb25050..45c05da 100644 --- a/docs/docs.md +++ b/docs/docs.md @@ -147,8 +147,8 @@ bufusb -s image.iso -t /dev/sdb --no-logging bufusb -s image.iso -t /dev/sdb -n ``` -By default, bufusb creates a timestamped log file in the user's home directory on -each run. This flag suppresses that. Cannot be combined with `--log-path`. +By default, bufusb creates a timestamped log file on each run (see [Logging](#logging)). +This flag suppresses that. Cannot be combined with `--log-path`. ### `-m, --mode ` @@ -180,8 +180,8 @@ on macOS (for now) ### `--log-path ` -Write the log file to the given path instead of the default timestamped file in -the home directory. +Write the log file to the given path instead of the default timestamped file +(see [Logging](#logging)). An existing file is appended to. ```sh bufusb -s image.iso -t /dev/sdb --log-path /tmp/flash.log @@ -193,9 +193,9 @@ The parent directory is created if it does not exist. Cannot be combined with ### `-v, --verbose` -Enable debug-level logging. Logs every block written, ioctl results, device -paths, and internal state. Implies log file creation unless `--no-logging` is -also set. +Enable debug-level logging in the log file: ioctl results, every directory +created in copy mode, skipped devices during enumeration, and other internal state. +The terminal still only shows warnings and errors. ```sh bufusb -s image.iso -t /dev/sdb --verbose @@ -212,13 +212,21 @@ Print the version and exit. ## Logging -Unless `--no-logging` is passed, bufusb writes a timestamped log file to the home -directory on each run. The filename format is: +Unless `--no-logging` is passed, bufusb writes a timestamped log file on each +write run, named `bufusb-YYYY-MM-DDTHH-MM-SS.log`, in: -``` -bufusb-MM-DD-YY-HH:MM:SS.log (Linux, macOS) -bufusb-MM-DD-YY-HH-MM-SS.log (Windows, colons are not valid in filenames) -``` +| Platform | Directory | +|----------|-----------| +| Linux | `$XDG_STATE_HOME/bufusb`, or `~/.local/state/bufusb` | +| macOS | `~/Library/Logs/bufusb` | +| Windows | `%LOCALAPPDATA%\bufusb\logs` | + +`--list` does not write a log unless `--log-path` is given. + +When bufusb relaunches itself elevated, the elevated run appends to the same file, +so one run is one log. Each line carries the process ID, so the two halves can be +told apart. Under `sudo`, `doas`, `run0` or `pkexec` the log goes to the invoking +user's directory, and files created in that user's home are owned by them. Use `--log-path` to write the log to a specific file instead: @@ -226,14 +234,24 @@ Use `--log-path` to write the log to a specific file instead: bufusb -s image.iso -t /dev/sdb --log-path /var/log/bufusb.log ``` -The log path is printed at startup: +The log path is printed at startup, and again next to the error if the run fails: ``` - Logging to: /home/user/bufusb-05-30-26-14:22:01.log + Logging to: /home/user/.local/state/bufusb/bufusb-2026-05-30T14-22-01.log ``` -Log files contain info-level output by default, debug-level with `--verbose`. -Warnings and errors are always mirrored to stderr regardless of the log settings. +What the log records, at the default info level: + +- bufusb version, OS and architecture, the exact command line, working directory, privilege level and invoking user +- the target device (model, size, removable) as the drive list sees it, and every drive found +- the image's detected capabilities and the chosen write mode, and why +- every external tool run (`mount`, `umount`, `mkfs.ntfs`, `diskutil`, `hdiutil`, PowerShell), with its exit status and full output +- dd mode: sector size, block size, a progress line every 5% with average speed, sync time +- copy mode: label resolution, partition layout, cluster size, every file copied, skipped files and why, sync time +- answers to confirmation prompts, total run time, and any error or panic + +The terminal only shows warnings and errors, prefixed `warning:` / `error:`. If the +log file cannot be opened, bufusb says so and keeps going with terminal output only. ## Privileges @@ -241,11 +259,12 @@ Writing to block devices requires root on Linux/macOS and Administrator on Windo If bufusb is not already running with the required privileges it will attempt to re-launch itself elevated automatically. -On Linux it tries `sudo` first, then `pkexec` as a fallback. On Windows it -triggers a UAC prompt via `ShellExecuteW` with the `runas` verb. +On Linux and macOS it tries `doas`, `sudo`, `run0`, then `pkexec`, or whatever +`BUF_SUDO` names. On Windows it triggers a UAC prompt via `ShellExecuteW` with the +`runas` verb. -If neither elevator is available on Linux, bufusb exits with an error asking you to -re-run as root manually. +If none of them is available, bufusb exits with an error asking you to re-run as +root manually. ## Examples diff --git a/flake.nix b/flake.nix index d36b062..58ec9ee 100644 --- a/flake.nix +++ b/flake.nix @@ -14,7 +14,7 @@ { packages.default = pkgs.rustPlatform.buildRustPackage { pname = "bufusb"; - version = "0.2.5"; + version = "0.2.6"; src = self; cargoLock.lockFile = ./Cargo.lock; diff --git a/libbuf/Cargo.toml b/libbuf/Cargo.toml index 02b5458..9048e2d 100755 --- a/libbuf/Cargo.toml +++ b/libbuf/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "libbuf" -version = "0.2.5" +version = "0.2.6" edition = "2021" publish = false description = "Core logic library for the buf USB flasher tool" @@ -14,7 +14,7 @@ indicatif = "0.17" fatfs = "0.3" [target.'cfg(unix)'.dependencies] -nix = { version = "0.27", features = ["user", "process"] } +nix = { version = "0.27", features = ["user", "process", "fs"] } [target.'cfg(windows)'.dependencies] windows = { version = "0.52", features = [ @@ -27,4 +27,4 @@ windows = { version = "0.52", features = [ "Win32_UI_Shell", "Win32_UI_WindowsAndMessaging", "Win32_Devices_DeviceAndDriverInstallation", -] } +] } \ No newline at end of file diff --git a/libbuf/src/copy/mod.rs b/libbuf/src/copy/mod.rs index 089abe1..77ab82c 100644 --- a/libbuf/src/copy/mod.rs +++ b/libbuf/src/copy/mod.rs @@ -27,6 +27,8 @@ use std::io::{self, Read, Seek, SeekFrom, Write}; use std::path::{Path, PathBuf}; use crate::list::human_bytes; +use crate::logger::{run as run_logged, tail}; +use crate::say; #[cfg(any(target_os = "linux", windows))] mod ntfs; @@ -38,6 +40,11 @@ const CACHE_BYTES: usize = 32 * 1024 * 1024; // SectorCache's cap, covers a typi pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Result<()> { let (mut label, explicit_label) = resolve_label(label, Path::new(source)); + info!( + "Volume label: '{}' ({})", + label, + if explicit_label { "from --label" } else { "from the ISO, or the BUF default" } + ); let target_path = Path::new(target); let sector = logical_sector_size(target_path); if !sector.is_power_of_two() || !(512..=4096).contains(§or) { @@ -51,6 +58,7 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re bail!("Fatal: Could not determine size of target device {}", target); } let total_sectors = dev_bytes / sector; + info!("Target size: {} bytes, {} sectors", dev_bytes, total_sectors); // 1 MiB partition let align_lba = (1024 * 1024) / sector; @@ -66,6 +74,13 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re let part_sectors = total_sectors - align_lba - gpt_tail; let part_bytes = part_sectors * sector; let cluster = fat32_cluster(part_bytes, sector); + info!( + "FAT32 layout: partition LBA {}..{} ({}), cluster {} bytes", + align_lba, + align_lba + part_sectors - 1, + human_bytes(part_bytes), + cluster + ); // Mount the ISO let guard = MountGuard::mount(Path::new(source)) @@ -75,9 +90,11 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re let scan = scan_tree(&mroot, cluster)?; info!( - "copy: {} across {} files, largest {}, efi_boot={}", + "ISO tree: {} across {} files and {} dirs, {} once cluster-rounded, largest {}, efi_boot={}", human_bytes(scan.total_bytes), scan.file_count, + scan.dir_count, + human_bytes(scan.alloc_bytes), human_bytes(scan.max_file), scan.has_efi_boot, ); @@ -97,14 +114,15 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re if label.len() > 11 { let short = String::from_utf8_lossy(&fat_label(&label)).trim_end().to_string(); if explicit_label { - warn!("Label '{}' truncated to '{}' for FAT32", label, short); - println!("note: FAT32 labels are 11 characters, using '{}'", short); + warn!("FAT32 labels are 11 characters, using '{}'", short); + } else { + info!("ISO label '{}' truncated to '{}' for FAT32", label, short); } label = short; } if dry_run { - println!( + say!( "\n --dry-run (copy mode): would write a GPT (protective MBR + one {} \ FAT32 data partition) to {} and copy {} across {} files from {}.", human_bytes(part_sectors * sector), @@ -114,11 +132,9 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re source, ); if !scan.has_efi_boot { - println!( - "note: no /EFI/BOOT/BOOT*.EFI in the image" - ); + say!("note: no /EFI/BOOT/BOOT*.EFI in the image"); } - println!(); + say!(); return Ok(()); } @@ -165,10 +181,7 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re Ok(found) => { boot_ok = found; if found { - info!("EFI loaders recovered from the El-Torito boot image"); - println!( - "note: EFI bootloader extracted from the ISO's El-Torito boot image" - ); + say!("note: EFI bootloader extracted from the ISO's El-Torito boot image"); } } Err(e) => warn!("El-Torito extraction failed: {:#}", e), @@ -179,31 +192,33 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: Option<&str>) -> Re .map_err(|e| anyhow::anyhow!("FAT32 flush/unmount failed: {}", e))?; if skipped > 0 { - println!("note: {} file(s) could not be read from the ISO and were skipped", skipped); + say!("note: {} file(s) could not be read from the ISO and were skipped", skipped); } } io.flush().context("Flushing cached sectors to the device failed")?; // release the cache's borrow of dev before we touch dev directly drop(io); pb.finish_with_message("Copied"); - println!("Syncing to device, all data is still being written, do not unplug..."); + say!("Syncing to device, all data is still being written, do not unplug..."); + let sync_start = std::time::Instant::now(); dev.sync_data().context("Final sync to device failed")?; + info!("Sync took {:.2?}", sync_start.elapsed()); drop(prep); - reread_partitions(&dev, target_path); + let reread = reread_partitions(&dev, target_path); + info!("Partition table re-read by the OS: {}", reread); drop(dev); // Guard drops here too, but drop explicitly so any unmount error logs now drop(guard); if !boot_ok { - warn!("No /EFI/BOOT/BOOT*.EFI found in image; result may not be UEFI-bootable"); - println!( - "warning: no EFI bootloader (/EFI/BOOT/BOOT*.EFI) found in the image \ + warn!( + "no EFI bootloader (/EFI/BOOT/BOOT*.EFI) found in the image \ or its El-Torito boot image; it may not boot under UEFI" ); } - println!( + say!( "\n Copy complete: {} across {} files written to a new FAT32 partition on {}\n", human_bytes(scan.total_bytes), scan.file_count, @@ -391,6 +406,7 @@ fn copy_tree(mroot: &Path, fs: &FileSystem, pb: &ProgressBa // skip symlinked dirs if ft.is_dir() { dir_for(fs, &comps)?; // creates the directory (and any parents) + debug!("mkdir {}", rel.display()); stack.push(p); continue; } @@ -417,7 +433,7 @@ fn copy_tree(mroot: &Path, fs: &FileSystem, pb: &ProgressBa Ok(mut src) => { let n = stream_copy(&mut src, &mut dst, &mut buf, pb) .map_err(|e| anyhow::anyhow!("copy {}: {}", rel.display(), e))?; - debug!("copied {} ({} bytes)", rel.display(), n); + info!("copied {} ({} bytes)", rel.display(), n); } Err(e) => { // Truly dangling... Skip @@ -574,6 +590,7 @@ fn extract_eltorito_into_fat( stream_copy(src, &mut dst, &mut buf, pb) .map_err(|e| anyhow::anyhow!("extract {}: {}", comps.join("/"), e))?; found_boot |= is_efi_boot_comps(comps); + info!("extracted {} ({} bytes) from the El-Torito image", comps.join("/"), len); Ok(()) })?; Ok(found_boot) @@ -610,6 +627,7 @@ fn extract_eltorito_into_dir(source: &Path, dst_root: &Path, pb: &ProgressBar) - stream_copy(src, &mut dst, &mut buf, pb) .map_err(|e| anyhow::anyhow!("extract {}: {}", comps.join("/"), e))?; found_boot |= is_efi_boot_comps(comps); + info!("extracted {} ({} bytes) from the El-Torito image", comps.join("/"), len); Ok(()) })?; Ok(found_boot) @@ -625,6 +643,7 @@ fn build_bar(total: u64) -> ProgressBar { .progress_chars("##-"), ); pb.set_message("Copying..."); + crate::logger::set_bar(&pb); pb } @@ -1219,15 +1238,11 @@ impl MountGuard { use std::process::Command; let mp = unique_mountpoint(); std::fs::create_dir_all(&mp)?; - let st = Command::new("mount") - .args(["-o", "loop,ro"]) - .arg(source) - .arg(&mp) - .status() + let out = run_logged(Command::new("mount").args(["-o", "loop,ro"]).arg(source).arg(&mp)) .context("failed to run mount")?; - if !st.success() { + if !out.status.success() { let _ = std::fs::remove_dir(&mp); - bail!("Fatal: mount exited with {}", st); + bail!("Fatal: mount exited with {}: {}", out.status, tail(&out)); } Ok(Self { mount_point: mp, source: source.to_path_buf() }) } @@ -1239,15 +1254,16 @@ impl MountGuard { use std::process::Command; let mp = unique_mountpoint(); std::fs::create_dir_all(&mp)?; - let st = Command::new("hdiutil") - .args(["attach", "-readonly", "-nobrowse", "-mountpoint"]) - .arg(&mp) - .arg(source) - .status() - .context("failed to run hdiutil attach")?; - if !st.success() { + let out = run_logged( + Command::new("hdiutil") + .args(["attach", "-readonly", "-nobrowse", "-mountpoint"]) + .arg(&mp) + .arg(source), + ) + .context("failed to run hdiutil attach")?; + if !out.status.success() { let _ = std::fs::remove_dir(&mp); - bail!("Fatal: hdiutil attach exited with {}", st); + bail!("Fatal: hdiutil attach exited with {}: {}", out.status, tail(&out)); } Ok(Self { mount_point: mp, source: source.to_path_buf() }) } @@ -1272,15 +1288,10 @@ impl MountGuard { }}; \ Write-Output $v.Path" ); - let out = Command::new("powershell") - .args(["-NoProfile", "-NonInteractive", "-Command", &ps]) - .output() + let out = run_logged(Command::new("powershell").args(["-NoProfile", "-NonInteractive", "-Command", &ps])) .context("failed to run Mount-DiskImage")?; if !out.status.success() { - bail!( - "Fatal: Mount-DiskImage failed: {}", - String::from_utf8_lossy(&out.stderr).trim() - ); + bail!("Fatal: Mount-DiskImage failed: {}", tail(&out)); } let stdout = String::from_utf8_lossy(&out.stdout); let vol = stdout @@ -1320,27 +1331,21 @@ impl Drop for MountGuard { use std::process::Command; #[cfg(target_os = "linux")] { - let _ = Command::new("umount").arg(&self.mount_point).status(); + let _ = run_logged(Command::new("umount").arg(&self.mount_point)); let _ = std::fs::remove_dir(&self.mount_point); } #[cfg(target_os = "macos")] { - let _ = Command::new("hdiutil") - .args(["detach", "-force"]) - .arg(&self.mount_point) - .status(); + let _ = run_logged(Command::new("hdiutil").args(["detach", "-force"]).arg(&self.mount_point)); let _ = std::fs::remove_dir(&self.mount_point); } #[cfg(windows)] { - // dismount echoes its DiskImage object to the inherited console otherwise let ps = format!( "Dismount-DiskImage -ImagePath {} | Out-Null", ps_quote(&self.source.to_string_lossy()) ); - let _ = Command::new("powershell") - .args(["-NoProfile", "-NonInteractive", "-Command", &ps]) - .status(); + let _ = run_logged(Command::new("powershell").args(["-NoProfile", "-NonInteractive", "-Command", &ps])); } let _ = &self.mount_point; } @@ -1357,26 +1362,27 @@ pub(crate) fn prepare_target(target: &Path) -> Result { use std::process::Command; // unmounts partitions of this device, matches /dev/sdb1 or nvme0n1p2 style suffixes not a bare prefix, a failed unmount is fatal since a new GPT under a live fs corrupts it let t = target.to_string_lossy().to_string(); - if let Ok(mounts) = std::fs::read_to_string("/proc/mounts") { - for line in mounts.lines() { - let src = line.split_whitespace().next().unwrap_or(""); - if is_partition_of(src, &t) { - let ok = Command::new("umount") - .arg(src) - .status() - .map(|s| s.success()) - .unwrap_or(false); - if !ok { - bail!( - "Fatal: {} is mounted and could not be unmounted (still in use? a file \ - manager window or open file will hold it). Close whatever is \ - using it and retry.", - src - ); - } - } + let mounts = std::fs::read_to_string("/proc/mounts").unwrap_or_default(); + let mut unmounted = 0; + for line in mounts.lines() { + let mut f = line.split_whitespace(); + let (src, at) = (f.next().unwrap_or(""), f.next().unwrap_or("?")); + if !is_partition_of(src, &t) { + continue; } + info!("{} is mounted at {}, unmounting", src, at); + let out = run_logged(Command::new("umount").arg(src)).context("failed to run umount")?; + if !out.status.success() { + bail!( + "Fatal: {} is mounted and could not be unmounted ({}). A file manager window or \ + open file will hold it, close whatever is using it and retry.", + src, + tail(&out) + ); + } + unmounted += 1; } + info!("Unmounted {} partition(s) of {}", unmounted, t); Ok(PrepGuard {}) } @@ -1401,17 +1407,14 @@ pub(crate) fn prepare_target(target: &Path) -> Result { if !ft.is_block_device() && !ft.is_char_device() { return Ok(PrepGuard {}); } - let ok = Command::new("diskutil") - .arg("unmountDisk") - .arg(target) - .status() - .map(|s| s.success()) - .unwrap_or(false); - if !ok { + let out = run_logged(Command::new("diskutil").arg("unmountDisk").arg(target)) + .context("failed to run diskutil")?; + if !out.status.success() { bail!( - "Fatal: diskutil unmountDisk {} failed; a volume on the target is still in use. \ + "Fatal: diskutil unmountDisk {} failed ({}), a volume on the target is still in use. \ Close whatever is using it and retry.", - target.display() + target.display(), + tail(&out) ); } Ok(PrepGuard {}) @@ -1437,6 +1440,7 @@ pub(crate) fn prepare_target(target: &Path) -> Result { let h = (0..LOCK_TRIES) .find_map(|i| { if i > 0 { + info!("Volume {} busy, lock retry {}/{}", vol, i + 1, LOCK_TRIES); std::thread::sleep(std::time::Duration::from_millis(500)); } lock_and_dismount(&vol) @@ -1452,9 +1456,7 @@ pub(crate) fn prepare_target(target: &Path) -> Result { info!("Locked + dismounted volume {} on drive {}", vol, drive_no); locked.push(h); } - if locked.is_empty() { - debug!("No mounted volumes found on drive {}", drive_no); - } + info!("Locked {} volume(s) on drive {}", locked.len(), drive_no); Ok(PrepGuard { locked }) } @@ -1581,7 +1583,8 @@ fn lock_and_dismount(vol: &str) -> Option { let locked = unsafe { DeviceIoControl(h, FSCTL_LOCK_VOLUME, None, 0, None, 0, Some(&mut returned), None) }; - if locked.is_err() { + if let Err(e) = locked { + info!("FSCTL_LOCK_VOLUME on {} failed: {}", vol, e); return None; } let _ = unsafe { diff --git a/libbuf/src/copy/ntfs.rs b/libbuf/src/copy/ntfs.rs index 27f1849..0181512 100644 --- a/libbuf/src/copy/ntfs.rs +++ b/libbuf/src/copy/ntfs.rs @@ -19,7 +19,7 @@ use anyhow::{bail, Context, Result}; use indicatif::ProgressBar; -use log::{debug, info, warn}; +use log::{info, warn}; use std::fs::File; use std::io::Write; use std::path::{Path, PathBuf}; @@ -30,6 +30,8 @@ use super::{ resolve_symlink, write_gpt, PartSpec, Scan, ESP_TYPE, MS_BASIC_DATA, }; use crate::list::human_bytes; +use crate::logger::{run as run_logged, tail}; +use crate::say; const SECTOR: u64 = 512; @@ -55,6 +57,13 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: &str, mroot: &Path, bail!("Target {} is too small for an NTFS + UEFI:NTFS layout", target); } let ntfs_sectors = total_sectors - ALIGN_LBA - GPT_TAIL - loader_sectors; + info!( + "NTFS layout: data LBA {}..{} ({}), UEFI:NTFS loader {} sectors after it", + ALIGN_LBA, + ALIGN_LBA + ntfs_sectors - 1, + human_bytes(ntfs_sectors * SECTOR), + loader_sectors + ); super::ensure_fits( scan.alloc_bytes + (scan.file_count + scan.dir_count) * 1024 + 64 * 1024 * 1024, @@ -62,16 +71,10 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: &str, mroot: &Path, target, )?; - info!( - "ntfs-copy: {} across {} files, largest {}, efi_boot={}", - human_bytes(scan.total_bytes), - scan.file_count, - human_bytes(scan.max_file), - scan.has_efi_boot, - ); + info!("Largest file {} is over the FAT32 limit, using the NTFS + UEFI:NTFS layout", human_bytes(scan.max_file)); if dry_run { - println!( + say!( "\n --dry-run (copy mode, NTFS fallback): would write a GPT ({} NTFS data \ partition + {} UEFI:NTFS loader partition) to {} and copy {} across {} files \ from {}.", @@ -82,7 +85,7 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: &str, mroot: &Path, scan.file_count, source, ); - println!(); + say!(); return Ok(()); } @@ -115,8 +118,10 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: &str, mroot: &Path, drop(io); dev.sync_data().context("Sync of GPT + loader to device failed")?; + info!("GPT and UEFI:NTFS loader written at LBA {}", loader_start); drop(prep); let reread = reread_partitions(&dev, target_path); + info!("Partition table re-read by the OS: {}", reread); drop(dev); if !reread && cfg!(target_os = "linux") { bail!( @@ -132,20 +137,19 @@ pub fn run(source: &str, target: &str, dry_run: bool, label: &str, mroot: &Path, format_and_copy(target_path, mroot, Path::new(source), !scan.has_efi_boot, &pb, label)?; if skipped > 0 { - println!("note: {} file(s) could not be read from the ISO and were skipped", skipped); + say!("note: {} file(s) could not be read from the ISO and were skipped", skipped); } if extracted_boot { - println!("note: EFI bootloader extracted from the ISO's El-Torito boot image"); + say!("note: EFI bootloader extracted from the ISO's El-Torito boot image"); } if !scan.has_efi_boot && !extracted_boot { - warn!("No /EFI/BOOT/BOOT*.EFI found in image; result may not be UEFI-bootable (Note: Try flashing with --mode dd)"); - println!( - "warning: no EFI bootloader (/EFI/BOOT/BOOT*.EFI) found in the image \ - or its El-Torito boot image; it may not boot under UEFI" + warn!( + "no EFI bootloader (/EFI/BOOT/BOOT*.EFI) found in the image \ + or its El-Torito boot image; it may not boot under UEFI (try --mode dd)" ); } - println!( + say!( "\n Copy complete (NTFS + UEFI:NTFS): {} across {} files written to {}\n", human_bytes(scan.total_bytes), scan.file_count, @@ -203,7 +207,7 @@ fn copy_tree_native(mroot: &Path, dst_root: &Path, pb: &ProgressBar) -> Result { warn!("skipping {} ({})", p.display(), e); @@ -229,15 +233,10 @@ fn format_and_copy( let part_node = partition_node(target, 1); wait_for_node(&part_node)?; - let st = Command::new("mkfs.ntfs") - .args(["-f", "-F", "-L", label]) - .arg(&part_node) - .status() - .context( - "failed to run mkfs.ntfs (is ntfs-3g and ntfsprogs installed?)", - )?; - if !st.success() { - bail!("mkfs.ntfs exited with {}", st); + let out = run_logged(Command::new("mkfs.ntfs").args(["-f", "-F", "-L", label]).arg(&part_node)) + .context("failed to run mkfs.ntfs (is ntfs-3g and ntfsprogs installed?)")?; + if !out.status.success() { + bail!("mkfs.ntfs exited with {}: {}", out.status, tail(&out)); } let mount = NtfsMount::mount(&part_node)?; @@ -251,7 +250,7 @@ fn format_and_copy( } pb.finish_with_message("Copied"); - println!("Syncing to device, all data is still being written, do not unplug..."); + say!("Syncing to device, all data is still being written, do not unplug..."); mount.unmount()?; File::open(&part_node) .and_then(|f| f.sync_all()) @@ -299,30 +298,23 @@ impl NtfsMount { // Prefer the in-kernel ntfs3 driver, fall back to the ntfs-3g FUSE // driver if ntfs3 isn't available on this kernel/distro - let ok = Command::new("mount") - .args(["-t", "ntfs3", "-o", "rw"]) - .arg(node) - .arg(&mp) - .status() - .map(|s| s.success()) - .unwrap_or(false); - let ok = ok - || Command::new("mount") - .args(["-t", "ntfs-3g"]) - .arg(node) - .arg(&mp) - .status() - .map(|s| s.success()) - .unwrap_or(false); - - if !ok { - let _ = std::fs::remove_dir(&mp); - bail!( - "Fatal: Could not mount {} as NTFS (tried ntfs3 and ntfs-3g). Is one of them installed?", - node.display() - ); + let mut errors = Vec::new(); + for fstype in ["ntfs3", "ntfs-3g"] { + match run_logged(Command::new("mount").args(["-t", fstype, "-o", "rw"]).arg(node).arg(&mp)) { + Ok(o) if o.status.success() => { + info!("Mounted {} with the {} driver at {}", node.display(), fstype, mp.display()); + return Ok(Self { mount_point: mp, mounted: true }); + } + Ok(o) => errors.push(format!("{}: {}", fstype, tail(&o))), + Err(e) => errors.push(format!("{}: {}", fstype, e)), + } } - Ok(Self { mount_point: mp, mounted: true }) + let _ = std::fs::remove_dir(&mp); + bail!( + "Fatal: Could not mount {} as NTFS ({}). Is ntfs3 or ntfs-3g available?", + node.display(), + errors.join("; ") + ); } fn mount_point(&self) -> &Path { @@ -331,16 +323,14 @@ impl NtfsMount { fn unmount(mut self) -> Result<()> { self.mounted = false; - let st = Command::new("umount") - .arg(&self.mount_point) - .status() - .context("failed to run umount")?; - if !st.success() { + let out = run_logged(Command::new("umount").arg(&self.mount_point)).context("failed to run umount")?; + if !out.status.success() { bail!( - "Fatal: umount {} exited with {}, data may not be fully written. \ + "Fatal: umount {} exited with {} ({}), data may not be fully written. \ Unmount it manually before unplugging", self.mount_point.display(), - st + out.status, + tail(&out) ); } Ok(()) @@ -351,7 +341,7 @@ impl NtfsMount { impl Drop for NtfsMount { fn drop(&mut self) { if self.mounted { - let _ = Command::new("umount").arg(&self.mount_point).status(); + let _ = run_logged(Command::new("umount").arg(&self.mount_point)); } let _ = std::fs::remove_dir(&self.mount_point); } @@ -384,12 +374,10 @@ fn format_and_copy( n = drive_no, label = label ); - let out = Command::new("powershell") - .args(["-NoProfile", "-NonInteractive", "-Command", &ps]) - .output() + let out = run_logged(Command::new("powershell").args(["-NoProfile", "-NonInteractive", "-Command", &ps])) .context("failed to run Format-Volume")?; if !out.status.success() { - bail!("NTFS format failed: {}", String::from_utf8_lossy(&out.stderr).trim()); + bail!("NTFS format failed: {}", tail(&out)); } let letter = String::from_utf8_lossy(&out.stdout) .trim() @@ -398,6 +386,7 @@ fn format_and_copy( .filter(|c| c.is_ascii_alphabetic()) .ok_or_else(|| anyhow::anyhow!("could not determine the assigned drive letter"))?; let mp = PathBuf::from(format!("{}:\\", letter)); + info!("NTFS volume formatted and mounted at {}", mp.display()); let skipped = copy_tree_native(mroot, &mp, pb)?; let mut extracted = false; @@ -409,17 +398,15 @@ fn format_and_copy( } pb.finish_with_message("Copied"); - println!("Syncing to device, all data is still being written, do not unplug..."); - let st = Command::new("powershell") - .args([ - "-NoProfile", - "-NonInteractive", - "-Command", - &format!("$ErrorActionPreference='Stop'; Write-VolumeCache -DriveLetter {}", letter), - ]) - .status() - .context("failed to run Write-VolumeCache")?; - if !st.success() { + say!("Syncing to device, all data is still being written, do not unplug..."); + let out = run_logged(Command::new("powershell").args([ + "-NoProfile", + "-NonInteractive", + "-Command", + &format!("$ErrorActionPreference='Stop'; Write-VolumeCache -DriveLetter {}", letter), + ])) + .context("failed to run Write-VolumeCache")?; + if !out.status.success() { bail!("Fatal: flushing {}: failed, data may not be fully written. Eject it before unplugging", letter); } diff --git a/libbuf/src/list.rs b/libbuf/src/list.rs index 600a1b4..9add06f 100755 --- a/libbuf/src/list.rs +++ b/libbuf/src/list.rs @@ -473,14 +473,7 @@ pub fn list_drives() -> Result> { info!("Enumerating disks via diskutil"); - let output = Command::new("diskutil").args(["list", "-plist"]).output()?; - let stdout = String::from_utf8_lossy(&output.stdout); - - // Parse the AllDisksAndPartitions plist to get disk identifiers, then - // query each with "diskutil info -plist" for size and media type let mut devices = Vec::new(); - - // Extract disk identifiers from the simple text list output instead let list_out = Command::new("diskutil").arg("list").output()?; let list_str = String::from_utf8_lossy(&list_out.stdout); @@ -625,7 +618,7 @@ pub fn print_device_table(devices: &[UsbDevice]) { if devices.is_empty() { println!("No storage devices found."); #[cfg(windows)] - println!("If a drive is plugged in, re-run with --verbose to see why each device was skipped."); + println!("If a drive is plugged in, re-run with --verbose --log-path list.log and check the log for why each device was skipped."); return; } diff --git a/libbuf/src/logger.rs b/libbuf/src/logger.rs index a02bb49..7267158 100755 --- a/libbuf/src/logger.rs +++ b/libbuf/src/logger.rs @@ -17,119 +17,279 @@ */ -use anyhow::{Context, Result}; use chrono::Local; use fern::Dispatch; -use log::LevelFilter; -use std::path::PathBuf; +use indicatif::ProgressBar; +use log::{info, LevelFilter}; +use std::path::{Path, PathBuf}; +use std::process::{Command, Output}; +use std::sync::Mutex; +use std::time::Instant; -fn home_dir() -> Option { - // When running under sudo, SUDO_USER holds the original username. - // HOME at this point is root, so we need to get the real user's home - // from passwd instead - #[cfg(unix)] - if let Ok(sudo_user) = std::env::var("SUDO_USER") { - if let Some(home) = passwd_home(&sudo_user) { - return Some(home); - } +static BAR: Mutex> = Mutex::new(None); + +pub fn set_bar(pb: &ProgressBar) { + *BAR.lock().unwrap_or_else(|e| e.into_inner()) = Some(pb.clone()); +} + +pub fn term(line: &str, stderr: bool) { + let bar = BAR.lock().unwrap_or_else(|e| e.into_inner()).clone(); + let print = || if stderr { eprintln!("{}", line) } else { println!("{}", line) }; + match bar { + Some(pb) if !pb.is_finished() => pb.suspend(print), + _ => print(), } +} + +#[macro_export] +macro_rules! say { + () => { $crate::logger::term("", false) }; + ($($t:tt)*) => {{ + let m = format!($($t)*); + if !m.trim().is_empty() { + ::log::info!("{}", m.trim()); + } + $crate::logger::term(&m, false); + }}; +} - if let Ok(h) = std::env::var("HOME") { - return Some(PathBuf::from(h)); +#[cfg(unix)] +pub(crate) fn invoking_user() -> Option { + use nix::unistd::{geteuid, Uid, User}; + if !geteuid().is_root() { + return None; } - if let Ok(h) = std::env::var("USERPROFILE") { - return Some(PathBuf::from(h)); + ["SUDO_USER", "DOAS_USER"] + .iter() + .filter_map(|v| std::env::var(v).ok()) + .find_map(|n| User::from_name(&n).ok().flatten()) + .or_else(|| { + let uid = std::env::var("PKEXEC_UID").ok()?.parse().ok()?; + User::from_uid(Uid::from_raw(uid)).ok().flatten() + }) + .filter(|u| !u.uid.is_root()) +} + +fn log_dir() -> Option { + #[cfg(windows)] + return std::env::var_os("LOCALAPPDATA") + .map(PathBuf::from) + .or_else(|| std::env::var_os("USERPROFILE").map(|p| PathBuf::from(p).join("AppData").join("Local"))) + .map(|d| d.join("bufusb").join("logs")); + + #[cfg(unix)] + { + let user = invoking_user(); + let home = user + .as_ref() + .map(|u| u.dir.clone()) + .or_else(|| std::env::var_os("HOME").map(PathBuf::from))?; + + #[cfg(target_os = "macos")] + return Some(home.join("Library").join("Logs").join("bufusb")); + + #[cfg(not(target_os = "macos"))] + return Some( + std::env::var_os("XDG_STATE_HOME") + .filter(|s| user.is_none() && !s.is_empty()) + .map(PathBuf::from) + .unwrap_or_else(|| home.join(".local").join("state")) + .join("bufusb"), + ); } + + #[cfg(not(any(unix, windows)))] None } +pub fn log_path() -> Option { + Some(log_dir()?.join(Local::now().format("bufusb-%Y-%m-%dT%H-%M-%S.log").to_string())) +} + #[cfg(unix)] -fn passwd_home(username: &str) -> Option { - use std::fs; - let passwd = fs::read_to_string("/etc/passwd").ok()?; - for line in passwd.lines() { - let mut fields = line.splitn(7, ':'); - let name = fields.next()?; - if name != username { - continue; +fn give_back(path: &Path, first_new_dir: Option<&Path>) { + let Some(u) = invoking_user() else { return }; + if !path.starts_with(&u.dir) { + return; + } + let dirs = path + .parent() + .into_iter() + .flat_map(Path::ancestors) + .take_while(|d| first_new_dir.is_some_and(|f| d.starts_with(f))); + for p in std::iter::once(path).chain(dirs) { + if let Err(e) = nix::unistd::chown(p, Some(u.uid), Some(u.gid)) { + log::debug!("chown {} to {} failed: {}", p.display(), u.name, e); } - let home = fields.nth(4)?; - return Some(PathBuf::from(home)); } - None } -pub fn log_path() -> Option { - let now = Local::now(); - // Colons are illegal in Windows filenames - #[cfg(windows)] - let filename = now.format("bufusb-%m-%d-%y-%H-%M-%S.log").to_string(); - #[cfg(not(windows))] - let filename = now.format("bufusb-%m-%d-%y-%H:%M:%S.log").to_string(); - home_dir().map(|d| d.join(filename)) +fn open_log(path: &Path) -> std::io::Result { + let dir = path.parent().filter(|d| !d.as_os_str().is_empty()); + let first_new = dir.and_then(|d| d.ancestors().take_while(|a| !a.exists()).last()).map(Path::to_path_buf); + if let Some(d) = dir { + std::fs::create_dir_all(d)?; + } + let file = fern::log_file(path)?; + #[cfg(unix)] + give_back(path, first_new.as_deref()); + #[cfg(not(unix))] + let _ = first_new; + Ok(file) } -pub fn init(enabled: bool, verbose: bool, custom_path: Option) -> Result> { +pub fn init(enabled: bool, verbose: bool, custom_path: Option) -> Option { let level = if verbose { LevelFilter::Debug } else { LevelFilter::Info }; - let formatter = - |out: fern::FormatCallback, message: &std::fmt::Arguments, record: &log::Record| { - out.finish(format_args!( - "[{timestamp}] [{level:<5}] [{target}] {message}", - timestamp = Local::now().format("%Y-%m-%d %H:%M:%S%.3f"), - level = record.level(), - target = record.target(), - message = message, - )) - }; - - if !enabled { - Dispatch::new() - .format(formatter) - .level(LevelFilter::Warn) - .chain(std::io::stderr()) - .apply() - .context("Failed to initialise stderr logger")?; - return Ok(None); - } + let stderr = Dispatch::new() + .level(LevelFilter::Warn) + .filter(|m| m.target() != "panic") + .format(|out, msg, rec| { + let tag = if rec.level() == log::Level::Error { "error" } else { "warning" }; + out.finish(format_args!("{}: {}", tag, msg)) + }) + .chain(fern::Output::call(|rec| term(&rec.args().to_string(), true))); - // Use the caller-supplied path if given, otherwise derive one from the - // current timestamp in the user's home directory - let path = match custom_path { - Some(p) => p, - None => match log_path() { - Some(p) => p, - None => { - // HOME/USERPROFILE unset; can happen when running as SYSTEM after UAC elevation - eprintln!("Warning: could not determine home directory, logging to stderr only"); - Dispatch::new() - .format(formatter) - .level(level) - .chain(std::io::stderr()) - .apply() - .context("Failed to initialise stderr logger")?; - return Ok(None); + let (path, file) = match enabled.then(|| custom_path.or_else(log_path)).flatten() { + Some(p) => match open_log(&p) { + Ok(f) => (Some(p), Some(f)), + Err(e) => { + term(&format!("warning: could not open log file {} ({}), logging to the terminal only", p.display(), e), true); + (None, None) } }, + None => { + if enabled { + term("warning: could not determine a log directory, logging to the terminal only", true); + } + (None, None) + } }; - if let Some(parent) = path.parent() { - std::fs::create_dir_all(parent) - .with_context(|| format!("Could not create log directory: {}", parent.display()))?; + let mut root = Dispatch::new() + .level_for("fatfs", LevelFilter::Info) + .chain(stderr); + if let Some(f) = file { + root = root.chain( + Dispatch::new() + .level(level) + .format(|out, msg, rec| { + out.finish(format_args!( + "[{}] [{:<5}] [{}] [{}] {}", + Local::now().format("%Y-%m-%d %H:%M:%S%.3f"), + rec.level(), + std::process::id(), + rec.target(), + msg, + )) + }) + .chain(f), + ); } + let _ = root.apply(); + + let default_hook = std::panic::take_hook(); + std::panic::set_hook(Box::new(move |p| { + log::error!(target: "panic", "{}", p); + default_hook(p); + })); + + if let Some(ref p) = path { + info!("Log file: {} (level {})", p.display(), level); + } + path +} - let log_file = fern::log_file(&path) - .with_context(|| format!("Could not open log file: {}", path.display()))?; +pub fn log_context() { + let cmd = std::env::args_os() + .map(|a| { + let s = a.to_string_lossy().into_owned(); + if s.is_empty() || s.contains(|c: char| c.is_whitespace() || c == '"' || c == '\'') { + format!("{:?}", s) + } else { + s + } + }) + .collect::>() + .join(" "); + info!("bufusb {} ({} {})", env!("CARGO_PKG_VERSION"), std::env::consts::OS, std::env::consts::ARCH); + info!("Command: {}", cmd); + info!("Working directory: {}", std::env::current_dir().map(|d| d.display().to_string()).unwrap_or_else(|e| e.to_string())); + info!("Privileged: {}", crate::is_privileged()); - Dispatch::new() - .format(formatter) - .chain(Dispatch::new().level(level).chain(log_file)) - .chain(Dispatch::new().level(LevelFilter::Warn).chain(std::io::stderr())) - .apply() - .context("Failed to initialise logger")?; + #[cfg(unix)] + if let Some(u) = invoking_user() { + info!("Invoked by user {} (uid {})", u.name, u.uid); + } - log::info!("bufusb logging started, file: {}", path.display()); - log::info!("Log level: {}", level); + #[cfg(target_os = "linux")] + { + let kernel = std::fs::read_to_string("/proc/sys/kernel/osrelease").unwrap_or_default(); + let distro = std::fs::read_to_string("/etc/os-release") + .unwrap_or_default() + .lines() + .find_map(|l| l.strip_prefix("PRETTY_NAME=")) + .map(|s| s.trim_matches('"').to_string()) + .unwrap_or_default(); + info!("OS: {} (kernel {})", distro, kernel.trim()); + } +} - Ok(Some(path)) +pub(crate) fn run(cmd: &mut Command) -> std::io::Result { + info!("exec: {:?}", cmd); + let start = Instant::now(); + let out = cmd.output(); + match &out { + Ok(o) => { + info!("exec: {} after {:.2?}", o.status, start.elapsed()); + for (name, bytes) in [("stdout", &o.stdout), ("stderr", &o.stderr)] { + let s = String::from_utf8_lossy(bytes); + if !s.trim().is_empty() { + info!("exec {}:\n{}", name, s.trim_end()); + } + } + } + Err(e) => info!("exec: could not start: {}", e), + } + out +} + +pub(crate) fn tail(o: &Output) -> String { + let s = String::from_utf8_lossy(if o.stderr.is_empty() { &o.stdout } else { &o.stderr }).into_owned(); + s.lines().rev().find(|l| !l.trim().is_empty()).unwrap_or("").trim().to_string() +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn log_name_sorts_and_has_no_colons() { + let p = log_path().expect("HOME or LOCALAPPDATA is set in tests"); + let name = p.file_name().unwrap().to_string_lossy(); + assert!(name.starts_with("bufusb-20") && name.ends_with(".log") && !name.contains(':'), "{}", name); + assert!(p.parent().unwrap().ends_with("bufusb") || p.parent().unwrap().ends_with("logs")); + } + + #[test] + #[cfg(unix)] + fn run_captures_output_and_tail_picks_last_line() { + let o = run(Command::new("sh").args(["-c", "echo out; echo first >&2; echo last >&2; exit 3"])).unwrap(); + assert_eq!(o.status.code(), Some(3)); + assert_eq!(tail(&o), "last"); + let o = run(Command::new("sh").args(["-c", "echo only-stdout"])).unwrap(); + assert_eq!(tail(&o), "only-stdout"); + } + + #[test] + #[cfg(unix)] + fn open_log_creates_dirs_and_appends() { + let base = std::env::temp_dir().join(format!("buf-log-test-{}", std::process::id())); + let p = base.join("a/b/run.log"); + use std::io::Write; + open_log(&p).unwrap().write_all(b"one\n").unwrap(); + open_log(&p).unwrap().write_all(b"two\n").unwrap(); + assert_eq!(std::fs::read_to_string(&p).unwrap(), "one\ntwo\n"); + std::fs::remove_dir_all(&base).unwrap(); + } } diff --git a/libbuf/src/privilege.rs b/libbuf/src/privilege.rs index e3558bb..078c8e5 100755 --- a/libbuf/src/privilege.rs +++ b/libbuf/src/privilege.rs @@ -18,7 +18,7 @@ use anyhow::Result; -use log::{debug, info, warn}; +use log::{debug, info}; pub fn is_privileged() -> bool { #[cfg(unix)] @@ -36,14 +36,13 @@ pub fn is_privileged() -> bool { #[cfg(not(any(unix, windows)))] { - warn!("Cannot determine privilege level on this platform, assuming OK"); + log::warn!("Cannot determine privilege level on this platform, assuming OK"); return true; } } pub fn elevate_or_warn(args: &[String]) -> Result<()> { - warn!("bufusb must be run as root/Administrator to write to block devices"); - eprintln!("\n bufusb requires elevated privileges to write to block devices.\n"); + crate::say!("\n bufusb requires elevated privileges to write to block devices.\n"); #[cfg(unix)] return unix_elevate(args); @@ -52,10 +51,7 @@ pub fn elevate_or_warn(args: &[String]) -> Result<()> { return windows_elevate(args); #[cfg(not(any(unix, windows)))] - { - eprintln!(" Please re-run bufusb with administrator/root privileges."); - std::process::exit(1); - } + anyhow::bail!("Fatal: re-run bufusb with administrator/root privileges"); } #[cfg(unix)] @@ -68,26 +64,23 @@ fn unix_elevate(args: &[String]) -> Result<()> { Ok(v) if !v.trim().is_empty() => { let v = v.trim().to_string(); if !can_exec(&v) { - eprintln!("BUF_SUDO is set to '{}' but that is not an executable.", v); - std::process::exit(1); + anyhow::bail!("Fatal: BUF_SUDO is set to '{}' but that is not an executable", v); } + info!("Escalator from BUF_SUDO: {}", v); v } _ => match CANDIDATES.iter().find(|c| can_exec(c)) { Some(c) => c.to_string(), - None => { - eprintln!( - "No escalation tool found (tried {}). Re-run bufusb as root, or set \ - BUF_SUDO to the one you use.", - CANDIDATES.join(", ") - ); - std::process::exit(1); - } + None => anyhow::bail!( + "Fatal: no escalation tool found (tried {}). Re-run bufusb as root, or set \ + BUF_SUDO to the one you use", + CANDIDATES.join(", ") + ), }, }; - eprintln!(" Attempting to re-launch via {}...\n", escalator); - info!("Re-launching via {} {:?} {:?}", escalator, exe, args); + crate::say!(" Attempting to re-launch via {}...\n", escalator); + info!("Re-launching: {} {:?} {:?}", escalator, exe, args); let status = std::process::Command::new(&escalator) .arg(&exe) @@ -95,6 +88,7 @@ fn unix_elevate(args: &[String]) -> Result<()> { .status() .map_err(|e| anyhow::anyhow!("Failed to spawn {}: {}", escalator, e))?; + info!("Elevated run exited with {}", status); std::process::exit(status.code().unwrap_or(1)); } @@ -166,8 +160,8 @@ fn windows_elevate(args: &[String]) -> Result<()> { quoted.join(" ") ); - eprintln!(" Requesting UAC elevation...\n"); - info!("Requesting UAC elevation for {:?} with args {:?}", exe, args); + crate::say!(" Requesting UAC elevation...\n"); + info!("Requesting UAC elevation: cmd.exe {}", cmd_params); fn to_wide(s: &str) -> Vec { OsStr::new(s).encode_wide().chain(once(0)).collect() @@ -192,6 +186,8 @@ fn windows_elevate(args: &[String]) -> Result<()> { anyhow::bail!("Fatal: UAC elevation was declined or failed (ShellExecuteW code {})", r.0); } + // ShellExecuteW doesn't hand back the child, the elevated window logs the rest into the same file + info!("Elevated window launched, this process exits"); std::process::exit(0); } diff --git a/libbuf/src/writer.rs b/libbuf/src/writer.rs index 931ba34..e100032 100755 --- a/libbuf/src/writer.rs +++ b/libbuf/src/writer.rs @@ -19,7 +19,7 @@ use anyhow::{Context, Result}; use indicatif::{ProgressBar, ProgressStyle}; -use log::{debug, info}; +use log::{debug, info, warn}; use std::fs::File; use std::io::{self, Read, Seek, SeekFrom}; use std::path::Path; @@ -29,12 +29,8 @@ use crate::list::human_bytes; use crate::validate::WriteParams; pub fn write(params: &WriteParams, source_size: u64, target_file: File) -> Result<()> { - info!("Beginning write operation"); - info!(" source : {}", params.source); - info!(" target : {}", params.target); - info!(" block_size : {} bytes", params.block_size); - info!(" offset : {} bytes", params.offset); - info!(" source_size: {} bytes ({})", source_size, human_bytes(source_size)); + // source, target, block size and offset were already logged + info!("Beginning write of {} bytes ({})", source_size, human_bytes(source_size)); let source_path = Path::new(¶ms.source); @@ -49,12 +45,13 @@ pub fn write(params: &WriteParams, source_size: u64, target_file: File) -> Resul // Query physical sector size for alignment. With O_DIRECT / FILE_FLAG_NO_BUFFERING, // every write must be a multiple of this size in length and start on an aligned offset let sector_size = get_sector_size(Path::new(¶ms.target)); - debug!("Sector size for {}: {} bytes", params.target, sector_size); + info!("Sector size for {}: {} bytes", params.target, sector_size); // block_size is already validated to be non-zero. Round it up to a sector boundary // so that all full blocks are already aligned, and only the final partial block // needs extra handling let aligned_block = round_up(params.block_size, sector_size); + info!("Write block: {} bytes ({} requested), direct I/O", aligned_block, params.block_size); let mut target = DirectWriter::new(target_file, sector_size); @@ -76,13 +73,14 @@ pub fn write(params: &WriteParams, source_size: u64, target_file: File) -> Resul let mut bytes_written: u64 = 0; let mut blocks_written: u64 = 0; let start = Instant::now(); + let step = (source_size / 20).max(1); + let mut next_mark = step; loop { let bytes_read = read_full(&mut source_file, buffer.as_mut_slice_n(aligned_block)) .context("Read error from source")?; if bytes_read == 0 { - debug!("EOF reached after {} blocks", blocks_written); break; } @@ -91,20 +89,40 @@ pub fn write(params: &WriteParams, source_size: u64, target_file: File) -> Resul buffer.zero_range(bytes_read, write_len); } - target - .write_all(buffer.as_slice_n(write_len)) - .context("Write error to target, device may be full or disconnected")?; + target.write_all(buffer.as_slice_n(write_len)).with_context(|| { + format!( + "Write error to target at byte {}, device may be full or disconnected", + params.offset + bytes_written + ) + })?; bytes_written += bytes_read as u64; blocks_written += 1; pb.set_position(bytes_written); - debug!("Block {:>6} | {} bytes | {} total", blocks_written, bytes_read, bytes_written); + if bytes_written >= next_mark { + let secs = start.elapsed().as_secs_f64().max(0.001); + info!( + "Progress: {}% ({} / {}), {}/s average, {} blocks", + bytes_written * 100 / source_size.max(1), + human_bytes(bytes_written), + human_bytes(source_size), + human_bytes((bytes_written as f64 / secs) as u64), + blocks_written, + ); + next_mark = (bytes_written / step + 1) * step; + } + } + debug!("EOF after {} blocks, {} bytes", blocks_written, bytes_written); + if bytes_written != source_size { + warn!("Wrote {} bytes but the source was {} bytes at validation, did it change?", bytes_written, source_size); } pb.set_message("Syncing..."); + let sync_start = Instant::now(); target.sync().context("Sync error, data may not have reached the device")?; + info!("Sync took {:.2?}", sync_start.elapsed()); pb.finish_with_message("Done"); let elapsed = start.elapsed(); @@ -119,12 +137,12 @@ pub fn write(params: &WriteParams, source_size: u64, target_file: File) -> Resul blocks_written, ); - println!( + crate::logger::term(&format!( "\n Written : {}\n Time : {:.2}s\n Speed : {}/s\n", human_bytes(bytes_written), elapsed_secs, human_bytes(throughput as u64), - ); + ), false); Ok(()) } @@ -216,6 +234,7 @@ fn build_progress_bar(total_bytes: u64) -> ProgressBar { .progress_chars("##-"), ); pb.set_message("Writing..."); + crate::logger::set_bar(&pb); pb }