Controllerx: MQTT integration with z2m

[xaviml]

Feature Request

Is your feature request related to a problem?

As of now, the z2m requires users to indicate the entity id from HA of the controller. This means that if we want to toggle a light, the signal needs to go through the following steps:

1. Controller to Coordinator (Zigbee)
2. Coordinator to Zigbee2MQTT
3. Zigbee2MQTT to MQTT
4. MQTT to HA entity state
5. HA entity state to ControllerX(AppDaemon)
6. ControllerX(AppDaemon) to HA call service
7. HA call service to MQTT
8. MQTT to Zigbee2MQTT
9. Zigbee2MQTT to Coordinator (Zigbee)
10. Coordinator to light

As you can observe there are too many layers to go from one end to another.

Describe the solution / feature you'd like

It is not in my hands to cut this path in just 2 steps (it would be nice, though), but to cut step number 4. This means that ControllerX would be able to get the message directly from MQTT and skip the change of an entity state from HA, which is the slowest step in this pipeline.

This change will not require any breaking changes. ControllerX allows integrations to have additional parameters, this means that the following code does the same in the latest version (v2.7.1 at the moment of writing this):

livingroom_controller:
  module: controllerx
  class: E1810Controller
  controller: sensor.livingroom_controller_action
  integration: z2m
  light: light.livingroom

is equal to

livingroom_controller:
  module: controllerx
  class: E1810Controller
  controller: sensor.livingroom_controller_action
  integration:
    name: z2m
  light: light.livingroom

So the change I am proposing will be to add a parameter to z2m integration that will allow us to use the z2m integration with MQTT rather than HA directly as we do now. The configuration will look like:

livingroom_controller:
  module: controllerx
  class: E1810Controller
  controller: zigbee2mqtt/livingroom_controller # Note this is the z2m MQTT state topic 
  integration:
    name: z2m
    state: mqtt # default will be "ha"
  light: light.livingroom

Additional context

This feature request was also requested by @htvekov. Thanks!

[htvekov]

Hi' Xavi.

I believe this would really help on the lag issues I've experienced in different set-up's and tests.
Especially notisable when toggling lights, where user always would expect immediate response when toggling wall switch.

Don't really know why the HA state machine actually appears to be so slow ?
HA service calls to MQTT seems to be really fast, so it's quite a mystery and apparently (in my case anyway) not hardware related.
Some precise 'real life' measurement tests to back up my lag experience would be great.
Haven't figured out yet how to actually perform such a test, though.

The description of the integration is in my opninion spot on.
Keep it simple and only use MQTT for 'inbound' controller actions and not (initially) to send MQTT messages as well.

I'll be looking forward to test this Xavi 😃👍😎

Ciao !

[xaviml]

Hi @htvekov ,

I have some good news. This feature is now on dev branch. Documentation is ready, but not visible on the website yet. If you want to test. You just need to add the MQTT plugin into appdaemon.yaml together with HASS:

plugins:
  HASS:
    type: hass
  MQTT:
    type: mqtt
    namespace: mqtt # This is important
    client_host: <Host without indicating the port (e.g. 192.168.1.10)>
    client_user: XXXXX
    client_password: XXXXX

Then the configuration on your apps.yaml would look like the following:

example_app:
  module: controllerx
  class: E1810Controller
  controller: 0x14b4883ffa81c167
  integration:
    name: z2m
    state: mqtt
  light: light.example_light

Where controller is the z2m friendly name of the device. In the example, it is also the device ID because z2m sets the device ID as a friendly name.

I have noticed a big improvement, to be honest. We could say that step number 4 (description) was a bottleneck on the pipeline. However, I would like to know how it is working on your environment and see if you also observe such improvement. Looking forward to it :)

Thanks @htvekov

[htvekov]

Wow, THAT was quick!! 🚀🚀😎

Initial test: Working ! 👍
Will test and compare speed with different setups and get back.

Beware of white spaces in friendly names (can't handle that).
Controllers correct friendly name in z2m devices.yaml (share folder) is 'Office Ikea 5 button'

2020-06-06 20:40:46.433057 WARNING example_app: ------------------------------------------------------------
2020-06-06 20:40:46.433693 WARNING example_app: Unexpected error in worker for App example_app:
2020-06-06 20:40:46.434442 WARNING example_app: Worker Ags: {'id': '57dcdefc85d44853a09cba6f2c0824a8', 'name': 'example_app', 'objectid': '3506d50ddaef4cc9a0544545d1816276', 'type': 'event', 'event': 'appd_started', 'function': <bound method Z2MIntegration.event_callback of <core.integration.z2m.Z2MIntegration object at 0x7f3ec69e7a30>>, 'data': {}, 'pin_app': True, 'pin_thread': 6, 'kwargs': {'topic': 'zigbee2mqtt/OfficeIkea5button/action', '__thread_id': 'MainThread'}}
2020-06-06 20:40:46.435070 WARNING example_app: ------------------------------------------------------------
2020-06-06 20:40:46.437189 WARNING example_app: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/threading.py", line 725, in async_worker
    await funcref(args["event"], data, args["kwargs"])
  File "/config/appdaemon/apps/controllerx/core/integration/z2m.py", line 39, in event_callback
    await self.controller.handle_action(data["payload"])
KeyError: 'payload'
2020-06-06 20:40:46.437767 WARNING example_app: ------------------------------------------------------------

[htvekov]

I have struggled to get my Tasmota wall switches to work with this mqtt implementation, Xavi.

What is appdeamon really listening for ?
Just the full topic or does the topic and payload need to have a specific layout to match commands published by z2m ? My Tasmota wall switches are (of course) not included as devices in z2m 😉

Are all classes supported in ControllerX ?

I've changed one of my Tasmota wall switches to use topic 'zigbee2mqtt/office_cmnd' for publishing all payloads. But appdeamon doesn't really pick-up the controller topic as a controller device.

Tasmota toogle topic and payload - all ok:

20:31:08 RUL: SWITCH1#STATE=2 performs "backlog publish zigbee2mqtt/office_cmnd toggle;publish zigbee2mqtt/office_cmnd"
20:31:08 MQT: kontor_loftlys/stat/SWITCH1T = {"TRIG":"ON"}
20:31:08 MQT: zigbee2mqtt/office_cmnd = toggle
20:31:08 MQT: zigbee2mqtt/office_cmnd = 
20:31:09 MQT: kontor_loftlys/stat/SWITCH1T = {"TRIG":"ON"}

Cut from appdeamon apps arguments. All also looking ok.

No errrors in appdeamon log, but nothing really happens when i push the button... 🤔

[htvekov]

And MQTT Lens output also looks ok ?

[htvekov]

Only direct x2m devices integration in appdeamon as far as I understand...
Can my 'virtual' Tasmota switches be added manually in appdeamon.yaml ?

[xaviml]

Hi @htvevok,

Thanks for the tip on friendly names with spaces, I will be checking that.

Regarding the use of mqtt out of z2m, you are right, it is nor possible as of now. What I've added it to be able to use the z2m integration with MQTT directly. You need to put the z2m friendly name on the controller because ControllerX listens for the topic: "zigbee2mqtt//action".

For the use of tasmota with MQTT, we will need to add a new integration, where you will be able to add the full topic where ControllerX should listen to and the how to get the action from the payload. I will be adding this nee integration as well. Now that this is done for z2m, it is easy to add.

Thanks :)

[htvekov]

Great, Xavi.
Much appreciated!! 😁

I'll check some more 'real' z2m integrations.
Seems that the first device I checked (z2m light) went from ok fast to blistering fast when toggling ⚡⚡🚀🚀😁

I've some z2m switches on Hue lights that are quite slow (some 300-400 ms. delay)
I'lll check these and report back.

CIao !

[htvekov]

Just had a new quick test with a E1743 controller.

topic is ending with /click but appdeamon app arguments are all stating /action at the end of the topic, regardless of controller type used.

First controller (OfficeIkea5button) below is a E1810, all ok as it uses 'action'.
But the E1743 (MikkelDimmer) uses 'click', meaning that appdeamon will never catch the events.

