The log file has been on external storage since it existed, and the
reason is stated at length in two places: /data/data/<pkg>/files needs
run-as against a debuggable build, /sdcard/Android/data/<pkg>/files is a
plain adb pull from any build, and a log nobody can retrieve is not a
diagnostic. The file was then opened 0600, which cancels that decision
out. On the tablet:
adb pull -> remote open failed: Permission denied
adb shell cat -> Permission denied
run-as -> package not debuggable
Every route off the device closed at once, on a file whose whole purpose
is to leave the device.
The mode is now per platform, because "who may read this" has two
different answers and the directory above the file is what makes them
differ. On the desktop, 0600 as before: $XDG_STATE_HOME/darkroom is in a
home directory on a machine that may have other accounts, and nothing
about that directory stops another local user reading a world-readable
file. On Android, 0644: /sdcard/Android/data is drwxrws--x
media_rw:ext_data_rw, so no other app can enter this app'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 read
bits buy is adb pull, which runs as shell — able to traverse a --x
directory, but then obliged to open the file as other.
The mode is also applied twice, and the second one is the fix rather
than belt and braces. OpenOptions::mode is a request: the kernel ANDs it
with the process umask, and an Android application process inherits
0o077 from the zygote, so asking for 0644 there creates 0600 and reports
nothing. It is ignored outright on a file that already exists, which
every launch after the first has. fchmod is subject to neither, and is
what the second call makes.
The comment claiming the mode was "ignored by the FAT-derived filesystem
Android presents as external storage" is gone with it. The device says
otherwise: the file it produced was 0600 exactly.
Two tests. One pins the literal mode per platform — only the desktop arm
can run under cargo test, and the comment says so rather than implying
the Android number is covered. The other reopens a log left behind with
the wrong mode, which is the one assertion on the host that fails if the
fchmod is deleted, since OpenOptions::mode cannot touch a file that is
already there.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
741 lines
30 KiB
Rust
741 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`.
|
|
//! * 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 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 (`dr_decode::base_curve`), 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));
|
|
}
|
|
}
|