Teslamate: Login timeout issue

[drlauridsen]

Describe the bug
Timeout occurs when logout and trying to login again on webserver.
Seems there is also a timeout error in log when restarting teslamate.

Expected behavior

How to reproduce it (as minimally and precisely as possible):
Simply logout and login again on webserver - or restart server

Relevant entries from the logs
This is after restarting server - same error applies for simple logout/login..

2021-02-20 15:50:10.617 [info] Version: 1.21.4
2021-02-20 15:51:10.844 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60162.928 ms)
2021-02-20 15:51:10.845 [warn] Token refresh failed: %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}
2021-02-20 15:51:10.845 [info] Scheduling token refresh in 1 h

Screenshots

Data

Environment

• TeslaMate version: 1.21.4
• Type of installation: Docker
• OS TeslaMate is installed on: rpi4b
• User OS & Browser: firefox on win10
• Others:

[darc87]

Same here. Running on Synology NAS in docker. Recent issue..

[meavydev]

Not sure if it's related to 2FA, as I've just turned it on, but can connect with the official Android app (and my own Android app which I've just added 2FA support to). The timeout is where I would expect the auth code prompt to appear, but not sure how teslamate shows this.

[jweber93]

I thought it was 2FA related as well...disabled it and I still have the same timeout issue.

[drlauridsen]

For me it happens with a secondary user account without 2fa - since that account is only used for 3rd party apps..

Can teslamate handle 2fa now?

[drchrisp]

Same here. Stopped working about 4 hours ago.

2021-02-20 20:14:14.976 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60176.076 ms)
2021-02-20 20:14:14.977 [warn] Token refresh failed: %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}

Login not possible either after logging out:

2021-02-20 20:19:14.509 [info] :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
2021-02-20 20:19:21.385 [error] GET https://auth.tesla.com/oauth2/v3/authorize -> error: "timeout" (60092.651 ms)

[treinberger]

+1

[dutenhnj]

Same, I can't log in or refresh the tokens, it has lost connectivity a couple times in the last week (health check failed), restarting teslamate temporarily resolves it (cached token?). Seeing the same errors in the logs.

[antonoal]

+1
For me Teslamate stops working about once a week. I think it’s happened third time now hence decided to check out open issues and found this one.

[hawkpc]

+1
Had connection issues last week, and got timeout on login for 2 Synology NAS and Raspberry Pi for ~15 hours

[UbuntuRoot]

+1... Been seeing the health-check icon and timeout errors for the past two days now. Works for a few mins after restarting the teslamate service.

[rmyadsk]

I am also encountering this issue chronically in the last ~30 hours. I'm finding that stopping and restarting the docker stack resolves it for a short while. Until/unless this is addressed, it might not be unreasonable to add a prophylactic docker-compose down; docker-compose up -d to crontab.

teslamate_1 | 2021-02-20 21:32:14.658 [info] Refreshing access token ...
teslamate_1 | 2021-02-20 21:33:14.755 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60096.508 ms)
teslamate_1 | 2021-02-20 21:33:14.756 [error] GenServer TeslaMate.Api terminating
teslamate_1 | ** (MatchError) no match of right hand side value: {:error, %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}}
teslamate_1 | (teslamate 1.21.4) lib/teslamate/api.ex:151: TeslaMate.Api.handle_info/2
teslamate_1 | (stdlib 3.14) gen_server.erl:689: :gen_server.try_dispatch/4
teslamate_1 | (stdlib 3.14) gen_server.erl:765: :gen_server.handle_msg/6
teslamate_1 | (stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1 | Last message: :refresh_auth
teslamate_1 | 2021-02-20 21:33:16.224 [error] Error / unauthorized
teslamate_1 | 2021-02-20 21:33:16.524 [error] Error / unauthorized
teslamate_1 | 2021-02-20 21:33:44.441 [info] :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
teslamate_1 | 2021-02-20 21:33:44.441 [info] :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_2_api_error, :fuse_blown}}

[rmyadsk]

Okay, I'm running the Docker stack in the foreground to attempt to suss out more about what's happening.

Approximately one minute into runtime we see:

teslamate_1 | 2021-02-20 23:54:25.302 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60340.364 ms)
teslamate_1 | 2021-02-20 23:54:25.303 [warn] Token refresh failed: %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}
teslamate_1 | 2021-02-20 23:54:25.303 [info] Scheduling token refresh in 1 h

Runtime continues cleanly. Subsequently, we see a troubling and predictable accumulation. (car_id 1 was asleep at this time)

