main
Drew Owens 0.11.3 source 7364e19 5d ago
//! IS SOLIDWORKS READY? — not "is it attached".
//!
//! MEASURED 2026-10-01 on Drew's machine: a warm launch reached `Run Begin` in
//! 4.5 s and COM attach in 29.7 s. `swx_new_document` 8 s after attach,
//! `swx_open` at 9 s and `swx_close_all_safely` at 12 s CRASHED SOLIDWORKS: its
//! performance log shows add-ins still loading, an unhandled exception during
//! the document commands, and the 3DEXPERIENCE add-in finishing its
//! initialisation only AFTER them. A control launch with no document commands
//! crashed nothing and logged `<3DXLOAD_TIME>` when the platform load finished.
//! So `attached` is not `ready`, and this module is the gate between them.
//!
//! Two signals, each independent of the other:
//!   * COM: `ISldWorks::StartupProcessCompleted` (host command `startup_state`);
//!   * the performance log, BOUND TO THIS SESSION (`perflog::startup_complete`):
//!     only a log written at or after this process's creation time may speak for
//!     it, and within it a 3DEXPERIENCE load marker after the last `LOAD_ADDIN`
//!     line says the start finished — file-based, no COM.
//!
//! THE RULE (0.9.5, adversary pass 42). MEASURED 2026-10-01 on hosted 0.9.3:
//! `StartupProcessCompleted` was already TRUE before the log's marker appeared,
//! and the session became ready 3.4 s after attach when `<3DXINITERROR>` was
//! written after the last `LOAD_ADDIN`. So:
//!   * log COMPLETE for this session, COM not false            -> ready;
//!   * log says a `LOAD_ADDIN` came after this session's marker and the log has
//!     been quiet for `perflog::ON_DEMAND_QUIET_SECS` (an add-in a user loaded
//!     ON DEMAND after the start), COM true                     -> ready;
//!   * log LOADING                                               -> starting;
//!   * the edition writes no markers at all (log unavailable)    -> COM decides;
//!   * the edition writes markers but none ties to THIS session (a log from an
//!     earlier session, or a creation time the bridge cannot learn) -> the log
//!     is UNREADABLE for this session and COM alone is NEVER enough, because COM
//!     answers true before the first marker is written.
//! With nothing that can verify the start, the session is `unverifiable`: after
//! `GRACE_SECS` READ verbs may run (`readsAllowed`), but a verb that creates,
//! opens, saves, closes or changes a document — or quits — keeps refusing
//! `host_app_starting`: the clock never authorises a document command. A start
//! that does not become ready within `TIMEOUT_SECS` is `readinessTimedOut`, still
//! starting. Once a session (by process id) is verified ready it stays ready.
//!
//! A QUICK RESTART (0.11.3, measured 2026-10-15): `ready` came 4 s after attach
//! and a document command 11 s after attach killed SOLIDWORKS. So the log is
//! read only beyond its state when no SOLIDWORKS was writing it
//! (`perflog::Baseline`: a launch, a quit, or a first sight of a log still
//! holding the previous session), and a FRESH attach — the bridge's own launch,
//! or a process first seen young — needs StartupProcessCompleted TRUE and
//! `settle_secs()` since attach on top of the marker. `evidence` lists what was
//! used and how old it is; the ready transition is ledgered.
//!
//! Every assessment also reads `GetDocumentCount` (in `startup_state`): a
//! non-zero count at ANY poll records the session as having held a document
//! (`session_history`).

use serde_json::{json, Value};
use std::collections::HashMap;
use std::sync::Mutex;
use std::time::Instant;

pub const GRACE_SECS: u64 = 60;
pub const TIMEOUT_SECS: u64 = 300;
pub const RETRY_AFTER_SECS: u64 = 5;

/// The grace, overridable (`SWX_READINESS_GRACE_SECS`) so the suite need not
/// wait a real minute. It only ever unlocks READ verbs.
/// THE SETTLE AFTER A FRESH ATTACH (0.11.3, `SWX_READY_SETTLE_SECS`). MEASURED
/// 2026-10-15 22:40 (hosted 0.11.2): a quick restart was called `ready` 4 s
/// after COM attached; a document command 11 s after attach "succeeded" and
/// SOLIDWORKS died a second later — the 2026-10-01 crash again (8 s after
/// attach, an add-in still initialising). A session this bridge has just seen
/// start is ready only with COM's StartupProcessCompleted TRUE, this session's
/// own marker, AND this long since it attached.
pub fn settle_secs() -> u64 {
    std::env::var("SWX_READY_SETTLE_SECS").ok().and_then(|v| v.trim().parse().ok()).unwrap_or(20)
}

/// When THIS session attached, as far as the bridge knows: the launch that
/// attached it (the attempt's attach time, when the attempt is about this
/// process or one created after the attempt began).
fn launch_attach_anchor(pid: i64, created: Option<u64>) -> Option<u64> {
    let a = crate::launch::attempt()?;
    if !a.finished || a.outcome.as_deref() != Some("attached") {
        return None;
    }
    let ours = match (a.attributed_sldworks, created) {
        (Some((p, c)), Some(cr)) if p as i64 == pid && c == cr => true,
        (_, Some(cr)) => cr + 5 >= a.started_at,
        _ => false,
    };
    ours.then_some(a.stage_at)
}

fn grace_secs() -> u64 {
    std::env::var("SWX_READINESS_GRACE_SECS")
        .ok()
        .and_then(|v| v.trim().parse().ok())
        .unwrap_or(GRACE_SECS)
}

struct Seen {
    first: Instant,
    /// The same moment, in epoch seconds — the settle's anchor for a session
    /// first seen young.
    first_epoch: u64,
    ready: bool,
    /// The performance log's length when this session was first seen (F7): a
    /// rewrite at the next start shrinks it; an appended log only grows.
    log_len_at_first_sight: Option<u64>,
}

/// Keyed by (pid, process creation time) — like the session history and the
/// quit ladder's same-process check — so a SOLIDWORKS relaunched in one bridge
/// lifetime that reuses a pid is a NEW session, never born ready (adversary
/// pass 45, V2). The map lives in the server, so it survives a com-host restart.
static SESSIONS: Mutex<Option<HashMap<(i64, Option<u64>), Seen>>> = Mutex::new(None);

