Skip to content

feat: add command debug logging#64

Merged
Bre77 merged 4 commits into
mainfrom
fm/tfa-cmd-debug-logging-g6
Jul 11, 2026
Merged

feat: add command debug logging#64
Bre77 merged 4 commits into
mainfrom
fm/tfa-cmd-debug-logging-g6

Conversation

@Bre77

@Bre77 Bre77 commented Jul 11, 2026

Copy link
Copy Markdown
Member

Intent

Add DEBUG-level logging that records the result of every vehicle command and which transport served it (bluetooth vs Fleet API vs Teslemetry vs Tessie), so the captain can troubleshoot whether commands are going over Bluetooth during live HA-integration testing with a BLE-primary Router, and see why a command failed when it does.

Scope was deliberately logging-only: no behavior changes, no new exceptions, no timing changes, one issue per PR, no release cut.

Design decisions:

  • Chose the minimum number of choke points rather than instrumenting all ~110 command methods: Commands._sendVehicleSecurity/_getVehicleSecurity/_sendInfotainment/_getInfotainment (commands.py) cover both BLE (VehicleBluetooth) and Fleet-signed (VehicleSigned) traffic; TeslaFleetApi._request (fleet.py) covers unsigned REST across Fleet/Teslemetry/Tessie since none of those subclasses override _request.
  • transport identity comes from a new _transport_name ClassVar set per concrete class (bluetooth/fleet/teslemetry/tessie), mirroring the existing _auth_method ClassVar pattern already used in this hierarchy - deliberately not derived via isinstance checks or stack introspection.
  • The logged command name is deliberately NOT the Python method name. It's derived from the populated protobuf oneof field on the outgoing message (vcsec_command_name/infotainment_command_name helpers), e.g. door_lock() logs as RKE_ACTION_LOCK and set_charge_limit() logs as chargingSetLimitAction. This was a considered tradeoff: deriving from the message itself is robust regardless of call depth/wrappers, whereas stack-frame introspection (e.g. sys._getframe) would break through VehicleBluetooth's override layer for verify_commands and add per-call overhead even when logging is disabled.
  • For BLE's opt-in verify_commands feature, a resolved/unresolved timeout logs a SEPARATE line (verify_commands=resolved|unresolved) rather than duplicating the base class's raw-attempt log line, so the two log statements together tell the full story (raw ack/timeout, then whether verification confirmed it).
  • Router._dispatch already had a debug log on failover failure; I extended it to also log the success line (which backend actually served the call) and reformatted both to the same grep-friendly command=/backend=/result= shape - this is a wording-only change to an existing log line, not new behavior.
  • All exception catches use the existing (Exception, TeslaFleetError) tuple pattern already established in router/base.py, since every library exception inherits BaseException via TeslaFleetError, not Exception.

Verification performed: full pytest suite (218 tests incl. 9 new ones in tests/test_command_logging.py), ruff check/format, and pyright strict all pass on every touched file. Manually ran each of the three logging paths (BLE via mocked transport, REST via mocked aiohttp session, Router via fake backends) standalone with logging.basicConfig(DEBUG) to confirm the actual emitted log lines exactly match what's documented in docs/bluetooth_vehicles.md's new Troubleshooting section (including exact BluetoothTimeout message text).

Known pre-existing issue noted but NOT touched (out of scope): ruff format --check flags 5 files unrelated to this change (tesla_fleet_api/tesla/bluetooth.py, tesla_fleet_api/tesla/tesla.py, tesla_fleet_api/tesla/vehicle/vehicle.py, tesla_fleet_api/tessie/init.py, tests/test_tessie_vehicle_params.py) as needing reformatting - this is pre-existing drift on main, not introduced by this branch.

What Changed

  • Added DEBUG-level command outcome logging across signed commands, unsigned REST requests, and router dispatch so logs include the command, transport/backend, and success or failure reason.
  • Added transport identity metadata for Fleet, Bluetooth, Teslemetry, and Tessie paths, including BLE verify_commands resolution logging for timeout verification outcomes.
  • Documented the new troubleshooting log format across the README and transport docs, with focused command logging tests covering the emitted line shapes.

Risk Assessment

✅ Low: The change is well-bounded to debug logging choke points and documentation/tests, with no material correctness, security, or behavior risks found in the reviewed diff.

Testing

Exercised the logging paths for BLE signed commands, verify_commands timeout resolution, Fleet REST, Teslemetry, Tessie, and Router failover; captured the actual DEBUG log lines as reviewer-visible evidence, then ran the full test suite successfully.

Evidence: DEBUG logging transcript
DEBUG:tesla_fleet_api:Sending AES to domain DOMAIN_VEHICLE_SECURITY
DEBUG:tesla_fleet_api:VCSEC Response: commandStatus {
}

DEBUG:tesla_fleet_api:command=RKE_ACTION_LOCK transport=bluetooth result=True reason=
DEBUG:tesla_fleet_api:Bluetooth command timed out waiting for vehicle response.
DEBUG:tesla_fleet_api:Sending AES to domain DOMAIN_VEHICLE_SECURITY
DEBUG:tesla_fleet_api:command=RKE_ACTION_LOCK transport=bluetooth result=error error=BluetoothTimeout: Bluetooth command timed out waiting for vehicle response.
DEBUG:tesla_fleet_api:Sending AES to domain DOMAIN_VEHICLE_SECURITY
DEBUG:tesla_fleet_api:VCSEC Response: vehicleStatus {
  vehicleLockState: VEHICLELOCKSTATE_LOCKED
}

