MQTT messages not sent #1465

TheMClaeys · 2021-08-09T07:54:15Z

TheMClaeys
Aug 9, 2021

I tried setting up MQTT to send usage data to Home Assistant.

However, I don't receive anything on Home Assistant and the message queue is always empty.


DSMR-READER
    App / Python / Database                                                     v4.16.3 / v3.7.3 / postgresql
    BE sleep / DL sleep / Retention / Override                                     1.0s / 5.0s / 672h / False
    Latest telegram version read / Parser settings                                             "None" / "101"

DATA
    Telegrams total (est.)                                                                             408389
    Consumption records electricity / gas (est.)                                                46704 / 14166

The connection itself works, I changed the name to test and Mosquito logged the following:

1628492672: Client OurDSMR disconnected.
1628492673: New connection from 192.168.1.11 on port 1883.
1628492673: New client connected from 192.168.1.11 as DSMR (p2, c1, k60, u'<username>').
...
1628492794: Client DSMR disconnected.
...
1628492836: New connection from 192.168.1.11 on port 1883.
1628492836: New client connected from 192.168.1.11 as DSMR (p2, c1, k60, u'<username>').

Since nothing is received, no entities are created so no data can be used.

Supervisorctl status shows everything running fine since the last update (21 days ago, no idea if it was working before that).
Restart didn't fix it.
Backend log shows the following (multiple times):
2021-08-09 08:36:06,970 ERROR persistent_clients run 37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...

After putting debug logging on I see one message with values, however nothing is seen in the logs of Mosquito: (placed in a clickable block due to length).

