MQTT connection issue

perIpI · December 19, 2022, 10:10am

Trying to learn the mqtt-connection from the HABApp.Rule, but does not get it to work so far.

Im running HABApp from my PC in PyCharm venv. I have tried to disable temporarily windows firewalls, but did no difference.

What am I missing?

from HABApp.mqtt.items import MqttItem
from HABApp import Rule
from HABApp.core.events import ValueUpdateEvent, ValueUpdateEventFilter


class MqttTest(Rule):
    def __init__(self):
        super().__init__()

        # self.my_mqtt_item = MqttItem.get_create_item('zigbee2mqtt/IKEA_ON_OFF_kontor/action')
        # self.my_mqtt_item.listen_event(callback=self.on_mqtt_update, event_filter=ValueUpdateEventFilter())

        self.mqtt.subscribe('zigbee2mqtt/IKEA_ON_OFF_kontor/action')
        self.listen_event('zigbee2mqtt/IKEA_ON_OFF_kontor/action', callback=self.on_mqtt_update)

        # self.mqtt.publish('test', payload='This is a test')

    def on_mqtt_update(self, event: ValueUpdateEvent):
        print(f'{event}')


MqttTest()

I got some entries in HABApp.log that seems to be correlated

[2022-12-19 11:03:43,663] [              HABApp.Rule]  WARNING | C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\paho\mqtt\client.py:1782: ResourceWarning:unclosed <ssl.SSLSocket fd=1120, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.9.8.237', 58360), raddr=('10.9.8.143', 1883)>
[2022-12-19 11:05:04,387] [             HABApp.Rules]    ERROR | Error "Mqtt client not connected" in load:
[2022-12-19 11:05:04,387] [             HABApp.Rules]    ERROR | Could not load C:\_HG\\\Python\habapp_test_env\rules\test\test_mqtt.py!
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | File "C:\_HG\\\Python\habapp_test_env\rules\test\test_mqtt.py", line 26 in test_mqtt.py
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | --------------------------------------------------------------------------------
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      20 |         # self.mqtt.publish('test', payload='This is a test')
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      22 |     def on_mqtt_update(self, event: ValueUpdateEvent):
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      23 |         print(f'{event}')
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | -->  26 | MqttTest()
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |    ------------------------------------------------------------
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      log = <Logger TestDebug (INFO)>
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |    ------------------------------------------------------------
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | 
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | File "C:\_HG\PN_AUTOMATION\CODING\Python\habapp_test_env\rules\test\test_mqtt.py", line 17 in __init__
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | --------------------------------------------------------------------------------
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      11 | def __init__(self):
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      12 |     super().__init__()
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      14 |     # self.my_mqtt_item = MqttItem.get_create_item('zigbee2mqtt/IKEA_ON_OFF_kontor/action')
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR |      15 |     # self.my_mqtt_item.listen_event(callback=self.on_mqtt_update, event_filter=ValueUpdateEventFilter())
[2022-12-19 11:05:04,388] [             HABApp.Rules]    ERROR | -->  17 |     self.mqtt.subscribe('zigbee2mqtt/IKEA_ON_OFF_kontor/action')
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |      18 |     self.listen_event('zigbee2mqtt/IKEA_ON_OFF_kontor/action', callback=self.on_mqtt_update)
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |    ------------------------------------------------------------
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |      self = <MqttTest>
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |    ------------------------------------------------------------
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR | 
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR | --------------------------------------------------------------------------------
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR | Traceback (most recent call last):
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\HABApp\rule_manager\rule_file.py", line 77, in load
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |     self.create_rules(created_rules)
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\HABApp\rule_manager\rule_file.py", line 67, in create_rules
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |     runpy.run_path(str(self.path), run_name=str(self.path), init_globals=init_globals)
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\AppData\Local\Programs\Python\Python310\lib\runpy.py", line 289, in run_path
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |     return _run_module_code(code, init_globals, run_name,
[2022-12-19 11:05:04,389] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\AppData\Local\Programs\Python\Python310\lib\runpy.py", line 96, in _run_module_code
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     _run_code(code, mod_globals, init_globals,
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\AppData\Local\Programs\Python\Python310\lib\runpy.py", line 86, in _run_code
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     exec(code, run_globals)
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |   File "C:\_HG\\\Python\habapp_test_env\rules\test\test_mqtt.py", line 26, in test_mqtt.py
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     MqttTest()
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |   File "C:\_HG\\\Python\habapp_test_env\rules\test\test_mqtt.py", line 17, in __init__
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     self.mqtt.subscribe('zigbee2mqtt/IKEA_ON_OFF_kontor/action')
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\HABApp\mqtt\mqtt_interface.py", line 67, in subscribe
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     if not __is_connected():
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |   File "C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\HABApp\mqtt\mqtt_interface.py", line 13, in __is_connected
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR |     raise ConnectionError('Mqtt client not connected')
[2022-12-19 11:05:04,390] [             HABApp.Rules]    ERROR | ConnectionError: Mqtt client not connected
[2022-12-19 11:05:04,394] [             HABApp.Rules]  WARNING | Failed to load C:\_HG\AUTOMATION\Python\habapp_test_env\rules\test\test_mqtt.py!
[2022-12-19 11:05:43,671] [              HABApp.Rule]  WARNING | C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\paho\mqtt\client.py:1782: ResourceWarning:unclosed <ssl.SSLSocket fd=1056, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('10.9.8.237', 58365), raddr=('10.9.8.143', 1883)>

Mqtt-configuration is done in the config.yml
Mqtt-server is alive and currently not protected by password.

Spaceman_Spiff · December 19, 2022, 10:16am

Plase post the mqtt parts from the config and the HABApp.log when you start.
You’ll get warnings/infos if the connect won’t work

perIpI · December 19, 2022, 10:26am

Thanks! Found it. HABApp.log gave following:

[2022-12-19 11:20:40,814] [              HABApp.Rule]  WARNING | C:\Users\perno\PycharmProjects\HABApp\venv\lib\site-packages\paho\mqtt\client.py:792: DeprecationWarning:ssl.PROTOCOL_TLS is deprecated

Tricky part was though, this line did not show in my PyCharm editor, but only when I opened HABApp.log in notepad++ (I think I at some point have accepted a kind of log-viewer inside PyCharm, possibly this has hidden this line from me).

Changing TLS enabled to false solved it.

    tls:
      enabled: false    # Enable TLS for the connection

perIpI · December 19, 2022, 10:39am

Confirmed: removed the plugin ‘Ideolog’ and all lines are shown in the HABApp.log also in PyCharm.

Ideolog was a plugin suggested to me by PyCharm to enable/improve log highlighting.

alfista2600 · January 18, 2023, 7:47pm

Posting here instead of creating a new thread… let me know if I should open one.

I have a HABApp rule that relays some info to MQTT based on item changes, for a CircuitPython display to consume.

Sometimes, it loses its connection, and I start getting errors like this:

2023-01-18 14:20:32.766 [ERROR] [HABApp.Worker                       ] -      45 | @staticmethod
2023-01-18 14:20:32.767 [ERROR] [HABApp.Worker                       ] -      46 | def on_change(event: ValueUpdateEventFilter):
2023-01-18 14:20:32.767 [ERROR] [HABApp.Worker                       ] -      47 |     my_mqtt_item = MqttItem.get_create_item(item_to_topic(event.name))
2023-01-18 14:20:32.767 [ERROR] [HABApp.Worker                       ] - -->  48 |     my_mqtt_item.publish(event.value, retain=False)
2023-01-18 14:20:32.768 [ERROR] [HABApp.Worker                       ] -    ------------------------------------------------------------
2023-01-18 14:20:32.768 [ERROR] [HABApp.Worker                       ] -      event = <ItemStateEvent name: Sensor_Outside_Humidity, value: 58>
2023-01-18 14:20:32.769 [ERROR] [HABApp.Worker                       ] -      event.name = 'Sensor_Outside_Humidity'
2023-01-18 14:20:32.769 [ERROR] [HABApp.Worker                       ] -      event.value = 58
2023-01-18 14:20:32.770 [ERROR] [HABApp.Worker                       ] -      my_mqtt_item = <MqttItem name: pyportal/humid/local, value: 74, last_change: 2023-01-18T11:40:19.788824, las

Restarting HABApp fixes the problem so I think the client has lost its connection. Is there a good way to re-establish the connection programmatically?

Spaceman_Spiff · January 19, 2023, 4:54am

Is this the whole error? There seems to be something missing.

alfista2600 · January 19, 2023, 12:06pm

here is the whole error:

2023-01-18 14:18:01.158 [ERROR] [HABApp.Worker                       ] - Traceback (most recent call last):
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -   File "/opt/habapp/lib/python3.10/site-packages/HABApp/core/internals/wrapped_function/wrapped_thread.py", line 79, in run_sync
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -     self.func(*args, **kwargs)
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -   File "/etc/openhab/habapp/rules/proxies/MQTT_Relay.py", line 48, in on_change
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -     my_mqtt_item.publish(event.value, retain=False)
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -   File "/opt/habapp/lib/python3.10/site-packages/HABApp/mqtt/items/mqtt_item.py", line 46, in publish
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -     return publish(self.name, payload, qos=qos, retain=retain)
2023-01-18 14:18:01.159 [ERROR] [HABApp.Worker                       ] -   File "/opt/habapp/lib/python3.10/site-packages/HABApp/mqtt/mqtt_interface.py", line 34, in publish
2023-01-18 14:18:01.160 [ERROR] [HABApp.Worker                       ] -     if not __is_connected():
2023-01-18 14:18:01.160 [ERROR] [HABApp.Worker                       ] -   File "/opt/habapp/lib/python3.10/site-packages/HABApp/mqtt/mqtt_interface.py", line 13, in __is_connected
2023-01-18 14:18:01.160 [ERROR] [HABApp.Worker                       ] -     raise ConnectionError('Mqtt client not connected')
2023-01-18 14:18:01.160 [ERROR] [HABApp.Worker                       ] - ConnectionError: Mqtt client not connected
2023-01-18 14:18:01.156 [ERROR] [HABApp.Worker                       ] - --------------------------------------------------------------------------------
2023-01-18 14:18:01.160 [ERROR] [HABApp.Worker                       ] -      45 | @staticmethod
2023-01-18 14:18:01.161 [ERROR] [HABApp.Worker                       ] -      46 | def on_change(event: ValueUpdateEventFilter):
2023-01-18 14:18:01.161 [ERROR] [HABApp.Worker                       ] -      47 |     my_mqtt_item = MqttItem.get_create_item(item_to_topic(event.name))
2023-01-18 14:18:01.161 [ERROR] [HABApp.Worker                       ] - -->  48 |     my_mqtt_item.publish(event.value, retain=False)
2023-01-18 14:18:01.162 [ERROR] [HABApp.Worker                       ] -    ------------------------------------------------------------
2023-01-18 14:18:01.162 [ERROR] [HABApp.Worker                       ] -      event = <ItemStateEvent name: Sensor_BasementPlants_Temperature, value: 56.6>
2023-01-18 14:18:01.162 [ERROR] [HABApp.Worker                       ] -      event.name = 'Sensor_BasementPlants_Temperature'
2023-01-18 14:18:01.163 [ERROR] [HABApp.Worker                       ] -      event.value = 56.6
2023-01-18 14:18:01.163 [ERROR] [HABApp.Worker                       ] -      my_mqtt_item = <MqttItem name: pyportal/temps/basement, value: 56.9, last_change: 2023-01-18T11:43:01.186604, last_update: 2023-01-18T11:58:01.166697>

Spaceman_Spiff · January 20, 2023, 9:32am

Doesn’t HABApp automatically reconnect and start the mqtt connection again?
That’s what I would have expected (or at least a log entry that indicates an error).

alfista2600 · January 20, 2023, 12:01pm

not in my experience… my log will fill up with errors until I restart habapp. It doesn’t happen all that frequently. What is the best way to trap for it to get more information, knowing it only happens at most every couple of weeks, perhaps?

MQTT server appears fine.

alfista2600 · January 20, 2023, 12:19pm

Dug through some logs and see that the first error of this latest round of errors started one minute before midnight when I capture some EOD metrics. Unsure if related, but I’ll watch more closely now.

2023-01-18 11:59:11.801 [ERROR] [HABApp.Worker                       ] - Error in mqtt_to_portal.on_change: Mqtt client not connected
2023-01-18 11:59:11.802 [ERROR] [HABApp.Worker                       ] - File "/etc/openhab/habapp/rules/proxies/MQTT_Relay.py", line 48 in on_change
2023-01-18 11:59:11.804 [ERROR] [HABApp.Worker                       ] - --------------------------------------------------------------------------------
2023-01-18 11:59:11.804 [ERROR] [HABApp.Worker                       ] -      45 | @staticmethod
2023-01-18 11:59:11.805 [ERROR] [HABApp.Worker                       ] -      46 | def on_change(event: ValueUpdateEventFilter):
2023-01-18 11:59:11.806 [ERROR] [HABApp.Worker                       ] -      47 |     my_mqtt_item = MqttItem.get_create_item(item_to_topic(event.name))
2023-01-18 11:59:11.806 [ERROR] [HABApp.Worker                       ] - -->  48 |     my_mqtt_item.publish(event.value, retain=False)
2023-01-18 11:59:11.806 [ERROR] [HABApp.Worker                       ] -    ------------------------------------------------------------
2023-01-18 11:59:11.809 [ERROR] [HABApp.Worker                       ] -      event = <ItemStateEvent name: Measurement_Climate_Rain_Day, value: 0>
2023-01-18 11:59:11.809 [ERROR] [HABApp.Worker                       ] -      event.name = 'Measurement_Climate_Rain_Day'
2023-01-18 11:59:11.809 [ERROR] [HABApp.Worker                       ] -      event.value = 0
2023-01-18 11:59:11.810 [ERROR] [HABApp.Worker                       ] -      my_mqtt_item = <MqttItem name: pyportal/rain/yesterday, value: 0, last_change: 2023-01-17T19:40:22.147680, last_update: 2023-01-17T23:59:00.063847>