zigbee2mqtt:info  2020-06-07 00:32:30: MQTT publish: topic 'zigbee2mqtt/OfficeIkea5button/action', payload 'brightness_up_click'
zigbee2mqtt:debug 2020-06-07 00:32:31: Received MQTT message on 'zigbee2mqtt/Office desk lamp/set' with data '{"state": "ON", "transition": 0.5, "brightness": 254}'
zigbee2mqtt:debug 2020-06-07 00:32:31: Publishing 'set' 'brightness' to 'Office desk lamp'
zigbee2mqtt:info  2020-06-07 00:32:31: MQTT publish: topic 'zigbee2mqtt/Office desk lamp', payload '{"state":"ON","color_temp":369,"brightness":254,"update_available":false}'
zigbee2mqtt:debug 2020-06-07 00:32:31: Publishing 'set' 'transition' to 'Office desk lamp'
zigbee2mqtt:debug 2020-06-07 00:32:48: Received Zigbee message from 'MikkelDimmer', type 'commandOn', cluster 'genOnOff', data '{}' from endpoint 1 with groupID 0
zigbee2mqtt:info  2020-06-07 00:32:48: MQTT publish: topic 'zigbee2mqtt/MikkelDimmer', payload '{"linkquality":113,"battery":8,"update_available":false,"click":"on"}'
zigbee2mqtt:info  2020-06-07 00:32:48: MQTT publish: topic 'zigbee2mqtt/MikkelDimmer', payload '{"linkquality":113,"battery":8,"update_available":false,"click":""}'
zigbee2mqtt:info  2020-06-07 00:32:48: MQTT publish: topic 'zigbee2mqtt/MikkelDimmer/click', payload 'on' 

mikkel_controller:
  module: controllerx
  class: E1743Controller #Ikea on/off remote
  controller: 'MikkelDimmer'
  integration:
    name: z2m
    state: mqtt
  #controller: sensor.0x000d6ffffee3a32d_click
  #integration: z2m
  smooth_power_on: true
  add_transition: false
  light: light.mikkel_loft

Ciao !

[xaviml]

Hi @htvekov,

Thanks for the testing. Your last comment makes me think if it is even worth it to have a special attribute for the z2m to read from MQTT. I think it would make more sense to have just a new MQTT integration as I mentioned yesterday. The config would look like:

mikkel_controller:
  module: controllerx
  class: E1743Controller #Ikea on/off remote
  controller: <topic (e.g. zigbee2mqtt/MikkelDimmer/click)>
  integration: mqtt
  smooth_power_on: true
  add_transition: false
  light: light.mikkel_loft

For the moment, we will assume that the event returns the direct action we want to fire and no JSON object needs to be parsed. Otherwise, we will need to tea into account which attributes from that object needs to be accessed to get the action. So, what do you think? It is a much generic solution in my opinion.

[xaviml]

In addition to the previous comment, I would like to say that by default the mqtt integration will take the actions from z2m, this is why the integration will work directly without doing the custom mapping with CustomLightController for example. However, MQTT integration can be also used together with custom controller and the mapping key will need to match the payload of the event from the MQTT topic.

[htvekov]

Hi' Xavi.

A generic solution like that seems to be the best solution.
Unless there's other befefits having a direct z2m device integration, I would go for the generic MQTT solution - Completely independent on anything else than MQTT topics and payloads.

In my usecase with the Tasmota wallswitches, I can tweak the topics and the payloads to be whatever i like. So it's not a problem to mimic a specific controllers payload. I also don't believe it should be neccesary to check for specific attributes or parse JSON objects.

Can't think of any 'simple' zigbee switch/button device that doesn't use only one topic and attribute + the payload. Other than one of the Xiaomi buttons that uses both action and click attributes for whatever reason.

[xaviml]

Hi Henning,

Totally agree, and if you think that parsing JSON objects is not needed, then I will leave it for a future implementation if needed.

I just pushed the changes to dev branch. This means that you can try the following:

mikkel_controller:
  module: controllerx
  class: E1743Controller #Ikea on/off remote
  controller: zigbee2mqtt/MikkelDimmer/click
  integration: mqtt
  smooth_power_on: true
  add_transition: false
  light: light.mikkel_loft

The spaces issue you discovered it should be also fixed, so your topic could contain spaces if needed.

Thanks :)

[htvekov]

Wow !?!?

I begin to suspect that you're like the TV chefs cooking - having everything prepared in advance 😉😁🚀🚀🚀

• Space issue with friendly names solved !
• E1743 on Hue bridge and E1810 on z2m tested - all ok.
• Zigbee devices on generic MQTT are REALLY fast now ! 🚀🚀👍 Very near instant. I would believe that it's very close or similar to the experience with direct zigbee to zigbee control (like Ikea) or zigbee to zigbee via bridge (like Hue). Well done, Xavi. This is a major improvement in user experience I would say 😃

