Rule triggers twice on received update via mqtt

Tags: #<Tag:0x00007f617efa2698> #<Tag:0x00007f617efa2580> #<Tag:0x00007f617efa23f0>
  • Platform information:
    • Hardware: Main:VM 4 core/ 3GB mem/ 50GB storage | RPI: PI 3B with aeotec gen5 zstick connected via eventbus (mqtt1 binding)
    • OS: Debian 9
    • Java Runtime Environment: Oracle 1.8.0_201"
    • openHAB version: 2.5.8 / 2.5.8

My setup with RPI being an OH 2.5.8 instance with Z-stick passing Z-wave items on to the main instance OH 2.5.8 in a VM, due to location issues wrt z-wave connectivity.
This has been running great for 2 years or so.
I added a new Fibaro Button to my setup as a scenecontroller and as a first trial used a rule found here on the forum.

Now when I press the button the rule triggers on the update correctly on the RPI by only triggering once, the update is sent via eventbus only once to the main instance, however there it triggers twice.
I’ve searched for other posts on the forum if this is a known side-effect of using mqtt-eventbus, but haven’t seen proof that other people have run into this before.

When using the trigger as changed, the trigger is correctly only triggered once. But that misses the flow of pressing the same options 2 times in a row(ie. single press 2 times with 5 sec interval)
I’m sure this can be mitigated using a locking mechanism, but I think it’s weird this only happens over mqtt1-plugin and not directly on the RPI directly.

Questions:
Anyone else encountered this issue before?
Seeing several topics regarding triggers on the mqtt-addon(v2), am I right to assume this issue doesn’t occur there? That would make biting the bullet regarding mqttv2 setup easier.

  • Items:
RPI:
  Number   Hobbyroombutton_SceneNumber    "Scene number"    {channel="zwave:device:512:node46:scene_number"}
Main:
  Number   Hobbyroombutton_SceneNumber    "Scene number [%s]"    {mqtt="<[mosquitto:domopi/Hobbyroombutton_SceneNumber/state:state:default]"}
  • Rules code related to the issue
rule	"Fibaro Hobbyroom Button Pushing"
when
	Item Hobbyroombutton_SceneNumber received update
    // Item Hobbyroombutton_SceneNumber changed
then
    logInfo("FB01", "<" + Hobbyroombutton_SceneNumber.state + ">")
	if (Hobbyroombutton_SceneNumber.state == 1.0) {
		logInfo("FB01", "FB01 1x pushed")
	}
	if (Hobbyroombutton_SceneNumber.state == 1.1) {
		logInfo("FB01", "FB01 let go")
	}
end//shortened for brevity and enough to show issue.
  • Services configuration related to the issue
RPI:
mqtt:
broker.qos=2

mqtt-eventbus:
broker=broker
statePublishTopic=domopi/${item}/state
commandSubscribeTopic=domopi/${item}/command

Main:
mqtt:
broker.qos=2

mqtt-eventbus:
broker=broker
commandPublishTopic=domopi/${item}/command
stateSubscribeTopic=domopi/${item}/state

Log from RPI:

2020-09-12 18:05:36.704 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 18:05:36.714 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 18:05:48.684 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.3>
2020-09-12 18:05:48.711 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 2x pushed

Log from Main:

2020-09-12 18:05:36.906 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 18:05:36.906 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 18:05:36.907 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 18:05:36.907 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 18:05:48.824 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.3>
2020-09-12 18:05:48.824 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.3>
2020-09-12 18:05:48.826 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 2x pushed
2020-09-12 18:05:48.827 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 2x pushed

Mosquitto:

1599926736: Received PUBLISH from domopi (d0, q2, r0, m63082, 'domopi/Hobbyroombutton_SceneNumber/state', ... (3 bytes))
1599926736: Sending PUBLISH to openHAB2 (d0, q2, r0, m2301, 'domopi/Hobbyroombutton_SceneNumber/state', ... (3 bytes))
1599926748: Received PUBLISH from domopi (d0, q2, r0, m63086, 'domopi/Hobbyroombutton_SceneNumber/state', ... (3 bytes))
1599926748: Sending PUBLISH to openHAB2 (d0, q2, r0, m2309, 'domopi/Hobbyroombutton_SceneNumber/state', ... (3 bytes))

Well, sure, but the rule you have shown us is not the rule producing those logs.

A comment, may or may not be relevant but depends on the hidden rule really -

It is theoretically possible to execute both of these logInfos. There is nothing to stop the Item changing between the if()s.

