From d695a08fea2bfc37e36a8733d52e216238f3f527 Mon Sep 17 00:00:00 2001 From: Mofei Zhu Date: Mon, 28 Sep 2026 14:28:38 +0300 Subject: [PATCH 1/2] Add diagnostic logs, shown through mapbox history show For each run command history records, `mapbox config set log on` (or MAPBOX_LOG=1) adds a line of detail to ~/.mapbox/logs/.jsonl, linked to the history record by its id: the command line with tokens redacted, which token was used, each request (method, redacted URL, status, request id, timing) and the error message. Off by default. Logging needs history. With history off it never runs, and `config set log on` refuses with history_required rather than store a setting that does nothing. A run history doesn't record gets no log either, since nothing could lead back to it. `mapbox history show` includes the log and says what became of it: diagnostics.status is captured, not_captured (logging was off) or unavailable (captured, since expired or evicted). The history record carries diagnosticsCaptured so the last two can be told apart. There is no separate logs command. Logs are kept up to 30 days and 100 MB in total. Past the limit the oldest go first, down to the line, and their history records stay. On every run, a day of logs whose day of history has expired or gone is deleted, logging on or off. --- CHANGELOG.md | 8 ++ README.md | 17 +++ docs/commands.md | 130 +++++++++++++---- src/account_usage.rs | 2 +- src/config.rs | 33 ++++- src/dated_jsonl.rs | 48 +++++++ src/history.rs | 144 +++++++++++++++++-- src/main.rs | 1 + src/run_history.rs | 32 +++-- src/run_log.rs | 286 +++++++++++++++++++++++++++++++++++++ src/run_record.rs | 16 ++- src/tilesets_cli.rs | 4 +- tests/auth_profiles.rs | 1 + tests/completion.rs | 1 + tests/config.rs | 6 +- tests/diagnostic_log.rs | 296 +++++++++++++++++++++++++++++++++++++++ tests/non_interactive.rs | 1 + 17 files changed, 971 insertions(+), 55 deletions(-) create mode 100644 src/run_log.rs create mode 100644 tests/diagnostic_log.rs 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..da53d5e 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,22 @@ 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 log goes when its history record does. Logging needs history: +with history off it never runs, and `config set log on` refuses. + ### Privacy **YOUR PRIVACY - COLLECTION OF TELEMETRY** diff --git a/docs/commands.md b/docs/commands.md index cbeb1bd..87adb9f 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,55 @@ Requests 1 "styles", "list" ], - "durationMs": 157, + "diagnostics": { + "log": { + "argv": [ + "styles", + "list", + "--username", + "example", + "--token", + "" + ], + "auth": { + "account": "example", + "source": "flag", + "type": "pk" + }, + "command": [ + "styles", + "list" + ], + "durationMs": 191, + "error": { + "code": "http_401", + "message": "Not Authorized - Invalid Token" + }, + "exitCode": 1, + "invocation": "execute", + "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 +3581,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/account_usage.rs b/src/account_usage.rs index 113ed42..8dbfbc3 100644 --- a/src/account_usage.rs +++ b/src/account_usage.rs @@ -497,7 +497,7 @@ fn parse_ymd(date: &str) -> Option<(i64, u32, u32)> { /// Date to day count, no calendar crate needed: Howard Hinnant's /// `days_from_civil` (). -fn days_from_civil(y: i64, m: u32, d: u32) -> i64 { +pub(crate) fn days_from_civil(y: i64, m: u32, d: u32) -> i64 { let y = if m <= 2 { y - 1 } else { y }; let era = y.div_euclid(400); let yoe = y - era * 400; // [0, 399] 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..3d59dc5 100644 --- a/src/dated_jsonl.rs +++ b/src/dated_jsonl.rs @@ -87,6 +87,45 @@ 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 day after `date` (`YYYY-MM-DD`), or `None` when it isn't one. +pub(crate) fn next_date(date: &str) -> Option { + dated_file(&format!("{date}.jsonl"))?; + let y = date.get(0..4)?.parse().ok()?; + let m = date.get(5..7)?.parse().ok()?; + let d = date.get(8..10)?.parse().ok()?; + let days = crate::account_usage::days_from_civil(y, m, d); + Some(utc_date((days as u64 + 1) * 86_400).0) +} + +/// The oldest date kept by a window of `days` (today included), as of now. +pub(crate) fn oldest_kept(days: u64) -> String { + utc_date(now_secs().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![]; @@ -335,4 +374,13 @@ mod tests { "the newest line stays" ); } + + #[test] + fn the_next_date_crosses_months_and_years() { + assert_eq!(next_date("2026-09-28").as_deref(), Some("2026-09-29")); + assert_eq!(next_date("2026-09-30").as_deref(), Some("2026-10-01")); + assert_eq!(next_date("2026-12-31").as_deref(), Some("2027-01-01")); + assert_eq!(next_date("2028-02-28").as_deref(), Some("2028-02-29")); + assert_eq!(next_date("not-a-date"), None); + } } diff --git a/src/history.rs b/src/history.rs index 9c5af6b..365e78f 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", "version"] { + 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..b9a1d61 100644 --- a/src/run_history.rs +++ b/src/run_history.rs @@ -60,19 +60,27 @@ 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) { + let Ok(text) = serde_json::to_string(&line(record, diagnostics)) else { return; }; if let Some(dir) = dated_jsonl::private_dir(DIR) { @@ -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) -> Line { let ids: Vec = record .requests .iter() @@ -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)).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..25d2cff --- /dev/null +++ b/src/run_log.rs @@ -0,0 +1,286 @@ +//! 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"; +pub(crate) const RETENTION_DAYS: u64 = run_history::RETENTION_DAYS; +pub(crate) 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")] +struct Line { + id: String, + time: String, + version: &'static str, + argv: Vec, + #[serde(skip_serializing_if = "Vec::is_empty")] + command: Vec, + #[serde(skip_serializing_if = "Option::is_none")] + invocation: Option<&'static str>, + #[serde(skip_serializing_if = "Option::is_none")] + exit_code: Option, + duration_ms: u64, + #[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. +pub(crate) fn write(record: &Record) { + let Ok(text) = serde_json::to_string(&line(record)) else { + return; + }; + if let Some(dir) = dated_jsonl::private_dir(DIR) { + dated_jsonl::append(&dir, &text, 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 — and the next, for a run that finished +/// across midnight. +pub(crate) fn find(id: &str, time: &str) -> Option { + let dir = dir_path()?; + let date = time.get(..10)?; + let next = dated_jsonl::next_date(date); + [Some(date.to_string()), next] + .into_iter() + .flatten() + .flat_map(|day| dated_jsonl::read_day(&dir, &day)) + .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) -> Line { + Line { + id: record.id.clone(), + time: dated_jsonl::timestamp(SystemTime::now()), + version: env!("CARGO_PKG_VERSION"), + argv: tilesets_cli::redacted_argv(&record.argv) + .iter() + .map(|arg| clean(arg)) + .collect(), + command: record.command.clone(), + invocation: record.invocation.map(run_record::Invocation::as_str), + exit_code: record.exit_code, + duration_ms: record.duration.as_millis() as u64, + 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. +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]; + if tilesets_cli::looks_like_a_token(word) { + out.push_str(REDACTED); + } else { + 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()), + ] { + 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..2688612 100644 --- a/src/run_record.rs +++ b/src/run_record.rs @@ -20,7 +20,9 @@ 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,17 @@ 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(); + if history { + run_history::write(record, diagnostics); + } + if diagnostics { + run_log::write(record); + } + 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..54123c9 --- /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 itself prunes on the first run of a day (`tests/history.rs`), + // so `expired_history` 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/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 } From f3bd984e42e3729ba2e46c6454db6e4606ee55c1 Mon Sep 17 00:00:00 2001 From: Mofei Zhu Date: Mon, 28 Sep 2026 15:49:59 +0300 Subject: [PATCH 2/2] Address review: one timestamp per run, scrub tokens inside a word - History and the log each read the clock, so a run finishing across UTC midnight could put its log a day after its history, and the same run's cleanup then deleted it. Both lines now share one time and one day's file, which also drops next_date. - The log no longer repeats what the history record has (command, invocation, exitCode, durationMs, version). - scrub_tokens now finds a token that starts inside a word, as after a percent-encoded `=` (`%3Dpk.`) or in a short-flag cluster (`-ytpk.`). - tests/history.rs clears MAPBOX_LOG like the other suites. - README: a day of logs goes with its day of history, and the refusal follows the `history` setting, not MAPBOX_HISTORY. --- README.md | 5 ++-- docs/commands.md | 7 ----- src/account_usage.rs | 2 +- src/dated_jsonl.rs | 42 +++++++++-------------------- src/history.rs | 2 +- src/run_history.rs | 12 ++++----- src/run_log.rs | 60 +++++++++++++++++++---------------------- src/run_record.rs | 9 ++++--- tests/diagnostic_log.rs | 4 +-- tests/history.rs | 1 + 10 files changed, 60 insertions(+), 84 deletions(-) diff --git a/README.md b/README.md index da53d5e..b6de39a 100644 --- a/README.md +++ b/README.md @@ -475,8 +475,9 @@ 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 log goes when its history record does. Logging needs history: -with history off it never runs, and `config set log on` refuses. +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 diff --git a/docs/commands.md b/docs/commands.md index 87adb9f..b320671 100644 --- a/docs/commands.md +++ b/docs/commands.md @@ -3540,17 +3540,10 @@ Log mapbox styles list --username example --token "source": "flag", "type": "pk" }, - "command": [ - "styles", - "list" - ], - "durationMs": 191, "error": { "code": "http_401", "message": "Not Authorized - Invalid Token" }, - "exitCode": 1, - "invocation": "execute", "requests": [ { "durationMs": 149, diff --git a/src/account_usage.rs b/src/account_usage.rs index 8dbfbc3..113ed42 100644 --- a/src/account_usage.rs +++ b/src/account_usage.rs @@ -497,7 +497,7 @@ fn parse_ymd(date: &str) -> Option<(i64, u32, u32)> { /// Date to day count, no calendar crate needed: Howard Hinnant's /// `days_from_civil` (). -pub(crate) fn days_from_civil(y: i64, m: u32, d: u32) -> i64 { +fn days_from_civil(y: i64, m: u32, d: u32) -> i64 { let y = if m <= 2 { y - 1 } else { y }; let era = y.div_euclid(400); let yoe = y - era * 400; // [0, 399] diff --git a/src/dated_jsonl.rs b/src/dated_jsonl.rs index 3d59dc5..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(); @@ -111,19 +112,13 @@ pub(crate) fn read_day(dir: &Path, date: &str) -> Vec { .unwrap_or_default() } -/// The day after `date` (`YYYY-MM-DD`), or `None` when it isn't one. -pub(crate) fn next_date(date: &str) -> Option { - dated_file(&format!("{date}.jsonl"))?; - let y = date.get(0..4)?.parse().ok()?; - let m = date.get(5..7)?.parse().ok()?; - let d = date.get(8..10)?.parse().ok()?; - let days = crate::account_usage::days_from_civil(y, m, d); - Some(utc_date((days as u64 + 1) * 86_400).0) -} - /// The oldest date kept by a window of `days` (today included), as of now. pub(crate) fn oldest_kept(days: u64) -> String { - utc_date(now_secs().saturating_sub(days.saturating_sub(1) * 86_400)).0 + 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 { @@ -230,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; }; @@ -274,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)] @@ -374,13 +367,4 @@ mod tests { "the newest line stays" ); } - - #[test] - fn the_next_date_crosses_months_and_years() { - assert_eq!(next_date("2026-09-28").as_deref(), Some("2026-09-29")); - assert_eq!(next_date("2026-09-30").as_deref(), Some("2026-10-01")); - assert_eq!(next_date("2026-12-31").as_deref(), Some("2027-01-01")); - assert_eq!(next_date("2028-02-28").as_deref(), Some("2028-02-29")); - assert_eq!(next_date("not-a-date"), None); - } } diff --git a/src/history.rs b/src/history.rs index 365e78f..b0cb9d8 100644 --- a/src/history.rs +++ b/src/history.rs @@ -168,7 +168,7 @@ fn diagnostics(entry: &Value) -> Diagnostics { Some(mut log) => { // Already in the record it belongs to. if let Some(object) = log.as_object_mut() { - for key in ["id", "time", "version"] { + for key in ["id", "time"] { object.remove(key); } } diff --git a/src/run_history.rs b/src/run_history.rs index b9a1d61..2d358d5 100644 --- a/src/run_history.rs +++ b/src/run_history.rs @@ -79,12 +79,12 @@ pub(crate) fn will_record(record: &Record) -> bool { /// 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) { - let Ok(text) = serde_json::to_string(&line(record, diagnostics)) else { +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); } } @@ -104,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, diagnostics: bool) -> Line { +fn line(record: &Record, diagnostics: bool, at: SystemTime) -> Line { let ids: Vec = record .requests .iter() @@ -112,7 +112,7 @@ fn line(record: &Record, diagnostics: bool) -> 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), @@ -177,7 +177,7 @@ mod tests { .iter() .map(std::ffi::OsString::from) .collect(); - let text = serde_json::to_string(&line(&run, false)).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 index 25d2cff..56fd235 100644 --- a/src/run_log.rs +++ b/src/run_log.rs @@ -33,8 +33,8 @@ use crate::{auth, config, dated_jsonl, run_history, telemetry, tilesets_cli}; const DIR: &str = "logs"; const LOG_ENV: &str = "MAPBOX_LOG"; -pub(crate) const RETENTION_DAYS: u64 = run_history::RETENTION_DAYS; -pub(crate) const LIMIT_BYTES: u64 = 100 * 1024 * 1024; +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. @@ -46,18 +46,12 @@ 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, - version: &'static str, argv: Vec, - #[serde(skip_serializing_if = "Vec::is_empty")] - command: Vec, - #[serde(skip_serializing_if = "Option::is_none")] - invocation: Option<&'static str>, - #[serde(skip_serializing_if = "Option::is_none")] - exit_code: Option, - duration_ms: u64, #[serde(skip_serializing_if = "Option::is_none")] auth: Option, #[serde(skip_serializing_if = "Vec::is_empty")] @@ -109,13 +103,13 @@ fn is_zero(n: &usize) -> bool { } /// Appends the run's line. The caller has checked [`enabled`] and that -/// history recorded the run. -pub(crate) fn write(record: &Record) { - let Ok(text) = serde_json::to_string(&line(record)) else { +/// 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, RETENTION_DAYS); + dated_jsonl::append(&dir, &text, at, RETENTION_DAYS); dated_jsonl::shed(&dir, LIMIT_BYTES); } } @@ -145,33 +139,23 @@ pub(crate) fn expire_with_history() { } /// The detail logged for the run `id` that history recorded at `time`. -/// Only that day's file is read — and the next, for a run that finished -/// across midnight. +/// 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()?; - let date = time.get(..10)?; - let next = dated_jsonl::next_date(date); - [Some(date.to_string()), next] + dated_jsonl::read_day(&dir, time.get(..10)?) .into_iter() - .flatten() - .flat_map(|day| dated_jsonl::read_day(&dir, &day)) .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) -> Line { +fn line(record: &Record, at: SystemTime) -> Line { Line { id: record.id.clone(), - time: dated_jsonl::timestamp(SystemTime::now()), - version: env!("CARGO_PKG_VERSION"), + time: dated_jsonl::timestamp(at), argv: tilesets_cli::redacted_argv(&record.argv) .iter() .map(|arg| clean(arg)) .collect(), - command: record.command.clone(), - invocation: record.invocation.map(run_record::Invocation::as_str), - exit_code: record.exit_code, - duration_ms: record.duration.as_millis() as u64, auth: record.token.as_ref().map(|token| Auth { source: token.source.as_str(), kind: token.kind, @@ -217,7 +201,9 @@ fn clean(text: &str) -> String { /// `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. +/// 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()); @@ -228,10 +214,13 @@ fn scrub_tokens(text: &str) -> String { .find(|c: char| !is_token_char(c)) .unwrap_or(rest.len() - start); let word = &rest[start..start + word_len]; - if tilesets_cli::looks_like_a_token(word) { - out.push_str(REDACTED); - } else { - out.push_str(word); + // 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..]; } @@ -257,6 +246,11 @@ mod tests { "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); } diff --git a/src/run_record.rs b/src/run_record.rs index 2688612..fbaa914 100644 --- a/src/run_record.rs +++ b/src/run_record.rs @@ -14,7 +14,7 @@ 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}; @@ -343,11 +343,14 @@ fn finish_locked(record: &mut Record, exit_code: Option) { // 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); + run_history::write(record, diagnostics, at); } if diagnostics { - run_log::write(record); + run_log::write(record, at); } run_log::expire_with_history(); } diff --git a/tests/diagnostic_log.rs b/tests/diagnostic_log.rs index 54123c9..16d54f4 100644 --- a/tests/diagnostic_log.rs +++ b/tests/diagnostic_log.rs @@ -283,8 +283,8 @@ fn a_log_goes_when_its_history_does() { std::fs::write(&expired_log, "{}\n").expect("an expired log"); // With logging off, so the cleanup is not a side effect of writing. - // History itself prunes on the first run of a day (`tests/history.rs`), - // so `expired_history` may still be there; its log goes regardless. + // 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"); 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")