feat: add command debug logging

AGENTS.md

@@ -136,6 +136,7 @@ Source protobuf definitions live in `proto/`; generated Python files live in `te
 - **`pair()` confirms whitelisting two ways: one-shot reply OR verify-by-state poll**: the whitelist-op success is a single VCSEC frame, and it lands on a dead session (lost forever) if the BLE link cycles while the user walks to the car to approve - live-observed on HA/macOS CoreBluetooth, where `tesla_fleet_api` logged "Reconnecting to S..." every ~100s during a pending pair, and the plain one-shot wait hung despite car-side completion. `pair()` (`bluetooth.py`) keeps the reply as the fast path (waits one `poll_interval` for it) but, on a lost reply, polls `_pair_probe()` every `poll_interval` until an overall `timeout` (default 300s) elapses. The probe is a VCSEC `_handshake` with our own public key: it succeeds only once the key is whitelisted and faults `NotOnWhitelistFault` until then - `_pair_probe` maps any `TeslaFleetError` (incl. transport failures from a mid-wait reconnect) to "not yet", so polling survives reconnects. The whitelist op is written **exactly once** - never re-sent - because a re-send re-prompts the user (and the retry/double-execute hazard documented above applies). Deadline with neither path confirming raises a typed `BluetoothTimeout`. Default behavior, no new knob (`poll_interval` is a defaulted param).
 - **Idle BLE keepalive (`keepalive_interval`)**: an idle held BLE link to the vehicle drops at ~42s mean lifetime (link supervision timeout ~720ms underneath, bluetoothd-verified on macOS CoreBluetooth); a single trivial passive GATT read every ~20s extends lifetime ~10x (~400s observed). `VehicleBluetooth.__init__`'s `keepalive_interval` (default `DEFAULT_KEEPALIVE_INTERVAL` = 20.0, `None`/`0` disables; threaded through `Vehicles`/`VehiclesBluetooth.create*`) starts one asyncio task per connection (`_keepalive_loop`, `bluetooth.py`) that reads `VERSION_UUID` only after `keepalive_interval` seconds of genuine GATT idleness. **Idle-triggered, not periodic**: `_last_activity` is bumped on every `_send` write and every `_on_notify` frame, so an active session never gets extra traffic; the loop recomputes the wait each pass and fires only when idle. The read is **bounded** (`_keepalive_timeout`, 2s) and **best-effort** - a prior un-timed RSSI read hung indefinitely against a sleeping car, so every attempt carries a timeout and swallows all failures (`_keepalive_read` catches `Exception`, never `CancelledError`); a failed keepalive never raises into user code, never triggers reconnect (the existing `connect_if_needed` machinery owns recovery), and never wakes the car. Task lifecycle is tied to the connection: started at the end of `connect()` (after `start_notify`), cancelled-and-awaited in `disconnect()` and restarted cleanly on reconnect (`_start_keepalive`/`_stop_keepalive`). **Sleep tradeoff**: these reads keep an *awake* car awake and defer vehicle sleep - consumers wanting the car to sleep should disable keepalive or disconnect when idle. Tests in `tests/test_ble_keepalive.py`.
 - **Cross-transport parity (cloud REST `VehicleFleet` vs BLE `Commands`)**: the same-named command on both paths should build a semantically equivalent instruction from identical args - a divergence there is a bug, but response *bodies* legitimately differ (REST JSON dict vs decoded protobuf) and are not. `tests/test_cross_transport_parity.py` locks the equivalence in with mocked-both-transports tests. Known **non-bug FORM differences** (do not "fix"): `set_scheduled_departure`'s `preconditioning_enabled`/`off_peak_charging_enabled` (no proto fields), `window_control` lat/lon and `navigation_sc_request` `id` (no proto fields), `navigation_request`'s `type`/`locale`/`timestamp_ms` (REST share-intent framing), and `media_volume_up` (no Tesla REST endpoint - BLE-only; cloud raises volume via `adjust_volume`). Two **open divergences left unfixed** pending live verification: `clear_pin_to_drive_admin` builds `DrivingClearSpeedLimitPinAction` (speed-limit PIN, not PIN-to-Drive - suspected mismapping, security-sensitive), and `navigation_gps_request`'s `order` is required on BLE but optional on cloud (signature mismatch; null-order wire semantics undecided).
+- **Per-command debug logging chokepoints and the `command=` name it derives**: `LOGGER.debug` lines of the form `command=<name> transport=<t> result=...` are emitted from exactly four places, not per-method - `Commands._sendVehicleSecurity`/`_getVehicleSecurity`/`_sendInfotainment`/`_getInfotainment` (`commands.py`, covers both BLE and Fleet-signed) and `TeslaFleetApi._request` (`fleet.py`, covers Fleet/Teslemetry/Tessie REST). `transport` comes from a `_transport_name` `ClassVar` set per concrete class (`"bluetooth"`/`"fleet"`/`"teslemetry"`/`"tessie"`), mirroring the existing `_auth_method` pattern - add that ClassVar to any new `Commands`/`TeslaFleetApi` subclass. For BLE/Fleet-signed, `command` is **not** the Python method name; it's derived from the populated protobuf oneof field (`vcsec_command_name`/`infotainment_command_name` in `commands.py`), e.g. `door_lock()` logs as `RKE_ACTION_LOCK` and `set_charge_limit()` as `chargingSetLimitAction` - deliberately robust to call-site changes since it reads the message being sent, not the call stack. `VehicleBluetooth`'s `verify_commands` resolution logs a second, separate line (`verify_commands=resolved`/`unresolved`) rather than duplicating the base class's raw-attempt line. `Router._dispatch` (`router/base.py`) logs `command=... backend=<ClassName> result=...` per backend tried, independent of the above. See `docs/bluetooth_vehicles.md`'s "Troubleshooting: Enable Debug Logging" section for the user-facing format; `tests/test_command_logging.py` locks in the exact line shapes.
 
 ## Maintaining this file
 

README.md

@@ -226,10 +226,30 @@ await router.set_operation(...)  # local first, cloud on failure
 
 `Router`, `VehicleRouter`, and `EnergySiteRouter` are all importable from `tesla_fleet_api.router` (and, for backward compatibility, from `tesla_fleet_api.tesla`).
 
+Enable `DEBUG` logging for `tesla_fleet_api` to see which backend served a routed call and why failover happened.
+
 > **Warning:** Because a failed call is replayed on the next backend, a non-idempotent command (e.g. `honk_horn`, `actuate_trunk`, `door_unlock`, `charge_start`) that fails _mid-flight_ — after a backend may have already partially applied it — can be **double-executed** (or executed more than once across a longer chain) when it is retried on the next backend. This is a deliberate tradeoff of per-command failover. When the primary is `VehicleBluetooth`, pass `verify_commands=True` to resolve supported mutating command timeouts by state before failover; callers needing exactly-once semantics for other commands should gate dispatch with an explicit `health` check or call the underlying backends directly.
 >
 > Dispatch is implemented via `__getattr__`, which does not proxy dunder methods, so `async with Router(...)` does **not** manage a backend's BLE connection lifecycle (`__aenter__`/`__aexit__`). Commands still auto-connect on send; for explicit connect/disconnect reach through `router.primary` (or `router.backends`).
 
+### Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to see each command's command
+name, transport/backend, and result. In standalone scripts, configure a handler
+first:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
+Command log lines use `transport=bluetooth`, `fleet`, `teslemetry`, or `tessie`.
+Routers also emit `backend=<ClassName>` lines for each backend tried. See
+[Bluetooth for Vehicles](docs/bluetooth_vehicles.md#troubleshooting-enable-debug-logging)
+for examples and the signed-command naming details.
+
 ### Teslemetry
 
 The `Teslemetry` class provides methods to interact with the Teslemetry service. Here's a basic example:

docs/bluetooth_vehicles.md

@@ -398,3 +398,33 @@ enough to prove either failure or success.
 `remote_boombox(sound)` also uses the INFO-domain signed-command transport and
 plays through the vehicle external speaker. Use it only when someone is present
 to confirm the sound is appropriate for the vehicle's surroundings.
+
+## Troubleshooting: Enable Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to see, for every command, which
+transport served it and how it ended:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
+Each command logs one terse, grep-friendly line:
+
+```
+command=RKE_ACTION_LOCK transport=bluetooth result=True reason=
+command=set_charge_limit transport=teslemetry result=True reason=
+command=mediaPlayAction transport=bluetooth result=error error=BluetoothTimeout: Bluetooth command timed out waiting for vehicle response.
+```
+
+`transport` is `bluetooth`, `fleet`, `teslemetry`, or `tessie`. For BLE signed
+commands, `command` is the underlying VCSEC/infotainment field name (e.g.
+`RKE_ACTION_LOCK`, `chargingSetLimitAction`), not the Python method name; for
+REST commands it is the endpoint's final path segment (e.g. `set_charge_limit`).
+For BLE commands run with `verify_commands=True`, a resolved timeout logs a
+second line with `verify_commands=resolved` and the confirmed result. `Router`
+additionally logs `command=... backend=<ClassName> result=...` for each
+backend it tries, so a BLE-primary/cloud-fallback setup shows exactly which
+backend served each call and why a failover happened.

docs/fleet_api_energy_sites.md

@@ -30,6 +30,18 @@ async def main():
 asyncio.run(main())
 ```
 