Alternative if() structure that ensures only one of the alternative actions takes place

	if (.. this ..) {
		// do stuff
	}
	else if ( .. that ..) {
		// do something else
	}

Might be important if there is more to this rule than we can see.

Overall, it looks like double logging somehow.
A method to distinguish multiple logging from multiple rule starts -

var Number rulecounter = 0

rule "blah"
...
then
   rulecounter = rulecounter + 1
   logInfo("test", "entry " + rulecounter.toString)

For every action there’s a unique logging rule.

Amended the rule with your counter and added a closing else.:

var Number rulecounter = 0
rule	"Fibaro Hobbyroom Button Pushing"
when
	Item Hobbyroombutton_SceneNumber received update
    // Item Hobbyroombutton_SceneNumber changed
then
    rulecounter = rulecounter + 1
	logInfo("FB01", "entry " + rulecounter.toString)
    logInfo("FB01", "<" + Hobbyroombutton_SceneNumber.state + ">")
	if (Hobbyroombutton_SceneNumber.state == 1.0) {
		logInfo("FB01", "FB01 1x pushed")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.1) {
		logInfo("FB01", "FB01 let go")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.2) {
		logInfo("FB01", "FB01 kept in")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.3) {
		logInfo("FB01", "FB01 2x pushed")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.4) {
		logInfo("FB01", "FB01 3x pushed")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.5) {
		logInfo("FB01", "FB01 4x pushed")
	}
	else if (Hobbyroombutton_SceneNumber.state == 1.6) {
		logInfo("FB01", "FB01 5x pushed")
	}
	else {
		logInfo("FB01", "No matching state")
	}
end

Logging:

RPI:
2020-09-12 21:32:45.742 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 1
2020-09-12 21:32:45.748 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:45.753 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 21:32:58.926 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 2
2020-09-12 21:32:58.936 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:58.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed

Main:
2020-09-12 21:32:45.398 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 1
2020-09-12 21:32:45.398 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 1
2020-09-12 21:32:45.399 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:45.399 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:45.400 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 21:32:45.400 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 21:32:59.149 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 2
2020-09-12 21:32:59.149 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 2
2020-09-12 21:32:59.149 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:59.149 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:59.150 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 21:32:59.150 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed

Mosquitto:
2020-09-12 21:32:45.742 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 1
2020-09-12 21:32:45.748 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:45.753 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-12 21:32:58.926 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 2
2020-09-12 21:32:58.936 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-12 21:32:58.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed

I’m wondering why the received update triggers twice when coming in from mqtt and only once directly on the Pi, I only added the same rule on the PI to determine if it was the zwave causing this.

That’s double logging. Look at the timestamps, there’s no real chance every ‘double’ incident would fall in the same millisecond (that’s what caught my eye in your previous log).
Taken with the counter value bumping just once each time, I’m confident there is one event and one rule run.

I’ve no idea how you can get double logging. Two log4j services running? Some weird custom configuration?

Alright I don’t think it’s a case of double logging, then it would happen all over my system with other rules.
The weirdness would be in the eventbus over mqtt where zwave devices are shared from an instance without rules as an remote zwave controller, with logic in the main instance.

To test it out however I tried 3 scenario’s:
1 with triggering this device on ‘changed’, this only logged once(this is what I have been using for sensor-updates so far)
1 with virtual switch and triggering on ‘received update’, this only logged once.
1 with a zwave sensor connected in the same RPI and triggering on ‘received update’, this only logged once.
I retried above tests using another action(sendNotification) with the same results

I’ve been pushing the button more often now and I notice that every now and again it does run twice(the rulecount goes up with 2 instead of 1 at 1 buttonpress.)

RPI:
2020-09-13 11:42:19.071 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 85
2020-09-13 11:42:19.081 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:19.092 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:25.583 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 86
2020-09-13 11:42:25.595 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:25.606 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:30.669 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 87
2020-09-13 11:42:30.680 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:30.693 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:42.937 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 88
2020-09-13 11:42:42.949 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:42.961 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:46.898 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 89
2020-09-13 11:42:46.910 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:46.922 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:49.797 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 90
2020-09-13 11:42:49.807 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:49.818 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:51.831 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 91
2020-09-13 11:42:51.843 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:51.854 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed
2020-09-13 11:42:53.949 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 92
2020-09-13 11:42:53.961 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:53.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - FB01 1x pushed

