Missed drive after charge

[ngardiner]

Describe the bug

This afternoon, I drove for at least 40 minutes (likely ~45) directly after a charging session. The charging session was logged correctly, however when I checked teslamate on arrival, it showed the car status as being "offline for 1 hour, unlocked, user present". Shortly (2-3 mins) after parking, the status returned to normal, however everything prior to that had been lost..

To Reproduce

Steps to reproduce the behavior:

1. Connect vehicle to charger, charge for ~31 mins
2. Send resume API call (automatically sent by my garage door opener)
3. Drive

Expected behavior

The drive should have been logged.

Relevant entries from the logs

11:18:23.561 car_id=1 [info] Start / :asleep
11:24:18.987 car_id=1 [info] Start / :online
11:24:21.020 car_id=1 [info] Charging / SOC: 57%
11:43:43.751 [info] Adding elevation to 1 positions ...
11:50:57.439 [info] PUT /api/car/1/logging/resume
11:50:57.449 [info] Sent 204 in 9ms
11:55:41.743 car_id=1 [info] Derived efficiency factor: 136.1 Wh/km (7x c
onfirmed)
11:55:41.743 car_id=1 [info] Charging / Disconnected / 1.57 kWh – 31 min
11:55:41.743 car_id=1 [info] Start / :online
11:56:42.202 car_id=1 [info] Driving / Start
11:56:55.034 [error] TeslaApi.Error / 504 – %{"error" => "upstream_timeout", "error_description" => "", "response" => nil}
11:56:55.034 car_id=1 [warn] Error / upstream timeout
11:57:00.771 car_id=1 [info] Driving / Ended / 0 km – 0 min
11:57:00.771 car_id=1 [info] Start / :online
11:57:11.132 [error] TeslaApi.Error / 408 – %{
  "error" => "vehicle unavailable: {:error=>\"vehicle unavailable:\"}",
  "error_description" => "",
  "response" => nil
}
11:57:21.656 car_id=1 [info] Start / :offline
12:59:31.970 [info] GET /
12:59:32.020 [info] Sent 200 in 49ms
13:03:43.701 car_id=1 [info] Start / :online

The entry at 12:59 is where I checked the status via web, which would have been perhaps 5 minutes after arriving. It seems like the API response at 11:57:11 caused teslamate to mark the vehicle unavailable and stop polling it. Given it appears to be just a hiccup on the API side, perhaps it should not be taken quite so literally as it seems teslmate backed off for an entire hour inbetween, losing my drive data.

Operating environment

• OS: Ubuntu 19.04
• TeslaMate Version: v1.14.0
• Type of installation: Manual

[adriankumpf]

It seems like the API response at 11:57:11 caused teslamate to mark the vehicle unavailable and stop polling it.

Just like you said it appears to be a hiccup on the API side. But you seem to misinterpret the events that happened as a result. It never stops polling (except of course to let the car fall asleep, which is not the case here). Logging will always continue despite any errors or incorrectly reported status. The absence of any other errors shows that there was nothing wrong otherwise. As of 11:57, the API apparently no longer has reported the car to be driving. I've never seen this kind of behavior before. However, there are relatively often problems with the API, so it doesn't really surprise me.

[ngardiner]

I didn't snip any output from that, it is exactly what was logged. Which was that teslamate interpreted the status as offline from the moment that API status was received and nothing was logged at all until 1 hour 10 seconds later when it sees the car as online again. For that entire time teslamate sees the car as offline. It didn't see it as parked or idle or any of the above, but as offline. My question is if the API maintained that unavailable status for the next hour exactly, would I have seen it logged repeatedly in the same way as the first message? Given the fact it is exactly 1 hour and 10 seconds after the first reported failure it does have all the hallmarks of a backoff mechanism

…

On Fri., 3 Jan. 2020, 7:35 am Adrian Kumpf, ***@***.***> wrote: It seems like the API response at 11:57:11 caused teslamate to mark the vehicle unavailable and stop polling it. Just like you said it appears to be a hiccup on the API side. But you seem to misinterpret the events that happened as a result. It never stops polling (except of course to let the car fall asleep, which is not the case here). Logging will always continue despite any errors or incorrectly reported status. The absence of any other errors shows that there was nothing wrong otherwise. As of 11:57, the API apparently no longer has reported the car to be driving. I've never seen this kind of behavior before. However, there are relatively often problems with the API, so it doesn't really surprise me. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#325>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AGFF33CRIFCEF2U7H53VCPDQ3ZFYPANCNFSM4KA2S2LQ> .

[SigLinJo]

Just as a comment, I've had a couple of instances when I have lost entire drives in a simular way. On new years eve I drove for 15 minutes, stopped at a store for approximatly 5 minutes and then drove 20 more minutes that never got logged. State during the second drive is reported as offline. As soon as I plugged in at the destination I got status charging. When I check in grafana I have 25 seconds of online state before the offline state that ends after the second drive just as I plug in the car for charging. Dont know if this helps, if you want me to go digging in logs and so on just point me in the right direction.

I have a similar situation on an earlier drive but then the logging started up again during the middle of the drive after ca 30 minutes logged as offline. Both happened with firmware 2019.40.50.1 7fefc12d805a in the car.

[adriankumpf]

would I have seen it logged repeatedly in the same way as the
first message?

After logging the state change [info] Start / :offline no further messages need to be output since offline is a legitimate state (e.g. parking in an underground car park). Therefore there is no backoff mechanism: the car gets regularly polled twice per minute when offline.

An easy way to check if this is a bug or an API problem is to open the app while the car is reported as offline. If the app can successfully read the real status of the car it is definitely a bug in teslamate :-)

[adriankumpf]

With the next release a spinner is displayed while the vehicle is polled to make it transparent when TeslaMate is active.