root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:21:00,628 DEBUG    broker       run                             10                                                                                                 5 | MQTT: Deleting published message (#1496714) from queue
2021-08-09 09:21:00,628 DEBUG    broker       run                              7                                                                                                 8 | MQTT: Publishing queued message (#1496713) for dsmr/day-consumption: {"elect                                                                                                 ricity1": "0.860", "electricity2": "2.730", "electricity1_returned": "0.170", "e                                                                                                 lectricity2_returned": "0.000", "electricity_merged": "3.590", "electricity_retu                                                                                                 rned_merged": "0.170", "electricity1_cost": "0.27", "electricity2_cost": "0.87",                                                                                                  "electricity_cost_merged": "1.14", "total_cost": "1.14", "gas": "0.060", "gas_c                                                                                                 ost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered                                                                                                 _1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "e                                                                                                 nergy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price                                                                                                 _electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-09 09:21:00,629 DEBUG    broker       on_log                          15                                                                                                 8 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m29), 'b'dsmr/day-consumpti                                                                                                 on'', ... (645 bytes)
2021-08-09 09:21:00,629 DEBUG    broker       run                              9                                                                                                 7 | MQTT: Waiting for message (#1496713) to be marked published by broker
2021-08-09 09:21:00,629 DEBUG    broker       on_log                          15                                                                                                 8 | MQTT: (Paho on_log) Received PUBREC (Mid: 29)
2021-08-09 09:21:00,629 DEBUG    broker       on_log                          15                                                                                                 8 | MQTT: (Paho on_log) Sending PUBREL (Mid: 29)
2021-08-09 09:21:00,629 DEBUG    broker       run                              9                                                                                                 7 | MQTT: Waiting for message (#1496713) to be marked published by broker
2021-08-09 09:21:00,629 DEBUG    broker       on_log                          15                                                                                                 8 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 29)
2021-08-09 09:21:00,629 DEBUG    broker       run                             10                                                                                                 5 | MQTT: Deleting published message (#1496713) from queue
2021-08-09 09:21:00,631 DEBUG    mixins       run_loop                         7                                                                                                 3 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:21:05,663 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:21:06,666 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:21:06,668 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:21:06,670 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:21:07,672 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:21:07,675 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:21:07,676 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:21:08,679 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:21:08,681 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:21:08,682 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:21:28,815 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:21:29,818 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:21:29,820 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:21:29,821 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:21:30,824 DEBUG    schedule     execute_scheduled_processes      28 | SP: 1 backend service(s) ready to run
2021-08-09 09:21:30,824 DEBUG    schedule     execute_scheduled_processes      31 | SP: Running "Generate consumption data" (dsmr_consumption.services.run)
2021-08-09 09:21:30,828 DEBUG    services     compact                          59 | Compact: Waiting for newer readings before grouping data...
2021-08-09 09:21:30,829 DEBUG    schedule     reschedule                       76 | SP: Rescheduled "Generate consumption data" to 2021-08-09 09:21:45.828749+02:00 (ETA 0:00:14.999128)
2021-08-09 09:21:30,831 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:21:30,833 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:22:06,160 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:22:07,163 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:22:07,165 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:22:07,167 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:22:08,169 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:22:08,172 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:22:08,173 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:22:09,175 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:22:09,178 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:22:09,179 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:23:05,674 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:23:06,676 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:23:06,679 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:23:06,680 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:23:07,683 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:23:07,685 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:23:07,687 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:23:08,689 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:23:08,692 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:23:08,693 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:25:47,942 DEBUG    services     compact                          59 | Compact: Waiting for newer readings before grouping data...
2021-08-09 09:25:47,943 DEBUG    schedule     reschedule                       76 | SP: Rescheduled "Generate consumption data" to 2021-08-09 09:26:02.942963+02:00 (ETA 0:00:14.999148)
2021-08-09 09:25:47,945 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:25:47,947 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:25:48,950 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:25:48,952 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:25:48,954 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:25:49,956 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:25:49,959 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:25:49,961 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
root@dsmr:/# tail /var/log/supervisor/dsmr_backend.log
2021-08-09 09:26:03,146 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496772) to be marked published by broker
2021-08-09 09:26:03,146 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 66)
2021-08-09 09:26:03,146 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496772) from queue
2021-08-09 09:26:03,148 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:26:04,150 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:26:04,153 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:26:04,154 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:26:05,157 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:26:05,159 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:26:05,161 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
...
2021-08-09 09:38:09,231 DEBUG    schedule     execute_scheduled_processes      28 | SP: 1 backend service(s) ready to run
2021-08-09 09:38:09,231 DEBUG    schedule     execute_scheduled_processes      31 | SP: Running "Generate consumption data" (dsmr_consumption.services.run)
2021-08-09 09:38:09,247 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/day-consumption: {"electricity1": "0.860", "electricity2": "2.730", "electricity1_returned": "0.311", "electricity2_returned": "0.000", "electricity_merged": "3.590", "electricity_returned_merged": "0.311", "electricity1_cost": "0.26", "electricity2_cost": "0.87", "electricity_cost_merged": "1.13", "total_cost": "1.13", "gas": "0.060", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-09 09:38:09,258 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/current-period: {"current_month_electricity1": "13.986", "current_month_electricity1_cost": "0.33", "current_month_electricity1_returned": "90.480", "current_month_electricity2": "47.776", "current_month_electricity2_cost": "13.52", "current_month_electricity2_returned": "36.474", "current_month_electricity_merged": "61.762", "current_month_electricity_cost_merged": "13.85", "current_month_electricity_returned_merged": "126.954", "current_month_gas": "3.152", "current_month_gas_cost": "0.14", "current_month_fixed_cost": "0.00", "current_month_total_cost": "13.99", "current_year_electricity1": "323.119", "current_year_electricity1_cost": "18.55", "current_year_electricity1_returned": "1850.526", "current_year_electricity2": "852.015", "current_year_electricity2_cost": "238.57", "current_year_electricity2_returned": "705.547", "current_year_electricity_merged": "1175.134", "current_year_electricity_cost_merged": "257.12", "current_year_electricity_returned_merged": "2556.073", "current_year_gas": "249.687", "current_year_gas_cost": "12.53", "current_year_fixed_cost": "0.00", "current_year_total_cost": "269.65"}
2021-08-09 09:38:09,268 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity1
2021-08-09 09:38:09,269 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity1_cost
2021-08-09 09:38:09,270 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/current-month/electricity1_returned: 90.480
2021-08-09 09:38:09,271 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity2
2021-08-09 09:38:09,271 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity2_cost
2021-08-09 09:38:09,272 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity2_returned
2021-08-09 09:38:09,272 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity_merged
2021-08-09 09:38:09,272 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/electricity_cost_merged
2021-08-09 09:38:09,274 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/current-month/electricity_returned_merged: 126.954
2021-08-09 09:38:09,274 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/gas
2021-08-09 09:38:09,275 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/gas_cost
2021-08-09 09:38:09,275 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/fixed_cost
2021-08-09 09:38:09,276 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-month/total_cost
2021-08-09 09:38:09,276 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity1
2021-08-09 09:38:09,276 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity1_cost
2021-08-09 09:38:09,278 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/current-year/electricity1_returned: 1850.526
2021-08-09 09:38:09,278 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity2
2021-08-09 09:38:09,279 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity2_cost
2021-08-09 09:38:09,279 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity2_returned
2021-08-09 09:38:09,280 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity_merged
2021-08-09 09:38:09,280 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/electricity_cost_merged
2021-08-09 09:38:09,281 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/current-year/electricity_returned_merged: 2556.073
2021-08-09 09:38:09,282 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/gas
2021-08-09 09:38:09,282 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/gas_cost
2021-08-09 09:38:09,283 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/fixed_cost
2021-08-09 09:38:09,283 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/current-year/total_cost
2021-08-09 09:38:09,285 DEBUG    services     compact                          76 | Compact: Processed reading: 2282302 @ 2021-08-09 09:37:02+02:00
2021-08-09 09:38:09,287 DEBUG    services     compact                          76 | Compact: Processed reading: 2282303 @ 2021-08-09 09:37:08+02:00
2021-08-09 09:38:09,290 DEBUG    services     compact                          76 | Compact: Processed reading: 2282304 @ 2021-08-09 09:37:14+02:00
2021-08-09 09:38:09,293 DEBUG    services     compact                          76 | Compact: Processed reading: 2282305 @ 2021-08-09 09:37:20+02:00
2021-08-09 09:38:09,296 DEBUG    services     compact                          76 | Compact: Processed reading: 2282306 @ 2021-08-09 09:37:26+02:00
2021-08-09 09:38:09,299 DEBUG    services     compact                          76 | Compact: Processed reading: 2282307 @ 2021-08-09 09:37:32+02:00
2021-08-09 09:38:09,301 DEBUG    services     compact                          76 | Compact: Processed reading: 2282308 @ 2021-08-09 09:37:38+02:00
2021-08-09 09:38:09,304 DEBUG    services     compact                          76 | Compact: Processed reading: 2282309 @ 2021-08-09 09:37:44+02:00
2021-08-09 09:38:09,307 DEBUG    services     compact                          76 | Compact: Processed reading: 2282310 @ 2021-08-09 09:37:50+02:00
2021-08-09 09:38:09,310 DEBUG    services     compact                          76 | Compact: Processed reading: 2282311 @ 2021-08-09 09:37:56+02:00
2021-08-09 09:38:09,311 DEBUG    services     compact                          59 | Compact: Waiting for newer readings before grouping data...
2021-08-09 09:38:09,312 DEBUG    schedule     reschedule                       76 | SP: Rescheduled "Generate consumption data" to 2021-08-09 09:38:24.311961+02:00 (ETA 0:00:14.999392)
2021-08-09 09:38:09,314 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:09,314 DEBUG    broker       run                              75 | MQTT: Processing 6 message(s)
2021-08-09 09:38:09,314 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496874) for dsmr/current-year/electricity_returned_merged: 2556.073
2021-08-09 09:38:09,315 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m79), 'b'dsmr/current-year/electricity_returned_merged'', ... (8 bytes)
2021-08-09 09:38:09,315 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PINGREQ
2021-08-09 09:38:09,315 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496874) to be marked published by broker
2021-08-09 09:38:09,315 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 79)
2021-08-09 09:38:09,315 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 79)
2021-08-09 09:38:09,315 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496874) to be marked published by broker
2021-08-09 09:38:09,316 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PINGRESP
2021-08-09 09:38:09,316 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496874) to be marked published by broker
2021-08-09 09:38:09,316 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 79)
2021-08-09 09:38:09,316 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496874) from queue
2021-08-09 09:38:09,317 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496873) for dsmr/current-year/electricity1_returned: 1850.526
2021-08-09 09:38:09,317 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m80), 'b'dsmr/current-year/electricity1_returned'', ... (8 bytes)
2021-08-09 09:38:09,317 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496873) to be marked published by broker
2021-08-09 09:38:09,318 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 80)
2021-08-09 09:38:09,318 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 80)
2021-08-09 09:38:09,318 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496873) to be marked published by broker
2021-08-09 09:38:09,318 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 80)
2021-08-09 09:38:09,318 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496873) from queue
2021-08-09 09:38:09,319 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496872) for dsmr/current-month/electricity_returned_merged: 126.954
2021-08-09 09:38:09,319 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m81), 'b'dsmr/current-month/electricity_returned_merged'', ... (7 bytes)
2021-08-09 09:38:09,319 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496872) to be marked published by broker
2021-08-09 09:38:09,321 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 81)
2021-08-09 09:38:09,321 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 81)
2021-08-09 09:38:09,321 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496872) to be marked published by broker
2021-08-09 09:38:09,321 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496872) to be marked published by broker
2021-08-09 09:38:09,321 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 81)
2021-08-09 09:38:09,322 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496872) from queue
2021-08-09 09:38:09,322 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496871) for dsmr/current-month/electricity1_returned: 90.480
2021-08-09 09:38:09,323 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m82), 'b'dsmr/current-month/electricity1_returned'', ... (6 bytes)
2021-08-09 09:38:09,323 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496871) to be marked published by broker
2021-08-09 09:38:09,323 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 82)
2021-08-09 09:38:09,323 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 82)
2021-08-09 09:38:09,323 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496871) to be marked published by broker
2021-08-09 09:38:09,323 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496871) to be marked published by broker
2021-08-09 09:38:09,323 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 82)
2021-08-09 09:38:09,323 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496871) from queue
2021-08-09 09:38:09,324 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496870) for dsmr/current-period: {"current_month_electricity1": "13.986", "current_month_electricity1_cost": "0.33", "current_month_electricity1_returned": "90.480", "current_month_electricity2": "47.776", "current_month_electricity2_cost": "13.52", "current_month_electricity2_returned": "36.474", "current_month_electricity_merged": "61.762", "current_month_electricity_cost_merged": "13.85", "current_month_electricity_returned_merged": "126.954", "current_month_gas": "3.152", "current_month_gas_cost": "0.14", "current_month_fixed_cost": "0.00", "current_month_total_cost": "13.99", "current_year_electricity1": "323.119", "current_year_electricity1_cost": "18.55", "current_year_electricity1_returned": "1850.526", "current_year_electricity2": "852.015", "current_year_electricity2_cost": "238.57", "current_year_electricity2_returned": "705.547", "current_year_electricity_merged": "1175.134", "current_year_electricity_cost_merged": "257.12", "current_year_electricity_returned_merged": "2556.073", "current_year_gas": "249.687", "current_year_gas_cost": "12.53", "current_year_fixed_cost": "0.00", "current_year_total_cost": "269.65"}
2021-08-09 09:38:09,324 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m83), 'b'dsmr/current-period'', ... (1110 bytes)
2021-08-09 09:38:09,325 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496870) to be marked published by broker
2021-08-09 09:38:09,325 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 83)
2021-08-09 09:38:09,325 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 83)
2021-08-09 09:38:09,325 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496870) to be marked published by broker
2021-08-09 09:38:09,325 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 83)
2021-08-09 09:38:09,325 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496870) from queue
2021-08-09 09:38:09,326 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1496869) for dsmr/day-consumption: {"electricity1": "0.860", "electricity2": "2.730", "electricity1_returned": "0.311", "electricity2_returned": "0.000", "electricity_merged": "3.590", "electricity_returned_merged": "0.311", "electricity1_cost": "0.26", "electricity2_cost": "0.87", "electricity_cost_merged": "1.13", "total_cost": "1.13", "gas": "0.060", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-09 09:38:09,326 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m84), 'b'dsmr/day-consumption'', ... (645 bytes)
2021-08-09 09:38:09,326 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496869) to be marked published by broker
2021-08-09 09:38:09,326 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBREC (Mid: 84)
2021-08-09 09:38:09,326 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBREL (Mid: 84)
2021-08-09 09:38:09,327 DEBUG    broker       run                              97 | MQTT: Waiting for message (#1496869) to be marked published by broker
2021-08-09 09:38:09,327 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 84)
2021-08-09 09:38:09,327 DEBUG    broker       run                             105 | MQTT: Deleting published message (#1496869) from queue
2021-08-09 09:38:09,329 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:10,331 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:10,334 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:10,335 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:11,338 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:11,340 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:11,341 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:12,344 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:12,346 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:12,348 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:13,350 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:13,353 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:13,354 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:14,357 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:14,360 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:14,361 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:15,363 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:15,366 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:15,367 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:16,370 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:16,372 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:16,374 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:17,376 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:17,378 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:17,380 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:18,382 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:18,385 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:18,386 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:19,389 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:19,391 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:19,393 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:20,395 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:20,397 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:20,398 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:21,400 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:21,402 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:21,403 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:22,406 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:22,408 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:22,410 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:23,412 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:23,415 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:23,416 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:24,419 DEBUG    schedule     execute_scheduled_processes      28 | SP: 1 backend service(s) ready to run
2021-08-09 09:38:24,419 DEBUG    schedule     execute_scheduled_processes      31 | SP: Running "Generate consumption data" (dsmr_consumption.services.run)
2021-08-09 09:38:24,422 DEBUG    services     compact                          59 | Compact: Waiting for newer readings before grouping data...
2021-08-09 09:38:24,424 DEBUG    schedule     reschedule                       76 | SP: Rescheduled "Generate consumption data" to 2021-08-09 09:38:39.423217+02:00 (ETA 0:00:14.999191)
2021-08-09 09:38:24,426 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:24,427 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:25,430 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:25,432 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:25,434 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:26,437 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:26,440 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:26,442 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:27,444 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:27,448 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:27,450 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:28,452 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:28,454 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:28,456 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:29,458 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:29,460 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:29,461 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:30,464 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:30,466 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:30,467 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:31,470 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:31,473 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:31,474 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-08-09 09:38:32,476 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-08-09 09:38:32,479 DEBUG    persistent_clients run                              30 | CLIENTS: Running 1 active client(s)
2021-08-09 09:38:32,480 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

The error doesn't show up when running in debug (or it takes a log longer, however nothing was received on Mosquito yet).

What more info can/should I provide to help troubleshoot this?
(I am also not 100% sure it's an issue on DSMR, but since it shows the error in the log and the connection to MQTT itself seems to work I ask the question here).

Both systems are in the same subnet, running on the same ESX host.
It worked before on a previous install of DSMR, but I migrated a while back from a Pi to an ESX system and I didn't really test it since.

Answered by dennissiemensma

Aug 10, 2021

Those errors are (likely) related to network issues:

But I'm not sure, since it maps any non-success result to the error.

Even so, if the errors do not persist every second (since there seems to be quite some time between most of them) it's probably not the root cause, just a side error.

Regarding the data in the broker, have you tried subscribing to all topics to see whatever is available?

E.g. on the host of the broker:

mosquitto_sub -d -t '#'

For me (with a single topic tested) it returns:

Client (null) send…

View full answer

dennissiemensma · 2021-08-09T17:49:25Z

dennissiemensma
Aug 9, 2021
Maintainer

Thanks for asking and providing quite some information.

It seems that the problem is between the broker and HA. The logs state the following:

You are using MQTT QoS 2 level (the most reliable), which requires both the MQTT client (DSMR-reader) and the broker to confirm communication twice. It also ensures each MQTT message is sent/processed exactly once.
Samples:

(Paho on_log) Sending PUBLISH (d0, q2, r1, m29), 'b'dsmr/day-consumption'', ... (645 bytes)
(Paho on_log) Received PUBREC (Mid: 29)
(Paho on_log) Sending PUBREL (Mid: 29)
(Paho on_log) Received PUBCOMP (Mid: 29)

The PUBREC and PUBCOMP are confirmations of the broker receiving the message, so I would expect the broker to receive them properly.

Note that DSMR-reader should sent MQTT messages with the retain flag as well, meaning that the broker should keep track of the latest message of each topic and re-send it to any new clients (such as HA), even if they were not listening the moment the (latest) MQTT message was received by the broker.

You can scan/grep the Sending PUBLISH... messages to see whether the topics you expect are actually sent (and confirmed). E.g.: 'b'dsmr/day-consumption'' of the sample above.
You may be able to provide some details of logs around Client loop() failed (I cannot find them in the log above) to check their root cause.

0 replies

TheMClaeys · 2021-08-10T07:45:02Z

TheMClaeys
Aug 10, 2021
Author

Thanks for the reply. I think QoS2 is the only allowed one since the last update.

That "Client loop() failed" log only shows up apparently when debug logging isn't on.
Probably because it's only a few times a day.

2021-08-08 07:56:09,887 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 08:31:10,350 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 08:36:13,036 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 08:39:14,884 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 09:34:09,640 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 14:32:06,825 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 14:36:09,122 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 14:41:11,849 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 14:45:14,732 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 18:29:08,759 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 18:32:10,676 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 18:59:08,093 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 19:14:15,136 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 19:27:06,181 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 19:40:12,347 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 20:01:10,274 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-08 20:10:14,762 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 08:02:05,890 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 08:16:12,487 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 08:30:03,821 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 08:36:06,970 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 08:41:09,663 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 12:04:02,061 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 14:31:07,477 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 17:21:06,529 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-09 18:29:07,382 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-10 08:09:13,487 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-10 08:29:07,572 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-10 08:34:10,316 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-10 08:38:12,613 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
2021-08-10 08:45:01,091 ERROR    persistent_clients run                              37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...

It doesn't provide more info than that, however I found 1 line when I grep the last 100k lines that is different:
2021-07-28 20:30:05,142 ERROR persistent_clients run 37 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart to prevent waiting forever...

The enabled MQTT statistics are

dsmr/day-consumption
dsmr/current-period
dsmr/consumption/gas/json

It does seem to send something, as I even see rejection messages. Or at least it tries. I see nothing on the other end though.


2021-08-10 09:14:00,299 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1508270) for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.137", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.137", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:14:00,299 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m121), 'b'dsmr/day-consumption'', ... (645 bytes)
2021-08-10 09:15:00,707 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/day-consumption
root@dsmr:/# tail -1000 /var/log/supervisor/dsmr_backend.log | grep 'dsmr/day-consumption'  
2021-08-10 09:12:14,349 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.134", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.134", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:12:14,427 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1508258) for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.134", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.134", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:12:14,427 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m109), 'b'dsmr/day-consumption'', ... (645 bytes)
2021-08-10 09:13:14,827 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.136", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.136", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:13:14,900 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1508264) for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.136", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.136", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:13:14,900 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m115), 'b'dsmr/day-consumption'', ... (645 bytes)
2021-08-10 09:14:00,222 DEBUG    messages     queue_message                    45 | MQTT: Queued message for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.137", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.137", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:14:00,299 DEBUG    broker       run                              78 | MQTT: Publishing queued message (#1508270) for dsmr/day-consumption: {"electricity1": "0.974", "electricity2": "2.980", "electricity1_returned": "0.137", "electricity2_returned": "0.000", "electricity_merged": "3.954", "electricity_returned_merged": "0.137", "electricity1_cost": "0.30", "electricity2_cost": "0.95", "electricity_cost_merged": "1.25", "total_cost": "1.25", "gas": "0.064", "gas_cost": "0.00", "fixed_cost": "0.00", "energy_supplier_price_electricity_delivered_1": "0.317700", "energy_supplier_price_electricity_delivered_2": "0.317700", "energy_supplier_price_electricity_returned_1": "0.045450", "energy_supplier_price_electricity_returned_2": "0.045450", "energy_supplier_price_gas": "0.050090"}
2021-08-10 09:14:00,299 DEBUG    broker       on_log                          158 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m121), 'b'dsmr/day-consumption'', ... (645 bytes)
2021-08-10 09:15:00,707 DEBUG    messages     queue_message                    36 | MQTT: Rejecting message as it exactly matches the previous message sent for this topic: dsmr/day-consumption

