main
Drew Owens 0.11.3 source 7364e19 5d ago
//! A QUICK RESTART IS NOT READY (0.11.3) — from the laptop's ledger,
//! 2026-10-15, hosted 0.11.2, SOLIDWORKS 2026:
//!
//! | 22:40:01 | quit (processGone) |
//! | 22:40:02 | launch |
//! | 22:40:07 | sldworksUp |
//! | 22:40:39 | attached |
//! | 22:40:43 | `solidworks.ready` TRUE — 4 s after attach |
//! | 22:40:50 | swx_new_document OK, title `Part1-…SLDPRT`, ledger `document_created` |
//! | 22:40:51 | swx_docs: [] — SOLIDWORKS (pid 26316) had DIED |
//!
//! The 2026-10-01 crash again: a document command while an add-in was still
//! initialising. Everything here runs in the simulator.

mod common;

use common::{Bridge, TempDir};
use serde_json::{json, Value};
use std::time::{Duration, SystemTime};

fn s(v: &Value) -> String {
    serde_json::to_string_pretty(v).unwrap_or_default()
}

fn ledger(b: &Bridge) -> Vec<Value> {
    b.call("swx_action_ledger", json!({"limit": 500}))["actions"].as_array().cloned().unwrap_or_default()
}

fn now() -> u64 {
    SystemTime::now().duration_since(SystemTime::UNIX_EPOCH).unwrap().as_secs()
}

fn session(scratch: &TempDir) {
    std::fs::write(
        scratch.join("mock-solidworks-open-docs.json"),
        json!({"running": true, "untitled": 0, "active": Value::Null, "docs": [], "files": {}}).to_string(),
    )
    .unwrap();
}

/// A session the simulated machine started `age` seconds ago.
fn young_session(scratch: &TempDir, age: u64) {
    session(scratch);
    std::fs::write(scratch.join("mock-sldworks-created"), (now() - age).to_string()).unwrap();
}

fn set_mtime(p: &std::path::Path, secs_ago: u64) {
    std::fs::File::options()
        .write(true)
        .open(p)
        .unwrap()
        .set_modified(SystemTime::now() - Duration::from_secs(secs_ago))
        .unwrap();
}

/// The previous session's whole start, as its log holds it.
const PREVIOUS: &str = "; SolidWorks generated log file\n<AD2> \"LOAD_ADDIN\" \"SWK3DCompassAddin.dll\" \"3DEXPERIENCE for WORKS\"\n\
<3DXLOAD_TIME>24000</3DXLOAD_TIME>\n<PROCMEM> CMD:AppRunTime 1\n<PROCMEM> CMD:AppRunTime 2\n";