Main:
2020-09-13 11:42:19.090 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 17
2020-09-13 11:42:19.091 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:19.092 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 18
2020-09-13 11:42:19.093 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:25.599 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 19
2020-09-13 11:42:25.600 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:25.603 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 20
2020-09-13 11:42:25.604 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:30.693 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 21
2020-09-13 11:42:30.694 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:30.694 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 22
2020-09-13 11:42:30.696 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:42.960 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 23
2020-09-13 11:42:42.960 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 23
2020-09-13 11:42:42.961 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:42.961 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:46.918 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 24
2020-09-13 11:42:46.918 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 24
2020-09-13 11:42:46.919 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:46.919 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:49.819 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 25
2020-09-13 11:42:49.819 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 25
2020-09-13 11:42:49.820 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:49.820 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:51.853 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 26
2020-09-13 11:42:51.853 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 26
2020-09-13 11:42:51.853 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:51.853 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:53.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 27
2020-09-13 11:42:53.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - entry 27
2020-09-13 11:42:53.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>
2020-09-13 11:42:53.971 [INFO ] [.eclipse.smarthome.model.script.FB01] - <1.0>

This (now) leads me to believe this is device specific, and there are 2 updates triggering the rule at the same time.
I’m now looking into where to find the updates, the itemchanged is logged by default in eventlog, but not the updates(which makes sense due to info overload).

In the meantime I implemented a lock which takes care of the effect of multiple updates.
I’ll write this down, since I want to migrate to the v2 binding which is likely more robust in the department of triggering.

Sure, if we rattle things enough there’s usually hiccups to be exposed. An important follow up would be to see dupe MQTT messaging on those occasions. I don’t think this is what you’re looking for.

But you don’t generally see that on your “source” system, which I assume is a less powerful Pi, so 'doubled" incidents would be more spread out in time.

Nor do you see that in your MQTT monitor, which absolutely would have to have a few mS between messages simply because it takes real time to send messages.
And of course that offset in time would continue to be reflected in your updates at the target system.

This is a massive clue, the consistent duplicate timestamps.
Two real updates could kick off two runs, two "copies’ of the rule. A sufficiently powerful multicore server could conceivably run those pretty much in parallel.
But there’s still only one counter variable, outside of the rule, and it’s very hard to believe that part won’t work differently.

A possibility is that there is somehow a doubled link between your single MQTT Thing and your single Item.
Items are allowed to be linked to more than one channel. The effects of linking to the same channel twice might look like this, on a server box powerful enough to run two copies of the same rule simultaneously.
I think you certainly should explore this - REST API links should show it up.
EDIT - SCRATCH THAT - it won’t help for a v1.x defined link,no Thing involved. but it remainstrue that Itemscan be linked to more than one v1.x binding path. I’ve no idea how you can verify the link there.

By setting logging in karaf to: log:set TRACE smarthome.event.ItemStateEvent I was able to pinpoint the main instance does get 2 updates as opposed to the RPI only one. Also the mqtt message is going out only once(QOS2).
The item was just created connecting to 1 topic which isn’t used elsewhere and isn’t part of a group yet.
Restarted after creating the items.

I’ve been using this setup for 2 years or so without issues and with the use of a locking mechanism makes sure rules are only executed once, so for me the issue is not pressing anymore.
And since mqtt1 addon wil become obsolete anyways with Openhab v3 on the horizon, I’ll start reading up on moving config to the v2 addon.

Doesn’t happen by magic, My best guess is still that Item is double linked.

If you wanted to prove the point, the simplest way would be to create a wholly new Item, but I expect that’s a fag with it being involved in the bus thing.

Maybe this has something to do with your issue? QOS 2 may result in resending the message if the receiver does not respond fast enough. While I don’t think that your system is slow enough to do this, maybe the mqtt binding is not handling the QOS 2 handshake correctly. Or possibly it is putting the message on the channel twice while handling the back and forth with the broker.

Try QOS 0 and see if it still happens.

1 Like

Good point, MQTT broker’s idea of “publish once” can be several actual messages. Bit curious why it would then be Item (topic) specific though.

I’m also still curious if this is a fairly potent host (relative to the usual plodding openHAB box). I have every sympathy for users discovering buried problems most others never see.

Sorry to burst your bubble, but my openhab has been running on an x64 desktop running debian with 4GB RAM for over 2 years now. I was running the mqtt1 binding when I first switched off the RPi and now I’m on mqtt2 and I’ve never experienced this problem. I’ve always run QOS 0 though and never had communication problems, it seemed like the right choice based on LAN/WI-FI being very high reliability in terms of networks.

I think this is either device specific or some strange thing with QOS 2 or the binding doing something weird.

