Ignores events in "falling sleep" mode

[brianmay]

Describe the bug

I just noticed that when Teslamate it in "falling sleep" mode, which often seems to be the case with my car, it doesn't notice any events that occur with the car. Including driving the car a short distance. Even though the car is awake. As in the Tesla now makes complete trips which are unobserved by teslamate. But as soon as a "cancel sleep attempt" it works out immediately what is happening.

e.g. on several occasions I have "cancel sleep attempt" and it immediately updated the plugged in status, the position of the vehicle, the charge status, etc.

Not sure if coincidence or not, but Teslamate ignoring events in "falling sleep" mode seems to have got a lot worse since I upgraded from 1.21.0 to 1.21.1.

I have copied this from #1221 is this is likely an unrelated bug.

Expected behavior

teslamate should notice when state of car has changed, or if somebody starts trip. Otherwise it is kind of pointless :-)

How to reproduce it (as minimally and precisely as possible):

1. Wait for teslamate to enter "falling sleep" mode, but not actual go to sleep.
2. Go for drive.
3. Notice teslamate still hasn't change and reports car as being locked, at the start point.

Relevant entries from the logs

Don't think this really helps. But log entries at time I canceled the sleep attempt:

2021-01-31 23:35:23.049 car_id=1 [info] Resuming logging
2021-01-31 23:35:25.466 car_id=1 [info] Driving / Start
2021-01-31 23:35:27.641 [info] Stream.Timeout / 5
2021-01-31 23:35:27.836 [info] Connection was closed (a:1|t:6|d:7). Reconnecting …

Environment

• TeslaMate version: 1.21.1
• Type of installation: Docker
• OS TeslaMate is installed on: Kubernetes 1.20.0

[brianmay]

If I continue having problems here, will downgrade to 1.21.0 and see if that helps.

[jmiverson]

I experience this occasionally as well. I’ve mostly gotten into the habit of checking if I recently got home or something (within the time frame that it might be trying to fall asleep).

What I don’t fully understand is why this functionality is still needed in Teslamate after moving to the Streaming API. Why does Teslamate ever stop listening to the car? Will the car not sleep if Teslamate doesn’t perform this “disconnect”?

[brianmay]

It seems to be constantly happening every time now for me that I upgraded to 1.21.1

I tried the "cancel sleep attempt" before the last trip, but it had already entered "falling asleep" before I left.

I am going to downgrade to 1.21.0, at least this will give confirmation if 1.21.1 actually made things worse or not.

[brianmay]

I believe the theory is that the car cannot go to sleep while teslamate is connected to the streaming API. But I am not entirely sure of my facts here.

[brianmay]

Last trip worked fine. Maybe just a string of bad luck?

I would like to think that the code could be improved somehow to solve this, but not really sure I know enough about the "falling asleep" mode to come up with a solution with won't prevent sleep from occuring.

[brianmay]

My attempt to downgrade to 1.21.0 was a failure, due to it constantly the token after unsuccessful renewal (approxish once an hour). Logs: https://gist.github.com/brianmay/4351597a43561253544f530b5d23a5a5. Which unfortunately means I can't easily test this bug with 1.21.0.

I have not seen it ever miss any trips before I upgraded to 1.21.1 however.

I have now upgraded to 1.21.2

[brianmay]

If this is still a problem with 1.21.2 - and I have seen reports it is (#1280 (comment)) - I would like to be able to disable the sleep mode entirely.

If I get the time I might see if I can understand the code enough to to create an option to do this.

[adriankumpf]

The car can only fall asleep if no queries are made via the API. Therefore events CANNOT be detected during this time. However, using the streaming API, TeslaMate is permanently connected until the car goes to sleep. This way we can detect when you start driving or charging during this period (no other logger I know of does this). However, only very limited information can be received via this method.

The crucial thing here is that TeslaMate is able to connect to the streaming API. If this is not the case, short trips can be missed. Keep in mind that TeslaMate is only the "last link in the chain", so if the other systems are not working correctly or are not available, data will be missed.

[jmiverson]

So then, are you saying that for events to be missed, the connection with the Streaming API must have failed/disconnected during the sleep attempt and that TeslaMate has reverted back to the "old" way of polling the car?

[brianmay]

I just had it completely miss a 20 minute trip. Surly even if it the streaming API wasn't working, it should be polling frequently enough not to miss a 20 minute trip?

[brianmay]

If there is no other solution, I would still like to see a way of disabling the sleep mode, e.g. during daylight hours when the car doesn't seem to want to go to sleep anyway.

[brianmay]

Just seeing if I can create a Docker image with debug messages enabled. Fingers crossed :-)

[brianmay]

Wow, that is verbose :-)

But looks like the timeouts are happening on a valid connection, and it reconnects within a second, so this shouldn't be affecting the streaming:

