From aaabfdf9b93932e632c1be8767ec0b7e0a981738 Mon Sep 17 00:00:00 2001 From: ScottW514 Date: Thu, 20 Aug 2026 14:16:27 -0400 Subject: [PATCH] Check the progress a print reports, where a print already runs Two tests already run a print end to end, and progress is a property of a running print, so the checks go there rather than into a test of their own that would cost the operator another job. cloud.pause-resume takes the job that fits the ring: the client names the length it is reporting against, and the operator is asked the question only a person can answer, whether the bar actually moved. cloud.oversize-stream takes the job that does not fit, which is where a moving denominator would show: the kernel's program total grows all run long under a live feed, and the test already samples it growing, so the check is that the figure progress divides by is larger than that - the job, not the count the ring had swallowed when the run started. The forgetest replay plays a captured log from a build that predates the line, so it carries the line where the current build emits it, as it already does for the warm-up and the rest. BRINGUP's cloud item now says a print reports itself again, and what is left on it is a print watched from the app. --- docs/BRINGUP.md | 12 ++++--- forgetest/forgetest/suite/cloud.py | 54 ++++++++++++++++++++++++++--- forgetest/tests/test_cloud_suite.py | 9 +++-- 3 files changed, 62 insertions(+), 13 deletions(-) diff --git a/docs/BRINGUP.md b/docs/BRINGUP.md index 033001f..93af5d3 100644 --- a/docs/BRINGUP.md +++ b/docs/BRINGUP.md @@ -979,14 +979,16 @@ Open items only. Anything closed is in `CAMPAIGN-LOG.md`. than by ring depth (a healthy feeder keeps the ring brim-full, so depth only falls an hour after the feed died): thirty seconds of no progress with room in the ring stops the job cleanly and retraces, and it resumes if the - feed moves again. The remaining gaps are tracked in + feed moves again. A running print also reports itself to the app again, on + the carrier a factory-session capture settled: the `type:"progress"` frame + that is the periodic settings report, every 30 s and at every phase change, + divided by the job's own length rather than by the kernel byte counter that + climbs all job long under a live feed. The remaining gaps are tracked in `python3-gfhardware/forgefirm-app/docs/CLOUD.md` "Outstanding items": a live job longer than the ring (built and covered, never yet run from the service), the memory guards against a real ceiling rather than a reasoned - one, sending progress to the app (F2: the carrier is settled, an outbound - `type:"progress"` frame that is the periodic settings report, at 30 s, from - a factory-session capture; what is owed is emitting it against the feeder's - job total rather than the kernel byte counter), packaged-path boot with + one, a print watched from the app to see the bar actually move, + packaged-path boot with `controller_mode = cloud`, the three unobserved actions, the lid-flash LED, and driving the park and the two lifecycle periods off the header (`CFrh`, `CCwp`, `CCrp`) once a capture confirms diff --git a/forgetest/forgetest/suite/cloud.py b/forgetest/forgetest/suite/cloud.py index af55228..e7b9ce2 100644 --- a/forgetest/forgetest/suite/cloud.py +++ b/forgetest/forgetest/suite/cloud.py @@ -347,6 +347,24 @@ def message(line): return line.split(" ", 2)[-1] if line else None +PROGRESS_MARK = "print:progress: reporting against " + + +def progress_denominator(lines): + """The length the print reported its progress against, or None. + + The client names it once per job, which is the number worth having: it + is what every progress frame of that job divides by. + """ + for ln in lines: + if PROGRESS_MARK in ln: + try: + return int(ln.split(PROGRESS_MARK, 1)[1].split()[0]) + except (IndexError, ValueError): + return None + return 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 @@ -731,7 +749,8 @@ def hunt_lid_open(ctx): "latch stays unlocked and the armed window open through the pause. The same " "print is where the job's lifecycle shows: a print warms up before its first " "fire and rests after its park, both non-zero, while the connect-time hunt in " - "the same session does neither.") + "the same session does neither. It is also where the app's progress bar shows: " + "the run reports how far it has gotten, against the job's own length.") def pause_resume(ctx): ev = ctx.evidence offset = enter_cloud(ctx) @@ -791,9 +810,20 @@ def pause_resume(ctx): ev["holds_before_the_print"] = early_holds ctx.check(not early_holds, "a hunt or motion held for a print's periods: %s", early_holds[:2]) + # The app's progress bar, from the same print. The machine reports where + # it has gotten to every 30 s and at every phase change, against the + # job's own length, which it names once when the run starts. + declared = progress_denominator(lines) + ev["progress_total"] = declared + ctx.log("progress reported against %s bytes", declared) + ctx.check(declared is not None, "the print reported no progress at all") + ctx.check(declared and declared > 0, "the print reported progress against %s bytes", declared) + ctx.confirm("Did the app show the print's progress advancing while it cut, rather than " + "standing still or jumping straight to nearly finished?") + settle_cloud(ctx, offset) - ctx.log("PASS: button pause/resume mid-print, warm-up and rest observed, job completed " - "and parked") + ctx.log("PASS: button pause/resume mid-print, warm-up and rest observed, progress reported, " + "job completed and parked") @test("cloud.oversize-stream", title="A print longer than the ring is fed while it plays", @@ -810,8 +840,9 @@ def pause_resume(ctx): "is several times the ring: the machine holds the job in memory, fills the ring, " "starts, and tops the ring up as it drains. This checks the signature of that - " "the device in live-feed mode, the kernel's program total growing during the run, " - "and no underrun - that a live-fed print pauses and resumes the factory way, the " - "ring having kept the history to back into, and that the job still cancels " + "and no underrun - that progress is reported against the job's length rather " + "than that growing total, that a live-fed print pauses and resumes the factory " + "way, the ring having kept the history to back into, and that the job cancels " "cleanly.") def oversize_stream(ctx): ev = ctx.evidence @@ -846,6 +877,19 @@ def oversize_stream(ctx): ev["underruns_during"] = after ctx.check(after == before, "the ring ran dry during the run (underruns %s -> %s)", before, after) + # Progress on a live feed is where a moving denominator would show. The + # kernel's program total is what just grew, and a bar divided by it would + # sit near full from the first frame to the last; the job's own length is + # what the report divides by, and on a job this long it is the larger + # number by a wide margin. + declared = progress_denominator(log_lines_since(GFCLOUD_LOG, offset)) + ev["progress_total"] = declared + ctx.log("progress reported against %s bytes, kernel program total %s", declared, grown) + ctx.check(declared is not None, "the print reported no progress at all") + ctx.check(declared and first is not None and declared > first, + "progress is being reported against %s bytes, which is the ring's count (%s), not " + "the job", declared, first) + # The pause on a live feed: the ring keeps the history to back into, so a # streamed print retraces and leads back on exactly like a preloaded one. ev["max_backtrack"] = hw.sysfs_int("cnc/max_backtrack", 0) diff --git a/forgetest/tests/test_cloud_suite.py b/forgetest/tests/test_cloud_suite.py index d9ae240..d5571bb 100644 --- a/forgetest/tests/test_cloud_suite.py +++ b/forgetest/tests/test_cloud_suite.py @@ -37,6 +37,8 @@ WARM_UP_LINE = ("2026-08-17T09:44:02.100000+00:00 gfcloud[1522] INFO " "machine:_dwell warm up: holding 3.0 s") COOL_DOWN_LINE = ("2026-08-17T09:45:31.700000+00:00 gfcloud[1522] INFO " "machine:_dwell cool down: holding 10.0 s") +PROGRESS_LINE = ("2026-08-17T09:44:05.200000+00:00 gfcloud[1522] INFO " + "machine:__init__ print:progress: reporting against 47848 bytes every 30 s") def cut(lines, marker, count=1): @@ -289,9 +291,10 @@ class CloudSuiteTests(unittest.TestCase): pre, rest = cut(lines, "waiting for button") run_pre, rest = cut(rest, "current state: MachineState.RUNNING") # the PRINT's run # The excerpt was captured before the machine held for a warm-up and - # a rest; the replay carries those two lines where it emits them now, - # rather than editing what the machine actually said that day. - run_pre = run_pre + [WARM_UP_LINE] + # a rest, and before it reported a print's progress; the replay + # carries those lines where it emits them now, rather than editing + # what the machine actually said that day. + run_pre = run_pre + [WARM_UP_LINE, PROGRESS_LINE] pre, rest = pre + run_pre + [rest[0]], rest[1:] mid, tail = cut(rest, at_end) tail = tail + [COOL_DOWN_LINE]