psmqtt icon indicating copy to clipboard operation
psmqtt copied to clipboard
verified publisher icon eschava

psmqtt reconnects continuously

Open f18m opened this issue 4 months ago • 4 comments

Today I encountered a strange issue with psmqtt on my NAS.

In short it was continuously connecting to the broker, publishing some message and then getting a disconnection notification in the paho.mqtt client (See https://pypi.org/project/paho-mqtt/#callbacks) with "reason=Unspecified error".

Here's an excerpt of the psmqtt logs:

2025-08-27T12:37:45.584321361Z INFO:root:Loading app config '/opt/psmqtt/conf/psmqtt.yaml' and its schema '/opt/psmqtt/schema/psmqtt.schema.yaml'
2025-08-27T12:37:45.680573658Z INFO:root:Configuration file '/opt/psmqtt/conf/psmqtt.yaml' successfully loaded and validated against schema. It contains 4 validated schedules.
2025-08-27T12:37:45.680799991Z INFO:root:Setting log level to INFO
2025-08-27T12:37:45.699718102Z INFO:root:Task.run_task(schedule0.task0.net_io_counters_rate): MQTT topic is 'psmqtt/tnas/net_io_counters_rate/bytes_sent/eth0'
2025-08-27T12:37:45.705074028Z INFO:root:Task.run_task(schedule0.task1.net_io_counters_rate): MQTT topic is 'psmqtt/tnas/net_io_counters_rate/bytes_recv/eth0'
2025-08-27T12:37:45.709873176Z INFO:root:Task.run_task(schedule0.task2.disk_io_counters_rate): MQTT topic is 'psmqtt/tnas/disk_io_counters_rate/read_bytes'
2025-08-27T12:37:45.714695065Z INFO:root:Task.run_task(schedule0.task3.disk_io_counters_rate): MQTT topic is 'psmqtt/tnas/disk_io_counters_rate/write_bytes'
2025-08-27T12:37:45.715109361Z INFO:root:SCHEDULE#0: Periodicity: every 15 seconds; Max interval: 15sec; Contains 4 tasks: [{'task': 'net_io_counters_rate', 'params': ['bytes_sent', 'eth0'], 'formatter': '{{x|MB_fractional}}', 'ha_discovery': {'name': 'Network TX', 'platform': 'sensor', 'device_class': 'data_rate', 'unit_of_measurement': 'MB/s', 'icon': 'mdi:upload', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'net_io_counters_rate', 'params': ['bytes_recv', 'eth0'], 'formatter': '{{x|MB_fractional}}', 'ha_discovery': {'name': 'Network RX', 'platform': 'sensor', 'device_class': 'data_rate', 'unit_of_measurement': 'MB/s', 'icon': 'mdi:download', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'disk_io_counters_rate', 'params': ['read_bytes'], 'formatter': '{{x|MB_fractional}}', 'ha_discovery': {'name': 'Disks Total Read', 'platform': 'sensor', 'device_class': 'data_rate', 'unit_of_measurement': 'MB/s', 'icon': 'mdi:harddisk', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'disk_io_counters_rate', 'params': ['write_bytes'], 'formatter': '{{x|MB_fractional}}', 'ha_discovery': {'name': 'Disks Total Written', 'platform': 'sensor', 'device_class': 'data_rate', 'unit_of_measurement': 'MB/s', 'icon': 'mdi:harddisk', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}]
2025-08-27T12:37:45.719314991Z INFO:root:Task.run_task(schedule1.task0.cpu_percent): MQTT topic is 'psmqtt/tnas/cpu_percent/total'
2025-08-27T12:37:45.719436213Z INFO:root:Task.run_task(schedule1.task1.virtual_memory): MQTT topic is 'psmqtt/tnas/virtual_memory/percent'
2025-08-27T12:37:45.757048546Z INFO:root:Task.run_task(schedule1.task2.getloadavg): MQTT topic is 'psmqtt/tnas/getloadavg/last5min/percent'
2025-08-27T12:37:45.757174621Z INFO:root:Task.run_task(schedule1.task3.sensors_temperatures): MQTT topic is 'psmqtt/tnas/sensors_temperatures/rtk_thermal/0'
2025-08-27T12:37:45.757662843Z INFO:root:SCHEDULE#1: Periodicity: every 1 minute; Max interval: 60sec; Contains 4 tasks: [{'task': 'cpu_percent', 'params': ['total'], 'ha_discovery': {'name': 'CPU Percentage', 'platform': 'sensor', 'unit_of_measurement': '%', 'icon': 'mdi:speedometer', 'device_class': None, 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'virtual_memory', 'params': ['percent'], 'ha_discovery': {'name': 'Memory Percentage', 'platform': 'sensor', 'unit_of_measurement': '%', 'icon': 'mdi:memory', 'device_class': None, 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'getloadavg', 'params': ['last5min', 'percent'], 'formatter': "{{'%0.2f'|format(x)}}", 'ha_discovery': {'name': 'Average System Load', 'platform': 'sensor', 'unit_of_measurement': '%', 'icon': 'mdi:speedometer', 'device_class': None, 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'sensors_temperatures', 'params': ['rtk_thermal', 0], 'ha_discovery': {'name': 'CPU Temperature', 'unit_of_measurement': '°C', 'platform': 'sensor', 'device_class': 'temperature', 'icon': 'mdi:thermometer', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}]
2025-08-27T12:37:45.761589361Z INFO:root:Task.run_task(schedule2.task0.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdc/temperature'
2025-08-27T12:37:45.761807806Z INFO:root:Task.run_task(schedule2.task1.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdc/smart_status'
2025-08-27T12:37:45.761926287Z INFO:root:Task.run_task(schedule2.task2.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdc/attribute_raw[Power_On_Hours]'
2025-08-27T12:37:45.765686472Z INFO:root:Task.run_task(schedule2.task3.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdc/test[0]'
2025-08-27T12:37:45.765803732Z INFO:root:Task.run_task(schedule2.task4.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdd/temperature'
2025-08-27T12:37:45.766137324Z INFO:root:Task.run_task(schedule2.task5.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdd/smart_status'
2025-08-27T12:37:45.766166472Z INFO:root:Task.run_task(schedule2.task6.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdd/attribute_raw[Power_On_Hours]'
2025-08-27T12:37:45.769901695Z INFO:root:Task.run_task(schedule2.task7.smart): MQTT topic is 'psmqtt/tnas/smart/|dev|sdd/test[0]'
2025-08-27T12:37:45.770033658Z INFO:root:Task.run_task(schedule2.task8.disk_usage): MQTT topic is 'psmqtt/tnas/disk_usage/percent/|mnt|md0'
2025-08-27T12:37:45.770198991Z INFO:root:Task.run_task(schedule2.task9.directory_usage): MQTT topic is 'psmqtt/tnas/directory_usage/|mnt|md0|photos'
2025-08-27T12:37:45.771009917Z INFO:root:SCHEDULE#2: Periodicity: every 10 minutes; Max interval: 600sec; Contains 10 tasks: [{'task': 'smart', 'params': ['/dev/sdc', 'temperature'], 'ha_discovery': {'name': 'Disk1 Temperature', 'platform': 'sensor', 'device_class': 'temperature', 'unit_of_measurement': '°C', 'icon': 'mdi:thermometer', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdc', 'smart_status'], 'ha_discovery': {'name': 'Disk1 SMART Status', 'platform': 'binary_sensor', 'device_class': 'problem', 'payload_on': 'FAIL', 'payload_off': 'PASS', 'icon': 'mdi:harddisk', 'state_class': 'measurement', 'unit_of_measurement': None, 'expire_after': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdc', 'attribute_raw[Power_On_Hours]'], 'ha_discovery': {'name': 'Disk1 PowerOn', 'platform': 'sensor', 'device_class': 'duration', 'unit_of_measurement': 'h', 'icon': 'mdi:clock', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdc', 'test[0]'], 'formatter': '{{hours}}', 'ha_discovery': {'name': 'Disk1 LastTest PowerOn', 'platform': 'sensor', 'device_class': 'duration', 'unit_of_measurement': 'h', 'icon': 'mdi:clock', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdd', 'temperature'], 'ha_discovery': {'name': 'Disk2 Temperature', 'platform': 'sensor', 'device_class': 'temperature', 'unit_of_measurement': '°C', 'icon': 'mdi:thermometer', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdd', 'smart_status'], 'ha_discovery': {'name': 'Disk2 SMART Status', 'platform': 'binary_sensor', 'device_class': 'problem', 'payload_on': 'FAIL', 'payload_off': 'PASS', 'icon': 'mdi:harddisk', 'state_class': 'measurement', 'unit_of_measurement': None, 'expire_after': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdd', 'attribute_raw[Power_On_Hours]'], 'ha_discovery': {'name': 'Disk2 PowerOn', 'platform': 'sensor', 'device_class': 'duration', 'unit_of_measurement': 'h', 'icon': 'mdi:clock', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'smart', 'params': ['/dev/sdd', 'test[0]'], 'formatter': '{{hours}}', 'ha_discovery': {'name': 'Disk2 LastTest PowerOn', 'platform': 'sensor', 'device_class': 'duration', 'unit_of_measurement': 'h', 'icon': 'mdi:clock', 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'topic': None}, {'task': 'disk_usage', 'params': ['percent', '/mnt/md0'], 'ha_discovery': {'name': 'RAID Disks Usage', 'platform': 'sensor', 'unit_of_measurement': '%', 'icon': 'mdi:harddisk', 'device_class': None, 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}, {'task': 'directory_usage', 'params': ['/mnt/md0/photos'], 'ha_discovery': {'name': 'Photos Bytes', 'platform': 'sensor', 'unit_of_measurement': 'B', 'icon': 'mdi:harddisk', 'device_class': None, 'state_class': 'measurement', 'expire_after': None, 'payload_on': None, 'payload_off': None, 'value_template': None}, 'formatter': None, 'topic': None}]
2025-08-27T12:37:45.779326880Z INFO:root:Task.run_task(schedule3.task0.boot_time): MQTT topic is 'psmqtt/tnas/boot_time'
2025-08-27T12:37:45.779596324Z INFO:root:SCHEDULE#3: Periodicity: every 24 hours; Max interval: 86400sec; Contains 1 tasks: [{'task': 'boot_time', 'formatter': '{{x|iso8601_str}}', 'ha_discovery': {'name': 'Uptime', 'platform': 'sensor', 'device_class': 'timestamp', 'icon': 'mdi:calendar', 'value_template': '{{ as_datetime(value) }}', 'unit_of_measurement': None, 'expire_after': None, 'payload_on': None, 'payload_off': None}, 'params': [], 'topic': None}]
2025-08-27T12:37:45.779784732Z INFO:root:PSMQTT status will be published on topic psmqtt/tnas/psmqtt_status every 3600sec
2025-08-27T12:37:45.780075843Z INFO:root:Connecting to MQTT broker '192.168.1.8:1883'
2025-08-27T12:37:45.861869954Z INFO:root:Connecting to MQTT broker '192.168.1.8:1883'... return code was 0
2025-08-27T12:37:45.862000435Z INFO:root:starting MQTT client loop
2025-08-27T12:37:45.864147398Z WARNING:root:Aborting task schedule0.task0.net_io_counters_rate: no MQTT connection available at this time
2025-08-27T12:37:45.866667139Z INFO:root:Successfully connected to MQTT broker with connection_id=1
2025-08-27T12:37:45.867909398Z INFO:root:Subscribing to REQUEST topic 'request/#'
2025-08-27T12:37:45.870067546Z INFO:root:Subscribing to HomeAssistant status topic 'homeassistant/status'
2025-08-27T12:37:46.386415435Z WARNING:root:New connection to the MQTT broker detected (id=1), sending out MQTT discovery messages...
2025-08-27T12:37:46.443356842Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-net_io_counters_rate-45e94fc8c1b6/config'
2025-08-27T12:37:46.444474583Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-net_io_counters_rate-39a25adecec4/config'
2025-08-27T12:37:46.446066509Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_io_counters_rate-b56f9444ab61/config'
2025-08-27T12:37:46.447717657Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_io_counters_rate-8f152d067367/config'
2025-08-27T12:37:46.449245953Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-cpu_percent-11239872d178/config'
2025-08-27T12:37:46.450525027Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-virtual_memory-fd86717aca41/config'
2025-08-27T12:37:46.451888509Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-getloadavg-81184b44415f/config'
2025-08-27T12:37:46.453207657Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-sensors_temperatures-1102658ee45e/config'
2025-08-27T12:37:46.456170324Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-246cffe8fd53/config'
2025-08-27T12:37:46.456292620Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/binary_sensor/tnas/tnas-smart-09d7c6e946d6/config'
2025-08-27T12:37:46.456941324Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-42eeaf4042dc/config'
2025-08-27T12:37:46.458983398Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-a6f92917bcd1/config'
2025-08-27T12:37:46.460286509Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-a68f3ea8545e/config'
2025-08-27T12:37:46.461655583Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/binary_sensor/tnas/tnas-smart-b2d88197a4a6/config'
2025-08-27T12:37:46.463034139Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-4a728f90216b/config'
2025-08-27T12:37:46.464313694Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-29ccd7897bc6/config'
2025-08-27T12:37:46.465647065Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_usage-38d061ee2a9d/config'
2025-08-27T12:37:46.466874916Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-directory_usage-88fb98a636ef/config'
2025-08-27T12:37:46.468249990Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-boot_time-e3b0c44298fc/config'
2025-08-27T12:37:46.469261250Z INFO:root:Published a total of 19 MQTT discovery messages under the topic prefix 'homeassistant' for the device 'tnas'. The HomeAssistant MQTT integration should now be showing 19 sensors for the device 'tnas'.
2025-08-27T12:37:51.882653617Z WARNING:root:OOOOPS! Unexpected disconnection from the MQTT broker with reason=Unspecified error. Reconnecting in 5sec.
2025-08-27T12:37:57.892323391Z INFO:root:Successfully connected to MQTT broker with connection_id=2
2025-08-27T12:37:57.892946428Z INFO:root:Subscribing to REQUEST topic 'request/#'
2025-08-27T12:37:57.893463613Z INFO:root:Subscribing to HomeAssistant status topic 'homeassistant/status'
2025-08-27T12:38:00.936586945Z WARNING:root:New connection to the MQTT broker detected (id=2), sending out MQTT discovery messages...
2025-08-27T12:38:01.007334093Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-net_io_counters_rate-45e94fc8c1b6/config'
2025-08-27T12:38:01.008393537Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-net_io_counters_rate-39a25adecec4/config'
2025-08-27T12:38:01.009663908Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_io_counters_rate-b56f9444ab61/config'
2025-08-27T12:38:01.011502019Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_io_counters_rate-8f152d067367/config'
2025-08-27T12:38:01.013097315Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-cpu_percent-11239872d178/config'
2025-08-27T12:38:01.015041241Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-virtual_memory-fd86717aca41/config'
2025-08-27T12:38:01.017009426Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-getloadavg-81184b44415f/config'
2025-08-27T12:38:01.019162130Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-sensors_temperatures-1102658ee45e/config'
2025-08-27T12:38:01.021243204Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-246cffe8fd53/config'
2025-08-27T12:38:01.022087574Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/binary_sensor/tnas/tnas-smart-09d7c6e946d6/config'
2025-08-27T12:38:01.023707093Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-42eeaf4042dc/config'
2025-08-27T12:38:01.025952574Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-a6f92917bcd1/config'
2025-08-27T12:38:01.027866871Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-a68f3ea8545e/config'
2025-08-27T12:38:01.029755685Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/binary_sensor/tnas/tnas-smart-b2d88197a4a6/config'
2025-08-27T12:38:01.031918019Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-4a728f90216b/config'
2025-08-27T12:38:01.033855463Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-smart-29ccd7897bc6/config'
2025-08-27T12:38:01.036399389Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-disk_usage-38d061ee2a9d/config'
2025-08-27T12:38:01.037881278Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-directory_usage-88fb98a636ef/config'
2025-08-27T12:38:01.039085315Z INFO:root:Publishing an MQTT discovery messages on topic 'homeassistant/sensor/tnas/tnas-boot_time-e3b0c44298fc/config'
2025-08-27T12:38:01.040927834Z INFO:root:Published a total of 19 MQTT discovery messages under the topic prefix 'homeassistant' for the device 'tnas'. The HomeAssistant MQTT integration should now be showing 19 sensors for the device 'tnas'.
2025-08-27T12:38:03.896484313Z WARNING:root:OOOOPS! Unexpected disconnection from the MQTT broker with reason=Unspecified error. Reconnecting in 5sec.
...

Here are mosquitto broker logs:

2025-08-27 15:22:18: New client connected from 192.168.1.5:55086 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:24: New connection from 192.168.1.5:42325 on port 1883.
2025-08-27 15:22:24: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:24: New client connected from 192.168.1.5:42325 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:30: New connection from 192.168.1.5:58481 on port 1883.
2025-08-27 15:22:30: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:30: New client connected from 192.168.1.5:58481 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:36: New connection from 192.168.1.5:38844 on port 1883.
2025-08-27 15:22:36: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:36: New client connected from 192.168.1.5:38844 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:42: New connection from 192.168.1.5:34483 on port 1883.
2025-08-27 15:22:42: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:42: New client connected from 192.168.1.5:34483 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:48: New connection from 192.168.1.5:40558 on port 1883.
2025-08-27 15:22:48: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:48: New client connected from 192.168.1.5:40558 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:54: New connection from 192.168.1.5:50277 on port 1883.
2025-08-27 15:22:54: Client psmqtt-tnas already connected, closing old connection.
2025-08-27 15:22:54: New client connected from 192.168.1.5:50277 as psmqtt-tnas (p2, c0, k60, u'psmqtt').
2025-08-27 15:22:57: New connection from 192.168.1.7:47077 on port 1883.

So a reconnection is happening roughly every 6sec

f18m avatar Aug 27 '25 13:08 f18m

After lot of debugging, it turns out that by changing the "clientid" in the psmqtt.yaml from "pmsqtt-tnas" to any other value e.g. "psmqtt-tnas2", everything turned back to normality: connection was stable.

f18m avatar Aug 27 '25 13:08 f18m

The issue is quite deterministic actually: if I restart psmqtt with the clientid being "psmqtt-tnas", the reconnection loop starts again. This makes me think that the problem is some state hold by the broker (mosquitto) for that particular client_id, and it's connected with the clean_session flag defaulting to False.

See https://eclipse.dev/paho/files/paho.mqtt.python/html/client.html:

clean_session (bool) – a boolean that determines the client type. If True, the broker will remove all information about this client when it disconnects. If False, the client is a persistent client and subscription information and queued messages will be retained when the client disconnects. Note that a client will never discard its own outgoing messages on disconnect. Calling connect() or reconnect() will cause the messages to be resent. Use reinitialise() to reset a client to its original state. The clean_session argument only applies to MQTT versions v3.1.1 and v3.1. It is not accepted if the MQTT version is v5.0 - use the clean_start argument on connect() instead.

f18m avatar Aug 27 '25 13:08 f18m

Actually if I use the old clientid and set clean_session=True, the reconnection loop still happens. According to https://stackoverflow.com/questions/34379203/mqtt-getting-disconnected-again-and-again-on-specific-client-id the reconnection might be caused also by a collision of clientid (same clientid used by multiple clients)

f18m avatar Aug 27 '25 13:08 f18m

Even restarting the Mosquitto broker does not fix the problem (!!!). Mosquitto is probably storing something borked for my particular clientid in its persistent DB. For now I will just open a PR to add more logging... even if the workaround is very simple (change the "clientid") this is very annoying issue though.

f18m avatar Aug 27 '25 13:08 f18m