2021-02-04 02:17:59.307 [info] Stream.Timeout / 6
2021-02-04 02:17:59.504 [info] Connection was closed (a:1|t:7|d:3). Reconnecting …
2021-02-04 02:18:00.308 [debug] Connection established
2021-02-04 02:18:00.308 [debug] Subscribing …

[brianmay]

Actually these timeouts do concern me. I think the timeout might be 15 seconds (https://github.com/adriankumpf/teslamate/blob/master/lib/tesla_api/stream.ex#L37), and as this is happening sometimes once a minute, that means it is offline 25% of the time.

[brianmay]

This still doesn't explain it though. Even if the stream gets disconnected, it should pick up the cars state when it reconnects.

[brianmay]

OK, I now have a theory:

I suspect when we are connecting to the stream it is already broken, so we don't receive any events from it. No idea why. Blame Tesla. Or maybe Telstra. Eventually after 70 seconds we time out and recreate the connection. Which is also broken. Even though the stream is broken, polling appears to work fine. Or at least it would work fine if we actually polled.

If the car was in suspended mode, then for 1 in every 10 connection failed connections, if this failed connection had no data, then we would poll the car state. But this doesn't happen because the car is in :online state.

I attempted to make experimental change, where I will poll the car if it is :online and for every connection failed without receiving any data. But unfortunately this has been a failure so far. Due to me not understanding the code 100%. Can provide details if anyone interested.

[brianmay]

Just some random thoughts:

• Is car going to sleep, but not reporting as such? So far I can't actually see any evidence to show this is the case.
• Is car loosing Internet connection? Have seen this happening on my wifi network, with 100% network signal. Also see it happen in areas that should have really good 3G coverage.
• Is car loosing connection to Tesla? Shouldn't happen... But of course this doesn't mean it isn't happening.
• Car has original 8GB eMMC chip that is covered by recently announced recall. Could this be causing problems?

Also note that Tesla app seems to be fine during these periods, but will try do some more testing to try to confirm this. Not entirely convinced here.

[brianmay]

Also, just in case the problem is with the car, last night I rebooted the center console. Will be interesting to see if that has any noticeable impact.

[ToniA]

I've got a car ('16 Model S facelift) which is suffering from slow instrument cluster startup if I enable the Display -> Energy saving option. If I have 'energy saving' off and 'always connected' on, the IC always wakes up instantly. The side-effect is that the car does not sleep.

I have the same issue with streaming, lots of disconnects and often missing the beginning of a drive. Last week I registered to TeslaFi trial, and it seems to work perfectly. I believe it's just polling, and not streaming.

I tried to switch using the non-streaming setting in Teslamate, but the problem is even bigger. The default setting is to try to poll the car every 21 minutes when attempting to go asleep. Since my car never goes to sleep, the Teslamate polling only polls every 21 minutes, which leads to even worse data loss.

I am now experimenting with these settings (set via SQL + restart the teslamate container). Let's see...

[ToniA]

Also, I would be grateful if anybody knows a solution for the slow instrument cluster startup. I.e. also enabling the car to sleep.

The car can't be driven before the IC has started up. MCU1 eMMC has been replaced (daughterboard change).

[brianmay]

Lots of disconnects, is normal I think. It will reconnect immediately, and shouldn't lose much data while disconnected. Unless of course the car lost reception.

Often missing the beginning of the drive is more annoying. In fact, I have lost complete drives. I would suggest trying rebooting the center console in your car. Surprisingly, this helped a lot for me. https://tesla-info.com/reboot.php - option 1.

There is still sometimes a delay of several minutes before it picks up events. And some quirks. e.g. teslamate sometimes sends the "left geofence" mqtt message before the "disconnected message". Which obviously is nonsense. But acceptable.

A polling solution will always be better, because it keeps the Tesla awake and responsive at all times. I did have such a solution before I moved to teslamate, and it had no issues. I think a streaming solution "could" be better, but I think it was designed for the Tesla app in mind, not a data logging application. So they are not really concerned about tracking all events in such a way that the car is still allowed to go to sleep. Which is rather unfortunate from our point of view.

[brianmay]

Forgot to say, there are a number of bug reports on vehicle not sleeping. See google search. The most recent I think is #826 - this might help.

[brianmay]

Will summarise my observations so far. I believe what is suppose to happen:

• When in "falling asleep" mode, we do not poll the car. But we continue to get streaming events, so we get notified if something changes.
• If car is asleep, when it wakes up we detect the state change. I think this is by polling the appropriate API that doesn't cause car to wake. We immediately poll the car.

What is actually happening:

• When "falling asleep" mode, we do not receive any events.

Theory - need to prove or disprove:

• The Tesla falls asleep but it is still reported as online. As a result, we do not receive any streaming events because the car is asleep. Furthermore when car wakes up, we cannot tell car woke up, because it looked like car always was awake. So we don't poll it.