DEBUG:tesla_fleet_api:command=InformationRequest transport=bluetooth result=success
DEBUG:tesla_fleet_api:command=RKE_ACTION_LOCK transport=bluetooth verify_commands=resolved result=True
DEBUG:tesla_fleet_api:Using server https://fleet.example.test
DEBUG:tesla_fleet_api:Status 200 from https://example.test/api
DEBUG:tesla_fleet_api:Response JSON: {'response': {'result': True, 'reason': ''}}
DEBUG:tesla_fleet_api:command=door_lock transport=fleet result=True reason=
DEBUG:tesla_fleet_api:Status 200 from https://example.test/api
DEBUG:tesla_fleet_api:Response JSON: {'response': {'result': True, 'reason': ''}}
DEBUG:tesla_fleet_api:command=set_charge_limit transport=teslemetry result=True reason=
DEBUG:tesla_fleet_api:Status 200 from https://example.test/api
DEBUG:tesla_fleet_api:Response JSON: {'result': False, 'reason': 'already_locked'}
DEBUG:tesla_fleet_api:command=door_lock transport=tessie result=False reason=already_locked
DEBUG:tesla_fleet_api:Bluetooth command timed out waiting for vehicle response.
DEBUG:tesla_fleet_api:command=door_lock backend=PrimaryBackend result=error error=BluetoothTimeout: Bluetooth command timed out waiting for vehicle response.
DEBUG:tesla_fleet_api:command=door_lock backend=FleetFallback result=success
# BLE public command success
door_lock -> {'response': {'result': True, 'reason': ''}}

# BLE verify_commands resolves a timeout by reading state
door_lock verify_commands -> {'response': {'result': True, 'reason': ''}}

# Fleet REST command success
fleet door_lock -> {'response': {'result': True, 'reason': ''}}

# Teslemetry REST transport identity
teslemetry set_charge_limit -> {'response': {'result': True, 'reason': ''}}

# Tessie REST transport identity
tessie door_lock -> {'result': False, 'reason': 'already_locked'}

# Router BLE-primary failover to cloud fallback
router door_lock -> {'response': {'result': True, 'reason': 'served_by_cloud'}}

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

🔧 **Review** - 1 issue found → auto-fixed (2) ✅
  • ⚠️ tesla_fleet_api/tesla/fleet.py:195 - REST requests log result=success for any successful JSON HTTP response, even when a vehicle command body is {"response": {"result": false, "reason": ...}} (for example rejected/no-op command responses). That makes the new grep-friendly command log disagree with the actual command outcome; consider mirroring the signed-command logger by extracting response.result and response.reason when present, and only using transport success for non-command response shapes.

🔧 Fix: Log REST command body outcomes
1 warning still open:

  • ⚠️ tesla_fleet_api/tesla/fleet.py:37 - _log_request_result only extracts command outcomes from data["response"], so Tessie command responses shaped like the existing Tessie vehicle tests' {"result": true}/{"result": false} fall through to result=success. That preserves the same misleading log outcome for Tessie failures that the follow-up commit fixed for Fleet/Teslemetry-style wrapped responses; handle a top-level result/reason shape before defaulting to transport success.

🔧 Fix: Log Tessie command outcomes correctly
✅ Re-checked - no issues remain.

✅ **Test** - passed

✅ No issues found.

  • uv run pytest tests/test_command_logging.py
  • uv run python - <<'PY' > /tmp/no-mistakes-evidence/01KX7A2GCCPRYAFNJCQN64S56J/debug_logging_transcript.txt 2>&1
  • uv run pytest tests
✅ **Document** - passed

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

firstmate crewmate added 4 commits July 11, 2026 10:42
Adds terse, grep-friendly debug logging so a live BLE-primary Router
deployment can be diagnosed: which transport (bluetooth/fleet/teslemetry/tessie)
served each command, and why it failed. Logging only, no behavior changes.

- Commands._sendVehicleSecurity/_getVehicleSecurity/_sendInfotainment/_getInfotainment
  (commands.py) log command=<proto-derived name> transport=<t> result=...,
  covering both BLE and Fleet-signed commands from one choke point each.
- TeslaFleetApi._request (fleet.py) logs the same shape for Fleet/Teslemetry/Tessie
  REST commands.
- VehicleBluetooth's verify_commands timeout resolution logs a second line
  (verify_commands=resolved/unresolved).
- Router._dispatch logs which backend served each call and any failover hop.
@Bre77 Bre77 merged commit baeef13 into main Jul 11, 2026
5 checks passed
Bre77 added a commit that referenced this pull request Jul 12, 2026
* fix(fleet): guard _log_request_result against non-dict JSON bodies

A JSON-legal response body that isn't a dict (null, list, or scalar -
e.g. Teslemetry's list_authorized_clients returning null) crashed
_request AFTER the HTTP request had already succeeded, since
_log_request_result unconditionally called data.get() assuming a
dict. It's DEBUG-level logging added purely for troubleshooting
(#64) and must never break a successful request.

* docs: note _log_request_result's non-dict body guard in AGENTS.md

* no-mistakes(document): Document REST non-object responses

---------

Co-authored-by: firstmate crewmate <crewmate@firstmate.local>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant