MQTT/Homie set behaviour

mjcumming · December 2, 2019, 2:10pm

When controlling a homie device from openhab, the set message is sent with retained false.

qos : 0, retain : false, cmd : publish, dup : false, topic : homie/testdimmer/dimmer/dimmer/set, messageId : , length : 38, Raw payload : 4954

If I close and reopen the subscriber, the “same” set message is re sent with retained true

qos : 0, retain : true, cmd : publish, dup : false, topic : homie/testdimmer/dimmer/dimmer/set, messageId : , length : 38, Raw payload : 4954

So what is happening, if the homie device goes offline and then reconnects to the broker, it is always getting the last set message from OH.

If I use a client like MQTT Explorer to send the set message, that message does not reappear if the homie device goes offline and back online.

So it seems that OH is sending a set message when there is a new subscriber. Is there a way to turn this behavior off?

vzorglub · December 2, 2019, 2:40pm

No, Homie sets the topic as retained therefore

Is incorrect, the broker sends the message, not openHAB. The broker will send the message to any new subscriber on connection because it is retained

Correct, unless to activate the retain flag

mjcumming · December 2, 2019, 3:42pm

Per homie protocol, set messages should not be sent as retained.

In the behavior above, the first message was generated by using the PaperUI to change the dimmer value. It is correct as retain is false.

The second message occurs after disconnecting a client (not OH) and then reconnecting the client to the broker. Notice the second message is now flagged retain true.

The problem is that everytime a client connected to the broker all the old set messages a sent and devices are changed even if that set value is no longer valid.

vzorglub · December 2, 2019, 4:16pm

Then there may be a bug in the binding. Please report on gitHUB

mjcumming · December 2, 2019, 5:26pm

Done https://github.com/openhab/openhab2-addons/issues/6493

Hard for me to believe others are not seeing this problem.

rlkoshak · December 2, 2019, 7:28pm

Once retained, always retained until cleared. Because there has been any retained message sent to the topic that message will remain on that topic even if there are later messages sent with the retained flag set to false.

openHAB is completely ignorant as to whether a subscriber subscribes or not so there is no way it can resend a message with the retained flag set to true when a client subscribes to the topic. So the most likely cause of the behavior is that at some point a retained message was published to that topic. That message remains because a retained message doesn’t get cleared out when non-retained messages are sent afterwords.

The first thing you need to do is clear out the retained message. You can do this by sending an empty message with the retained flag set to true. I think MQTT Explorer has a button you can use that will do this for you.

Until you clear out that old retained message, any client that subscribes to that topic will get that message every time they connect.

mjcumming · December 2, 2019, 7:40pm

@rlkoshak, I have cleared out all messages - using MQTT Explorer as you mentioned. The Homie spec says that set messages are to be sent with retain false. This is exactly what OH does.

BUT, if a client (not OH) disconnects from the broker and then reconnects, there is a second set message being sent that has the retain flag true. This second message only happens if the set command comes from OH. I know the set message is from OH as it comes with the same value as the first message.

Ie. If I clear out all messages and send a set command using MQTT Explorer, disconnect the non OH client and reconnect, no second set message appears. So this second set message with retain true when a client reconnects has to be coming from OH…

rlkoshak · December 2, 2019, 8:06pm

The only way OH will know about this is if it sends this second message when the broker publishes the LWT message for that client. Do you see a correlation between the LWT message and OH republishing the message?

If not, there is no way that OH can know that the client disconnected so how can it resend the message with or without the retained flag set to true?

I’m not convinced that is strong enough evidence yet to definitely say that is where the message is coming from. I’m not arguing it’s not coming from OH either.

Put the binding into trace logging. If OH is in fact sending the message, you will see it doing so in the logs.

How are you observing this second retained message? Does MQTT Explorer receive the message independently or are you seeing the disconnected client receiving the message when it reconnects? What is the exact timing of the message? Immediately when the client disconnects, when the broker publishes the LWT, some other delay?

mjcumming · December 2, 2019, 8:41pm

I’ll work on figuring out the log for the binding - have not used that before.

Openhab will know when the homie client reconnects as the homie client will republish itself. Its this reconnection that triggers OH to send the second set message.