Tested my Tasmota switches as well. Odd thing is that MQTT response toggling lights through appdeamon is notisable slower than handling the MQTT calls through HA automation ?
HA handles the MQTT calls really,really fast (near instant) and I did expect appdeamon to be equally fast. I've even simplified the controller and removed the constrain_input_boolean I'm using to remove any HA state machine lag. I'll test some more and report back...

Anyway, No doubt that this MQTT implemetation is (once more) a major leap forward for ControllerX and the future user experience in general.
Thank you for ALL your hard work and all the hours you put into this project, Xavi ! 👍

Ciao !

[xaviml]

I begin to suspect that you're like the TV chefs cooking - having everything prepared in advance

I actually believe that you will like the implementation, so I was already implementing it haha

Tested my Tasmota switches as well. Odd thing is that MQTT response toggling lights through appdeamon is notisable slower than handling the MQTT calls through HA automation ?

Interesting, right? Whereas the mqtt integration handles the connection between ControllerX and the controller, the requests to lights or media players are handle by call services as always.

Thank you for ALL your hard work and all the hours you put into this project, Xavi !

Thank YOU for all the testing :)

[htvekov]

I DO, Xavi 😃😁

I think it all comes down to the apparently quite slow HA state machine - everytime...

On a MQTT event HA can push an API call to Hue bridge or call to z2m really fast.
But for inbound service calls, HA has to 'wait' for it's own state machine to change and that takes forever - or in my case some 300-400 ms. I would say that HA core is simply not quick enough for actions like this where user would expect instant change.

HA in general is very responsive, but state machine... 🙄

[htvekov]

Just for the record - not critical.

I'm getting appdeamon warnings with one of my Tasmota switches.
Can't really see what's the problem. And it's one out of two almost identical controllers using contrain_input_booleean. But appdeamon is only complaining about one of them ?

Am I missing something obvious or ??

Both controllers are working fine and are not throwing errors on use.

2020-06-07 15:42:51.732239 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 15:42:51.732883 WARNING AppDaemon: Unexpected error during process_event()
2020-06-07 15:42:51.733416 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 15:42:51.734804 WARNING AppDaemon: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 187, in process_event
    await self.process_event_callbacks(namespace, data)
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 263, in process_event_callbacks
    for name in self.AD.callbacks.callbacks.keys():
RuntimeError: dictionary changed size during iteration
2020-06-07 15:42:51.735414 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 15:42:51.741202 WARNING controller_switchmode11_on_office: ------------------------------------------------------------
2020-06-07 15:42:51.742143 WARNING controller_switchmode11_on_office: Unexpected error in worker for App controller_switchmode11_on_office:
2020-06-07 15:42:51.743014 WARNING controller_switchmode11_on_office: Worker Ags: {'id': '9cb7cafc894c45b8b2cab91248a257b5', 'name': 'controller_switchmode11_on_office', 'objectid': '1fe6835c055d423a8eedde809ee104a9', 'type': 'event', 'event': 'appd_started', 'function': <bound method MQTTIntegration.event_callback of <core.integration.mqtt.MQTTIntegration object at 0x7fe7d8fe8580>>, 'data': {}, 'pin_app': True, 'pin_thread': 2, 'kwargs': {'topic': 'zigbee2mqtt/office_cmnd', '__thread_id': 'MainThread'}}
2020-06-07 15:42:51.743728 WARNING controller_switchmode11_on_office: ------------------------------------------------------------
2020-06-07 15:42:51.745832 WARNING controller_switchmode11_on_office: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/threading.py", line 725, in async_worker
    await funcref(args["event"], data, args["kwargs"])
  File "/config/appdaemon/apps/controllerx/core/integration/mqtt.py", line 25, in event_callback
    await self.controller.handle_action(data["payload"])
KeyError: 'payload'
2020-06-07 15:42:51.746596 WARNING controller_switchmode11_on_office: ------------------------------------------------------------

controller_switchmode11_on_office:
  module: controllerx
  class: CustomLightController
  controller: 'zigbee2mqtt/office_cmnd'
  integration: mqtt
  light: light.0xec1bbdfffed45c3b_light
  automatic_steps: 8
  delay: 400
    #delay: 350
    #transition: 350
    #add_transition: false
  add_transition_turn_toggle: false
    #min_brightness: 50
    #max_brightness: 200
  constrain_input_boolean: light.0xec1bbdfffed45c3b_light,on # This whole configuration will work when the light is on
  mapping:
    #toggle: toggle
    inc-dec: hold_brightness_toggle
    clear: release

