search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.9k stars 3.59k forks source link

[mqtt.homie] Homie Thing never comes online #10711

Closed ccutrer closed 2 years ago

ccutrer commented 3 years ago

Expected Behavior

Homie device conforming to specification comes online. If it can't a more detailed message (what topic did it not receive?) would be useful.

Current Behavior

The thing initially shows ONLINE, but after a while it switches to OFFLINE (COMMUNICATION_ERROR): Did not receive all required topics. AFAICT all topics are present, and they're sent to the broker QoS 1 and retained: true. I have another device running the exact same code, but has fewer constituent parts that is working fine. I initially thought it was because it was just such a large device (851 topics), but I have another Homie device with 10,973 topics that works just fine. It behaves pretty much the same regardless if disable/enable the Thing, restart the broker or homie bindings, or restart all of OpenHAB. The key log lines:

2021-05-17 12:59:37.037 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:homie300:mosquitto:monoprice10761a' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2021-05-17 12:59:37.041 [DEBUG] [e.internal.handler.HomieThingHandler] - About to initialize Homie device null
2021-05-17 12:59:37.041 [DEBUG] [e.internal.handler.HomieThingHandler] - About to start Homie device null
2021-05-17 12:59:37.047 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:homie300:mosquitto:monoprice10761a' changed from INITIALIZING to ONLINE
2021-05-17 12:59:42.042 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:homie300:mosquitto:monoprice10761a' takes more than 5000ms.
2021-05-17 13:00:07.044 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:homie300:mosquitto:monoprice10761a' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Did not receive all required topics

I'll attach a full log that shows all of the subscription logs, but basically all the subscribes happen within 0.1s after the thing goes ONLINE. I've also confirmed that every subscribeRaw line in the log has a corresponding Successfully subscribed line, and that for every one of those lines, a retained topic does exist in the broker (with the exception of optional attributes $format, $unit, $retained, and $settable), so I'm not missing any required topics. And vice versa - every topic on the broker was subscribed to, with the exception of the actual state topics (i.e. all the metadata topics did try to subscribe). I have TRACE logging on for org.openhab.core.io.transport.mqtt and org.openhab.binding.mqtt - I don't see any logging that shows when a value was actually received though.

openhab.log mqtt_topics.log

Steps to Reproduce (for Bugs)

Add a discovered Homie Thing from the inbox.

Context

I've looked at #7252, but AFAICT I should have the fix for that already in the code I'm running.

Your Environment

ccutrer commented 3 years ago

🤦 🤦 🤦 🤦

Turns out for one of my properties, the $datatype attribute was mis-spelled as booelan insted of boolean. Correcting that, and it comes online immediately. Better logging or error message would still be nice.