vectorcraft/crates/engine/src/tests/script_console.rs

//! The Script Console: `$.write` and `$.writeln`, `vc.log` lines, the bounded store of a session
//! and of a run, errors with their place, the end and report lines, and the diagnostics a run's
//! report holds.

use serde_json::{Value, json};

use crate::script::console::{CUT_MARK, MAX_CONSOLE_BYTES, MAX_CONSOLE_LINES, MAX_LINE_BYTES, MAX_NAME_BYTES};
use crate::*;

fn run(s: &mut Session, source: &str) -> Result<Value> {
    s.execute("script.run", &json!({"source": source, "name": "t.js"}))
}

/// The session console's `(run, kind, text)` lines.
fn lines(s: &mut Session) -> Vec<(u64, String, String)> {
    let c = s.execute("script.console", &json!({})).unwrap();
    c["lines"]
        .as_array()
        .unwrap()
        .iter()
        .map(|l| (l["run"].as_u64().unwrap(), l["kind"].as_str().unwrap().to_string(), l["text"].as_str().unwrap().to_string()))
        .collect()
}

fn texts(s: &mut Session, kind: &str) -> Vec<String> {
    lines(s).into_iter().filter(|(_, k, _)| k == kind).map(|(_, _, t)| t).collect()
}

#[test]
fn write_and_writeln_join_their_values_and_break_lines() {
    let mut s = Session::new();
    run(&mut s, "$.write('a', 1, null, undefined, 1/0); $.write('b\\r\\nc\\rd\\n'); $.writeln(); $.write('x\\r'); $.write('\\ny'); $.writeln([1, 2], {}); $.write('p\\r'); $.write(''); $.write('\\nq'); $.writeln(); $.write('\\0\\t\\u2028\\x7f')").unwrap();
    let want = ["a1nullundefinedInfinityb", "c", "d", "", "x", "y1,2[object Object]", "p", "q", "\u{2400}\u{2409}\u{2424}\u{2421}"];
    assert_eq!(texts(&mut s, "output"), want);
    let report = s.script_report().unwrap();
    assert_eq!(report["console"]["lines"], json!(want), "the run's own console holds the same output");
    assert_eq!(report["hostCallCounts"]["consoleWrites"], 11);
}

#[test]
fn an_endless_writeln_stays_within_the_line_limit_and_counts_what_it_dropped() {
    let mut s = Session::new();
    let e = s.execute("script.run", &json!({"source": "while (1) $.writeln('x')", "name": "t.js", "maxFuel": 2_000_000})).unwrap_err();
    assert!(e.to_string().ends_with("(limit)"), "{e}");
    let c = s.execute("script.console", &json!({})).unwrap();
    let kept = c["lines"].as_array().unwrap().len();
    assert_eq!(kept, MAX_CONSOLE_LINES);
    let report = s.script_report().unwrap().clone();
    let writes = report["hostCallCounts"]["consoleWrites"].as_u64().unwrap();
    assert!(writes > MAX_CONSOLE_LINES as u64 * 2, "{writes} writes");
    // The session console holds a start line, the output, an error, an end and a report line.
    assert_eq!(c["droppedLines"].as_u64().unwrap(), writes + 4 - MAX_CONSOLE_LINES as u64);
    assert_eq!(report["console"]["lines"].as_array().unwrap().len(), MAX_CONSOLE_LINES);
    assert_eq!(report["console"]["droppedLines"].as_u64().unwrap(), writes + 1 - MAX_CONSOLE_LINES as u64);
    assert!(report["fuelUsed"].as_u64().unwrap() > 1_900_000);
    assert_eq!(report["hostCalls"].as_u64().unwrap(), writes);
    let tail = lines(&mut s);
    let ends: Vec<&str> = tail.iter().rev().take(3).map(|(_, k, t)| if k == "error" { "error" } else { t.as_str() }).collect();
    assert_eq!(ends[1], "ended: fuel");
    assert_eq!(ends[2], "error", "{tail:?}");
}

#[test]
fn long_lines_stay_within_the_byte_limit() {
    let mut s = Session::new();
    let source = "var l = new Array(4000).join('y'); for (var i = 0; i < 400; i++) $.writeln(l)";
    run(&mut s, source).unwrap();
    let c = s.execute("script.console", &json!({})).unwrap();
    let bytes: usize = c["lines"].as_array().unwrap().iter().map(|l| l["text"].as_str().unwrap().len()).sum();
    assert!(bytes <= MAX_CONSOLE_BYTES, "{bytes}");
    let kept = c["lines"].as_array().unwrap().len();
    assert!(kept < 400 && kept > 200, "{kept} lines");
    assert!(c["droppedLines"].as_u64().unwrap() > 100);
}