controller_switchmode11_off_office:
  module: controllerx
  class: CustomLightController
  controller: 'zigbee2mqtt/office_cmnd'
  integration: mqtt
  light: light.0xec1bbdfffed45c3b_light
    #transition: 500
  #add_transition: false
  #add_transition_turn_toggle: false
    #min_brightness: 50
    #max_brightness: 200
  constrain_input_boolean: light.0xec1bbdfffed45c3b_light,off # This whole configuration will work when the light is off
  mapping:
    #toggle: toggle
    inc-dec: sync

[xaviml]

Hi @htvekov

Did you get this error everytime or ust sometimes? Could you place:

self.controller.log(f"data={data}")

in mqtt.py from ControllerX? after:

await self.controller.handle_action(data["payload"])

Then restart AppDaemon and let's see what is the data looks like from the logs.

[htvekov]

Hi' Xavi.

Haven't really noticed until I wrote to you earlier.
Though, I've seen it since on every appdeamon restart. So apparently it's persistant.

Only thing out of the ordinary in the data (that I can see) is around 19:26:48.652335
Here's two payloads one after another, followed by the two emtpy payloads ?
Should have been payload, empty, payload, empty.
Also there's two seconds between topic and clear topic messages.
MQTT server must have been busy at that time. Normally there some max. 0,1 seconds between these messages. In Tasmota the delay between the single commands are set to 50 ms.

Here a log cut with some event data:

2020-06-07 19:26:12.122702 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 19:26:12.123359 WARNING AppDaemon: Unexpected error during process_event()
2020-06-07 19:26:12.123932 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 19:26:12.125394 WARNING AppDaemon: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 187, in process_event
    await self.process_event_callbacks(namespace, data)
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 263, in process_event_callbacks
    for name in self.AD.callbacks.callbacks.keys():
RuntimeError: dictionary changed size during iteration
2020-06-07 19:26:12.125950 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 19:26:12.131321 WARNING controller_switchmode11_on_office: ------------------------------------------------------------
2020-06-07 19:26:12.131872 WARNING controller_switchmode11_on_office: Unexpected error in worker for App controller_switchmode11_on_office:
2020-06-07 19:26:12.132711 WARNING controller_switchmode11_on_office: Worker Ags: {'id': 'ddc0a51d307d4094929e36e9024185bc', 'name': 'controller_switchmode11_on_office', 'objectid': '54664596dbd3440eaea4364167908420', 'type': 'event', 'event': 'appd_started', 'function': <bound method MQTTIntegration.event_callback of <core.integration.mqtt.MQTTIntegration object at 0x7f64b5ae9070>>, 'data': {}, 'pin_app': True, 'pin_thread': 2, 'kwargs': {'topic': 'zigbee2mqtt/office_cmnd', '__thread_id': 'MainThread'}}
2020-06-07 19:26:12.133309 WARNING controller_switchmode11_on_office: ------------------------------------------------------------
2020-06-07 19:26:12.135182 WARNING controller_switchmode11_on_office: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/threading.py", line 725, in async_worker
    await funcref(args["event"], data, args["kwargs"])
  File "/config/appdaemon/apps/controllerx/core/integration/mqtt.py", line 25, in event_callback
    await self.controller.handle_action(data["payload"])
