lost mqtt connexion? #176

vbarrier · 2022-05-10T14:31:09Z

Hi! thank you for this great addon :)

However, I have a problem since I use it :(. It seems that the backend loose the connection with the Mosquitto server or doesn't not refresh the cached data.

I'm polling the api/v1/cars/*/status every 1 minutes to populate a tracking database.

vbarrier · 2022-05-11T08:13:38Z

I can confirm that of the docker container fix the problem. Any insight on what happen is happening?

tobiasehlert · 2022-05-11T09:12:31Z

Hi @vbarrier,
What version of TeslaMateApi and Mosquitto are you using in your setup?
Has this issue appeared after you have done some upgrade?
You you see some suspicious entries in the container logs?

I can confirm that of the docker container fix the problem. Any insight on what happen is happening?

What you mean with docker container fix?

vbarrier · 2022-05-16T07:11:52Z

Hi I'm using the latest version of TeslMateApi (1.14) and MQTT version is 2.

It seems that the api lost connexion or doesn't take any more mqtt updates..

1652680291: Client teslamateapi-Lv85 closed its connection.
1652680293: New connection from 172.18.0.11:53518 on port 1883.
1652680293: New client connected from 172.18.0.11:53518 as teslamateapi-Jp2A (p2, c1, k2).

About docker container, I mean, that a restart of the docker container fix the issue for couple hours..

virusbrain · 2022-09-19T14:05:16Z

Hi @vbarrier,

have you done some more debugging for this issue? I currently experiencing the exact same behavior.

vbarrier · 2022-09-19T15:37:19Z

Hi, still facing the bug I ended up restarting the container every 4 hours. :(

LelandSindt · 2022-09-19T21:02:41Z

I looks like connections should be re-established...

teslamateapi/src/v1_TeslaMateAPICarsStatus.go

Lines 134 to 135 in 27d2044

    
           opts.SetAutoReconnect(true)                           // if connection drops automatically re-establish it 
        
           opts.AutoReconnect = true

but also.. it looks like there are some some handlers that could be better utilized at a minimum for the purpose of logging... for example....
https://pkg.go.dev/github.com/eclipse/paho.mqtt.golang#ClientOptions.SetConnectionLostHandler

... again.. might be worth adding some logging.. then we may be able to better determine the nature of the failure.

virusbrain · 2022-09-21T13:17:28Z

I have forked the project and tried to add some debugging output as suggested. This version is running now inside a docker container. We will see if the problem occurs again, then I will keep you informed. If you look in my forked sourcecode you may see that I am not a go developer ;-).

virusbrain · 2022-09-21T14:31:41Z

I have forked the project and tried to add some debugging output as suggested. This version is running now inside a docker container. We will see if the problem occurs again, then I will keep you informed. If you look in my forked sourcecode you may see that I am not a go developer ;-).

The problem occurred again. For me it looks like there is no MQTT issue. I cannot see any log entries regarding lost connections or reconnecting. But if I call the status api end point I get:

teslamateapi_1 | 2022/09/21 16:27:00.611535 [debug] TeslaMateAPICarsStatusV1 - (/api/v1/cars/1/status) returned data:
teslamateapi_1 | 2022/09/21 16:27:00.611642 [debug] {"data":{"car":{"car_id":1,"car_name":"XXXXXX"},"status":{"display_name":"","state":"suspended", [...]

In the TeslaMate UI I see the state as "online" not "suspended".

I have tried to restart the my MQTT-Server (mosquitto in this case) and got the following messages in the logfile:

teslamateapi_1 | 2022/09/21 16:25:55.177510 [error] MQTT connection lost: %s
teslamateapi_1 | 2022/09/21 16:25:55.177578 [info] mqtt reconnecting...
teslamateapi_1 | 2022/09/21 16:25:56.209363 [info] mqtt reconnecting...

So the "extended logging" seems to work. Maybe there is a problem with the cache?

virusbrain · 2022-09-27T06:30:17Z

I have tried to restart the my MQTT-Server (mosquitto in this case) and got the following messages in the logfile:

teslamateapi_1 | 2022/09/21 16:25:55.177510 [error] MQTT connection lost: %s
teslamateapi_1 | 2022/09/21 16:25:55.177578 [info] mqtt reconnecting...
teslamateapi_1 | 2022/09/21 16:25:56.209363 [info] mqtt reconnecting...

So the "extended logging" seems to work. Maybe there is a problem with the cache?

Another example:
teslamateapi_1 | 2022/09/27 01:30:03.468099 [error] MQTT connection lost: pingresp not received, disconnecting teslamateapi_1 | 2022/09/27 01:30:03.468264 [info] mqtt reconnecting...

Maybe we have to "resubscribe" the topics after a reconnect? Does anybody know?

vbarrier · 2022-09-28T18:11:05Z

I also think this is a cache problem somewhere. I'm querying the teslamate-api every minutes and after sometime not working anymore. The restart thing remove all cache.. I will try to have a mirror setup as I don't want to break my current production setup.

virusbrain · 2022-09-28T20:29:42Z

I have another point found and currently do some tests with this patch implemented: virusbrain@3ce7126

Test is currently ongoing and as I am not a MQTT expert I am not sure which side effects this patch would produce... But if it will help I may be able to make the code a bit more fancy and create a pull request for this.

LelandSindt · 2022-09-29T13:20:02Z

virusbrain@3ce7126#r85320141

If I read your response correctly, I should be able to re-create this scenario by restarting the MQTT service, is that correct?

virusbrain · 2022-09-29T13:38:01Z

virusbrain@3ce7126#r85320141

If I read your response correctly, I should be able to re-create this scenario by restarting the MQTT service, is that correct?

This should be the case.

As already mentioned I do currently running a version with opts.SetCleanSession(false) set. Because I guess the subscriptions get lost when a reconnect is necessary. While googeling I found this which - I think - goes in the same direction of this bug: emitter-io/go#18

virusbrain · 2022-10-01T14:06:54Z

As already mentioned I do currently running a version with opts.SetCleanSession(false) set. Because I guess the subscriptions get lost when a reconnect is necessary. While googeling I found this which - I think - goes in the same direction of this bug: emitter-io/go#18

Just FYI: With SetCleanSession(false) my Docker container runs for about 72h without any problems. All data seems to be refreshed correctly.

So from my point of view we do have two possibilities:

Set SetCleanSession to false (as I have done with virusbrain@3ce7126)
Find a way to resubscribe to the mqtt topcis on a reconnect.

LelandSindt · 2022-10-01T14:16:43Z

This is really good information, thank you for taking the time to troubleshoot and document.

I will see what I can do to make time this next week to dig in... I am inclined to say we should certainly be re-subscribing on re-connect... I would need to read up more on SetCleanSession.

LelandSindt · 2022-10-05T02:04:59Z

After reviewing/testing some... it looks like opts.SetCleanSession(false) is the simplest solution. I would like to do a little more testing (likely tomorrow while my wife drives to/from work) and some more reading to confirm/support the change.

LelandSindt · 2022-10-05T03:20:52Z

also considering returning 500 when mqtt is not connected...

LelandSindt@8ecda10

LelandSindt · 2022-10-05T13:23:46Z

Test went well this morning. I was able to interrupt the connection between teslamateapi and mosquitto see the connection loss, re-connection and new data flow. I think that the 500 on connection loss provides value but I am open to feedback.

opts.SetCleanSession(false) only fixes situations where the connection is lost but mosquitto maintains state. If mosquitto is restarted and looses state, when teslamateapi re-connects its subscriptions will have been lost and no new updates will be sent... 🤔

virusbrain · 2022-10-05T14:36:21Z

Test went well this morning. I was able to interrupt the connection between teslamateapi and mosquitto see the connection loss, re-connection and new data flow. I think that the 500 on connection loss provides value but I am open to feedback.

opts.SetCleanSession(false) only fixes situations where the connection is lost but mosquitto maintains state. If mosquitto is restarted and looses state, when teslamateapi re-connects its subscriptions will have been lost and no new updates will be sent... 🤔

Aren't we able to simply resubscribe to the mqtt topics after a reconnect occured? According to my understandig we just have to refactor the subscription part (https://github.com/LelandSindt/teslamateapi/blob/96d53a66dd30574a1f1d15a4d86f77766d9b5018/src/v1_TeslaMateAPICarsStatus.go#L151-L156) somehow that it can subscribe to the topics in a reconnecting-handler. Or do I miss something?

LelandSindt · 2022-10-05T15:29:23Z

I started down the re-subscribe path last night, but could not quite grok how it would best be done cleanly.

... I will have another look at it tonight.

LelandSindt · 2022-10-06T02:18:24Z

After reviewing this.. eclipse-paho/paho.mqtt.golang#22

I made these changes... LelandSindt@59784a7 they look good in simple/synthetic tests, I will test again in the morning.

virusbrain · 2022-10-06T08:12:26Z

After reviewing this.. eclipse/paho.mqtt.golang#22

I made these changes... LelandSindt@59784a7 they look good in simple/synthetic tests, I will test again in the morning.

Yeah, on the first look this looks promising! I will setup a docker container to test this too.

vbarrier · 2022-10-06T10:13:07Z

Thank you for your time & testing

I will do this too this evening

LelandSindt · 2022-10-06T12:33:30Z

watch "curl -s localhost:8080/api/v1/cars/1/status | jq '.data.status.odometer' "

kubectl --namespace mosquitto delete pod mosquitto-56dc565797-m6mv8

[GIN] 2022/10/06 - 07:22:07 | 200 |    8.492773ms |       127.0.0.1 | GET      "/api/v1/cars/1/status"     
2022/10/06 07:22:07.572515 [error] MQTT connection lost: EOF                                                                                                                                                              
2022/10/06 07:22:07.572517 [info] mqtt reconnecting...                                                                                                                                                                    
2022/10/06 07:22:07.572543 [info] mqtt connecting...                                                         
2022/10/06 07:22:08.581626 [info] mqtt reconnecting... 
2022/10/06 07:22:08.581692 [info] mqtt connecting...
2022/10/06 07:22:09.149964 [notice] TeslaMateAPICarsStatusV1 mqtt is disconnected.. can not return status for car without mqtt!
2022/10/06 07:22:09.149994 [info] TeslaMateAPICarsStatusV1 - (/api/v1/cars/1/status) executed successfully.
[GIN] 2022/10/06 - 07:22:09 | 500 |     103.194µs |       127.0.0.1 | GET      "/api/v1/cars/1/status"
2022/10/06 07:22:10.583033 [info] mqtt reconnecting... 
2022/10/06 07:22:10.583079 [info] mqtt connecting...
...
2022/10/06 07:22:21.414245 [notice] TeslaMateAPICarsStatusV1 mqtt is disconnected.. can not return status for car without mqtt!                                                                                           
2022/10/06 07:22:21.414260 [info] TeslaMateAPICarsStatusV1 - (/api/v1/cars/1/status) executed successfully.                                                                                                               
[GIN] 2022/10/06 - 07:22:21 | 500 |      52.859µs |       127.0.0.1 | GET      "/api/v1/cars/1/status"                                                                                                                    
2022/10/06 07:22:22.585712 [info] mqtt reconnecting...                                                                                                                                                                    
2022/10/06 07:22:22.585733 [info] mqtt connecting...                                                                                                                                                                      
2022/10/06 07:22:22.654997 [info] mqtt connected...                                                                                                                                                                       
2022/10/06 07:22:22.659715 [info] subscribed to: teslamate/cars/#                                                                                                                                                         
2022/10/06 07:22:23.470383 [info] TeslaMateAPICarsStatusV1 - (/api/v1/cars/1/status) executed successfully.                                                                                                               
[GIN] 2022/10/06 - 07:22:23 | 200 |   23.586126ms |       127.0.0.1 | GET      "/api/v1/cars/1/status"                                                                                                                    
2022/10/06 07:22:25.489866 [info] TeslaMateAPICarsStatusV1 - (/api/v1/cars/1/status) executed successfully.

After K8s started a new mosquitto pod teslamateapi re-connected/re-subscribed and curl | jq ... displayed updated odometer readings as my wife drove to work this morning... (I miss driving my car to work.. but I don't miss driving to work... )

looks good to me, y'all have any feedback or concerns?

LelandSindt · 2022-10-06T21:53:58Z

@virusbrain do you want the honour of issuing the PR? --- if not let me know, I can put it together right quick.

virusbrain · 2022-10-07T05:56:33Z

@virusbrain do you want the honour of issuing the PR? --- if not let me know, I can put it together right quick.

I would really be happy issuing the PR. I try to cleanup the MQTT_ClientID stuff and then open the PR. I think I have some time this evening.

LelandSindt · 2022-10-07T12:28:36Z

specific to MQTT_CLIENTID I should have mentioned I cleaned that up last night...
e649d38

Let me know if you have any questions/issues pulling my commits/changes in!

Co-authored-by: Leland Sindt <[email protected]>

tobiasehlert added good first issue Good for newcomers question Further information is requested labels May 11, 2022

virusbrain added a commit to virusbrain/teslamateapi that referenced this issue Sep 21, 2022

Issued tobiasehlert#176 try to add some debugging info

424cc29

virusbrain mentioned this issue Oct 7, 2022

Fix for issue #176 #199

Merged

tobiasehlert added bug Something isn't working and removed question Further information is requested labels Oct 11, 2022

tobiasehlert closed this as completed in #199 Oct 11, 2022

tobiasehlert pushed a commit that referenced this issue Oct 11, 2022

Fix mqtt reconnection issue #176 (#199)

02826ed

Co-authored-by: Leland Sindt <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

lost mqtt connexion? #176

lost mqtt connexion? #176

vbarrier commented May 10, 2022

vbarrier commented May 11, 2022

tobiasehlert commented May 11, 2022

vbarrier commented May 16, 2022

virusbrain commented Sep 19, 2022

vbarrier commented Sep 19, 2022

LelandSindt commented Sep 19, 2022

virusbrain commented Sep 21, 2022

virusbrain commented Sep 21, 2022

virusbrain commented Sep 27, 2022

vbarrier commented Sep 28, 2022

virusbrain commented Sep 28, 2022 •

edited

Loading

LelandSindt commented Sep 29, 2022

virusbrain commented Sep 29, 2022

virusbrain commented Oct 1, 2022 •

edited

Loading

LelandSindt commented Oct 1, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

virusbrain commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 6, 2022

virusbrain commented Oct 6, 2022

vbarrier commented Oct 6, 2022

LelandSindt commented Oct 6, 2022

LelandSindt commented Oct 6, 2022

virusbrain commented Oct 7, 2022

LelandSindt commented Oct 7, 2022

lost mqtt connexion? #176

lost mqtt connexion? #176

Comments

vbarrier commented May 10, 2022

vbarrier commented May 11, 2022

tobiasehlert commented May 11, 2022

vbarrier commented May 16, 2022

virusbrain commented Sep 19, 2022

vbarrier commented Sep 19, 2022

LelandSindt commented Sep 19, 2022

virusbrain commented Sep 21, 2022

virusbrain commented Sep 21, 2022

virusbrain commented Sep 27, 2022

vbarrier commented Sep 28, 2022

virusbrain commented Sep 28, 2022 • edited Loading

LelandSindt commented Sep 29, 2022

virusbrain commented Sep 29, 2022

virusbrain commented Oct 1, 2022 • edited Loading

LelandSindt commented Oct 1, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

virusbrain commented Oct 5, 2022

LelandSindt commented Oct 5, 2022

LelandSindt commented Oct 6, 2022

virusbrain commented Oct 6, 2022

vbarrier commented Oct 6, 2022

LelandSindt commented Oct 6, 2022

LelandSindt commented Oct 6, 2022

virusbrain commented Oct 7, 2022

LelandSindt commented Oct 7, 2022

virusbrain commented Sep 28, 2022 •

edited

Loading

virusbrain commented Oct 1, 2022 •

edited

Loading