Skip to content
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion crates/engine/src/cmd/exports.rs
Original file line number Diff line number Diff line change
Expand Up @@ -268,7 +268,8 @@ pub fn export_land(s: &mut Session, started: Started, done: Result<Wrote, String
}
s.diagnostic_source = before;
if s.log.on() && crate::project_log::is_logged(s, command, &params) {
let entry = crate::project_log::entry(command, crate::project_log::kept_params(&params), &landed, at, start.elapsed());
let (kept, partial) = crate::project_log::kept(&params);
let entry = crate::project_log::entry(s, command, kept, partial, &landed, at, start.elapsed());
Comment thread
jgregoriorincon marked this conversation as resolved.
Resolved
s.log.push(entry);
}
landed
Expand Down
2 changes: 1 addition & 1 deletion crates/engine/src/cmd/project.rs
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,7 @@ pub fn commands() -> Vec<C> {
// The session log (#797): read, written out, emptied, turned on or off. It sits outside
// the project, so none of these changes the project or takes an undo step.
C::new("project.log", "Session Log", "Project", log).roles(&[]).effects(crate::policy::Effects::NONE.with(crate::policy::Effect::Files)).view().params(
r#"{"since"?: milliseconds since 1970 (UTC), "until"?: milliseconds, "command"?: "a command id, or the start of one (layer.)", "failed"?: bool (true: only those that failed; false: only those that succeeded), "limit"?: entries, a whole number (default 100, the newest; 1 to 1000)} → {"entries": [{"at", "command", "params", "ok", "error"?, "millis"}], "count": matching, "total": in the log, "on": bool}"#,
r#"{"since"?: milliseconds since 1970 (UTC), "until"?: milliseconds, "command"?: "a command id, or the start of one (layer.)", "failed"?: bool (true: only those that failed; false: only those that succeeded), "limit"?: entries, a whole number (default 100, the newest; 1 to 1000)} → {"entries": [{"at", "command", "params", "ok", "error"?, "millis", "project": the project open when it ran, "partial"?: true when params were cut or had secrets taken out}], "count": matching, "total": in the log, "on": bool}"#,
),
C::new("project.exportLog", "Export Session Log", "Project", export_log).roles(&[]).effects(crate::policy::Effects::NONE.with(crate::policy::Effect::Files))
.view()
Expand Down
9 changes: 5 additions & 4 deletions crates/engine/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1496,11 +1496,12 @@ impl Session {
// command's result as it was, without an entry, and says so in the app's log.
let logged = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
if project_log::is_logged(self, id, params) {
let params = match step {
Some(label) => serde_json::json!({"step": label}),
None => project_log::kept_params(params),
// The step's label isn't a parameter: the command, run again, takes none.
let (params, partial) = match step {
Some(label) => (serde_json::json!({"step": label}), false),
None => project_log::kept(params),
};
let e = project_log::entry(id, params, &res, at, start.elapsed());
let e = project_log::entry(self, id, params, partial, &res, at, start.elapsed());
Comment thread
jgregoriorincon marked this conversation as resolved.
Resolved
if joins && res.is_ok() { self.log.join_last(e) } else { self.log.push(e) }
}
}));
Expand Down
108 changes: 100 additions & 8 deletions crates/engine/src/project_log.rs
Original file line number Diff line number Diff line change
Expand Up @@ -258,6 +258,56 @@ fn embedded_redacted(v: &Value, depth: usize) -> Value {
}
}

/// JSON whose every object has each of its keys once, as its text is read: deserializing one with
/// a key written twice (at any depth) fails.
struct OnceEach;

impl<'de> Deserialize<'de> for OnceEach {
fn deserialize<D: serde::Deserializer<'de>>(d: D) -> Result<Self, D::Error> {
d.deserialize_any(OnceEach)
}
}