#[test]
fn a_marker_the_previous_session_wrote_never_makes_the_new_one_ready() {
    let scratch = TempDir::new("restart-stale");
    young_session(&scratch, 3);
    let log = scratch.join("SolidWorksPerformance.log");
    std::fs::write(&log, PREVIOUS).unwrap();
    // Last written 30 s ago: before this SOLIDWORKS started.
    set_mtime(&log, 30);
    let logp = log.to_string_lossy().to_string();
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[("SWX_PERF_LOG", &logp)]);
    b.call("swx_start", json!({}));
    let st = b.call("swx_status", json!({}));
    check!(
        b,
        "first sight: the log is still the previous session's — not ready, and its state is recorded as the baseline",
        st["solidworks"]["ready"] == false && scratch.join("perflog-baselines.json").exists(),
        s(&st["solidworks"]["readiness"])
    );
    // The NEW session touches the file — a line, no header, no add-in yet. The
    // old reading took the text after the last header: the previous session's
    // marker after its last LOAD_ADDIN — "complete".
    std::fs::write(&log, format!("{PREVIOUS}<PROCMEM> CMD:SessionStart\n")).unwrap();
    let r = b.call("swx_new_document", json!({"type": "part"}));
    let ev = r["readiness"].clone();
    check!(
        b,
        "a quick restart is NOT ready on the previous session's marker: host_app_starting",
        r["errorCode"] == "host_app_starting",
        s(&r)
    );
    let full = b.call("swx_status", json!({}));
    let pl = full["solidworks"]["readiness"]["evidence"][1].clone();
    check!(
        b,
        "...the evidence says the log was read from beyond the launch baseline, and holds no marker of this session",
        pl["launchBaseline"]["length"].as_u64() == Some(PREVIOUS.len() as u64)
            && pl["readFromOffset"].as_u64() == Some(PREVIOUS.len() as u64)
            && pl["marker"].is_null()
            && pl["rewrittenSinceBaseline"] == false,
        format!("{}\n{}", s(&full["solidworks"]["readiness"]), s(&ev))
    );
    // THIS session loads its add-ins and writes its own marker: ready.
    std::fs::write(
        &log,
        format!("{PREVIOUS}<PROCMEM> CMD:SessionStart\n<AD2> \"LOAD_ADDIN\" \"SWK3DCompassAddin.dll\" \"3DEXPERIENCE for WORKS\"\n<3DXLOAD_TIME>21000</3DXLOAD_TIME>\n"),
    )
    .unwrap();
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(b, "this session's own marker, beyond the baseline: ready, the document is made", r["success"] == true, s(&r));
    let ready = ledger(&b).into_iter().find(|e| e["action"] == "solidworks_ready").unwrap_or(Value::Null);
    check!(
        b,
        "...and the transition is LEDGERED with the evidence that decided it",
        ready["detail"]["evidence"][1]["markerOffset"].as_u64().map(|o| o > PREVIOUS.len() as u64).unwrap_or(false),
        s(&ready)
    );
}

#[test]
fn a_rewritten_log_is_read_whole_and_its_marker_counts() {
    let scratch = TempDir::new("restart-rewritten");
    young_session(&scratch, 3);
    let log = scratch.join("SolidWorksPerformance.log");
    std::fs::write(&log, format!("{PREVIOUS}{}", "<PROCMEM> CMD:AppRunTime n\n".repeat(40))).unwrap();
    set_mtime(&log, 30);
    let logp = log.to_string_lossy().to_string();
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[("SWX_PERF_LOG", &logp)]);
    b.call("swx_start", json!({}));
    b.call("swx_status", json!({}));
    // REWRITTEN at the new start (measured 2026-10-01: one header, at the top).
    std::fs::write(&log, PREVIOUS).unwrap();
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(b, "a log rewritten since the baseline is this session's: its marker counts", r["success"] == true, s(&r));
}

#[test]
fn a_log_rewritten_past_the_old_length_is_known_by_its_bytes_not_its_size() {
    let scratch = TempDir::new("restart-rewritten-long");
    young_session(&scratch, 3);
    let log = scratch.join("SolidWorksPerformance.log");
    std::fs::write(&log, PREVIOUS).unwrap();
    set_mtime(&log, 30);
    let logp = log.to_string_lossy().to_string();
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[("SWX_PERF_LOG", &logp)]);
    b.call("swx_start", json!({}));
    b.call("swx_status", json!({}));
    // Rewritten, this session's marker EARLY in it, and already LONGER than the
    // old file: only the bytes where the old file ended can tell.
    let mut fresh = String::from("; SolidWorks generated log file\n<AD2> \"LOAD_ADDIN\" \"SWK3DCompassAddin.dll\" \"3DEXPERIENCE for WORKS\"\n<3DXLOAD_TIME>19000</3DXLOAD_TIME>\n");
    while fresh.len() < PREVIOUS.len() * 3 {
        fresh.push_str("<PROCMEM> CMD:AppRunTime this-session\n");
    }
    std::fs::write(&log, fresh).unwrap();
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(b, "rewritten (different bytes where the old file ended): its early marker counts", r["success"] == true, s(&r));
}

