Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Reconnect to MQTT broker if connection is lost #166

Closed
c0ldtech opened this issue Apr 19, 2024 · 8 comments · Fixed by #168
Closed

Reconnect to MQTT broker if connection is lost #166

c0ldtech opened this issue Apr 19, 2024 · 8 comments · Fixed by #168

Comments

@c0ldtech
Copy link

It seems that there currently is no reconnect mechanism in place if the connection to MQTT broker is lost for whatever reason.

To Reproduce
Steps to reproduce the behavior:

  1. have deye-inverter-mqtt container running and working
  2. restart the MQTT broker it is connected to

Expected behavior
Connection retries should be attempted at regular intervals.

Actual behaviour
Error Unknown MQTT publishing error: Message publish failed: The client is not currently connected. is seen in the logs and no reconnection attempt is made.

Software (please complete the following information):

  • deye-inverter-mqtt version: 2024.04.2
@kbialek
Copy link
Owner

kbialek commented Apr 20, 2024

Please provide the config and full debug log. Actually MQTT reconnect is already in place. It's performed by the underlying paho-mqtt library, and is also tested in tests/deye_mqtt_inttest.py

@c0ldtech
Copy link
Author

How can I generate the debug log? By config you mean the deye docker container config, right?

@kbialek
Copy link
Owner

kbialek commented Apr 20, 2024

How can I generate the debug log?

Set LOG_LEVEL env var to DEBUG

By config you mean the deye docker container config, right?

Yes

@c0ldtech
Copy link
Author

OK, here goes - this is my docker compose config:


  deye-mqtt:
    container_name: deye-mqtt
    image: ghcr.io/kbialek/deye-inverter-mqtt
    environment:
      - TZ=Europe/Berlin
      - DEYE_LOGGER_IP_ADDRESS=192.168.188.47
      - DEYE_LOGGER_PORT=8899
      - DEYE_LOGGER_SERIAL_NUMBER=2756771583
      - MQTT_HOST=192.168.15.4
      - MQTT_PORT=1883
      - MQTT_USERNAME=mqttoelzsch
      - MQTT_PASSWORD=77dfjkhg55
      - DEYE_DATA_READ_INTERVAL=15
      - DEYE_PUBLISH_ON_CHANGE=true
      - DEYE_METRIC_GROUPS=deye_sg04lp3,deye_sg04lp3_battery,settings
      - DEYE_FEATURE_TIME_OF_USE=true
    
    restart: unless-stopped
    networks:
      hostPublicUtil:
        ipv4_address: 192.168.15.21
    dns:
      - 192.168.10.53
      - 192.168.15.53

I'll attach the log. It seems it tries to publish when the broker is stopped and fails. Judging by the log it even reeastablishes the connection to the broker, but for some reason does not publish anymore.

_deye-mqtt_logs.txt

@kbialek
Copy link
Owner

kbialek commented Apr 20, 2024

Reconnecting worked. Look at the bottom of the log.
The first two lines are showing reconnecting, the next two lines are showing logger status publishing.

2024-04-20 22:33:53,963 - paho.mqtt.client - DEBUG - Sending CONNECT (u1, p1, wr1, wq1, wf1, c1, k60) client_id=b'deye-inverter-xxxxxxxxxxx'
2024-04-20 22:33:53,964 - paho.mqtt.client - DEBUG - Received CONNACK (0, 0)
2024-04-20 22:33:53,965 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m126), 'b'deye/logger_status'', ... (6 bytes)
2024-04-20 22:33:53,966 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 126)

@c0ldtech
Copy link
Author

Yes, I saw that. But before losing connection to the broker the log looked like this when successfully publishing:

2024-04-20 22:33:16,386 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/logger_status', value: 'online'
2024-04-20 22:33:16,386 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m85), 'b'deye/logger_status'', ... (6 bytes)
2024-04-20 22:33:16,387 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 85)
2024-04-20 22:33:16,387 - DeyeMqttClient - INFO - Logger is online
2024-04-20 22:33:16,387 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/dc/pv1/power', value: '0.0'
2024-04-20 22:33:16,388 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m86), 'b'deye/dc/pv1/power'', ... (3 bytes)
2024-04-20 22:33:16,389 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 86)
2024-04-20 22:33:16,389 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/dc/pv2/power', value: '0.0'
2024-04-20 22:33:16,389 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m87), 'b'deye/dc/pv2/power'', ... (3 bytes)
2024-04-20 22:33:16,390 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 87)
2024-04-20 22:33:16,391 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/dc/pv1/voltage', value: '0.0'
2024-04-20 22:33:16,391 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m88), 'b'deye/dc/pv1/voltage'', ... (3 bytes)
2024-04-20 22:33:16,391 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 88)
2024-04-20 22:33:16,392 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/dc/pv2/voltage', value: '0.0'
2024-04-20 22:33:16,392 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m89), 'b'deye/dc/pv2/voltage'', ... (3 bytes)
2024-04-20 22:33:16,392 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 89)
2024-04-20 22:33:16,392 - DeyeMqttClient - DEBUG - Publishing message. topic: 'deye/dc/pv1/current', value: '0.0'
2024-04-20 22:33:16,393 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m90), 'b'deye/dc/pv1/current'', ... (3 bytes)

