main
Drew Owens 0.11.3 source 7364e19 5d ago
//! SOLIDWORKS' own performance log — a second witness that needs no COM.
//!
//! `%APPDATA%\SOLIDWORKS\SOLIDWORKS <year>\SolidWorksPerformance.log` is written
//! by SOLIDWORKS as it runs. MEASURED 2026-10-01 on Drew's machine (hosted 0.9.2):
//!
//!   * a start writes `LOAD_ADDIN` lines while add-ins load, and the
//!     3DEXPERIENCE add-in reports when it has finished — `<3DXLOAD_TIME>24000`
//!     on a clean start, `<3DXINITERROR>` on the start that crashed;
//!   * the crash: document commands sent 8 s after COM attach ran while
//!     `LOAD_ADDIN` lines were still being written; the log then shows
//!     `<SWEXH>` / `<UNHANDLED>` / `</SWEXH>`, the 3DEXPERIENCE marker AFTER the
//!     document commands, `<PROCMEM> CMD:DocSave`, `<RUNTIME>`, `<SWERR_REPORT>`;
//!   * a control launch with no document commands: no `SWEXH`, and the log gains
//!     `<3DXLOAD_TIME>` when the platform load finishes.
//!
//! So this module answers two questions from the file alone: has the current
//! start finished (a 3DEXPERIENCE marker written AFTER the last `LOAD_ADDIN`
//! line), and what did SOLIDWORKS say on its way down (the crash markers in the
//! tail). The first is a HEURISTIC over a format nobody documents — the
//! readiness gate pairs it with COM's `StartupProcessCompleted` and says which
//! signals it used. `SWX_PERF_LOG` overrides the path (an empty value means "no
//! log"), which is how the suite supplies one.

use std::path::PathBuf;

/// How much of the end of the log is read. The markers that matter are recent,
/// and the file grows for the life of the install.
const TAIL_BYTES: u64 = 2 * 1024 * 1024;

/// The first line of the log, written at every start (measured 2026-10-01).
const LOG_HEADER: &str = "; SolidWorks generated log file";
/// The 3DEXPERIENCE platform add-in's DLL, lower-case (measured 2026-10-01).
const PLATFORM_ADDIN_DLL: &str = "swk3dcompassaddin.dll";

const LOAD_MARKERS: &[&str] = &["<3DXLOAD_TIME>", "<3DXINITERROR>"];
const CRASH_MARKERS: &[&str] = &["<SWEXH>", "<UNHANDLED>", "<SWERR_REPORT>", "<RUNTIME>"];

/// The log, if there is one. Of several `SOLIDWORKS <year>` folders, the one
/// whose log was written most recently.
pub fn path() -> Option<PathBuf> {
    if let Ok(p) = std::env::var("SWX_PERF_LOG") {
        return if p.trim().is_empty() { None } else { Some(PathBuf::from(p)) };
    }
    let appdata = std::env::var("APPDATA").ok().filter(|a| !a.trim().is_empty())?;
    let base = PathBuf::from(appdata).join("SOLIDWORKS");
    let mut best: Option<(std::time::SystemTime, PathBuf)> = None;
    for e in std::fs::read_dir(&base).ok()?.flatten() {
        let log = e.path().join("SolidWorksPerformance.log");
        if let Ok(m) = std::fs::metadata(&log).and_then(|m| m.modified()) {
            if best.as_ref().map(|(t, _)| m > *t).unwrap_or(true) {
                best = Some((m, log));
            }
        }
    }
    best.map(|(_, p)| p)
}

fn tail() -> Option<String> {
    tail_bytes().map(|(b, _)| String::from_utf8_lossy(&b).to_string())
}

/// The tail as BYTES, with the file offset it starts at — positions compare
/// exactly only before a lossy UTF-8 conversion.
fn tail_bytes() -> Option<(Vec<u8>, u64)> {
    use std::io::{Read, Seek, SeekFrom};
    let mut f = std::fs::File::open(path()?).ok()?;
    let len = f.metadata().ok()?.len();
    let start = len.saturating_sub(TAIL_BYTES);
    f.seek(SeekFrom::Start(start)).ok()?;
    let mut buf = Vec::new();
    f.read_to_end(&mut buf).ok()?;
    Some((buf, start))
}