#[test]
fn a_huge_line_is_cut_at_a_character_boundary_and_counted() {
    let mut s = Session::new();
    run(&mut s, "$.writeln(new Array(5000).join('é')); $.write(new Array(3000).join('a')); $.write(new Array(3000).join('b')); $.writeln('c'); $.writeln('ok')")
        .unwrap();
    let out = texts(&mut s, "output");
    assert_eq!(out.len(), 3);
    for line in &out[..2] {
        assert!(line.len() <= MAX_LINE_BYTES && line.len() > MAX_LINE_BYTES - 8, "{}", line.len());
        assert!(line.ends_with(CUT_MARK));
    }
    assert!(!out[1].contains('c'), "the rest of a cut line is left out until it ends");
    assert_eq!(out[2], "ok");
    let c = s.execute("script.console", &json!({})).unwrap();
    assert_eq!(c["truncatedLines"], 2);
    assert_eq!(s.script_report().unwrap()["console"]["truncatedLines"], 2);
}

#[test]
fn a_long_script_name_is_cut_in_every_line_and_shows_its_control_characters() {
    let mut s = Session::new();
    let name = format!("a\nb{}", "é".repeat(100_000));
    s.execute("script.run", &json!({"source": "$.writeln('x'); $.writeln('y')", "name": name})).unwrap();
    let c = s.execute("script.console", &json!({})).unwrap();
    let names: Vec<&str> = c["lines"].as_array().unwrap().iter().map(|l| l["name"].as_str().unwrap()).collect();
    assert_eq!(names.len(), 5);
    for n in names {
        assert!(n.len() <= MAX_NAME_BYTES && n.len() > MAX_NAME_BYTES - 8, "{}", n.len());
        assert!(n.starts_with("a\u{240a}b") && n.ends_with(CUT_MARK), "{n}");
    }
    assert_eq!(s.script_report().unwrap()["name"].as_str().map(str::len), Some(name.len()), "the report keeps the name given");
}

#[test]
fn an_uncaught_error_shows_the_script_its_line_and_column() {
    let mut s = Session::new();
    run(&mut s, "$.write('half');\n\n  throw new Error('boom\\nsecond');").unwrap_err();
    let all = lines(&mut s);
    let kinds: Vec<&str> = all.iter().map(|(_, k, _)| k.as_str()).collect();
    assert_eq!(kinds, ["start", "output", "error", "error", "end", "report"]);
    assert_eq!(all[1].2, "half", "a line left unended still shows");
    assert_eq!(all[2].2, "t.js:3:3: Error: boom");
    assert_eq!(all[3].2, "second");
    assert_eq!(all[4].2, "ended: error");
    let report = s.script_report().unwrap();
    assert_eq!(report["console"]["lines"], json!(["half", "t.js:3:3: Error: boom", "second"]));
    let mut s = Session::new();
    run(&mut s, "var = 1").unwrap_err();
    assert!(texts(&mut s, "error")[0].starts_with("t.js:1:"), "a syntax error has its place too");
    let mut s = Session::new();
    s.script_frames = true;
    run(&mut s, "while (true) {}").unwrap();
    s.script_abandon();
    assert_eq!(texts(&mut s, "error"), ["t.js: location unavailable: limit reached: Interrupted"]);
}

#[test]
fn the_result_and_the_report_agree_and_count_each_kind_of_host_call() {
    let mut s = Session::new();
    s.execute("file.new", &json!({})).unwrap();
    let source = "vc.run('shape.rectangle', {x:0,y:0,width:5,height:5}); vc.run('shape.rectangle', {x:9,y:0,width:5,height:5}); \
                  try { vc.run('no.such', {}); } catch (e) {} var d = vc.document; var c = vc.commands; vc.log({a: 1}); vc.log('two\\nlines'); $.writeln('w');";
    let r = run(&mut s, source).unwrap();
    assert_eq!(&r, s.script_report().unwrap());
    assert_eq!(
        r["hostCallCounts"],
        json!({"vcRun": 3, "documentReads": 1, "commandListReads": 1, "vcLog": 2, "consoleWrites": 1, "fileCalls": 0, "fileExecutes": 0})
    );
    assert_eq!(r["timingAvailable"], true);
    assert!(r["runTimeMs"].is_u64());
    let slow = r["slowestCommands"].as_array().unwrap();
    assert_eq!(slow.len(), 1, "an unknown command is not timed: {slow:?}");
    assert_eq!((slow[0]["id"].as_str(), slow[0]["calls"].as_u64()), (Some("shape.rectangle"), Some(2)));
    assert!(slow[0]["maxMs"].as_u64() <= slow[0]["totalMs"].as_u64());
    assert_eq!(r["console"]["lines"], json!(["{\"a\":1}", "two", "lines", "w"]));
    assert_eq!(texts(&mut s, "log"), ["{\"a\":1}", "two", "lines"]);
    assert_eq!(texts(&mut s, "end"), ["ended: finished"]);
    assert!(texts(&mut s, "report")[0].contains("host calls; slowest: shape.rectangle ×2"), "{:?}", texts(&mut s, "report"));
    assert_eq!(r["log"], json!([{"a": 1}, "two\nlines"]), "the log keeps its values");
}

