diff --git a/CHANGELOG.md b/CHANGELOG.md index a3b4e7a..c707676 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,14 @@ that may never merge. They are not releases and are not listed here. ## Unreleased +- Diagnostic logs, off by default: `mapbox config set log on` (or + `MAPBOX_LOG=1`) keeps, for each run in history, the command line, each + request and the error message, tokens redacted, on your machine only. + `mapbox history show` includes the log, or says it was not captured or is + no longer available (`diagnostics.status`: `captured`, `not_captured`, + `unavailable`). Kept up to 30 days and 100 MB; needs history on. + `mapbox config list` now reports a third key, `log`. + - Command history, on by default: each run appends one line to `~/.mapbox/history/.jsonl`, kept 30 days and at most 10 MB, with its command path, exit code, error code, duration and request ids — never an argument value. It diff --git a/README.md b/README.md index c5ade6f..b6de39a 100644 --- a/README.md +++ b/README.md @@ -24,6 +24,7 @@ time from OpenAPI specs, so they always match the specs. - [Confirmation and `--yes`](#confirmation-and---yes) - [Update notices](#update-notices) - [Command history](#command-history) + - [Diagnostic logs](#diagnostic-logs) - [Privacy](#privacy) - [Uninstall](#uninstall) - [Contributing](#contributing) @@ -461,6 +462,23 @@ good, and `MAPBOX_HISTORY=0` for one shell; with it off, nothing is written and no directory is created, but what was already recorded stays until you delete `~/.mapbox/history`. `MAPBOX_CLI_NO_TELEMETRY` does not affect it. +### Diagnostic logs + +Off by default. `mapbox config set log on` (or `MAPBOX_LOG=1` for one shell) +adds, for each run history records, a line of detail in +`~/.mapbox/logs/.jsonl`: the command line, each request's method, +URL, status, request id and timing, which token was used (where it came +from, its type and account, never the token itself) and the error message. +Tokens are replaced with `` wherever they appear, and the files +never leave your machine. + +`mapbox history show` includes a run's log, or says it was not captured +(logging was off) or is no longer available. Logs are kept up to 30 days and +100 MB in total; past that the oldest go first, and the run's history record +stays. A day of logs goes when that day of history does. Logging needs +history: with history off it never runs, and with the `history` setting off +`config set log on` refuses. + ### Privacy **YOUR PRIVACY - COLLECTION OF TELEMETRY** diff --git a/docs/commands.md b/docs/commands.md index cbeb1bd..b320671 100644 --- a/docs/commands.md +++ b/docs/commands.md @@ -3205,6 +3205,7 @@ was set in, and stays in every future shell instead. | --- | --- | --- | | `update-check` | `on` | The update notice; mirrors `MAPBOX_NO_UPDATE_CHECK` (see [Update notices](../README.md#update-notices)) | | `history` | `on` | [Command history](../README.md#command-history), read by `mapbox history`; `MAPBOX_HISTORY=0` or `=1` overrides it for a session | +| `log` | `off` | [Diagnostic logs](../README.md#diagnostic-logs), shown by `mapbox history show`; `MAPBOX_LOG=1` or `=0` overrides it for a session. Needs `history` on: `config set log on` with history off fails with `history_required` | ### `mapbox config get` @@ -3216,7 +3217,7 @@ than failing, the same forgiving read the update-check cache itself uses. | Parameter | Effect | | --- | --- | -| `` | Which setting to read: `update-check` or `history`. | +| `` | Which setting to read: `update-check`, `history` or `log`. | #### Examples @@ -3255,7 +3256,7 @@ without an environment variable. | Parameter | Effect | | --- | --- | -| `` | Which setting to change: `update-check` or `history`. | +| `` | Which setting to change: `update-check`, `history` or `log`. | | `` | `on` or `off`. | #### Examples @@ -3313,6 +3314,7 @@ mapbox config list ``` update-check on history on +log off ``` @@ -3326,6 +3328,10 @@ history on { "key": "history", "value": true + }, + { + "key": "log", + "value": false } ] ``` @@ -3344,7 +3350,7 @@ default, a key explicitly set to the old default value does not. | Parameter | Effect | | --- | --- | -| `` | Which setting to clear: `update-check` or `history`. | +| `` | Which setting to clear: `update-check`, `history` or `log`. | #### Examples @@ -3388,11 +3394,17 @@ on stderr. Neither makes a request or needs a token, and neither is itself recorded — nor are `--help`, `--version`, `completion` or a run under `sudo`. +History is also the way in to [diagnostic logs](../README.md#diagnostic-logs): +there is no separate command for them. `history show` includes a run's log +when one was captured and is still kept. + ### `mapbox history list` The most recent runs, newest first: a short id, when it ran (UTC), its exit -code and its command path. `json` gives each run's full `id`, which -`history show` also accepts shortened to any prefix that names one run. +code and its command path, with `[log]` after a run whose diagnostic log was +captured (`diagnosticsCaptured` in `json`). `json` gives each run's full +`id`, which `history show` also accepts shortened to any prefix that names +one run. #### Parameters @@ -3416,8 +3428,8 @@ mapbox history list --limit 0 ``` ID TIME EXIT COMMAND -d05b3f4d 2026-09-28T11:20:03.095Z 2 mapbox styles -be40d711 2026-09-28T11:20:03.045Z 1 mapbox styles list +49d6ec63 2026-09-28T11:26:38.569Z 2 mapbox styles +2c67e6a1 2026-09-28T11:26:38.515Z 1 mapbox styles list [log] ``` @@ -3428,22 +3440,23 @@ be40d711 2026-09-28T11:20:03.045Z 1 mapbox styles list "command": [ "styles" ], - "durationMs": 41, + "durationMs": 42, "errorCode": "usage", "exitCode": 2, - "id": "d05b3f4d-9947-4662-a037-3d00b68d1d6e", - "time": "2026-09-28T11:20:03.095Z" + "id": "49d6ec63-719d-4844-9005-a201fa9902c3", + "time": "2026-09-28T11:26:38.569Z" }, { "command": [ "styles", "list" ], - "durationMs": 157, + "diagnosticsCaptured": true, + "durationMs": 191, "errorCode": "http_401", "exitCode": 1, - "id": "be40d711-3d62-4e9b-8dde-23535020b368", - "time": "2026-09-28T11:20:03.045Z" + "id": "2c67e6a1-0e32-4037-9c49-3fd21a62fab5", + "time": "2026-09-28T11:26:38.515Z" } ] ``` @@ -3453,12 +3466,19 @@ be40d711 2026-09-28T11:20:03.045Z 1 mapbox styles list ### `mapbox history show` -Everything recorded about one run: its command path, how it ended, its -error code, how many requests it made and the ids of the last five. `json` -gives the record as it was written. An id that names no run fails with -`history_not_found`; a prefix shared by several fails with -`history_ambiguous_id`; with nothing recorded yet, `show` with no id fails -with `history_empty`. +Everything recorded about one run — its command path, how it ended, its +error code, how many requests it made and the ids of the last five — and +what became of its diagnostic log, as `diagnostics.status` in `json`: + +| `status` | Meaning | +| --- | --- | +| `captured` | The log is in `diagnostics.log`: the command line with tokens redacted, which token was used, each request and the error message. | +| `not_captured` | Diagnostic logging was off for this run. | +| `unavailable` | A log was captured but has since expired or been removed to keep diagnostic logs under 100 MB. | + +An id that names no run fails with `history_not_found`; a prefix shared by +several fails with `history_ambiguous_id`; with nothing recorded yet, +`show` with no id fails with `history_empty`. #### Parameters @@ -3471,23 +3491,30 @@ with `history_empty`. ```sh mapbox history show -mapbox history show be40d711 +mapbox history show 2c67e6a1 ``` #### Outputs +A run whose log was captured: +
textjson
``` -Run be40d711-3d62-4e9b-8dde-23535020b368 -Time 2026-09-28T11:20:03.045Z (mapbox 0.3.0) +Run 2c67e6a1-0e32-4037-9c49-3fd21a62fab5 +Time 2026-09-28T11:26:38.515Z (mapbox 0.3.0) Command mapbox styles list -Exit 1 after 157 ms +Exit 1 after 191 ms Error http_401 Requests 1 - request id 7ovbf8wEjg4S_uS-u8SNW0OHb64pCVgD5fThd2C2q9ZlE7bDY-s0yw== + request id Aa-RR5_S57xRecEYSj1rtfOCcwjDVNCnA8eUvLDFDf824mdVExRDDg== +Log mapbox styles list --username example --token + token flag, pk, account example + GET https://api.mapbox.com/styles/v1/example?access_token= -> 401 in 149 ms (request id Aa-RR5_S57xRecEYSj1rtfOCcwjDVNCnA8eUvLDFDf824mdVExRDDg==) + 0 bytes to stdout + error http_401: Not Authorized - Invalid Token ``` @@ -3498,16 +3525,48 @@ Requests 1 "styles", "list" ], - "durationMs": 157, + "diagnostics": { + "log": { + "argv": [ + "styles", + "list", + "--username", + "example", + "--token", + "" + ], + "auth": { + "account": "example", + "source": "flag", + "type": "pk" + }, + "error": { + "code": "http_401", + "message": "Not Authorized - Invalid Token" + }, + "requests": [ + { + "durationMs": 149, + "method": "GET", + "requestId": "Aa-RR5_S57xRecEYSj1rtfOCcwjDVNCnA8eUvLDFDf824mdVExRDDg==", + "status": 401, + "url": "https://api.mapbox.com/styles/v1/example?access_token=" + } + ], + "stdoutBytes": 0 + }, + "status": "captured" + }, + "durationMs": 191, "errorCode": "http_401", "exitCode": 1, - "id": "be40d711-3d62-4e9b-8dde-23535020b368", + "id": "2c67e6a1-0e32-4037-9c49-3fd21a62fab5", "invocation": "execute", "requestCount": 1, "requestIds": [ - "7ovbf8wEjg4S_uS-u8SNW0OHb64pCVgD5fThd2C2q9ZlE7bDY-s0yw==" + "Aa-RR5_S57xRecEYSj1rtfOCcwjDVNCnA8eUvLDFDf824mdVExRDDg==" ], - "time": "2026-09-28T11:20:03.045Z", + "time": "2026-09-28T11:26:38.515Z", "version": "0.3.0" } ``` @@ -3515,6 +3574,14 @@ Requests 1
+Without a log, the last line of `text` says why, and `json` carries only +the status: + +``` +Log not captured: diagnostic logging was off for this run (`mapbox config set log on` captures the next ones) +Log no longer available: it expired or was removed to keep diagnostic logs under 100 MB +``` + --- ## Doctor diff --git a/src/config.rs b/src/config.rs index a33d479..81fcaa7 100644 --- a/src/config.rs +++ b/src/config.rs @@ -23,7 +23,8 @@ use serde::{Deserialize, Serialize}; use serde_json::{json, Value}; use crate::auth; -use crate::output::{self, Mode}; +use crate::output::{self, CliError, Mode}; +use crate::remedy::Remedy; pub const COMMAND: &str = "config"; @@ -31,7 +32,8 @@ const CONFIG_FILE: &str = "config.json"; const UPDATE_CHECK_KEY: &str = "update-check"; const HISTORY_KEY: &str = "history"; -const KEYS: &[&str] = &[UPDATE_CHECK_KEY, HISTORY_KEY]; +const LOG_KEY: &str = "log"; +const KEYS: &[&str] = &[UPDATE_CHECK_KEY, HISTORY_KEY, LOG_KEY]; const ON: &str = "on"; const OFF: &str = "off"; @@ -46,6 +48,8 @@ struct Config { update_check: Option, #[serde(default, skip_serializing_if = "Option::is_none")] history: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + log: Option, } fn config_path() -> Option { @@ -92,6 +96,12 @@ pub fn history_enabled() -> bool { read_config().history.unwrap_or(true) } +/// Whether [`crate::run_log`] writes diagnostics, per the persisted setting. +/// Off unless turned on, and it has no effect while history is off. +pub fn log_enabled() -> bool { + read_config().log.unwrap_or(false) +} + fn on_off(enabled: bool) -> &'static str { if enabled { ON @@ -107,6 +117,7 @@ fn resolve(config: &Config, key: &str) -> bool { match key { UPDATE_CHECK_KEY => update_check_setting(config), HISTORY_KEY => config.history.unwrap_or(true), + LOG_KEY => config.log.unwrap_or(false), _ => unreachable!("clap's value_parser restricts `key` to {KEYS:?}"), } } @@ -120,6 +131,7 @@ fn clear(config: &mut Config, key: &str) { match key { UPDATE_CHECK_KEY => config.update_check = None, HISTORY_KEY => config.history = None, + LOG_KEY => config.log = None, _ => unreachable!("clap's value_parser restricts `key` to {KEYS:?}"), } } @@ -182,9 +194,26 @@ pub fn set(matches: &ArgMatches, mode: Mode) -> Result<()> { let enabled = value == ON; let mut config = read_config(); + // Diagnostics belong to history records, so they need history on. + // Refused rather than stored: a setting that reads `on` and does + // nothing would be worse than an error that says why. + if key == LOG_KEY && enabled && !resolve(&config, HISTORY_KEY) { + return Err(CliError::new( + "history_required", + "Diagnostic logging needs command history, which is off.", + ) + .with_remedy( + Remedy::default().with_action(Some("mapbox config set history on".to_string())), + ) + .into()); + } + if key == HISTORY_KEY && !enabled && resolve(&config, LOG_KEY) { + output::progress("Diagnostic logging (`log`) stays off while history is off."); + } match key.as_str() { UPDATE_CHECK_KEY => config.update_check = Some(enabled), HISTORY_KEY => config.history = Some(enabled), + LOG_KEY => config.log = Some(enabled), _ => unreachable!("clap's value_parser restricts `key` to {KEYS:?}"), } write_config(&config)?; diff --git a/src/dated_jsonl.rs b/src/dated_jsonl.rs index 098cc34..397a274 100644 --- a/src/dated_jsonl.rs +++ b/src/dated_jsonl.rs @@ -39,10 +39,11 @@ pub(crate) fn private_dir(name: &str) -> Option { Some(dir) } -/// Appends `line` to today's file in `dir`, and on the first write of a day -/// deletes files older than `keep_days` (today included). Best-effort. -pub(crate) fn append(dir: &Path, line: &str, keep_days: u64) { - let now = now_secs(); +/// Appends `line` to the file in `dir` for `at`'s UTC day, and on the first +/// write of a day deletes files older than `keep_days` (that day included). +/// Best-effort. +pub(crate) fn append(dir: &Path, line: &str, at: SystemTime, keep_days: u64) { + let now = unix_secs(at); let (today, _) = utc_date(now); let path = dir.join(format!("{today}.jsonl")); let is_new_day = !path.exists(); @@ -87,6 +88,39 @@ pub(crate) fn shed(dir: &Path, limit: u64) { } } +/// Deletes the dated files in `dir` whose date `keep` refuses. +pub(crate) fn prune_where(dir: &Path, keep: impl Fn(&str) -> bool) { + for name in dated_names(dir) { + if let Some(date) = dated_file(&name) { + if !keep(date) { + let _ = std::fs::remove_file(dir.join(&name)); + } + } + } +} + +/// The lines of `dir`'s file for `date` (`YYYY-MM-DD`), oldest first. +pub(crate) fn read_day(dir: &Path, date: &str) -> Vec { + let path = dir.join(format!("{date}.jsonl")); + std::fs::read_to_string(path) + .map(|text| { + text.lines() + .filter(|line| !line.is_empty()) + .map(str::to_string) + .collect() + }) + .unwrap_or_default() +} + +/// The oldest date kept by a window of `days` (today included), as of now. +pub(crate) fn oldest_kept(days: u64) -> String { + oldest_kept_at(unix_secs(SystemTime::now()), days) +} + +fn oldest_kept_at(now: u64, days: u64) -> String { + utc_date(now.saturating_sub(days.saturating_sub(1) * 86_400)).0 +} + fn dated_names(dir: &Path) -> Vec { let Ok(entries) = std::fs::read_dir(dir) else { return vec![]; @@ -191,7 +225,7 @@ fn create_private(path: &Path) -> std::io::Result { } fn prune(dir: &Path, now: u64, keep_days: u64) { - let (oldest_kept, _) = utc_date(now.saturating_sub(keep_days.saturating_sub(1) * 86_400)); + let oldest_kept = oldest_kept_at(now, keep_days); let Ok(entries) = std::fs::read_dir(dir) else { return; }; @@ -235,10 +269,8 @@ pub(crate) fn timestamp(at: SystemTime) -> String { ) } -fn now_secs() -> u64 { - SystemTime::now() - .duration_since(UNIX_EPOCH) - .map_or(0, |d| d.as_secs()) +fn unix_secs(at: SystemTime) -> u64 { + at.duration_since(UNIX_EPOCH).map_or(0, |d| d.as_secs()) } #[cfg(test)] diff --git a/src/history.rs b/src/history.rs index 9c5af6b..b0cb9d8 100644 --- a/src/history.rs +++ b/src/history.rs @@ -1,19 +1,22 @@ //! `mapbox history` — the runs [`crate::run_history`] recorded. //! //! `list` is one line per run, newest first; `show` is everything recorded -//! about one run, the newest when no id is given. An id can be shortened to -//! any prefix that names one run, the way `list` prints them. +//! about one run, the newest when no id is given, with its diagnostic log +//! when one was captured and is still kept ([`crate::run_log`]). An id can +//! be shortened to any prefix that names one run, the way `list` prints +//! them. There is no separate command for the logs: history is the one way +//! in to both. //! //! Reads history and nothing else: no token, no request, and nothing //! created on disk. It is not itself recorded. use anyhow::Result; use clap::{value_parser, Arg, ArgMatches, Command}; -use serde_json::Value; +use serde_json::{json, Value}; use crate::output::{self, CliError, Mode}; use crate::remedy::Remedy; -use crate::run_history; +use crate::{run_history, run_log}; pub const COMMAND: &str = "history"; @@ -64,13 +67,17 @@ pub fn list(matches: &ArgMatches, mode: Mode) -> Result<()> { } let rows = entries.iter().map(|entry| { - format!( + let mut line = format!( "{:SHORT_ID$} {:24} {:>4} {}", short_id(entry), field(entry, "time"), exit_code(entry), command_line(entry) - ) + ); + if captured(entry) { + line.push_str(" [log]"); + } + line }); let text = if entries.is_empty() { String::new() @@ -94,6 +101,7 @@ pub fn list(matches: &ArgMatches, mode: Mode) -> Result<()> { "exitCode", "errorCode", "durationMs", + "diagnosticsCaptured", ] { if let Some(value) = entry.get(key) { summary.insert(key.to_string(), value.clone()); @@ -115,7 +123,128 @@ pub fn show(matches: &ArgMatches, mode: Mode) -> Result<()> { })?, Some(prefix) => find(&entries, prefix)?, }; - output::emit(mode, &detail(&entry), entry) + let diagnostics = diagnostics(&entry); + let mut text = detail(&entry); + text.push('\n'); + text.push_str(&diagnostics_detail(&diagnostics)); + let mut json = entry; + if let Some(object) = json.as_object_mut() { + object.remove("diagnosticsCaptured"); + object.insert("diagnostics".to_string(), diagnostics.json()); + } + output::emit(mode, &text, json) +} + +/// What became of a run's diagnostic log. +enum Diagnostics { + /// Logging was off for the run. + NotCaptured, + /// Captured, then expired or dropped to stay under the size limit. + Unavailable, + Captured(Value), +} + +impl Diagnostics { + /// `status` is a machine-readable value: `not_captured`, `unavailable` + /// or `captured`. + fn json(&self) -> Value { + match self { + Diagnostics::NotCaptured => json!({ "status": "not_captured" }), + Diagnostics::Unavailable => json!({ "status": "unavailable" }), + Diagnostics::Captured(log) => json!({ "status": "captured", "log": log }), + } + } +} + +fn captured(entry: &Value) -> bool { + entry.get("diagnosticsCaptured").and_then(Value::as_bool) == Some(true) +} + +fn diagnostics(entry: &Value) -> Diagnostics { + if !captured(entry) { + return Diagnostics::NotCaptured; + } + match run_log::find(field(entry, "id"), field(entry, "time")) { + Some(mut log) => { + // Already in the record it belongs to. + if let Some(object) = log.as_object_mut() { + for key in ["id", "time"] { + object.remove(key); + } + } + Diagnostics::Captured(log) + } + None => Diagnostics::Unavailable, + } +} + +fn diagnostics_detail(diagnostics: &Diagnostics) -> String { + let log = match diagnostics { + Diagnostics::NotCaptured => { + return "Log not captured: diagnostic logging was off for this run \ + (`mapbox config set log on` captures the next ones)" + .to_string() + } + Diagnostics::Unavailable => { + return "Log no longer available: it expired or was removed to keep \ + diagnostic logs under 100 MB" + .to_string() + } + Diagnostics::Captured(log) => log, + }; + let argv: Vec<&str> = log["argv"] + .as_array() + .map(|args| args.iter().filter_map(Value::as_str).collect()) + .unwrap_or_default(); + let mut out = vec![format!("Log mapbox {}", argv.join(" "))]; + if let Some(auth) = log.get("auth") { + let mut line = format!(" token {}, {}", field(auth, "source"), field(auth, "type")); + if let Some(account) = auth.get("account").and_then(Value::as_str) { + line.push_str(&format!(", account {account}")); + } + out.push(line); + } + if let Some(step) = log.get("authStep").and_then(Value::as_str) { + out.push(format!(" auth step {step}")); + } + for request in log["requests"].as_array().into_iter().flatten() { + let outcome = match request.get("status").and_then(Value::as_u64) { + Some(status) => status.to_string(), + None => field(request, "error").to_string(), + }; + let mut line = format!( + " {} {} -> {} in {} ms", + field(request, "method"), + field(request, "url"), + outcome, + request["durationMs"].as_u64().unwrap_or(0) + ); + if let Some(id) = request.get("requestId").and_then(Value::as_str) { + line.push_str(&format!(" (request id {id})")); + } + out.push(line); + } + if let Some(n) = log.get("requestsNotListed").and_then(Value::as_u64) { + out.push(format!(" and {n} more requests not listed")); + } + if log.get("morePages").and_then(Value::as_bool) == Some(true) { + out.push(" stopped with pages left".to_string()); + } + out.push(format!( + " {} bytes to stdout", + log["stdoutBytes"].as_u64().unwrap_or(0) + )); + if let Some(version) = log.get("updateNotice").and_then(Value::as_str) { + out.push(format!(" update notice for {version}")); + } + if let Some(error) = log.get("error") { + out.push(format!( + " error {}: {}", + field(error, "code"), + field(error, "message") + )); + } + out.join("\n") } /// The one run whose id starts with `prefix`. @@ -214,7 +343,6 @@ fn command_line(entry: &Value) -> String { #[cfg(test)] mod tests { use super::*; - use serde_json::json; fn runs() -> Vec { vec![ diff --git a/src/main.rs b/src/main.rs index 52319c7..49d4ebe 100644 --- a/src/main.rs +++ b/src/main.rs @@ -30,6 +30,7 @@ mod link; mod output; mod remedy; mod run_history; +mod run_log; mod run_record; mod schema; mod skill_dest; diff --git a/src/run_history.rs b/src/run_history.rs index 5fa944d..2d358d5 100644 --- a/src/run_history.rs +++ b/src/run_history.rs @@ -60,23 +60,31 @@ struct Line { request_count: usize, #[serde(skip_serializing_if = "Vec::is_empty")] request_ids: Vec, + /// Whether a diagnostic log was written for this run. Kept with the + /// record so that detail dropped later reads as "no longer available", + /// not "never captured". + #[serde(skip_serializing_if = "std::ops::Not::not")] + diagnostics_captured: bool, } fn is_zero(n: &usize) -> bool { *n == 0 } -/// Appends the run's line, unless history is off or the run is one it -/// does not record. -pub(crate) fn write(record: &Record) { - if !enabled() || !recorded(record, std::env::var_os("SUDO_USER").is_some()) { - return; - } - let Ok(text) = serde_json::to_string(&line(record)) else { +/// Whether this run gets a history line: history is on and the run is one +/// it records. +pub(crate) fn will_record(record: &Record) -> bool { + enabled() && recorded(record, std::env::var_os("SUDO_USER").is_some()) +} + +/// Appends the run's line. The caller has checked [`will_record`]; +/// `diagnostics` says whether a diagnostic log is written for it too. +pub(crate) fn write(record: &Record, diagnostics: bool, at: SystemTime) { + let Ok(text) = serde_json::to_string(&line(record, diagnostics, at)) else { return; }; if let Some(dir) = dated_jsonl::private_dir(DIR) { - dated_jsonl::append(&dir, &text, RETENTION_DAYS); + dated_jsonl::append(&dir, &text, at, RETENTION_DAYS); dated_jsonl::shed(&dir, LIMIT_BYTES); } } @@ -96,7 +104,7 @@ fn recorded(record: &Record, under_sudo: bool) -> bool { && record.command.first().map(String::as_str) != Some(history::COMMAND) } -fn line(record: &Record) -> Line { +fn line(record: &Record, diagnostics: bool, at: SystemTime) -> Line { let ids: Vec = record .requests .iter() @@ -104,7 +112,7 @@ fn line(record: &Record) -> Line { .collect(); Line { id: record.id.clone(), - time: dated_jsonl::timestamp(SystemTime::now()), + time: dated_jsonl::timestamp(at), version: env!("CARGO_PKG_VERSION"), command: record.command.clone(), invocation: record.invocation.map(Invocation::as_str), @@ -113,6 +121,7 @@ fn line(record: &Record) -> Line { duration_ms: record.duration.as_millis() as u64, request_count: record.requests.len(), request_ids: ids[ids.len().saturating_sub(MAX_REQUEST_IDS)..].to_vec(), + diagnostics_captured: diagnostics, } } @@ -121,6 +130,11 @@ fn dir_path() -> Option { Some(auth::config_dir_path()?.join(DIR)) } +/// Whether history still has a file for `date` (`YYYY-MM-DD`). +pub(crate) fn has_day(date: &str) -> bool { + dir_path().is_some_and(|dir| dir.join(format!("{date}.jsonl")).is_file()) +} + /// Every run in history, oldest first, skipping any line that doesn't parse. pub(crate) fn entries() -> Vec { let Some(dir) = dir_path() else { @@ -163,7 +177,7 @@ mod tests { .iter() .map(std::ffi::OsString::from) .collect(); - let text = serde_json::to_string(&line(&run)).unwrap(); + let text = serde_json::to_string(&line(&run, false, SystemTime::now())).unwrap(); assert!(text.contains(r#""command":["search","forward"]"#), "{text}"); assert!(!text.contains("Pennsylvania"), "{text}"); } diff --git a/src/run_log.rs b/src/run_log.rs new file mode 100644 index 0000000..56fd235 --- /dev/null +++ b/src/run_log.rs @@ -0,0 +1,280 @@ +//! Diagnostic logs: for a run that [`crate::run_history`] recorded, one +//! line of detail in `~/.mapbox/logs/.jsonl` (or under +//! `$MAPBOX_CONFIG_DIR`), linked to the history record by its `id` and +//! shown by `mapbox history show`. +//! +//! History keeps only what is safe without anyone having asked; this keeps +//! what answers "why did that command fail": the command line, each request +//! and the error message. So it is off unless turned on — `mapbox config +//! set log on`, or `MAPBOX_LOG=1` for a session (`=0` turns it off over the +//! setting) — and it requires history: with history off it never runs, +//! rather than writing detail that nothing could lead back to. +//! +//! Kept for [`RETENTION_DAYS`] days and at most [`LIMIT_BYTES`] in total, +//! the oldest dropped first. The history record stays when its detail is +//! dropped, and says it was captured, so `history show` can tell "not +//! captured" from "no longer available". A day of detail goes when that +//! day of history does. +//! +//! It still never records a token. The command line goes through the +//! redaction `--debug` applies to `tilesets-cli`'s arguments, URLs arrive +//! with the access token already redacted by [`crate::http::send`], and +//! every string is then scrubbed of token-shaped words, because an error +//! message can quote a URL that a module other than `executor` built. + +use std::path::PathBuf; +use std::time::SystemTime; + +use serde::Serialize; +use serde_json::Value; + +use crate::run_record::{self, Record}; +use crate::{auth, config, dated_jsonl, run_history, telemetry, tilesets_cli}; + +const DIR: &str = "logs"; +const LOG_ENV: &str = "MAPBOX_LOG"; +const RETENTION_DAYS: u64 = run_history::RETENTION_DAYS; +const LIMIT_BYTES: u64 = 100 * 1024 * 1024; + +/// A `--all` run can page hundreds of times; past this, requests are counted +/// rather than listed. +const MAX_REQUESTS: usize = 100; +/// Long enough for an error message or a URL, short enough that an inline +/// `--data` body does not make one line of the log most of the file. +const MAX_TEXT: usize = 2000; +const REDACTED: &str = ""; + +#[derive(Serialize)] +#[serde(rename_all = "camelCase")] +/// Only what the history record lacks, plus the `id` and `time` that find +/// that record. +struct Line { + id: String, + time: String, + argv: Vec, + #[serde(skip_serializing_if = "Option::is_none")] + auth: Option, + #[serde(skip_serializing_if = "Vec::is_empty")] + requests: Vec, + #[serde(skip_serializing_if = "is_zero")] + requests_not_listed: usize, + #[serde(skip_serializing_if = "std::ops::Not::not")] + more_pages: bool, + stdout_bytes: u64, + #[serde(skip_serializing_if = "Option::is_none")] + auth_step: Option<&'static str>, + #[serde(skip_serializing_if = "Option::is_none")] + update_notice: Option, + #[serde(skip_serializing_if = "Option::is_none")] + error: Option, +} + +#[derive(Serialize)] +struct Auth { + source: &'static str, + #[serde(rename = "type")] + kind: &'static str, + #[serde(skip_serializing_if = "Option::is_none")] + account: Option, +} + +#[derive(Serialize)] +#[serde(rename_all = "camelCase")] +struct Request { + method: String, + url: String, + #[serde(skip_serializing_if = "Option::is_none")] + status: Option, + #[serde(skip_serializing_if = "Option::is_none")] + request_id: Option, + duration_ms: u64, + #[serde(skip_serializing_if = "Option::is_none")] + error: Option, +} + +#[derive(Serialize)] +struct Failure { + code: String, + message: String, +} + +fn is_zero(n: &usize) -> bool { + *n == 0 +} + +/// Appends the run's line. The caller has checked [`enabled`] and that +/// history recorded the run at `at`. +pub(crate) fn write(record: &Record, at: SystemTime) { + let Ok(text) = serde_json::to_string(&line(record, at)) else { + return; + }; + if let Some(dir) = dated_jsonl::private_dir(DIR) { + dated_jsonl::append(&dir, &text, at, RETENTION_DAYS); + dated_jsonl::shed(&dir, LIMIT_BYTES); + } +} + +/// Whether this run writes diagnostics: never with history off, otherwise +/// `MAPBOX_LOG` when it is set and the persisted setting when it is not. +pub(crate) fn enabled() -> bool { + run_history::enabled() && telemetry::env_switch(LOG_ENV).unwrap_or_else(config::log_enabled) +} + +/// Where the logs live, without creating them. +fn dir_path() -> Option { + Some(auth::config_dir_path()?.join(DIR)) +} + +/// Deletes each day of detail whose day of history has expired or gone. +/// Run on every run that finishes, logging on or off, so detail never +/// outlives the record it belongs to. Creates nothing. +pub(crate) fn expire_with_history() { + let Some(dir) = dir_path().filter(|dir| dir.is_dir()) else { + return; + }; + let oldest = dated_jsonl::oldest_kept(RETENTION_DAYS); + dated_jsonl::prune_where(&dir, |date| { + date >= oldest.as_str() && run_history::has_day(date) + }); +} + +/// The detail logged for the run `id` that history recorded at `time`. +/// Only that day's file is read: both lines carry the same time. +pub(crate) fn find(id: &str, time: &str) -> Option { + let dir = dir_path()?; + dated_jsonl::read_day(&dir, time.get(..10)?) + .into_iter() + .filter_map(|line| serde_json::from_str::(&line).ok()) + .find(|entry| entry.get("id").and_then(Value::as_str) == Some(id)) +} + +fn line(record: &Record, at: SystemTime) -> Line { + Line { + id: record.id.clone(), + time: dated_jsonl::timestamp(at), + argv: tilesets_cli::redacted_argv(&record.argv) + .iter() + .map(|arg| clean(arg)) + .collect(), + auth: record.token.as_ref().map(|token| Auth { + source: token.source.as_str(), + kind: token.kind, + account: token.account.as_deref().map(clean), + }), + requests: record + .requests + .iter() + .take(MAX_REQUESTS) + .map(request) + .collect(), + requests_not_listed: record.requests.len().saturating_sub(MAX_REQUESTS), + more_pages: record.more_pages, + stdout_bytes: record.stdout_bytes, + auth_step: record.auth_step, + update_notice: record.update_notice.as_deref().map(clean), + error: record.error.as_ref().map(|failure| Failure { + code: clean(&failure.code), + message: clean(&failure.message), + }), + } +} + +fn request(request: &run_record::Request) -> Request { + Request { + method: request.method.clone(), + url: clean(&request.url), + status: request.status, + request_id: request.request_id.as_deref().map(clean), + duration_ms: request.elapsed.as_millis() as u64, + error: request.error.as_deref().map(clean), + } +} + +/// Scrubbed of token-shaped words, then clipped to [`MAX_TEXT`]. +fn clean(text: &str) -> String { + let scrubbed = scrub_tokens(text); + match scrubbed.char_indices().nth(MAX_TEXT) { + Some((end, _)) => format!("{}…", &scrubbed[..end]), + None => scrubbed, + } +} + +/// `text` with every word that looks like a Mapbox token replaced. A word +/// here is a run of the characters a token is made of, so a token inside a +/// URL, after `=`, or in quotes is still found. The token may start inside +/// the word, as after a percent-encoded `=` (`%3Dpk.`) or in a short-flag +/// cluster (`-ytpk.`); the word is redacted from there. +fn scrub_tokens(text: &str) -> String { + let is_token_char = |c: char| c.is_ascii_alphanumeric() || matches!(c, '.' | '_' | '-'); + let mut out = String::with_capacity(text.len()); + let mut rest = text; + while let Some(start) = rest.find(is_token_char) { + out.push_str(&rest[..start]); + let word_len = rest[start..] + .find(|c: char| !is_token_char(c)) + .unwrap_or(rest.len() - start); + let word = &rest[start..start + word_len]; + // Every token character is ASCII, so every index is a boundary. + match (0..word.len()).find(|&i| tilesets_cli::looks_like_a_token(&word[i..])) { + Some(at) => { + out.push_str(&word[..at]); + out.push_str(REDACTED); + } + None => out.push_str(word), + } + rest = &rest[start + word_len..]; + } + out.push_str(rest); + out +} + +#[cfg(test)] +mod tests { + use super::*; + + const TOKEN: &str = "pk.eyJ1IjoiZXhhbXBsZS11c2VyIiwiYSI6IngifQ.SIGNATURE-NOT-FOR-LOGS"; + + #[test] + fn tokens_are_scrubbed_wherever_they_sit() { + for (text, expected) in [ + ( + format!("GET https://api.mapbox.com/x?access_token={TOKEN}&a=1"), + "GET https://api.mapbox.com/x?access_token=&a=1".to_string(), + ), + ( + format!("token \"{TOKEN}\"."), + "token \"\".".to_string(), + ), + (TOKEN.to_string(), REDACTED.to_string()), + ( + format!("url-https%3A%2F%2Fh%2Fm.png%3Faccess_token%3D{TOKEN}"), + "url-https%3A%2F%2Fh%2Fm.png%3Faccess_token%3D".to_string(), + ), + (format!("-yt{TOKEN}"), "-yt".to_string()), + ] { + assert_eq!(scrub_tokens(&text), expected); + } + } + + #[test] + fn ordinary_text_is_left_alone() { + for text in [ + "", + "styles get my-style --username pk", + "pk.short", + "No such style: ckabc123.", + "héllo wörld", + ] { + assert_eq!(scrub_tokens(text), text); + } + } + + #[test] + fn long_text_is_clipped_on_a_character_boundary() { + let text = "é".repeat(MAX_TEXT + 10); + let clipped = clean(&text); + assert_eq!(clipped.chars().count(), MAX_TEXT + 1); + assert!(clipped.ends_with('…')); + assert_eq!(clean("short"), "short"); + } +} diff --git a/src/run_record.rs b/src/run_record.rs index 208dd6e..fbaa914 100644 --- a/src/run_record.rs +++ b/src/run_record.rs @@ -14,13 +14,15 @@ use std::ffi::OsString; use std::sync::{Mutex, OnceLock}; -use std::time::{Duration, Instant}; +use std::time::{Duration, Instant, SystemTime}; use clap::parser::ValueSource; use clap::{ArgMatches, Command}; use crate::spec::ServiceSpec; -use crate::{auth, completion, confirm, executor, http, output, run_history, tilesets_cli}; +use crate::{ + auth, completion, confirm, executor, http, output, run_history, run_log, tilesets_cli, +}; const TILESETS: &str = tilesets_cli::COMMAND; @@ -337,7 +339,20 @@ fn finish_locked(record: &mut Record, exit_code: Option) { record.finished = true; record.duration = STARTED.get().map_or(Duration::ZERO, Instant::elapsed); record.exit_code = exit_code; - run_history::write(record); + // Diagnostics only for a run history records: detail with no record + // would be unreachable, and the record says whether detail exists. + let history = run_history::will_record(record); + let diagnostics = history && run_log::enabled(); + // One time for both lines, so they land in the same day's file even + // across midnight. + let at = SystemTime::now(); + if history { + run_history::write(record, diagnostics, at); + } + if diagnostics { + run_log::write(record, at); + } + run_log::expire_with_history(); } fn uuid_v4(mut bytes: [u8; 16]) -> String { diff --git a/src/tilesets_cli.rs b/src/tilesets_cli.rs index 238624c..dfebf28 100644 --- a/src/tilesets_cli.rs +++ b/src/tilesets_cli.rs @@ -379,7 +379,7 @@ const REDACTED: &str = ""; /// starts with one — and the length keeps a user literally named `pk` from /// having their account redacted out of a debug line. Real tokens run to /// eighty characters and more. -fn looks_like_a_token(text: &str) -> bool { +pub(crate) fn looks_like_a_token(text: &str) -> bool { const PREFIXES: [&str; 3] = ["pk.", "sk.", "tk."]; text.len() >= 40 && PREFIXES.iter().any(|prefix| text.starts_with(prefix)) } @@ -397,7 +397,7 @@ fn looks_like_a_token(text: &str) -> bool { /// Both halves are needed. The flag forms catch a value the child was told to /// use; the shape catches one written anywhere else, including after a `--` /// where nothing is a flag any more. -fn redacted_argv(args: &[OsString]) -> Vec { +pub(crate) fn redacted_argv(args: &[OsString]) -> Vec { let mut rendered: Vec = Vec::with_capacity(args.len()); let mut value_is_a_token = false; diff --git a/tests/auth_profiles.rs b/tests/auth_profiles.rs index 793f7bb..fbc70eb 100644 --- a/tests/auth_profiles.rs +++ b/tests/auth_profiles.rs @@ -52,6 +52,7 @@ fn command(home: &Path) -> Command { // Off: these tests hold a run to leaving nothing on disk; what // history leaves is `tests/history.rs`'s to check. .env("MAPBOX_HISTORY", "0") + .env_remove("MAPBOX_LOG") .env("HOME", home) .env("XDG_CONFIG_HOME", home.join(".config")) .env("MAPBOX_CONFIG_DIR", config_dir(home)); diff --git a/tests/completion.rs b/tests/completion.rs index 904fb17..2e9fb56 100644 --- a/tests/completion.rs +++ b/tests/completion.rs @@ -48,6 +48,7 @@ fn command() -> Command { // Off: these tests hold a run to leaving nothing on disk; what // history leaves is `tests/history.rs`'s to check. .env("MAPBOX_HISTORY", "0") + .env_remove("MAPBOX_LOG") .env("HOME", &home) .env("XDG_CONFIG_HOME", home.join(".config")) .env("MAPBOX_CONFIG_DIR", home.join(".mapbox")); diff --git a/tests/config.rs b/tests/config.rs index a1ec7c4..471da92 100644 --- a/tests/config.rs +++ b/tests/config.rs @@ -135,7 +135,7 @@ fn list_reports_every_setting_including_an_unset_one() { assert!(empty.status.success()); assert_eq!( stdout(&empty), - r#"[{"key":"update-check","value":true},{"key":"history","value":true}]"# + r#"[{"key":"update-check","value":true},{"key":"history","value":true},{"key":"log","value":false}]"# ); let set = command(&home) @@ -151,7 +151,7 @@ fn list_reports_every_setting_including_an_unset_one() { assert!(after.status.success()); assert_eq!( stdout(&after), - r#"[{"key":"update-check","value":false},{"key":"history","value":true}]"# + r#"[{"key":"update-check","value":false},{"key":"history","value":true},{"key":"log","value":false}]"# ); let text = command(&home) @@ -159,7 +159,7 @@ fn list_reports_every_setting_including_an_unset_one() { .output() .expect("run mapbox config list"); assert!(text.status.success()); - assert_eq!(stdout(&text), "update-check\toff\nhistory\ton"); + assert_eq!(stdout(&text), "update-check\toff\nhistory\ton\nlog\toff"); } #[test] diff --git a/tests/diagnostic_log.rs b/tests/diagnostic_log.rs new file mode 100644 index 0000000..16d54f4 --- /dev/null +++ b/tests/diagnostic_log.rs @@ -0,0 +1,296 @@ +//! End-to-end tests for diagnostic logs and what `mapbox history show` says +//! about them. +//! +//! The unit tests in `src/run_log.rs` and `src/dated_jsonl.rs` cover the +//! pure parts — scrubbing a token out of a string, which lines a trim or a +//! shed keeps. What they cannot show is the contract across two stores: a +//! log only for a run history recorded, never with history off, dropped +//! without taking its history record along, and gone when its record is. +//! +//! Nothing here reaches the network. The one request a test makes goes to a +//! proxy on a loopback port nobody is listening on, so it fails at once and +//! is still a request `http::send` saw. + +use std::net::TcpListener; +use std::path::{Path, PathBuf}; +use std::process::{Command, Output}; + +use serde_json::Value; + +/// A token-shaped fake. The signature is what must never reach the disk. +const TOKEN: &str = "pk.eyJ1IjoiZXhhbXBsZS11c2VyIiwiYSI6IngifQ.SIGNATURE-NOT-FOR-LOGS"; + +fn scratch(name: &str) -> PathBuf { + let home = PathBuf::from(env!("CARGO_TARGET_TMPDIR")).join(format!("diagnostic-{name}")); + let _ = std::fs::remove_dir_all(&home); + std::fs::create_dir_all(&home).expect("create the scratch home"); + home +} + +fn config_dir(home: &Path) -> PathBuf { + home.join(".mapbox") +} + +fn log_dir(home: &Path) -> PathBuf { + config_dir(home).join("logs") +} + +fn history_dir(home: &Path) -> PathBuf { + config_dir(home).join("history") +} + +fn command(home: &Path) -> Command { + let mut cmd = Command::new(env!("CARGO_BIN_EXE_mapbox")); + cmd.env_remove("MAPBOX_ACCESS_TOKEN") + .env_remove("MapboxAccessToken") + .env_remove("MAPBOX_USERNAME") + .env_remove("MAPBOX_OUTPUT") + .env_remove("MAPBOX_HISTORY") + .env_remove("MAPBOX_LOG") + .env_remove("SUDO_USER") + .env_remove("NO_PROXY") + .env_remove("no_proxy") + .env("MAPBOX_NO_UPDATE_CHECK", "1") + .env("HOME", home) + .env("XDG_CONFIG_HOME", home.join(".config")) + .env("MAPBOX_CONFIG_DIR", config_dir(home)); + cmd +} + +fn run(home: &Path, args: &[&str]) -> Output { + command(home).args(args).output().expect("run mapbox") +} + +fn logged(home: &Path, args: &[&str]) -> Output { + command(home) + .env("MAPBOX_LOG", "1") + .args(args) + .output() + .expect("run mapbox") +} + +/// Every file's text under `dir`, concatenated in date order. +fn raw(dir: &Path) -> String { + let Ok(entries) = std::fs::read_dir(dir) else { + return String::new(); + }; + let mut files: Vec = entries.map(|e| e.expect("an entry").path()).collect(); + files.sort(); + files + .iter() + .map(|f| std::fs::read_to_string(f).unwrap_or_default()) + .collect() +} + +/// A request that fails before it leaves the machine: through a proxy on a +/// loopback port with nothing listening. +fn a_refused_request(home: &Path) -> Output { + let port = { + let listener = TcpListener::bind("127.0.0.1:0").expect("a loopback port"); + listener.local_addr().expect("the bound address").port() + }; + command(home) + .env("MAPBOX_LOG", "1") + .env("HTTPS_PROXY", format!("http://127.0.0.1:{port}")) + .args(["styles", "list", "--username", "example", "--token", TOKEN]) + .output() + .expect("run mapbox") +} + +fn show(home: &Path, id: Option<&str>) -> Value { + let mut args = vec!["-o", "json", "history", "show"]; + args.extend(id); + let out = run(home, &args); + assert!( + out.status.success(), + "{}", + String::from_utf8_lossy(&out.stderr) + ); + serde_json::from_slice(&out.stdout).expect("a JSON run") +} + +/// Today's UTC date, as the files the binary just wrote are named. +fn today(home: &Path) -> String { + std::fs::read_dir(history_dir(home)) + .expect("the history directory") + .map(|e| { + e.expect("an entry") + .file_name() + .to_string_lossy() + .into_owned() + }) + .filter_map(|name| name.strip_suffix(".jsonl").map(str::to_string)) + .max() + .expect("today's history file") +} + +/// The day before `date`, without a calendar crate. +fn day_before(date: &str) -> String { + let (mut y, mut m, mut d): (u32, u32, u32) = ( + date[0..4].parse().unwrap(), + date[5..7].parse().unwrap(), + date[8..10].parse().unwrap(), + ); + if d > 1 { + d -= 1; + } else { + if m > 1 { + m -= 1; + } else { + m = 12; + y -= 1; + } + let leap = y % 4 == 0 && (y % 100 != 0 || y % 400 == 0); + d = match m { + 2 if leap => 29, + 2 => 28, + 4 | 6 | 9 | 11 => 30, + _ => 31, + }; + } + format!("{y:04}-{m:02}-{d:02}") +} + +#[test] +fn nothing_is_logged_unless_logging_was_turned_on() { + let home = scratch("off"); + run(&home, &["styles", "lsit"]); + assert!(!log_dir(&home).exists(), "logging off created logs/"); + assert_eq!( + show(&home, None)["diagnostics"], + serde_json::json!({ "status": "not_captured" }) + ); +} + +#[test] +fn a_logged_run_is_shown_with_its_record_and_keeps_no_token() { + let home = scratch("captured"); + assert!(!a_refused_request(&home).status.success()); + + let shown = show(&home, None); + assert_eq!(shown["command"], serde_json::json!(["styles", "list"])); + let diagnostics = &shown["diagnostics"]; + assert_eq!(diagnostics["status"], "captured", "{shown}"); + let log = &diagnostics["log"]; + assert_eq!(log["auth"]["source"], "flag"); + assert_eq!(log["auth"]["account"], "example-user"); + assert!(log["argv"].to_string().contains(""), "{log}"); + let request = &log["requests"][0]; + assert!(request["status"].is_null(), "{request}"); + assert!( + request["url"] + .as_str() + .unwrap() + .contains("access_token="), + "{request}" + ); + + let on_disk = raw(&log_dir(&home)) + &raw(&history_dir(&home)); + assert!(!on_disk.contains("SIGNATURE-NOT-FOR-LOGS"), "{on_disk}"); + assert!(!on_disk.contains(TOKEN), "{on_disk}"); +} + +#[test] +fn logging_needs_history() { + let home = scratch("needs-history"); + let out = command(&home) + .env("MAPBOX_HISTORY", "0") + .env("MAPBOX_LOG", "1") + .args(["styles", "lsit"]) + .output() + .expect("run mapbox"); + assert!(!out.status.success()); + assert!(!config_dir(&home).exists(), "logging ran with history off"); + + assert!(run(&home, &["config", "set", "history", "off"]) + .status + .success()); + let refused = run(&home, &["-o", "json", "config", "set", "log", "on"]); + assert!(!refused.status.success()); + assert!( + String::from_utf8_lossy(&refused.stderr).contains(r#""code":"history_required""#), + "{}", + String::from_utf8_lossy(&refused.stderr) + ); + let get = run(&home, &["-o", "text", "config", "get", "log"]); + assert_eq!(String::from_utf8_lossy(&get.stdout).trim(), "off"); +} + +#[test] +fn a_log_that_is_gone_is_no_longer_available_and_its_record_stays() { + let home = scratch("gone"); + logged(&home, &["styles", "lsit"]); + let id = show(&home, None)["id"].as_str().unwrap().to_string(); + for entry in std::fs::read_dir(log_dir(&home)).expect("logs/") { + std::fs::remove_file(entry.expect("an entry").path()).expect("remove a log file"); + } + let shown = show(&home, Some(&id[..8])); + assert_eq!(shown["id"], id.as_str(), "the record stays"); + assert_eq!( + shown["diagnostics"], + serde_json::json!({ "status": "unavailable" }) + ); +} + +#[test] +fn past_the_size_limit_the_oldest_logs_go_and_their_records_stay() { + let home = scratch("limit"); + logged(&home, &["styles", "lsit"]); + let yesterday = day_before(&today(&home)); + + // A run from yesterday, with a log large enough to cross 100 MB alone. + // Sparse: the size is in the metadata, which is all the limit reads. + let old_id = "0ld00000-0000-4000-8000-000000000001"; + std::fs::write( + history_dir(&home).join(format!("{yesterday}.jsonl")), + format!( + "{{\"id\":\"{old_id}\",\"time\":\"{yesterday}T12:00:00.000Z\",\"diagnosticsCaptured\":true}}\n" + ), + ) + .expect("yesterday's history"); + let big = std::fs::File::create(log_dir(&home).join(format!("{yesterday}.jsonl"))) + .expect("yesterday's log"); + big.set_len(101 * 1024 * 1024) + .expect("a sparse 101 MB file"); + + assert!(!logged(&home, &["styles", "lsit"]).status.success()); + let total: u64 = std::fs::read_dir(log_dir(&home)) + .expect("logs/") + .map(|e| e.expect("an entry").metadata().expect("its size").len()) + .sum(); + assert!(total <= 100 * 1024 * 1024, "{total} bytes of logs"); + let old = show(&home, Some(old_id)); + assert_eq!(old["id"], old_id, "its history record stays"); + assert_eq!(old["diagnostics"]["status"], "unavailable"); + assert_eq!( + show(&home, None)["diagnostics"]["status"], + "captured", + "the newest log stays" + ); +} + +#[test] +fn a_log_goes_when_its_history_does() { + let home = scratch("linked"); + logged(&home, &["styles", "lsit"]); + let yesterday = day_before(&today(&home)); + + // Detail for a day history no longer has, and a day past the window. + let orphan = log_dir(&home).join(format!("{yesterday}.jsonl")); + std::fs::write(&orphan, "{}\n").expect("an orphaned log"); + let expired_log = log_dir(&home).join("2000-01-01.jsonl"); + std::fs::write(history_dir(&home).join("2000-01-01.jsonl"), "{}\n").expect("expired history"); + std::fs::write(&expired_log, "{}\n").expect("an expired log"); + + // With logging off, so the cleanup is not a side effect of writing. + // History prunes itself only on the first run of a day, so the expired + // history file may still be there; its log goes regardless. + run(&home, &["styles", "lsit"]); + assert!(!orphan.exists(), "a log outlived its history"); + assert!(!expired_log.exists(), "a log outlived 30 days"); + assert_eq!( + show(&home, None)["diagnostics"]["status"], + "not_captured", + "the newest run, with logging off" + ); +} diff --git a/tests/history.rs b/tests/history.rs index 99aad4c..bc3ff80 100644 --- a/tests/history.rs +++ b/tests/history.rs @@ -43,6 +43,7 @@ fn command(home: &Path) -> Command { .env_remove("MAPBOX_USERNAME") .env_remove("MAPBOX_OUTPUT") .env_remove("MAPBOX_HISTORY") + .env_remove("MAPBOX_LOG") .env_remove("SUDO_USER") .env_remove("NO_PROXY") .env_remove("no_proxy") diff --git a/tests/non_interactive.rs b/tests/non_interactive.rs index 63e3a13..a5475dd 100644 --- a/tests/non_interactive.rs +++ b/tests/non_interactive.rs @@ -42,6 +42,7 @@ fn command(home: &Path) -> Command { .env("MAPBOX_HISTORY", "0") .env_remove("MAPBOX_YES") .env_remove("MAPBOX_CONFIG_DIR") + .env_remove("MAPBOX_LOG") .env("HOME", home); cmd }