From 86ce0419e5aa23b6737dc3799dafb5b6884842bd Mon Sep 17 00:00:00 2001 From: ScottW514 Date: Mon, 17 Aug 2026 06:42:38 -0400 Subject: [PATCH] forgetest: cloud tests stay in cloud mode; the page can ignore prerequisites The cloud job tests (lid-abort, lid-during-button-wait, hunt-lid-open, pause-resume) run in cloud mode and leave the machine there: enter_cloud reuses a live session (pid-scoped from the client's own websocket state lines) and switches once from GRBL mode, declaring the change to the baseline; nothing switches back. Each test judges the log from its own window, the print by its own "print [id]: finished" line, and waits the service's follow-up moves out (wait_quiet) before it ends. hunt-lid-open restarts the cloud client through the supervisor's stop/start lever for a fresh connect. The former switch-back is what failed the last bench run of hunt-lid-open (409 machine is not idle: the service was still re-finding the head after the lid closed). The baseline is mode-aware: in cloud mode the client owns the GRBL controller's init values, the lid lamp, and the position counters; the mode itself is preserved unless the run declared the change (Context.mode_changed); controller_mode is never handed back as a bare setting (a bare write left the persisted mode out of step with the live one). The undeclared-change restore now uses the captured state, which the post pass never saw before. The acceptance page gets an "Ignore prerequisites" switch (remembered by the browser): POST /start {ignore_requires} starts a test whose requires are unmet, and the run records the unmet prerequisites in its evidence and log; they stay required for the release. The cloud tests' requires no longer chain through cloud.mode-switch. Proof: tests/test_cloud_suite.py replays the four tests on the bench's own gfcloud excerpts (fixtures/) and the run loop's emitted pause/resume lines under the real runner Context against a fake forgectrl; baseline mode tests and the server override test; the whole suite (98) and the coverage lint pass. Catalog consequence: cloud.* fingerprints move with the module; the catalog hash moves with the requires. --- docs/ACCEPTANCE.md | 29 +- docs/BRINGUP.md | 26 +- forgetest/forgetest/baseline.py | 56 +- forgetest/forgetest/page.py | 18 +- forgetest/forgetest/runner.py | 25 +- forgetest/forgetest/server.py | 5 +- forgetest/forgetest/suite/cloud.py | 510 +++++++++++------- .../tests/fixtures/gfcloud-buttonwait.log | 41 ++ forgetest/tests/fixtures/gfcloud-huntlid.log | 207 +++++++ forgetest/tests/fixtures/gfcloud-lidabort.log | 72 +++ forgetest/tests/fixtures/gfcloud-pause.log | 53 ++ forgetest/tests/helpers.py | 86 +++ forgetest/tests/test_baseline.py | 92 ++++ forgetest/tests/test_cloud_suite.py | 385 +++++++++++++ forgetest/tests/test_server.py | 12 + 15 files changed, 1408 insertions(+), 209 deletions(-) create mode 100644 forgetest/tests/fixtures/gfcloud-buttonwait.log create mode 100644 forgetest/tests/fixtures/gfcloud-huntlid.log create mode 100644 forgetest/tests/fixtures/gfcloud-lidabort.log create mode 100644 forgetest/tests/fixtures/gfcloud-pause.log create mode 100644 forgetest/tests/test_cloud_suite.py diff --git a/docs/ACCEPTANCE.md b/docs/ACCEPTANCE.md index 93d05db..379f934 100644 --- a/docs/ACCEPTANCE.md +++ b/docs/ACCEPTANCE.md @@ -30,7 +30,12 @@ Every test declares, in code (`forgetest/forgetest/suite/*.py`): - **covers** - the source paths whose content the test stands for, as `(component, glob)` pairs; - **requires** - tests that must be satisfied first (the emission tests - require the motion and readback tests); + require the motion and readback tests). This orders the runs; it is not + a release condition of its own (the release needs every test satisfied + anyway). The page's **Ignore prerequisites** switch lets any test start + alone; a run started that way records the unmet prerequisites in its + `evidence.prerequisites` and its log, and the prerequisites stay + required; - **always** - membership in the **always-required core**, which is run in every campaign and is never inherited: image health, the kernel latch/safety readbacks, and one live emission witness with the @@ -103,7 +108,16 @@ forces a full campaign; nothing before it can be inherited. do not. 3. Start the required tests. `operator` tests ask questions in the run pane; `live` tests need the acknowledgment and the physical arm press; - `takeover` tests stop forgectrl for the duration. + `takeover` tests stop forgectrl for the duration. A test whose + prerequisites are not satisfied is locked until they are - or until + the **Ignore prerequisites** switch in the Campaign card is on, which + unlocks every Start (the switch is remembered by the browser; a run + started under it says so in its record). + The `cloud.*` job tests run **in cloud mode and stay there**: the first + one switches from GRBL mode (once, its connect-time hunt waited out) + and the following ones reuse the live session; nothing switches back - + switch on the control panel when done. `cloud.mode-switch` is the one + round trip and starts in GRBL mode. 4. When *Release authorized: YES*, **Export release artifact**, download `acceptance.json` and `acceptance.md`, and commit them as `releases/v/acceptance.json` and `.md`. @@ -126,7 +140,16 @@ at forgectrl's `lid_lamp_idle` setting; forgectrl: the controller running with motion verified, no diagnostic, the camera engine and cooling engine idle), and **preserved** state with no resting policy that a run must hand back as it found it (the position counters, the settings map, the -controller mode). Deviations are +controller mode). The mode in force decides what the baseline owns: in +cloud mode the cloud client's own configuration (the GRBL controller's +init values, which it rewrites from every pulse header; the lid lamp, +its lid-image level; the position counters, re-zeroed at every service +action) is left to it, and the safety readbacks, latch, ring, module +defaults, and forgectrl's engines are checked as always. The mode itself +is preserved unless the run declared the change (`ctx.mode_changed()`, +the cloud tests entering cloud mode); the persisted `controller_mode` +setting is never written back as a bare setting - only the switch keeps +it in step with the live mode. Deviations are **leftovers**: logged in the run pane, kept in the result's `evidence` (`baseline.pre` / `baseline.post`), and surfaced in the page's message line - a leftover found before a run is attributed to the previous run; one diff --git a/docs/BRINGUP.md b/docs/BRINGUP.md index 362a9c5..ff0e091 100644 --- a/docs/BRINGUP.md +++ b/docs/BRINGUP.md @@ -3082,7 +3082,31 @@ dev image (the confirmation campaign's image).** `cloud.lid-during-button-wait`, `cloud.hunt-lid-open`, `cloud.pause-resume` (live). Items 4 and 12 above are superseded by this policy (the mid-job Door hold is no longer the default path); - close them with these tests. Still to observe once on the bench: the + close them with these tests. + Bench 2026-08-17 (dev image 20260817014132): `cloud.lid-abort` and + `cloud.lid-during-button-wait` PASSED; `cloud.hunt-lid-open` reported + FAIL for a harness defect - the hunt had completed with the lid open, + but the test then insisted on switching back to GRBL while the + service was still re-finding the head after the lid closed (`409 + machine is not idle`). Reworked: the cloud job tests now run **in + cloud mode and stay there** (`enter_cloud` reuses a live session, + pid-scoped from the client's own websocket lines; the switch is + made once from GRBL and declared to the baseline; `wait_quiet` + waits the service's follow-up moves out; the hunt test restarts the + cloud client through the supervisor's stop/start lever for a fresh + connect; every print is judged by its own `print [id]: finished` + line), the baseline is mode-aware (cloud mode owns its kernel + config, lamp, and counters; `controller_mode` is never restored as + a bare setting - that had desynced the persisted mode from the live + one), and the page has an **Ignore prerequisites** switch so any + test can be started alone. Proof: `tests/test_cloud_suite.py` (15 + cases, the four tests replayed on the bench's own gfcloud excerpts + + the run loop's pause/resume lines), baseline/server tests, and a + bench drill of `enter_cloud` (reuse) and of the fresh connect + + hunt detection + quiet wait against the live machine (hunt + `:completed`, 3 follow-up motions, quiet at 41 s). Left for the + operator: `cloud.hunt-lid-open` with the lid actually open, + `cloud.pause-resume` (live print + two presses). Still to observe once on the bench: the ~90 ms HV_ENABLE re-arm gap on a GRBL resume (whether a dark dwell lead is wanted), the app's rendering of `print:paused`, and a lid open during the return-to-start motion (should be ignored). diff --git a/forgetest/forgetest/baseline.py b/forgetest/forgetest/baseline.py index e2e164b..ce69759 100644 --- a/forgetest/forgetest/baseline.py +++ b/forgetest/forgetest/baseline.py @@ -16,6 +16,17 @@ restores it after (on every exit path), so a test cannot hand the next one The lid lamp is fixed too, at forgectrl's `lid_lamp_idle` setting (unset = 236): the daemon asserts it at start and at every controller spawn. +The controller mode in force decides what the baseline owns. In GRBL mode +everything above applies. In cloud mode the cloud client owns what it +configures for itself - the GRBL controller's init values (it writes its +own from each pulse header), the lid lamp (its lid-image level), and the +position counters (re-zeroed at every service action, so not a preserved +value) - and the baseline checks the rest: the safety readbacks, the +latch, the ring, the module defaults, the diagnostics tools, the cooling +engine. The mode itself is preserved: a run hands back the mode it +found, unless it declared a deliberate change (Context.mode_changed) - +the cloud tests enter cloud mode once and stay there. + Everything found off-baseline is a "leftover": logged, kept in the run's evidence, and surfaced on the page. The pre-run pass attributes leftovers to the previous run; the post-run pass attributes them to the run itself. @@ -53,6 +64,20 @@ FIXED_SYSFS = [ ("thermal/tec_on", "0"), ] +# The subset the GRBL controller writes at its start: checked and restored +# in GRBL mode only. The cloud client sets its own values for these from +# every pulse header (step_freq 10 kHz, the run currents) and hands the +# hold currents back at idle; forcing the GRBL values under it would be +# the baseline configuring another controller's machine. +GRBL_CONTROLLER_SYSFS = ("cnc/motor_lock", "cnc/x_mode", "cnc/y_mode", "cnc/x_decay", "cnc/y_decay", + "cnc/step_freq", "pic/x_step_current", "pic/y_step_current") + +# Settings the baseline never hands back as bare settings: controller_mode +# is the persisted mirror of the live mode (the mode item restores it +# through POST /mode, which keeps the two in step; a bare settings write +# would leave the runtime in one mode and the boot in the other). +UNPRESERVED_SETTINGS = ("controller_mode",) + # Read-only readbacks with their idle values (no direct restore: the state # comes right through forgectrl - see restore_forgectrl - or is fatal). IDLE_READBACKS = [ @@ -149,6 +174,7 @@ class Baseline: self.abort = abort or (lambda: False) self.captured = None self.forgectrl = None + self.mode = None # the controller mode in force (per enforce) def log(self, msg): self._log("baseline: " + msg) @@ -228,7 +254,8 @@ class Baseline: cap["sysfs"][attr] = hw.sysfs_read(attr) st, body = self.fc_get("/settings") if st == 200 and isinstance(body, dict): - cap["settings"] = {k: v for k, v in body.items() if isinstance(v, str)} + cap["settings"] = {k: v for k, v in body.items() + if isinstance(v, str) and k not in UNPRESERVED_SETTINGS} st, body = self.fc_get("/mode") if st == 200 and isinstance(body, dict): cap["mode"] = body.get("mode") @@ -241,7 +268,8 @@ class Baseline: phase is 'pre' or 'post' (log wording only). captured is the preserved state to hand back (post) - None compares nothing.""" left = [] - self._forgectrl_side(left) + self.mode = None + self._forgectrl_side(left, captured) self._kernel_side(left) self._lamp_side(left) self._preserved(left, captured) @@ -259,11 +287,15 @@ class Baseline: time.sleep(1.0) return None - def _forgectrl_side(self, left): + def cloud_mode(self): + return self.mode == "cloud" + + def _forgectrl_side(self, left, captured=None): st, mode = self.fc_get("/mode") if st != 200 or not isinstance(mode, dict): self.log("forgectrl not answering - service-side checks skipped") return + self.mode = mode.get("mode") # a diagnostic left running seizes the thermal hardware: abort it st, d = self.fc_get("/diag/status") if st == 200 and isinstance(d, dict) and d.get("running"): @@ -278,11 +310,14 @@ class Baseline: CAM_IDLE_S) if w is None: left.append(Leftover("cam.running", True, False, "failed: still running")) - # supervisor: the captured mode, controller running, motion verified - want = (self.captured or {}).get("mode") or mode.get("mode") or "grbl" + # supervisor: the mode the run found (or declared), controller + # running, motion verified. A mode the run changed without + # declaring it is handed back through the switch. + want = (captured or {}).get("mode") or mode.get("mode") or "grbl" if mode.get("mode") != want: st, body = self.fc_post("/mode", data={"controller": want}) mode = self.wait_settled() or mode + self.mode = mode.get("mode") left.append(Leftover("mode", mode.get("mode"), want, "restored" if mode.get("mode") == want else "failed: %s %s" % (st, body))) if mode.get("controller") == "motion-fault": @@ -336,7 +371,10 @@ class Baseline: "waited" if w is not None else "failed: still %s" % found)) def _lamp_side(self, left): - """The lid lamp at forgectrl's idle level (the lid_lamp_idle setting).""" + """The lid lamp at forgectrl's idle level (the lid_lamp_idle setting). + In cloud mode the cloud client owns the lamp (its lid-image level).""" + if self.cloud_mode(): + return st, body = self.fc_get("/settings") if st != 200 or not isinstance(body, dict): return @@ -373,6 +411,8 @@ class Baseline: left.append(Leftover("pulse ring", "%d unplayed bytes" % residue, "0 (nothing queued)", "unrestorable: the next run would replay them first")) for attr, want in FIXED_SYSFS: + if self.cloud_mode() and attr in GRBL_CONTROLLER_SYSFS: + continue got = hw.sysfs_read(attr) if got is None or got == want: continue @@ -461,9 +501,11 @@ class Baseline: except OSError as e: act = "failed: %s" % e left.append(Leftover(attr, now, was, act)) + # In cloud mode the counters are the cloud client's: every service + # action re-zeroes them at its start, so they preserve nothing. was = captured.get("position") now = read_position() - if was is not None and now is not None and now != was: + if was is not None and now is not None and now != was and not self.cloud_mode(): left.append(Leftover("position", now, was, self._return_head(was, now))) was = captured.get("settings") if was: diff --git a/forgetest/forgetest/page.py b/forgetest/forgetest/page.py index 4d5c1e5..2850261 100644 --- a/forgetest/forgetest/page.py +++ b/forgetest/forgetest/page.py @@ -63,6 +63,10 @@ pre#log{background:#1d1e26;color:#d7dae0;font-family:ui-monospace,Consolas,monos .err{color:var(--red);font-size:13px;margin:6px 0} .note{background:#fdf3e3;border:1px solid #eccb90;border-radius:6px;padding:8px 12px;margin:8px 0;font-size:13px} .ack{display:block;margin:8px 0;font-size:12.5px} +.switch{display:flex;align-items:center;gap:8px;margin:10px 0 0;font-size:13px} +.switch input{width:16px;height:16px;margin:0} +.switch .on{color:var(--warn);font-weight:600} +.req.over{color:var(--dim)} .grp{margin-top:6px} .tool .argrow{display:flex;gap:8px;flex-wrap:wrap;margin:6px 0} .tool .argrow label{font-size:12px;color:var(--dim)} @@ -89,7 +93,10 @@ pre#log{background:#1d1e26;color:#d7dae0;font-family:ui-monospace,Consolas,monos
-

A release is authorized when a campaign is open on this image and every catalog test is satisfied - by a PASS in the campaign, or (never for the core) by an earlier PASS whose domain fingerprint is unchanged. A FAIL ends the campaign. Invalidate-all forces a full campaign; give the reason.

+ +

A release is authorized when a campaign is open on this image and every catalog test is satisfied - by a PASS in the campaign, or (never for the core) by an earlier PASS whose domain fingerprint is unchanged. A FAIL ends the campaign. Invalidate-all forces a full campaign; give the reason. A test's requires list only orders the runs: with the switch above on, any test starts alone and its record notes which prerequisites were unmet - the release still needs every test satisfied.

@@ -114,7 +121,10 @@ pre#log{background:#1d1e26;color:#d7dae0;font-family:ui-monospace,Consolas,monos var TOKEN='__TOKEN__'; var state=null, catalog=null, catalogHash=null, bench=null, tab='acceptance', openDetails={}; var lastRunKey=null; +var ignoreReq=false;try{ignoreReq=window.localStorage.getItem('forgetest.ignoreReq')==='1'}catch(e){} function $(id){return document.getElementById(id)} +function setIgnoreReq(on){ignoreReq=!!on;try{window.localStorage.setItem('forgetest.ignoreReq',ignoreReq?'1':'0')}catch(e){} + $('ignreq').checked=ignoreReq;$('ignreqon').innerHTML=ignoreReq?"ON - prerequisites are not enforced":'';if(state&&catalog)renderGroups()} function esc(s){return String(s==null?'':s).replace(/[&<>"']/g,function(c){return {'&':'&','<':'<','>':'>','"':'"',"'":'''}[c]})} function api(method,path,body,cb){var x=new XMLHttpRequest();x.open(method,path,true);x.setRequestHeader('X-ForgeFIRM-Token',TOKEN); if(body!==undefined&&body!==null){x.setRequestHeader('Content-Type','application/json')} @@ -151,8 +161,10 @@ function renderGroups(){var groups={},order=[];catalog.forEach(function(t){if(!g if(s.required&&s.status!=='running')st+="
required: "+esc(s.reason)+""; var last=s.last?(esc(s.last.result)+' '+esc(fmtTs(s.last.ts))):'-'; if(s.status==='inherited'&&s.origin)last+="
from "+esc(s.origin.campaign)+" on "+esc(s.origin.image)+""; - var canStart=!busy&&s.requires_met!==false;var why=busy?'a run is in progress':(!s.requires_met?('needs: '+(s.missing_requires||[]).join(', ')):''); + var unmet=s.requires_met===false;var canStart=!busy&&(!unmet||ignoreReq); + var why=busy?'a run is in progress':(unmet?((ignoreReq?'prerequisites overridden - needs: ':'needs: ')+(s.missing_requires||[]).join(', ')):''); var startBtn=""; + if(unmet)startBtn+="
"+(ignoreReq?'unmet: ':'needs: ')+esc((s.missing_requires||[]).join(', '))+"
"; var det="
"+esc(t.description||'')+ (t.steps&&t.steps.length?"
Operator steps:
    "+t.steps.map(function(x){return '
  1. '+esc(x)+'
    2. '}).join('')+"
":'')+ "Requires: "+esc((t.requires||[]).join(', ')||'-')+"
Covers: "+esc((t.covers||[]).map(function(c){return c[0]+':'+c[1]}).join(', ')||'-')+ @@ -179,6 +191,7 @@ function renderRun(){var r=state.running||state.last_run;var key=r?(r.kind+':'+r var benchNeedsRefresh=false; function findTest(id){for(var i=0;i """ diff --git a/forgetest/forgetest/runner.py b/forgetest/forgetest/runner.py index 7f03d0f..8a586e6 100644 --- a/forgetest/forgetest/runner.py +++ b/forgetest/forgetest/runner.py @@ -203,6 +203,16 @@ class Context: self.log("position counters re-zeroed at the starting position; the baseline " "expects (0,0,0) at the end") + def mode_changed(self, mode): + """Declare a deliberate controller-mode change for the operator: + the run leaves the machine in `mode` and the baseline keeps it + there instead of switching back to the mode the run found (the + cloud tests enter cloud mode once and stay).""" + cap = self.run.baseline_captured + if cap is not None and cap.get("mode") != mode: + self.log("controller mode changed to %s for the operator; the baseline keeps it", mode) + cap["mode"] = mode + class Takeover: """Hardware takeover: the controller is stopped through the supervisor, @@ -391,7 +401,12 @@ class Runner: return art # -- starting ----------------------------------------------------------- - def start_test(self, test_id, ack_live=False): + def start_test(self, test_id, ack_live=False, ignore_requires=False): + """Start a test. `requires` gates the start unless the operator + set ignore_requires: the test then runs alone, and the run's + evidence records which prerequisites were unmet (the release gate + needs every test satisfied anyway, so nothing is hidden - the + record just says the order was the operator's).""" t = _catalog.get(test_id, self.registry) if t is None: return False, "unknown test" @@ -400,8 +415,9 @@ class Runner: return False, "a run is in progress" state, _ = self.state() ts = state["tests"][t.id] - if not ts["requires_met"]: - return False, "prerequisites not satisfied: %s" % ", ".join(ts["missing_requires"]) + missing = list(ts["missing_requires"]) + if missing and not ignore_requires: + return False, "prerequisites not satisfied: %s" % ", ".join(missing) if t.kind == "live" and not ack_live: return False, "live test: acknowledge eye protection, fire watch, and exhaust first" campaign = self._open_campaign_if_needed(state) @@ -409,6 +425,9 @@ class Runner: self.last = self.current self.current = run run.log("start %s (%s, %s) in campaign %s" % (t.id, t.kind, t.hardware, campaign["id"])) + if missing: + run.log("prerequisites overridden by the operator - not satisfied: %s" % ", ".join(missing)) + run.evidence["prerequisites"] = {"overridden": True, "missing": missing, "ts": now_ts()} if t.kind == "live": run.evidence["operator"] = {"ack_live": True, "ts": now_ts()} th = threading.Thread(target=self._exec_test, args=(t, run, campaign), daemon=True, diff --git a/forgetest/forgetest/server.py b/forgetest/forgetest/server.py index 6857bf0..07228a4 100644 --- a/forgetest/forgetest/server.py +++ b/forgetest/forgetest/server.py @@ -15,7 +15,7 @@ Routes GET /result?test&ts one full result record (log, evidence) GET /log the raw JSONL GET /export/acceptance.json | .md the last export - POST /start {test, ack_live} start an acceptance test + POST /start {test, ack_live, ignore_requires} start an acceptance test POST /bench/start {tool, args, ack_live} POST /answer {prompt_id, value} POST /abort @@ -219,7 +219,8 @@ class Handler(BaseHTTPRequestHandler): return try: if path == "/start": - ok, msg = r.start_test(str(body.get("test", "")), ack_live=bool(body.get("ack_live"))) + ok, msg = r.start_test(str(body.get("test", "")), ack_live=bool(body.get("ack_live")), + ignore_requires=bool(body.get("ignore_requires"))) self._send(200 if ok else 409, {"ok": ok, "message": msg}) elif path == "/bench/start": args = body.get("args") or {} diff --git a/forgetest/forgetest/suite/cloud.py b/forgetest/forgetest/suite/cloud.py index 5acef19..0c00f7d 100644 --- a/forgetest/forgetest/suite/cloud.py +++ b/forgetest/forgetest/suite/cloud.py @@ -1,5 +1,7 @@ """cloud.* - the controller mode switch and the optional Glowforge web-service -mode (gfcloud daemon, gfhome homing runner).""" +mode (gfcloud daemon, gfhome homing runner). The mode-switch test makes the +grbl -> cloud -> grbl round trip; the job-behavior tests run in cloud mode +and leave the machine there (see enter_cloud).""" import json import os import socket @@ -198,7 +200,7 @@ def mode_switch(ctx): @test("cloud.gfhome-homing", title="Glowforge web-service homing ($H with homing_mode=gfcloud)", subsystem="cloud", kind="operator", est_min=5, - covers=_CLOUD_COVERS + [("grblhal-glowforge", "src/**")], requires=["cloud.mode-switch"], + covers=_CLOUD_COVERS + [("grblhal-glowforge", "src/**")], requires=[], steps=["homing_mode = gfcloud and cloud credentials configured; bed clear, lid closed.", "Watch the gantry: the service drives it to the corner with camera corrections.", "The machine ends homed, the head parked at the home corner (the position " @@ -249,6 +251,24 @@ def gfhome_homing(ctx): # ---- lid / button behavior of a cloud job (the factory's) ------------------ +# +# These tests run IN cloud mode and stay there: enter_cloud() reuses a live +# cloud session when the machine is already in cloud mode (the operator +# switched once, on the panel or through an earlier test) and switches - +# once, declaring the change to the baseline - only when it finds GRBL +# mode. Nothing switches back; the operator does, when done. Each test +# judges the gfcloud log from its own window (the offset enter_cloud +# returns) and waits for the service's deferred moves (the re-hunt after a +# lid close, the hunt after a print) to finish before it ends, so the next +# run - or the operator - gets a quiet machine. + +WS_MARKS = ("RX-EVENT: ready", "RX-EVENT: closed", "RECONNECTING", "CLOSING") +ACTIVITY_MARKS = ("start motion", "start return home", "starting run", "starting z homing cycle") +LOG_TAIL_BYTES = 4 << 20 +QUIET_S = 8 # the re-hunt's motions are ~4 s apart (a lid image between them) +QUIET_TIMEOUT_S = 180 +HUNT_TIMEOUT_S = 180 + def log_lines_since(path, offset): """New gfcloud log lines since offset (each 'ISO-time gfcloud[pid] LEVEL where message').""" @@ -260,6 +280,12 @@ def log_lines_since(path, offset): return [] +def log_tail(path, max_bytes=LOG_TAIL_BYTES): + """The last max_bytes of the log, as lines (the first may be partial).""" + size = log_size(path) + return log_lines_since(path, max(0, size - max_bytes)) + + def line_time(line): """Seconds (float) from the log line's ISO timestamp, or None.""" try: @@ -296,47 +322,150 @@ def wait_log(ctx, offset, needles, timeout, poll=0.5): return found -def enter_cloud(ctx): - """Switch to the cloud controller and wait for its service session. - Returns (log offset at the switch, lid lamp level before).""" - fc = ctx.forgectrl - st, m0 = fc.get("/mode") - ctx.check(st == 200 and isinstance(m0, dict) and m0.get("mode") == "grbl", - "start this test in grbl mode (now %s)", m0) - lamp0 = hw.sysfs_read("pic/lid_led") - offset = log_size(GFCLOUD_LOG) - st, body = fc.post("/mode", data={"controller": "cloud"}) - ctx.check(st == 200, "mode switch to cloud refused: %s %s", st, body) - m = wait_mode(ctx, fc, "cloud", timeout=90) - ctx.check(m and m.get("mode") == "cloud" and m.get("controller") == "running", - "cloud controller did not come up: %s", m) +def action_finish_index(lines, action): + """Index of the first ' [id]: finished with event ...' line, or None.""" + return next((i for i, ln in enumerate(lines) + if (action + " [") in ln and "finished with event" in ln), None) + + +def wait_action_finished(ctx, offset, action, timeout, poll=0.5): + """The action's own terminal line (' [id]: finished with event + ":completed"' / '":cancelled"'), or None within timeout.""" t0 = time.time() + while time.time() - t0 < timeout: + ctx.checkpoint() + lines = log_lines_since(GFCLOUD_LOG, offset) + i = action_finish_index(lines, action) + if i is not None: + return lines[i] + time.sleep(poll) + return None + + +def message(line): + """The message part of a log line (after 'ISO-time gfcloud[pid]').""" + return line.split(" ", 2)[-1] if line else None + + +def session_live(pid): + """(live, detail): the running cloud client (gfcloud[pid]) has a live + service session when its last websocket state line is 'ready' - a + later 'closed'/'RECONNECTING'/'CLOSING' means it is not connected + now. Without any line for that pid the newest lines of the log stand + in (the client may log under a wrapper's pid).""" + tag = "gfcloud[%s]" % pid if pid else None + last_pid = last_any = None + for ln in log_tail(GFCLOUD_LOG): + for m in WS_MARKS: + if m in ln: + last_any = m + if tag and tag in ln: + last_pid = m + last = last_pid if last_pid is not None else last_any + where = "pid %s" % pid if last_pid is not None else "newest lines" + return last == "RX-EVENT: ready", "%s: last websocket state %s" % (where, last) + + +def wait_quiet(ctx, offset, quiet_s=None, timeout=None): + """The service's moves are over: the machine idle and no new service + activity in the log (a motion, a park, a run, a lens homing) for + quiet_s (default QUIET_S; timeout QUIET_TIMEOUT_S). False on timeout.""" + quiet_s = QUIET_S if quiet_s is None else quiet_s + timeout = QUIET_TIMEOUT_S if timeout is None else timeout + fc = ctx.forgectrl + t0 = time.time() + n_seen = -1 + last_change = t0 + while time.time() - t0 < timeout: + ctx.checkpoint() + lines = log_lines_since(GFCLOUD_LOG, offset) + n = sum(1 for ln in lines if any(m in ln for m in ACTIVITY_MARKS)) + if n != n_seen: + n_seen = n + last_change = time.time() + if fc.status().get("state") == "idle" and time.time() - last_change >= quiet_s: + return True + time.sleep(0.5) + return False + + +def wait_session(ctx, offset, timeout=120): session = [] - while time.time() - t0 < 120: + t0 = time.time() + while time.time() - t0 < timeout: ctx.checkpoint() session = session_lines(GFCLOUD_LOG, offset) if session_established(session): - break + return session time.sleep(2) - ctx.check(session_established(session), "the cloud client never established its service session") - ctx.log("cloud session established") - return offset, lamp0 + return session -def leave_cloud(ctx, lamp0): - """Back to grbl; the head returns to where the run found it.""" +def fresh_cloud_connect(ctx): + """A NEW cloud client with a fresh service session (its connect-time + hunt follows): in cloud mode the controller is restarted through the + supervisor's stop/start lever; in GRBL mode the mode is switched (and + the change declared - the machine stays in cloud mode). Returns the log + offset from before the connect, so the caller sees the whole session.""" fc = ctx.forgectrl - st, body = fc.post("/mode", data={"controller": "grbl"}) - ctx.check(st == 200, "mode switch back to grbl refused: %s %s", st, body) - m = wait_mode(ctx, fc, "grbl", timeout=120) - ctx.check(m and m.get("mode") == "grbl" and m.get("controller") == "running", - "grbl controller did not come back: %s", m) - ctx.sleep(3) - ctx.counters_rezeroed() - return_head(ctx) - lamp1 = hw.sysfs_read("pic/lid_led") - if lamp0 is not None and lamp1 != lamp0: - hw.sysfs_write("pic/lid_led", lamp0) + st, m = fc.get("/mode") + ctx.check(st == 200 and isinstance(m, dict), "GET /mode -> %s", st) + offset = log_size(GFCLOUD_LOG) + if m.get("mode") == "cloud": + ctx.log("cloud mode: restarting the cloud client for a fresh connect (was pid %s)", m.get("pid")) + st, body = fc.post("/controller/stop") + ctx.check(st == 200, "controller stop refused: %s %s", st, body) + m = wait_mode(ctx, fc, "cloud", want_controller="standby", timeout=30) + ctx.check(m and m.get("controller") == "standby", "the cloud client did not stop: %s", m) + st, body = fc.post("/controller/start") + ctx.check(st == 200, "controller start refused: %s %s", st, body) + else: + ctx.log("%s mode: switching to cloud", m.get("mode")) + st, body = fc.post("/mode", data={"controller": "cloud"}) + ctx.check(st == 200, "mode switch to cloud refused: %s %s", st, body) + m = wait_mode(ctx, fc, "cloud", timeout=90) + ctx.check(m and m.get("mode") == "cloud" and m.get("controller") == "running", + "cloud controller did not come up: %s", m) + ctx.mode_changed("cloud") + session = wait_session(ctx, offset) + ctx.check(session_established(session), + "the cloud client never established its service session (no credentials, no " + "network, or the service refused)") + ctx.log("cloud session established (pid %s)", m.get("pid")) + return offset + + +def enter_cloud(ctx): + """Cloud mode with a live service session and a quiet machine. An + existing cloud session is reused; from GRBL mode the switch is made + once (its connect-time hunt is waited out) and the machine stays in + cloud mode. Returns the log offset where the test's own window begins.""" + fc = ctx.forgectrl + st, m = fc.get("/mode") + ctx.check(st == 200 and isinstance(m, dict), "GET /mode -> %s", st) + if m.get("mode") == "cloud" and m.get("controller") == "running": + live, detail = session_live(m.get("pid")) + ctx.check(live, "cloud mode is up (pid %s) but the client has no live service session (%s) - " + "check credentials and network, or restart the controller", m.get("pid"), detail) + ctx.log("cloud mode already up (pid %s), service session live - reusing it", m.get("pid")) + offset = log_size(GFCLOUD_LOG) + else: + offset = fresh_cloud_connect(ctx) + hunt = wait_action_finished(ctx, offset, "hunt", HUNT_TIMEOUT_S) + ctx.check(hunt, "the service sent no connect-time hunt (or it never finished) within %d s", + HUNT_TIMEOUT_S) + ctx.log("connect-time hunt: %s", message(hunt)) + ctx.check(wait_quiet(ctx, offset), "the cloud client was still running service moves after %d s", + QUIET_TIMEOUT_S) + return log_size(GFCLOUD_LOG) + + +def settle_cloud(ctx, offset): + """End of a cloud test: the service's follow-up moves (a hunt after a + print, the re-hunt after a lid close) done and the machine idle.""" + ctx.check(wait_quiet(ctx, offset), "the service was still moving the head %d s after the test", + QUIET_TIMEOUT_S) + ctx.log("cloud mode stays up; the machine is quiet") def wait_print_running(ctx, offset, timeout): @@ -367,13 +496,14 @@ APP_PRINT_CUE = ("In the Glowforge app: scrap on the bed, lid closed, a SMALL en CANCELLED = 'finished with event ":cancelled"' COMPLETED = 'finished with event ":completed"' +CLOUD_STEP = ("Cloud credentials configured; the machine in cloud mode (the test switches once from " + "GRBL mode and stays in cloud mode; switch back on the panel when done).") @test("cloud.lid-abort", title="Lid open during a cloud print: stop, park with the lid open, cancelled", subsystem="cloud", kind="live", est_min=8, - covers=_CLOUD_COVERS, requires=["cloud.mode-switch", "laser.emission-witness"], - steps=["Cloud credentials configured; the app open in a browser; scrap on the bed and a small " - "engrave/score job ready.", + covers=_CLOUD_COVERS, requires=["laser.emission-witness"], + steps=[CLOUD_STEP, "The app open in a browser; scrap on the bed and a small engrave/score job ready.", "Print from the app and press the button when it lights; open the lid a few seconds " "into the run."], description="A cloud print aborted by the lid behaves as the factory's does: the edge " @@ -382,161 +512,158 @@ COMPLETED = 'finished with event ":completed"' "closes, and the job ends ':cancelled'.") def lid_abort(ctx): ev = ctx.evidence - offset, lamp0 = enter_cloud(ctx) - try: - ctx.instruct(APP_PRINT_CUE) - got = wait_print_running(ctx, offset, 300) - ctx.check(got, "the print never reached its run within 300 s (not started, or the button not pressed)") - ctx.instruct("The head is moving. Open the lid NOW, then click Done. Leave it open until the head " - "has returned to the corner.") - needles = ["lid opened", "lid opened mid-run; stopping motion", "start return home", - "return home complete", CANCELLED] - got = wait_log(ctx, offset, needles, 90) - ev["log"] = {k: (v.split(" ", 2)[-1] if v else None) for k, v in got.items()} - for k, v in got.items(): - ctx.log(" %s: %s", k, "seen" if v else "MISSING") - ctx.check(got["lid opened mid-run; stopping motion"], "the lid open did not stop the run") - # The lid edge that stopped the run is the LAST "lid opened" edge line - # before the stop line (an earlier open, e.g. to place the scrap, is - # not the one). - lines = log_lines_since(GFCLOUD_LOG, offset) - stop_i = next((i for i, ln in enumerate(lines) if "lid opened mid-run; stopping motion" in ln), None) - edge_line = None - if stop_i is not None: - edge_line = next((ln for ln in reversed(lines[:stop_i]) - if "_switch_event lid opened" in ln or ln.rstrip().endswith(" lid opened")), None) - t_edge = line_time(edge_line) if edge_line else None - t_stop = line_time(lines[stop_i]) if stop_i is not None else None - if t_edge is not None and t_stop is not None: - ev["edge_to_stop_ms"] = round((t_stop - t_edge) * 1000, 1) - ctx.log("lid edge -> stop: %s ms", ev["edge_to_stop_ms"]) - ctx.check(ev["edge_to_stop_ms"] < 60, "stop was not edge-driven (%s ms after the lid edge)", - ev["edge_to_stop_ms"]) - ctx.check(got["start return home"] and got["return home complete"], - "the park did not run to completion with the lid open") - # the machine, not the client: the job started at counters (0,0,0) - # (cloud clears them at every job start), so a completed park reads - # back there - stale ring bytes replayed ahead of the park would not - ctx.check(ctx.forgectrl.wait_idle(15, abort=ctx.aborted), "machine not idle after the park") - kpos = read_position() - ev["kernel_counters_after_park"] = kpos - ctx.log("kernel counters after the park: %s", kpos) - ctx.check(kpos is not None and abs(kpos[0]) <= 3 and abs(kpos[1]) <= 3, - "the head did not come back to the job start (kernel counters %s)", kpos) - ctx.check(got[CANCELLED], "the print did not end ':cancelled'") - st, cs = ctx.forgectrl.get("/cool/status") - ev["armed_after"] = cs.get("armed") if isinstance(cs, dict) else None - ev["latch_locked"] = latch_locked() - ctx.check(not ev["armed_after"], "armed window still open after the abort") - ctx.check(ev["latch_locked"], "kernel latch not locked after the abort") - ctx.confirm("Did the head stop as soon as the lid opened and go straight home with the lid " - "still open, and does the app show the print as cancelled?") - ctx.instruct("Close the lid, then click Done.") - ctx.sleep(3) - finally: - leave_cloud(ctx, lamp0) + offset = enter_cloud(ctx) + ctx.instruct(APP_PRINT_CUE) + got = wait_print_running(ctx, offset, 300) + ctx.check(got, "the print never reached its run within 300 s (not started, or the button not pressed)") + ctx.instruct("The head is moving. Open the lid NOW, then click Done. Leave it open until the head " + "has returned to the corner.") + needles = ["lid opened", "lid opened mid-run; stopping motion", "start return home", + "return home complete"] + got = wait_log(ctx, offset, needles, 90) + fin = wait_action_finished(ctx, offset, "print", 60) + got["print finished"] = fin + ev["log"] = {k: message(v) for k, v in got.items()} + for k, v in got.items(): + ctx.log(" %s: %s", k, "seen" if v else "MISSING") + ctx.check(got["lid opened mid-run; stopping motion"], "the lid open did not stop the run") + # The lid edge that stopped the run is the LAST "lid opened" edge line + # before the stop line (an earlier open, e.g. to place the scrap, is + # not the one). + lines = log_lines_since(GFCLOUD_LOG, offset) + stop_i = next((i for i, ln in enumerate(lines) if "lid opened mid-run; stopping motion" in ln), None) + edge_line = None + if stop_i is not None: + edge_line = next((ln for ln in reversed(lines[:stop_i]) + if "_switch_event lid opened" in ln or ln.rstrip().endswith(" lid opened")), None) + t_edge = line_time(edge_line) if edge_line else None + t_stop = line_time(lines[stop_i]) if stop_i is not None else None + if t_edge is not None and t_stop is not None: + ev["edge_to_stop_ms"] = round((t_stop - t_edge) * 1000, 1) + ctx.log("lid edge -> stop: %s ms", ev["edge_to_stop_ms"]) + ctx.check(ev["edge_to_stop_ms"] < 60, "stop was not edge-driven (%s ms after the lid edge)", + ev["edge_to_stop_ms"]) + ctx.check(got["start return home"] and got["return home complete"], + "the park did not run to completion with the lid open") + # the machine, not the client: the job started at counters (0,0,0) + # (cloud clears them at every job start), so a completed park reads + # back there - stale ring bytes replayed ahead of the park would not + ctx.check(ctx.forgectrl.wait_idle(15, abort=ctx.aborted), "machine not idle after the park") + kpos = read_position() + ev["kernel_counters_after_park"] = kpos + ctx.log("kernel counters after the park: %s", kpos) + ctx.check(kpos is not None and abs(kpos[0]) <= 3 and abs(kpos[1]) <= 3, + "the head did not come back to the job start (kernel counters %s)", kpos) + ctx.check(fin and CANCELLED in fin, "the print did not end ':cancelled': %s", + message(fin) or "no finish line") + st, cs = ctx.forgectrl.get("/cool/status") + ev["armed_after"] = cs.get("armed") if isinstance(cs, dict) else None + ev["latch_locked"] = latch_locked() + ctx.check(not ev["armed_after"], "armed window still open after the abort") + ctx.check(ev["latch_locked"], "kernel latch not locked after the abort") + ctx.confirm("Did the head stop as soon as the lid opened and go straight home with the lid " + "still open, and does the app show the print as cancelled?") + ctx.instruct("Close the lid, then click Done.") + settle_cloud(ctx, offset) ctx.log("PASS: lid open -> stop in %s ms, park completed with the lid open, ':cancelled'", ev.get("edge_to_stop_ms")) @test("cloud.lid-during-button-wait", title="Lid open at the cloud button prompt cancels the print", subsystem="cloud", kind="operator", est_min=6, - covers=_CLOUD_COVERS, requires=["cloud.mode-switch"], - steps=["Cloud credentials configured; the app open; any small job ready (nothing will fire).", + covers=_CLOUD_COVERS, requires=[], + steps=[CLOUD_STEP, "The app open; any small job ready (nothing will fire).", "Print from the app; when the button lights white, do NOT press it - open the lid."], description="A cloud print waiting for the button is cancelled by the lid: the wait ends " "with the lid named as the reason, the laser latch relocks, the armed window " "closes, no run starts, and the job ends ':cancelled'.") def lid_during_button_wait(ctx): ev = ctx.evidence - offset, lamp0 = enter_cloud(ctx) - try: - ctx.instruct("In the Glowforge app: lid closed, a small job set up. Click Done here, then press " - "Print in the app. When the button lights white, do NOT press it.") - got = wait_log(ctx, offset, ["waiting for button"], 300) - ctx.check(got["waiting for button"], "the print never reached the button wait") - ctx.instruct("The button is lit. Open the lid now (do not press the button), then click Done.") - needles = ["button wait lid opened - relocking the laser", CANCELLED] - got = wait_log(ctx, offset, needles, 60) - ev["log"] = {k: bool(v) for k, v in got.items()} - ctx.check(got["button wait lid opened - relocking the laser"], "the lid did not end the button wait") - ctx.check(got[CANCELLED], "the print did not end ':cancelled'") - # No run may start between the button wait and the cancel: the print - # itself, or a park (the head never moved, there is nothing to park). - # The connect-time hunt and the service's moves BEFORE the print are - # legitimate runs and are outside this window. - lines = log_lines_since(GFCLOUD_LOG, offset) - wait_i = next((i for i, ln in enumerate(lines) if "waiting for button" in ln), None) - end_i = next((i for i, ln in enumerate(lines) if wait_i is not None and i > wait_i and CANCELLED in ln), - len(lines)) - ran = ([ln for ln in lines[wait_i:end_i] if "starting run" in ln] - if wait_i is not None else []) - ev["runs_started_after_wait"] = len(ran) - ctx.check(not ran, "a run started after the lid-open cancel (%d)", len(ran)) - st, cs = ctx.forgectrl.get("/cool/status") - ev["armed_after"] = cs.get("armed") if isinstance(cs, dict) else None - ev["latch_locked"] = latch_locked() - ctx.check(not ev["armed_after"], "armed window still open after the cancel") - ctx.check(ev["latch_locked"], "kernel latch not locked after the cancel") - ctx.confirm("Did the button go dark when the lid opened, with no motion, and does the app show " - "the print as cancelled?") - ctx.instruct("Close the lid, then click Done.") - ctx.sleep(3) - finally: - leave_cloud(ctx, lamp0) + offset = enter_cloud(ctx) + ctx.instruct("In the Glowforge app: lid closed, a small job set up. Click Done here, then press " + "Print in the app. When the button lights white, do NOT press it.") + got = wait_log(ctx, offset, ["waiting for button"], 300) + ctx.check(got["waiting for button"], "the print never reached the button wait") + ctx.instruct("The button is lit. Open the lid now (do not press the button), then click Done.") + relock = "button wait lid opened - relocking the laser" + got = wait_log(ctx, offset, [relock], 60) + fin = wait_action_finished(ctx, offset, "print", 60) + ev["log"] = {relock: bool(got[relock]), "print finished": message(fin)} + ctx.check(got[relock], "the lid did not end the button wait") + ctx.check(fin and CANCELLED in fin, "the print did not end ':cancelled': %s", + message(fin) or "no finish line") + # No run may start between the button wait and the cancel: the print + # itself, or a park (the head never moved, there is nothing to park). + # The service's moves BEFORE the print are legitimate runs and are + # outside this window. + lines = log_lines_since(GFCLOUD_LOG, offset) + wait_i = next((i for i, ln in enumerate(lines) if "waiting for button" in ln), None) + end_i = action_finish_index(lines, "print") + if end_i is None or wait_i is None or end_i < wait_i: + end_i = len(lines) + ran = ([ln for ln in lines[wait_i:end_i] if "starting run" in ln] + if wait_i is not None else []) + ev["runs_started_after_wait"] = len(ran) + ctx.check(not ran, "a run started after the lid-open cancel (%d)", len(ran)) + st, cs = ctx.forgectrl.get("/cool/status") + ev["armed_after"] = cs.get("armed") if isinstance(cs, dict) else None + ev["latch_locked"] = latch_locked() + ctx.check(not ev["armed_after"], "armed window still open after the cancel") + ctx.check(ev["latch_locked"], "kernel latch not locked after the cancel") + ctx.confirm("Did the button go dark when the lid opened, with no motion, and does the app show " + "the print as cancelled?") + ctx.instruct("Close the lid, then click Done.") + settle_cloud(ctx, offset) ctx.log("PASS: lid open at the button prompt cancelled the print; latch locked, armed=false") @test("cloud.hunt-lid-open", title="A cloud hunt runs with the lid open", subsystem="cloud", kind="operator", est_min=5, - covers=_CLOUD_COVERS, requires=["cloud.mode-switch"], - steps=["Cloud credentials configured; bed clear.", - "Open the lid BEFORE the test switches to cloud mode and leave it open through the " - "connect-time hunt."], + covers=_CLOUD_COVERS + [("forgectrl", "src/super.c")], requires=[], + steps=[CLOUD_STEP, "Bed clear.", + "Open the lid when asked and leave it open through the connect-time hunt of the fresh " + "cloud client the test starts (in cloud mode the client is restarted; from GRBL mode " + "the switch is made)."], description="The service's connect-time hunt (lens homing plus its XY hunt) is not gated by " - "the lid: it runs and reports ':completed' with the lid open, as the factory's does.") + "the lid: it runs and reports ':completed' with the lid open, as the factory's does. " + "The service's moves after the lid closes again are waited out.") def hunt_lid_open(ctx): ev = ctx.evidence ctx.instruct("Open the lid and leave it open, then click Done.") sw = (ctx.forgectrl.status().get("switches") or {}) ev["lid_before"] = sw.get("lid") ctx.check(not sw.get("lid"), "the lid reads closed (%s)", sw) - offset, lamp0 = enter_cloud(ctx) - try: - # The hunt's own terminal line ("hunt [id]: finished with event ..."): - # it must be :completed, and no lid refusal may precede it. Service - # motions AFTER the hunt are rightly refused with the lid open and - # are outside this window. - hunt_line = None - t0 = time.time() - while time.time() - t0 < 180 and hunt_line is None: - ctx.checkpoint() - lines = log_lines_since(GFCLOUD_LOG, offset) - hunt_i = next((i for i, ln in enumerate(lines) if "hunt [" in ln and "finished with event" in ln), None) - if hunt_i is not None: - hunt_line = lines[hunt_i] - break - time.sleep(0.5) - ev["hunt_line"] = hunt_line.split(" ", 2)[-1] if hunt_line else None - ctx.check(hunt_line, "the service sent no hunt (or it never finished) within 180 s of the session") - refused = [ln for ln in lines[:hunt_i] if "unsafe to move" in ln] - ev["refusals_before_hunt_end"] = len(refused) - ctx.check(not refused, "the hunt was refused for the lid (%d 'unsafe to move')", len(refused)) - ctx.check(COMPLETED in hunt_line, "the hunt did not complete: %s", ev["hunt_line"]) - ctx.confirm("Did the lens home (Z motion) with the lid open, with no error in the app?") - ctx.instruct("Close the lid, then click Done.") - ctx.sleep(3) - finally: - leave_cloud(ctx, lamp0) - ctx.log("PASS: the connect-time hunt ran and completed with the lid open") + offset = fresh_cloud_connect(ctx) + # The hunt's own terminal line ("hunt [id]: finished with event ..."): + # it must be :completed, and no lid refusal may precede it. Service + # motions AFTER the hunt are rightly refused with the lid open and + # are outside this window. + hunt_line = wait_action_finished(ctx, offset, "hunt", HUNT_TIMEOUT_S) + ev["hunt_line"] = message(hunt_line) + ctx.check(hunt_line, "the service sent no hunt (or it never finished) within %d s of the session", + HUNT_TIMEOUT_S) + lines = log_lines_since(GFCLOUD_LOG, offset) + hunt_i = action_finish_index(lines, "hunt") + refused = [ln for ln in lines[:hunt_i] if "unsafe to move" in ln] + ev["refusals_before_hunt_end"] = len(refused) + ctx.check(not refused, "the hunt was refused for the lid (%d 'unsafe to move')", len(refused)) + ctx.check(COMPLETED in hunt_line, "the hunt did not complete: %s", ev["hunt_line"]) + ctx.log("hunt with the lid open: %s", ev["hunt_line"]) + ctx.confirm("Did the lens home (Z motion) with the lid open, with no error in the app?") + ctx.instruct("Close the lid, then click Done. (The service now re-finds the head: several " + "moves with lid images between them - the test waits them out.)") + settle_cloud(ctx, offset) + lines = log_lines_since(GFCLOUD_LOG, offset) + ev["motions_after_lid_close"] = sum(1 for ln in lines if "motion [" in ln and COMPLETED in ln) + ctx.log("PASS: the connect-time hunt ran and completed with the lid open; %d service motion(s) " + "completed after the lid closed", ev["motions_after_lid_close"]) @test("cloud.pause-resume", title="Button pauses and resumes a cloud print (factory backtrack + lead)", subsystem="cloud", kind="live", est_min=8, covers=_CLOUD_COVERS + [("forgectrl", "src/main.c")], - requires=["cloud.mode-switch", "laser.emission-witness"], - steps=["Cloud credentials configured; the app open; scrap on the bed and a small engrave/score " - "job (about 60 s) ready.", + requires=["laser.emission-witness"], + steps=[CLOUD_STEP, "The app open; scrap on the bed and a small engrave/score job (about 60 s) ready.", "Print from the app and press the button when it lights; a few seconds into the run " "press it again (pause), wait ~3 s, press again (resume); let the job finish."], description="Pressing the button during a cloud print pauses it the factory way - controlled " @@ -545,32 +672,33 @@ def hunt_lid_open(ctx): "latch stays unlocked and the armed window open through the pause.") def pause_resume(ctx): ev = ctx.evidence - offset, lamp0 = enter_cloud(ctx) - try: - ctx.instruct(APP_PRINT_CUE) - got = wait_print_running(ctx, offset, 300) - ctx.check(got, "the print never reached its run within 300 s (not started, or the button not pressed)") - ctx.instruct("The head is moving. Press the button once NOW (pause), watch the head stop and back up " - "a few millimeters, wait about 3 seconds, press it again (resume), then click Done.") - got = wait_log(ctx, offset, ["button pressed mid-run; pausing", "paused at", - "button pressed while paused; resuming"], 90) - ev["log"] = {k: bool(v) for k, v in got.items()} - ctx.check(got["button pressed mid-run; pausing"], "the press did not pause the run") - ctx.check(got["paused at"], "the pause did not settle (no 'paused at')") - ctx.check(got["button pressed while paused; resuming"], "the second press did not resume") - st, cs = ctx.forgectrl.get("/cool/status") - ev["armed_after_resume"] = cs.get("armed") if isinstance(cs, dict) else None - ctx.log("armed after the resume: %s", ev["armed_after_resume"]) - got = wait_log(ctx, offset, ["return home complete", COMPLETED], 300) - ev["log_end"] = {k: bool(v) for k, v in got.items()} - ctx.check(got[COMPLETED], "the print did not complete after the resume") - ctx.check(got["return home complete"], "the post-print park did not complete") - relocked = [ln for ln in log_lines_since(GFCLOUD_LOG, offset) - if "relocking the laser" in ln or CANCELLED in ln] - ev["relock_or_cancel_lines"] = len(relocked) - ctx.check(not relocked, "the pause relocked or cancelled the job (%s)", relocked[:2]) - ctx.confirm("Did the head stop and back up a few millimeters (laser off) on the first press, " - "resume on the second, and did the job finish and the app show it complete?") - finally: - leave_cloud(ctx, lamp0) + offset = enter_cloud(ctx) + ctx.instruct(APP_PRINT_CUE) + got = wait_print_running(ctx, offset, 300) + ctx.check(got, "the print never reached its run within 300 s (not started, or the button not pressed)") + ctx.instruct("The head is moving. Press the button once NOW (pause), watch the head stop and back up " + "a few millimeters, wait about 3 seconds, press it again (resume), then click Done.") + got = wait_log(ctx, offset, ["button pressed mid-run; pausing", "paused at", + "button pressed while paused; resuming"], 90) + ev["log"] = {k: bool(v) for k, v in got.items()} + ctx.check(got["button pressed mid-run; pausing"], "the press did not pause the run") + ctx.check(got["paused at"], "the pause did not settle (no 'paused at')") + ctx.check(got["button pressed while paused; resuming"], "the second press did not resume") + st, cs = ctx.forgectrl.get("/cool/status") + ev["armed_after_resume"] = cs.get("armed") if isinstance(cs, dict) else None + ctx.log("armed after the resume: %s", ev["armed_after_resume"]) + fin = wait_action_finished(ctx, offset, "print", 300) + got = wait_log(ctx, offset, ["return home complete"], 5) + ev["log_end"] = {"return home complete": bool(got["return home complete"]), + "print finished": message(fin)} + ctx.check(fin, "the print did not finish within 300 s of the resume") + ctx.check(COMPLETED in fin, "the print did not complete after the resume: %s", message(fin)) + ctx.check(got["return home complete"], "the post-print park did not complete") + relocked = [ln for ln in log_lines_since(GFCLOUD_LOG, offset) + if "relocking the laser" in ln or ("print [" in ln and CANCELLED in ln)] + ev["relock_or_cancel_lines"] = len(relocked) + ctx.check(not relocked, "the pause relocked or cancelled the job (%s)", relocked[:2]) + ctx.confirm("Did the head stop and back up a few millimeters (laser off) on the first press, " + "resume on the second, and did the job finish and the app show it complete?") + settle_cloud(ctx, offset) ctx.log("PASS: button pause/resume mid-print, job completed and parked") diff --git a/forgetest/tests/fixtures/gfcloud-buttonwait.log b/forgetest/tests/fixtures/gfcloud-buttonwait.log new file mode 100644 index 0000000..6e5456b --- /dev/null +++ b/forgetest/tests/fixtures/gfcloud-buttonwait.log @@ -0,0 +1,41 @@ +2026-08-17T09:44:00.417337+00:00 gfcloud[1927] INFO cnc:set_step_freq 28160 +2026-08-17T09:44:00.418627+00:00 gfcloud[1927] INFO cnc:set_x_decay 1 +2026-08-17T09:44:00.419858+00:00 gfcloud[1927] INFO cnc:set_x_mode 8 +2026-08-17T09:44:00.421083+00:00 gfcloud[1927] INFO cnc:set_x_current 135 +2026-08-17T09:44:00.422535+00:00 gfcloud[1927] INFO cnc:set_y_decay 1 +2026-08-17T09:44:00.423794+00:00 gfcloud[1927] INFO cnc:set_y_mode 8 +2026-08-17T09:44:00.425014+00:00 gfcloud[1927] INFO cnc:set_y_current 22 +2026-08-17T09:44:00.432591+00:00 gfcloud[1927] INFO machine:_run_loop starting run +2026-08-17T09:44:00.434005+00:00 gfcloud[1927] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:44:00.438277+00:00 gfcloud[1927] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:44:01.785230+00:00 gfcloud[1927] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:44:01.797728+00:00 gfcloud[1927] INFO machine:_run_loop finished run +2026-08-17T09:44:01.800661+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:01.808504+00:00 gfcloud[1927] INFO machine:_motion_locked end positions (actual/expected): X (-10313/-10313), Y (-649/-649), Z (0/0) +2026-08-17T09:44:01.809326+00:00 gfcloud[1927] INFO machine:_motion_locked motion bytes actual:34952, expected: 34952 +2026-08-17T09:44:01.810066+00:00 gfcloud[1927] INFO machine:_motion_locked start idle +2026-08-17T09:44:01.811352+00:00 gfcloud[1927] INFO cnc:set_x_current 33 +2026-08-17T09:44:01.812874+00:00 gfcloud[1927] INFO cnc:set_y_current 5 +2026-08-17T09:44:01.820631+00:00 gfcloud[1927] INFO machine:_motion_locked end positions (-10313, -649, 0) +2026-08-17T09:44:01.822062+00:00 gfcloud[1927] INFO machine:_motion end motion +2026-08-17T09:44:01.822829+00:00 gfcloud[1927] INFO basemachine:_finish_action motion [1576550614]: finished with event ":completed" +2026-08-17T09:44:01.824200+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:07.993647+00:00 gfcloud[1927] INFO gfuiservice:run service action request: print (ready) +2026-08-17T09:44:07.998655+00:00 gfcloud[1927] INFO machine:_motion start motion +2026-08-17T09:44:07.999643+00:00 gfcloud[1927] INFO gfuiservice:run print (ready) service action print +2026-08-17T09:44:14.199666+00:00 gfcloud[1927] INFO cnc:laser_latch 0 +2026-08-17T09:44:14.208291+00:00 gfcloud[1927] INFO machine:_button_wait waiting for button +2026-08-17T09:44:21.270846+00:00 gfcloud[1927] INFO machine:_switch_event lid opened +2026-08-17T09:44:21.275703+00:00 gfcloud[1927] WARNING machine:_button_wait button wait lid opened - relocking the laser +2026-08-17T09:44:21.278615+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:21.288305+00:00 gfcloud[1927] INFO machine:_return_home start return home +2026-08-17T09:44:21.291373+00:00 gfcloud[1927] INFO machine:_return_home return home: already at the job start +2026-08-17T09:44:21.292501+00:00 gfcloud[1927] INFO machine:_motion_locked start cool down +2026-08-17T09:44:21.305578+00:00 gfcloud[1927] INFO machine:_motion_locked start idle +2026-08-17T09:44:21.307322+00:00 gfcloud[1927] INFO cnc:set_x_current 33 +2026-08-17T09:44:21.309185+00:00 gfcloud[1927] INFO cnc:set_y_current 5 +2026-08-17T09:44:21.316340+00:00 gfcloud[1927] INFO machine:_motion_locked end positions (0, 0, 0) +2026-08-17T09:44:21.318139+00:00 gfcloud[1927] INFO machine:_motion end motion +2026-08-17T09:44:21.318860+00:00 gfcloud[1927] INFO basemachine:_finish_action print [1576550621]: finished with event ":cancelled" +2026-08-17T09:44:21.320214+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:34.058320+00:00 gfcloud[1927] INFO machine:_switch_event lid closed diff --git a/forgetest/tests/fixtures/gfcloud-huntlid.log b/forgetest/tests/fixtures/gfcloud-huntlid.log new file mode 100644 index 0000000..8378908 --- /dev/null +++ b/forgetest/tests/fixtures/gfcloud-huntlid.log @@ -0,0 +1,207 @@ +2026-08-17T09:44:35.789556+00:00 gfcloud[1927] INFO websocket:img_upload START +2026-08-17T09:44:36.105516+00:00 gfcloud[1927] INFO websocket:img_upload COMPLETE +2026-08-17T09:44:36.109421+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:38.461442+00:00 gfcloud[1927] INFO gfcloud:_shutdown shutdown requested +2026-08-17T09:44:38.910494+00:00 gfcloud[1927] INFO machine:_shutdown shutting down +2026-08-17T09:44:38.913049+00:00 gfcloud[1927] INFO cnc:laser_latch 1 +2026-08-17T09:44:38.950354+00:00 gfcloud[1927] INFO machine:_shutdown joining switch thread +2026-08-17T09:44:38.956909+00:00 gfcloud[1927] INFO machine:_shutdown shut down complete +2026-08-17T09:44:38.986287+00:00 gfcloud[1927] INFO websocket:_on_close RX-EVENT: closed (None, None) +2026-08-17T09:44:38.989003+00:00 gfcloud[1927] INFO websocket:run CLOSING +2026-08-17T09:44:38.992724+00:00 gfcloud[1927] INFO gfcloud:main gfcloud exit +2026-08-17T09:45:08.449553+00:00 gfcloud[2278] INFO gfuiservice:__init__ INITIALIZED +2026-08-17T09:45:08.451929+00:00 gfcloud[2278] INFO authentication:authenticate_machine START +2026-08-17T09:45:08.965893+00:00 gfcloud[2278] INFO authentication:authenticate_machine SUCCESS +2026-08-17T09:45:08.967947+00:00 gfcloud[2278] INFO websocket:ws_connect CONNECTING +2026-08-17T09:45:09.421918+00:00 gfcloud[2278] INFO _logging:info Websocket connected +2026-08-17T09:45:09.424224+00:00 gfcloud[2278] INFO websocket:_on_open RX-EVENT: ready +2026-08-17T09:45:09.973615+00:00 gfcloud[2278] INFO websocket:ws_connect ESTABLISHED +2026-08-17T09:45:09.994287+00:00 gfcloud[2278] INFO cnc:set_ignored_faults 0 +2026-08-17T09:45:09.996281+00:00 gfcloud[2278] INFO cnc:set_step_freq 10000 +2026-08-17T09:45:09.998803+00:00 gfcloud[2278] INFO cnc:set_x_mode Microstep.M_8 +2026-08-17T09:45:09.999688+00:00 gfcloud[2278] INFO cnc:set_y_mode Microstep.M_8 +2026-08-17T09:45:10.000483+00:00 gfcloud[2278] INFO cnc:set_x_decay 1 +2026-08-17T09:45:10.001229+00:00 gfcloud[2278] INFO cnc:set_y_decay 1 +2026-08-17T09:45:10.002000+00:00 gfcloud[2278] INFO cnc:set_x_current 33 +2026-08-17T09:45:10.007267+00:00 gfcloud[2278] INFO cnc:set_y_current 33 +2026-08-17T09:45:10.008695+00:00 gfcloud[2278] INFO z_axis:reset resetting z +2026-08-17T09:45:10.009124+00:00 gfcloud[2278] INFO z_axis:configure configuring z_enable: False, current: ZCur.LOW, mode: Microstep.HALF +2026-08-17T09:45:10.021592+00:00 gfcloud[2278] INFO gfuiservice:run service action request: settings (ready) +2026-08-17T09:45:10.024928+00:00 gfcloud[2278] INFO settings:send_report START +2026-08-17T09:45:10.039856+00:00 gfcloud[2278] INFO settings:send_report COMPLETE +2026-08-17T09:45:10.040650+00:00 gfcloud[2278] INFO gfuiservice:run settings (ready) service action dispatched +2026-08-17T09:45:10.591813+00:00 gfcloud[2278] INFO gfuiservice:run service action request: hunt (ready) +2026-08-17T09:45:10.596213+00:00 gfcloud[2278] INFO z_axis:home starting z homing cycle +2026-08-17T09:45:10.599109+00:00 gfcloud[2278] INFO gfuiservice:run hunt (ready) service action hunt +2026-08-17T09:45:10.600433+00:00 gfcloud[2278] INFO z_axis:configure configuring z_enable: True, current: ZCur.HIGH, mode: Microstep.FULL +2026-08-17T09:45:10.607559+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:11.160422+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:11.161195+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:11.714663+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:11.717907+00:00 gfcloud[2278] INFO z_axis:home pass: 1 +2026-08-17T09:45:11.719134+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:12.272747+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:12.274301+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:12.829585+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:12.831305+00:00 gfcloud[2278] INFO z_axis:home pass: 2 +2026-08-17T09:45:12.832786+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:13.385567+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:13.397106+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:13.947958+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:13.949754+00:00 gfcloud[2278] INFO z_axis:home pass: 3 +2026-08-17T09:45:13.951244+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:14.504840+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:14.506743+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:15.060854+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:15.062536+00:00 gfcloud[2278] INFO z_axis:home pass: 4 +2026-08-17T09:45:15.063941+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:15.617907+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:15.619505+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:16.175270+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:16.177421+00:00 gfcloud[2278] INFO z_axis:home pass: 5 +2026-08-17T09:45:16.179808+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:45:16.733698+00:00 gfcloud[2278] INFO z_axis:_step_until took -3 z_steps +2026-08-17T09:45:16.735355+00:00 gfcloud[2278] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:45:17.289377+00:00 gfcloud[2278] INFO z_axis:_step_until took 3 z_steps +2026-08-17T09:45:17.291109+00:00 gfcloud[2278] INFO z_axis:configure configuring z_enable: None, current: ZCur.LOW, mode: Microstep.HALF +2026-08-17T09:45:17.296301+00:00 gfcloud[2278] INFO z_axis:home homing cycle complete: [0, 0, 0, 0, 0] +2026-08-17T09:45:17.298209+00:00 gfcloud[2278] INFO machine:_motion start motion +2026-08-17T09:45:17.968494+00:00 gfcloud[2278] INFO cnc:set_step_freq 10000 +2026-08-17T09:45:17.969759+00:00 gfcloud[2278] INFO cnc:set_x_decay 1 +2026-08-17T09:45:17.970993+00:00 gfcloud[2278] INFO cnc:set_x_mode 8 +2026-08-17T09:45:17.972200+00:00 gfcloud[2278] INFO cnc:set_x_current 135 +2026-08-17T09:45:17.973616+00:00 gfcloud[2278] INFO cnc:set_y_decay 1 +2026-08-17T09:45:17.974870+00:00 gfcloud[2278] INFO cnc:set_y_mode 8 +2026-08-17T09:45:17.976077+00:00 gfcloud[2278] INFO cnc:set_y_current 22 +2026-08-17T09:45:17.983820+00:00 gfcloud[2278] INFO machine:_run_loop starting run +2026-08-17T09:45:17.985159+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:17.989360+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:45:19.630807+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:19.636283+00:00 gfcloud[2278] INFO machine:_run_loop finished run +2026-08-17T09:45:19.637979+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:19.651159+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (actual/expected): X (0/0), Y (0/0), Z (-4/-4) +2026-08-17T09:45:19.652103+00:00 gfcloud[2278] INFO machine:_motion_locked motion bytes actual:15874, expected: 15874 +2026-08-17T09:45:19.652852+00:00 gfcloud[2278] INFO machine:_motion_locked start idle +2026-08-17T09:45:19.653964+00:00 gfcloud[2278] INFO cnc:set_x_current 33 +2026-08-17T09:45:19.655305+00:00 gfcloud[2278] INFO cnc:set_y_current 5 +2026-08-17T09:45:19.664032+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (0, 0, -4) +2026-08-17T09:45:19.664853+00:00 gfcloud[2278] INFO machine:_motion end motion +2026-08-17T09:45:19.665575+00:00 gfcloud[2278] INFO basemachine:_finish_action hunt [1576550660]: finished with event ":completed" +2026-08-17T09:45:19.667114+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:20.027338+00:00 gfcloud[2278] INFO gfuiservice:run service action request: lid_image (ready) +2026-08-17T09:45:20.030024+00:00 gfcloud[2278] INFO ffmachine:_lid_image capturing Lid Image via forgectrl +2026-08-17T09:45:20.040337+00:00 gfcloud[2278] INFO gfuiservice:run lid_image (ready) service action dispatched +2026-08-17T09:45:21.195560+00:00 gfcloud[2278] INFO ffmachine:_lid_image uploading Lid Image +2026-08-17T09:45:21.196529+00:00 gfcloud[2278] INFO websocket:img_upload START +2026-08-17T09:45:21.721382+00:00 gfcloud[2278] INFO websocket:img_upload COMPLETE +2026-08-17T09:45:21.725394+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:23.732857+00:00 gfcloud[2278] INFO gfuiservice:run service action request: motion (ready) +2026-08-17T09:45:23.736044+00:00 gfcloud[2278] INFO machine:_motion start motion +2026-08-17T09:45:23.737995+00:00 gfcloud[2278] INFO gfuiservice:run motion (ready) service action motion +2026-08-17T09:45:23.738941+00:00 gfcloud[2278] INFO machine:_safe_to_move lid opened, unsafe to move +2026-08-17T09:45:23.739814+00:00 gfcloud[2278] INFO machine:_motion end motion +2026-08-17T09:45:23.740605+00:00 gfcloud[2278] INFO basemachine:_finish_action motion [1576550667]: finished with event ":cancelled" +2026-08-17T09:45:23.742169+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:42.629674+00:00 gfcloud[2278] INFO machine:_switch_event lid closed +2026-08-17T09:45:42.920194+00:00 gfcloud[2278] INFO gfuiservice:run service action request: lid_image (ready) +2026-08-17T09:45:42.924152+00:00 gfcloud[2278] INFO ffmachine:_lid_image capturing Lid Image via forgectrl +2026-08-17T09:45:42.927934+00:00 gfcloud[2278] INFO gfuiservice:run lid_image (ready) service action dispatched +2026-08-17T09:45:43.989152+00:00 gfcloud[2278] INFO ffmachine:_lid_image uploading Lid Image +2026-08-17T09:45:43.990022+00:00 gfcloud[2278] INFO websocket:img_upload START +2026-08-17T09:45:44.312060+00:00 gfcloud[2278] INFO websocket:img_upload COMPLETE +2026-08-17T09:45:44.315952+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:46.652633+00:00 gfcloud[2278] INFO gfuiservice:run service action request: motion (ready) +2026-08-17T09:45:46.654950+00:00 gfcloud[2278] INFO machine:_motion start motion +2026-08-17T09:45:46.657522+00:00 gfcloud[2278] INFO gfuiservice:run motion (ready) service action motion +2026-08-17T09:45:48.089456+00:00 gfcloud[2278] INFO cnc:set_step_freq 10000 +2026-08-17T09:45:48.090706+00:00 gfcloud[2278] INFO cnc:set_x_decay 1 +2026-08-17T09:45:48.091970+00:00 gfcloud[2278] INFO cnc:set_x_mode 8 +2026-08-17T09:45:48.093155+00:00 gfcloud[2278] INFO cnc:set_x_current 135 +2026-08-17T09:45:48.094587+00:00 gfcloud[2278] INFO cnc:set_y_decay 1 +2026-08-17T09:45:48.095866+00:00 gfcloud[2278] INFO cnc:set_y_mode 8 +2026-08-17T09:45:48.097182+00:00 gfcloud[2278] INFO cnc:set_y_current 22 +2026-08-17T09:45:48.104758+00:00 gfcloud[2278] INFO machine:_run_loop starting run +2026-08-17T09:45:48.106128+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:48.110477+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:45:50.393091+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:50.398748+00:00 gfcloud[2278] INFO machine:_run_loop finished run +2026-08-17T09:45:50.399629+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:50.423949+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (actual/expected): X (12939/12939), Y (7402/7402), Z (0/0) +2026-08-17T09:45:50.425534+00:00 gfcloud[2278] INFO machine:_motion_locked motion bytes actual:22740, expected: 22740 +2026-08-17T09:45:50.426258+00:00 gfcloud[2278] INFO machine:_motion_locked start idle +2026-08-17T09:45:50.427835+00:00 gfcloud[2278] INFO cnc:set_x_current 33 +2026-08-17T09:45:50.429387+00:00 gfcloud[2278] INFO cnc:set_y_current 5 +2026-08-17T09:45:50.437659+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (12939, 7402, 0) +2026-08-17T09:45:50.438474+00:00 gfcloud[2278] INFO machine:_motion end motion +2026-08-17T09:45:50.439167+00:00 gfcloud[2278] INFO basemachine:_finish_action motion [1576550679]: finished with event ":completed" +2026-08-17T09:45:50.440481+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:50.770056+00:00 gfcloud[2278] INFO gfuiservice:run service action request: lid_image (ready) +2026-08-17T09:45:50.772800+00:00 gfcloud[2278] INFO ffmachine:_lid_image capturing Lid Image via forgectrl +2026-08-17T09:45:50.782017+00:00 gfcloud[2278] INFO gfuiservice:run lid_image (ready) service action dispatched +2026-08-17T09:45:51.427848+00:00 gfcloud[2278] INFO ffmachine:_lid_image uploading Lid Image +2026-08-17T09:45:51.428456+00:00 gfcloud[2278] INFO websocket:img_upload START +2026-08-17T09:45:51.757479+00:00 gfcloud[2278] INFO websocket:img_upload COMPLETE +2026-08-17T09:45:51.760692+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:54.222123+00:00 gfcloud[2278] INFO gfuiservice:run service action request: motion (ready) +2026-08-17T09:45:54.224786+00:00 gfcloud[2278] INFO machine:_motion start motion +2026-08-17T09:45:54.226855+00:00 gfcloud[2278] INFO gfuiservice:run motion (ready) service action motion +2026-08-17T09:45:54.557705+00:00 gfcloud[2278] INFO cnc:set_step_freq 10000 +2026-08-17T09:45:54.562210+00:00 gfcloud[2278] INFO cnc:set_x_decay 1 +2026-08-17T09:45:54.571212+00:00 gfcloud[2278] INFO cnc:set_x_mode 8 +2026-08-17T09:45:54.573373+00:00 gfcloud[2278] INFO cnc:set_x_current 135 +2026-08-17T09:45:54.596668+00:00 gfcloud[2278] INFO cnc:set_y_decay 1 +2026-08-17T09:45:54.597612+00:00 gfcloud[2278] INFO cnc:set_y_mode 8 +2026-08-17T09:45:54.598479+00:00 gfcloud[2278] INFO cnc:set_y_current 22 +2026-08-17T09:45:54.622488+00:00 gfcloud[2278] INFO machine:_run_loop starting run +2026-08-17T09:45:54.624223+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:54.629307+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:45:54.835600+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:45:54.838848+00:00 gfcloud[2278] INFO machine:_run_loop finished run +2026-08-17T09:45:54.839726+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:54.849011+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (actual/expected): X (159/159), Y (5/5), Z (0/0) +2026-08-17T09:45:54.849946+00:00 gfcloud[2278] INFO machine:_motion_locked motion bytes actual:1222, expected: 1222 +2026-08-17T09:45:54.850790+00:00 gfcloud[2278] INFO machine:_motion_locked start idle +2026-08-17T09:45:54.852317+00:00 gfcloud[2278] INFO cnc:set_x_current 33 +2026-08-17T09:45:54.854073+00:00 gfcloud[2278] INFO cnc:set_y_current 5 +2026-08-17T09:45:54.880450+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (159, 5, 0) +2026-08-17T09:45:54.881925+00:00 gfcloud[2278] INFO machine:_motion end motion +2026-08-17T09:45:54.882641+00:00 gfcloud[2278] INFO basemachine:_finish_action motion [1576550683]: finished with event ":completed" +2026-08-17T09:45:54.884500+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:55.137070+00:00 gfcloud[2278] INFO gfuiservice:run service action request: lid_image (ready) +2026-08-17T09:45:55.139449+00:00 gfcloud[2278] INFO ffmachine:_lid_image capturing Lid Image via forgectrl +2026-08-17T09:45:55.142346+00:00 gfcloud[2278] INFO gfuiservice:run lid_image (ready) service action dispatched +2026-08-17T09:45:55.809276+00:00 gfcloud[2278] INFO ffmachine:_lid_image uploading Lid Image +2026-08-17T09:45:55.810155+00:00 gfcloud[2278] INFO websocket:img_upload START +2026-08-17T09:45:56.158888+00:00 gfcloud[2278] INFO websocket:img_upload COMPLETE +2026-08-17T09:45:56.162644+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:45:58.467590+00:00 gfcloud[2278] INFO gfuiservice:run service action request: motion (ready) +2026-08-17T09:45:58.469426+00:00 gfcloud[2278] INFO machine:_motion start motion +2026-08-17T09:45:58.471091+00:00 gfcloud[2278] INFO gfuiservice:run motion (ready) service action motion +2026-08-17T09:46:00.721960+00:00 gfcloud[2278] INFO cnc:set_step_freq 28160 +2026-08-17T09:46:00.725688+00:00 gfcloud[2278] INFO cnc:set_x_decay 1 +2026-08-17T09:46:00.727477+00:00 gfcloud[2278] INFO cnc:set_x_mode 8 +2026-08-17T09:46:00.728738+00:00 gfcloud[2278] INFO cnc:set_x_current 135 +2026-08-17T09:46:00.730198+00:00 gfcloud[2278] INFO cnc:set_y_decay 1 +2026-08-17T09:46:00.731506+00:00 gfcloud[2278] INFO cnc:set_y_mode 8 +2026-08-17T09:46:00.732735+00:00 gfcloud[2278] INFO cnc:set_y_current 22 +2026-08-17T09:46:00.740459+00:00 gfcloud[2278] INFO machine:_run_loop starting run +2026-08-17T09:46:00.741865+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:46:00.745983+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:46:02.491897+00:00 gfcloud[2278] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:46:02.494137+00:00 gfcloud[2278] INFO machine:_run_loop finished run +2026-08-17T09:46:02.495155+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:46:02.530565+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (actual/expected): X (-13096/-13096), Y (-7400/-7400), Z (0/0) +2026-08-17T09:46:02.531413+00:00 gfcloud[2278] INFO machine:_motion_locked motion bytes actual:47243, expected: 47243 +2026-08-17T09:46:02.538168+00:00 gfcloud[2278] INFO machine:_motion_locked start idle +2026-08-17T09:46:02.539603+00:00 gfcloud[2278] INFO cnc:set_x_current 33 +2026-08-17T09:46:02.541147+00:00 gfcloud[2278] INFO cnc:set_y_current 5 +2026-08-17T09:46:02.549578+00:00 gfcloud[2278] INFO machine:_motion_locked end positions (-13096, -7400, 0) +2026-08-17T09:46:02.550385+00:00 gfcloud[2278] INFO machine:_motion end motion +2026-08-17T09:46:02.551153+00:00 gfcloud[2278] INFO basemachine:_finish_action motion [1576550685]: finished with event ":completed" +2026-08-17T09:46:02.552496+00:00 gfcloud[2278] INFO cnc:laser_latch 1 +2026-08-17T09:46:03.007623+00:00 gfcloud[2278] INFO gfuiservice:run service action request: lid_image (ready) +2026-08-17T09:46:03.009488+00:00 gfcloud[2278] INFO ffmachine:_lid_image capturing Lid Image via forgectrl +2026-08-17T09:46:03.037155+00:00 gfcloud[2278] INFO gfuiservice:run lid_image (ready) service action dispatched +2026-08-17T09:46:03.758520+00:00 gfcloud[2278] INFO ffmachine:_lid_image uploading Lid Image +2026-08-17T09:46:03.760049+00:00 gfcloud[2278] INFO websocket:img_upload START +2026-08-17T09:46:04.128126+00:00 gfcloud[2278] INFO websocket:img_upload COMPLETE diff --git a/forgetest/tests/fixtures/gfcloud-lidabort.log b/forgetest/tests/fixtures/gfcloud-lidabort.log new file mode 100644 index 0000000..c88ffd6 --- /dev/null +++ b/forgetest/tests/fixtures/gfcloud-lidabort.log @@ -0,0 +1,72 @@ +2026-08-17T09:42:09.781500+00:00 gfcloud[1522] INFO gfuiservice:run motion (ready) service action motion +2026-08-17T09:42:11.281337+00:00 gfcloud[1522] INFO cnc:set_step_freq 28160 +2026-08-17T09:42:11.282627+00:00 gfcloud[1522] INFO cnc:set_x_decay 1 +2026-08-17T09:42:11.283850+00:00 gfcloud[1522] INFO cnc:set_x_mode 8 +2026-08-17T09:42:11.285121+00:00 gfcloud[1522] INFO cnc:set_x_current 135 +2026-08-17T09:42:11.286711+00:00 gfcloud[1522] INFO cnc:set_y_decay 1 +2026-08-17T09:42:11.287977+00:00 gfcloud[1522] INFO cnc:set_y_mode 8 +2026-08-17T09:42:11.289235+00:00 gfcloud[1522] INFO cnc:set_y_current 22 +2026-08-17T09:42:11.297425+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:42:11.299141+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:11.303264+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:42:12.560917+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:12.572022+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:42:12.572811+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:42:12.580801+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (actual/expected): X (-10313/-10313), Y (-649/-649), Z (0/0) +2026-08-17T09:42:12.581620+00:00 gfcloud[1522] INFO machine:_motion_locked motion bytes actual:34952, expected: 34952 +2026-08-17T09:42:12.582366+00:00 gfcloud[1522] INFO machine:_motion_locked start idle +2026-08-17T09:42:12.583540+00:00 gfcloud[1522] INFO cnc:set_x_current 33 +2026-08-17T09:42:12.584928+00:00 gfcloud[1522] INFO cnc:set_y_current 5 +2026-08-17T09:42:12.593681+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (-10313, -649, 0) +2026-08-17T09:42:12.604394+00:00 gfcloud[1522] INFO machine:_motion end motion +2026-08-17T09:42:12.604757+00:00 gfcloud[1522] INFO basemachine:_finish_action motion [1576550503]: finished with event ":completed" +2026-08-17T09:42:12.605824+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:42:15.672518+00:00 gfcloud[1522] INFO gfuiservice:run service action request: print (ready) +2026-08-17T09:42:15.676330+00:00 gfcloud[1522] INFO machine:_motion start motion +2026-08-17T09:42:15.680419+00:00 gfcloud[1522] INFO gfuiservice:run print (ready) service action print +2026-08-17T09:42:21.975587+00:00 gfcloud[1522] INFO cnc:laser_latch 0 +2026-08-17T09:42:22.001354+00:00 gfcloud[1522] INFO machine:_button_wait waiting for button +2026-08-17T09:42:24.774117+00:00 gfcloud[1522] INFO machine:_switch_event button pushed +2026-08-17T09:42:24.778509+00:00 gfcloud[1522] INFO cnc:set_step_freq 10000 +2026-08-17T09:42:24.781114+00:00 gfcloud[1522] INFO cnc:set_x_decay 1 +2026-08-17T09:42:24.783654+00:00 gfcloud[1522] INFO cnc:set_x_mode 8 +2026-08-17T09:42:24.786180+00:00 gfcloud[1522] INFO cnc:set_x_current 135 +2026-08-17T09:42:24.789088+00:00 gfcloud[1522] INFO cnc:set_y_decay 1 +2026-08-17T09:42:24.791559+00:00 gfcloud[1522] INFO cnc:set_y_mode 8 +2026-08-17T09:42:24.794380+00:00 gfcloud[1522] INFO cnc:set_y_current 22 +2026-08-17T09:42:24.815263+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:42:24.816687+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:24.820823+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:42:25.049489+00:00 gfcloud[1522] INFO machine:_switch_event button released +2026-08-17T09:42:30.832527+00:00 gfcloud[1522] INFO machine:_switch_event lid opened +2026-08-17T09:42:30.838627+00:00 gfcloud[1522] WARNING machine:_run_loop lid opened mid-run; stopping motion +2026-08-17T09:42:30.941553+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:30.947477+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:42:30.949099+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:42:30.964916+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (actual/expected): X (8454/7573), Y (684/684), Z (3/3) +2026-08-17T09:42:30.965704+00:00 gfcloud[1522] INFO machine:_motion_locked motion bytes actual:60649, expected: 238043 +2026-08-17T09:42:30.972180+00:00 gfcloud[1522] INFO machine:_return_home start return home +2026-08-17T09:42:31.847247+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:42:31.848617+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:31.852977+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:42:36.970521+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:36.976059+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:42:36.977738+00:00 gfcloud[1522] INFO machine:_return_home return home complete +2026-08-17T09:42:36.979696+00:00 gfcloud[1522] INFO machine:_motion_locked start cool down +2026-08-17T09:42:36.998973+00:00 gfcloud[1522] INFO machine:_motion_locked start idle +2026-08-17T09:42:37.000314+00:00 gfcloud[1522] INFO cnc:set_x_current 33 +2026-08-17T09:42:37.001774+00:00 gfcloud[1522] INFO cnc:set_y_current 5 +2026-08-17T09:42:37.010089+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (0, 0, 3) +2026-08-17T09:42:37.010885+00:00 gfcloud[1522] INFO machine:_motion end motion +2026-08-17T09:42:37.011563+00:00 gfcloud[1522] INFO basemachine:_finish_action print [1576550507]: finished with event ":cancelled" +2026-08-17T09:42:37.013071+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:42:37.449180+00:00 gfcloud[1522] INFO gfuiservice:run service action request: hunt (ready) +2026-08-17T09:42:37.451286+00:00 gfcloud[1522] INFO z_axis:home starting z homing cycle +2026-08-17T09:42:37.452782+00:00 gfcloud[1522] INFO gfuiservice:run hunt (ready) service action hunt +2026-08-17T09:42:37.453691+00:00 gfcloud[1522] INFO z_axis:configure configuring z_enable: True, current: ZCur.HIGH, mode: Microstep.FULL +2026-08-17T09:42:37.458283+00:00 gfcloud[1522] INFO z_axis:_step_until starting z_step until at_home: False +2026-08-17T09:42:37.827610+00:00 gfcloud[1522] INFO z_axis:_step_until took -2 z_steps +2026-08-17T09:42:37.829278+00:00 gfcloud[1522] INFO z_axis:_step_until starting z_step until at_home: True +2026-08-17T09:42:38.200493+00:00 gfcloud[1522] INFO z_axis:_step_until took 2 z_steps +2026-08-17T09:42:38.202234+00:00 gfcloud[1522] INFO z_axis:home pass: 1 +2026-08-17T09:42:38.203788+00:00 gfcloud[1522] INFO z_axis:_step_until starting z_step until at_home: False diff --git a/forgetest/tests/fixtures/gfcloud-pause.log b/forgetest/tests/fixtures/gfcloud-pause.log new file mode 100644 index 0000000..c29caaf --- /dev/null +++ b/forgetest/tests/fixtures/gfcloud-pause.log @@ -0,0 +1,53 @@ +2026-08-17T09:42:15.672518+00:00 gfcloud[1522] INFO gfuiservice:run service action request: print (ready) +2026-08-17T09:42:15.676330+00:00 gfcloud[1522] INFO machine:_motion start motion +2026-08-17T09:42:15.680419+00:00 gfcloud[1522] INFO gfuiservice:run print (ready) service action print +2026-08-17T09:42:21.975587+00:00 gfcloud[1522] INFO cnc:laser_latch 0 +2026-08-17T09:42:22.001354+00:00 gfcloud[1522] INFO machine:_button_wait waiting for button +2026-08-17T09:42:24.774117+00:00 gfcloud[1522] INFO machine:_switch_event button pushed +2026-08-17T09:42:24.778509+00:00 gfcloud[1522] INFO cnc:set_step_freq 10000 +2026-08-17T09:42:24.781114+00:00 gfcloud[1522] INFO cnc:set_x_decay 1 +2026-08-17T09:42:24.783654+00:00 gfcloud[1522] INFO cnc:set_x_mode 8 +2026-08-17T09:42:24.786180+00:00 gfcloud[1522] INFO cnc:set_x_current 135 +2026-08-17T09:42:24.789088+00:00 gfcloud[1522] INFO cnc:set_y_decay 1 +2026-08-17T09:42:24.791559+00:00 gfcloud[1522] INFO cnc:set_y_mode 8 +2026-08-17T09:42:24.794380+00:00 gfcloud[1522] INFO cnc:set_y_current 22 +2026-08-17T09:42:24.815263+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:42:24.816687+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:24.820823+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:42:25.049489+00:00 gfcloud[1522] INFO machine:_switch_event button released +2026-08-17T09:42:31.104201+00:00 gfcloud[1522] INFO machine:_switch_event button pushed +2026-08-17T09:42:31.106877+00:00 gfcloud[1522] INFO machine:_run_loop button pressed mid-run; pausing +2026-08-17T09:42:31.288114+00:00 gfcloud[1522] INFO machine:_switch_event button released +2026-08-17T09:42:31.612040+00:00 gfcloud[1522] INFO machine:_run_loop paused at Position(x=AxisPosition(steps=1210, mm=22.68, inch=0.89), y=AxisPosition(steps=402, mm=7.54, inch=0.30), z=AxisPosition(steps=3, mm=0.0, inch=0.0), bytes=PulsPosition(total=238043, processed=61200)) +2026-08-17T09:42:34.702311+00:00 gfcloud[1522] INFO machine:_switch_event button pushed +2026-08-17T09:42:34.704560+00:00 gfcloud[1522] INFO machine:_run_loop button pressed while paused; resuming (laser lead 1950 ticks) +2026-08-17T09:42:34.901002+00:00 gfcloud[1522] INFO machine:_switch_event button released +2026-08-17T09:42:58.130807+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:58.136283+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:42:58.137979+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:42:58.151159+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (actual/expected): X (7573/7573), Y (684/684), Z (3/3) +2026-08-17T09:42:58.152103+00:00 gfcloud[1522] INFO machine:_motion_locked motion bytes actual:238043, expected: 238043 +2026-08-17T09:42:58.160180+00:00 gfcloud[1522] INFO machine:_return_home start return home +2026-08-17T09:42:59.047247+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:42:59.048617+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:42:59.052977+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.RUNNING +2026-08-17T09:43:04.170521+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:43:04.176059+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:43:04.177738+00:00 gfcloud[1522] INFO machine:_return_home return home complete +2026-08-17T09:43:04.179696+00:00 gfcloud[1522] INFO machine:_motion_locked start cool down +2026-08-17T09:43:04.198973+00:00 gfcloud[1522] INFO machine:_motion_locked start idle +2026-08-17T09:43:04.200314+00:00 gfcloud[1522] INFO cnc:set_x_current 33 +2026-08-17T09:43:04.201774+00:00 gfcloud[1522] INFO cnc:set_y_current 5 +2026-08-17T09:43:04.210089+00:00 gfcloud[1522] INFO machine:_motion_locked end positions (0, 0, 3) +2026-08-17T09:43:04.210885+00:00 gfcloud[1522] INFO machine:_motion end motion +2026-08-17T09:43:04.211563+00:00 gfcloud[1522] INFO basemachine:_finish_action print [1576550507]: finished with event ":completed" +2026-08-17T09:43:04.213071+00:00 gfcloud[1522] INFO cnc:laser_latch 1 +2026-08-17T09:43:04.649180+00:00 gfcloud[1522] INFO gfuiservice:run service action request: hunt (ready) +2026-08-17T09:43:04.651286+00:00 gfcloud[1522] INFO z_axis:home starting z homing cycle +2026-08-17T09:43:04.652782+00:00 gfcloud[1522] INFO gfuiservice:run hunt (ready) service action hunt +2026-08-17T09:43:11.298209+00:00 gfcloud[1522] INFO machine:_motion start motion +2026-08-17T09:43:11.983820+00:00 gfcloud[1522] INFO machine:_run_loop starting run +2026-08-17T09:43:13.630807+00:00 gfcloud[1522] INFO machine:_run_loop current state: MachineState.IDLE +2026-08-17T09:43:13.636283+00:00 gfcloud[1522] INFO machine:_run_loop finished run +2026-08-17T09:43:13.664853+00:00 gfcloud[1522] INFO machine:_motion end motion +2026-08-17T09:43:13.665575+00:00 gfcloud[1522] INFO basemachine:_finish_action hunt [1576550560]: finished with event ":completed" diff --git a/forgetest/tests/helpers.py b/forgetest/tests/helpers.py index 423a7c3..e81def5 100644 --- a/forgetest/tests/helpers.py +++ b/forgetest/tests/helpers.py @@ -76,3 +76,89 @@ def make_test(id, covers, always=False, requires=(), kind="auto", fn=None, subsy def registry(*tests): return {t.id: t for t in tests} + + +# ------------------------------------------------------- fake forgectrl + +class FakeForgectrl: + """A stand-in for the machine-services daemon on localhost: canned + JSON for the endpoints the suite reads, a mutable `state` the test + scripts, every POST recorded, and an optional `on_post(path, form)` + hook returning (status, body) to script the daemon's reactions. + Point the suite at it with FORGECTRL_URL (see start/stop).""" + + def __init__(self): + import http.server + import json as _json + import threading as _threading + import urllib.parse as _up + self.state = { + "mode": {"mode": "grbl", "controller": "running", "pid": 100, "motion": "verified"}, + "status": {"state": "idle", "homed": False, "diag": False, "laser_locked": True, + "pos": {"x": 0.0, "y": 0.0, "z": 0.0}, + "switches": {"lid": True, "button": False, "interlock_ok": True, + "head": True, "hv_enable": False}}, + "cool": {"phase": "idle", "armed": False, "hold": False}, + "cam": {"running": False, "clients": 0}, + "diag": {"running": False}, + "settings": {"controller_mode": "grbl", "lid_lamp_idle": ""}, + } + self.posts = [] + self.on_post = None + fake = self + + class H(http.server.BaseHTTPRequestHandler): + def log_message(self, *a): + pass + + def _send(self, st, body): + data = _json.dumps(body).encode() + self.send_response(st) + self.send_header("Content-Type", "application/json") + self.send_header("Content-Length", str(len(data))) + self.end_headers() + self.wfile.write(data) + + def do_GET(self): + path = self.path.split("?", 1)[0] + key = {"/mode": "mode", "/status": "status", "/cool/status": "cool", "/cam/status": "cam", + "/diag/status": "diag", "/settings": "settings"}.get(path) + if key is None: + return self._send(404, {"error": "no " + path}) + self._send(200, fake.state[key]) + + def do_POST(self): + path, _, query = self.path.partition("?") + n = int(self.headers.get("Content-Length") or 0) + raw = self.rfile.read(n).decode() if n else "" + form = dict(_up.parse_qsl(raw)) if raw else dict(_up.parse_qsl(query)) + fake.posts.append((path, form)) + if fake.on_post: + r = fake.on_post(path, form) + if r is not None: + return self._send(*r) + if path == "/mode" and form.get("controller"): + fake.state["mode"] = dict(fake.state["mode"], mode=form["controller"], controller="running", + pid=fake.state["mode"].get("pid", 0) + 1) + fake.state["settings"]["controller_mode"] = form["controller"] + elif path == "/settings": + fake.state["settings"].update(form) + self._send(200, {"ok": True}) + + self._srv = http.server.ThreadingHTTPServer(("127.0.0.1", 0), H) + self._srv.daemon_threads = True + self._srv.block_on_close = False # never wait on a lingering connection + self.url = "http://127.0.0.1:%d" % self._srv.server_address[1] + self._th = _threading.Thread(target=self._srv.serve_forever, daemon=True) + + def start(self): + self._th.start() + os.environ["FORGECTRL_URL"] = self.url + os.environ["FORGECTRL_TOKEN_FILE"] = os.devnull + return self + + def stop(self): + self._srv.shutdown() + self._srv.server_close() + os.environ.pop("FORGECTRL_URL", None) + os.environ.pop("FORGECTRL_TOKEN_FILE", None) diff --git a/forgetest/tests/test_baseline.py b/forgetest/tests/test_baseline.py index 302517c..f57556d 100644 --- a/forgetest/tests/test_baseline.py +++ b/forgetest/tests/test_baseline.py @@ -266,3 +266,95 @@ class BaselineTests(unittest.TestCase): if __name__ == "__main__": unittest.main() + + +class BaselineModeTests(BaselineTests): + """The baseline against a fake forgectrl: what the mode in force + owns. Reuses the fake sysfs tree of BaselineTests; only the new + tests run here (the inherited ones are skipped).""" + + def setUp(self): + super().setUp() + import helpers + self.fc = helpers.FakeForgectrl().start() + baseline.Baseline._unreachable_until = 0.0 + + def tearDown(self): + self.fc.stop() + super().tearDown() + + def run(self, result=None): + # only this class's own tests, not the base class's + if self._testMethodName not in BaselineModeTests.__dict__: + return + return super().run(result) + + def cloud(self): + self.fc.state["mode"] = {"mode": "cloud", "controller": "running", "pid": 7, "motion": "verified"} + self.fc.state["settings"]["controller_mode"] = "cloud" + + def test_grbl_mode_restores_the_controller_values_and_the_lamp(self): + self._attr("cnc/step_freq", "10000") + self._attr("pic/lid_led", "77") + left = self.bl().enforce("pre", captured=None) + self.assertEqual(sorted(x.item for x in left), ["cnc/step_freq", "pic/lid_led"]) + self.assertEqual(self._read("cnc/step_freq"), "28160") + self.assertEqual(self._read("pic/lid_led"), "236") + + def test_cloud_mode_leaves_the_clients_config_lamp_and_counters(self): + self.cloud() + self._attr("cnc/step_freq", "10000") # the cloud client's tick + self._attr("pic/x_step_current", "135") + self._attr("pic/lid_led", "77") # its lid-image level + b = self.bl() + cap = b.capture() + self.assertEqual(cap["mode"], "cloud") + self.assertNotIn("controller_mode", cap["settings"]) + self._pos(-13096, -7400, 0) # the service re-zeroed and moved + self._attr("cnc/streaming", "1") # NOT the client's: still restored + left = b.enforce("post", captured=cap) + self.assertEqual([x.item for x in left], ["cnc/streaming"]) + self.assertEqual(self._read("cnc/step_freq"), "10000") + self.assertEqual(self._read("pic/x_step_current"), "135") + self.assertEqual(self._read("pic/lid_led"), "77") + self.assertEqual(self._read("cnc/streaming"), "0") + self.assertEqual(self.fc.posts, []) # no mode switch, no settings write + + def test_cloud_mode_still_relocks_the_latch(self): + self.cloud() + self._attr("cnc/interlock_circuit", "37") # bit 3 clear: unlocked + left = self.bl().enforce("post", captured=None) + self.assertEqual([x.item for x in left], ["laser_latch"]) + self.assertEqual(self._read("cnc/laser_latch"), "1") + + def test_undeclared_mode_change_is_handed_back_through_the_switch(self): + b = self.bl() + cap = b.capture() # found in grbl + self.assertEqual(cap["mode"], "grbl") + self.cloud() # the run left it in cloud, silently + left = b.enforce("post", captured=cap) + items = {x.item: x for x in left} + self.assertIn("mode", items) + self.assertEqual(items["mode"].action, "restored") + self.assertEqual(self.fc.posts, [("/mode", {"controller": "grbl"})]) + self.assertEqual(self.fc.state["mode"]["mode"], "grbl") + + def test_declared_mode_change_is_kept(self): + b = self.bl() + cap = b.capture() + self.cloud() + cap["mode"] = "cloud" # Context.mode_changed("cloud") + left = b.enforce("post", captured=cap) + self.assertNotIn("mode", [x.item for x in left]) + self.assertEqual(self.fc.posts, []) + self.assertEqual(self.fc.state["mode"]["mode"], "cloud") + + def test_controller_mode_setting_is_never_written_back_bare(self): + b = self.bl() + cap = b.capture() + self.assertNotIn("controller_mode", cap["settings"]) + self.fc.state["settings"]["controller_mode"] = "cloud" # a switch persisted it + self.fc.state["mode"]["mode"] = "cloud" + cap["mode"] = "cloud" + b.enforce("post", captured=cap) + self.assertEqual([p for p, _ in self.fc.posts if p == "/settings"], []) diff --git a/forgetest/tests/test_cloud_suite.py b/forgetest/tests/test_cloud_suite.py new file mode 100644 index 0000000..f0e9b6e --- /dev/null +++ b/forgetest/tests/test_cloud_suite.py @@ -0,0 +1,385 @@ +"""The cloud.* job-behavior tests against a fake forgectrl and a replayed +gfcloud log: the real test functions run under the real runner Context, +the operator prompts answered by a script that also drives the replay +(open the lid -> the machine's lid reads open; close it -> the service's +re-hunt lines land). The log lines are the machine's own: bench excerpts +(the lid-abort, button-wait, and lid-open-hunt runs) and, for the pause, +the run loop's lines as its host test emits them on the print skeleton +of the lid-abort excerpt. + +What is proven here: the tests find the right lines in real log noise, +reuse an existing cloud session and never switch back, restart the client +for a fresh hunt, judge the print's own finish line (not another action's), +wait the service's deferred moves out, and fail for the right reasons.""" +import os +import shutil +import struct +import tempfile +import threading +import time +import unittest + +import helpers +from forgetest.runner import Context, Failed, Run +from forgetest.suite import cloud + +HERE = os.path.dirname(os.path.abspath(__file__)) +FIX = os.path.join(HERE, "fixtures") + + +def fixture(name): + with open(os.path.join(FIX, "gfcloud-%s.log" % name), "rb") as f: + return f.read().decode().splitlines() + + +def cut(lines, marker, count=1): + """(before, after) at the count-th line containing marker (the line + itself opens `after`).""" + n = 0 + for i, ln in enumerate(lines): + if marker in ln: + n += 1 + if n == count: + return lines[:i], lines[i:] + raise KeyError(marker) + + +class Script: + """Answers every prompt with its first option; a hook per prompt + substring drives the fake machine and the log replay.""" + + def __init__(self, run, hooks=None): + self.run = run + self.hooks = hooks or {} + self.asked = [] + self.th = threading.Thread(target=self._loop, daemon=True) + self.stop = False + + def start(self): + self.th.start() + return self + + def _loop(self): + seen = None + while not self.stop: + p = self.run.prompt + if p and p["id"] != seen: + seen = p["id"] + self.asked.append(p["question"]) + for key, fn in self.hooks.items(): + if key in p["question"]: + fn() + self.run.answer(p["id"], p["options"][0]) + time.sleep(0.02) + + +class CloudSuiteTests(unittest.TestCase): + def setUp(self): + self.tmp = tempfile.mkdtemp(prefix="forgetest-cloud-") + self.log = os.path.join(self.tmp, "gfcloud.log") + open(self.log, "wb").close() + self.sysfs = os.path.join(self.tmp, "sysfs") + os.sep + os.makedirs(self.sysfs + "cnc") + self._attr("cnc/interlock_circuit", "45") # latch locked (bit 3) + self._pos(0, 0, 3) + os.environ["GF_SYSFS_ROOT"] = self.sysfs + self.fc = helpers.FakeForgectrl().start() + self.saved = (cloud.GFCLOUD_LOG, cloud.QUIET_S, cloud.QUIET_TIMEOUT_S, cloud.HUNT_TIMEOUT_S) + cloud.GFCLOUD_LOG = self.log + cloud.QUIET_S = 0.4 + cloud.QUIET_TIMEOUT_S = 3 + cloud.HUNT_TIMEOUT_S = 8 + self.script = None + + def tearDown(self): + if self.script: + self.script.stop = True + self.fc.stop() + cloud.GFCLOUD_LOG, cloud.QUIET_S, cloud.QUIET_TIMEOUT_S, cloud.HUNT_TIMEOUT_S = self.saved + os.environ.pop("GF_SYSFS_ROOT", None) + shutil.rmtree(self.tmp, ignore_errors=True) + + # -- fakes ----------------------------------------------------------- + def _attr(self, attr, val): + with open(self.sysfs + attr, "w") as f: + f.write(val) + + def _pos(self, x, y, z): + with open(self.sysfs + "cnc/position", "wb") as f: + f.write(struct.pack("<3i2I", x, y, z, 0, 0)) + + def append(self, lines, delay=0.0): + def go(): + if delay: + time.sleep(delay) + with open(self.log, "ab") as f: + f.write(("\n".join(lines) + "\n").encode()) + if delay: + threading.Thread(target=go, daemon=True).start() + else: + go() + + def in_cloud(self, pid=2278): + self.fc.state["mode"] = {"mode": "cloud", "controller": "running", "pid": pid, "motion": "verified"} + self.fc.state["settings"]["controller_mode"] = "cloud" + + def lid(self, closed): + self.fc.state["status"]["switches"]["lid"] = bool(closed) + + def run_test(self, fn, hooks=None, test_id="cloud.x"): + run = Run("test", test_id, test_id) + run.baseline_captured = {"mode": self.fc.state["mode"]["mode"], "position": [0, 0, 0]} + ctx = Context(run, None, helpers.make_test(test_id, [])) + self.script = Script(run, hooks).start() + try: + fn(ctx) + finally: + self.script.stop = True + return run + + def assertFails(self, fn, needle, hooks=None): + with self.assertRaises(Failed) as cm: + self.run_test(fn, hooks) + self.assertIn(needle, str(cm.exception)) + return cm.exception + + # -- session detection ------------------------------------------------- + def test_session_live_is_per_client(self): + lines = fixture("huntlid") + # the old client (1927) closed and left; the new one (2278) is ready + self.append(lines) + self.assertTrue(cloud.session_live(2278)[0]) + self.assertFalse(cloud.session_live(1927)[0]) + # an unknown pid falls back to the newest lines (ready) + self.assertTrue(cloud.session_live(9999)[0]) + # a drop after the ready line: not live until it is ready again + self.append(["2026-08-17T10:00:00.000000+00:00 gfcloud[2278] INFO websocket:_on_close RX-EVENT: closed (1006, )", + "2026-08-17T10:00:00.100000+00:00 gfcloud[2278] INFO websocket:run RECONNECTING"]) + live, detail = cloud.session_live(2278) + self.assertFalse(live) + self.assertIn("RECONNECTING", detail) + self.append(["2026-08-17T10:00:06.000000+00:00 gfcloud[2278] INFO websocket:_on_open RX-EVENT: ready"]) + self.assertTrue(cloud.session_live(2278)[0]) + + def test_enter_cloud_reuses_a_live_session_and_never_switches(self): + self.in_cloud() + self.append(fixture("huntlid")) + run = self.run_test(lambda ctx: cloud.enter_cloud(ctx)) + self.assertTrue(any("reusing it" in l for l in run.lines), run.lines) + self.assertEqual(self.fc.posts, []) + self.assertEqual(run.baseline_captured["mode"], "cloud") + + def test_enter_cloud_refuses_a_dead_session(self): + self.in_cloud(pid=1927) # the client that shut down in the excerpt + self.append(fixture("huntlid")) + self.assertFails(cloud.enter_cloud, "no live service session") + + def test_enter_cloud_switches_once_from_grbl_and_declares_it(self): + lines = fixture("huntlid") + pre, post = cut(lines, "gfuiservice:__init__ INITIALIZED") + self.append(pre) + + def on_post(path, form): + if path == "/mode": + self.append(post, delay=0.2) # the new client's session + hunt + moves + return None + self.fc.on_post = on_post + run = self.run_test(lambda ctx: cloud.enter_cloud(ctx)) + self.assertEqual([p for p, _ in self.fc.posts], ["/mode"]) + self.assertEqual(self.fc.state["mode"]["mode"], "cloud") + self.assertEqual(run.baseline_captured["mode"], "cloud") # declared: the baseline keeps it + self.assertTrue(any("connect-time hunt" in l and ":completed" in l for l in run.lines), run.lines) + + def test_enter_cloud_waits_for_the_service_to_stop_moving(self): + self.in_cloud() + self.append(fixture("huntlid")) + # a motion in flight (never idle within the timeout) fails, and says so + self.fc.state["status"]["state"] = "running" + self.assertFails(cloud.enter_cloud, "still running service moves") + + # -- the hunt with the lid open ------------------------------------------ + def test_hunt_lid_open_restarts_the_client_in_cloud_mode(self): + self.in_cloud(pid=1927) + lines = fixture("huntlid") + pre, post = cut(lines, "gfuiservice:__init__ INITIALIZED") + hunt_part, close_part = cut(post, "_switch_event lid closed") + self.append(pre) + + def on_post(path, form): + if path == "/controller/stop": + self.fc.state["mode"] = dict(self.fc.state["mode"], controller="standby", pid=0) + elif path == "/controller/start": + self.fc.state["mode"] = dict(self.fc.state["mode"], controller="running", pid=2278) + self.append(hunt_part, delay=0.2) + return None + self.fc.on_post = on_post + + def lid_closed(): + self.lid(True) + self.append(close_part, delay=0.2) + run = self.run_test(cloud.hunt_lid_open, + hooks={"Open the lid": lambda: self.lid(False), "Close the lid": lid_closed}, + test_id="cloud.hunt-lid-open") + self.assertEqual([p for p, _ in self.fc.posts], ["/controller/stop", "/controller/start"]) + ev = run.evidence + self.assertIn(":completed", ev["hunt_line"]) + self.assertEqual(ev["refusals_before_hunt_end"], 0) + self.assertEqual(ev["motions_after_lid_close"], 3) + self.assertEqual(self.fc.state["mode"]["mode"], "cloud") # still cloud + self.assertTrue(any("PASS:" in l for l in run.lines)) + # the prompts, in order: open, confirm lens, close + self.assertEqual(len(self.script.asked), 3) + + def test_hunt_lid_open_from_grbl_switches_and_stays(self): + lines = fixture("huntlid") + pre, post = cut(lines, "gfuiservice:__init__ INITIALIZED") + hunt_part, close_part = cut(post, "_switch_event lid closed") + self.append(pre) + + def on_post(path, form): + if path == "/mode": + self.append(hunt_part, delay=0.2) + return None + self.fc.on_post = on_post + run = self.run_test(cloud.hunt_lid_open, + hooks={"Open the lid": lambda: self.lid(False), + "Close the lid": lambda: (self.lid(True), self.append(close_part, delay=0.2))}) + self.assertEqual([p for p, _ in self.fc.posts], ["/mode"]) + self.assertEqual(self.fc.state["mode"]["mode"], "cloud") + self.assertEqual(run.baseline_captured["mode"], "cloud") + self.assertIn(":completed", run.evidence["hunt_line"]) + + def test_hunt_lid_open_needs_the_lid_open(self): + self.in_cloud() + self.append(fixture("huntlid")) + self.assertFails(cloud.hunt_lid_open, "lid reads closed") + + def test_hunt_refused_for_the_lid_fails(self): + self.in_cloud(pid=1927) + lines = fixture("huntlid") + pre, post = cut(lines, "gfuiservice:__init__ INITIALIZED") + # a refusal ahead of the hunt's end (the lid gating the hunt would look like this) + i = next(i for i, l in enumerate(post) if "z_axis:home starting z homing cycle" in l) + post = post[:i] + ["2026-08-17T09:45:10.595000+00:00 gfcloud[2278] INFO machine:_safe_to_move lid opened, unsafe to move"] + post[i:] + self.append(pre) + + def on_post(path, form): + if path == "/controller/stop": + self.fc.state["mode"] = dict(self.fc.state["mode"], controller="standby", pid=0) + elif path == "/controller/start": + self.fc.state["mode"] = dict(self.fc.state["mode"], controller="running", pid=2278) + self.append(post, delay=0.1) + return None + self.fc.on_post = on_post + self.assertFails(cloud.hunt_lid_open, "refused for the lid", hooks={"Open the lid": lambda: self.lid(False)}) + + # -- pause / resume --------------------------------------------------------- + def replay_print(self, name, at_run, at_end, tail_delay=0.3): + """Split a print excerpt into: up to the run's RUNNING line + (lands when the operator says Print is done), the block landing at + the mid-run prompt, and the rest.""" + lines = fixture(name) + pre, rest = cut(lines, "waiting for button") + run_pre, rest = cut(rest, "current state: MachineState.RUNNING") # the PRINT's run + pre, rest = pre + run_pre + [rest[0]], rest[1:] + mid, tail = cut(rest, at_end) + return {"Click Done here": lambda: self.append(pre, delay=0.1), + at_run: lambda: (self.append(mid, delay=0.05), self.append(tail, delay=tail_delay))} + + def test_pause_resume_passes_on_the_machines_lines(self): + self.in_cloud(pid=1522) + self.append(["2026-08-17T09:41:00.000000+00:00 gfcloud[1522] INFO authentication:authenticate_machine SUCCESS", + "2026-08-17T09:41:00.500000+00:00 gfcloud[1522] INFO websocket:_on_open RX-EVENT: ready", + "2026-08-17T09:41:00.900000+00:00 gfcloud[1522] INFO websocket:ws_connect ESTABLISHED"]) + hooks = self.replay_print("pause", "Press the button once NOW", "current state: MachineState.IDLE") + self.fc.state["cool"]["armed"] = True + run = self.run_test(cloud.pause_resume, hooks=hooks, test_id="cloud.pause-resume") + ev = run.evidence + self.assertEqual(ev["log"], {"button pressed mid-run; pausing": True, "paused at": True, + "button pressed while paused; resuming": True}) + self.assertTrue(ev["armed_after_resume"]) + self.assertIn(":completed", ev["log_end"]["print finished"]) + self.assertTrue(ev["log_end"]["return home complete"]) + self.assertEqual(ev["relock_or_cancel_lines"], 0) + self.assertEqual(self.fc.posts, []) + self.assertTrue(any("PASS: button pause/resume" in l for l in run.lines)) + # the post-print hunt was waited out + self.assertTrue(any("machine is quiet" in l for l in run.lines)) + + def test_pause_resume_fails_when_the_print_is_cancelled_instead(self): + self.in_cloud(pid=1522) + self.append(["2026-08-17T09:41:00.500000+00:00 gfcloud[1522] INFO websocket:_on_open RX-EVENT: ready"]) + lines = fixture("pause") + lines = [l.replace('print [1576550507]: finished with event ":completed"', + 'print [1576550507]: finished with event ":cancelled"') for l in lines] + pre, rest = cut(lines, "current state: MachineState.RUNNING") + pre, rest = pre + [rest[0]], rest[1:] + hooks = {"Click Done here": lambda: self.append(pre, delay=0.1), + "Press the button once NOW": lambda: self.append(rest, delay=0.05)} + self.assertFails(cloud.pause_resume, "did not complete after the resume", hooks=hooks) + + def test_pause_resume_fails_without_the_pause_line(self): + self.in_cloud(pid=1522) + self.append(["2026-08-17T09:41:00.500000+00:00 gfcloud[1522] INFO websocket:_on_open RX-EVENT: ready"]) + lines = [l for l in fixture("pause") if "button pressed mid-run" not in l] + pre, rest = cut(lines, "current state: MachineState.RUNNING") + pre, rest = pre + [rest[0]], rest[1:] + # the wait for the pause lines is 90 s: shorten it through the module's poll by + # ending the log early - the finish line arrives, but the pause never does + saved = cloud.wait_log + + def fast_wait_log(ctx, offset, needles, timeout, poll=0.5): + return saved(ctx, offset, needles, min(timeout, 1.5), poll=0.1) + cloud.wait_log = fast_wait_log + try: + hooks = {"Click Done here": lambda: self.append(pre, delay=0.1), + "Press the button once NOW": lambda: self.append(rest, delay=0.05)} + self.assertFails(cloud.pause_resume, "did not pause the run", hooks=hooks) + finally: + cloud.wait_log = saved + + # -- the two lid tests, on their bench excerpts -------------------------------- + def test_lid_abort_on_the_bench_excerpt(self): + self.in_cloud(pid=1522) + self.append(["2026-08-17T09:41:00.500000+00:00 gfcloud[1522] INFO websocket:_on_open RX-EVENT: ready"]) + hooks = self.replay_print("lidabort", "Open the lid NOW", "start cool down") + run = self.run_test(cloud.lid_abort, hooks=hooks, test_id="cloud.lid-abort") + ev = run.evidence + self.assertLess(ev["edge_to_stop_ms"], 60) + self.assertIn(":cancelled", ev["log"]["print finished"]) + self.assertEqual(ev["kernel_counters_after_park"], [0, 0, 3]) + self.assertTrue(ev["latch_locked"]) + self.assertFalse(ev["armed_after"]) + self.assertEqual(self.fc.posts, []) + self.assertTrue(any("PASS: lid open" in l for l in run.lines)) + + def test_lid_during_button_wait_on_the_bench_excerpt(self): + self.in_cloud(pid=1927) + self.append(["2026-08-17T09:41:00.500000+00:00 gfcloud[1927] INFO websocket:_on_open RX-EVENT: ready"]) + lines = fixture("buttonwait") + pre, rest = cut(lines, "waiting for button") + pre, rest = pre + [rest[0]], rest[1:] + hooks = {"Click Done here": lambda: self.append(pre, delay=0.1), + "Open the lid now": lambda: self.append(rest, delay=0.05)} + run = self.run_test(cloud.lid_during_button_wait, hooks=hooks, test_id="cloud.lid-during-button-wait") + ev = run.evidence + self.assertEqual(ev["runs_started_after_wait"], 0) + self.assertIn(":cancelled", ev["log"]["print finished"]) + self.assertTrue(ev["latch_locked"]) + self.assertEqual(self.fc.posts, []) + self.assertTrue(any("PASS: lid open at the button prompt" in l for l in run.lines)) + + def test_print_finish_is_the_prints_not_another_actions(self): + # a motion that completes before the print must not satisfy the print's finish + lines = fixture("lidabort") + i = cloud.action_finish_index(lines, "print") + j = cloud.action_finish_index(lines, "motion") + self.assertIsNotNone(i) + self.assertIsNotNone(j) + self.assertLess(j, i) + self.assertIn(":cancelled", lines[i]) + self.assertIn(":completed", lines[j]) + + +if __name__ == "__main__": + unittest.main() diff --git a/forgetest/tests/test_server.py b/forgetest/tests/test_server.py index 35fa12e..cd18038 100644 --- a/forgetest/tests/test_server.py +++ b/forgetest/tests/test_server.py @@ -181,6 +181,18 @@ class ServerTests(unittest.TestCase): st, d = self.call("POST", "/start", {"test": "fake.needs"}) self.assertEqual(st, 409) self.assertIn("prerequisites", d["message"]) + # the operator's override: the test runs alone and the record says so + st, d = self.call("POST", "/start", {"test": "fake.needs", "ignore_requires": True}) + self.assertEqual(st, 200) + state = self.wait_idle() + self.assertEqual(state["tests"]["fake.needs"]["status"], "pass") + st, rec = self.call("GET", "/result?test=fake.needs") + self.assertEqual(rec["evidence"]["prerequisites"]["missing"], ["fake.prompt"]) + self.assertTrue(rec["evidence"]["prerequisites"]["overridden"]) + self.assertTrue(any("prerequisites overridden" in l for l in rec["log"])) + # its prerequisite is still required for the release + self.assertFalse(state["tests"]["fake.prompt"]["satisfied"]) + self.assertFalse(state["authorized"]) st, d = self.call("POST", "/start", {"test": "fake.live"}) self.assertEqual(st, 409) self.assertIn("live", d["message"])