I really haven't watched TM in the foreground before (except for when debugging Traefik/LetsEncrypt near startup) so I'm not sure if this is a normal condition while this major timeout issue is not present - _but it appears that approximately every six and a half minutes something is getting hot and bothered._

teslamate_1 | 2021-02-21 00:00:54.624 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:00:54.625 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:00:54.625 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:00:54.645 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:07:20.826 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:07:20.826 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:07:20.827 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:07:20.847 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:13:49.002 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:13:49.002 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:13:49.002 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:13:49.022 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:20:14.930 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:20:14.931 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:20:14.932 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:20:14.952 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:26:40.567 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:26:40.568 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:26:40.568 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:26:40.588 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:33:06.684 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:33:06.684 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:33:06.685 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:33:06.705 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:39:32.870 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:39:32.870 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:39:32.870 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:39:32.892 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:45:59.262 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:45:59.262 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:45:59.262 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:45:59.283 car_id=2 [info] Connecting ...
teslamate_1 | 2021-02-21 00:52:25.821 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:52:25.821 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:52:25.821 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:52:25.840 car_id=2 [info] Connecting ...

However, this does not appear to affect production - TM is fully functional. But as promised, TM attempts to refresh the token, and things get real bad real fast:

teslamate_1 | 2021-02-21 00:54:54.304 [info] Refreshing access token ...
teslamate_1 | 2021-02-21 00:55:54.414 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60099.976 ms)
teslamate_1 | 2021-02-21 00:55:54.414 [error] GenServer TeslaMate.Api terminating
teslamate_1 | ** (MatchError) no match of right hand side value: {:error, %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}}
teslamate_1 | (teslamate 1.21.4) lib/teslamate/api.ex:151: TeslaMate.Api.handle_info/2
teslamate_1 | (stdlib 3.14) gen_server.erl:689: :gen_server.try_dispatch/4
teslamate_1 | (stdlib 3.14) gen_server.erl:765: :gen_server.handle_msg/6
teslamate_1 | (stdlib 3.14) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1 | Last message: :refresh_auth
teslamate_1 | 2021-02-21 00:55:55.230 [error] Error / unauthorized
teslamate_1 | 2021-02-21 00:55:57.081 [error] Error / unauthorized
teslamate_1 | 2021-02-21 00:56:24.166 [info] :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
teslamate_1 | 2021-02-21 00:56:24.166 [info] :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_2_api_error, :fuse_blown}}
teslamate_1 | 2021-02-21 00:56:54.537 [error] POST https://auth.tesla.com/oauth2/v3/token -> error: "timeout" (60102.681 ms)
teslamate_1 | 2021-02-21 00:56:54.537 [warn] Token refresh failed: %TeslaApi.Error{env: nil, message: "timeout", reason: :token_refresh}
teslamate_1 | 2021-02-21 00:56:54.538 [info] Scheduling token refresh in 1 h

Both cars now display "Health check failed" as in the screenshot above.

Not missing a beat, TM persists our tried-and-true six-and-a-half-minute gremlin:

teslamate_1 | 2021-02-21 00:58:51.987 [warn] Too many disconnects from streaming API
teslamate_1 | 2021-02-21 00:58:51.987 car_id=2 [info] Creating new connection …
teslamate_1 | 2021-02-21 00:58:51.987 car_id=2 [info] Disconnecting ...
teslamate_1 | 2021-02-21 00:58:52.008 car_id=2 [info] Connecting ...

[rmyadsk]

Some initial thoughts from reviewing the log:

What I suspect is happening is that TM has implemented insufficient error handling at execution of the token refresh attempt. This results in the runtime continuing in a sort of zombified state at ~T+1 hour runtime. Put another way, it's a wide-awake drunk: step one is admitting it has a problem, but it's slamming vodka Red Bulls, and it doesn't seem to know or care that it's lost communication to its vehicle(s). The six-and-a-half-minute-gremlin continuing unabated post-refresh is particularly galling.

However, killing and restarting the stack appears to revert back to the last known good auth token, and it also seems to confer a limited, but finite, amount of safe-ish runtime. So unless you want to be involved in debugging, you might consider doing that on a regular basis, until we figure out how to embiggen/embetter the system.

So this is very far from ideal, but programmatically & prophylactically restarting the TM stack may eliminate the most awful symptom of this periodic (and irreversible, without user intervention) API terminal hospice care case. You could automate this via cron using crontab -e:

# m h  dom mon dow   command
0 * * * * /usr/local/bin/docker-compose -f /path/to/your/teslamate/docker-compose.yml restart

[send2ali]