+## Troubleshooting: Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to log each Fleet API request's
+final path segment, `transport=fleet`, and result:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
 ## Backup Reserve
 
 You can adjust the backup reserve for a specific energy site using its ID:

docs/fleet_api_signed_commands.md

@@ -190,6 +190,22 @@ state after the call instead of relying on the number of send attempts.
 `adjust_volume(volume)` accepts absolute volume values from `0.0` through
 `11.0`, matching the Fleet API command validation.
 
+## Troubleshooting: Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to log each signed command's
+protobuf command name, `transport=fleet`, and result:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
+For signed commands, `command` is the underlying VCSEC or infotainment field
+name (for example `RKE_ACTION_LOCK` or `chargingSetLimitAction`), not the Python
+method name.
+
 ## Flash Lights
 
 You can flash the lights of a specific vehicle using its VIN:

docs/fleet_api_vehicles.md

@@ -29,6 +29,25 @@ async def main():
 asyncio.run(main())
 ```
 
+## Troubleshooting: Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to log each Fleet API request's
+final path segment, `transport=fleet`, and result:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
+Example command lines:
+
+```
+command=vehicle_data transport=fleet result=success
+command=set_charge_limit transport=fleet result=True reason=
+```
+
 ## Create a Vehicle
 
 You can create a `VehicleFleet` instance for a specific vehicle using its VIN:

docs/teslemetry.md

@@ -21,6 +21,18 @@ async def main():
 asyncio.run(main())
 ```
 
+## Troubleshooting: Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to log each Teslemetry request's
+final path segment, `transport=teslemetry`, and result:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
 ## Ping
 
 The `ping` method sends a ping request to the Teslemetry server.

docs/tessie.md

@@ -28,6 +28,18 @@ async def main():
 asyncio.run(main())
 ```
 
+## Troubleshooting: Debug Logging
+
+Enable the `tesla_fleet_api` logger at `DEBUG` to log each Tessie request's
+final path segment, `transport=tessie`, and result:
+
+```python
+import logging
+
+logging.basicConfig(level=logging.DEBUG)
+logging.getLogger("tesla_fleet_api").setLevel(logging.DEBUG)
+```
+
 ## Top-Level Client Methods
 
 These methods exist on `Tessie` itself.

tesla_fleet_api/router/base.py

@@ -54,6 +54,8 @@ class Router(Generic[PrimaryT, SecondaryT]):
     failure or a disconnect), the same call is automatically retried on the next
     backend that has it, with the same arguments. The error only propagates when
     every applicable backend fails, in which case the last error is raised.
+    Each attempted backend emits a ``DEBUG`` log line with the routed command
+    name, backend class, and success/error result.
 
     .. warning::
 
@@ -148,15 +150,21 @@ async def _routed(*args: Any, **kwargs: Any) -> Any:
             last_exc: BaseException | None = None
             for backend, attr in targets[start:]:
                 try:
-                    return await _maybe_await(attr(*args, **kwargs))
+                    result = await _maybe_await(attr(*args, **kwargs))
                 except (Exception, TeslaFleetError) as e:  # noqa: BLE001 - any failure -> next backend
                     last_exc = e
                     LOGGER.debug(
-                        "Backend %s call %r failed, routing to next backend: %s",
-                        type(backend).__name__,
+                        "command=%s backend=%s result=error error=%s: %s",
                         name,
+                        type(backend).__name__,
+                        type(e).__name__,
                         e,
                     )
+                    continue
+                LOGGER.debug(
+                    "command=%s backend=%s result=success", name, type(backend).__name__
+                )
+                return result
             # The loop always runs at least once (``start`` only advances past
             # the primary when a later backend remains), so a failure here means
             # every applicable backend raised.