Need to check:

• When teslamate is in "falling asleep" does it always ignore events? Or only sometimes. I suspect the later. Which would fit the theory.
• When teslamate is in "falling asleep" and ignoring events, is it really asleep? I suspect way to find out is to enter the car and watch how long it takes centre console to show up.

Possible solution:

• Ability to configure hours when teslamate is allowed to try to put car to sleep. So you can configure teslamate to disable sleep during hours when driving is much more likely.
• Even more general: Add to API https://github.com/adriankumpf/teslamate/blob/master/lib/teslamate_web/router.ex#L38 calls that allow/deny sleeping ability. And maybe wakeup on demand. This in turn can be triggered by automatic time based task, motion detector near car, door sensor to car, or something like that.

[LelandSindt]

wakeup on demand. This in turn can be triggered by automatic time based task, motion detector near car, door sensor to car, or something like that.

PUT /api/car/1/logging/resume --- is what you are looking for, I think.

#1433 (reply in thread)

[ToniA]

Wakeup on demand is coming, it will be a part of the TeslaMateApi package. The implementation already works, but at the moment you'd need to build the Docker image from sources from branch https://github.com/tobiasehlert/TeslaMateApi/tree/feature-commands. The combination of TeslaMateApi's wakeup and TeslaMate's resume will do the trick. However, TeslaMate will only monitor the car actively for 3 minutes, and will then let it fall asleep.

[brianmay]

I think I just confirmed that "When teslamate is in "falling asleep" it only sometimes ignores events".

[rmyadsk]

Can confirm. I've noticed that occasionally, Teslamate will be stuck on "falling asleep" while the car will be, say, driving. Clicking the "cancel sleep attempt" button immediately returns the car to the correct state (online, driving, etc.).

I wonder if it is possible to listen for a specific message from the API - without causing the car to stay awake - that would indicate non-sleep activity. That might trigger Teslamate to break the sleep attempt and resume active polling.

[LelandSindt]

If the streaming connection is lost and TeslaMate is falling asleep a transition from Park to Drive will not be noticed. When You cancel sleep attempt TeslaMate returns to online and polling is resumed....

[LelandSindt]

