[SOLVED] MQTT Messages Lost - looking for direction on this

rrroonn · December 15, 2018, 5:31am

Hi,
[0H 2.3.0 on RPi openhabian]

I am integrating OH2 on RPi with a custom security app on ardquino. Generally, this is working well, except that sometimes MQTT messages are not picked up by OH2. Restarting mosquitto does not fix the problem. Restarting OH2 generally does fix the problem.

I can confirm messages are sent by using MQTT.fx to subscribe to the topic. The event log shows no response … see attached image.

The item that does not always get updated:

String EventLog     "xxx[%s]" (gEventInternal)		{mqtt="<[broker:/RWB/Security/Log:state:default]"}

the rule


rule "New Event Log"
when
    Item EventLog changed
then
    var String msg = now.toString("HH:mm ") + EventLog.state

	logWarn("myLog", "Logging event = " + msg)
	sendBroadcastNotification("SECURITY: " + msg)

    if (EventLog08.state != NULL) postUpdate(EventLog09, EventLog08.state)
    if (EventLog07.state != NULL) postUpdate(EventLog08, EventLog07.state)
    if (EventLog06.state != NULL) postUpdate(EventLog07, EventLog06.state)
    if (EventLog05.state != NULL) postUpdate(EventLog06, EventLog05.state)
    if (EventLog04.state != NULL) postUpdate(EventLog05, EventLog04.state)
    if (EventLog03.state != NULL) postUpdate(EventLog04, EventLog03.state)
    if (EventLog02.state != NULL) postUpdate(EventLog03, EventLog02.state)
    if (EventLog01.state != NULL) postUpdate(EventLog02, EventLog01.state)
    if (EventLog00.state != NULL) postUpdate(EventLog01, EventLog00.state)
    if (EventLog.state != NULL)   postUpdate(EventLog00, msg)
end

It is curious, as other items ties to different MQTT topics continue to work fine while this one.

tail of eventlog:

2018-12-15 15:17:30.835 [vent.ItemStateChangedEvent] - SecuritySystemMode changed from 1 to 5
2018-12-15 15:17:30.842 [vent.ItemStateChangedEvent] - SirenCount changed from 0 to 1
2018-12-15 15:17:30.970 [vent.ItemStateChangedEvent] - LoungePIR changed from 1 to 4
2018-12-15 15:17:31.017 [vent.ItemStateChangedEvent] - AlarmUpdate changed from 2018-12-15T15:17:27.415+1000 to 2018-12-15T15:17:30.970+1000
2018-12-15 15:17:40.971 [vent.ItemStateChangedEvent] - SecuritySystemMode changed from 5 to 1
2018-12-15 15:17:41.072 [vent.ItemStateChangedEvent] - LoungePIR changed from 4 to 1
2018-12-15 15:17:41.081 [vent.ItemStateChangedEvent] - AlarmUpdate changed from 2018-12-15T15:17:30.970+1000 to 2018-12-15T15:17:40.992+1000
2018-12-15 15:17:52.601 [vent.ItemStateChangedEvent] - AlarmUpdate changed from 2018-12-15T15:17:40.992+1000 to 2018-12-15T15:17:52.549+1000

LoungePIR for example, is getting the MQTT message - it is configured as:

Number HallPIR				<motion> (gSecurity, gHouse, gInternal) 	{mqtt="<[broker:/RWB/Security/HallwayPIR:state:default]"}
Number LoungePIR			<motion> (gSecurity, gHouse, gInternal) 	{mqtt="<[broker:/RWB/Security/LoungePIR:state:default]"}

but nothing for “EventLog”.

tail of mosquitto log is not enlightening:

[

14:51:52] openhabian@openHABianPi:~$ tail -f /var/log/mosquitto/mosquitto.log
1544849438: mosquitto version 1.4.10 (build date Wed, 17 Oct 2018 19:03:03 +0200) starting
1544849438: Config loaded from /etc/mosquitto/mosquitto.conf.
1544849438: Opening ipv4 listen socket on port 1883.
1544849438: Opening ipv6 listen socket on port 1883.
1544849443: New connection from 192.168.1.101 on port 1883.
1544849443: New client connected from 192.168.1.101 as arduinoClient (c1, k15).
1544849448: New connection from 192.168.1.100 on port 1883.
1544849448: New client connected from 192.168.1.100 as openhab2 (c1, k60).
1544849508: Client openhab2 disconnected.
1544849557: New connection from 192.168.1.100 on port 1883.
1544849557: New client connected from 192.168.1.100 as openhab2 (c1, k60).
1544850466: New connection from 192.168.1.101 on port 1883.
1544850466: Client arduinoClient already connected, closing old connection.
1544850466: Client arduinoClient disconnected.
1544850466: New client connected from 192.168.1.101 as arduinoClient (c1, k15).
1544850524: New connection from 192.168.1.10 on port 1883.
1544850524: New client connected from 192.168.1.10 as dfd5a5b1ebe2445a82796db7fb3e9564 (c1, k60).
1544851238: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.

There are no other OH2 Items subscribed to the same topic.

Any ideas how to diagnose further?

thanks,

Ron

Dim · December 15, 2018, 6:24am

Is EventLog.state getting updated when a new message is published to the broker or the rule is not firing properly all the time?

Try to check with a simple rule:

rule "New Event Log Troubleshooting"
when
	Item EventLog received update  // with "changed" you will only fire when the state is different
then
	logInfo("myLog", "Logging event = " + EventLog.state)
end

This will log into openhab.log
The events.log should also show the state update of the Item

You can also check the state of the item from the console to see if the state was updated following a new MQTT message: items list |grep EventLog

Ps: not a problem, but it’s better not to use a leading forward slash / in the beginning of the topic (RWB/Security/Log). Ref

vzorglub · December 15, 2018, 9:54am

Great MQTT best practice link. Thanks @Dim

rrroonn · December 15, 2018, 8:32pm

@Dim thank you for your suggestion - its seems very valid. I will try your suggestion.

You can also check the state of the item from the console to see if the state was updated

Something I did not know about - thanks

it’s better not to use a leading forward slash

OK, I will change this - thanks for advice

Thank you for your time and your sage advice.

Ron

rrroonn · December 16, 2018, 4:22am

@Dim , “received update” seems to have done the trick. Thanks for your help on this.

waspie · January 4, 2019, 12:36pm

I guess I’m not the only one. Since the upgrade to 2.4.0 (maybe coincidental) I’m losing MQTT messages. I’ve only really noticed this from one client but that’s because the function that affected by the message is very noticeable.

An ESP unit is generating the message. I have the ESP logging to syslog. I have confirmed via syslog that it is generated the message. I’ve also confirmed that MQTT is getting the message via sub -t "#’.
I’m using command rather than state but regardless (even when changing state) the openhab item is not getting updated. This is using the 1.x legacy binding.

To summarize, everything is working except openhab.