TeslaBle2Mqtt crashing on "context deadline exceeded"

[bjv]

Hi Lenart,

I was using TeslaBle2Mqtt the last 24 hours and implemented dynamic solar power charging ("Überschussladen") in Home Assistent which is working fine so far.

Unfortuntaly, I noticed some disconnects in binary_sensor.tesla_ble_to_mqtt_<VIN>_connected:

I checked statistics and found that it crashed several times:

thanks to docker and automatic restarts, everything continued working.

But I guess I figured out the issue since all logs showed similar entries (like below) on all crash times:

teslable2mqtt           | 2025-02-09T09:10:00.206175966Z 2025/02/09 09:10:00 DEBU Publish state loop handler=per_vehicle for=tb2m_<VIN>
teslable2mqtt           | 2025-02-09T09:10:00.206345184Z 2025/02/09 09:10:00 DEBU Getting proxy response url=http://localhost:8080/api/proxy/1/vehicles/<VIN>/connection_status
tesla-ble-http-proxy    | 2025-02-09T09:10:00.209948090Z 2025/02/09 10:10:00 INFO received command=connection_status
teslable2mqtt           | 2025-02-09T09:10:00.211808814Z 2025/02/09 09:10:00 DEBU Getting proxy response url=http://localhost:8080/api/proxy/1/vehicles/<VIN>/body_controller_state
tesla-ble-http-proxy    | 2025-02-09T09:10:00.213161622Z 2025/02/09 10:10:00 INFO received command=body_controller_state
tesla-ble-http-proxy    | 2025-02-09T09:10:00.442123536Z 2025/02/09 10:10:00 INFO successfully executed command=body_controller_state body=map[]
teslable2mqtt           | 2025-02-09T09:10:00.443572699Z 2025/02/09 09:10:00 DEBU Getting proxy response url="http://localhost:8080/api/1/vehicles/<VIN>/vehicle_data?endpoints=charge_state;climate_state"
tesla-ble-http-proxy    | 2025-02-09T09:10:00.445403995Z 2025/02/09 10:10:00 INFO received command=vehicle_data body="map[endpoints:[charge_state climate_state]]"
teslable2mqtt           | 2025-02-09T09:10:02.510262459Z 2025/02/09 09:10:02 DEBU Publish state loop handler=handler for=tb2m
teslable2mqtt           | 2025-02-09T09:10:02.510609697Z 2025/02/09 09:10:02 INFO Publishing topic=tb2m/tb2m/uptime/state access path=uptime state=13950 old_state=13860
teslable2mqtt           | 2025-02-09T09:10:02.511314435Z 2025/02/09 09:10:02 DEBU Waiting for next poll interval interval=90
tesla-ble-http-proxy    | 2025-02-09T09:10:03.239864373Z 2025/02/09 10:10:03 INFO successfully executed command=vehicle_data body="map[endpoints:[charge_state climate_state]]"
teslable2mqtt           | 2025-02-09T09:10:03.242282543Z 2025/02/09 09:10:03 DEBU Using charging poll interval vin=<VIN>
teslable2mqtt           | 2025-02-09T09:10:03.242890926Z 2025/02/09 09:10:03 INFO Publishing topic=tb2m/<VIN>/rssi/state access path=connection_status.rssi state=-80 old_state=-79
teslable2mqtt           | 2025-02-09T09:10:03.243611497Z 2025/02/09 09:10:03 DEBU Waiting for next poll interval interval=20
teslable2mqtt           | 2025-02-09T09:10:23.245187350Z 2025/02/09 09:10:23 DEBU Publish state loop handler=per_vehicle for=tb2m_<VIN>
tesla-ble-http-proxy    | 2025-02-09T09:10:23.247754373Z 2025/02/09 10:10:23 INFO received command=connection_status
teslable2mqtt           | 2025-02-09T09:10:23.249115411Z 2025/02/09 09:10:23 DEBU Getting proxy response url=http://localhost:8080/api/proxy/1/vehicles/<VIN>/connection_status
teslable2mqtt           | 2025-02-09T09:10:23.531399760Z 2025/02/09 09:10:23 DEBU Getting proxy response url=http://localhost:8080/api/proxy/1/vehicles/<VIN>/body_controller_state
tesla-ble-http-proxy    | 2025-02-09T09:10:23.532187466Z 2025/02/09 10:10:23 INFO received command=body_controller_state
tesla-ble-http-proxy    | 2025-02-09T09:10:24.531045675Z 2025/02/09 10:10:24 INFO connecting to Vehicle ...
tesla-ble-http-proxy    | 2025-02-09T09:10:25.534665067Z 2025/02/09 10:10:25 ERRO can't connect to vehicle error="vehicle not in range: ble: failed to scan for <VIN>: context deadline exceeded"
teslable2mqtt           | 2025-02-09T09:10:25.537411152Z panic: assignment to entry in nil map
teslable2mqtt           | 2025-02-09T09:10:25.537479537Z
teslable2mqtt           | 2025-02-09T09:10:25.537495214Z goroutine 1663 [running]:
teslable2mqtt           | 2025-02-09T09:10:25.537856567Z TeslaBle2Mqtt/internal/handler.publishState({0x42a680, 0x4000482b90}, {0x7fd1329f44, 0x11}, 0x40003464e0, {0x42cad0, 0x40001c2288}, 0x40000c0200, 0x4000346510, 0x40003301f0)
teslable2mqtt           | 2025-02-09T09:10:25.537897088Z        /build/internal/handler/handler.go:269 +0x204
teslable2mqtt           | 2025-02-09T09:10:25.537912817Z TeslaBle2Mqtt/internal/handler.Run.func3.1()
teslable2mqtt           | 2025-02-09T09:10:25.537926619Z        /build/internal/handler/handler.go:399 +0x134
teslable2mqtt           | 2025-02-09T09:10:25.537940786Z created by TeslaBle2Mqtt/internal/handler.Run.func3 in goroutine 34
teslable2mqtt           | 2025-02-09T09:10:25.537959379Z        /build/internal/handler/handler.go:393 +0x1b4
teslable2mqtt           | 2025-02-09T09:10:26.006448421Z 2025/02/09 09:10:26 INFO Starting TeslaBle2Mqtt
teslable2mqtt           | 2025-02-09T09:10:26.006823055Z 2025/02/09 09:10:26 DEBU Running with settings="&{Vins:[<VIN>] ProxyHost:http://localhost:8080 PollInterval:90 PollIntervalCharging:20 MaxChargingAmps:16 MqttHost:<IP> MqttPort:1883 MqttUser: <USER> MqttPass: <PASS> MqttQos:0 DiscoveryPrefix:homeassistant MqttPrefix:tb2m ResetDiscovery:false SensorsYaml: LogLevel:debug MqttDebug:false ReportedVersion:dev ReportedConfigUrl:{proxy-host}/dashboard ForceAnsiColor:true LogPrefix:}"

Since this error is most likely caused by an unstable connection, maybe a solution can be to catch these errors and repeat the last command. After the crash and restart, the response seems to be fine each time.

[Lenart12]

Nice report thanks :^) New versions published everywere with the fix.