/// `n` bytes of the log ending at `end` (or fewer at the start of the file).
fn bytes_before(path: &std::path::Path, end: u64, n: u64) -> Option<Vec<u8>> {
    use std::io::{Read, Seek, SeekFrom};
    let mut f = std::fs::File::open(path).ok()?;
    let from = end.saturating_sub(n);
    f.seek(SeekFrom::Start(from)).ok()?;
    let mut buf = vec![0u8; (end - from) as usize];
    f.read_exact(&mut buf).ok()?;
    Some(buf)
}

// ── THE LAUNCH BASELINE (0.11.3) ────────────────────────────────────────────
// MEASURED 2026-10-15 22:40 (hosted 0.11.2): a quit at 22:40:01, a launch at
// 22:40:02, COM attached at 22:40:39 — and `ready` at 22:40:43. A document
// command at 22:40:50 "succeeded", and SOLIDWORKS died a second later: the
// 2026-10-01 crash, an add-in still initialising. The log is tied to a session
// by its modification time, which says nothing about WHICH lines are the new
// session's: a marker the PREVIOUS session wrote, still in the file when the new
// one touched it, read as this start completing. So the file's state is
// recorded when no SOLIDWORKS can be writing it — when a launch begins, when a
// quit has verifiably finished — and a marker counts for a session that started
// after that only if it lies BEYOND the recorded length, unless the file has
// been REWRITTEN since (shorter now, or different bytes where the recorded file
// ended).

/// The log's state at a moment no SOLIDWORKS session was writing it.
#[derive(Clone, Debug, PartialEq, serde::Serialize, serde::Deserialize)]
pub struct Baseline {
    /// The file's length then.
    pub len: u64,
    /// sha256 of the (up to) 256 bytes that ended the file then: still there
    /// unchanged means the file was APPENDED to; different, it was rewritten.
    pub end_fp: String,
    /// When it was taken (epoch seconds).
    pub at_secs: u64,
    /// Why (launch / quit / first sight of a session whose log was still the
    /// previous session's).
    pub why: String,
}

const END_FP_BYTES: u64 = 256;

/// The log's state now, if there is a log.
pub fn snapshot(why: &str) -> Option<Baseline> {
    let p = path()?;
    let len = std::fs::metadata(&p).ok()?.len();
    let end_fp = crate::sha256::hex_of(&bytes_before(&p, len, END_FP_BYTES)?);
    Some(Baseline { len, end_fp, at_secs: crate::launchos::epoch_secs(), why: why.to_string() })
}

fn baselines_path() -> PathBuf {
    crate::scratch::root().join("perflog-baselines.json")
}

pub fn baselines() -> Vec<Baseline> {
    std::fs::read_to_string(baselines_path()).ok().and_then(|t| serde_json::from_str(&t).ok()).unwrap_or_default()
}

/// Record the log's state now (keeps the last 8). `at_override`: the moment the
/// record speaks for (a session's creation time, for a first-sight record).
pub fn record_baseline(why: &str, at_override: Option<u64>) -> Option<Baseline> {
    let mut b = snapshot(why)?;
    if let Some(a) = at_override {
        b.at_secs = a;
    }
    let mut all = baselines();
    all.push(b.clone());
    let keep = all.len().saturating_sub(8);
    let all: Vec<Baseline> = all.into_iter().skip(keep).collect();
    let _ = std::fs::write(baselines_path(), serde_json::to_string(&all).unwrap_or_else(|_| "[]".into()));
    Some(b)
}

/// The latest record taken at or before a session started: everything the file
/// held then was written by earlier sessions.
pub fn baseline_for(session_start: u64) -> Option<Baseline> {
    baselines().into_iter().filter(|b| b.at_secs <= session_start).max_by_key(|b| b.at_secs)
}

/// Has the file been rewritten since `b` (shorter, or different bytes where it
/// ended)? `None` = could not tell.
pub fn rewritten_since(b: &Baseline) -> Option<bool> {
    let p = path()?;
    let len = std::fs::metadata(&p).ok()?.len();
    if len < b.len {
        return Some(true);
    }
    let now = bytes_before(&p, b.len, END_FP_BYTES)?;
    Some(crate::sha256::hex_of(&now) != b.end_fp)
}

/// How long the log must have been QUIET before a `LOAD_ADDIN` after this
/// session's 3DEXPERIENCE marker is read as an add-in loaded ON DEMAND (a user
/// enabling Toolbox or Simulation later) rather than as startup still running.
pub const ON_DEMAND_QUIET_SECS: u64 = 60;

/// What the log says about the RUNNING session's start.
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
pub enum LogVerdict {
    /// No log at all (the default location holds none): the log cannot judge,
    /// and COM decides.
    Unavailable,
    /// A log that exists — or a configured path (`SWX_PERF_LOG`) that is
    /// missing — and cannot be read: UNVERIFIABLE. Never treated as absent: COM
    /// alone was measured true before the marker (adversary pass 45, V1).
    Unreadable,
    /// Nothing ties the log to THIS session: no process creation time, or a log
    /// last written before the process started (adversary pass 42: a day-old log
    /// ending in a completed start read "complete" for a session that had not
    /// written a line). COM alone never decides then. Not ready.
    NotThisSession,
    /// This session's log is still being written with add-ins loading and no
    /// marker after them (or the platform add-in loaded and its marker has not
    /// come): a start is loading. Not ready.
    Loading,
    /// A marker after the latest `LOAD_ADDIN`, in a log written since the
    /// process started. Ready, by the log.
    Complete,
    /// A marker, then a `LOAD_ADDIN` that is not the platform add-in, then
    /// nothing for `ON_DEMAND_QUIET_SECS`: an add-in loaded on demand after the
    /// start completed. Ready — ONLY together with COM's StartupProcessCompleted.
    OnDemandAfterComplete,
    /// This session never loaded the platform add-in (`SWK3DCompassAddin.dll`
    /// — the one that writes the marker; a user may disable it), its log has
    /// gone quiet: there is no marker to wait for (adversary pass 44, F2). Ready
    /// — ONLY together with COM's StartupProcessCompleted.
    PlatformAddInNotLoaded,
}

impl LogVerdict {
    pub fn name(self) -> &'static str {
        match self {
            LogVerdict::Unavailable => "unavailable",
            LogVerdict::Unreadable => "unreadable",
            LogVerdict::NotThisSession => "notThisSession",
            LogVerdict::Loading => "loading",
            LogVerdict::Complete => "complete",
            LogVerdict::OnDemandAfterComplete => "onDemandAddInAfterComplete",
            LogVerdict::PlatformAddInNotLoaded => "platformAddInNotLoaded",
        }
    }
}

/// IS THIS LINE AN ADD-IN *LOAD* EVENT? Parsed as a token, never a substring
/// (0.9.11): MEASURED 2026-10-01, `<AD2> "UNLOAD_ADDIN" "SWK3DCompassAddin.dll"`
/// CONTAINS `LOAD_ADDIN`, and reading it as the platform add-in loading after the
/// marker locked a three-hour-old session out as "a start". The measured format
/// is `<AD2> "LOAD_ADDIN" "<dll>" "<name>" …` — the quoted token exactly; the
/// `<LOAD_ADDIN> …` tag form is accepted too. `"UNLOAD_ADDIN"` is its own event
/// and never evidence of loading.
pub fn is_load_event(line: &str) -> bool {
    let t = line.trim_start();
    t.contains("\"LOAD_ADDIN\"") || t.starts_with("<LOAD_ADDIN>")
}

fn is_marker_line(line: &str) -> bool {
    LOAD_MARKERS.iter().any(|m| line.contains(m))
}

/// The quiet window, overridable (`SWX_STARTUP_QUIET_SECS`) for the suite.
pub fn quiet_window() -> u64 {
    std::env::var("SWX_STARTUP_QUIET_SECS").ok().and_then(|v| v.trim().parse().ok()).unwrap_or(ON_DEMAND_QUIET_SECS)
}

/// STARTUP ACTIVITY, not file activity (0.9.11, L3): an ACTIVE session writes
/// `<PROCMEM> CMD:AppRunTime` lines periodically, so "the file was written
/// recently" says nothing about add-ins. What counts is when the STARTUP lines
/// (add-in loads, markers) last changed: all of them were written at or before
/// the file's mtime when the bridge first saw them, and the bridge remembers
/// that time per session until they change again.
static STARTUP_SEEN: std::sync::Mutex<Option<std::collections::HashMap<u64, (String, u64)>>> =
    std::sync::Mutex::new(None);

