From 6854118aa2343c8ef5b142e5774088acea21ae71 Mon Sep 17 00:00:00 2001 From: dirwin31 <83434411+dirwin31@users.noreply.github.com> Date: Sun, 1 Nov 2026 13:41:21 -0800 Subject: [PATCH] Wait out an unreachable car by why it was unreachable Most failed drives in Bugsink never reached video and stopped at Bluetooth, but one backoff treated a sleeping radio, a service that was not up yet and this comma's own busy stack alike. reachability.classify() separates a car that never answered a page (Host is down, page timeout), a car that answered but refused or reset, and a local Bluetooth failure. A sleeping car or busy controller now waits at least as long as before and often longer; other failures wait exactly as before. A sleeping car no longer makes the comma forget the cached RFCOMM channel. The class is logged on attempt_failed and reported as aa.reach_class. The 141 'unknown' failures at the discovering stage now get a diagnosis: car_asleep, car_not_ready or bluetooth_stack_busy, with next steps. --- .../system/starport/bugsink_diagnosis.py | 20 ++++++- .../system/starport/bugsink_report.py | 10 ++-- .../starpilot/system/starport/reachability.py | 52 ++++++++++++++++++ .../starpilot/system/starport/supervisor.py | 18 +++++-- .../starport/tests/test_car_never_answered.py | 19 ++++++- .../starport/tests/test_reachability.py | 54 +++++++++++++++++++ 6 files changed, 164 insertions(+), 9 deletions(-) create mode 100644 openpilot/starpilot/system/starport/reachability.py create mode 100644 openpilot/starpilot/system/starport/tests/test_reachability.py diff --git a/openpilot/starpilot/system/starport/bugsink_diagnosis.py b/openpilot/starpilot/system/starport/bugsink_diagnosis.py index 058b9505cf..9d5f060d31 100644 --- a/openpilot/starpilot/system/starport/bugsink_diagnosis.py +++ b/openpilot/starpilot/system/starport/bugsink_diagnosis.py @@ -86,7 +86,7 @@ def attempt_records(events): if name == "attempt_failed": current.update(failed_stage=str(event.get("stage", "")), error_kind=str(event.get("kind", "")), error=sanitize(str(event.get("error", ""))), failed_at_s=elapsed(start, event), - where=sanitize(event.get("where", [])[-4:])) + where=sanitize(event.get("where", [])[-4:]), reach=str(event.get("reach", ""))) if name == "session_ended": current["ended_by_car"] = str(event.get("reason", "")).startswith("Head unit ended projection") shutdown = shutdown or current["ended_by_car"] @@ -130,11 +130,27 @@ def diagnosis(session): explanation = "Bluetooth connected and the version exchange ran, but the head unit stopped answering the Wi-Fi setup." actions = ["Read the attached handshake trace for the last messages the head unit sent and the ones it ignored.", "Compare the head unit make, model and protocol version with other reports before changing timings."] - elif stage in ("connecting_bluetooth", "rfcomm", "bootstrap"): + elif stage in ("connecting_bluetooth", "discovering", "rfcomm", "bootstrap"): category, confidence = "head_unit_unavailable", "suspected" explanation = "The Bluetooth/bootstrap exchange did not complete; the head unit may still be waking or already off." actions = ["Confirm the selected car is awake and inspect Bluetooth/bootstrap responses in the bundle.", "Retry while parked before considering re-pairing; preserve existing bonds for diagnosis."] + reach = session.get("reach", "") + if reach == "asleep": + category = "car_asleep" + explanation = "The car did not answer the Bluetooth page at all. Its radio is off or still waking, so waiting is the fix." + actions = ["Wait for the car to finish waking and let the retry run; the saved pairing and RFCOMM channel were kept.", + "Only re-pair if the car is awake with its Bluetooth screen open and pages still go unanswered."] + elif reach == "not_ready": + category = "car_not_ready" + explanation = "The car answered Bluetooth but its Android Auto service refused or dropped the connection; it is not ready yet." + actions = ["Let the retry run; the car usually accepts a few seconds later.", + "If it repeats on every drive, compare the head unit make and model with other reports."] + elif reach == "local": + category = "bluetooth_stack_busy" + explanation = "This comma's own Bluetooth stack was busy or refused, which says nothing about the car." + actions = ["Check for another process or a second pairing attempt holding the controller.", + "Retry once the controller is idle; preserve existing bonds."] elif stage == "streaming": category, confidence = "projection_interrupted", "observed" explanation = "Projection was interrupted. EOF or a timeout alone cannot distinguish a car shutdown from link loss." diff --git a/openpilot/starpilot/system/starport/bugsink_report.py b/openpilot/starpilot/system/starport/bugsink_report.py index c4860ff879..dd28f84267 100644 --- a/openpilot/starpilot/system/starport/bugsink_report.py +++ b/openpilot/starpilot/system/starport/bugsink_report.py @@ -13,7 +13,7 @@ from collections.abc import Callable from datetime import UTC, datetime, timedelta from pathlib import Path -from openpilot.starpilot.system.starport import identity as identity_store, system_slice +from openpilot.starpilot.system.starport import identity as identity_store, reachability, system_slice from openpilot.starpilot.system.starport.bugsink_diagnosis import attempt_records, diagnosis, elapsed, sanitize from openpilot.starpilot.system.starport.bugsink_summary import batch_summary, failure_summary, pairing_summary, session_timeline, software_tags @@ -258,6 +258,9 @@ def session_record(path: Path) -> dict: "furthest_stage": report["furthest_stage"], "failed_stage": str(last_failure.get("failed_stage", "")), "error_kind": str(last_failure.get("error_kind", "")), + "reach": str(last_failure.get("reach", "")) or (reachability.classify( + str(last_failure.get("failed_stage", "")), str(last_failure.get("error_kind", "")), str(last_failure.get("error", ""))) + if last_failure else ""), "error": scrub(last_failure.get("error", "")), "failures": len(failures), "drops": len(drops), @@ -401,7 +404,7 @@ def failure_detail(session: dict) -> dict: "title": f"{assessment['category']} at {stage}: {kind}", "session": session["seq"], "attempt": session.get("failed_attempt"), - "cause": assessment["category"], "stage": stage, "error_kind": kind, + "cause": assessment["category"], "stage": stage, "error_kind": kind, "reach": session.get("reach", ""), "summary": sanitize(failure_summary(assessment), names), "diagnosis": sanitize(assessment, names), } @@ -495,7 +498,8 @@ def drive_event(sessions: list[dict]) -> dict: **({"aa.profile_source": setup["profile_source"]} if setup.get("profile_source") else {}), **({"aa.phone_address_sent": "yes" if sent else "no"} if sent is not None else {}), **({"aa.attention": ",".join(reasons)[:190]} if reasons else {}), - **({"aa.cause": latest["cause"], "aa.stage": latest["stage"], "aa.error_kind": latest["error_kind"]} if latest else {})}, + **({"aa.cause": latest["cause"], "aa.stage": latest["stage"], "aa.error_kind": latest["error_kind"]} if latest else {}), + **({"aa.reach_class": latest["reach"]} if latest and latest.get("reach") else {})}, "breadcrumbs": {"values": attempt_breadcrumbs(sessions)}, "contexts": {"starport_drive": summary, "starport_head_unit": head_unit, **{f"starport_session_{index + 1}": _public(session) for index, session in enumerate(sessions)}, diff --git a/openpilot/starpilot/system/starport/reachability.py b/openpilot/starpilot/system/starport/reachability.py new file mode 100644 index 0000000000..6d38a6ff9a --- /dev/null +++ b/openpilot/starpilot/system/starport/reachability.py @@ -0,0 +1,52 @@ +"""Why a connection attempt could not reach the car, so each cause is waited out differently. + +Bugsink showed most failed drives never got as far as video, and nearly all of those stopped at Bluetooth: "Host is +down" and page timeouts (the car's radio is off or busy), connection refused or reset (the radio answered but the +Android Auto service was not up yet), and the comma's own Bluetooth stack being busy. One fixed backoff treated them alike. + +The class is derived from strings so the supervisor (live exceptions) and the report (logged text) agree. +""" + +ASLEEP = "asleep" # the car did not answer a page at all: off, or still waking +NOT_READY = "not_ready" # the car answered, but its Android Auto service or Wi-Fi handshake is not up yet +LOCAL = "local" # this comma's own Bluetooth stack refused or was busy; the car says nothing +OTHER = "other" # anything else, including every failure after the link is up + +CLASSES = (ASLEEP, NOT_READY, LOCAL, OTHER) + +_LOCAL = ("device or resource busy", "errno 16]", "operation not permitted", "no such device") +_ASLEEP = ("host is down", "errno 112]", "page-timeout", "page timeout", "br-connection-page") +_NOT_READY = ("connection refused", "errno 111]", "connection reset", "errno 104]", "sdp record missing", + "does not advertise android auto", "did not answer in time") +_EARLY_STAGES = ("connecting_bluetooth", "discovering", "rfcomm", "wifi_start", "wifi_info", "bootstrap") + +# Waiting longer for a radio that is off does not wake it, and every page holds the controller (a page that crosses +# the car's own page can strand the link). These are floors: a class never waits less than the standard backoff. +ASLEEP_FLOOR = (6.0, 8.0, 12.0, 20.0, 30.0) +LOCAL_FLOOR = (8.0, 10.0, 15.0, 30.0) + + +def classify(stage: str, kind: str, message: str) -> str: + text = f"{kind} {message}".lower() + if kind == "BluetoothRejected" or any(word in text for word in _LOCAL): + return LOCAL + if stage not in _EARLY_STAGES: + return OTHER + if any(word in text for word in _ASLEEP) or (kind == "TimeoutError" and stage == "connecting_bluetooth"): + return ASLEEP + if any(word in text for word in _NOT_READY) or kind == "BootstrapTimeout": + return NOT_READY + return OTHER + + +def retry_delay(reach: str, attempt: int, standard: float) -> float: + """The wait before the next attempt; never shorter than the standard backoff, and unchanged for other failures.""" + floor = {ASLEEP: ASLEEP_FLOOR, LOCAL: LOCAL_FLOOR}.get(reach) + if floor is None: + return standard + return max(standard, floor[min(max(attempt, 0), len(floor) - 1)]) + + +def keeps_cached_channel(reach: str) -> bool: + """A sleeping car says nothing about which RFCOMM channel is right, so its cached channel is kept.""" + return reach in (ASLEEP, LOCAL) diff --git a/openpilot/starpilot/system/starport/supervisor.py b/openpilot/starpilot/system/starport/supervisor.py index 20152d392a..3a3b22a636 100644 --- a/openpilot/starpilot/system/starport/supervisor.py +++ b/openpilot/starpilot/system/starport/supervisor.py @@ -33,7 +33,7 @@ from pathlib import Path from typing import Any from openpilot.common.hardware import COMMA_HARDWARE -from openpilot.starpilot.system.starport import car_profiles, device_health, identity as identity_store, system_slice +from openpilot.starpilot.system.starport import car_profiles, device_health, identity as identity_store, reachability, system_slice from openpilot.starpilot.system.starport.auto_connect import AutoConnectPolicy from openpilot.starpilot.system.starport.bootstrap import MODERN_MAJOR, NAMES, BootstrapError, WirelessBootstrap from openpilot.starpilot.system.starport.bugsink_report import PairingAttempt @@ -177,6 +177,15 @@ def car_never_answered(error: BaseException) -> bool: return not (isinstance(error, OSError) and error.errno in LOCAL_SOCKET_ERRORS) +def drops_cached_channel(stage: str, error: BaseException) -> bool: + """Forget the cached RFCOMM channel only when the car answered nothing there for a reason about the channel. + + A sleeping car (page timeout, host down) or this comma's own busy Bluetooth says nothing about which channel is right.""" + if stage not in ("rfcomm", "wifi_start") or not car_never_answered(error): + return False + return not reachability.keeps_cached_channel(reachability.classify(stage, type(error).__name__, str(error))) + + def _where(error: BaseException, depth: int = 4) -> list[str]: """The innermost frames of a failure, so a bare exception still says which call raised it.""" frames = traceback.extract_tb(error.__traceback__)[-depth:] @@ -1148,6 +1157,7 @@ class Supervisor: while not self._stop.is_set(): started = time.monotonic() peer_stopped = False + reach = reachability.OTHER # set by a failed attempt; a clean end or a car-ended session keeps the standard wait self.log("attempt_start") try: if car_first: @@ -1167,7 +1177,8 @@ class Supervisor: stage = error.stage if isinstance(error, BootstrapError) else self._status["last_stage"] message = self._describe_error(stage, error) self._set(error=message) - self.log("attempt_failed", stage=stage, error=message, kind=type(error).__name__, where=_where(error)) + reach = reachability.classify(stage, type(error).__name__, f"{message} {error}") + self.log("attempt_failed", stage=stage, error=message, kind=type(error).__name__, where=_where(error), reach=reach) if isinstance(error, StrayLinkError): self._clear_stray_link() car_first = True # the car pages right back once its link drops; let it, rather than crossing it again @@ -1181,6 +1192,7 @@ class Supervisor: break attempt = 0 if time.monotonic() - started > STABLE_SESSION_SECONDS else attempt + 1 delay = BACKOFF_SECONDS[min(attempt, len(BACKOFF_SECONDS) - 1)] + delay = reachability.retry_delay(reach, attempt, delay) if peer_stopped: delay = max(delay, PEER_STOP_RETRY_SECONDS) # the car ended projection itself; do not bounce straight back self._set(state="backoff", attempt=attempt, retry_in=delay, mode=None) @@ -1272,7 +1284,7 @@ class Supervisor: if boot is not None and boot.silent_after_modern_version(error): self._modern_reply[address] = not boot.modern_reply # try the other version reply next self.log("bootstrap_reply_switched", modern=self._modern_reply[address]) - if source == "cache" and not self._stop.is_set() and self._status["last_stage"] in ("rfcomm", "wifi_start") and car_never_answered(error): + if source == "cache" and not self._stop.is_set() and drops_cached_channel(self._status["last_stage"], error): self._remember_channel(address, None) # the car never answered there; ask it over SDP next time self.log("rfcomm_cache_dropped", channel=channel) raise diff --git a/openpilot/starpilot/system/starport/tests/test_car_never_answered.py b/openpilot/starpilot/system/starport/tests/test_car_never_answered.py index 730e488806..8263ab1e35 100644 --- a/openpilot/starpilot/system/starport/tests/test_car_never_answered.py +++ b/openpilot/starpilot/system/starport/tests/test_car_never_answered.py @@ -2,7 +2,7 @@ import errno import unittest from openpilot.starpilot.system.starport.bootstrap import BootstrapTimeout -from openpilot.starpilot.system.starport.supervisor import car_never_answered +from openpilot.starpilot.system.starport.supervisor import car_never_answered, drops_cached_channel class TestCarNeverAnswered(unittest.TestCase): @@ -14,3 +14,20 @@ class TestCarNeverAnswered(unittest.TestCase): for error in (OSError(errno.ECONNREFUSED, 'refused'), OSError(errno.EHOSTDOWN, 'down'), TimeoutError(), BootstrapTimeout('wifi_start', 'head unit did not answer in time')): self.assertTrue(car_never_answered(error)) + + +class TestDropsCachedChannel(unittest.TestCase): + def test_a_sleeping_car_keeps_its_channel(self): + # The message is what the kernel prints on the device (the errno number differs between macOS and Linux). + self.assertFalse(drops_cached_channel('rfcomm', OSError(errno.EHOSTDOWN, 'Host is down'))) + self.assertFalse(drops_cached_channel('rfcomm', OSError(112, 'Host is down'))) + + def test_a_car_that_refuses_or_resets_loses_it(self): + for error in (ConnectionRefusedError(errno.ECONNREFUSED, 'Connection refused'), ConnectionResetError(errno.ECONNRESET, 'reset'), + BootstrapTimeout('wifi_start', 'head unit did not answer in time')): + self.assertTrue(drops_cached_channel('rfcomm' if not isinstance(error, BootstrapTimeout) else 'wifi_start', error)) + + def test_other_stages_and_local_failures_never_drop_it(self): + self.assertFalse(drops_cached_channel('authenticating', ConnectionResetError(errno.ECONNRESET, 'reset'))) + self.assertFalse(drops_cached_channel('rfcomm', OSError(errno.ENOSYS, 'local'))) + self.assertFalse(drops_cached_channel('rfcomm', OSError(errno.EBUSY, 'Device or resource busy'))) diff --git a/openpilot/starpilot/system/starport/tests/test_reachability.py b/openpilot/starpilot/system/starport/tests/test_reachability.py new file mode 100644 index 0000000000..5268acb628 --- /dev/null +++ b/openpilot/starpilot/system/starport/tests/test_reachability.py @@ -0,0 +1,54 @@ +"""Failures before video are told apart by why the car could not be reached, using the texts Bugsink actually showed.""" + +import pytest + +from openpilot.starpilot.system.starport import bugsink_report as br, reachability as r +from openpilot.starpilot.system.starport.tests.test_bugsink_report import write_session + +CASES = [ + ("discovering", "RuntimeError", "Could not find the car's Android Auto service: [Errno 112] Host is down", r.ASLEEP), + ("connecting_bluetooth", "RuntimeError", "org.bluez.Error.Failed: br-connection-page-timeout", r.ASLEEP), + ("connecting_bluetooth", "TimeoutError", "", r.ASLEEP), + ("rfcomm", "OSError", "starting wireless setup: [Errno 112] Host is down", r.ASLEEP), + ("rfcomm", "ConnectionRefusedError", "[Errno 111] Connection refused", r.NOT_READY), + ("rfcomm", "ConnectionResetError", "starting wireless setup: [Errno 104] Connection reset by peer", r.NOT_READY), + ("discovering", "RuntimeError", "Head unit does not advertise Android Auto Wireless (SDP record missing)", r.NOT_READY), + ("wifi_start", "BootstrapTimeout", "waiting for car: wifi_start: head unit did not answer in time", r.NOT_READY), + ("rfcomm", "OSError", "[Errno 16] Device or resource busy", r.LOCAL), + ("connecting_bluetooth", "BluetoothRejected", "pairing rejected", r.LOCAL), + ("streaming", "TimeoutError", "projecting: Video acknowledgement older than 2.5 s", r.OTHER), # after the link is up + ("authenticating", "ConnectionResetError", "Connection reset by peer", r.OTHER), + ("joining_wifi", "BootstrapError", "joining_wifi: ", r.OTHER), +] + + +@pytest.mark.parametrize("stage,kind,message,expected", CASES) +def test_classify_known_bugsink_texts(stage, kind, message, expected): + assert r.classify(stage, kind, message) == expected + + +def test_waits_are_never_shorter_than_the_standard_backoff_and_other_failures_are_unchanged(): + standard = (2.0, 4.0, 8.0, 15.0, 30.0) + for attempt, base in enumerate(standard): + assert r.retry_delay(r.OTHER, attempt, base) == base and r.retry_delay(r.NOT_READY, attempt, base) == base + for reach in (r.ASLEEP, r.LOCAL): + assert r.retry_delay(reach, attempt, base) >= base + assert r.retry_delay(r.ASLEEP, 0, 2.0) == 6.0 and r.retry_delay(r.ASLEEP, 99, 30.0) == 30.0 + + +def test_a_sleeping_car_keeps_its_cached_channel_but_a_refusing_one_does_not(): + assert r.keeps_cached_channel(r.ASLEEP) and r.keeps_cached_channel(r.LOCAL) + assert not r.keeps_cached_channel(r.NOT_READY) and not r.keeps_cached_channel(r.OTHER) + + +def test_report_names_a_sleeping_car_instead_of_unknown(tmp_path): + events = [(0, 0, "session_start", {"receiver": "Car"}), (0, 1, "stage", {"state": "discovering"}), + (0, 9, "attempt_failed", {"stage": "discovering", "kind": "RuntimeError", + "error": "finding android auto: Could not find the car's Android Auto service: [Errno 112] Host is down"})] + record = br.session_record(write_session(tmp_path, 1, events)) + assert record["reach"] == "asleep" # derived from the text for logs written before the supervisor recorded it + event = br.drive_event([record]) + assert event["tags"]["aa.cause"] == "car_asleep" and event["tags"]["aa.reach_class"] == "asleep" + recorded = [(0, 0, "session_start", {}), (0, 9, "attempt_failed", {"stage": "rfcomm", "kind": "ConnectionRefusedError", + "error": "refused", "reach": "not_ready"})] + assert br.session_record(write_session(tmp_path, 2, recorded))["reach"] == "not_ready"