diff --git a/.github/workflows/forgetest-ci.yml b/.github/workflows/forgetest-ci.yml index 765c073..03cd5fc 100644 --- a/.github/workflows/forgetest-ci.yml +++ b/.github/workflows/forgetest-ci.yml @@ -2,7 +2,10 @@ # # - unit tests: campaign rules, fingerprints, artifact build/verify (the # release gate's decision, including the negative fixtures), runner + -# HTTP API end to end with a fake catalog and a fake bench tool +# HTTP API end to end with a fake catalog and a fake bench tool, the +# suites replayed on the machine's own log lines, and the check that +# every log phrase the cloud suite greps for is one the pinned cloud +# app can log (it reads the app sources from the manifest cache) # - coverage lint: every source path of every component pinned by the # recipes must be selected by some catalog test's coverage globs (the # tree manifest is generated from the pins with git - no Yocto build); @@ -43,14 +46,14 @@ jobs: with: python-version: '3.12' + - name: Tree manifest from the recipe pins (also fetches the pinned app sources the needle check reads) + working-directory: forgefirm + run: python scripts/manifest-from-tree.py --out tree-manifest.json + - name: Unit tests working-directory: forgefirm/forgetest run: python -m unittest discover -s tests -v - - name: Tree manifest from the recipe pins - working-directory: forgefirm - run: python scripts/manifest-from-tree.py --out tree-manifest.json - - name: Coverage lint (enforced) working-directory: forgefirm/forgetest run: python -m forgetest.coverage --manifest ../tree-manifest.json --enforce | tee "$GITHUB_STEP_SUMMARY" diff --git a/forgetest/forgetest/suite/cloud.py b/forgetest/forgetest/suite/cloud.py index 54843fe..409e3b2 100644 --- a/forgetest/forgetest/suite/cloud.py +++ b/forgetest/forgetest/suite/cloud.py @@ -317,6 +317,17 @@ def action_finish_index(lines, action): if (action + " [") in ln and "finished with event" in ln), None) +def check_pause_resume(ctx, got, offset, what="the run"): + """The pause and the resume, judged on the run loop's lines (got is + wait_log's result over PAUSE_LINES + RESUME_LINES).""" + ctx.check(got["button pressed mid-run; pausing"], "the press did not pause %s", what) + ctx.check(got["paused at"], "the pause did not settle (no 'paused at')") + ctx.check(got["button pressed while paused"], "the second press was not seen while paused") + refused = [ln for ln in log_lines_since(GFCLOUD_LOG, offset) if RESUME_REFUSED in ln] + ctx.check(not refused, "the resume was refused: %s", message(refused[0]) if refused else "") + ctx.check(got["resuming (laser lead"], "the second press did not resume (no retraced restart logged)") + + 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.""" @@ -503,6 +514,13 @@ 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"' +# The run loop's own lines for a button pause and the resume that follows: +# the press, the settled hold, the second press, and the retraced restart +# with its laser lead (logged by _resume_retraced, on its own line). A +# resume the kernel refuses logs "resume refused" instead and cancels. +PAUSE_LINES = ("button pressed mid-run; pausing", "paused at") +RESUME_LINES = ("button pressed while paused", "resuming (laser lead") +RESUME_REFUSED = "resume refused" 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).") @@ -748,12 +766,9 @@ def pause_resume(ctx): 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) + got = wait_log(ctx, offset, list(PAUSE_LINES + RESUME_LINES), 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") + check_pause_resume(ctx, got, offset) 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"]) @@ -885,12 +900,9 @@ def oversize_stream(ctx): ctx.log("max_backtrack while the feed runs: %s steps", ev["max_backtrack"]) ctx.instruct("Press the button once (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) + got = wait_log(ctx, offset, list(PAUSE_LINES + RESUME_LINES), 90) ev["pause_log"] = {k: bool(v) for k, v in got.items()} - ctx.check(got["button pressed mid-run; pausing"], "the press did not pause the live-fed 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") + check_pause_resume(ctx, got, offset, what="the live-fed run") backtracked = [ln for ln in log_lines_since(GFCLOUD_LOG, offset) if "backtrack refused" in ln] ev["backtrack_refused_lines"] = backtracked[:2] @@ -937,7 +949,7 @@ def pause_cancel_paths(ctx): ctx.check(got, "print 1 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 it stop and back up a " "few millimeters, then click Done.") - got = wait_log(ctx, offset, ["button pressed mid-run; pausing", "paused at"], 90) + got = wait_log(ctx, offset, list(PAUSE_LINES), 90) ev["paused"] = {k: bool(v) for k, v in got.items()} ctx.check(got["button pressed mid-run; pausing"], "the press did not pause print 1") ctx.check(got["paused at"], "the pause did not settle (no 'paused at')") diff --git a/forgetest/tests/fixtures/gfcloud-pause.log b/forgetest/tests/fixtures/gfcloud-pause.log index c29caaf..92bbd4e 100644 --- a/forgetest/tests/fixtures/gfcloud-pause.log +++ b/forgetest/tests/fixtures/gfcloud-pause.log @@ -20,7 +20,8 @@ 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.704560+00:00 gfcloud[1522] INFO machine:_run_loop button pressed while paused +2026-08-17T09:42:34.706100+00:00 gfcloud[1522] INFO machine:_resume_retraced 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 diff --git a/forgetest/tests/test_cloud_needles.py b/forgetest/tests/test_cloud_needles.py new file mode 100644 index 0000000..bdff3b8 --- /dev/null +++ b/forgetest/tests/test_cloud_needles.py @@ -0,0 +1,259 @@ +"""Every phrase the cloud suite greps for in the gfcloud log must be a +phrase the pinned cloud app can actually log. + +The cloud tests judge a print on the machine's own log lines. When the +app's wording moves (a resume that used to log one line logs two), a +test keeps looking for the old line and fails a print that worked. The +replay fixtures cannot catch that: they are excerpts of the old wording. +This test reads the phrases straight out of suite/cloud.py and checks +each against the logger calls in the app sources at the revisions the +recipes pin (python3-gfhardware and python3-gfutilities, from the +manifest cache the tree manifest builds, or the sibling checkouts when +no cache is at hand), placeholder-aware: "paused at" is covered by +'paused at %s', "warm up: holding" by '%s: holding %.1f s', and +"authenticate_machine SUCCESS" by logger.info('SUCCESS') inside +def authenticate_machine (the log format is module:function message). +""" +import ast +import importlib.util +import os +import re +import subprocess +import unittest + +import helpers # noqa: F401 (sys.path) + +HERE = os.path.dirname(os.path.abspath(__file__)) +FORGETEST = os.path.dirname(HERE) +REPO = os.path.dirname(FORGETEST) +CLOUD_PY = os.path.join(FORGETEST, "forgetest", "suite", "cloud.py") +APP_COMPONENTS = ("python3-gfhardware", "python3-gfutilities") +SIBLINGS = {"python3-gfhardware": "python3-gfhardware", "python3-gfutilities": "Glowforge-Utilities"} + +# Phrases cloud.py builds at run time rather than writing out (a "%s: holding" +# with the phase filled in), listed here so they are checked too. +BUILT_PHRASES = ("warm up: holding", "cool down: holding", "warm up: skipped", "cool down: skipped", + 'finished with event ":cancelled"', 'finished with event ":completed"', + "motion [", "print [") +# Phrases that are not the app's: forgetest's own log, or a line prefix +# of the log format rather than a message. +NOT_APP = ("PASS", "gfcloud", "[") + +PLACEHOLDER = re.compile(r"%(?:\([^)]*\))?[-+ #0]*\d*(?:\.\d+)?[sdifrxXeEgGcu]|%%") + + +# ------------------------------------------------------------ the needles + +def needles_in(path): + """String constants cloud.py tests against log lines: the left side of + an `x in ln`, the arguments of wait_log, endswith() arguments, and the + names those resolve to (module- or function-level constants).""" + with open(path, encoding="utf-8") as f: + tree = ast.parse(f.read()) + consts = {} # name -> list of str + + def strings_of(node): + if isinstance(node, ast.Constant) and isinstance(node.value, str): + return [node.value] + if isinstance(node, (ast.List, ast.Tuple)): + return [s for e in node.elts for s in strings_of(e)] + if isinstance(node, ast.Name): + return consts.get(node.id, []) + if isinstance(node, ast.BinOp) and isinstance(node.op, ast.Add): + return strings_of(node.left) + strings_of(node.right) + if isinstance(node, ast.Call) and isinstance(node.func, ast.Name) and node.func.id == "list": + return [s for a in node.args for s in strings_of(a)] + return [] + + for node in ast.walk(tree): + if isinstance(node, ast.Assign) and len(node.targets) == 1 and isinstance(node.targets[0], ast.Name): + got = strings_of(node.value) + if got: + consts[node.targets[0].id] = got + found = set() + for node in ast.walk(tree): + if isinstance(node, ast.Compare) and any(isinstance(op, ast.In) for op in node.ops): + found.update(strings_of(node.left)) + elif isinstance(node, ast.Call): + fn = node.func + if isinstance(fn, ast.Name) and fn.id == "wait_log" and len(node.args) >= 3: + found.update(strings_of(node.args[2])) + elif isinstance(fn, ast.Attribute) and fn.attr == "endswith": + for a in node.args: + found.update(strings_of(a)) + # the mark tuples the suite scans lines against in comprehensions + # (`any(m in ln for m in SESSION_MARKS)`), where the name is a loop variable + for name, vals in consts.items(): + if name.endswith(("_MARKS", "_LINES")): + found.update(vals) + found.update(BUILT_PHRASES) + return sorted(s.strip() for s in found if s.strip() and s.strip() not in NOT_APP and " " in s or s in BUILT_PHRASES) + + +# ------------------------------------------------------------ the app's lines + +def log_literals(source, label): + """(function name, fragments) for every logger call in a Python source: + the message's fixed text split at its placeholders.""" + out = [] + try: + tree = ast.parse(source) + except SyntaxError: + return out + funcs = {} + for node in ast.walk(tree): + if isinstance(node, (ast.FunctionDef, ast.AsyncFunctionDef)): + for sub in ast.walk(node): + funcs.setdefault(id(sub), node.name) + for node in ast.walk(tree): + if not (isinstance(node, ast.Call) and isinstance(node.func, ast.Attribute) + and node.func.attr in ("debug", "info", "warning", "warn", "error", "critical", "exception") + and node.args): + continue + msg = node.args[0] + if isinstance(msg, ast.BinOp) and isinstance(msg.op, ast.Mod): + msg = msg.left + frags = None + if isinstance(msg, ast.Constant) and isinstance(msg.value, str): + frags = [p.replace("%%", "%") for p in PLACEHOLDER.split(msg.value)] + elif isinstance(msg, ast.JoinedStr): + frags = [""] + for v in msg.values: + if isinstance(v, ast.Constant): + frags[-1] += str(v.value) + else: + frags.append("") + if frags is not None: + out.append((funcs.get(id(node), ""), frags, label)) + return out + + +def covers(frags, needle): + """True when `needle` is a substring of a rendering of the message whose + fixed text is `frags` (the gaps between fragments are placeholders; the + rendered line is `function message`, so frags[0] carries the function). + A placeholder is a value, never the phrase itself: the needle must lie + inside one fixed fragment, or run through the fragments in order and + contain at least one complete non-empty fragment.""" + n = len(frags) + if any(needle in f for f in frags if f): + return True + + def in_gap(text, i, complete): + """`text` starts in the gap before frags[i].""" + if i >= n: + return False + frag = frags[i] + if frag == "": + return complete if i == n - 1 else in_gap(text, i + 1, complete) + start = 0 + while True: + j = text.find(frag, start) + if j < 0: + break + if after(text[j + len(frag):], i, True): + return True + start = j + 1 + # the needle ends inside frags[i]: a proper prefix of it, which counts + # as the complete fragment the rule wants only when the gap before it + # was preceded by one, or when what is left of the fragment is a + # trailing separator (": holding " is covered by "warm up: holding") + for k in range(1, len(frag)): + if text.endswith(frag[:k]) and (complete or not frag[k:].strip()): + return True + return False + + def after(text, i, complete): + """`text` starts right after the whole of frags[i].""" + if text == "": + return complete + return in_gap(text, i + 1, complete) + + for i, frag in enumerate(frags): + for off in range(len(frag)): + suffix = frag[off:] + if needle.startswith(suffix) and after(needle[len(suffix):], i, off == 0): + return True + if i >= 1 and in_gap(needle, i, False): + return True + return False + + +# ------------------------------------------------------------ sources + +def pinned_sources(): + """{component: [(path, text)]} for the app components at their pinned + revisions, through the tree manifest's recipe parser and cache; the + sibling checkouts when the cache cannot be reached.""" + spec = importlib.util.spec_from_file_location("mft", os.path.join(REPO, "scripts", "manifest-from-tree.py")) + mft = importlib.util.module_from_spec(spec) + spec.loader.exec_module(mft) + meta = os.path.join(os.path.dirname(REPO), "meta-openglow") + cache = os.path.join(REPO, ".manifest-cache") + out = {} + for name, rel, layer in mft.RECIPES: + if name not in APP_COMPONENTS: + continue + base = REPO if layer == "forgefirm" else meta + files = [] + try: + url, rev = mft.parse_recipe(os.path.join(base, rel)) + repo = mft.fetch(url, rev, cache) + names = mft.git(["ls-tree", "-r", "--name-only", rev], cwd=repo).decode().split("\n") + for p in names: + if p.endswith(".py"): + files.append((p, mft.git(["show", "%s:%s" % (rev, p)], cwd=repo).decode("utf-8", "replace"))) + out[name] = ("pinned %s" % rev[:12], files) + continue + except (OSError, subprocess.CalledProcessError, SystemExit): + pass + sib = os.path.join(os.path.dirname(REPO), SIBLINGS[name]) + if os.path.isdir(sib): + for root, _dirs, fnames in os.walk(sib): + if ".git" in root: + continue + for fn in fnames: + if fn.endswith(".py"): + p = os.path.join(root, fn) + files.append((os.path.relpath(p, sib), open(p, encoding="utf-8", errors="replace").read())) + out[name] = ("sibling checkout", files) + return out + + +class CloudNeedleTests(unittest.TestCase): + def test_every_needle_is_a_line_the_pinned_app_can_log(self): + needles = needles_in(CLOUD_PY) + self.assertGreaterEqual(len(needles), 30, needles) + self.assertIn("authenticate_machine SUCCESS", needles) + self.assertIn("RX-EVENT: ready", needles) + sources = pinned_sources() + missing = [c for c in APP_COMPONENTS if c not in sources] + if missing: + if os.environ.get("CI"): + self.fail("no source for %s (run scripts/manifest-from-tree.py first)" % ", ".join(missing)) + self.skipTest("no source for %s" % ", ".join(missing)) + literals = [] + for comp, (where, files) in sources.items(): + for path, text in files: + literals.extend(log_literals(text, "%s:%s" % (comp, path))) + self.assertGreater(len(literals), 100, "too few logger calls found: is the app source complete?") + uncovered = [] + for needle in needles: + if not any(covers([fn + " " + frags[0]] + frags[1:], needle) for fn, frags, _ in literals): + uncovered.append(needle) + self.assertEqual(uncovered, [], "cloud.py greps for lines the pinned app never logs (sources: %s)" + % ", ".join("%s=%s" % (c, w) for c, (w, _) in sources.items())) + + def test_cover_rules(self): + self.assertTrue(covers(["_run_loop paused at ", ""], "paused at")) + self.assertTrue(covers(["_dwell ", ": holding ", " s"], "warm up: holding")) + self.assertTrue(covers(["authenticate_machine SUCCESS"], "authenticate_machine SUCCESS")) + self.assertTrue(covers(["_resume_retraced resuming (laser lead ", " ticks)"], "resuming (laser lead")) + self.assertTrue(covers(["_finish_action ", " [", "]: finished with event \"", "\""], + 'finished with event ":completed"')) + self.assertFalse(covers(["_run_loop button pressed while paused"], "button pressed while paused; resuming")) + self.assertFalse(covers(["_run_loop paused at ", ""], "paused it")) + + +if __name__ == "__main__": + unittest.main() diff --git a/forgetest/tests/test_cloud_suite.py b/forgetest/tests/test_cloud_suite.py index d5571bb..30111e7 100644 --- a/forgetest/tests/test_cloud_suite.py +++ b/forgetest/tests/test_cloud_suite.py @@ -11,6 +11,7 @@ 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 contextlib import os import shutil import struct @@ -311,7 +312,7 @@ class CloudSuiteTests(unittest.TestCase): 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}) + "button pressed while paused": True, "resuming (laser lead": True}) self.assertTrue(ev["armed_after_resume"]) self.assertIn(":completed", ev["log_end"]["print finished"]) self.assertTrue(ev["log_end"]["return home complete"]) @@ -333,25 +334,56 @@ class CloudSuiteTests(unittest.TestCase): "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_retraced_restart(self): + """The second press was seen but the retraced restart never logged + (the app's resume is its own line now): the failure names that.""" + 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 "resuming (laser lead" not in l] + pre, rest = cut(lines, "current state: MachineState.RUNNING") + pre, rest = pre + [rest[0]], rest[1:] + with self.fast_wait_log(): + 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, "no retraced restart logged", hooks=hooks) + + def test_pause_resume_fails_when_the_kernel_refuses_the_resume(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.replace("machine:_resume_retraced resuming (laser lead 1950 ticks)", + "machine:_resume_retraced resume refused ([Errno 22] Invalid argument); cancelling") + for l in fixture("pause")] + pre, rest = cut(lines, "current state: MachineState.RUNNING") + pre, rest = pre + [rest[0]], rest[1:] + with self.fast_wait_log(): + 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, "the resume was refused", hooks=hooks) + + @contextlib.contextmanager + def fast_wait_log(self): + """The wait for the pause lines is 90 s: a replay whose line never + comes would sit it out. Cap it through the module's wait.""" + saved = cloud.wait_log + + def fast(ctx, offset, needles, timeout, poll=0.5): + return saved(ctx, offset, needles, min(timeout, 1.5), poll=0.1) + cloud.wait_log = fast + try: + yield + finally: + cloud.wait_log = saved + 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: + with self.fast_wait_log(): 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 lid/interlock abort and the button-wait tests, on their excerpts ------ # -- the merged lid + interlock abort test -------------------------------