/// Seconds since this session's STARTUP lines last changed, as last computed —
/// for the long-running-session rule in readiness.rs. `None` = never computed.
pub fn startup_quiet_of(session_start: u64) -> Option<u64> {
    let g = STARTUP_SEEN.lock().unwrap_or_else(|e| e.into_inner());
    g.as_ref()
        .and_then(|m| m.get(&session_start))
        .map(|e| crate::launchos::epoch_secs().saturating_sub(e.1))
}

fn startup_quiet(session_start: u64, fingerprint: String, mtime: u64) -> u64 {
    let now = crate::launchos::epoch_secs();
    let mut g = STARTUP_SEEN.lock().unwrap_or_else(|e| e.into_inner());
    let m = g.get_or_insert_with(std::collections::HashMap::new);
    let e = m.entry(session_start).or_insert_with(|| (fingerprint.clone(), mtime));
    if e.0 != fingerprint {
        *e = (fingerprint, mtime);
    }
    now.saturating_sub(e.1)
}

fn mtime_secs(path: &std::path::Path) -> Option<u64> {
    std::fs::metadata(path)
        .and_then(|md| md.modified())
        .ok()
        .and_then(|t| t.duration_since(std::time::UNIX_EPOCH).ok())
        .map(|d| d.as_secs())
}

/// HAS THIS SESSION'S START FINISHED, by the log? `session_start` is the
/// process creation time in epoch seconds, and the log may speak for the
/// session only if it was last written at or after it. MEASURED 2026-10-01:
/// the file is REWRITTEN at every start and begins with a header; only the text
/// after the last header is read. Within it:
///
///   * a marker after the last `LOAD_ADDIN`                     -> complete;
///   * a `LOAD_ADDIN` after the marker: the platform DLL        -> loading;
///     anything else, log quiet >= quiet_window()          -> on demand;
///     log still being written                                   -> loading;
///   * NO marker: log still being written (quiet < the window)  -> loading —
///     a log THIS session is actively writing is evidence on its own, whatever
///     history says (F3: the first start on a machine was the crash window);
///     quiet, the platform DLL loaded (its marker never came)    -> loading;
///     quiet, the platform DLL never loaded (disabled)           -> no marker
///     to wait for: `platformAddInNotLoaded` (F2).
///
/// MEASURED: COM's StartupProcessCompleted was TRUE before the marker of a real
/// start, so a log that cannot be tied to the session never lets COM decide
/// alone, and a log still being written holds COM's `true`.
pub fn startup_complete(session_start: Option<u64>) -> (LogVerdict, String) {
    let base = session_start.and_then(baseline_for);
    let (v, why, _) = startup_complete_since(session_start, base.as_ref());
    (v, why)
}

/// What the region read came from: the baseline used, whether the file was
/// rewritten since it, and where the region began (file offset).
#[derive(Clone, Debug, Default, PartialEq)]
pub struct Region {
    pub baseline: Option<Baseline>,
    pub rewritten: Option<bool>,
    pub from_offset: u64,
    /// The file offset of the marker that decided `Complete`, if one did.
    pub marker_offset: Option<u64>,
    pub marker: Option<String>,
}