KeyError: 'payload'
2020-06-07 19:26:12.135720 WARNING controller_switchmode11_on_office: ------------------------------------------------------------
2020-06-07 19:26:43.053326 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'toggle', 'wildcard': None}
2020-06-07 19:26:43.116612 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:44.542623 INFO controller_switchmode11_off_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'toggle', 'wildcard': None}
2020-06-07 19:26:44.573062 INFO controller_switchmode11_off_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:46.682248 INFO controller_switchmode11_on_office: 🎮 Button event triggered: `inc-dec`
2020-06-07 19:26:46.685956 INFO controller_switchmode11_on_office: 🏃 Running `hold_brightness_toggle` now
2020-06-07 19:26:46.691832 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:46.780482 INFO controller_switchmode11_on_office: 🤖 Service: light.turn_on
2020-06-07 19:26:46.785645 INFO controller_switchmode11_on_office:   - entity_id: light.0xec1bbdfffed45c3b_light
2020-06-07 19:26:46.790737 INFO controller_switchmode11_on_office:   - brightness: 222.38
2020-06-07 19:26:46.795781 INFO controller_switchmode11_on_office:   - transition: 0.40
2020-06-07 19:26:47.254947 INFO controller_switchmode11_on_office: 🤖 Service: light.turn_on
2020-06-07 19:26:47.261842 INFO controller_switchmode11_on_office:   - entity_id: light.0xec1bbdfffed45c3b_light
2020-06-07 19:26:47.266923 INFO controller_switchmode11_on_office:   - brightness: 190.75
2020-06-07 19:26:47.271978 INFO controller_switchmode11_on_office:   - transition: 0.40
2020-06-07 19:26:47.722564 INFO controller_switchmode11_on_office: 🤖 Service: light.turn_on
2020-06-07 19:26:47.727788 INFO controller_switchmode11_on_office:   - entity_id: light.0xec1bbdfffed45c3b_light
2020-06-07 19:26:47.732933 INFO controller_switchmode11_on_office:   - brightness: 159.12
2020-06-07 19:26:47.737978 INFO controller_switchmode11_on_office:   - transition: 0.40
2020-06-07 19:26:48.193088 INFO controller_switchmode11_on_office: 🤖 Service: light.turn_on
2020-06-07 19:26:48.198197 INFO controller_switchmode11_on_office:   - entity_id: light.0xec1bbdfffed45c3b_light
2020-06-07 19:26:48.203797 INFO controller_switchmode11_on_office:   - brightness: 127.50
2020-06-07 19:26:48.208797 INFO controller_switchmode11_on_office:   - transition: 0.40
2020-06-07 19:26:48.419032 INFO controller_switchmode11_on_office: 🎮 Button event triggered: `clear`
2020-06-07 19:26:48.422759 INFO controller_switchmode11_on_office: 🏃 Running `release` now
2020-06-07 19:26:48.426053 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'clear', 'wildcard': None}
2020-06-07 19:26:48.525372 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:48.652335 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'inc-dec', 'wildcard': None}
2020-06-07 19:26:50.542369 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'toggle', 'wildcard': None}
2020-06-07 19:26:50.605480 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:52.861906 INFO controller_switchmode11_off_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}
2020-06-07 19:26:52.870536 INFO controller_switchmode11_off_office: 🎮 Button event triggered: `inc-dec`
2020-06-07 19:26:52.873847 INFO controller_switchmode11_off_office: 🏃 Running `sync` now
2020-06-07 19:26:52.880797 INFO controller_switchmode11_off_office: 🤖 Service: light.turn_on
2020-06-07 19:26:52.885089 INFO controller_switchmode11_off_office:   - entity_id: light.0xec1bbdfffed45c3b_light
2020-06-07 19:26:52.889308 INFO controller_switchmode11_off_office:   - color_temp: 370
2020-06-07 19:26:52.893481 INFO controller_switchmode11_off_office:   - brightness: 254
2020-06-07 19:26:52.897757 INFO controller_switchmode11_off_office:   - transition: 0.30
2020-06-07 19:26:52.939449 INFO controller_switchmode11_off_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'inc-dec', 'wildcard': None}
2020-06-07 19:26:54.454536 INFO controller_switchmode11_on_office: 🎮 Button event triggered: `clear`
2020-06-07 19:26:54.458175 INFO controller_switchmode11_on_office: 🏃 Running `release` now
2020-06-07 19:26:54.461237 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': 'clear', 'wildcard': None}
2020-06-07 19:26:54.470536 INFO controller_switchmode11_on_office: data={'topic': 'zigbee2mqtt/office_cmnd', 'payload': '', 'wildcard': None}

[htvekov]

If I remove controller_switchmode11_on_office from app, I just get the same warning for the next almost identical controller.

2020-06-07 22:10:59.510310 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 22:10:59.510826 WARNING AppDaemon: Unexpected error during process_event()
2020-06-07 22:10:59.511284 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 22:10:59.512568 WARNING AppDaemon: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 187, in process_event
    await self.process_event_callbacks(namespace, data)
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 263, in process_event_callbacks
    for name in self.AD.callbacks.callbacks.keys():