That’d be true for QOS 1 (at least once) but QOS 2 means deliver exactly once. There is an ack protocol set up with QOS 2 to ensure the message is delivered once and only once. QOS 0 means at most once so with QOS 0 if the message is missed by the client it’s missed and there is no retry. Only QOS 1 would permit delivery of the same message more than once.

I think the suggestion is that there’s some problem in the loop.
QoS2 - send message, await ack.
Oh no, there’s a send failure or no ack!
But I must send it, so send again.

I find it hard to believe that could all happen within 1mS but there is something screwy.

There is a four part handshake with QOS 2 that prevents this and ensures that the message can only be received/processed once by the client. See https://www.hivemq.com/blog/mqtt-essentials-part-6-mqtt-quality-of-service-levels/ for a good explanation for how that handshake works to prevent it.

I only bring it up to avoid heading down the wrong path in trying to figure out this problem.

While I agree with you, this is the part that makes me think something weird is happening. The 3rd step involves the receiver getting a second packet related to the same message. I’m wondering if that is what is triggering the binding to put the message on the channel again. 4 small packets on a 100M network would be pretty damn fast, on 1000M network probably in the sub millisecond range.

That fourth packet, all the handshake really, is handled by the MQTT library and is transparent to the binding. I believe the MQTT 2.5 binding is using the HiveMQ library. But the old MQTT 1.x binding uses Paho. In either case though, the binding wouldn’t receive the message until the handshake is complete. The whole process is set up such that no matter how many times the library receives the message, it only delivers it the one time. The handshake is defined to ensure this.

The only way that the message could be received twice by the binding is:

  • it’s really using QOS 1, not QOS 2
  • there is a bug in the MQTT library the binding is using

But there are some points worth considering. QOS is defined between the client and the MQTT broker. Furthermore, the QOS can be set at the subscription and the for each published message independently. So it could publish one message at QOS 1 and another at QOS 0 and subscribe using QOS 2.

So the question is what exactly the QOS setting in the MQTT 1.x binding config applies to. Published messages only? Published messages and subscriptions? Just subscriptions? Does it apply to subscriptions at all?

By default, if the subscription doesn’t define a QOS, the QOS specified by the publisher is used I think. So, if we assume that the QOS setting only applies to the messages published by OH, one needs to set the QOS to 2 at the device that is publishing the messages in order for OH to receive messages at QOS 2.

It’s possible that the binding defaults the QOS on subscriptions and it cannot be changed.

To answer the question one would need to look at the code.

Note, this ambiguity is still present in MQTT 2.5. It’s possible to set the QOS on a per Channel basis, but it’s unclear whether that setting applies to just the publisher or both the publisher and subscriber.

I think if all other possibilities are eliminated, the code needs to be reviewed to see if the QOS 2 is being used in the subscription, the QOS for the subscription isn’t defined, or it’s hard coded to 1.

Can we see this fairly crucial log?

However …

Okay, a single message gets published at the source.

And when that message arrives, the event bus handler of MQTTv1 binding automatically updates the given Item.

Meantime …

This Item has also been individually configured to listen to a topic that happens to be identical to the event bus topic. So of course when the event bus message arrives, the “ordinary” part of the MQTTv1 binding swings into action and updates the Item.

Voila, two updates from one message as quickly as the binding and internal events bus can handle them (and I think on this multicore box that can be quite fast).
It’s doing exactly what it has been configured to do.

You could confirm that by examining subscriptions at the broker - there’ll be a wildcard sub from events bus, a specific sub from Item

I’m still quite impressed this box can run two ‘copies’ of the rule in such close lockstep.

I’m further surprised that a global variable is not thread safe, that’s spiteful.
EDIT - I wonder if
rulecounter = rulecounter + 1
is the problem because there are separate variable ‘read’ and ‘write’
rulecounter++
might have been a better choice in this very close rule-race. Or might be just the same internally!

I’ve had this happen before, it’s really night and day when you come off an RPi to an x86/64 platform. When I switched off the RPi my start to fully loaded time for openHAB was 5-7 minutes, now with a much much larger setup openhab is fully loaded in under a minute (all non-autogen items are still in files).


Time to switch to Jython rules :wink:
With Jython rules you could easily have this scenario of two rules running essentially in parallel on an RPi, they are lightning fast compared to Xtend.

I do run on a multicore x86, and have had to learn a lot about race conditions :wink:

I understood they were queued.

Interesting, I assumed they were threaded but maybe they are just that fast. I’ve never tested it and I have ported over thread/concurrency safeties where needed from my Xtend rules.