/// `startup_complete`, reading only what a session that started after `base`
/// can have written (0.11.3): when the file was APPENDED to since `base`, the
/// region starts at `base.len`; when it was rewritten (or there is no
/// baseline), at the last start header, as before.
pub fn startup_complete_since(session_start: Option<u64>, base: Option<&Baseline>) -> (LogVerdict, String, Region) {
    let mut region = Region { baseline: base.cloned(), ..Default::default() };
    let Some(path) = path() else {
        return (LogVerdict::Unavailable, "no SOLIDWORKS performance log to read".into(), region);
    };
    let Some((raw, tail_start)) = tail_bytes() else {
        // ABSENT AND UNREADABLE ARE DIFFERENT FACTS (adversary pass 45, V1). A
        // log that exists — or a configured path that is missing — and cannot
        // be read says the edition DOES write one and this bridge did not see
        // it: UNVERIFIABLE, never "no log, let COM decide".
        return (
            LogVerdict::Unreadable,
            if path.exists() {
                format!("the performance log exists but could not be read ({})", path.display())
            } else {
                format!("the configured performance log path is missing ({})", path.display())
            },
            region,
        );
    };
    // WHERE THIS SESSION'S TEXT CAN BEGIN. Appended since the baseline: after
    // the recorded length — what lies before it is an earlier session's, its
    // markers included. Rewritten (or no baseline): the whole tail.
    let mut from_rel = 0usize;
    if let Some(b) = base {
        let rw = rewritten_since(b);
        region.rewritten = rw;
        if rw == Some(false) {
            from_rel = (b.len.saturating_sub(tail_start) as usize).min(raw.len());
        }
    }
    let scoped = String::from_utf8_lossy(&raw[from_rel..]).to_string();
    let (t, header_rel): (&str, usize) = match scoped.rfind(LOG_HEADER) {
        Some(h) => (&scoped[h..], h),
        None => (&scoped, 0),
    };
    region.from_offset = tail_start + from_rel as u64 + header_rel as u64;
    let mtime = mtime_secs(&path);
    let Some(start) = session_start else {
        return (
            LogVerdict::NotThisSession,
            "this SOLIDWORKS process's creation time is unknown, so the log cannot be tied to it".into(),
            region,
        );
    };
    let mt = match mtime {
        Some(mt) if mt >= start => mt,
        Some(mt) => {
            return (
                LogVerdict::NotThisSession,
                format!(
                    "the log was last written {}s BEFORE this SOLIDWORKS process started: it speaks for \
                     an earlier session, not this one",
                    start - mt
                ),
                region,
            )
        }
        None => return (LogVerdict::NotThisSession, "the log's modification time could not be read".into(), region),
    };
    let is_platform = |l: &str| is_load_event(l) && l.to_ascii_lowercase().contains(PLATFORM_ADDIN_DLL);
    // Every line with its byte offset, so positions compare exactly.
    let mut lines: Vec<(usize, &str)> = Vec::new();
    {
        let mut off = 0usize;
        for l in t.split_inclusive('\n') {
            lines.push((off, l));
            off += l.len();
        }
    }
    let startup_lines: Vec<&str> =
        lines.iter().map(|(_, l)| *l).filter(|l| is_load_event(l) || is_marker_line(l)).collect();
    let fingerprint = format!(
        "{}|{}",
        startup_lines.len(),
        startup_lines.last().map(|l| l.trim()).unwrap_or("")
    );
    let quiet = startup_quiet(start, fingerprint, mt);
    let last_marker = LOAD_MARKERS.iter().filter_map(|m| t.rfind(m).map(|i| (i, *m))).max();
    let Some((m, name)) = last_marker else {
        let addins = lines.iter().filter(|(_, l)| is_load_event(l)).count();
        let platform = t.lines().any(is_platform);
        if quiet < quiet_window() {
            return (
                LogVerdict::Loading,
                format!(
                    "this session's startup lines changed {quiet}s ago ({addins} LOAD_ADDIN \
                     line(s)) and the log holds no 3DEXPERIENCE marker {}yet: a start in progress — \
                     held until the marker arrives or no startup line changes for {}s",
                    if from_rel > 0 { "written since the launch " } else { "" },
                    quiet_window()
                ),
                region,
            );
        }
        if platform {
            return (
                LogVerdict::Loading,
                format!(
                    "the platform add-in ({PLATFORM_ADDIN_DLL}) loaded in this session but its marker \
                     has not been written, and no startup line has changed for {quiet}s: the platform \
                     load has not finished (a dialog, a sign-in?)"
                ),
                region,
            );
        }
        return (
            LogVerdict::PlatformAddInNotLoaded,
            format!(
                "this session never loaded the platform add-in ({PLATFORM_ADDIN_DLL}), so no marker \
                 is coming; {addins} LOAD_ADDIN line(s) and no startup activity for {quiet}s (>= \
                 {ON_DEMAND_QUIET_SECS}s): the add-in load phase is over — ready only if COM also \
                 says the start completed"
            ),
            region,
        );
    };
    let last_addin = lines.iter().rev().find(|(_, l)| is_load_event(l)).map(|(o, _)| *o);
    region.marker = Some(name.to_string());
    region.marker_offset = Some(region.from_offset + m as u64);
    let verdict_and_why = match last_addin {
        Some(a) if a > m => {
            // A START loads the PLATFORM add-in — it is what writes the marker —
            // so a LOAD_ADDIN for it after the last marker is a start in
            // progress, however quiet the log (wedged behind a dialog). Keyed on
            // the DLL NAME (measured 2026-10-01): three add-ins carry
            // "3DEXPERIENCE" in their names — SaveFolderTo3DEXPERIENCEAddin2
            // ("Batch Save to 3DEXPERIENCE"), TaskPaneCacheExplorerAddin
            // ("3DEXPERIENCE files on This PC") and SWK3DCompassAddin
            // ("3DEXPERIENCE for WORKS"); only the last is the platform.
            let start_block = t[m..].lines().any(is_platform);
            if quiet >= quiet_window() && !start_block {
                (
                    LogVerdict::OnDemandAfterComplete,
                    format!(
                        "a {name} marker, then LOAD_ADDIN line(s) not naming the platform add-in \
                         ({PLATFORM_ADDIN_DLL}), then no startup activity for {quiet}s (>= \
                         {ON_DEMAND_QUIET_SECS}s): an add-in loaded on demand after the start \
                         completed — ready only if COM also says the start completed"
                    ),
                )
            } else {
                (
                    LogVerdict::Loading,
                    format!(
                        "add-ins are still loading: the last LOAD_ADDIN is newer than the last {name}{}, \
                         and the startup lines last changed {quiet}s ago",
                        if start_block {
                            " and names the platform add-in (a start, not an on-demand load)"
                        } else {
                            ""
                        }
                    ),
                )
            }
        }
        _ => (
            LogVerdict::Complete,
            format!(
                "{name} written after the last LOAD_ADDIN line, in a log written since this process started{}",
                match (&region.baseline, region.rewritten) {
                    (Some(b), Some(false)) => format!(", and beyond the {} bytes the file held before this launch ({})", b.len, b.why),
                    (Some(b), Some(true)) => format!(" (the file was rewritten since the {} record)", b.why),
                    _ => String::new(),
                }
            ),
        ),
    };
    (verdict_and_why.0, verdict_and_why.1, region)
}