/// The readiness of the running session, with what it is based on. `running`
/// false (or a host that cannot answer) means there is no session to judge, and
/// `ready` is null. `ready` is true only when a signal VERIFIED the start;
/// `readsAllowed` is also true once the grace has run out on a session nothing
/// can verify.
pub fn assess(ctx: &crate::verbs::Ctx) -> Value {
    let state = match ctx.call("startup_state", json!({}), 20) {
        Ok(s) => s,
        Err(e) => {
            return json!({"running": Value::Null, "ready": Value::Null,
                          "why": format!("the com host could not say: {}", e.message)})
        }
    };
    if state.get("running").and_then(|v| v.as_bool()) != Some(true) {
        return json!({"running": false, "ready": Value::Null, "why": "SOLIDWORKS is not running"});
    }
    let pid = state.get("processId").and_then(|v| v.as_i64());
    let com = state.get("startupCompleted").and_then(|v| v.as_bool());
    // THIS PROCESS'S CREATION TIME, from the process census — the same identity
    // the quit ladder and the session history use. A host that cannot take a
    // census may report it itself (`processCreatedAt`).
    let created: Option<u64> = pid
        .and_then(|p| u32::try_from(p).ok())
        .and_then(|p| {
            crate::launchos::os()
                .processes()
                .ok()
                .and_then(|ps| ps.iter().find(|x| x.pid == p).and_then(|x| x.created_at))
        })
        .or_else(|| state.get("processCreatedAt").and_then(|v| v.as_u64()));
    // THE LOG, READ ONLY WHERE THIS SESSION CAN HAVE WRITTEN (0.11.3): beyond
    // the state the file was in when no SOLIDWORKS was writing it (a launch
    // began, a quit finished), unless it has been rewritten since. A session
    // first seen while the log is still the previous session's records that
    // state itself.
    if let Some(c) = created {
        let written = crate::perflog::path().and_then(|p| {
            std::fs::metadata(&p).and_then(|m| m.modified()).ok().and_then(|t| t.duration_since(std::time::UNIX_EPOCH).ok()).map(|d| d.as_secs())
        });
        if written.map(|w| w < c).unwrap_or(false) && crate::perflog::baseline_for(c).is_none() {
            crate::perflog::record_baseline("firstSightWhileTheLogWasStillTheLastSession's", Some(c));
        }
    }
    let base = created.and_then(crate::perflog::baseline_for);
    let (log, log_why, region) = crate::perflog::startup_complete_since(created, base.as_ref());
    use crate::perflog::LogVerdict as L;
    let mut guard = SESSIONS.lock().unwrap_or_else(|e| e.into_inner());
    let map = guard.get_or_insert_with(HashMap::new);
    let key = (pid.unwrap_or(-1), created);
    let shape = crate::perflog::shape();
    let len_now = shape.get("lengthNow").and_then(|v| v.as_u64());
    let seen = map.entry(key).or_insert(Seen {
        first: Instant::now(),
        first_epoch: crate::launchos::epoch_secs(),
        ready: false,
        log_len_at_first_sight: len_now,
    });
    let len_first = seen.log_len_at_first_sight;
    let age = seen.first.elapsed().as_secs();
    let mut based_on: Vec<&str> = Vec::new();
    // Some(true) verified ready, Some(false) verified starting, None unverifiable.
    // THE READY LATCH SURVIVES A BRIDGE RESPAWN (0.9.11, L5): every update
    // respawns the bridge, and MEASURED 2026-10-01 a respawned bridge re-opened
    // the question for a three-hour-old session. Persisted in the data root by
    // (pid, creation time).
    if !seen.ready && pid.is_some() && created.is_some() && persisted_ready(pid.unwrap_or(-1), created) {
        seen.ready = true;
        based_on.push("readyBeforeThisBridgeRestarted");
    }
    let verdict: Option<bool> = if seen.ready && pid.is_some() {
        based_on.push("alreadyReadyThisSession");
        Some(true)
    } else {
        if com.is_some() {
            based_on.push("StartupProcessCompleted");
        }
        if log != L::Unavailable {
            based_on.push("performanceLog");
        }
        // A SESSION CANNOT BE STARTING FOR HOURS (0.9.11, L2). MEASURED
        // 2026-10-01: a three-hour-old session with 34 documents open read
        // "loading" and every gated verb refused. When the process is older
        // than long_running_secs() and COM says the start completed, "loading"
        // HOLDS only if a startup line (an add-in load, a marker) changed within
        // the quiet window; otherwise ready, basis `longRunningSession`.
        let process_age = created.map(|c| crate::launchos::epoch_secs().saturating_sub(c));
        let startup_quiet = created.and_then(crate::perflog::startup_quiet_of);
        let long_running = process_age.map(|a| a > long_running_secs()).unwrap_or(false)
            && com == Some(true)
            && startup_quiet.map(|q| q >= crate::perflog::quiet_window()).unwrap_or(false);
        match (log, com) {
            (_, Some(false)) => Some(false),
            (L::Loading, Some(true)) if long_running => {
                based_on.push("longRunningSession");
                Some(true)
            }
            (L::Loading, _) => Some(false),
            (L::Complete, _) => Some(true),
            (L::OnDemandAfterComplete, Some(true)) => Some(true),
            (L::OnDemandAfterComplete, None) => None,
            (L::PlatformAddInNotLoaded, Some(true)) => Some(true),
            (L::PlatformAddInNotLoaded, None) => None,
            // Exists but unreadable: unverifiable, whatever COM says.
            (L::Unreadable, _) => None,
            (L::Unavailable, Some(true)) => Some(true),
            (L::Unavailable, None) => None,
            // Nothing ties the log to this session: COM alone is never enough
            // (it answers true before the first marker).
            (L::NotThisSession, _) => None,
        }
    };
    // A FRESH ATTACH (0.11.3): a session the bridge saw start — attached by its
    // own launch, or first seen while the process was young — is ready only with
    // StartupProcessCompleted TRUE and `settle_secs()` since it attached.
    let now_secs = crate::launchos::epoch_secs();
    let launch_anchor = launch_attach_anchor(pid.unwrap_or(-1), created);
    let young_at_first_sight = created.map(|c| seen.first_epoch.saturating_sub(c) < long_running_secs()).unwrap_or(false);
    let anchor: Option<u64> = match (launch_anchor, young_at_first_sight) {
        (Some(a), _) => Some(a),
        (None, true) => Some(seen.first_epoch),
        (None, false) => None,
    };
    let fresh = anchor.is_some() && !seen.ready;
    let since_attach = anchor.map(|a| now_secs.saturating_sub(a));
    let mut held_by: Option<String> = None;
    let mut verdict = verdict;
    if verdict == Some(true) && fresh {
        if com != Some(true) {
            held_by = Some("a fresh start is ready only with StartupProcessCompleted TRUE, and COM has not said so".into());
            verdict = Some(false);
        } else if since_attach.map(|s| s < settle_secs()).unwrap_or(false) {
            held_by = Some(format!(
                "settling: attached {}s ago, and a fresh start is ready only {}s after attach (SWX_READY_SETTLE_SECS) — \
                 document commands 8 s and 11 s after attach crashed SOLIDWORKS (2026-10-01, 2026-10-15)",
                since_attach.unwrap_or(0),
                settle_secs()
            ));
            verdict = Some(false);
        }
    }
    if held_by.is_some() {
        based_on.push("settleAfterAttach");
    }
    let ready = verdict == Some(true);
    // THE EVIDENCE, with its age — what the verdict was built from.
    let log_age = crate::perflog::path()
        .and_then(|p| std::fs::metadata(&p).and_then(|m| m.modified()).ok())
        .and_then(|t| t.duration_since(std::time::UNIX_EPOCH).ok())
        .map(|d| now_secs.saturating_sub(d.as_secs()));
    let evidence = json!([
        {"signal": "StartupProcessCompleted", "value": com},
        {"signal": "performanceLog", "verdict": log.name(), "marker": region.marker, "markerOffset": region.marker_offset,
         "readFromOffset": region.from_offset,
         "launchBaseline": region.baseline.as_ref().map(|b| json!({"length": b.len, "why": b.why, "ageSeconds": now_secs.saturating_sub(b.at_secs)})),
         "rewrittenSinceBaseline": region.rewritten,
         "logLastWrittenSecondsAgo": log_age},
        {"signal": "settleAfterAttach", "attachedSecondsAgo": since_attach, "required": settle_secs(),
         "anchor": if launch_anchor.is_some() { "launchAttach" } else if anchor.is_some() { "firstSeenYoung" } else { "notAFreshStart" },
         "satisfied": since_attach.map(|s| s >= settle_secs()).unwrap_or(true)},
    ]);
    if ready && pid.is_some() {
        if !seen.ready {
            persist_ready(pid.unwrap_or(-1), created);
            // THE TRANSITION IS ON THE RECORD, with what decided it — so a
            // crash after it can be laid beside the evidence.
            crate::ledger::record(
                "solidworks_ready",
                json!({"processId": pid, "processCreatedAt": created, "basedOn": based_on, "evidence": evidence}),
            );
        }
        seen.ready = true;
    }
    drop(guard);
    // WHAT THE POLL SAW, recorded — but only on a session verified READY. Live
    // 2026-10-01 (pid 29108): a count read during startup recorded a session no
    // one had opened a document in as having held one. A count while starting is
    // never evidence; after the start, a count > 0 must persist across two polls
    // (session_history::observe) to count.
    if let (Some(p), Some(n)) = (
        pid.and_then(|p| u32::try_from(p).ok()),
        state.get("documentCount").and_then(|v| v.as_u64()),
    ) {
        if ready {
            crate::session_history::observe(p, created, n, "readinessPoll");
        }
    }
    let unverifiable = verdict.is_none();
    if unverifiable {
        based_on.push("graceAfterFirstSeen");
    }
    let reads_allowed = ready || (unverifiable && age >= grace_secs());
    json!({
        "running": true,
        "ready": ready,
        "state": if ready { "ready" } else if unverifiable { "unverifiable" } else { "starting" },
        "readsAllowed": reads_allowed,
        "processId": pid,
        "processCreatedAt": created,
        "basedOn": based_on,
        "evidence": evidence,
        "why": held_by.clone().unwrap_or_else(|| log_why.clone()),
        "startupProcessCompleted": com,
        "performanceLog": {
            "verdict": log.name(),
            "why": log_why,
            "shape": shape,
            "lengthAtFirstSight": len_first,
            "shrankSinceFirstSight": match (len_first, len_now) {
                (Some(a), Some(b)) => json!(b < a),
                _ => Value::Null,
            },
        },
        "rule": "ready = this session's performance log (the text after its last start header, \
                 written since the process started) shows the start complete with COM not false; \
                 or COM true and the log quiet 60 s after an on-demand add-in that is not the \
                 platform DLL, or quiet 60 s with the platform DLL never loaded (no marker is \
                 coming); or COM true with no log at all. A log still being written holds COM's \
                 true; a log not tied to this session never lets COM decide alone. Unverifiable \
                 sessions allow read verbs after the grace; never document commands.",
        "secondsSinceFirstSeen": age,
        "readinessTimedOut": !ready && age >= TIMEOUT_SECS,
    })
}

