mirror of
https://github.com/openglow-org/forgefirm.git
synced 2026-09-27 16:51:12 -07:00
installer: a download that resumes and retries, and an install log
A field install failed on "firmware download failed", and worked after a reboot. The download was one bare curl -fL: no retry, no resume, no bound on a stalled transfer, and nothing on the machine recorded what had gone wrong. The download. download_fw makes up to five tries, 5, 15, 30 and 60 seconds apart. Each try resumes the partial file (curl -C -) and is bounded: 20 s to connect, and a transfer below 1 KB/s for 30 s ends the try. The file is written as forgefirm.fw.part and takes its name only when curl finished; the signature check that follows is what vouches for its content. A full disk (curl 23) and a release that is not there (HTTP 404) end the tries at once, because waiting cannot fix them. A partial file the server will not resume (curl 33 or 36, HTTP 416) starts over. The loop is the installer's own rather than curl --retry: the factory curl on the bench reference is 7.69.1, whose --retry does not count a resolver failure or a dropped transfer as retryable, and older factory builds carry older curls. The owner sees the reason in words with each retry, and the final failure says that a re-run goes straight to the download, because the archives are kept. The log. Every run appends to /data/log/forgefirm/install/install.log, in the log tree's own line format (UTC, program "install"): the installer's md5 (which revision ran), the factory version and the slots, the owner's answers, each archive, each download try with curl's exit code, the HTTP code and the reason, the machine's clock at each try (a wrong clock breaks TLS), and after a failed try the address, the default route, the resolver and whether github.com resolves; then the signature and identity checks, the write, the boot selection, and the reason for any failure through die(). The log is appended across runs, so the run that failed is still there after the run that worked. Logging never fails the install. forgectrl's log export carries the directory (forgectrl 0dae758). Proven: tests/test_installer.py runs the installer's own functions under sh against a scripted curl - a clean download, a resolver failure and a dropped transfer that resume to the full file, the tries running out, 404 and a full disk ending them at once, a stale partial file starting over, the TLS reason naming the clock, every log line in the tree format, die() leaving its reason, and an unwritable log not failing the run. The whole host suite, 409 tests, passes under Linux and the coverage lint is clean. Bench: the same functions under the factory firmware's own shell (busybox 1.31.1 ash, the factory slot of the bench reference in a chroot) resumed, retried, ran out of tries and logged exactly as under sh. Acceptance: logs.tree-tail-export now plants a probe file in the install directory and requires it back in the export bundle, its line intact and its MAC and IPv4 address redacted, and requires an install log in the bundle when the machine has one. The installer itself is not on the image: the install page fetches it from master, so it is live with this push.
This commit is contained in:
ScottW514
@@ -27,14 +27,46 @@ def _read(path, default=None):
|
||||
_LOG_COVERS = [("forgectrl", "src/logs.*"), ("forgectrl", "src/fflog.*"), ("forgectrl", "src/sanitize.*"),
|
||||
("forgectrl", "src/main.c")]
|
||||
|
||||
LOGS_ROOT = "/data/log/forgefirm"
|
||||
# What the export test plants in the installer's directory: a line to find
|
||||
# again, and two addresses (documentation ranges) the sanitizer must take.
|
||||
_PROBE_MARK = "forgetest export probe"
|
||||
_PROBE_MAC = "02:00:5e:10:20:30"
|
||||
_PROBE_IP = "192.0.2.77"
|
||||
|
||||
|
||||
@test("logs.tree-tail-export", title="Log tree, tail, and sanitized export", subsystem="logs",
|
||||
kind="auto", est_min=1,
|
||||
covers=_LOG_COVERS, requires=["forgectrl.auth"],
|
||||
description="/logs lists the loggers with their levels and files, /logs/tail returns the "
|
||||
"forgectrl logger's tail, and POST /logs/export streams a sanitized tar.gz "
|
||||
"bundle that contains neither the panel token nor the camera key.")
|
||||
"bundle that contains neither the panel token nor the camera key. The bundle "
|
||||
"also carries the installer's directory of the tree (logs/install/), which no "
|
||||
"logger feeds: a probe file planted there for the export comes back in the "
|
||||
"bundle with its addresses redacted, and an install log that the installer "
|
||||
"left is in the bundle too.")
|
||||
def tree_tail_export(ctx):
|
||||
install_dir = os.path.join(LOGS_ROOT, "install")
|
||||
probe = os.path.join(install_dir, "forgetest-probe.txt")
|
||||
made_dir = not os.path.isdir(install_dir)
|
||||
try:
|
||||
os.makedirs(install_dir, exist_ok=True)
|
||||
with open(probe, "w") as f:
|
||||
f.write("%s from %s at %s\n" % (_PROBE_MARK, _PROBE_MAC, _PROBE_IP))
|
||||
_tree_tail_export(ctx, probe)
|
||||
finally:
|
||||
try:
|
||||
os.unlink(probe)
|
||||
except OSError:
|
||||
pass
|
||||
if made_dir:
|
||||
try:
|
||||
os.rmdir(install_dir)
|
||||
except OSError:
|
||||
pass
|
||||
|
||||
|
||||
def _tree_tail_export(ctx, probe):
|
||||
fc = ctx.forgectrl
|
||||
ev = ctx.evidence
|
||||
st, body = fc.get("/logs")
|
||||
@@ -87,6 +119,21 @@ def tree_tail_export(ctx):
|
||||
ev[what.replace(" ", "_") + "_leaks"] = leaked
|
||||
ctx.check(not leaked, "the sanitized bundle contains the %s: %s", what, leaked)
|
||||
|
||||
# the installer's directory: no logger feeds it, the export carries it
|
||||
by_name = dict(contents)
|
||||
want = "logs/install/" + os.path.basename(probe)
|
||||
got = [name for name in by_name if name.endswith(want)]
|
||||
ev["install_members"] = sorted(name for name in by_name if "/logs/install/" in name)
|
||||
ctx.check(got, "the bundle lacks %s: %s", want, ev["install_members"])
|
||||
if got:
|
||||
text = by_name[got[0]].decode("utf-8", "replace")
|
||||
ctx.check(_PROBE_MARK in text, "the probe file came back without its line: %r", text)
|
||||
for what, value in (("MAC address", _PROBE_MAC), ("IPv4 address", _PROBE_IP)):
|
||||
ctx.check(value not in text, "the install directory left the sanitizer with its %s", what)
|
||||
if os.path.isfile(os.path.join(os.path.dirname(probe), "install.log")):
|
||||
ctx.check(any(name.endswith("logs/install/install.log") for name in by_name),
|
||||
"the machine has an install log and the bundle does not")
|
||||
|
||||
|
||||
# The routing test proves the whole path every logger takes: emitter (or
|
||||
# relay) -> /dev/log -> rsyslog rules rendered from the settings -> the
|
||||
@@ -100,8 +147,7 @@ _ROUTING_COVERS = [("forgectrl", "src/logs.*"), ("forgectrl", "src/fflog.*"), ("
|
||||
("forgefirm-app", "forgefirm-app/ffmachine.py"), ("forgefirm-app", "forgefirm-app/gfcloud.py"),
|
||||
("forgefirm-app", "forgefirm-app/gfhome.py")]
|
||||
|
||||
LOGS_ROOT = "/data/log/forgefirm"
|
||||
LOGGERS = ("forgectrl", "grblhal", "gfcloud", "gfhome", "kernel", "system")
|
||||
LOGGERS =("forgectrl", "grblhal", "gfcloud", "gfhome", "kernel", "system")
|
||||
_LINE_RE = re.compile(r"^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(\.\d+)?[+-]\d\d:\d\d (?P<prog>[A-Za-z0-9_.-]+)\[(?P<pid>[-\d]+)\] "
|
||||
r"(?P<sev>EMERG|ALERT|CRIT|ERR|WARNING|NOTICE|INFO|DEBUG) (?P<msg>.*)$")
|
||||
_SEV_RANK = {"off": -1, "error": 3, "warning": 4, "notice": 5, "info": 6, "debug": 7}
|
||||
|
||||
@@ -0,0 +1,194 @@
|
||||
# Copyright 2026 514 LLC d/b/a OpenGlow
|
||||
# Written by Scott Wiederhold
|
||||
# https://community.openglow.org
|
||||
# SPDX-License-Identifier: MIT
|
||||
|
||||
"""scripts/install-forgefirm.sh - the download that retries, and the log.
|
||||
|
||||
The installer runs once per machine, on factory firmware, over whatever
|
||||
network the owner has. These tests run its own functions under sh with a
|
||||
scripted curl in front of them: a transfer that fails resumes and is
|
||||
tried again, the failures that waiting cannot fix end the tries at once,
|
||||
and every step leaves a line in the install log in the log tree's own
|
||||
format."""
|
||||
import os
|
||||
import re
|
||||
import shutil
|
||||
import stat
|
||||
import subprocess
|
||||
import tempfile
|
||||
import unittest
|
||||
|
||||
import helpers # noqa: F401 (sys.path)
|
||||
|
||||
REPO = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
|
||||
SCRIPT = os.path.join(REPO, "scripts", "install-forgefirm.sh")
|
||||
MARK = "# The install log, before anything can fail."
|
||||
|
||||
# The log tree's line format (forgetest/suite/logs.py keeps the same one).
|
||||
LINE_RE = re.compile(r"^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(\.\d+)?[+-]\d\d:\d\d install\[\d+\] "
|
||||
r"(EMERG|ALERT|CRIT|ERR|WARNING|NOTICE|INFO|DEBUG) .+$")
|
||||
|
||||
# A curl that plays a script: each call takes the next "rc http bytes"
|
||||
# line of $CURL_PLAN, appends that many bytes to the --output file the way
|
||||
# a resumed transfer does, prints the HTTP code as -w '%{http_code}'
|
||||
# would, records its arguments, and exits rc.
|
||||
FAKE_CURL = r"""#!/bin/sh
|
||||
echo "$*" >> "$CURL_CALLS"
|
||||
OUT=""
|
||||
while [ $# -gt 0 ]; do
|
||||
[ "$1" = "--output" ] && OUT="$2"
|
||||
shift
|
||||
done
|
||||
LINE=$(sed -n 1p "$CURL_PLAN")
|
||||
sed -i 1d "$CURL_PLAN"
|
||||
set -- $LINE
|
||||
[ "${3:-0}" -gt 0 ] && dd if=/dev/zero bs=1 count="$3" 2>/dev/null | tr '\0' 'x' >> "$OUT"
|
||||
printf '%s' "$2"
|
||||
exit "$1"
|
||||
"""
|
||||
|
||||
|
||||
def functions():
|
||||
"""The installer up to its first action: constants and functions."""
|
||||
with open(SCRIPT, encoding="utf-8") as f:
|
||||
text = f.read()
|
||||
head, mark, _ = text.partition(MARK)
|
||||
assert mark, "the installer lost the line the tests cut it at"
|
||||
return head
|
||||
|
||||
|
||||
@unittest.skipUnless(shutil.which("sh") and os.name == "posix", "needs a POSIX sh")
|
||||
class InstallerTests(unittest.TestCase):
|
||||
def setUp(self):
|
||||
self.tmp = tempfile.mkdtemp(prefix="ffinstall-test.")
|
||||
self.addCleanup(shutil.rmtree, self.tmp, ignore_errors=True)
|
||||
self.bin = os.path.join(self.tmp, "bin")
|
||||
os.mkdir(self.bin)
|
||||
for name, body in (("curl", FAKE_CURL), ("nslookup", "#!/bin/sh\nexit 1\n"),
|
||||
("ip", "#!/bin/sh\nexit 0\n"), ("sleep", "#!/bin/sh\nexit 0\n")):
|
||||
path = os.path.join(self.bin, name)
|
||||
with open(path, "w", newline="\n") as f:
|
||||
f.write(body)
|
||||
os.chmod(path, os.stat(path).st_mode | stat.S_IXUSR)
|
||||
self.fw = os.path.join(self.tmp, "forgefirm.fw")
|
||||
self.log = os.path.join(self.tmp, "log", "install.log")
|
||||
self.calls = os.path.join(self.tmp, "curl.calls")
|
||||
self.plan = os.path.join(self.tmp, "curl.plan")
|
||||
|
||||
def run_sh(self, body, plan=()):
|
||||
with open(self.plan, "w", newline="\n") as f:
|
||||
f.write("".join("%s\n" % line for line in plan))
|
||||
open(self.calls, "w").close()
|
||||
script = "%s\nFW_FILE='%s'\nLOG_DIR='%s'\nLOG_FILE='%s'\nmkdir -p \"$LOG_DIR\"\nLOG_OK=yes\n%s\n" % (
|
||||
functions(), self.fw, os.path.dirname(self.log), self.log, body)
|
||||
env = dict(os.environ, PATH=self.bin + os.pathsep + os.environ["PATH"],
|
||||
CURL_PLAN=self.plan, CURL_CALLS=self.calls)
|
||||
return subprocess.run(["sh", "-c", script], env=env, capture_output=True, text=True, timeout=60)
|
||||
|
||||
def download(self, plan):
|
||||
r = self.run_sh('download_fw; echo "rc=$? why=$DL_WHY"', plan)
|
||||
with open(self.calls) as f:
|
||||
calls = f.read().splitlines()
|
||||
return r.stdout, calls, self.log_lines()
|
||||
|
||||
def log_lines(self):
|
||||
try:
|
||||
with open(self.log) as f:
|
||||
return f.read().splitlines()
|
||||
except OSError:
|
||||
return []
|
||||
|
||||
def test_a_clean_download_takes_one_try_and_its_name(self):
|
||||
out, calls, log = self.download(["0 200 5000"])
|
||||
self.assertIn("rc=0", out)
|
||||
self.assertEqual(len(calls), 1)
|
||||
self.assertEqual(os.path.getsize(self.fw), 5000)
|
||||
self.assertFalse(os.path.exists(self.fw + ".part"))
|
||||
self.assertTrue(any("complete on try 1, 5000 bytes" in line for line in log), log)
|
||||
|
||||
def test_a_failed_transfer_resumes_and_is_tried_again(self):
|
||||
out, calls, log = self.download(["6 000 0", "56 200 3000", "0 206 2000"])
|
||||
self.assertIn("rc=0", out)
|
||||
self.assertEqual(len(calls), 3)
|
||||
for c in calls: # every try resumes, bounded in time
|
||||
self.assertIn("-C -", c)
|
||||
self.assertIn("--connect-timeout", c)
|
||||
self.assertIn("--speed-time", c)
|
||||
self.assertEqual(os.path.getsize(self.fw), 5000) # 3000 kept, 2000 resumed
|
||||
warns = [line for line in log if " WARNING download: try " in line]
|
||||
self.assertEqual(len(warns), 2, log)
|
||||
self.assertIn("did not resolve", warns[0])
|
||||
self.assertIn("dropped mid-transfer (3000 bytes so far)", warns[1])
|
||||
self.assertIn("Trying again in 5s (try 2 of 5)", out)
|
||||
self.assertIn("Trying again in 15s (try 3 of 5)", out)
|
||||
|
||||
def test_the_tries_run_out(self):
|
||||
out, calls, log = self.download(["28 000 0"] * 5)
|
||||
self.assertIn("rc=1", out)
|
||||
self.assertIn("timed out or stalled", out)
|
||||
self.assertEqual(len(calls), 5)
|
||||
self.assertFalse(os.path.exists(self.fw))
|
||||
self.assertFalse(os.path.exists(self.fw + ".part"))
|
||||
# each failed try leaves what the network looked like
|
||||
self.assertEqual(sum("github.com does not resolve" in line for line in log), 5, log)
|
||||
|
||||
def test_a_missing_release_and_a_full_disk_end_the_tries_at_once(self):
|
||||
out, calls, _ = self.download(["22 404 0"])
|
||||
self.assertIn("rc=1", out)
|
||||
self.assertIn("HTTP 404", out)
|
||||
self.assertEqual(len(calls), 1)
|
||||
out, calls, _ = self.download(["23 200 100"])
|
||||
self.assertIn("rc=1", out)
|
||||
self.assertIn("could not be written", out)
|
||||
self.assertEqual(len(calls), 1)
|
||||
|
||||
def test_a_partial_file_the_server_will_not_resume_starts_over(self):
|
||||
out, calls, _ = self.download(["56 200 4000", "22 416 0", "0 200 5000"])
|
||||
self.assertIn("rc=0", out)
|
||||
self.assertEqual(len(calls), 3)
|
||||
self.assertEqual(os.path.getsize(self.fw), 5000) # not 9000: the stale part went
|
||||
|
||||
def test_a_tls_failure_names_the_clock(self):
|
||||
out, _, _ = self.download(["60 000 0"] * 5)
|
||||
self.assertRegex(out, r"TLS handshake failed \(a wrong clock does this: \d{4}-\d\d-\d\d")
|
||||
|
||||
def test_every_log_line_is_in_the_tree_format(self):
|
||||
self.download(["7 000 0", "0 200 10"])
|
||||
self.run_sh('log NOTICE "operator declined to continue; no changes made"')
|
||||
lines = self.log_lines()
|
||||
self.assertGreater(len(lines), 5)
|
||||
for line in lines:
|
||||
self.assertRegex(line, LINE_RE)
|
||||
|
||||
def test_die_leaves_the_reason_in_the_log(self):
|
||||
r = self.run_sh('die "archiving slot 1 failed"; echo not-reached')
|
||||
self.assertEqual(r.returncode, 1)
|
||||
self.assertNotIn("not-reached", r.stdout)
|
||||
self.assertTrue(any(" ERR install failed: archiving slot 1 failed" in line
|
||||
for line in self.log_lines()))
|
||||
|
||||
def test_no_writable_log_never_fails_the_install(self):
|
||||
r = self.run_sh('LOG_OK=""; log INFO "x"; LOG_OK=yes; LOG_FILE=/nonexistent/dir/x.log; '
|
||||
'log INFO "y"; echo "still-running rc=$?"')
|
||||
self.assertIn("still-running rc=0", r.stdout)
|
||||
|
||||
|
||||
class InstallerShapeTests(unittest.TestCase):
|
||||
"""What holds on any host, with no shell to run."""
|
||||
|
||||
def test_the_log_lives_in_the_tree_the_export_carries(self):
|
||||
head = functions()
|
||||
self.assertIn('LOG_DIR="/data/log/forgefirm/install"', head)
|
||||
self.assertIn('LOG_FILE="$LOG_DIR/install.log"', head)
|
||||
|
||||
def test_the_download_is_the_retrying_one(self):
|
||||
with open(SCRIPT, encoding="utf-8") as f:
|
||||
text = f.read()
|
||||
body = text.partition(MARK)[2]
|
||||
self.assertIn("download_fw", body)
|
||||
self.assertNotRegex(body, r"(?m)^\s*curl ") # no bare curl past the functions
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
unittest.main()
|
||||
Reference in New Issue
Block a user