From 800863fb090f63054e6021e1c58d148e1345ea93 Mon Sep 17 00:00:00 2001 From: ScottW514 Date: Fri, 25 Sep 2026 14:22:51 -0400 Subject: [PATCH] forgetest: the cloud tests wait out the service's thinking wait_quiet took the machine as quiet after 8 s without the start of a motion, a park, a run or a lens homing. Between a lid image and its next move the service is working on the image and the log is silent, and on the bench reference the re-hunt's moves came 9.6 s apart: cloud.mode-switch switched back to GRBL mode in the middle of the re-hunt, twice, the first time canceling a motion at 988 of its 1002 steps. Every line of a service action now counts as activity: the requests, the image uploads, the action ends, the runs, the parks, the motions and the lens homing. The quiet is 30 s. Over 1901 motion, lid-image and hunt requests in the bench reference's logs, half came within 1.6 s of the line before, 99 percent within 12.8 s, and two after more than 30 s (32.8 and 62.2 s). return_head goes: cloud.mode-switch hands its cloud stretch back through the cloud client's log (homeoff.cloud_mode_return), and nothing else called it. RETURN_MAX_MM moves to homeoff, its one user. Proof: tests/test_cloud_suite.py's new case lands a motion, a lid image 0.8 s later and the next move 1.6 s after the motion, with the quiet at 1 s: the quiet comes after the move. With the old activity marks it is declared after the image, before the move. forgetest 499 OK. Acceptance: cloud.mode-switch gates the change on a machine, its re-hunt waited out before the switch back. The fingerprints of every test in suite/cloud.py and of every module that imports from it move: 29 tests, the cloud tests, events.button-telemetry, the exthost tests, homing.cloud-offsets and setup.check-envelope. --- forgetest/forgetest/suite/cloud.py | 53 ++++++++-------------------- forgetest/forgetest/suite/homeoff.py | 3 +- forgetest/tests/test_cloud_suite.py | 23 ++++++++++++ 3 files changed, 39 insertions(+), 40 deletions(-) diff --git a/forgetest/forgetest/suite/cloud.py b/forgetest/forgetest/suite/cloud.py index 2a2409d..06150cd 100644 --- a/forgetest/forgetest/suite/cloud.py +++ b/forgetest/forgetest/suite/cloud.py @@ -95,7 +95,6 @@ SESSION_MARKS = ("authenticate_machine SUCCESS", "ws_connect ESTABLISHED") # The service's connect-time hunt, as the client logs its request: a few # seconds after the controller starts, right behind the session. HUNT_REQUEST = "service action request: hunt" -RETURN_MAX_MM = 600.0 # the head comes back from the home corner across the bed def log_size(path): @@ -120,39 +119,6 @@ def session_established(lines): return all(any(m in ln for ln in lines) for m in SESSION_MARKS) -def return_head(ctx, feed=2400): - """Jog the head back to where the run found it: cloud mode re-zeroed the - kernel counters at the starting position, so the counters now read the - displacement (the home corner). Ends on the machine idle.""" - fc = ctx.forgectrl - pos = fc.status().get("pos") or {} - x, y = float(pos.get("x", 0.0)), float(pos.get("y", 0.0)) - ctx.log("head displacement since the switch: X %.3f Y %.3f mm", x, y) - ctx.check(abs(x) <= RETURN_MAX_MM and abs(y) <= RETURN_MAX_MM, - "displacement %.1f/%.1f mm exceeds %.0f mm - not jogging back", x, y, RETURN_MAX_MM) - if abs(x) < 0.05 and abs(y) < 0.05: - return - with ctx.grbl() as g: - st = g.status_report()["state"] - if st.startswith("Alarm"): - g.command("$X") - r = g.command("$J=G91X%.3fY%.3fF%d" % (-x, -y, feed)) - ctx.check(not any(k.startswith("error") for k in r), "return jog refused: %s", r) - t0 = time.time() - while time.time() - t0 < 120: - ctx.checkpoint() - st = g.status_report()["state"] - if st.startswith("Idle") and time.time() - t0 > 0.5: - break - time.sleep(0.2) - g.command("G90") - ctx.check(fc.wait_idle(15, abort=ctx.aborted), "machine not idle after the return jog") - pos = fc.status().get("pos") or {} - ctx.log("head returned: counters X %.3f Y %.3f mm", float(pos.get("x", 0)), float(pos.get("y", 0))) - ctx.check(abs(float(pos.get("x", 0))) < 0.1 and abs(float(pos.get("y", 0))) < 0.1, - "head not back at the start after the return jog: %s", pos) - - def wait_mode(ctx, fc, want_mode, want_controller="running", timeout=90, poll=1.0): t0 = time.time() last = None @@ -536,9 +502,18 @@ NOHUNT_MARK = "NO-HUNT:" NOHUNT_MARKER = "/run/gfcloud-nohunt" HUNT_DONE = "hunt [" WS_MARKS = ("RX-EVENT: ready", "RX-EVENT: closed", "RECONNECTING", "CLOSING", OFFLINE_MARK) -ACTIVITY_MARKS = ("start motion", "start return home", "starting run", "starting z homing cycle") +# The service at work: every line of a service action, the requests, the image +# uploads and the ends included. Between a lid image and its next move the +# service is thinking and the log is silent, so the ends count: the quiet is +# measured from the last line of any action. +ACTIVITY_MARKS = ("service action request:", "img_upload COMPLETE", "finished with event", + "start motion", "end motion", "start return home", "return home complete", + "starting run", "finished 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) +# The service's think time after an image, on the bench reference: over 1901 +# motion, lid-image and hunt requests, half came within 1.6 s of the line before, +# 99 percent within 12.8 s, and two after more than 30 s (32.8 and 62.2 s). +QUIET_S = 30 QUIET_TIMEOUT_S = 180 HUNT_TIMEOUT_S = 180 @@ -763,9 +738,9 @@ def client_offline(pid): 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.""" + """The service's moves are over: the machine idle and no new line of any + service action in the log (ACTIVITY_MARKS) 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 diff --git a/forgetest/forgetest/suite/homeoff.py b/forgetest/forgetest/suite/homeoff.py index 5675d26..a700cb2 100644 --- a/forgetest/forgetest/suite/homeoff.py +++ b/forgetest/forgetest/suite/homeoff.py @@ -21,10 +21,11 @@ from ..baseline import XY_STEPS_PER_MM, counter_frame, counter_steps_per_mm, rea from ..catalog import test from ..runner import Failed from . import cloud as logs # the log paths, read at each call -from .cloud import RETURN_MAX_MM, _HOMING_PATH, gfhome_homing, log_lines_since, log_size +from .cloud import _HOMING_PATH, gfhome_homing, log_lines_since, log_size from .motion import _drop_reference, clean_slate, machine_idle, wait_idle, wait_state HOME_X, HOME_Y = 4.5, -3.25 +RETURN_MAX_MM = 600.0 # no hand-back jogs farther on an axis: the bed is smaller # The client's own record of a motion's end: the kernel counters, which # the motion zeroed at its start (the "(actual/expected)" line of the same # motion is not this one). A print's park keeps the counters and drives diff --git a/forgetest/tests/test_cloud_suite.py b/forgetest/tests/test_cloud_suite.py index aed7b4f..ea7e9ef 100644 --- a/forgetest/tests/test_cloud_suite.py +++ b/forgetest/tests/test_cloud_suite.py @@ -563,6 +563,29 @@ class CloudSuiteTests(unittest.TestCase): cloud.QUIET_TIMEOUT_S = 3 # this one waits the deadline out; tearDown puts it back self.assertFails(cloud.enter_cloud, "still running service moves") + def test_the_quiet_waits_out_the_service_thinking_after_a_lid_image(self): + # Between a lid image and the service's next move the log is silent + # while the service works on the image (the re-hunt on the bench + # reference, 2026-09-25). The quiet counts from the image's own + # lines, so it is not declared in that gap: it comes after the move. + cloud.QUIET_S = 1.0 + offset = cloud.log_size(self.log) + p = "2026-09-25T16:43:%s+00:00 gfcloud[12821] INFO " + self.append([p % "20.103479" + "gfuiservice:run service action request: motion (ready)", + p % "20.105376" + "machine:_motion start motion", + p % "22.617720" + "machine:_motion_locked end positions (12120, 7402, 0)", + p % "22.618542" + "machine:_motion end motion", + p % "22.619218" + "basemachine:_finish_action motion [1588864337]: finished with event " + "\":completed\""]) + self.append([p % "23.249589" + "gfuiservice:run service action request: lid_image (ready)", + p % "24.686536" + "websocket:img_upload COMPLETE"], delay=0.8) + self.append([p % "29.667978" + "gfuiservice:run service action request: motion (ready)", + p % "29.671663" + "machine:_motion start motion"], delay=1.6) + run = Run("test", "cloud.x", "cloud.x") + ctx = Context(run, None, helpers.make_test("cloud.x", [])) + self.assertTrue(cloud.wait_quiet(ctx, offset)) + self.assertIn("service action request: motion", cloud.log_lines_since(self.log, offset)[-2]) + # -- the hunt with the lid open ------------------------------------------ # -- the mode switch: hunt with the lid open, then $H ----------------------- HUNT_RUN_SAMPLE = {"phase": "run", "verdict": "ok", "armed": False,