...continuing with all the other metrics. But after it reestablishes the connection to the broker, it stops after

2024-04-20 22:33:53,965 - paho.mqtt.client - DEBUG - Sending PUBLISH (d0, q1, r0, m126), 'b'deye/logger_status'', ... (6 bytes)
2024-04-20 22:33:53,966 - paho.mqtt.client - DEBUG - Received PUBACK (Mid: 126)

and does not continue. Next log entry should have been

DeyeMqttClient - INFO - Logger is online

followed by the readings from the inverter. That never happens though, no matter if I wait one minute or ten minutes. Checking the topics, there really is nothing published to the broker.

Only restarting the deye-mqtt container will make it publish to the broker again.

So I guess this does not happen to you if you stop your MQTT broker until the error shows up in the logs and start the broker again? For you publishing resumes as it should without needing to restart the deye-mqtt container?

@kbialek
Copy link
Owner

kbialek commented Apr 21, 2024

My educated guess is that it could be a thread locking issue, that I mistakenly introduced when adding multi-inverter support. Could you test this beta version? ghcr.io/kbialek/deye-inverter-mqtt:2024.04.3-beta-1

@c0ldtech
Copy link
Author

c0ldtech commented Apr 22, 2024 •
edited
Loading

Thanks, this seems to work fine:

2024-04-22 07:40:02,425 - DeyeInverterState - INFO - Reading start
2024-04-22 07:40:02,426 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0202-022e]
2024-04-22 07:40:02,631 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3_battery'}, range: 024a-024f]
2024-04-22 07:40:02,762 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0256-027c]
2024-04-22 07:40:03,025 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 02a0-02a7]
2024-04-22 07:40:03,147 - DeyeInverterState - INFO - Reading registers [metrics group: {'settings_micro', 'settings'}, range: 0028-0028]
2024-04-22 07:40:03,272 - DeyeMqttClient - INFO - Logger is online
2024-04-22 07:40:03,333 - DeyeInverterState - INFO - Reading completed
2024-04-22 07:40:17,426 - DeyeInverterState - INFO - Reading start
2024-04-22 07:40:17,426 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0202-022e]
2024-04-22 07:40:17,707 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3_battery'}, range: 024a-024f]
2024-04-22 07:40:17,819 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0256-027c]
2024-04-22 07:40:18,024 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 02a0-02a7]
2024-04-22 07:40:18,147 - DeyeInverterState - INFO - Reading registers [metrics group: {'settings_micro', 'settings'}, range: 0028-0028]
2024-04-22 07:40:23,254 - DeyeMqttClient - ERROR - Failed to connect to MQTT Broker located at 192.168.15.4:1883
2024-04-22 07:40:23,255 - DeyeMqttPublisher - ERROR - Unknown MQTT publishing error: Message publish failed: The client is not currently connected.
2024-04-22 07:40:23,255 - DeyeInverterState - INFO - Reading completed
2024-04-22 07:40:32,426 - DeyeInverterState - INFO - Reading start
2024-04-22 07:40:32,426 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0202-022e]
2024-04-22 07:40:32,624 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3_battery'}, range: 024a-024f]
2024-04-22 07:40:32,747 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0256-027c]
2024-04-22 07:40:32,940 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 02a0-02a7]
2024-04-22 07:40:33,062 - DeyeInverterState - INFO - Reading registers [metrics group: {'settings_micro', 'settings'}, range: 0028-0028]
2024-04-22 07:40:38,178 - DeyeMqttClient - ERROR - Failed to connect to MQTT Broker located at 192.168.15.4:1883
2024-04-22 07:40:38,179 - DeyeMqttPublisher - ERROR - Unknown MQTT publishing error: Message publish failed: The client is not currently connected.
2024-04-22 07:40:38,179 - DeyeInverterState - INFO - Reading completed
2024-04-22 07:40:47,426 - DeyeInverterState - INFO - Reading start
2024-04-22 07:40:47,427 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0202-022e]
2024-04-22 07:40:47,626 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3_battery'}, range: 024a-024f]
2024-04-22 07:40:48,077 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 0256-027c]
2024-04-22 07:40:48,268 - DeyeInverterState - INFO - Reading registers [metrics group: {'deye_sg04lp3'}, range: 02a0-02a7]
2024-04-22 07:40:48,390 - DeyeInverterState - INFO - Reading registers [metrics group: {'settings_micro', 'settings'}, range: 0028-0028]
2024-04-22 07:40:48,497 - DeyeMqttClient - INFO - Logger is online
2024-04-22 07:40:48,527 - DeyeInverterState - INFO - Reading completed

It fails to publish twice because the MQTT broker was offline at that time, but when MQTT came back up it continued publishing. Thank you for the investigation! I'll keep using the Beta for now.

@kbialek kbialek linked a pull request Apr 25, 2024 that will close this issue
Release publish_lock on error #168
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Release publish_lock on error kbialek/deye-inverter-mqtt
2 participants
@kbialek @c0ldtech