/// How long ago THIS session attached, as far as the bridge knows: its own
/// launch's attach, or its first sight if the process was young then. `None` =
/// not a session the bridge saw start.
pub fn attached_secs_ago(pid: i64, created: Option<u64>) -> Option<u64> {
    let now = crate::launchos::epoch_secs();
    if let Some(a) = launch_attach_anchor(pid, created) {
        return Some(now.saturating_sub(a));
    }
    let g = SESSIONS.lock().unwrap_or_else(|e| e.into_inner());
    let seen = g.as_ref()?.get(&(pid, created))?;
    let young = created.map(|c| seen.first_epoch.saturating_sub(c) < long_running_secs()).unwrap_or(false);
    young.then(|| now.saturating_sub(seen.first_epoch))
}

/// A session is long-running past this many seconds (`SWX_LONG_RUNNING_SECS`).
pub fn long_running_secs() -> u64 {
    std::env::var("SWX_LONG_RUNNING_SECS").ok().and_then(|v| v.trim().parse().ok()).unwrap_or(600)
}

fn ready_path() -> std::path::PathBuf {
    crate::scratch::root().join("ready-sessions.json")
}

fn persisted_ready(pid: i64, created: Option<u64>) -> bool {
    let Some(c) = created else { return false };
    std::fs::read_to_string(ready_path())
        .ok()
        .and_then(|t| serde_json::from_str::<Value>(&t).ok())
        .and_then(|v| v.get(format!("{pid}:{c}")).cloned())
        .is_some()
}