/// THE FILE'S SHAPE, for the record (adversary pass 44, F7): its length now and
/// how many start headers its tail holds. MEASURED 2026-10-01: rewritten at
/// every start (one header, at the top). An APPENDED log would hold several —
/// the reading above still takes only the text after the last one.
pub fn shape() -> serde_json::Value {
    let Some(p) = path() else { return serde_json::Value::Null };
    let len = std::fs::metadata(&p).map(|m| m.len()).ok();
    let t = tail().unwrap_or_default();
    let headers = t.matches(LOG_HEADER).count();
    let whole = len.map(|l| l <= TAIL_BYTES).unwrap_or(false);
    let model = match headers {
        0 => "noHeader",
        1 if whole && t.starts_with(LOG_HEADER) => "rewrittenPerStart",
        1 => "oneHeaderInTail",
        _ => "appended",
    };
    serde_json::json!({"lengthNow": len, "headersInTail": headers, "model": model})
}

/// WHAT SOLIDWORKS WROTE ON ITS WAY DOWN: the last lines of the tail that carry
/// a crash marker, verbatim, newest last. Empty when there are none — which is
/// not proof of anything.
pub fn crash_evidence() -> Vec<String> {
    let Some(t) = tail() else { return Vec::new() };
    let lines: Vec<&str> = t.lines().collect();
    // Only what was written after the last start's add-ins began loading: an
    // older session's crash is not this one's.
    let from = lines.iter().rposition(|l| is_load_event(l)).unwrap_or(0);
    let hits: Vec<String> = lines[from..]
        .iter()
        .filter(|l| CRASH_MARKERS.iter().any(|m| l.contains(m)))
        .map(|l| l.trim().to_string())
        .collect();
    let keep = hits.len().saturating_sub(20);
    hits[keep..].to_vec()
}