#[test]
fn a_stopped_run_reports_its_diagnostics_and_its_unended_line() {
    let mut s = Session::new();
    s.script_frames = true;
    run(&mut s, "$.write('so far'); vc.log(1); while (true) {}").unwrap();
    assert!(s.script_pump().is_none());
    assert_eq!(texts(&mut s, "log"), ["1"], "a line shows while the run goes on");
    s.execute("script.stop", &json!({})).unwrap();
    assert!(s.script_pump().unwrap().is_err());
    let report = s.script_report().unwrap();
    assert_eq!(report["kind"], "stopped");
    for key in ["runTimeMs", "hostCallCounts", "slowestCommands", "console", "fuelUsed", "hostCalls", "timingAvailable"] {
        assert!(!report[key].is_null(), "{key}: {report}");
    }
    assert_eq!(report["hostCalls"], 2);
    assert_eq!(texts(&mut s, "output"), ["so far"]);
    assert_eq!(texts(&mut s, "end"), ["ended: stopped"]);
}

/// A report line counts one host call in the singular, and gives a run without a clock as "time
/// unavailable".
#[test]
fn a_report_line_counts_one_host_call_in_the_singular_and_says_when_time_is_unavailable() {
    use crate::script::console::{Entry, Slow};
    let report = |ms: Option<u64>, host_calls: u64| Entry::Report { ms, host_calls, slowest: vec![] }.text();
    assert_eq!(report(Some(3), 0), "3 ms, 0 host calls");
    assert_eq!(report(Some(3), 1), "3 ms, 1 host call");
    assert_eq!(report(Some(0), 2), "0 ms, 2 host calls");
    assert_eq!(report(None, 0), "time unavailable, 0 host calls");
    assert_eq!(report(None, 1), "time unavailable, 1 host call");
    assert_eq!(report(None, 2), "time unavailable, 2 host calls");
    let slowest = vec![Slow { id: "a.b".into(), calls: 1, total_ms: 4, max_ms: 4 }];
    assert_eq!(Entry::Report { ms: None, host_calls: 1, slowest }.text(), "time unavailable, 1 host call; slowest: a.b ×1 4 ms");
}

/// A run whose job is gone still ends its console entry, once, with its own number and name and no
/// report line: as stopped when it is abandoned, as an internal fault when a slice finds it gone.
/// The session can start the next run.
#[test]
fn a_run_whose_job_is_gone_still_ends_its_console_entry() {
    for abandon in [true, false] {
        let mut s = Session::new();
        s.script_frames = true;
        run(&mut s, "$.writeln('one'); while (true) {}").unwrap();
        assert!(s.script_pump().is_none());
        assert!(script::forget_job(&s));
        if abandon {
            assert!(s.script_abandon());
        } else {
            let e = s.script_pump().unwrap().unwrap_err();
            assert_eq!(e.to_string(), "the script's run is no longer available");
        }
        assert!(!s.script_running());
        let all = lines(&mut s);
        let kinds: Vec<&str> = all.iter().map(|(_, k, _)| k.as_str()).collect();
        assert_eq!(kinds, ["start", "output", "end"], "{all:?}");
        assert_eq!(all[2].2, if abandon { "ended: stopped" } else { "ended: internal" });
        let c = s.execute("script.console", &json!({})).unwrap();
        assert_eq!((c["lines"][2]["run"].as_u64(), c["lines"][2]["name"].as_str()), (Some(1), Some("t.js")));
        assert!(!s.script_abandon() && s.script_pump().is_none(), "nothing is left to end");
        assert_eq!(lines(&mut s).len(), 3, "the entry ends once");
        s.script_frames = false;
        run(&mut s, "$.writeln('two')").unwrap();
        assert_eq!(texts(&mut s, "end").last().map(String::as_str), Some("ended: finished"), "the next run starts");
        assert_eq!(lines(&mut s).last().map(|l| l.0), Some(2));
    }
}