fn persist_ready(pid: i64, created: Option<u64>) {
    let Some(c) = created else { return };
    let mut m = std::fs::read_to_string(ready_path())
        .ok()
        .and_then(|t| serde_json::from_str::<Value>(&t).ok())
        .and_then(|v| v.as_object().cloned())
        .unwrap_or_default();
    m.insert(format!("{pid}:{c}"), json!({"readyAtMs": crate::launchos::epoch_ms() as u64}));
    while m.len() > 20 {
        let oldest = m
            .iter()
            .min_by_key(|(_, v)| v.get("readyAtMs").and_then(|a| a.as_u64()).unwrap_or(0))
            .map(|(k, _)| k.clone());
        match oldest {
            Some(o) => {
                m.remove(&o);
            }
            None => break,
        }
    }
    let _ = crate::launch::write_atomic(&ready_path(), &Value::Object(m).to_string());
}

/// Has this bridge VERIFIED that session `pid` finished starting? Read from the
/// per-session cache; no COM.
pub fn known_ready(pid: u32, created: Option<u64>) -> bool {
    SESSIONS
        .lock()
        .unwrap_or_else(|e| e.into_inner())
        .as_ref()
        .and_then(|m| m.get(&(pid as i64, created)).map(|s| s.ready))
        .unwrap_or(false)
}

/// What a verb does to SOLIDWORKS, for the gate.
#[derive(Clone, Copy, PartialEq, Eq)]
pub enum Touch {
    /// Reads only (catalog risk `read`): may run once the grace has run out on a
    /// session nothing can verify.
    Read,
    /// Creates, opens, saves, closes, changes or quits: needs a VERIFIED start.
    Mutate,
}