#[test]
fn the_ready_latch_belongs_to_one_process_identity() {
    let scratch = TempDir::new("restart-latch");
    session(&scratch);
    std::fs::write(scratch.join("mock-startup-incomplete"), "").unwrap();
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[("SWX_PERF_LOG", "")]);
    b.call("swx_start", json!({}));
    let st = b.call("swx_status", json!({}));
    let pid = st["solidworks"]["readiness"]["processId"].as_i64().unwrap();
    let created = st["solidworks"]["readiness"]["processCreatedAt"].as_u64().unwrap();
    // A latch for the SAME pid with ANOTHER creation time — the previous
    // session's — and one for another pid.
    std::fs::write(
        scratch.join("ready-sessions.json"),
        json!({format!("{pid}:{}", created - 7): {"readyAtMs": 1}, format!("{}:{created}", pid + 1): {"readyAtMs": 1}}).to_string(),
    )
    .unwrap();
    let st = b.call("swx_status", json!({}));
    check!(
        b,
        "a latch from another process identity never makes this session ready",
        st["solidworks"]["ready"] == false
            && !st["solidworks"]["readiness"]["basedOn"].as_array().map(|a| a.iter().any(|x| x == "readyBeforeThisBridgeRestarted")).unwrap_or(true),
        s(&st["solidworks"]["readiness"])
    );
    std::fs::write(scratch.join("ready-sessions.json"), json!({format!("{pid}:{created}"): {"readyAtMs": 1}}).to_string()).unwrap();
    let st = b.call("swx_status", json!({}));
    check!(b, "...THIS identity's latch does (a bridge restart keeps a verified session ready)", st["solidworks"]["ready"] == true, s(&st["solidworks"]["readiness"]));
}

#[test]
fn a_fresh_start_settles_after_attach_and_needs_com_to_say_it_completed() {
    let scratch = TempDir::new("restart-settle");
    young_session(&scratch, 2);
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[("SWX_PERF_LOG", ""), ("SWX_READY_SETTLE_SECS", "3")]);
    b.call("swx_start", json!({}));
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(
        b,
        "attached a moment ago: host_app_starting — settling, with the evidence and its age",
        r["errorCode"] == "host_app_starting"
            && r["readiness"]["basedOn"].as_array().map(|a| a.iter().any(|x| x == "settleAfterAttach")).unwrap_or(false),
        s(&r)
    );
    let st = b.call("swx_status", json!({}));
    let settle = st["solidworks"]["readiness"]["evidence"][2].clone();
    check!(
        b,
        "...the settle evidence: required 3 s, not yet satisfied, anchored on the young session's first sight",
        settle["required"] == 3 && settle["satisfied"] == false && settle["anchor"] == "firstSeenYoung"
            && st["solidworks"]["readiness"]["why"].as_str().unwrap_or("").contains("settling"),
        s(&st["solidworks"]["readiness"])
    );
    std::thread::sleep(Duration::from_millis(3300));
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(b, "after the settle: ready, the document is made", r["success"] == true, s(&r));

    // COM UNSURE on a fresh start: never ready on the log alone.
    let scratch2 = TempDir::new("restart-com");
    young_session(&scratch2, 2);
    std::fs::write(scratch2.join("mock-startup-unreadable"), "").unwrap();
    let log = scratch2.join("SolidWorksPerformance.log");
    std::fs::write(&log, PREVIOUS).unwrap();
    let logp = log.to_string_lossy().to_string();
    let b2 = Bridge::start_in(TempDir::borrowed(&scratch2.0), &[("SWX_PERF_LOG", &logp)]);
    b2.call("swx_start", json!({}));
    let st = b2.call("swx_status", json!({}));
    check!(
        b2,
        "a fresh start with a complete log but StartupProcessCompleted unknown is NOT ready",
        st["solidworks"]["ready"] == false
            && st["solidworks"]["readiness"]["why"].as_str().unwrap_or("").contains("StartupProcessCompleted"),
        s(&st["solidworks"]["readiness"])
    );
}