#[test]
fn runs_are_numbered_a_busy_run_adds_nothing_and_clear_keeps_the_report() {
    let mut s = Session::new();
    for _ in 0..3 {
        run(&mut s, "for (var i = 0; i < 1000; i++) $.writeln(i)").unwrap();
    }
    let all = lines(&mut s);
    assert_eq!(all.len(), MAX_CONSOLE_LINES);
    assert_eq!(all.last().map(|l| l.0), Some(3));
    s.script_frames = true;
    run(&mut s, "$.writeln('four'); while (true) {}").unwrap();
    assert!(s.script_pump().is_none());
    let before = lines(&mut s);
    assert!(matches!(run(&mut s, "$.writeln('five')"), Err(EngineError::Busy)));
    assert_eq!(lines(&mut s), before, "a refused run adds no line");
    assert_eq!(s.execute("script.console.clear", &json!({})).unwrap()["cleared"], MAX_CONSOLE_LINES);
    let c = s.execute("script.console", &json!({})).unwrap();
    assert_eq!((c["lines"].as_array().map(Vec::len), c["droppedLines"].as_u64()), (Some(0), Some(0)));
    s.execute("script.stop", &json!({})).unwrap();
    assert!(s.script_pump().unwrap().is_err());
    let report = s.script_report().unwrap();
    assert_eq!(report["console"]["lines"][0], "four", "a clear leaves the running script's own console");
    assert_eq!(texts(&mut s, "end"), ["ended: stopped"], "the run goes on writing after a clear");
    assert_eq!(lines(&mut s)[0].0, 4);
    let mut other = Session::new();
    assert!(lines(&mut other).is_empty(), "each session has its own console");
}

#[test]
fn the_slowest_commands_are_the_longest_in_all_then_by_id() {
    let times = std::collections::HashMap::from([
        ("a.one", (1, 5_000_000, 5_000_000)),
        ("b.two", (3, 9_000_000, 4_000_000)),
        ("c.three", (1, 5_000_000, 5_000_000)),
        ("d", (1, 1, 1)),
        ("e", (1, 2, 2)),
        ("f", (1, 3, 3)),
    ]);
    let slow = script::slowest(&times);
    let ids: Vec<&str> = slow.iter().map(|c| c.id.as_str()).collect();
    assert_eq!(ids, ["b.two", "a.one", "c.three", "f", "e"]);
    assert_eq!((slow[0].calls, slow[0].total_ms, slow[0].max_ms), (3, 9, 4));
}

/// Under automation read roots, the error lines of a failed run name the included file it stopped
/// in by its file name also when the console cut a line inside the file's path.
#[test]
fn a_cut_error_line_leaves_out_an_included_files_folder_outside_the_read_root() {
    use crate::file_access::{AutomationRoots, confine};
    let base = crate::tests_links::Folder::new("script-report-cut-line");
    let inside = base.0.join("in");
    std::fs::create_dir_all(&inside).unwrap();
    // A path longer than a console line, as the report of a failed run names it.
    let file = base.0.join("out").join("d".repeat(MAX_LINE_BYTES)).join("bad.jsxinc").to_string_lossy().to_string();
    let mut report = json!({"ok": false, "name": "t.js", "file": file, "line": 2, "column": 7, "message": format!("Error: stopped\nin {file}")});
    let error = script::error_lines(&report);
    assert!(error.len() == 2 && error.iter().all(|l| l.len() <= MAX_LINE_BYTES && l.ends_with(CUT_MARK)), "both lines are cut: {error:?}");
    let written: Vec<String> = std::iter::once("written by the script".to_string()).chain(error).collect();
    report["console"] = json!({"lines": written, "droppedLines": 0, "truncatedLines": 2});
    let mut s = Session::new();
    s.script_report = Some(report.clone());

    let roots = AutomationRoots::new(&[&inside], &[]).unwrap();
    let shown = confine(roots.as_ref(), || s.shown_script_report()).unwrap();
    assert_eq!((&shown["file"], &shown["message"]), (&json!("bad.jsxinc"), &json!("Error: stopped\nin bad.jsxinc")), "{shown}");
    assert_eq!(shown["console"]["lines"], json!(["written by the script", "t.js: bad.jsxinc:2:7: Error: stopped", "in bad.jsxinc"]), "{shown}");
    let outside = json!(base.0.join("out").to_string_lossy()).to_string();
    assert!(!shown.to_string().contains(outside.trim_matches('"')), "no path outside the root: {shown}");
    // The person sees the report as it is.
    assert_eq!(s.shown_script_report(), Some(report));
}