trigger OVP while RCU moving

Bound serial close so a dead port cannot hang the run
When a USB-serial adapter disappears mid-run, writes to the open handle fail with PermissionError, but serial.close() can block forever. Cleanup then wedged after the second port closed and Ctrl+C could not break out, because the main thread was stuck inside a blocking Windows call. Close on a daemon thread and give up after CLOSE_TIMEOUT_S, so an abandoned port can never hold up the exit. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-28 16:09:26 +08:00 · 2026-09-23 15:11:36 +08:00
1 changed files with 296 additions and 25 deletions
@@ -15,27 +15,33 @@ answers nothing. So the relay is closed and given RELAY_SETTLE_S to boot the
 RCU before any RCU access anywhere in this script - the link test included -
 and while the relay is open the RCU telemetry columns are left blank.

-Per cycle:
-    1. Relay control = 1, then wait RELAY_SETTLE_S for the RCU to power up.
+Two scenarios, picked with --scenario. Both establish charging and then cut
+the relay; they differ only in when the cut lands.
+
+  static (default), jig optional:
+    1. Relay control = 1, wait RELAY_SETTLE_S for the RCU to power up.
    2. Jig -> NEAR_POSITION, settle.
-    3. RCU charging cmd = 1, then wait for RCU main_state == CHARGING(5) and
-       output current above the threshold held continuously for the dwell.
-       Abort the cycle on timeout.
+    3. RCU charging cmd = 1, wait for RCU main_state == CHARGING(5) and output
+       current above the threshold held continuously for the dwell.
    4. Relay control = 0 (this also cuts RCU power).
    5. Jig -> FAR_POSITION, keep monitoring for FAR_OBSERVE_S.
-    6. RCU charging cmd = 0 (best-effort; the RCU is unpowered by now),
-       settle, next cycle.
+    6. RCU charging cmd = 0, settle, next cycle.

-A background monitor thread samples RCU and TPU input registers every 5 s for
-the whole run (all cycles, including the aborted ones) and appends each sample
-to the CSV.
+  move, jig required - the cut lands while the coupling is still changing:
+    1-3. As above, but parked at (0, 0, --move-from).
+    4. Jig -> (0, 0, --move-to), relay cut at half the travel time.
+    5. RCU charging cmd = 0, settle.
+    6. Jig back to (0, 0, --move-from), last, so the whole post-cut window is
+       observed at a standstill.
+
+A background monitor thread samples RCU and TPU input registers every
+MONITOR_INTERVAL_S for the whole run and appends each sample to the CSV.

 Usage:
-    # check the wiring: read registers from all four ports, then exit
    python BE-RCU-ovp_test_csv.py -r COM4 -t COM10 -l COM13 -j COM9 --link-test