#[test]
fn a_document_solidworks_dies_right_after_is_never_reported_created() {
    let scratch = TempDir::new("restart-died");
    session(&scratch);
    let b = Bridge::start_in(TempDir::borrowed(&scratch.0), &[]);
    b.call("swx_start", json!({}));
    // The command answers, the identity save answers — then the process is gone.
    std::fs::write(scratch.join("mock-dies-after-new-document"), "1").unwrap();
    let r = b.call("swx_new_document", json!({"type": "part"}));
    check!(
        b,
        "swx_new_document: host_app_died, with the pid and the ledger line — never ok",
        r["success"] == false && r["errorCode"] == "host_app_died" && r["processId"].is_i64() && r["ledger"] == "host_app_died",
        s(&r)
    );
    let l = ledger(&b);
    check!(
        b,
        "...the ledger records the death, and NO document_created",
        l.iter().any(|e| e["action"] == "host_app_died" && e["detail"]["verb"] == "swx_new_document")
            && !l.iter().any(|e| e["action"] == "document_created"),
        s(&json!(l))
    );

    // A reply that names a document SOLIDWORKS does not have.
    let scratch2 = TempDir::new("restart-vanish");
    session(&scratch2);
    let b2 = Bridge::start_in(TempDir::borrowed(&scratch2.0), &[]);
    b2.call("swx_start", json!({}));
    // Another document is open, so the count alone cannot tell.
    let other = b2.call("swx_new_document", json!({"type": "part"}));
    check!(b2, "a first, real document", other["success"] == true, s(&other));
    std::fs::write(scratch2.join("mock-newdoc-vanishes"), "").unwrap();
    let r = b2.call("swx_new_document", json!({"type": "part", "keepUnsaved": true}));
    check!(
        b2,
        "a document missing from the live list: document_not_created, never ok",
        r["success"] == false && r["errorCode"] == "document_not_created",
        s(&r)
    );
    std::fs::remove_file(scratch2.join("mock-newdoc-vanishes")).unwrap();
    let ok = b2.call("swx_new_document", json!({"type": "part"}));
    check!(b2, "...and a real document reports the effect it verified", ok["success"] == true && ok["effect"]["verified"] == true, s(&ok));
}

#[test]
fn a_start_right_after_a_quit_waits_for_the_quit_sessions_process_tree() {
    let m = TempDir::new("restart-quit");
    std::fs::write(m.join("quit-script.json"), json!({"a": "exited"}).to_string()).unwrap();
    std::fs::write(m.join("windows.json"), "[]").unwrap();
    std::fs::write(m.join("sldworks.json"), json!({"responding": true, "hwnd": 6622700, "privateMB": 900, "handles": 4000}).to_string()).unwrap();
    // sldProcMon outlives the quit by 1.5 s; the platform daemons survive it
    // by design and must never be waited for.
    std::fs::write(
        m.join("preexisting.json"),
        json!([
            {"pid": 6076, "image": "3DEXPERIENCELauncher.exe", "ageSeconds": 30000},
            {"pid": 701, "image": "ENOPLMCSAClient.exe", "ageSeconds": 30000},
            {"pid": 800, "image": "sldProcMon.exe", "ageSeconds": 500, "reapedAfterQuitMs": 1500}
        ])
        .to_string(),
    )
    .unwrap();
    let b = Bridge::start_in(
        TempDir::new("restart-quit-scratch"),
        &[
            ("SWX_LAUNCH_FAKE_DIR", &m.path()),
            ("SWX_ALLOW_USER_WRITES", "1"),
            ("SWX_QUIT_SETTLE_MS", "80"),
            ("SWX_QUIT_EXIT_WAIT_SECS", "3"),
        ],
    );
    b.call("swx_start", json!({}));
    let st = b.call("swx_stop", json!({"userAuthorized": true, "confirm": true, "reason": "test: restart", "maxRung": "a"}));
    check!(b, "the quit goes through", st["stopped"] == true, s(&st));
    let r = b.call("swx_start", json!({}));
    let w = r["waitedForPreviousExit"].clone();
    check!(
        b,
        "the start right after it WAITED for the quit session's sldProcMon — not for the platform daemons",
        w["gone"] == true && w["waitedMs"].as_u64().unwrap_or(0) >= 700
            && !s(&w).contains("ENOPLMCSAClient") && !s(&w).contains("3DEXPERIENCELauncher"),
        s(&r)
    );
    check!(
        b,
        "...ledgered as launch_waited_for_previous_exit",
        ledger(&b).iter().any(|e| e["action"] == "launch_waited_for_previous_exit" && e["detail"]["gone"] == true),
        s(&json!(ledger(&b)))
    );
}