There are two methods for retrieving data from the car, polling (https://owner-api.teslamotors.com/api/1/vehicles/...) and streaming (wss://streaming.vn.teslamotors.com/streaming/)

Polling can return all available details about the status of the car. However, Polling will prevent the car from falling asleep. Attempting to Poll the car while it is asleep will return a 408 (Request Timeout)

Streaming data from the car will return a smaller subset of details. Streaming does not prevent the car from falling asleep. TeslaMate attempts to keep a stream open to the car at all times.

state	polling	streaming
online	x	x
falling asleep	o	x
asleep	x	o
charging	x	x

Because the streaming API does not return information like... window, door, trunk/funk, or charge port door status, these state changes are not noticed/recorded while the TeslaMate is falling asleep.

However, because a streaming connection is aggressively maintained, state changes from park to drive are noticed, and can kick TeslaMate back into online from falling asleep.

[ToniA]

I think the car falls asleep in about 12 minutes. TeslaMate suspends all polling for 19 minutes, but keeps the websocket stream open. What happens if the car goes online at, say, 17 minutes since polling was suspended? I guess the stream was already closed, but the next poll happens only after 2 minutes.

[adriankumpf]

If the car fell asleep after 12 minutes, TeslaMate disconnects and polls the state. If the car is reported to be asleep at that point, regular polling resumes (twice per minute).

If streaming does not work for some reason, TeslaMate consequently won't get any data from the car. In this case it checks the vehicle state every 30 minutes (e.g. [info] Vehicle is still online. Falling asleep for: xx min).

[ToniA]

Yesterday I was polling the Vehicle API directly while the car was falling asleep. TeslaMate didn't notice the car being asleep until 19 minutes had elapsed, but the Vehicle API showed 'asleep' many minutes earlier. I think TeslaMate always suspends the polling for a fixed amount of time, unless the streaming API reports something.

[adriankumpf]

Exactly, it requires the streaming API to immediately notice that the car is asleep. Otherwise it takes 30 minutes until TeslaMate checks the state.

[ToniA]

Here's an interesting data point, I have tried this twice so far with the same result... Somehow querying for the vehicle status disturbs the sleep mode. See the 21:22:41 data point, I think the car would normally fall asleep at this point.

$ while true; do echo `date` `curl -s -X GET -H "Authorization: Bearer <token>" https://owner-api.teslamotors.com/api/1/vehicles/<id>| jq .response.state`; sleep 60; done
Wed 17 Mar 21:05:23 EET 2021 "asleep"
Wed 17 Mar 21:06:24 EET 2021 "asleep"
Wed 17 Mar 21:07:25 EET 2021 "online"
Wed 17 Mar 21:08:26 EET 2021 "online"
Wed 17 Mar 21:09:27 EET 2021 "online"
Wed 17 Mar 21:10:28 EET 2021 "online"
Wed 17 Mar 21:11:29 EET 2021 "online"
Wed 17 Mar 21:12:30 EET 2021 "online"
Wed 17 Mar 21:13:31 EET 2021 "online"
Wed 17 Mar 21:14:32 EET 2021 "online"
Wed 17 Mar 21:15:33 EET 2021 "online"
Wed 17 Mar 21:16:34 EET 2021 "online"
Wed 17 Mar 21:17:35 EET 2021 "online"
Wed 17 Mar 21:18:36 EET 2021 "online"
Wed 17 Mar 21:19:37 EET 2021 "online"
Wed 17 Mar 21:20:38 EET 2021 "online"
Wed 17 Mar 21:21:40 EET 2021 "online"
Wed 17 Mar 21:22:41 EET 2021 "asleep"
Wed 17 Mar 21:23:42 EET 2021 "online"
Wed 17 Mar 21:24:43 EET 2021 "online"
Wed 17 Mar 21:25:44 EET 2021 "online"
Wed 17 Mar 21:26:45 EET 2021 "online"
Wed 17 Mar 21:27:46 EET 2021 "online"
Wed 17 Mar 21:28:47 EET 2021 "online"
Wed 17 Mar 21:29:48 EET 2021 "online"
Wed 17 Mar 21:30:49 EET 2021 "online"
Wed 17 Mar 21:31:51 EET 2021 "online"
Wed 17 Mar 21:32:52 EET 2021 "online"
Wed 17 Mar 21:33:53 EET 2021 "asleep"
Wed 17 Mar 21:34:54 EET 2021 "asleep"
Wed 17 Mar 21:35:55 EET 2021 "asleep"
Wed 17 Mar 21:36:56 EET 2021 "asleep"
Wed 17 Mar 21:37:57 EET 2021 "asleep"

I woke the car up at Wed 17 Mar 21:06:38 EET 2021 using the Tesla wake_up API.

This is what I get in TeslaMate's log:

teslamate_1     | 2021-03-17 17:03:15.812 car_id=1 [info] Disconnecting ...
teslamate_1     | 2021-03-17 21:07:04.922 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/27646799048910751/vehicle_data -> 408 (9280.103 ms)
teslamate_1     | 2021-03-17 21:07:04.923 car_id=1 [error] Error / :vehicle_unavailable
teslamate_1     | 2021-03-17 21:07:35.828 car_id=1 [info] Start / :online
teslamate_1     | 2021-03-17 21:07:35.867 car_id=1 [info] Connecting ...
teslamate_1     | 2021-03-17 21:10:42.193 car_id=1 [info] Suspending logging
teslamate_1     | 2021-03-17 21:35:03.857 car_id=1 [info] Fetching vehicle state ...
teslamate_1     | 2021-03-17 21:35:04.738 car_id=1 [info] Start / :asleep
teslamate_1     | 2021-03-17 21:35:04.749 car_id=1 [info] Disconnecting ...

In Grafana I see my car was online between 21:07:35 and 21:35:04.

[brianmay]

OK, so only have skimmed through the updates from yesterday, but to me it sounds like if the Tesla is in "Waiting to sleep" mode for a large period of time (e.g. car doesn't want to go to sleep for any reason), then there is a large chance events will get missed. Because we don't poll the car, and the streaming API is limited in what events it will report.

It sounds like we could poll the car every 15 minutes in this mode - on the assumption that if we have been waiting for sleep this long, the car isn't going to sleep anyway. Which isn't great. But better then not getting any updates.

[ToniA]

I switched to scheduled charging, starting at midnight in February. Before I got my car sleeping, I was missing data from the beginning of each charge. There was also a similar problem with drives.

Now my car is sleeping, and the reporting is just perfect. So there definitely is a problem with streaming API mode and cars which refuse to sleep.

 2021-03-18 00:00:20.974
 2021-03-16 00:00:22.273282
 2021-03-13 00:00:08.581
 2021-03-11 00:00:11.468
 2021-03-10 00:00:14.843
 2021-03-06 00:14:41.842
 2021-03-03 00:28:01.542
 2021-02-28 00:21:00.699
 2021-02-27 00:27:42.312
 2021-02-24 00:14:51.941
 2021-02-23 00:20:17.662
 2021-02-21 00:18:12.928
 2021-02-20 05:18:24.059
 2021-02-19 19:40:07.214
 2021-02-19 00:29:36.072
 2021-02-18 00:20:29.794
 2021-02-17 00:25:24.267
 2021-02-16 00:08:01.891
 2021-02-13 00:27:43.11
 2021-02-12 00:14:42.506
 2021-02-11 00:16:00.14