search

elad-bar / DahuaVTO2MQTT

Listens to events from Dahua VTO unit and publishes them via MQTT Message
103 stars 39 forks source link

Error when disconnected from MQTT #42

Closed dudu631 closed 3 years ago

dudu631 commented 3 years ago

Version used: Docker Image (latest)

When it disconnects from the MQTT Broker, it fails to reconnect until I restart the container.

Usually when I restart home assistant server.

2021-04-27 13:48:28,073 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:28,074 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:28,074 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:29,214 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:29,214 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:29,214 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:48:29,214 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-27 13:50:56,646 INFO __main__ Connecting

2021-04-27 13:50:56,680 INFO __main__ Connecting MQTT Broker

2021-04-27 13:50:56,680 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 177

2021-04-27 15:10:31,152 INFO __main__ Connecting

2021-04-27 15:10:31,226 INFO __main__ Connecting MQTT Broker

2021-04-27 15:10:31,227 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 177

2021-04-27 17:05:50,197 INFO __main__ Connecting

2021-04-27 17:05:50,274 INFO __main__ Connecting MQTT Broker

2021-04-27 17:05:50,275 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 177

2021-04-28 17:50:36,197 INFO __main__ Connecting

2021-04-28 17:50:36,264 INFO __main__ Connecting MQTT Broker

2021-04-28 17:50:36,459 INFO __main__ MQTT Broker connected with result code 0
elad-bar commented 3 years ago

Can you please change the log level to DEBUG (using environment variable DEBUG=True) and post the log afterwards?

thanks

dudu631 commented 3 years ago

Alright, when it crashes again I'll post it.

dudu631 commented 3 years ago 
2021-04-30 21:40:31,664 DEBUG __main__ Publishing MQTT message DahuaVTO/SIPRegisterResult/Event: {'Action': 'Pulse', 'Code': 'SIPRegisterResult', 'Data': {'Date': '30-04-2021 18:40:31', 'LocaleTime': '2021-04-30 18:40:31', 'Success': True, 'UTC': 1619818831.0}, 'Index': 0, 'deviceType': 'VTO2111D-P-S2', 'serialNumber': '6K00DD4PAJ2A544'}

2021-04-30 21:40:32,685 DEBUG __main__ Keep alive

2021-04-30 21:40:32,691 DEBUG __main__ Data received: {'id': 182, 'params': {'timeout': 55}, 'result': True, 'session': 1477911009}

2021-04-30 21:40:32,876 INFO __main__ MQTT Broker got disconnected trying to reconnect

2021-04-30 21:42:55,421 INFO __main__ Connecting

2021-04-30 21:42:55,422 DEBUG asyncio Using selector: EpollSelector

2021-04-30 21:42:55,426 DEBUG __main__ Connection established

2021-04-30 21:42:55,427 DEBUG __main__ Loading Dahua details

2021-04-30 21:42:55,429 DEBUG urllib3.connectionpool Starting new HTTP connection (1): 192.168.0.108:80

2021-04-30 21:42:55,442 DEBUG urllib3.connectionpool http://192.168.0.108:80 "GET /cgi-bin/magicBox.cgi?action=getSystemInfo HTTP/1.1" 401 0

2021-04-30 21:42:55,444 DEBUG urllib3.connectionpool Resetting dropped connection: 192.168.0.108

2021-04-30 21:42:55,463 DEBUG urllib3.connectionpool http://192.168.0.108:80 "GET /cgi-bin/magicBox.cgi?action=getSystemInfo HTTP/1.1" 200 260

2021-04-30 21:42:55,465 INFO __main__ Connecting MQTT Broker

2021-04-30 21:42:55,466 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 159

Seems like it's not trying again to connect to the MQTT broker.

elad-bar commented 3 years ago

Yes, it fails to connect to your unit, will check what can potentially be the problem

dudu631 commented 3 years ago

My guess is when something happens to the server, like a power loss or a full restart...it tries to connect to the MQTT broker that is not UP yet, and it fails. What I find odd is that it's not trying to connect again later on.

That could go 2 ways, implement the retry to the mqtt connection or provide an endpoint so we can check healthstatus from home assistant, that way I could send a command to restart the container I guess.

elad-bar commented 3 years ago

The error is related to the Dahua unit, MQTT is different protocol than http which the error related to

dudu631 commented 3 years ago

Yeah, I'm aware of the difference. I just thought there was no relation between the error on the connection to the Dahua VTO itself as it returns a 401 (when it's booting up) and right after returns a 200 so I thought that part was ok.

The problem is the connection refused right after...

2021-04-30 21:42:55,465 INFO __main__ Connecting MQTT Broker

2021-04-30 21:42:55,466 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 159

What am I missing?

dudu631 commented 3 years ago

Found a fix. Will explain it in detail as soon as I finish some tests.

I'll open a PR later, thanks!

dudu631 commented 3 years ago

So, the problem was the first connection to the MQTT Broker.

When the Broker was UP, there was no problem:

============Connecting with BROKER UP============
2021-05-02 19:06:48,247 INFO __main__ Connecting
2021-05-02 19:06:48,305 INFO __main__ Initializing MQTT Broker
2021-05-02 19:06:48,306 INFO __main__ MQTT Broker is trying to connect...
2021-05-02 19:06:48,308 INFO __main__ MQTT Broker connected with result code 0
2021-05-02 19:06:48,833 INFO __main__ Attach event manager
===========================================

When the Broker was DOWN, the first connection didn't take this in consideration:

============Connecting with BROKER DOWN==========

2021-04-27 17:05:50,197 INFO __main__ Connecting
2021-04-27 17:05:50,274 INFO __main__ Connecting MQTT Broker
2021-04-27 17:05:50,275 ERROR __main__ Failed to handle message, error: [Errno 111] Connection refused, Line: 177
===========================================

The process would stop here, with no retries until container restart.

Solution: It'll keep trying until connected with the MQTT broker, just like the on_disconnect handler, but for first-time connection.

===========Connecting with BROKER DOWN===========
2021-05-02 19:09:48,751 INFO __main__ Connecting
2021-05-02 19:09:48,799 INFO __main__ Initializing MQTT Broker,
2021-05-02 19:09:48,799 INFO __main__ MQTT Broker is trying to connect...,
2021-05-02 19:09:48,800 ERROR __main__ Failed to connect to broker, retry in 60 seconds, error: [Errno 111] Connection refused, Line: 103,

2021-05-02 19:10:48,860 INFO __main__ MQTT Broker is trying to connect...,
2021-05-02 19:10:48,861 ERROR __main__ Failed to connect to broker, retry in 60 seconds, error: [Errno 111] Connection refused, Line: 103

2021-05-02 19:11:48,919 INFO __main__ MQTT Broker is trying to connect...
2021-05-02 19:11:48,959 INFO __main__ Attach event manager,
2021-05-02 19:11:49,125 INFO __main__ MQTT Broker connected with result code 0,
===========================================

I also tested a solution mentioned in the PAHO lib for this problem, with websocket type connection but it didn't work...

Opening PR now.

dudu631 commented 3 years ago

PR43

dudu631 commented 3 years ago

Problem fixed on merge #43 .