Homey Community Forum

Strange MQTT Client behavior

Hello,
I observe quite strange behavior with MQTT Client.
I have MQTT Hub, where all devices are published to topic homie/homey-5dd…1/#

I also have other devices which publish messages like openHab/# and UPS/#
I have two flows which subscribe to topic: UPS/status and openHab/Okno3/BlindsControl.
But those flows get disabled due to too much run.

What is most strange is log from MQTT Hub:

20210322-18:41:39 publish_options: {“qos”:0,“retain”:true}
20210322-18:41:39 send 0 on topic homie/homey-5dd…1/town/measure-cloudiness
20210322-18:41:39 OnMessage called
20210322-18:41:39 received ‘’ on ‘homie/homey-5dd…1/town/measure-cloudiness’
20210322-18:41:39 Trigger generic card for homie/homey-5dd…1/town/measure-cloudiness
20210322-18:41:39 send message to listeners via realtime api
20210322-18:41:39 homie/homey-5dd…1/town/measure-cloudiness:
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/measure-cloudiness topic = UPS/status
20210322-18:41:39 topic: homie/homey-5dd…1/town/measure-cloudiness pattern: UPS/status
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/measure-cloudiness topic = openHab/Okno3/BlindsControl
20210322-18:41:39 topic: homie/homey-5dd…1/town/measure-cloudiness pattern: openHab/Okno3/BlindsControl
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:39 SendMessageToTopic called
20210322-18:41:39 SendMessageToTopic: {“qos”:0,“retain”:“1”,“mqttTopic”:“homie/homey-5dd…1/town/description”,“mqttMessage”:“clear sky”}
20210322-18:41:39 publish_options: {“qos”:0,“retain”:true}
20210322-18:41:39 send clear sky on topic homie/homey-5dd…1/town/description
20210322-18:41:39 OnMessage called
20210322-18:41:39 received ‘clear sky’ on ‘homie/homey-5dd…1/town/description’
20210322-18:41:39 Trigger generic card for homie/homey-5dd…1/town/description
20210322-18:41:39 send message to listeners via realtime api
20210322-18:41:39 homie/homey-5dd…1/town/description: clear sky
20210322-18:41:39 SendMessageToTopic called
20210322-18:41:39 SendMessageToTopic: {“qos”:0,“retain”:“1”,“mqttTopic”:“homie/homey-5dd…1/town/conditioncode”,“mqttMessage”:“Clear”}
20210322-18:41:39 publish_options: {“qos”:0,“retain”:true}
20210322-18:41:39 send Clear on topic homie/homey-5dd…1/town/conditioncode
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/description topic = UPS/status
20210322-18:41:39 topic: homie/homey-5dd…1/town/description pattern: UPS/status
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/description topic = openHab/Okno3/BlindsControl
20210322-18:41:39 topic: homie/homey-5dd…1/town/description pattern: openHab/Okno3/BlindsControl
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:39 OnMessage called
20210322-18:41:39 received ‘Clear’ on ‘homie/homey-5dd…1/town/conditioncode’
20210322-18:41:39 Trigger generic card for homie/homey-5dd…1/town/conditioncode
20210322-18:41:39 send message to listeners via realtime api
20210322-18:41:39 homie/homey-5dd…1/town/conditioncode: Clear
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/conditioncode topic = UPS/status
20210322-18:41:39 topic: homie/homey-5dd…1/town/conditioncode pattern: UPS/status
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:39 Listener eventMQTT called
20210322-18:41:39 state.topic = homie/homey-5dd…1/town/conditioncode topic = openHab/Okno3/BlindsControl
20210322-18:41:39 topic: homie/homey-5dd…1/town/conditioncode pattern: openHab/Okno3/BlindsControl
20210322-18:41:39 We are not waiting for this topic
20210322-18:41:40 getLogLines called

I do not understand what has OpenWheatherMap to do with my blinds?

An here is example of flow:

Do you have the MQTT Hub app running?

Yes, but hub is publishing to different topic: homie/homey-5dd…1/#

I have issue with topics: UPS/status and openHab/Okno3/BlindsControl
(they are from other sources like UPS connected to PC via USB)

What you see being logged is the MQTT Client app deciding which flows to trigger when a message comes in. For instance this:

20210322-18:41:39 topic: homie/homey-5dd…1/town/conditioncode pattern: openHab/Okno3/BlindsControl
20210322-18:41:39 We are not waiting for this topic

There’s an incoming message on the homie/homey-5dd…1/town/conditioncode topic, and the client checks if your trigger card which listens to openHab/Okno3/BlindsControl should handle the message. It obviously shouldn’t, hence the message “We are not waiting for this topic”.

The last screenshot you post shows that your UPS and Blinds flows have been disabled by Homey, so until you enable them again they won’t trigger.

Thanks for explanation of logs - it was little bit confusing for me.

Now my only issue seems to be related to this flow - why homey keeps disabling it every time I enable them?

For topic openHab/Okno3/BlindsControl there is retained message = 0 and I have checked - openhab is publishing only when device status is changed.
For topic UPS/status there is currently no message at all as it’s not retained and last message expired over month ago…
(I did those two scenarios by intent - because I try to solve this disabling issue for some time)

The system that disables flows because they get called too much has been acting strangely ever since it was introduced. For some people, it triggers way to often, for others, not enough. Athom hasn’t been able to fix this (I don’t even know if they consider it broken).

OK, I’ll try to contact support. Just to be sure - from logs provided do you think that it’s not MQTT client who is trying to start this flow so many times?

I have discovered that this task disable occurs every time I restart MQTT hub application - any logic in that?
reality is, that flow do not run many times - because I have added logging in my flows:
image

some flows didn’t run at all and are disabled after MQTT hub restart…

So if I understand correctly: your flow that listens on an OpenHAB topic gets disabled when you restart the MQTT hub app?

I initially thought of a possible reason why Homey decides to disable your flows, but I cannot reproduce it. Which Homey firmware are you running?

Yes Robert, with only correction - my flows that listen to ANY topic get disabled when I restart MQTT hub.

Homey fw: 5.0.4

I also created ticket for support, but I’m afraid, that it might be issue of MQTT Hub…

I’m sure they will blame the MQTT Hub app, but they should explain how that app can cause flows for another app to get disabled.

Are you also using the MQTT broker app?

nope - I have separate mosquitto on linux box.

@scanno, @HarriedeGroot what do you think about this issue?
(not that I do not appreciate your help @robertklep)

1 Like

At startup the MQTT Hub does a ‘broadcast’. Meaning all capabilities of all devices are traversed and the current state/value is published to their representing mqtt topic. The number of messages being send adds up quickly with an increased number of devices.

If you’re listening to all mqtt messages with a topic wildcard within a flowcard, this flow will probably be called hundreds of times in a very short period.
That’s probably causing the flow to be disabled by Homey.

From what I understand though, flows that listen on a specific unrelated MQTT topic are also being disabled.

It feels like an(other) issue with the flow rate limiter. The way the MQTT Client works is that when it receives a message on any of the topics it’s subscribed to, it will call each flow trigger’s run listener to see if the topic in the flow trigger matches the incoming message (it has to work like this to be able to support wildcard subscriptions). When there’s no match, the trigger will “cancel” the flow.

I initially thought that because the run listener is called, Homey considers the flow to be started (and apply the rate limiter) even though the run listener can decide the message isn’t meant for it and cancel the flow. However, I haven’t been able to reproduce this.

+1 to robert theory.

I have only one flow enabled and it listen to some “made up” topic:
image

When I manually push broadcast button in hub setting - it finishes broadcast cycle and flow stays enabled:
image

when I restart hub app - it disables flow

You just know that Athom will be blaming the MQTT Hub app for this :stuck_out_tongue_winking_eye:

That’s why I want to try and reproduce it without the MQTT Hub app, which hasn’t worked so far. I’ll try and mimic how the Hub app uses the MQTT Client app for publishing.

@Zimo which version of the MQTT Client app are you running?

v2.4.1 from Menno

That rate limiting problem was there also when Athom implemented rate limiting before. Then I complained about it and they changed it. Guess they made the same mistake again. You have to walk through the each trigger card. There is no other way. Back then Athom counted each check as part of the rate, no matter if the card was triggered or not.

Anyway… I dont feel like going to fight about that again.