dtourolle
872e35670c
Nobody working on DarkRoom has a Mac, so every macOS build is in the hands of someone who can send a log and cannot attach a debugger. Three changes make that log worth sending: - The desktop's default filter on macOS is `debug` for every `dr_*` crate, the desktop crate and `onnxruntime` (the runtime's own session log). - The state directory — the log and crash records — is `~/Library/Logs` on macOS rather than the `~/.local/state` Finder hides; Console.app lists it. Config and data keep the Unix rules. - A `diagnostic` cargo profile: release plus line tables, so a crash record's backtrace reads file:line. On macOS the tables are in the `.dSYM` beside the executable, which the bundle must keep.
744 lines
30 KiB
Rust
744 lines
30 KiB
Rust
//! TRACES: NFR-OPS-1 | NFR-SEC-2
|
|
//! A log the photographer still has tomorrow.
|
|
//!
|
|
//! Until this existed, everything this application knew about a failure went
|
|
//! to stderr on the desktop and to logcat on Android, and both are gone the
|
|
//! moment the terminal closes or the ring buffer wraps. That is tolerable when
|
|
//! the person debugging is sitting at the machine. It is useless for the case
|
|
//! this module is built for and which NFR-OPS-1 describes: **somebody
|
|
//! reproduces a bug on a tablet, and then sends us a file.**
|
|
//!
|
|
//! Android makes that the *normal* case rather than an awkward one. A
|
|
//! `NativeActivity` has no console. `adb logcat` requires a cable, developer
|
|
//! mode, and — crucially — that you were already watching when it happened.
|
|
//! The failures most worth catching are the ones that are one line long and
|
|
//! scroll past: a class the activity's loader could not find, a permission
|
|
//! that was refused, a root the system revoked while the app was backgrounded.
|
|
//! A file survives all three.
|
|
//!
|
|
//! # The shape of it
|
|
//!
|
|
//! One [`LogFile`] in [`crate::state::state_dir`], teed with whatever logger
|
|
//! the platform already had rather than replacing it — logcat stays exactly as
|
|
//! it was, which matters because losing it while debugging would make this a
|
|
//! downgrade. [`install`] is the whole of the wiring.
|
|
//!
|
|
//! Four properties, each of which is a test below — the first of them only
|
|
//! half-testable off a device, and the test says which half:
|
|
//!
|
|
//! * **Retrievable.** Created with a mode that the way *this* platform gets a
|
|
//! file off the machine can actually open: `FILE_MODE`, the one number here
|
|
//! that differs by platform, and the only one whose reasoning is about the
|
|
//! directory above the file rather than about the file. Get it wrong and the
|
|
//! other three properties are worth nothing, because nobody ever reads the
|
|
//! log.
|
|
//! * **Capped.** Two files of [`MAX_FILE_BYTES`], so the worst case is stated
|
|
//! rather than discovered on a full phone.
|
|
//! * **Redacted at the sink** ([`redact`]), not at the call sites. A rule
|
|
//! every author has to remember is not a rule.
|
|
//! * **Durable per line.** No `BufWriter` anywhere, which is deliberate and
|
|
//! costs a syscall per record: the line worth having is the last one before
|
|
//! the process died, and on Android processes do not die politely — the
|
|
//! system kills them, with no unwinding and no `Drop`. A buffered log loses
|
|
//! precisely the evidence it was kept for.
|
|
//!
|
|
//! # Where the file lands
|
|
//!
|
|
//! * Linux: `$XDG_STATE_HOME/darkroom/darkroom.log`, else
|
|
//! `~/.local/state/darkroom/darkroom.log`.
|
|
//! * macOS: `$XDG_STATE_HOME/darkroom/darkroom.log`, else
|
|
//! `~/Library/Logs/darkroom/darkroom.log`, where Console.app lists it.
|
|
//! * Android: `/sdcard/Android/data/paris.tourolle.darkroom/files/darkroom.log`,
|
|
//! which `adb pull` reads from an ordinary release build. See
|
|
//! [`crate::state`] for why not the internal directory, and
|
|
//! [`redact`] for the consequence.
|
|
//!
|
|
//! # How crash capture should reach this
|
|
//!
|
|
//! It should not open its own file. A panic hook that calls `log::error!`
|
|
//! lands here like anything else, and lands *completely*, because writes are
|
|
//! unbuffered and per record — that is the property NFR-OPS-2 needs from
|
|
//! NFR-OPS-1 and the reason the two are not the same file. For a crash record
|
|
//! written separately, [`log_path`] says which log belongs with it and
|
|
//! [`redact::redact`] is public so the record gets the same treatment as the
|
|
//! lines around it.
|
|
|
|
pub mod bundle;
|
|
pub mod redact;
|
|
|
|
use std::fmt::Write as _;
|
|
use std::fs::{self, File, OpenOptions};
|
|
use std::io::{self, Write as _};
|
|
use std::path::{Path, PathBuf};
|
|
use std::sync::{Mutex, OnceLock};
|
|
use std::time::{SystemTime, UNIX_EPOCH};
|
|
|
|
use log::{LevelFilter, Log, Metadata, Record};
|
|
|
|
/// The current log, and — after one rotation — `darkroom.log.1` beside it.
|
|
const FILE_NAME: &str = "darkroom.log";
|
|
|
|
/// The stated cap, per file. With [`RETAINED_GENERATIONS`] the application
|
|
/// occupies at most 8 MiB of the state directory, ever.
|
|
///
|
|
/// Chosen against the retrieval, not against the disk: this is roughly forty
|
|
/// thousand lines at `info`, which is a long session's worth of context, and
|
|
/// it is small enough that `adb pull` over USB is instant and a user can
|
|
/// attach it to a message without thinking about it. A larger cap would buy
|
|
/// history nobody reads at the price of a file nobody sends.
|
|
pub const MAX_FILE_BYTES: u64 = 4 * 1024 * 1024;
|
|
|
|
/// How many rotated files are kept behind the current one.
|
|
///
|
|
/// One. The reason to keep any is that the interesting event often precedes
|
|
/// the rotation that a burst of retry logging then caused; the reason not to
|
|
/// keep more is that the worst case has to be a number this module can state.
|
|
pub const RETAINED_GENERATIONS: usize = 1;
|
|
|
|
/// The longest one record may be before it is cut short.
|
|
///
|
|
/// A guard against a single `{:?}` on something large — a decoded buffer, a
|
|
/// face embedding, an entire WebDAV response — turning the whole cap into one
|
|
/// unreadable line and evicting everything that led up to it. Generous enough
|
|
/// that no real message reaches it.
|
|
pub const MAX_LINE_BYTES: usize = 8 * 1024;
|
|
|
|
const TRUNCATION_MARK: &str = "…[truncated]";
|
|
|
|
/// Set by [`install`] once, so crash capture can name the file without
|
|
/// re-deriving the directory and possibly disagreeing about it.
|
|
static LOG_PATH: OnceLock<PathBuf> = OnceLock::new();
|
|
|
|
/// What [`install`] managed, said as data rather than as a log line — because
|
|
/// at the moment it is decided there is no logger to say it with.
|
|
///
|
|
/// The caller logs it as the first line of the session, which is how the file
|
|
/// ends up naming itself to anyone reading logcat over the user's shoulder.
|
|
#[derive(Debug, Clone)]
|
|
pub enum Installed {
|
|
/// The tee is live and this is the file to ask the user for.
|
|
ToFile(PathBuf),
|
|
/// Logging works, but only where it always did, and this is why. A
|
|
/// read-only or missing state directory is not a reason to start the
|
|
/// application without a logger.
|
|
ConsoleOnly(String),
|
|
}
|
|
|
|
/// Where this session is logging, if it is logging to a file at all.
|
|
pub fn log_path() -> Option<PathBuf> {
|
|
LOG_PATH.get().cloned()
|
|
}
|
|
|
|
/// Install the file sink alongside the logger the platform already provides.
|
|
///
|
|
/// `console` is the platform's own logger — `env_logger`'s on the desktop,
|
|
/// `android_logger`'s on a device — and it keeps receiving every record it
|
|
/// would have received. `level` is the maximum level to let through globally;
|
|
/// pass whatever the console logger was built to filter at, so the two agree.
|
|
///
|
|
/// Call it exactly once, first thing, and *after*
|
|
/// [`crate::state::set_state_dir`] on any platform that needs to declare a
|
|
/// directory.
|
|
pub fn install(console: Box<dyn Log>, level: LevelFilter) -> Installed {
|
|
let dir = crate::state::state_dir();
|
|
|
|
let (file, outcome) = match LogFile::open_in(&dir, MAX_FILE_BYTES) {
|
|
Ok(file) => {
|
|
let path = file.path().to_path_buf();
|
|
let _ = LOG_PATH.set(path.clone());
|
|
(Some(file), Installed::ToFile(path))
|
|
}
|
|
Err(e) => (
|
|
None,
|
|
Installed::ConsoleOnly(format!("{} is not writable: {e}", dir.display())),
|
|
),
|
|
};
|
|
|
|
if log::set_boxed_logger(Box::new(Tee { console, file })).is_err() {
|
|
// Something installed a logger before us. Saying so is the only useful
|
|
// response: whatever it was is still logging, and the file is not.
|
|
return Installed::ConsoleOnly("a logger was already installed".to_string());
|
|
}
|
|
log::set_max_level(level);
|
|
outcome
|
|
}
|
|
|
|
/// The platform's logger and ours, both fed from every record.
|
|
struct Tee {
|
|
console: Box<dyn Log>,
|
|
file: Option<LogFile>,
|
|
}
|
|
|
|
impl Log for Tee {
|
|
fn enabled(&self, metadata: &Metadata<'_>) -> bool {
|
|
self.console.enabled(metadata)
|
|
}
|
|
|
|
fn log(&self, record: &Record<'_>) {
|
|
// The console first, and unconditionally: it applies its own filter,
|
|
// and on Android it is the thing a developer is watching live.
|
|
self.console.log(record);
|
|
|
|
if let Some(file) = &self.file {
|
|
// The same gate the console applies, so the file is a transcript
|
|
// of logcat rather than a different log with different contents.
|
|
// It can be a slight superset — `env_logger`'s message-regex
|
|
// filter is applied inside its `log` and not by `enabled` — and a
|
|
// superset is the right way round for a file nobody is watching.
|
|
if self.console.enabled(record.metadata()) {
|
|
file.write_line(&format_record(record));
|
|
}
|
|
}
|
|
}
|
|
|
|
fn flush(&self) {
|
|
self.console.flush();
|
|
// Nothing to do for the file: there is no buffer to flush, which is
|
|
// the point. See the module documentation.
|
|
}
|
|
}
|
|
|
|
/// The log file itself, with its rotation.
|
|
///
|
|
/// Cheap to construct and safe to share: every write takes a mutex, and the
|
|
/// formatting and redaction that precede it happen outside the lock, so a
|
|
/// thread logging cannot hold up an unrelated one for longer than a `write`.
|
|
pub struct LogFile {
|
|
path: PathBuf,
|
|
/// The single retained generation. Named once here rather than derived at
|
|
/// each rotation, so the two cannot drift.
|
|
previous: PathBuf,
|
|
cap: u64,
|
|
open: Mutex<Open>,
|
|
}
|
|
|
|
struct Open {
|
|
file: File,
|
|
/// Bytes in the *current* file. Seeded from the file's length on open
|
|
/// rather than from zero — otherwise an application restarted often enough
|
|
/// would append past the cap forever and NFR-OPS-1's "size-capped" would
|
|
/// hold only within a single run.
|
|
written: u64,
|
|
}
|
|
|
|
impl LogFile {
|
|
/// Open (or create) the log in `dir`, creating the directory if needed.
|
|
///
|
|
/// `cap` is per file; the directory holds at most `cap * 2`. Public with
|
|
/// an explicit cap because the tests need a small one — a rotation test
|
|
/// that had to write 4 MiB would be a rotation test nobody runs.
|
|
pub fn open_in(dir: &Path, cap: u64) -> io::Result<Self> {
|
|
fs::create_dir_all(dir)?;
|
|
let path = dir.join(FILE_NAME);
|
|
let file = open_append(&path)?;
|
|
// A failure to stat a file we just opened is not worth refusing to log
|
|
// over; treating it as empty costs at most one late rotation.
|
|
let written = file.metadata().map(|m| m.len()).unwrap_or(0);
|
|
Ok(Self {
|
|
path,
|
|
previous: dir.join(format!("{FILE_NAME}.1")),
|
|
cap,
|
|
open: Mutex::new(Open { file, written }),
|
|
})
|
|
}
|
|
|
|
/// The file to ask the user to send.
|
|
pub fn path(&self) -> &Path {
|
|
&self.path
|
|
}
|
|
|
|
/// Redact, cap, and append one record.
|
|
///
|
|
/// Infallible by design. A logger that panicked, or that tried to report
|
|
/// its own failure through `log`, would take the application down or
|
|
/// recurse; a log line lost to a full disk is a smaller problem than
|
|
/// either.
|
|
pub fn write_line(&self, line: &str) {
|
|
// Both before the lock: neither can block, and neither should make
|
|
// another thread's `write` wait.
|
|
let mut line = redact::redact(line);
|
|
truncate_to(&mut line, MAX_LINE_BYTES);
|
|
line.push('\n');
|
|
|
|
// A poisoned mutex means another thread panicked mid-write. The log is
|
|
// exactly what is wanted at that moment, so carry on with whatever
|
|
// state it left: the worst case is one interleaved line.
|
|
let mut open = self.open.lock().unwrap_or_else(|e| e.into_inner());
|
|
|
|
let len = line.len() as u64;
|
|
if open.written > 0 && open.written + len > self.cap {
|
|
// A failed rotation is not a reason to drop the record. The only
|
|
// way `rename` fails on a directory we opened a file in is that
|
|
// the directory has gone, in which case the write below fails too
|
|
// and the line is lost either way.
|
|
let _ = self.rotate(&mut open);
|
|
}
|
|
|
|
if open.file.write_all(line.as_bytes()).is_ok() {
|
|
open.written += len;
|
|
}
|
|
}
|
|
|
|
/// `darkroom.log` becomes `darkroom.log.1`; the previous `.1` is dropped.
|
|
///
|
|
/// Rename rather than copy-and-truncate, so a reader holding the old file
|
|
/// keeps reading a whole file and never sees it shrink under them. The old
|
|
/// descriptor stays valid against the renamed inode until it is replaced
|
|
/// on the next line.
|
|
fn rotate(&self, open: &mut Open) -> io::Result<()> {
|
|
let _ = fs::remove_file(&self.previous);
|
|
fs::rename(&self.path, &self.previous)?;
|
|
open.file = open_append(&self.path)?;
|
|
open.written = 0;
|
|
Ok(())
|
|
}
|
|
}
|
|
|
|
/// The mode the log is created with, on the desktop.
|
|
///
|
|
/// `$XDG_STATE_HOME/darkroom` is inside a home directory on a machine that may
|
|
/// have other accounts on it, and this file names the user's photographs and
|
|
/// the shape of their library. Nothing about the directory above it stops
|
|
/// another local user reading a world-readable file, so the owner is the only
|
|
/// reader who has any business with it.
|
|
#[cfg(all(unix, not(target_os = "android")))]
|
|
const FILE_MODE: u32 = 0o600;
|
|
|
|
/// The mode the log is created with, on Android — deliberately not the
|
|
/// desktop's, because "who may read this" has a different answer here.
|
|
///
|
|
/// **The directory is the access control, and the file being readable does not
|
|
/// widen it.** `/sdcard/Android/data` is `drwxrws--x media_rw:ext_data_rw`: no
|
|
/// other application can enumerate or enter this application's subdirectory,
|
|
/// and anyone who can traverse it is holding the unlocked tablet, which
|
|
/// already gets them the photographs the log merely names.
|
|
///
|
|
/// What the group and other read bits buy is the entire reason
|
|
/// [`crate::state`] puts the file on external storage rather than in
|
|
/// `/data/data`: **`adb pull` runs as `shell`**, which can traverse a `--x`
|
|
/// directory but must then open the file as *other*. At `0o600` it cannot —
|
|
/// and `run-as` is refused on a build that is not debuggable, which a release
|
|
/// build is not — so every route off the device is closed at once and the log
|
|
/// is a diagnostic nobody can be sent. That is the one outcome the choice of
|
|
/// directory exists to prevent.
|
|
#[cfg(target_os = "android")]
|
|
const FILE_MODE: u32 = 0o644;
|
|
|
|
fn open_append(path: &Path) -> io::Result<File> {
|
|
let mut options = OpenOptions::new();
|
|
options.create(true).append(true);
|
|
#[cfg(unix)]
|
|
{
|
|
use std::os::unix::fs::OpenOptionsExt as _;
|
|
options.mode(FILE_MODE);
|
|
}
|
|
let file = options.open(path)?;
|
|
|
|
// And then again, explicitly, because the line above is a *request*: the
|
|
// kernel ANDs it with the process umask, and an Android application
|
|
// process inherits `0o077` from the zygote. Asking for `0o644` there
|
|
// creates `0o600`, silently, and `OpenOptions::mode` is ignored outright
|
|
// on a file that already exists — between them, that is how a log written
|
|
// for `adb pull` ended up unreadable by it. `fchmod` is subject to
|
|
// neither.
|
|
//
|
|
// Ignored on failure rather than refused. A file this process does not
|
|
// own, or a filesystem with no modes to set, is a reason to log without
|
|
// the mode; it is not a reason to log nowhere.
|
|
#[cfg(unix)]
|
|
{
|
|
use std::os::unix::fs::PermissionsExt as _;
|
|
let _ = file.set_permissions(fs::Permissions::from_mode(FILE_MODE));
|
|
}
|
|
|
|
Ok(file)
|
|
}
|
|
|
|
/// One record as one line.
|
|
///
|
|
/// The thread name is here and not in `env_logger`'s default format because of
|
|
/// what it costs to leave out on Android: the failure this module was written
|
|
/// to catch is a class the activity's loader will not resolve, and whether the
|
|
/// call came from `android_main`'s thread or from a worker is the entire
|
|
/// diagnosis. Unnamed threads report their id instead of nothing, so two
|
|
/// interleaved workers can still be told apart.
|
|
fn format_record(record: &Record<'_>) -> String {
|
|
let mut line = String::with_capacity(128);
|
|
push_timestamp(&mut line, SystemTime::now());
|
|
|
|
let thread = std::thread::current();
|
|
let _ = match thread.name() {
|
|
Some(name) => write!(line, " {:<5} [{name}]", record.level()),
|
|
None => write!(line, " {:<5} [{:?}]", record.level(), thread.id()),
|
|
};
|
|
let _ = write!(line, " {}: {}", record.target(), record.args());
|
|
line
|
|
}
|
|
|
|
/// `2026-08-30T12:34:56.789Z`, in UTC.
|
|
///
|
|
/// Hand-rolled rather than reached for from a crate. `chrono` and `jiff` are
|
|
/// both already in the lock file, and pulling either into `dr-plat` would put
|
|
/// a new dependency in the Android cross-compile for twenty lines of
|
|
/// arithmetic that cannot change — which is the same reasoning the workspace
|
|
/// manifest applies to TLS, SQLite and lens profiles, at a much smaller scale.
|
|
///
|
|
/// UTC and not local time, deliberately: a log is read by somebody other than
|
|
/// the person who produced it, and a timestamp with no zone in it is a
|
|
/// timestamp that has to be guessed at. Milliseconds are there to line the
|
|
/// file up against a logcat capture of the same session.
|
|
fn push_timestamp(out: &mut String, now: SystemTime) {
|
|
let since_epoch = now.duration_since(UNIX_EPOCH).unwrap_or_default();
|
|
let secs = since_epoch.as_secs() as i64;
|
|
let millis = since_epoch.subsec_millis();
|
|
|
|
// `div_euclid`, not `/`: the truncating division would put every instant
|
|
// in the six hours before 1970 on the wrong day. A clock that has not been
|
|
// set yet reports one of them.
|
|
let (year, month, day) = civil_from_days(secs.div_euclid(86_400));
|
|
let second_of_day = secs.rem_euclid(86_400);
|
|
|
|
let _ = write!(
|
|
out,
|
|
"{year:04}-{month:02}-{day:02}T{:02}:{:02}:{:02}.{millis:03}Z",
|
|
second_of_day / 3600,
|
|
(second_of_day % 3600) / 60,
|
|
second_of_day % 60,
|
|
);
|
|
}
|
|
|
|
/// Days since 1970-01-01 to a proleptic Gregorian date.
|
|
///
|
|
/// Howard Hinnant's `civil_from_days`, which is the algorithm every date
|
|
/// library uses underneath: it shifts the epoch to 0000-03-01 so that the
|
|
/// leap day falls at the end of the year and the 400-year cycle divides
|
|
/// evenly, which is what removes every branch.
|
|
fn civil_from_days(days: i64) -> (i64, i64, i64) {
|
|
let z = days + 719_468;
|
|
// Split out rather than written inline: `if a { x } else { y } / n` is a
|
|
// parse hazard in Rust, and getting it wrong here would be a silent
|
|
// off-by-a-century for dates before 1970 rather than a compile error.
|
|
let toward_negative_infinity = if z >= 0 { z } else { z - 146_096 };
|
|
let era = toward_negative_infinity / 146_097;
|
|
let day_of_era = z - era * 146_097;
|
|
let year_of_era =
|
|
(day_of_era - day_of_era / 1460 + day_of_era / 36_524 - day_of_era / 146_096) / 365;
|
|
let year = year_of_era + era * 400;
|
|
let day_of_year = day_of_era - (365 * year_of_era + year_of_era / 4 - year_of_era / 100);
|
|
let month_shifted = (5 * day_of_year + 2) / 153;
|
|
let day = day_of_year - (153 * month_shifted + 2) / 5 + 1;
|
|
let month = if month_shifted < 10 {
|
|
month_shifted + 3
|
|
} else {
|
|
month_shifted - 9
|
|
};
|
|
(if month <= 2 { year + 1 } else { year }, month, day)
|
|
}
|
|
|
|
/// Cut a line to `max` bytes without splitting a character in half.
|
|
fn truncate_to(line: &mut String, max: usize) {
|
|
if line.len() <= max {
|
|
return;
|
|
}
|
|
let mut cut = max.saturating_sub(TRUNCATION_MARK.len());
|
|
while cut > 0 && !line.is_char_boundary(cut) {
|
|
cut -= 1;
|
|
}
|
|
line.truncate(cut);
|
|
line.push_str(TRUNCATION_MARK);
|
|
}
|
|
|
|
#[cfg(test)]
|
|
mod tests {
|
|
use super::*;
|
|
|
|
/// An empty directory of this test's own. The convention elsewhere in the
|
|
/// workspace, and it matters more here: two
|
|
/// tests sharing a log directory would rotate each other's files.
|
|
fn a_log_dir(name: &str) -> PathBuf {
|
|
let dir = std::env::temp_dir().join(format!("darkroom-diagnostics-{name}"));
|
|
let _ = fs::remove_dir_all(&dir);
|
|
fs::create_dir_all(&dir).expect("a writable temp directory");
|
|
dir
|
|
}
|
|
|
|
fn read(path: &Path) -> String {
|
|
fs::read_to_string(path).unwrap_or_default()
|
|
}
|
|
|
|
/// Long enough that a handful of them cross a small cap, short enough that
|
|
/// the arithmetic in each test stays readable.
|
|
fn a_line(n: usize) -> String {
|
|
format!("{n:04} scanning /home/duncan/Pictures/2026/Iceland for images")
|
|
}
|
|
|
|
/// The permission bits of a file, as an octal number to compare against.
|
|
#[cfg(unix)]
|
|
fn mode_of(path: &Path) -> u32 {
|
|
use std::os::unix::fs::PermissionsExt as _;
|
|
fs::metadata(path).expect("a log").permissions().mode() & 0o777
|
|
}
|
|
|
|
#[cfg(unix)]
|
|
#[test]
|
|
fn the_log_is_created_with_the_mode_its_platform_can_retrieve_it_by() {
|
|
let dir = a_log_dir("mode");
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("opens");
|
|
log.write_line("a line the user will be asked for");
|
|
|
|
// Written as a literal rather than compared against `FILE_MODE`: a
|
|
// test that reads the same constant the code writes agrees with
|
|
// whatever the constant says, which is not a test of anything.
|
|
//
|
|
// **Only one of these two arms can ever run.** The Android one is the
|
|
// one that matters — `0o600` there closes `adb pull` and `run-as` at
|
|
// once, which is the failure this test exists for — and it cannot run
|
|
// under `cargo test`, because the behaviour is a property of a
|
|
// filesystem and a umask that only exist on a device. What the desktop
|
|
// arm does prove is the other half, and it is not nothing: the log
|
|
// must not become group- or world-readable in a home directory
|
|
// because somebody made one mode serve both platforms.
|
|
#[cfg(target_os = "android")]
|
|
assert_eq!(
|
|
mode_of(&dir.join(FILE_NAME)),
|
|
0o644,
|
|
"a log only the app can read cannot be sent to anyone (NFR-OPS-1)"
|
|
);
|
|
#[cfg(not(target_os = "android"))]
|
|
assert_eq!(
|
|
mode_of(&dir.join(FILE_NAME)),
|
|
0o600,
|
|
"the log names the user's library, and every other account on \
|
|
this machine can now read it"
|
|
);
|
|
}
|
|
|
|
#[cfg(unix)]
|
|
#[test]
|
|
fn a_log_left_by_an_older_build_is_reopened_with_this_mode() {
|
|
// The regression test for the actual bug, and the only one that can
|
|
// fail on the host: `OpenOptions::mode` applies at *creation* and is
|
|
// ANDed with the umask even then, so on its own it neither fixes an
|
|
// existing file nor delivers what it asked for in a process whose
|
|
// umask is `0o077`, which every Android application process inherits
|
|
// from the zygote.
|
|
//
|
|
// The explicit `set_permissions` is what makes the mode the one the
|
|
// platform needs rather than the one the umask happened to allow, and
|
|
// deleting it makes this assertion fail: the file already exists, so
|
|
// nothing else here can change it.
|
|
use std::os::unix::fs::PermissionsExt as _;
|
|
|
|
let dir = a_log_dir("mode-existing");
|
|
let path = dir.join(FILE_NAME);
|
|
fs::write(&path, "written by a build that chose a different mode\n").expect("writes");
|
|
fs::set_permissions(&path, fs::Permissions::from_mode(0o666)).expect("chmods");
|
|
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("opens");
|
|
log.write_line("this session");
|
|
|
|
assert_eq!(
|
|
mode_of(&path),
|
|
FILE_MODE,
|
|
"the mode of an existing log is left as whoever created it left it"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn the_log_stays_under_its_stated_cap() {
|
|
// **This is NFR-OPS-1's "size-capped".** Without rotation a phone left
|
|
// running fills its state directory and the failure lands on the user
|
|
// as "storage full", days after the logging that caused it.
|
|
let dir = a_log_dir("cap");
|
|
let cap = 4096;
|
|
let log = LogFile::open_in(&dir, cap).expect("opens");
|
|
|
|
for n in 0..500 {
|
|
log.write_line(&a_line(n));
|
|
}
|
|
|
|
let current = fs::metadata(dir.join(FILE_NAME))
|
|
.expect("a current log")
|
|
.len();
|
|
assert!(
|
|
current <= cap,
|
|
"the current log is {current} bytes, over {cap}"
|
|
);
|
|
|
|
let previous = fs::metadata(dir.join(format!("{FILE_NAME}.1")))
|
|
.expect("a rotated log, since 500 lines cannot fit in 4 KiB")
|
|
.len();
|
|
assert!(
|
|
previous <= cap,
|
|
"the rotated log is {previous} bytes, over {cap}"
|
|
);
|
|
|
|
assert!(
|
|
!dir.join(format!("{FILE_NAME}.2")).exists(),
|
|
"only {RETAINED_GENERATIONS} generation is kept; a second would make the \
|
|
worst case unstatable"
|
|
);
|
|
assert!(
|
|
current + previous <= cap * 2,
|
|
"the whole directory must fit in twice the cap"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn rotation_keeps_the_newest_lines_and_drops_the_oldest() {
|
|
// Which half survives is the whole value of the feature: the user
|
|
// reports a bug and the interesting lines are the last ones.
|
|
let dir = a_log_dir("newest");
|
|
let log = LogFile::open_in(&dir, 4096).expect("opens");
|
|
for n in 0..500 {
|
|
log.write_line(&a_line(n));
|
|
}
|
|
|
|
let current = read(&dir.join(FILE_NAME));
|
|
let previous = read(&dir.join(format!("{FILE_NAME}.1")));
|
|
assert!(
|
|
current.contains(&a_line(499)),
|
|
"the last line written must be in the current log"
|
|
);
|
|
let oldest = a_line(0);
|
|
assert!(
|
|
!current.contains(&oldest) && !previous.contains(&oldest),
|
|
"the oldest lines are what a cap gives up"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn a_line_survives_a_process_restart() {
|
|
// The requirement in one test. Everything else about this module is an
|
|
// implementation detail of "the user reproduces it, quits, and sends
|
|
// us the file".
|
|
let dir = a_log_dir("restart");
|
|
{
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("opens");
|
|
log.write_line("the failure the user is about to report");
|
|
} // the process ends here
|
|
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("reopens");
|
|
log.write_line("the next launch");
|
|
|
|
let text = read(&dir.join(FILE_NAME));
|
|
assert!(
|
|
text.contains("the failure the user is about to report"),
|
|
"a restart truncated the log: {text}"
|
|
);
|
|
assert!(text.contains("the next launch"));
|
|
assert!(
|
|
text.find("the failure") < text.find("the next launch"),
|
|
"the second session must append, not prepend"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn the_cap_survives_a_restart_too() {
|
|
// The bug this exists to prevent: seeding `written` from zero on open
|
|
// rather than from the file's length. Nothing looks wrong until an
|
|
// application that restarts often has a log of unbounded size, which
|
|
// is the one failure mode a cap is for.
|
|
let dir = a_log_dir("restart-cap");
|
|
let cap = 2048;
|
|
for _ in 0..40 {
|
|
let log = LogFile::open_in(&dir, cap).expect("opens");
|
|
for n in 0..5 {
|
|
log.write_line(&a_line(n));
|
|
}
|
|
}
|
|
|
|
let current = fs::metadata(dir.join(FILE_NAME))
|
|
.expect("a current log")
|
|
.len();
|
|
assert!(
|
|
current <= cap,
|
|
"forty restarts appended {current} bytes into a {cap}-byte file"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn a_credential_never_reaches_the_file() {
|
|
// **NFR-SEC-2 at the sink**, which is the placement the requirement
|
|
// depends on: the call site here has done nothing wrong that a
|
|
// reviewer would catch, and the credential still does not land.
|
|
let dir = a_log_dir("redaction");
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("opens");
|
|
log.write_line(r#"login response {"loginName":"duncan","appPassword":"wYh3K8mLpQr2"}"#);
|
|
log.write_line("PUT https://duncan:hunter2@cloud.example/remote.php/dav failed");
|
|
|
|
let text = read(&dir.join(FILE_NAME));
|
|
assert!(
|
|
!text.contains("wYh3K8mLpQr2"),
|
|
"an app password reached the log: {text}"
|
|
);
|
|
assert!(
|
|
!text.contains("hunter2"),
|
|
"a URL password reached the log: {text}"
|
|
);
|
|
assert!(
|
|
text.contains("cloud.example") && text.contains("duncan"),
|
|
"the diagnostic part must survive the redaction: {text}"
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn one_enormous_record_cannot_evict_the_whole_log() {
|
|
// A `{:?}` on something large — a decoded buffer, an embedding — must
|
|
// cost a line rather than the file.
|
|
let dir = a_log_dir("truncation");
|
|
let log = LogFile::open_in(&dir, MAX_FILE_BYTES).expect("opens");
|
|
log.write_line("a line worth keeping");
|
|
log.write_line(&"x".repeat(MAX_LINE_BYTES * 4));
|
|
|
|
let text = read(&dir.join(FILE_NAME));
|
|
assert!(text.contains("a line worth keeping"));
|
|
assert!(
|
|
text.contains(TRUNCATION_MARK),
|
|
"the oversized record should have been cut short"
|
|
);
|
|
assert!(
|
|
text.len() < MAX_LINE_BYTES * 2,
|
|
"the oversized record was written whole: {} bytes",
|
|
text.len()
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn truncation_never_splits_a_character() {
|
|
let mut line = "é".repeat(64);
|
|
truncate_to(&mut line, 40);
|
|
// The assertion is that this is still a `String` at all — the failure
|
|
// is a panic inside `truncate` on a non-boundary index — plus that it
|
|
// says it was cut.
|
|
assert!(line.ends_with(TRUNCATION_MARK));
|
|
assert!(line.len() <= 40);
|
|
}
|
|
|
|
#[test]
|
|
fn the_timestamp_is_utc_and_sortable() {
|
|
let mut out = String::new();
|
|
let an_instant = UNIX_EPOCH + std::time::Duration::from_millis(1_700_000_000_123);
|
|
push_timestamp(&mut out, an_instant);
|
|
assert_eq!(out, "2023-11-14T22:13:20.123Z");
|
|
|
|
let mut epoch = String::new();
|
|
push_timestamp(&mut epoch, UNIX_EPOCH);
|
|
assert_eq!(epoch, "1970-01-01T00:00:00.000Z");
|
|
|
|
// Lexicographic order is chronological order, which is what makes
|
|
// `sort` and a plain `grep` on a date prefix work.
|
|
assert!(epoch < out);
|
|
}
|
|
|
|
#[test]
|
|
fn the_calendar_handles_the_cases_that_are_usually_wrong() {
|
|
assert_eq!(civil_from_days(0), (1970, 1, 1));
|
|
assert_eq!(civil_from_days(19_723), (2024, 1, 1));
|
|
// 2024 is a leap year; 2100 will not be, and the century rule is the
|
|
// one every hand-rolled calendar gets wrong.
|
|
assert_eq!(civil_from_days(19_782), (2024, 2, 29));
|
|
assert_eq!(civil_from_days(-1), (1969, 12, 31));
|
|
}
|
|
}
|