The second set message does not appear if you reconnect a MQTT browser like MQTT Explorer or Lens

rlkoshak · December 2, 2019, 9:02pm

I use these settings:

# MQTT
log4j2.logger.mqtt.name = org.openhab.binding.mqtt
log4j2.logger.mqtt.level = TRACE
log4j2.logger.mqtt.additivity = false
log4j2.logger.mqtt.appenderRefs = MQTT
log4j2.logger.mqtt.appenderRef.mqtt.ref = MQTT

log4j2.appender.mqtt.name = MQTT
log4j2.appender.mqtt.type = RollingRandomAccessFile
log4j2.appender.mqtt.fileName = ${openhab.logdir}/mqtt.log
log4j2.appender.mqtt.filePattern = ${openhab.logdir}/mqtt.log.%i
log4j2.appender.mqtt.immediateFlush = true
log4j2.appender.mqtt.append = true
log4j2.appender.mqtt.layout.type = PatternLayout
log4j2.appender.mqtt.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.mqtt.policies.type = Policies
log4j2.appender.mqtt.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.mqtt.policies.size.size = 10MB
log4j2.appender.mqtt.strategy.type = DefaultRolloverStrategy
log4j2.appender.mqtt.strategy.max = 10

This will put the binding into trace logging and put all the MQTT logs into it’s own mqtt.log file.

mjcumming · December 2, 2019, 9:20pm

I know I should know this but where do I put that file?

rlkoshak · December 2, 2019, 9:23pm

Add that to the end of $OH_USERDATA/etc/org.ops4j.pax.logging.cfg. See the following for details:

mjcumming · December 2, 2019, 9:51pm

Ok got logging working!

I see the errors below when I try and set a value using the PaperUI. The right value gets sent but there is this error dump.

02-Dec-2019 15:51:29.571 [DEBUG] [org.openhab.binding.mqtt.generic.ChannelState     ] - Format pattern incorrect for mqtt:homie300:Queen:testdimmer:dimmer#dimmer
java.util.IllegalFormatConversionException: d != java.lang.String
	at java.util.Formatter$FormatSpecifier.failConversion(Formatter.java:4302) ~[?:1.8.0_222]
	at java.util.Formatter$FormatSpecifier.printInteger(Formatter.java:2793) ~[?:1.8.0_222]
	at java.util.Formatter$FormatSpecifier.print(Formatter.java:2747) ~[?:1.8.0_222]
	at java.util.Formatter.format(Formatter.java:2520) ~[?:1.8.0_222]
	at java.util.Formatter.format(Formatter.java:2455) ~[?:1.8.0_222]
	at org.openhab.binding.mqtt.generic.ChannelState.publishValue(ChannelState.java:366) [bundleFile:?]
	at org.openhab.binding.mqtt.generic.AbstractMQTTThingHandler.handleCommand(AbstractMQTTThingHandler.java:128) [bundleFile:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_222]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_222]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
	at com.sun.proxy.$Proxy502.handleCommand(Unknown Source) [?:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:74) [bundleFile:?]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_222]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_222]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
02-Dec-2019 15:51:29.581 [DEBUG] [nhab.binding.mqtt.generic.AbstractMQTTThingHandler] - Successfully published value 0.21000000 to topic homie/testdimmer/dimmer/dimmer/set

mjcumming · December 2, 2019, 10:05pm

Additionally, I am wondering if there is different logging if using the Homie thing of the MQTT binding?

rlkoshak · December 3, 2019, 3:15am

I don’t know for sure but I would expect it to log under org.openhab.binding.mqtt

mjcumming · December 5, 2019, 2:06am

Well after an exhaustive search I cannot find the culprit.

When using a homie device from OH, a set message is set with retain FALSE

But, when any MQTT client connects or reconnects AFTER OH has sent a set message, that client gets the set message with retain TRUE.

I cannot tell where that message is coming from.

Simple fix, in my homie 4 python class, simply ignore set messages that have a retain TRUE flag.

mjcumming · December 9, 2019, 7:45pm

See https://github.com/openhab/openhab2-addons/issues/6493#issuecomment-563399014