impl<'de> serde::de::Visitor<'de> for OnceEach {
type Value = OnceEach;

fn expecting(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
f.write_str("JSON")
}
fn visit_bool<E>(self, _: bool) -> Result<Self, E> {
Ok(self)
}
fn visit_i64<E>(self, _: i64) -> Result<Self, E> {
Ok(self)
}
fn visit_u64<E>(self, _: u64) -> Result<Self, E> {
Ok(self)
}
fn visit_f64<E>(self, _: f64) -> Result<Self, E> {
Ok(self)
}
fn visit_str<E>(self, _: &str) -> Result<Self, E> {
Ok(self)
}
fn visit_unit<E>(self) -> Result<Self, E> {
Ok(self)
}
fn visit_seq<A: serde::de::SeqAccess<'de>>(self, mut items: A) -> Result<Self, A::Error> {
while items.next_element::<OnceEach>()?.is_some() {}
Ok(self)
}
fn visit_map<A: serde::de::MapAccess<'de>>(self, mut keys: A) -> Result<Self, A::Error> {
let mut seen = std::collections::HashSet::new();
while let Some(key) = keys.next_key::<String>()? {
if !seen.insert(key) {
return Err(serde::de::Error::custom("a key written twice"));
}
keys.next_value::<OnceEach>()?;
}
Ok(self)
}
}

