diff --git a/hands/camcheck.py b/hands/camcheck.py index 84e70b6..ef75980 100755 --- a/hands/camcheck.py +++ b/hands/camcheck.py @@ -56,13 +56,19 @@ ANSI = re.compile(r"\x1b\[[0-9;]*m") STAMP = re.compile(r"^\w{3} \w{3} \d{2} \d{4} (\d{2}:\d{2}:\d{2})\.\d+ (\w+): ?(.*)$") # Lines worth reading; anything else is skipped before the regexes (the log grows by MBs a day). KEYS = ("FPGA", "VCINT", "Created", "TrackingCameraInit", "Closing tracking camera", "Streaming", - "systemd suspend", "systemd resume", "XRService logging to", "Exiting XRService") + "systemd suspend", "systemd resume", "XRService logging to", "Exiting XRService", "ISP ") +# XRService's numbering of its tracking cameras (the TrackingCameraInit index): ft-hands names +# them this way too (track/main.cpp, cameras_from_xrservice_log). +NAMES = ("slam_left", "slam_right", "upper_left", "upper_right") RE_PASSTHRU = re.compile(r"Passthrough connected but FPGA is (\S+) - loading VCINT") RE_INTERLEAVE = re.compile(r"Upper cameras FPGA interleaving support: (\d)") RE_TASKS = re.compile(r"Created (\d+) tasks \((\d+) tracking, (\d+) passthrough\)") RE_INIT = re.compile(r"TrackingCameraInit: index: (\d+)\. video device: /dev/video(\d+)") RE_STREAM = re.compile(r"Streaming resumed \(FPGA: (\S+), VC interleaving: (\w+)\)") RE_STATE = re.compile(r"FPGA state check: (\S+)") +# Without the colour module XRService runs the side cameras through the ISP, as NV12 on other +# capture pipes (vfe0 and vfe1), and the upper pair on vfe3 and vfe4. +RE_ISP = re.compile(r"ISP (enabled|disabled) for tracking cameras") class LogState: @@ -85,7 +91,7 @@ class LogState: def _new_episode(self, t): self.closed = False self.episode = {"start": t, "fpga_before": "", "vcint": "", "interleave": None, "tasks": None, - "inits": {}, "stream": "", "failure": "", "evidence": []} + "inits": {}, "stream": "", "isp": None, "failure": "", "evidence": []} if self.closed_at: self.episode["evidence"].append(self.closed_at) @@ -146,6 +152,12 @@ class LogState: ep["interleave"] = int(m.group(1)) ep["evidence"].append(short) return + m = RE_ISP.search(text) + if m: + ep = self._ep(t) + ep["isp"] = m.group(1) == "enabled" + ep["evidence"].append(short) + return m = RE_TASKS.search(text) if m: ep = self._ep(t) @@ -184,6 +196,12 @@ class LogState: got = tuple(self.nodes[i] for i in (2, 3) if i in self.nodes) return got if len(got) == 2 else UPPER_NODES + def camera_map(self): + """{calibration name: /dev/videoN's N} from the latest camera start's TrackingCameraInit + lines (the whole log's when that start has none yet).""" + inits = (self.episode or {}).get("inits") or self.nodes + return {NAMES[i]: node for i, node in sorted(inits.items()) if 0 <= i < len(NAMES)} + def tracking_nodes(self): got = tuple(self.nodes[i] for i in range(TRACKING) if i in self.nodes) return got if len(got) == TRACKING else SIDE_NODES + UPPER_NODES @@ -353,7 +371,9 @@ def check(log=None, proc=True, ring=True, ring_path=None): status, reason = "unknown", "no XRService log in %s" % LOG_DIR out = {"log": path, "xrservice": None, "ring": None, "episode": state.snapshot()["episode"] if state else {}, - "failure": state.snapshot()["failure"] if state else ""} + "failure": state.snapshot()["failure"] if state else "", + "map": {name: {"node": n, "pipe": pipe_name(n)} for name, n in state.camera_map().items()} if state else {}, + "ring_missing": []} if proc: if pid is None: @@ -389,13 +409,30 @@ def check(log=None, proc=True, ring=True, ring_path=None): evidence.append("ft-camd (pid %d, %s): %d mono cameras: %s" % ( r["writer_pid"], "running" if r["alive"] else "stale ring", len(r["mono"]), names)) if r["alive"] and len(r["mono"]) < TRACKING and status == "ok": - status, reason = "degraded", ("ft-camd publishes only %d of %d mono cameras (it started while " - "they were missing: restart it)" % (len(r["mono"]), TRACKING)) + have = {c["node"] for c in r["mono"]} + want = state.tracking_nodes() if state else SIDE_NODES + UPPER_NODES + out["ring_missing"] = [n for n in want if n not in have] + status, reason = "degraded", ("ft-camd publishes only %d of %d mono cameras (missing: %s)" % ( + len(r["mono"]), TRACKING, " ".join("video%d" % n for n in out["ring_missing"]) or "?")) out.update(status=status, reason=reason, evidence=evidence, summary="ok" if status == "ok" else "%s: %s" % (status, reason)) return out +def pipe_name(node): + """The capture pipe behind /dev/videoN (msm_vfe3_video0 and so on), or "".""" + try: + with open("/sys/class/video4linux/video%d/name" % node) as f: + return f.read().strip() + except OSError: + return "" + + +def is_ring_short(result): + """XRService runs all the tracking cameras, but ft-camd doesn't publish them all.""" + return bool(result) and result.get("status") == "degraded" and bool(result.get("ring_missing")) + + def is_vcint_failure(result): return bool(result) and result.get("status") == "degraded" and result.get("reason") == VCINT_REASON diff --git a/hands/camd/xrcams.c b/hands/camd/xrcams.c index 4dfd634..591a08d 100644 --- a/hands/camd/xrcams.c +++ b/hands/camd/xrcams.c @@ -544,22 +544,26 @@ static void probe_cameras(xr_state_t *st) /* * qcom-camss can report bytesperline as the visible width while the VFE * writes a larger aligned pitch. sizeimage is right, so derive the pitch. + * For NV12, plane 0 normally holds the chroma rows after the luma (the side + * cameras through the ISP: 1056 wide, 1152 bytes a row); if it's too small for + * that, it holds the luma alone. */ unsigned xr_camera_stride(const xr_camera_t *c) { if (!c->height || !c->planesize[0]) return c->bytesperline ? c->bytesperline : c->width; - double bpp = 1.0; - - if (c->pixfmt == V4L2_PIX_FMT_NV12 || c->pixfmt == V4L2_PIX_FMT_NV21) - bpp = 1.5; - - unsigned s = (unsigned)((double)c->planesize[0] / ((double)c->height * bpp)); + bool yuv = c->pixfmt == V4L2_PIX_FMT_NV12 || c->pixfmt == V4L2_PIX_FMT_NV21; + unsigned s = (unsigned)((double)c->planesize[0] / ((double)c->height * (yuv ? 1.5 : 1.0))); if (s >= c->width && s <= c->width * 4) return s; + s = (unsigned)(c->planesize[0] / c->height); + + if (yuv && s >= c->width && s <= c->width * 4) + return s; + return c->bytesperline ? c->bytesperline : c->width; } @@ -591,7 +595,20 @@ void xr_camera_layout(const xr_camera_t *c, xr_layout_t *l) l->pitch = xr_camera_stride(c); l->width = c->width < l->pitch ? c->width : l->pitch; - if (c->pixfmt == V4L2_PIX_FMT_NV12 || c->pixfmt == V4L2_PIX_FMT_NV21) { + /* + * Without the colour module, XRService runs the side cameras through the + * ISP ("ISP enabled for tracking cameras (main VFE available)" in its log), + * and they come out NV12. They're mono sensors, so the luma is the image. + */ + bool yuv = c->pixfmt == V4L2_PIX_FMT_NV12 || c->pixfmt == V4L2_PIX_FMT_NV21; + + if (yuv && c->role && !strcmp(c->role, "tracking")) { + l->fmt = XR_FMT_GREY8; + l->rows = c->height; + return; + } + + if (yuv) { l->fmt = XR_FMT_NV12; l->rows = c->height + c->height / 2; } else { diff --git a/hands/rec/ft_handrec.py b/hands/rec/ft_handrec.py index 49a323c..5af73aa 100755 --- a/hands/rec/ft_handrec.py +++ b/hands/rec/ft_handrec.py @@ -457,11 +457,12 @@ class Backend(QObject): """Start stays off: the check found the cameras degraded (unless --ignore-cameras).""" return not self._ignore_cameras and self._camera.get("status") == "degraded" - def _check_now(self): + def _check_now(self, repair=False): + """repair (off this thread only: it may restart ft-camd, up to 15 s): see session.camera_check.""" mod = self._runner() if not mod or self._session_options.get("dry_run"): return {"status": "unknown", "summary": "not checked (dry run)", "reason": "dry run", "evidence": []} - return mod.camera_check() + return mod.camera_check(repair=repair) @Slot() def checkCameras(self): @@ -470,7 +471,7 @@ class Backend(QObject): return self._camera_busy = True self.cameraChanged.emit() - self._thread(lambda: self._cameraArrived.emit(self._check_now())) + self._thread(lambda: self._cameraArrived.emit(self._check_now(repair=True))) def _on_camera(self, result): self._camera = result @@ -499,7 +500,7 @@ class Backend(QObject): end = time.monotonic() + RECHECK_FOR_S time.sleep(RECHECK_S * 2) while time.monotonic() < end: - result = self._check_now() + result = self._check_now(repair=True) # Done once a new XRService (a new log) has opened its cameras, ok or not. if result.get("status") in ("ok", "degraded") and result.get("log") != before: break diff --git a/hands/rec/session.py b/hands/rec/session.py index 33ab5d2..dfae52a 100755 --- a/hands/rec/session.py +++ b/hands/rec/session.py @@ -1153,11 +1153,33 @@ def _steamvr_version(): return "" -def camera_check(): - """camcheck.check() (the XRService log, its open cameras where readable, ft-camd's ring); - never raises: a failure is "unknown".""" +_camd_restarted = set() # ft-camd pids camera_check(repair=True) has restarted: once each + + +def _unit_pid(unit): + r = subprocess.run(host_command("systemctl", "--user", "show", "-p", "MainPID", "--value", unit), + capture_output=True, text=True, timeout=30) try: - return camcheck.check() + return int(r.stdout.strip() or 0) + except ValueError: + return 0 + + +def camera_check(repair=False): + """camcheck.check() (the XRService log, its open cameras where readable, ft-camd's ring); + never raises: a failure is "unknown". repair (the window, never during a session): when + XRService runs every tracking camera but the recorder's own ft-camd doesn't publish them all + (it started while some were missing), restart it, once per ft-camd, and check again.""" + try: + r = camcheck.check() + pid = (r.get("ring") or {}).get("writer_pid") + if repair and camcheck.is_ring_short(r) and pid not in _camd_restarted and _unit_pid(CAMD_UNIT) == pid: + _camd_restarted.add(pid) + stop_unit(CAMD_UNIT) + start_camd() + r = camcheck.check() + r["evidence"].append("restarted ft-camd (pid %d) because it published only some of the cameras" % pid) + return r except Exception as e: return {"status": "unknown", "summary": "unknown: the camera check failed (%s)" % e, "reason": str(e), "evidence": []} @@ -1169,6 +1191,10 @@ def camera_text(result): return "" if camcheck.is_vcint_failure(result): return camcheck.USER_TEXT + if camcheck.is_ring_short(result): + return ("The headset's tracking cameras are all running, but the recorder can't read some of them (%s). " + "Close the Hand Recorder, run ~/frametop/hands/rec/install.sh again, and open it again. If that " + "doesn't help, ask in the Frametop Discord." % result.get("reason", "")) return ("Not all of the headset's tracking cameras are running (%s). Restart SteamVR, or restart the " "headset if that doesn't fix it." % result.get("reason", "")) @@ -1451,6 +1477,10 @@ class Session: cam = self._status.get("camera") if cam: self._session_json["camera"] = {"status": cam.get("status"), "reason": cam.get("reason", "")} + # which device each calibrated camera was (XRService's numbering) and whether XRService + # ran the side cameras through the ISP (no colour module): to check the names later + self._session_json["device"]["camera_map"] = cam.get("map") or {} + self._session_json["device"]["isp"] = (cam.get("episode") or {}).get("isp") if self.dry_run: self._session_json["dry_run"] = True if self.speed != 1: diff --git a/hands/tests/test_camcheck.py b/hands/tests/test_camcheck.py index fe58216..69cc887 100644 --- a/hands/tests/test_camcheck.py +++ b/hands/tests/test_camcheck.py @@ -66,6 +66,22 @@ RESUME_OK = [L("12:30:00", "[SystemdInhibitor] Received systemd resume notificat for i, n in enumerate((9, 13, 6, 7))] + \ [L("12:30:02", "[DeckardCaptureSource] Streaming resumed (FPGA: VCINT, VC interleaving: enabled)")] EXIT = [L("13:00:00", "XRService - main thread exiting"), L("13:00:00", "Exiting XRService")] +# The colour module unplugged while SteamVR runs (2026-10-05 12:42): XRService reopens the +# cameras with the side pair through the ISP on vfe0 and vfe1 (NV12); VCINT stays loaded, so the +# upper pair stays on vfe2. +UNPLUG = [L("12:42:25", "Received passthrough camera connection event (connected=0)"), + L("12:42:25", "[DeckardCaptureSource] Closing tracking camera interfaces camerasToUse: 1111"), + L("12:42:26", "FPGA state check: VCINT (register value: 0x00021211)"), + L("12:42:26", "Upper cameras FPGA interleaving support: 1 (Driver features available = 1 | VCINT loaded = 1)"), + L("12:42:26", "[buildMediaCtlSetupTasks] ISP enabled for tracking cameras (main VFE available)"), + L("12:42:26", "[buildMediaCtlSetupTasks] Created 4 tasks (4 tracking, 0 passthrough)")] + \ + [L("12:42:26", "TrackingCameraInit: index: %d. video device: /dev/video%d. v4l subdevice: x" % (i, n)) + for i, n in enumerate((0, 3, 6, 7))] +# Started without the module (FrameEyeCameraFeed's layout): the upper pair on vfe3 and vfe4. +NO_MODULE = [L("10:00:02", "[buildMediaCtlSetupTasks] ISP enabled for tracking cameras (main VFE available)"), + L("10:00:02", "[buildMediaCtlSetupTasks] Created 4 tasks (4 tracking, 0 passthrough)")] + \ + [L("10:00:03", "TrackingCameraInit: index: %d. video device: /dev/video%d. v4l subdevice: x" % (i, n)) + for i, n in enumerate((0, 3, 9, 13))] def state(lines): @@ -128,6 +144,23 @@ class SyntheticLogs(unittest.TestCase): self.assertEqual(status, "degraded") self.assertEqual(reason, "only 2 of 4 tracking cameras running") + def test_camera_map_with_module(self): + st = state(START + GOOD_OPEN) + self.assertEqual(st.camera_map(), {"slam_left": 9, "slam_right": 13, "upper_left": 6, "upper_right": 7}) + + def test_module_unplugged(self): + st = state(START + GOOD_OPEN + UNPLUG) + self.assertEqual(st.verdict()[0], "ok") + self.assertIs(st.episode["isp"], True) + self.assertEqual(st.camera_map(), {"slam_left": 0, "slam_right": 3, "upper_left": 6, "upper_right": 7}) + self.assertEqual(st.tracking_nodes(), (0, 3, 6, 7)) + + def test_started_without_module(self): + st = state(START + NO_MODULE) + self.assertEqual(st.verdict()[0], "ok") + self.assertEqual(st.camera_map(), {"slam_left": 0, "slam_right": 3, "upper_left": 9, "upper_right": 13}) + self.assertEqual(st.upper_nodes(), (9, 13)) + def test_exited_and_empty(self): self.assertEqual(state(START + GOOD_OPEN + EXIT).verdict()[0], "unknown") self.assertEqual(state([]).verdict()[0], "unknown") @@ -223,9 +256,9 @@ class RealLog(unittest.TestCase): self.assertEqual(out.getvalue().split("\n")[0], "ok") -def make_ring(path, mono_names, alive=True): +def make_ring(path, mono_names, alive=True, nodes=None): """A ring header as ft-camd writes it (camd/fhring.h), no frames.""" - cams = [(b"og01a1b", n.encode(), 9 + i) for i, n in enumerate(mono_names)] + cams = [(b"og01a1b", n.encode(), nodes[i] if nodes else 9 + i) for i, n in enumerate(mono_names)] hb = time.clock_gettime_ns(time.CLOCK_MONOTONIC) if alive else 1 data = bytearray(camcheck.RING_HDR.pack(b"FHRING01", 1, 0, len(cams), 0, 0, 4242, 0)) struct.pack_into(" cameras_from_xrservice_log() { + static const char *const names[] = {"slam_left", "slam_right", "upper_left", "upper_right"}; + const char *home = std::getenv("HOME"); + std::ifstream in(std::string(home ? home : "") + "/.local/share/Steam/logs/xrservice.txt"); + const std::string key = "TrackingCameraInit: index: "; + std::map node_of; // index -> N of /dev/videoN, from the latest camera start + std::string line; + while (std::getline(in, line)) { + if (line.find("XRService logging to") != std::string::npos) node_of.clear(); + const auto at = line.find(key); + int index = -1, node = -1; + if (at != std::string::npos && + std::sscanf(line.c_str() + at + key.size(), "%d. video device: /dev/video%d", &index, &node) == 2 && + index >= 0 && index < 4) + node_of[index] = node; + } + std::map out; + for (auto &[index, node] : node_of) out[node] = names[index]; + return out; +} + const char *camera_for_pipe(int node) { char path[64], name[64] = ""; std::snprintf(path, sizeof path, "/sys/class/video4linux/video%d/name", node); @@ -302,6 +329,7 @@ int main(int argc, char **argv) { double decided_after_s = -1; if (sides_mode != "auto") truth = names_swapped, decided_by = sides_from, sides_state = "forced"; std::string rec_dir; + std::string cams_json; // which device each calibrated camera is (set below), for the sides files std::vector> rec_names; // from which recorded set on, names_swapped was what // DIR/sides.json beside a recording's sets.bin: how its side cameras are named. A set's // names are right when its names_swapped equals swapped (null: not known when recorded). @@ -312,7 +340,8 @@ int main(int argc, char **argv) { write_file(rec_dir + "/sides.json", "{\"swapped\": " + json_bool(truth) + ", \"decided_by\": " + json_str(truth ? decided_by : "") + ", \"names_swapped\": [" + runs + "]" + - (decision_evidence.empty() ? "" : ", \"evidence\": " + decision_evidence) + "}\n"); + (decision_evidence.empty() ? "" : ", \"evidence\": " + decision_evidence) + + (cams_json.empty() ? "" : ", \"cameras\": " + cams_json) + "}\n"); }; auto start_recording = [&](const std::string &dir, std::string &e) { rec = std::make_unique(); @@ -340,19 +369,42 @@ int main(int argc, char **argv) { // (--with-color). Recorded names hold 15 characters, so "upper_right_dark" wouldn't fit. std::map dark; std::map used; + // ft-camd's cameras by XRService's numbering, else by capture pipe (see camera_for_pipe); + // ft-ringplay's (no device) by the name it gives + const std::map by_log = cameras_from_xrservice_log(); + const char *named_by = by_log.empty() ? "capture pipe" : "XRService's log"; for (int i = 0; i < ring.cameras(); ++i) { - if (ring.camera(i).flags & FH_CAM_COLOR) { - const std::string name = "color_video" + std::to_string(ring.camera(i).node); + const fh_ring_cam_t &rc = ring.camera(i); + if (rc.flags & FH_CAM_COLOR) { + const std::string name = "color_video" + std::to_string(rc.node); dark[name] = i, color[name] = i; continue; } - // ft-camd's cameras by capture pipe; ft-ringplay's (no device) by the name it gives - const char *name = camera_for_pipe(ring.camera(i).node); - if (!name && ring.camera(i).node < 0) name = ring.camera(i).name; - if (!name || !calib.count(name)) continue; - if (ring.camera(i).flags & FH_CAM_DARK) dark[std::string(name) + "_dk"] = i; - else index[name] = i, used[name] = calib[name]; + const auto it = by_log.find(rc.node); + const char *name = rc.node < 0 ? rc.name + : !by_log.empty() ? (it == by_log.end() ? nullptr : it->second.c_str()) + : camera_for_pipe(rc.node); + if (!name || !calib.count(name)) { + if (!(rc.flags & FH_CAM_DARK)) std::fprintf(stderr, "video%d (%s): not one of the calibrated cameras, left out\n", rc.node, rc.name); + continue; + } + if (int(rc.width) != calib[name].width || int(rc.height) != calib[name].height) { + std::fprintf(stderr, "video%d (%s) is %ux%u, but %s is calibrated at %dx%d: left out\n", rc.node, rc.name, + rc.width, rc.height, name, calib[name].width, calib[name].height); + continue; + } + if (rc.flags & FH_CAM_DARK) { + dark[std::string(name) + "_dk"] = i; + } else if (index.count(name)) { + std::fprintf(stderr, "video%d (%s) would be %s too (video%d is): left out\n", rc.node, rc.name, name, + ring.camera(index[name]).node); + } else { + index[name] = i, used[name] = calib[name]; + cams_json += std::string(cams_json.empty() ? "" : ", ") + json_str(name) + ": {\"node\": " + + std::to_string(rc.node) + ", \"ring\": " + json_str(rc.name) + "}"; + } } + cams_json = "{\"named_by\": " + json_str(named_by) + ", \"cameras\": {" + cams_json + "}}"; // ft-camd tells the side cameras' buffers apart by XRService's allocation order, which // some XRService restarts reverse (see the top). const bool have_sides = index.count("slam_left") && index.count("slam_right"); @@ -397,7 +449,7 @@ int main(int argc, char **argv) { } const bool switching = automatic && !color.empty(); Cams mode = switching || color.empty() ? Cams::Mono : fixed; - std::printf("cameras:"); + std::printf("cameras (by %s):", named_by); for (auto &[name, i] : index) std::printf(" %s=video%d", name.c_str(), ring.camera(i).node); for (auto &[name, i] : color) std::printf(" %s", name.c_str()); std::printf(" tracking with %s%s models: %s%s, %d threads on CPUs", cams_name(mode), @@ -446,6 +498,7 @@ int main(int argc, char **argv) { ", \"decided_after_s\": " + std::to_string(decided_after_s) + ", \"evidence\": " + (decision_evidence.empty() ? "null" : decision_evidence) + ", \"checking\": " + (checking ? side_check.json() : "null") + + ", \"cameras\": " + (cams_json.empty() ? "null" : cams_json) + ", \"updated_ns\": " + std::to_string(mono_ns()) + "}\n"); }; write_sides();