-
-    # run the test (the link test also runs as a pre-flight check)
-    python BE-RCU-ovp_test_csv.py -r COM4 -t COM10 -l COM13 -j COM9 -n 1
+    python BE-RCU-ovp_test_csv.py -r COM4 -t COM10 -l COM13 -n 1
+    python BE-RCU-ovp_test_csv.py -r COM4 -t COM10 -l COM13 -j COM9 \
+        --scenario move --move-from 20 --move-to 0 -n 1
 """

 import argparse
@@ -56,6 +62,7 @@ import minimalmodbus
 SLAVE_ID = 0x10          # all four devices share slave id 16
 BAUDRATE = 9600
 SERIAL_TIMEOUT = 2.0     # seconds
+CLOSE_TIMEOUT_S = 3.0    # give up on a port that will not close


 # ---------------------------------------------------------------------------
@@ -130,12 +137,20 @@ FAR_POSITION = (30, 0, 20)          # (x, y, z) mm - move-away position

 JIG_SETTLE_S = 5.0                  # after the near move, before the relay
 CHARGING_TIMEOUT_S = 60.0           # max wait for the charging criteria
-CHARGING_DWELL_S = 30.0             # current must stay above threshold this long
+CHARGING_DWELL_S = 10.0             # current must stay above threshold this long
 CHARGING_CURRENT_THRESHOLD_A = 3.0
 FAR_OBSERVE_S = 15.0                # keep monitoring after the move-away
 CYCLE_GAP_S = 5.0                   # after charging cmd = 0
 MONITOR_INTERVAL_S = 2.0            # telemetry sampling / CSV row period
-RELAY_SETTLE_S = 10.0               # time to wait for relay to settle
+RELAY_SETTLE_S = 2.0                # time to wait for relay to settle
+
+# --- Scenario "move": cut the relay midway through a jig move --------------
+MOVE_X_MM = 0                       # held for the whole scenario; only Z moves
+MOVE_Y_MM = 0
+MOVE_Z_FROM_MM = 20                 # where the move starts - the charging spot
+MOVE_Z_TO_MM = 0                    # where it ends
+JIG_SPEED_MM_S = 10.0               # override with --jig-speed
+JIG_MOVE_MAX_S = 5.0                # time allowed for one move, in or out

 RESULTS_DIR = "results"

@@ -217,6 +232,17 @@ class Device:
        return reads

    def close(self):
+        # A USB adapter unplugged mid-run wedges serial.close() forever, and
+        # Ctrl+C cannot break a blocking Windows call. Close on a daemon
+        # thread so a dead port can never hold up the exit.
+        closer = threading.Thread(target=self._close_serial, daemon=True)
+        closer.start()
+        closer.join(CLOSE_TIMEOUT_S)
+        if closer.is_alive():
+            logger.warning("%s: %s did not close in %.0fs, abandoning it",
+                           self.name, self.port, CLOSE_TIMEOUT_S)
+
+    def _close_serial(self):
        try:
            self.inst.serial.close()
            logger.info("%s disconnected", self.name)
@@ -285,8 +311,15 @@ class RCU(Device):
        self.write_coil(RCU_CHARGING_CMD_ADDRESS, enable)

    def read_data(self):
+        # Probe once: a dead RCU costs 9 x SERIAL_TIMEOUT otherwise.
+        try:
+            main_pre_state = self.read_u16(RCU_MAIN_PRE_STATE_ADDRESS)
+        except Exception as exc:
+            logger.debug("RCU did not answer: %s", exc)
+            return dict(BLANK_RCU_DATA)
+
        return {
-            'main_pre_state': _safe(self.read_u16, RCU_MAIN_PRE_STATE_ADDRESS),
+            'main_pre_state': main_pre_state,
            'main_state': _safe(self.read_u16, RCU_MAIN_STATE_ADDRESS),
            'output_current': _q128(
                _safe(self.read_u16, RCU_OUTPUT_CURRENT_ADDRESS)),
@@ -366,11 +399,13 @@ class Jig(Device):
        super().__init__(port, "JIG")

    def move_to(self, x, y, z):
+        """Command a move. Returns the perf_counter() of the go command."""
        logger.info("JIG move to (%d, %d, %d) mm", x, y, z)
        self.write_holding(JIG_X_ADDRESS, x)
        self.write_holding(JIG_Y_ADDRESS, y)
        self.write_holding(JIG_Z_ADDRESS, z)
        self.write_coil(JIG_CMD_ADDRESS, True)
+        return time.perf_counter()


 # ---------------------------------------------------------------------------
@@ -587,6 +622,28 @@ class Monitor(threading.Thread):
        with self._state_lock:
            return dict(self._latest)

+    def write_event(self, phase, note):
+        """Append one row now, telemetry blank. set_context() only paints the
+        next periodic sample, which is too late to record an instant."""
+        with self._state_lock:
+            cycle = self._cycle
+            jig_x, jig_y, jig_z = self._jig
+            relay_cmd, charging_cmd = self._relay_cmd, self._charging_cmd
+            powered = self._rcu_powered
+
+        blank = dict(BLANK_RCU_DATA)
+        self.recorder.write([
+            datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")[:-3],
+            round(time.time() - self.t0, 1), cycle, phase,
+            jig_x, jig_y, jig_z, relay_cmd, charging_cmd, int(powered),
+            blank['main_pre_state'], blank['main_state'],
+            blank['output_current'], blank['output_voltage'],
+            blank['dc_bus_voltage'], blank['error_code'],
+            blank['shadow_error'],
+            None, None, None, None, None, '', '', '',
+            None, 0.0, note,
+        ])
+
    def stop(self):
        self._stop.set()

@@ -663,8 +720,30 @@ def _wait(seconds, stop_when=None, poll=0.2):
    return False


+def _cut_relay(relay, retry=True):
+    """Open the relay, tolerating one lost frame. Returns True if it landed."""
+    try:
+        relay.set_control(False)
+        return True
+    except Exception as exc:
+        logger.warning("Relay cut not acknowledged: %s", exc)
+        if not retry:
+            return False
+
+    try:
+        relay.set_control(False)
+        logger.info("Relay cut acknowledged on retry.")
+        return True
+    except Exception as exc:
+        logger.error("Relay cut failed twice: %s", exc)
+        return False
+
+
 def run_cycle(cycle, rcu, relay, jig, monitor, cfg):
-    """Run one OVP cycle. Returns 'PASS' or 'TIMEOUT'."""
+    """Run one OVP cycle with the jig standing still.
+
+    Returns 'PASS', 'TIMEOUT' or 'CUT_FAILED'.
+    """
    logger.info("=" * 62)
    logger.info("CYCLE %d/%d", cycle, cfg['cycles'])

@@ -714,8 +793,10 @@ def run_cycle(cycle, rcu, relay, jig, monitor, cfg):

    # Step 4: open the relay. This also cuts the RCU's power, so from here on
    # the RCU is dead and its telemetry columns stay blank.
-    relay.set_control(False)
-    monitor.set_context(phase="relay_off", relay_cmd=0, rcu_powered=False)
+    if not _cut_relay(relay):
+        result = "CUT_FAILED"
+    monitor.set_context(phase="relay_off", relay_cmd=0, rcu_powered=False,
+                        note=result)

    # Step 5: move away, keep monitoring. Without a jig there is nothing to
    # move, so this becomes a plain observation window after the relay opens.
@@ -742,6 +823,123 @@ def run_cycle(cycle, rcu, relay, jig, monitor, cfg):
    return result


+def move_timing(cfg):
+    """(distance_mm, travel_s, trigger_s). --trigger-at only pulls it earlier."""
+    distance = abs(cfg['move_from'] - cfg['move_to'])
+    travel = distance / cfg['jig_speed']
+    trigger = travel / 2.0
+    if cfg.get('trigger_at') is not None:
+        trigger = min(trigger, cfg['trigger_at'])
+    return distance, travel, trigger
+
+
+def run_cycle_move(cycle, rcu, relay, jig, monitor, cfg):
+    """One OVP cycle with the relay cut midway through a jig move.
+
+    Returns 'PASS', 'TIMEOUT' or 'CUT_FAILED'.
+    """
+    distance, travel_s, trigger_s = move_timing(cfg)
+    home = (cfg['move_x'], cfg['move_y'], cfg['move_from'])
+    target = (cfg['move_x'], cfg['move_y'], cfg['move_to'])
+
+    logger.info("=" * 62)
+    logger.info("CYCLE %d/%d  (move scenario)", cycle, cfg['cycles'])
+
+    # Step 1: close the relay and let the RCU boot.
+    monitor.set_context(cycle=cycle, phase="relay_on", relay_cmd=1, note="")
+    power_up_rcu(relay)
+    monitor.set_context(rcu_powered=True)
+
+    # Step 2: park at the charging position.
+    monitor.set_context(phase="jig_home", jig=home)
+    jig.move_to(*home)
+    _wait(JIG_MOVE_MAX_S)
+
+    # Step 3: charge, and wait for it to be established - the cut means
+    # nothing until then.
+    monitor.reset_dwell()
+    monitor.set_context(phase="charging", charging_cmd=1)
+    rcu.set_charging(True)
+
+    logger.info(
+        "Waiting for RCU main_state=%d and output current > %.1f A held for "
+        "%.0fs (timeout %.0fs)...",
+        RCU_STATE_CHARGING, cfg['current_threshold'], cfg['dwell'],
+        cfg['timeout'])
+
+    met = _wait(cfg['timeout'],
+                stop_when=lambda: monitor.dwell_seconds() >= cfg['dwell'])
+    result = "PASS" if met else "TIMEOUT"
+
+    if met:
+        logger.info("Cycle %d: criteria met after %.1fs of dwell.",
+                    cycle, monitor.dwell_seconds())
+    else:
+        latest = monitor.latest().get('rcu', {})
+        logger.warning(
+            "Cycle %d: TIMEOUT after %.0fs (last RCU state=%s, current=%s A).",
+            cycle, cfg['timeout'], latest.get('main_state'),
+            latest.get('output_current'))
+
+    monitor.set_context(note=result)
+
+    # Step 4: the move, with the relay cut partway through it.
+    logger.info("Moving %d mm (%.2fs), cutting relay at %.2fs",
+                distance, travel_s, trigger_s)
+    monitor.set_context(phase="jig_move", jig=target)
+    t_go = jig.move_to(*target)
+
+    # Sleep straight through, not via _wait(): its 0.2s poll is far too coarse
+    # for a sub-second target.
+    remaining = (t_go + trigger_s) - time.perf_counter()
+    if remaining > 0:
+        time.sleep(remaining)
+
+    # write_coil, not set_control(): that helper logs before it writes, and a
+    # Windows console write blocks while text is selected in the terminal -
+    # which here would swallow the cut itself. Log afterwards.
+    try:
+        relay.write_coil(RELAY_CONTROL_CMD_ADDRESS, False)
+        achieved = time.perf_counter() - t_go
+        cut_ok = True
+    except Exception as exc:
+        achieved = time.perf_counter() - t_go
+        logger.warning("Relay cut not acknowledged at %.3fs: %s", achieved, exc)
+        cut_ok = _cut_relay(relay, retry=False)
+
+    monitor.set_context(phase="relay_cut", relay_cmd=0, rcu_powered=False)
+
+    note = "cut at %.3fs of %.2fs travel" % (achieved, travel_s)
+    if not cut_ok:
+        result = "CUT_FAILED"
+        note = "CUT_FAILED: " + note
+    logger.info("RELAY %s", note)
+
+    monitor.write_event("relay_cut", note)
+    monitor.set_context(note=result)
+
+    _wait(max(0.0, JIG_MOVE_MAX_S - achieved))
+
+    # Step 5: stop charging. Best-effort - the RCU lost power at the cut.
+    try:
+        rcu.set_charging(False)
+    except Exception as exc:
+        logger.info("Charging cmd = 0 not acknowledged, as expected with the "
+                    "relay open and the RCU unpowered (%s).", exc)
+    monitor.set_context(phase="charging_off", charging_cmd=0)
+    _wait(CYCLE_GAP_S)
+
+    # Step 6: back to the charging position, last thing in the cycle, so the
+    # whole post-cut window is observed at a standstill.
+    monitor.set_context(phase="jig_return", jig=home)
+    jig.move_to(*home)
+    _wait(JIG_MOVE_MAX_S)
+    monitor.set_context(note="")
+
+    logger.info("Cycle %d finished: %s", cycle, result)
+    return result
+
+
 def ovp_test(rcu_port, tpu_port, relay_port, jig_port, cycles, cfg, stamp):
    os.makedirs(RESULTS_DIR, exist_ok=True)
    csv_path = os.path.join(RESULTS_DIR, "ovp_test_%s.csv" % stamp)
@@ -795,9 +993,9 @@ def ovp_test(rcu_port, tpu_port, relay_port, jig_port, cycles, cfg, stamp):
                            relay_cmd=1, charging_cmd=0, rcu_powered=True)
        monitor.start()

+        runner = run_cycle_move if cfg['scenario'] == 'move' else run_cycle
        for cycle in range(1, cycles + 1):
-            results.append(
-                run_cycle(cycle, rcu, relay, jig, monitor, cfg))
+            results.append(runner(cycle, rcu, relay, jig, monitor, cfg))

    except KeyboardInterrupt:
        logger.warning("Interrupted by user.")
@@ -832,10 +1030,13 @@ def ovp_test(rcu_port, tpu_port, relay_port, jig_port, cycles, cfg, stamp):

        # Nothing to summarise if we bailed out before logging started.
        if recorder is not None:
-            passed = results.count("PASS")
+            # CUT_FAILED is counted apart from TIMEOUT: the relay never opened,
+            # so the cycle proves nothing either way about the RCU.
            logger.info("=" * 62)
-            logger.info("Cycles run: %d/%d  |  PASS: %d  |  TIMEOUT: %d",
-                        len(results), cycles, passed, len(results) - passed)
+            logger.info("Cycles run: %d/%d  |  PASS: %d  |  TIMEOUT: %d  "
+                        "|  CUT_FAILED: %d",
+                        len(results), cycles, results.count("PASS"),
+                        results.count("TIMEOUT"), results.count("CUT_FAILED"))
            for i, res in enumerate(results, start=1):
                logger.info("  cycle %d: %s", i, res)
            logger.info("Results saved to: %s", os.path.abspath(csv_path))
@@ -878,6 +1079,37 @@ def main():
    parser.add_argument("--interval", type=float, default=MONITOR_INTERVAL_S,
                        help="Telemetry sampling interval in seconds "
                             "(default: %(default)s)")
+    parser.add_argument("--scenario", choices=("static", "move"),
+                        default="static",
+                        help="static: cut the relay with the jig still. "
+                             "move: cut it partway through a jig move, which "
+                             "needs a jig (default: %(default)s)")
+    # int, not float: Device.write_holding does `value & 0xFFFF`.
+    parser.add_argument("--move-x", type=int, default=MOVE_X_MM, metavar="X",
+                        help="Scenario move: X in mm, held for the whole "
+                             "scenario (default: %(default)s)")
+    parser.add_argument("--move-y", type=int, default=MOVE_Y_MM, metavar="Y",
+                        help="Scenario move: Y in mm, held for the whole "
+                             "scenario (default: %(default)s)")
+    parser.add_argument("--move-from", type=int, default=MOVE_Z_FROM_MM,
+                        metavar="Z",
+                        help="Scenario move: Z in mm where the move starts, "
+                             "also the charging position "
+                             "(default: %(default)s)")
+    parser.add_argument("--move-to", type=int, default=MOVE_Z_TO_MM,
+                        metavar="Z",
+                        help="Scenario move: Z in mm where the move ends "
+                             "(default: %(default)s)")
+    parser.add_argument("--trigger-at", type=float, default=None,
+                        metavar="SECONDS",
+                        help="Scenario move: seconds after the go command to "
+                             "cut the relay (default: half the travel time). "
+                             "Only pulls the cut earlier")
+    parser.add_argument("--jig-speed", type=float, default=JIG_SPEED_MM_S,
+                        metavar="MM_S",
+                        help="Scenario move: jig speed in mm/s. Decides where "
+                             "the cut lands, and the jig cannot confirm it - "
+                             "measure it (default: %(default)s)")
    args = parser.parse_args()

    if not args.link_test:
@@ -888,6 +1120,29 @@ def main():
    if args.dwell > args.timeout:
        parser.error("--dwell cannot exceed --timeout")

+    if args.scenario == "move" and not args.link_test:
+        if not args.jig:
+            parser.error("--scenario move needs -j/--jig")
+        if args.jig_speed <= 0:
+            parser.error("--jig-speed must be positive")
+        if args.trigger_at is not None and args.trigger_at <= 0:
+            parser.error("--trigger-at must be positive")
+
+        distance = abs(args.move_from - args.move_to)
+        if distance == 0:
+            parser.error("--move-from and --move-to are the same")
+        travel = distance / args.jig_speed
+
+        # The whole travel, not half: step 5 re-commands the jig after
+        # JIG_MOVE_MAX_S, and a new target mid-move is undocumented behaviour.
+        if travel > JIG_MOVE_MAX_S:
+            parser.error("%d mm at %.1f mm/s takes %.1fs, over the %.1fs "
+                         "move window (JIG_MOVE_MAX_S)"
+                         % (distance, args.jig_speed, travel, JIG_MOVE_MAX_S))
+        if travel / 2.0 < 0.2:
+            print("WARNING: only %.0f ms before the cut; Modbus latency is "
+                  "15-35 ms" % (travel / 2.0 * 1000), file=sys.stderr)
+
    os.makedirs(RESULTS_DIR, exist_ok=True)

    # One log per run, stamped like its CSV so the two pair up by name. A
@@ -917,7 +1172,23 @@ def main():
        'timeout': args.timeout,
        'interval': args.interval,
        'link_test': not args.no_link_test,
+        'scenario': args.scenario,
+        'move_x': args.move_x,
+        'move_y': args.move_y,
+        'move_from': args.move_from,
+        'move_to': args.move_to,
+        'jig_speed': args.jig_speed,
+        'trigger_at': args.trigger_at,
    }
+
+    if args.scenario == "move":
+        distance, travel, trigger = move_timing(cfg)
+        logger.info("Scenario move: (%d,%d,%d) -> (%d,%d,%d), %d mm at "
+                    "%.1f mm/s = %.2fs travel, cut at %.2fs",
+                    args.move_x, args.move_y, args.move_from,
+                    args.move_x, args.move_y, args.move_to,
+                    distance, args.jig_speed, travel, trigger)
+
    ovp_test(args.rcu, args.tpu, args.relay, args.jig, args.cycles, cfg,
             stamp)