/// THE GATE: no COM verb — and no quit — until SOLIDWORKS has finished
/// starting. `None` lets the verb run: SOLIDWORKS is ready (or, for a READ verb,
/// unverifiable past the grace), or not running at all (the verb then answers
/// that for itself), or the host could not say (the verb's own call meets the
/// same failure and reports it). `Some` is the refusal.
/// What the gate saw, for the verb's reply (0.9.6, G3): every gated verb —
/// success or refusal — carries `readiness: {ready, state, basedOn, readsAllowed,
/// evaluatedAt:"gate"}`, so a live run can prove no COM verb ran while starting.
pub fn gate_summary(r: &Value) -> Value {
    json!({
        "ready": r.get("ready").cloned().unwrap_or(Value::Null),
        "state": r.get("state").cloned().unwrap_or(Value::Null),
        "basedOn": r.get("basedOn").cloned().unwrap_or_else(|| json!([])),
        "readsAllowed": r.get("readsAllowed").cloned().unwrap_or(Value::Null),
        "running": r.get("running").cloned().unwrap_or(Value::Null),
        "why": r.get("why").cloned().unwrap_or(Value::Null),
        "evaluatedAt": "gate",
    })
}

/// The gate itself. `Ok(summary)` lets the verb run (the summary goes into its
/// reply); `Err(refusal)` is the refusal, which carries the full assessment.
pub fn gate(ctx: &crate::verbs::Ctx, verb: &str, touch: Touch) -> Result<Value, Value> {
    let r = assess(ctx);
    match refusal_for(&r, verb, touch) {
        None => Ok(gate_summary(&r)),
        Some(refusal) => Err(refusal),
    }
}

fn refusal_for(r: &Value, verb: &str, touch: Touch) -> Option<Value> {
    let r = r.clone();
    if r.get("ready").and_then(|v| v.as_bool()) != Some(false) {
        return None;
    }
    let unverifiable = r.get("state").and_then(|v| v.as_str()) == Some("unverifiable");
    let reads_allowed = r.get("readsAllowed").and_then(|v| v.as_bool()) == Some(true);
    if touch == Touch::Read && reads_allowed {
        return None;
    }
    let timed_out = r.get("readinessTimedOut").and_then(|v| v.as_bool()) == Some(true);
    let mut out = crate::verbs::err_code(
        "host_app_starting",
        if unverifiable {
            format!(
                "{verb} refused: the bridge cannot verify that SOLIDWORKS has finished starting \
                 (no signal it can read ties a completed start to this session: {}), and a verb \
                 that touches documents is never sent on the clock alone. Document commands sent \
                 while SOLIDWORKS was still starting crashed it on 2026-10-01.",
                r.pointer("/performanceLog/why").and_then(|v| v.as_str()).unwrap_or("no performance log")
            )
        } else {
            format!(
                "{verb} refused: SOLIDWORKS is attached but has not finished starting (add-ins, the \
                 3DEXPERIENCE platform load). Document commands sent in that window crashed \
                 SOLIDWORKS on 2026-10-01."
            )
        },
        if unverifiable {
            "Cannot verify startup completed. Read verbs run once `readiness.readsAllowed` is true \
             (the grace); this one does not. Look at swx_status's `solidworks.readiness` \
             (`performanceLog.why` says why the log cannot vouch for this session) and at the \
             user's screen. Nothing was sent to SOLIDWORKS."
                .to_string()
        } else if timed_out {
            format!(
                "SOLIDWORKS has not reported a finished start for over five minutes. It is still \
                 treated as starting — the clock never promotes it to ready. Why: {}. Look at \
                 swx_status's `solidworks.readiness` and at the user's screen (a dialog, a \
                 sign-in); do not force document commands through.",
                r.pointer("/performanceLog/why").and_then(|v| v.as_str())
                    .or_else(|| r.get("startupProcessCompleted").and_then(|v| v.as_bool()).filter(|c| !c).map(|_| "COM's StartupProcessCompleted is false"))
                    .unwrap_or("no signal says the start finished")
            )
        } else {
            "Wait `retryAfterSeconds`, then call again — or poll swx_status until \
             `solidworks.ready` is true. Nothing was sent to SOLIDWORKS."
                .to_string()
        },
    );
    if let Value::Object(m) = &mut out {
        m.insert("retryAfterSeconds".into(), json!(RETRY_AFTER_SECS));
        if unverifiable {
            m.insert("startingUnverifiable".into(), json!(true));
        }
        m.insert("readiness".into(), r);
    }
    Some(out)
}