I don't think I can set extra logging on Mosquito so I'm a bit blind on that side, I think it shows every log it receives, at least it used to do that.

0 replies

dennissiemensma · 2021-08-10T17:37:52Z

dennissiemensma
Aug 10, 2021
Maintainer

Those errors are (likely) related to network issues:

But I'm not sure, since it maps any non-success result to the error.

Even so, if the errors do not persist every second (since there seems to be quite some time between most of them) it's probably not the root cause, just a side error.

Regarding the data in the broker, have you tried subscribing to all topics to see whatever is available?

E.g. on the host of the broker:

mosquitto_sub -d -t '#'

For me (with a single topic tested) it returns:

Client (null) sending CONNECT
Client (null) received CONNACK (0)
Client (null) sending SUBSCRIBE (Mid: 1, Topic: #, QoS: 0, Options: 0x00)
Client (null) received SUBACK
Subscribed (mid: 1): 0
Client (null) received PUBLISH (d0, q0, r1, m0, 'dsmr/json', ... (798 bytes))
{"id": 5, "timestamp": "2021-08-10T19:34:00+02:00", "electricity_delivered_1": "20854.644", "electricity_returned_1": "0.000", "electricity_delivered_2": "12512.787", "electricity_returned_2": "0.000", "electricity_currently_delivered": "0.000", "electricity_currently_returned": "3.381", "phase_currently_delivered_l1": "0.000", "phase_currently_delivered_l2": "0.000", "phase_currently_delivered_l3": "0.000", "extra_device_timestamp": "2021-08-10T19:30:00+02:00", "extra_device_delivered": "6256.394", "phase_currently_returned_l1": "1.069", "phase_currently_returned_l2": "1.050", "phase_currently_returned_l3": "1.262", "phase_voltage_l1": "255.6", "phase_voltage_l2": "257.6", "phase_voltage_l3": "262.6", "phase_power_current_l1": 5, "phase_power_current_l2": 3, "phase_power_current_l3": 1}

The message was sent a few seconds before subscribing, but Mosquitto seems to cache it properly due to the retain flag.

Do you see similar output with the command above?

0 replies

TheMClaeys · 2021-08-10T21:03:16Z

TheMClaeys
Aug 10, 2021
Author

I'll have to check if I can do that, it's an integration in Home Assistant within its own docker container I think. I'll check it tomorrow to see if I can figure that out.

0 replies

dennissiemensma · 2021-08-10T21:21:19Z

dennissiemensma
Aug 10, 2021
Maintainer

You can try any other client though. It's just that the example above seemed the easiest one to do, were you to have easy access to the host where the server is installed. 🙈

It should also work on any other command line where the mosquitto software (and therefore mosquitto_sub) is installed. Maybe a random MQTT explorer works as well.

0 replies

TheMClaeys · 2021-08-11T06:51:52Z

TheMClaeys
Aug 11, 2021
Author

I learned some new things today 😳

Anyway:

Message 279 received on dsmr/day-consumption at 08:36:

{
    "electricity1": "0.867",
    "electricity2": "2.761",
    "electricity1_returned": "0.000",
    "electricity2_returned": "0.000",
    "electricity_merged": "3.628",
    "electricity_returned_merged": "0.000",
    "electricity1_cost": "0.28",
    "electricity2_cost": "0.88",
    "electricity_cost_merged": "1.16",
    "total_cost": "1.17",
    "gas": "0.105",
    "gas_cost": "0.01",
    "fixed_cost": "0.00",
    "energy_supplier_price_electricity_delivered_1": "0.317700",
    "energy_supplier_price_electricity_delivered_2": "0.317700",
    "energy_supplier_price_electricity_returned_1": "0.045450",
    "energy_supplier_price_electricity_returned_2": "0.045450",
    "energy_supplier_price_gas": "0.050090"
}

QoS: 0 - Retain: false

Message 278 received on dsmr/current-period at 08:36:

{
    "current_month_electricity1": "20.506",
    "current_month_electricity1_cost": "1.23",
    "current_month_electricity1_returned": "116.374",
    "current_month_electricity2": "57.653",
    "current_month_electricity2_cost": "16.66",
    "current_month_electricity2_returned": "36.474",
    "current_month_electricity_merged": "78.159",
    "current_month_electricity_cost_merged": "17.89",
    "current_month_electricity_returned_merged": "152.848",
    "current_month_gas": "3.889",
    "current_month_gas_cost": "0.18",
    "current_month_fixed_cost": "0.00",
    "current_month_total_cost": "18.07",
    "current_year_electricity1": "329.639",
    "current_year_electricity1_cost": "19.45",
    "current_year_electricity1_returned": "1876.420",
    "current_year_electricity2": "861.892",
    "current_year_electricity2_cost": "241.71",
    "current_year_electricity2_returned": "705.547",
    "current_year_electricity_merged": "1191.531",
    "current_year_electricity_cost_merged": "261.16",
    "current_year_electricity_returned_merged": "2581.967",
    "current_year_gas": "250.424",
    "current_year_gas_cost": "12.57",
    "current_year_fixed_cost": "0.00",
    "current_year_total_cost": "273.73"
}

QoS: 0 - Retain: false

Message 277 received on dsmr/current-month/electricity1 at 08:36:

20.506

QoS: 0 - Retain: false
Message 276 received on dsmr/current-month/electricity1_cost at 08:36:

1.23

QoS: 0 - Retain: false
Message 275 received on dsmr/current-month/electricity_merged at 08:36:

78.159

QoS: 0 - Retain: false
Message 274 received on dsmr/current-month/electricity_cost_merged at 08:36:

17.89

QoS: 0 - Retain: false
Message 273 received on dsmr/current-month/total_cost at 08:36:

18.07

QoS: 0 - Retain: false
Message 272 received on dsmr/current-year/electricity1 at 08:36:

329.639

QoS: 0 - Retain: false

So messages are coming in apparently.
QoS isn't version 2 in the messages but I don't know if that matters.

Since the message comes in I guess that means it's a Home Assistant issue?

0 replies

dennissiemensma · 2021-08-11T17:54:19Z

dennissiemensma
Aug 11, 2021
Maintainer

Thanks for trying!

Regarding the QoS, it's regarding communication between the broker and mosquitto_sub, which is just another client with its own preference. It defaults to q0, but you can use QoS 2 as well, using mosquitto_sub -d -t '#' -q 2. But it indeed doesn't matter since it's just for debugging now.

Unfortunately I cannot help you any further with your main issue. The only suggestion I have left for you to try, is to check the broker server logs for the HA-client. See if it connects properly. Like you checked initially for DSMR-reader in your issue:

1628492794: Client DSMR disconnected.
...
1628492836: New connection from 192.168.1.11 on port 1883.
1628492836: New client connected from 192.168.1.11 as DSMR (p2, c1, k60, u'<username>').

Another thing you can try is check the broker config options: https://mosquitto.org/man/mosquitto-conf-5.html
You may want to see if you find more information regarding the HA-client and the topics it subscribes to, using the log_type config. It seems to default to "error, warning, notice and information" and you may try adding debug as well, but I'm not sure if it aids you in debugging.

Finally don't forget to check the topics the HA-client is listening to. Maybe there are typo's? Does the client connect at all? Try connecting with mosquitto_sub (it has many options) using the HA-client credentials yourself? Etc etc

0 replies

dennissiemensma · 2021-08-11T17:55:53Z

dennissiemensma
Aug 11, 2021
Maintainer

I'm closing the issue, but feel free to ask any follow up questions. Even if I might not have the answer you're looking for.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MQTT messages not sent #1465

{{title}}

Replies: 8 comments

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

MQTT messages not sent #1465

TheMClaeys Aug 9, 2021

Replies: 8 comments

dennissiemensma Aug 9, 2021 Maintainer

TheMClaeys Aug 10, 2021 Author

dennissiemensma Aug 10, 2021 Maintainer

TheMClaeys Aug 10, 2021 Author

dennissiemensma Aug 10, 2021 Maintainer

TheMClaeys Aug 11, 2021 Author

dennissiemensma Aug 11, 2021 Maintainer

dennissiemensma Aug 11, 2021 Maintainer

TheMClaeys
Aug 9, 2021

dennissiemensma
Aug 9, 2021
Maintainer

TheMClaeys
Aug 10, 2021
Author

dennissiemensma
Aug 10, 2021
Maintainer

TheMClaeys
Aug 10, 2021
Author

dennissiemensma
Aug 10, 2021
Maintainer

TheMClaeys
Aug 11, 2021
Author

dennissiemensma
Aug 11, 2021
Maintainer

dennissiemensma
Aug 11, 2021
Maintainer