RuntimeError: dictionary changed size during iteration
2020-06-07 22:10:59.513100 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 22:10:59.517952 WARNING controller_switchmode11_off_office: ------------------------------------------------------------
2020-06-07 22:10:59.519053 WARNING controller_switchmode11_off_office: Unexpected error in worker for App controller_switchmode11_off_office:
2020-06-07 22:10:59.519575 WARNING controller_switchmode11_off_office: Worker Ags: {'id': 'b296222cd8c44b37813bbfcf8b12705f', 'name': 'controller_switchmode11_off_office', 'objectid': '4d263f8863154768878f8e913d22fedb', 'type': 'event', 'event': 'appd_started', 'function': <bound method MQTTIntegration.event_callback of <core.integration.mqtt.MQTTIntegration object at 0x7f0b3780d760>>, 'data': {}, 'pin_app': True, 'pin_thread': 2, 'kwargs': {'topic': 'zigbee2mqtt/office_cmnd', '__thread_id': 'MainThread'}}
2020-06-07 22:10:59.520460 WARNING controller_switchmode11_off_office: ------------------------------------------------------------
2020-06-07 22:10:59.522186 WARNING controller_switchmode11_off_office: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/threading.py", line 725, in async_worker
    await funcref(args["event"], data, args["kwargs"])
  File "/config/appdaemon/apps/controllerx/core/integration/mqtt.py", line 25, in event_callback
    await self.controller.handle_action(data["payload"])
KeyError: 'payload'
2020-06-07 22:10:59.522675 WARNING controller_switchmode11_off_office: ------------------------------------------------------------

I suspect it has something to do with the topic naming ?
If I change topic and add some form of attribute at the end (eg. zigbee2mqtt/office_cmnd/attribute) I get this warning instead ?

2020-06-07 22:28:44.402046 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 22:28:44.402671 WARNING AppDaemon: Unexpected error during process_event()
2020-06-07 22:28:44.403171 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 22:28:44.404499 WARNING AppDaemon: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 187, in process_event
    await self.process_event_callbacks(namespace, data)
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 263, in process_event_callbacks
    for name in self.AD.callbacks.callbacks.keys():
RuntimeError: dictionary changed size during iteration
2020-06-07 22:28:44.405060 WARNING AppDaemon: ------------------------------------------------------------

[xaviml]

Hi @htvekov,

Could you share in here your appdaemon.yaml? (Hiding the secrets if any)

Also, I found these 3 bugs related to this:

• https://github.com/home-assistant/appdaemon/issues/920
• https://github.com/home-assistant/appdaemon/issues/452
• https://github.com/home-assistant/appdaemon/issues/495

I also pushed some changes to dev to avoid the KeyError message. Maybe it got something to do with it, but I think the both messages you where getting are totally independent.

[htvekov]

Yep, appdeamon.yaml below (nothing special at all):

---
secrets: /config/secrets.yaml
appdaemon:
  latitude: 55.35XXXX
  longitude: 10.60XXXX
  elevation: 24
  time_zone: Europe/Copenhagen
  plugins:
    HASS:
      type: hass
    MQTT:
      type: mqtt
      namespace: mqtt # This is important
      client_host: 192.168.xxx.xxx
      client_user: xxxxx
      client_password: xxxxx
http:
  url: http://127.0.0.1:5050
admin:
api:
hadashboard:

[htvekov]

Just updated to latest dev and key error message is now gone.

Looks like home-assistant/appdaemon#920 is exactly same error as I'm experiencing.

2020-06-07 23:23:20.082916 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 23:23:20.083488 WARNING AppDaemon: Unexpected error during process_event()
2020-06-07 23:23:20.084050 WARNING AppDaemon: ------------------------------------------------------------
2020-06-07 23:23:20.085593 WARNING AppDaemon: Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 187, in process_event
    await self.process_event_callbacks(namespace, data)
  File "/usr/lib/python3.8/site-packages/appdaemon/events.py", line 263, in process_event_callbacks
    for name in self.AD.callbacks.callbacks.keys():
RuntimeError: dictionary changed size during iteration
2020-06-07 23:23:20.086160 WARNING AppDaemon: ------------------------------------------------------------

[xaviml]

Indeed, my appdaemon.yaml looks the same... In one of the issues I sent above they said that the problem got solved after a while, but they do not know the solution.

For the moment, as long as it works as expected, it should be fine.

[htvekov]

Yes, it's only a warning and everything works as expected.

Don't spend more time on this now, Xavi 🙂

[xaviml]

Feature added in ControllerX v2.8.0