ALso having this issue. Made it worse buy rebuilding the Pi4, TM (restoring from backup) and changing my Tesla account password. Now i can get TS to login to my Tesla account at all. Just times out.

2021-02-21 08:20:32.733 [info] GET https://auth.tesla.com/oauth2/v3/authorize -> 200 (453.676 ms)
2021-02-21 08:21:32.766 [error] POST https://auth.tesla.com/oauth2/v3/authorize -> error: "timeout" (60002.418 ms)

[rmyadsk]

I have it on good authority that changing your Tesla account password revokes all existing auth tokens. _Folks, please don't do this if you don't have to._

[send2ali]

@rmyadsk is there a way i can inject my new auth token into TM if i'm able to retrieve it ?

[rmyadsk]

@send2ali my understanding is that once a token is revoked, it is forever invalid. (At least theoretically, as far as GUIDs go.)

[adriankumpf]

This potentially affects all third-party services. Tesla seem to have misconfigured something on their end which makes certain requests time out: https://github.com/timdorr/tesla-api/issues/321

The latest development version of TeslaMate implements a workaround. I'll work on releasing this soon.

[adriankumpf]

Version 1.21.5 with the fix is out.

[juvander]

Excellent, seems to work just fine again!

[rmyadsk]

A most excellent improvement with 1.21.5 - I've had one runtime going smoothly all day without interruption. Excellent refactoring @adriankumpf

My peculiar [warn] Too many disconnects from streaming API event persists once every six-and-a-half-minutes but there does not appear to have any effect on data collection. It appears to be a duplicate of #1359.

[geertsmichael]

I am on 1.21.5 and still get the issue.
I started with a fresh install of postgres, Grafana and TeslaMate.

2021-03-14 17:19:17.734 [info] == Migrated 20210130174838 in 0.0s
2021-03-14 17:19:18.566 [info] Version: 1.21.5
2021-03-14 17:19:18.576 [info] Running TeslaMateWeb.Endpoint with cowboy 2.8.0 at :::4000 (http)
2021-03-14 17:19:18.577 [info] Access TeslaMateWeb.Endpoint at http://localhost
2021-03-14 17:19:18.580 [info] MQTT connection has been established
2021-03-14 17:19:22.105 [info] tzdata release in place is from a file last modified Tue, 22 Dec 2020 23:35:21 GMT. Release file on server was last modified Sun, 24 Jan 2021 19:35:23 GMT.
2021-03-14 17:19:23.281 [info] Tzdata has updated the release from 2020e to 2021a
2021-03-14 17:19:35.619 [info] GET /
2021-03-14 17:19:35.624 [info] Sent 302 in 4ms
2021-03-14 17:19:35.634 [info] GET /sign_in
2021-03-14 17:19:35.638 [info] Sent 200 in 4ms
2021-03-14 17:19:56.027 [info] GET /
2021-03-14 17:19:56.028 [info] Sent 302 in 1ms
2021-03-14 17:19:56.042 [info] GET /sign_in
2021-03-14 17:19:56.044 [info] Sent 200 in 2ms
2021-03-14 17:20:53.114 [error] GET https://auth.tesla.com/oauth2/v3/authorize -> error: "timeout" (60066.840 ms)

[josok64]

This is on 1.21.6, same issue still ?

teslamate_1 | 2021-03-15 18:51:07.194 [info] MQTT connection has been established
teslamate_1 | 2021-03-15 18:51:10.877 [info] tzdata release in place is from a file last modified Tue, 22 Dec 2020 23:35:21 GMT. Release file on server was last modified Sun, 24 Jan 2021 19:35:23 GMT.
teslamate_1 | 2021-03-15 18:51:12.913 [info] Tzdata has updated the release from 2020e to 2021a
teslamate_1 | 2021-03-15 18:51:13.572 [info] GET /sign_in
teslamate_1 | 2021-03-15 18:51:13.577 [info] Sent 200 in 4ms
teslamate_1 | 2021-03-15 18:51:22.184 [info] GET /sign_in
teslamate_1 | 2021-03-15 18:51:22.189 [info] Sent 200 in 4ms
teslamate_1 | 2021-03-15 18:53:09.059 [error] GET https://auth.tesla.com/oauth2/v3/authorize -> error: "timeout" (60088.478 ms)

[iSuchtel]

Had to change my Tesla password about a week ago and now my teslamate is broken too. Already installed 1.21.6 and still getting timeout when logging in.

[adriankumpf]

There's already another issue for this topic https://github.com/adriankumpf/teslamate/issues/1412