/// `t` with each JSON object it holds (from a `{` to where the object ends) redacted. Texts are
/// clipped before this, so trying each `{` stays cheap; the secret names are looked for once.
pub(crate) fn json_in_text_redacted(t: &str) -> String {
Expand All @@ -273,7 +323,17 @@ pub(crate) fn json_in_text_redacted(t: &str) -> String {
match objects.next() {
Some(Ok(v @ Value::Object(_))) => {
let end = objects.byte_offset();
out.push_str(&serde_json::to_string(&crate::cmd::history::redacted(&v)).unwrap_or_default());
// Nothing taken out: the object as written, so a script copied back from the log
// is the one run, and isn't said to be partial for its spacing. Only one with no
// key written twice: it is read as its last value, and its text keeps the others
// (a secret's first, its last left empty, its name escaped or not).
let kept = crate::cmd::history::redacted(&v);
let written = from.get(..end).unwrap_or("");
if kept == v && serde_json::from_str::<OnceEach>(written).is_ok() {
out.push_str(written);
} else {
out.push_str(&serde_json::to_string(&kept).unwrap_or_default());
}
rest = from.get(end..).unwrap_or("");
}
// Cut short by the clip, or an object that doesn't parse (a trailing comma, single
Expand Down Expand Up @@ -430,7 +490,9 @@ fn clip(v: &Value, chars: usize, items: usize, depth: usize) -> Value {

/// The entry of command `id`, which started at `at` and took `took`; its error without secrets,
/// clipped to [`LOG_ERROR_CHARS`].
pub(crate) fn entry(id: &str, params: Value, res: &CmdResult, at: u64, took: web_time::Duration) -> LogEntry {
/// `partial`: its parameters aren't all as given ([`kept`]). It is the entry of the project open
/// in `s` as it ended: the one a command that opens a project opened.
pub(crate) fn entry(s: &Session, id: &str, params: Value, partial: bool, res: &CmdResult, at: u64, took: web_time::Duration) -> LogEntry {
let error = res.as_ref().err().map(|e| kept_error(e));
LogEntry {
at,
Expand All @@ -439,9 +501,27 @@ pub(crate) fn entry(id: &str, params: Value, res: &CmdResult, at: u64, took: web
ok: res.is_ok(),
error,
millis: u64::try_from(took.as_millis()).unwrap_or(u64::MAX),
project: kept_name(&s.title()),
opened: s.opened,
partial,
}
}

/// A project's name as the log keeps it: cut at [`crate::cmd::MAX_NAME`] characters and a `…`, as
/// a name read from a file may be longer than one given to `project.rename`.
fn kept_name(name: &str) -> String {
let max = crate::cmd::MAX_NAME;
if name.chars().nth(max).is_some() { format!("{}…", name.chars().take(max).collect::<String>()) } else { name.to_string() }
}

/// `params` as the log keeps them ([`kept_params`]), and whether that is less than they were:
/// cut to fit or with secrets taken out, so they wouldn't run again as they ran.
pub(crate) fn kept(params: &Value) -> (Value, bool) {
let kept = kept_params(params);
let partial = kept != *params;
(kept, partial)
}
Comment thread
jgregoriorincon marked this conversation as resolved.
Resolved

/// Most entries the log keeps; past it, the oldest go first.
pub const LOG_LIMIT: usize = 10_000;
/// The most entries of plugins' commands the log keeps, their oldest going first past it: a
Expand All @@ -454,9 +534,9 @@ pub const LOG_LIST_ITEMS: usize = 100;
pub const LOG_ERROR_CHARS: usize = 500;

/// One command run in the session: when it started (UTC, milliseconds since 1970), its id, its
/// parameters (secrets taken out, large values clipped), whether it succeeded, its error, and how
/// long it took.
#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)]
/// parameters (secrets taken out, large values clipped), whether it succeeded, its error, how
/// long it took, and the project it ran in.
#[derive(Clone, Debug, Default, PartialEq, Serialize, Deserialize)]
pub struct LogEntry {
pub at: u64,
pub command: String,
Expand All @@ -467,6 +547,17 @@ pub struct LogEntry {
pub error: Option<String>,
#[serde(default)]
pub millis: u64,
/// The name of the project open when it ran (the one it opened, for a command that opens one).
#[serde(default)]
pub project: String,
/// Which of the session's projects that was ([`Session::opened`]), so two of the same name
/// (two new ones, both "Untitled") are told apart. The session's own: not saved with the log.
#[serde(skip)]
pub opened: u64,
/// Its parameters aren't all as given (cut to fit, or with secrets taken out): copied, they
/// wouldn't run as they ran.
#[serde(default, skip_serializing_if = "std::ops::Not::not")]
pub partial: bool,
}

impl LogEntry {
Expand Down Expand Up @@ -607,7 +698,7 @@ impl SessionLog {
/// line). Entry by entry, so a long log isn't held as text first.
pub fn write(&self, w: &mut dyn std::io::Write, csv: bool) -> std::io::Result<()> {
if csv {
w.write_all(b"time_utc,at,command,ok,millis,error,params\n")?;
w.write_all(b"time_utc,at,command,ok,millis,error,params,project\n")?;
}
self.entries.iter().try_for_each(|e| write_entry(w, e, csv))
}
Expand All @@ -634,14 +725,15 @@ fn write_entry(w: &mut dyn std::io::Write, e: &LogEntry, csv: bool) -> std::io::
if csv {
writeln!(
w,
"{},{},{},{},{},{},{}",
"{},{},{},{},{},{},{},{}",
e.time_utc(),
e.at,
csv_cell(&e.command),
e.ok,
e.millis,
csv_cell(e.error.as_deref().unwrap_or("")),
csv_cell(&e.params.to_string())
csv_cell(&e.params.to_string()),
csv_cell(&e.project)
)
} else {
serde_json::to_writer(&mut *w, e).map_err(std::io::Error::other)?;
Expand Down
110 changes: 105 additions & 5 deletions crates/engine/src/tests.rs
Original file line number Diff line number Diff line change
Expand Up @@ -28740,7 +28740,15 @@ fn the_session_log_records_each_command_run_in_the_session() {
assert_eq!(doc.params["text"], json!(format!("(a document of {} characters)", qgs.chars().count())), "{doc:?}");
// A step joined to the newest entry (a held key's nudges) is a change too, so a view of the
// log reads it again.
let nudge = |millis| LogEntry { at: 1, command: "layout.nudge".into(), params: json!({"dx": 1}), ok: true, error: None, millis };
let nudge = |millis| LogEntry {
at: 1,
command: "layout.nudge".into(),
params: json!({"dx": 1}),
ok: true,
error: None,
millis,
..Default::default()
};
s.log.push(nudge(2));
let before = s.log.changes();
s.log.join_last(nudge(3));
Expand Down Expand Up @@ -28800,15 +28808,26 @@ fn the_session_log_records_each_command_run_in_the_session() {
assert!(s.run("project.log", &json!({"failed": "true"})).is_err());
assert!(s.run("project.log", &json!({"command": 7})).is_err());
// An error that starts as a spreadsheet formula is written as text in the CSV.
let formula = LogEntry { at: 2, command: "x".into(), params: Value::Null, ok: false, error: Some("=HYPERLINK(1)".into()), millis: 0 };
let formula = LogEntry {
at: 2,
command: "x".into(),
params: Value::Null,
ok: false,
error: Some("=HYPERLINK(1)".into()),
millis: 0,
..Default::default()
};
s.log.push(formula);
// Written out as CSV and JSON Lines.
let dir = std::env::temp_dir().join(format!("rustgis-session-log-{}", std::process::id()));
std::fs::create_dir_all(&dir).unwrap();
let csv = dir.join("log.csv");
s.run("project.exportLog", &json!({"path": csv.to_string_lossy()})).unwrap();
let csv_text = std::fs::read_to_string(&csv).unwrap();
assert!(csv_text.starts_with("time_utc,at,command,ok,millis,error,params\n") && csv_text.contains("\"edit.undo\""), "{csv_text}");
assert!(
csv_text.starts_with("time_utc,at,command,ok,millis,error,params,project\n") && csv_text.contains("\"edit.undo\""),
"{csv_text}"
);
assert!(csv_text.contains("\"'=HYPERLINK(1)\"") && !csv_text.contains(",\"=HYPERLINK"), "{csv_text}");
let jsonl = dir.join("log.jsonl");
s.run("project.exportLog", &json!({"path": jsonl.to_string_lossy()})).unwrap();
Expand Down Expand Up @@ -28851,7 +28870,15 @@ fn the_session_log_records_each_command_run_in_the_session() {
s.run("project.logCommands", &json!({"on": true})).unwrap();
// Capped: the oldest go first.
for i in 0..LOG_LIMIT + 5 {
s.log.push(LogEntry { at: i as u64, command: "x".into(), params: Value::Null, ok: true, error: None, millis: 0 });
s.log.push(LogEntry {
at: i as u64,
command: "x".into(),
params: Value::Null,
ok: true,
error: None,
millis: 0,
..Default::default()
});
}
assert_eq!(s.log.len(), LOG_LIMIT);
assert_eq!(s.log.entries().next().unwrap().at, 5);
Expand Down Expand Up @@ -28882,6 +28909,71 @@ fn the_session_log_records_each_command_run_in_the_session() {
assert_eq!(s.log.len(), n, "nothing to undo or redo: not logged");
}

/// Each entry names the project it ran in (the one it opened, for a command that opens one), and
/// another project of the same name is told apart; parameters cut to fit or without their secrets
/// are said to be partial, as they wouldn't run as they ran; a saved log keeps the project's name.
#[test]
fn session_log_entries_name_their_project_and_say_when_their_params_are_partial() {
#[cfg(not(target_arch = "wasm32"))]
if isolate_process_test("tests::session_log_entries_name_their_project_and_say_when_their_params_are_partial") {
return;
}
let mut s = world();
s.log.clear();
let last = |s: &Session| s.log.entries().last().cloned().unwrap();
s.run("project.rename", &json!({"name": "Atlas"})).unwrap();
let renamed = last(&s);
assert_eq!((renamed.project.as_str(), renamed.opened, renamed.partial), ("Atlas", s.opened, false), "{renamed:?}");
s.run("project.new", &json!({"name": "Atlas"})).unwrap();
let made = last(&s);
assert_eq!((made.command.as_str(), made.project.as_str(), made.opened), ("project.new", "Atlas", s.opened));
assert_ne!(made.opened, renamed.opened, "the same name, another project");
// A script with nothing to take out is kept as written, its spacing too: not partial.
let script = "map.new {\"name\": \"Third\"}\n# a { that isn't JSON";
s.run("script.run", &json!({"script": script})).unwrap();
let ran = last(&s);
assert_eq!((ran.params["script"].as_str(), ran.partial), (Some(script), false), "{ran:?}");
// A secret's key written twice is read as its last value: the first isn't kept as written.
let _ =
s.run("script.run", &json!({"script": "map.new {\"name\": \"M\", \"secretAccessKey\": \"S3CRET\", \"secretAccessKey\": \"\"}"}));
let twice = last(&s);
assert!(!twice.params.to_string().contains("S3CRET") && twice.partial, "{twice:?}");
// Nor with its name escaped, nor a key a plain name blanks only for its value, nor deeper in.
for script in [
r#"map.new {"name": "M", "\u0074oken": "S3CRET", "\u0074oken": ""}"#,
r#"map.new {"name": "M", "key": "AKIAIOSFODNN7S3CRET", "key": ""}"#,
r#"map.new {"name": "M", "style": {"token": "S3CRET", "token": ""}}"#,
] {
let before = s.log.len();
let _ = s.run("script.run", &json!({"script": script}));
let e = last(&s);
assert_eq!((s.log.len(), e.command.as_str()), (before + 1, "script.run"), "{script}: its own entry");
assert!(!e.params.to_string().contains("S3CRET") && e.partial, "{script}: {e:?}");
}
// A name past the bound is cut, and says so.
s.project.name = "n".repeat(crate::cmd::MAX_NAME + 5);
s.run("map.new", &json!({"name": "Long"})).unwrap();
assert_eq!(last(&s).project, format!("{}…", "n".repeat(crate::cmd::MAX_NAME)));
s.project.name = "Atlas".into();
// A script past the log's bound is cut: partial, so it isn't run again as a part.
let long = format!("# {}", "x".repeat(crate::project_log::LOG_PARAMS_BYTES * 2));
s.run("script.run", &json!({"script": long})).unwrap();
assert!(last(&s).partial);
// An address without its token: partial too.
let _ = s.run("service.layers", &json!({"url": "https://x.org/wms?token=S3CRET&layers=a", "text": "not a capabilities document"}));
let service = last(&s);
Comment thread
jgregoriorincon marked this conversation as resolved.
Resolved
assert_eq!(service.command, "service.layers", "{service:?}");
assert!(!service.params.to_string().contains("S3CRET") && service.partial, "{service:?}");
Comment thread
coderabbitai[bot] marked this conversation as resolved.
Resolved
// Saved: the project's name last in a CSV row; in JSON, the name, and `partial` only when so.
let mut csv = Vec::new();
s.log.write(&mut csv, true).unwrap();
let csv = String::from_utf8(csv).unwrap();
assert!(csv.lines().nth(1).is_some_and(|row| row.ends_with(",\"Atlas\"")), "{csv}");
let json = serde_json::to_value(&renamed).unwrap();
assert_eq!(json["project"], "Atlas");
assert!(json.get("opened").is_none() && json.get("partial").is_none(), "{json}");
}

/// What the session log keeps of a command's parameters: bounded in bytes, keys and time, and
/// without secrets, those in JSON a text holds and in SQL `CREATE … SECRET` options included.
#[test]
Expand Down Expand Up @@ -28950,7 +29042,15 @@ fn plugins_can_neither_clear_the_session_log_nor_crowd_out_the_users_entries() {
use crate::project_log::LogEntry;
// Plugins' commands keep at most their own share of the log: the user's entries stay.
let mut log = crate::project_log::SessionLog::default();
let entry = |command: &str| LogEntry { at: 1, command: command.into(), params: Value::Null, ok: true, error: None, millis: 0 };
let entry = |command: &str| LogEntry {
at: 1,
command: command.into(),
params: Value::Null,
ok: true,
error: None,
millis: 0,
..Default::default()
};
log.push(entry("layer.rename"));
for _ in 0..crate::project_log::LOG_PLUGIN_LIMIT + 5 {
log.push(entry("plugin:p/flood"));
Expand Down
Loading
Loading