Possible bug: rules fire more then once

I use

  ____  ____  ___  ____  / / / /   |  / __ )
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  |
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/
    /_/                        2.0.0-SNAPSHOT
                               Build #650

  1. First bug. When I’m saving .items/.rules/.sitemap file… I see duplicates message:
11:16:31.974 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '_default.rules'
11:16:32.419 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '_default.rules'
  1. Second bug. Steps to reproduce:
  • sudo service openhab2 restart
  • each rule fire twice (I see duplicates with logInfo())
  • open file /etc/openhab2/rules/_default.rules and save (simple press Ctrl+S without changes)
  • in log I see
11:16:31.974 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '_default.rules'
11:16:32.419 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '_default.rules'
  • each rule fire once, all is ok now

Hi,
I’ve noticed the same behavior with the OH2b5 build 674
I’ve also noticed, don’t know if it’s also your case that if depending on the fact that the rules file is the latestt saved or not, the rules are tirggered several times or not.
Let’s me explain. I’ve got two rules files.If I save the first file, the second bug occurs once but after the rule from this file is triggered only once… normal …until the moment where I save the second rule file. The rule from the first rule file are triggered twice.every time.

Do you have the same behavior?

I also see duplicate messages when updating rules/files/items/sitemaps

I hab this behaviour with rules firing twice until they were saved during the runtime of OH2. In my case the problem was the “escape” character in a string.Removing this character did resolve the problem.
If you’d post the rule, we could have a look.

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.joda.time.*
import java.lang.Integer

var DateTime startedAt = new DateTime()
var Boolean homeIsEmptyNotificationWasSent = false

rule "TvReceiver"
when
	Item GI received command OFF
then
	var String baseUrl = "http://192.168.0.198/"
	var String command

	command = "curl -s " + baseUrl + "psw_check.html --referer " + baseUrl + " --data username=xxx&password=xxx"
	executeCommandLine(command, 2000)

	createTimer(now.plusSeconds(8)) [|
		command = "curl -s " + baseUrl + "system_shutdown.html --referer " + baseUrl + " --data shutdown=1"
		executeCommandLine(command, 2000)
        postUpdate(GI, OFF)
    ]
end


rule "TV"
when
	LgTvPower received command OFF
then
	postUpdate(LgTvState, OFF)
end


rule "Debug"
when 
	System started or
	Time cron "*/20 * * * * ?"
then
	logInfo("Debug", iPhonePavel.toString())
	logInfo("Debug", iPhoneAlina.toString())
end


rule "Torrent"
when
	System started or
	Time cron "0 * * * * ?"
then
	var String json = executeCommandLine("/home/pi/dlna-files.sh", 1000)

	var DecimalType total = new DecimalType(transform("JSONPATH", "$.total", json))

	logInfo("Torrent", dlnaFilesCount.toString() + ", json=" + json)

  	if (dlnaFilesCount.state != NULL && dlnaFilesCount.state < total) {
  		var String lastFile = transform("JSONPATH", "$.lastFile", json)
  		sendBroadcastNotification("Файл скачался " + lastFile) // File loaded
  	}

	postUpdate(dlnaFilesCount, total)
end


rule "ServerInfo"
when 
	System started or
	Time cron "*/30 * * * * ?"
then
	var String jsonTemp = executeCommandLine("/home/pi/temp.sh", 1000)
	
	var DecimalType cpuTemp = new DecimalType(transform("JSONPATH", "$.cpu", jsonTemp))
	postUpdate(serverCpuTemp, cpuTemp)

	var DecimalType gpuTemp = new DecimalType(transform("JSONPATH", "$.gpu", jsonTemp))
	postUpdate(serverGpuTemp, gpuTemp)

    var String jsonIp = executeCommandLine("/home/pi/wget.sh https://api.ipify.org/?format=json", 2000)
    if (jsonIp == "") {
    	jsonIp = '{"ip":"0.0.0.0"}'
	}
	var String ip = transform("JSONPATH", "$.ip", jsonIp)
	postUpdate(serverIp, ip)
end


rule "WhoAtHome"
when 
	System started or
	Item whoAtHomeRepeat received command ON or
	Time cron "0 * * * * ?"
then
	var String curlCmd = "curl -s http://192.168.0.1/userRpm/WlanStationRpm.htm --referer http://192.168.0.1 --cookie Authorization=Basic%20xxxx%3D%3D"
	var String html = executeCommandLine(curlCmd, 2000)
	var Boolean isRepeat = receivedCommand != null
	var String state

	// PAVEL
	state = transform("JS", "mac_online.js", "xx-xx-xx-xx-xx-xx" + html)

	if (state == "BadRequest") {
		if (!isRepeat) {
			logInfo("WhoAtHome", "state=BadRequest, timer created")
			createTimer(now.plusSeconds(10)) [|
				sendCommand(whoAtHomeRepeat, ON)
			]
		}
		else {
			logInfo("WhoAtHome", "state=BadRequest, timer loop detected")
		}
		return false
	}

	if (iPhonePavel.state != state) {
		postUpdate(isAnybodyHome, new DateTimeType())
	}
	postUpdate(iPhonePavel, state)

	// ALINA
	state = transform("JS", "mac_online.js", "xx-xx-xx-xx-xx-xx" + html)
	if (iPhoneAlina.state != state) {
		postUpdate(isAnybodyHome, new DateTimeType())
	}
	postUpdate(iPhoneAlina, state)
end


rule "HomeIsEmpty"
when 
	Time cron "25 */5 * * * ?"
then
	var Boolean isAnybodyHomeBoolean = Phones?.members.filter(s | s.state == "Online").size > 0
	var DateTime isAnybodyHomeDt = new DateTime((isAnybodyHome.state as DateTimeType).calendar.timeInMillis)

	logInfo("HomeIsEmpty", "isAnybodyHomeBoolean = " +  if(isAnybodyHomeBoolean) "true" else "false")
	logInfo("HomeIsEmpty", "isAnybodyHomeDt = " + isAnybodyHomeDt.toString())

	if (isAnybodyHomeBoolean) {
		homeIsEmptyNotificationWasSent = false
	}

	if (!isAnybodyHomeBoolean && isAnybodyHomeDt.plusMinutes(3).isBefore(now)) {
		if (!homeIsEmptyNotificationWasSent) {
			var String time = new DateTimeType().format("%1$tH:%1$tM")
			sendBroadcastNotification("Все ушли из дома " + time) // All is out from home
			homeIsEmptyNotificationWasSent = true
		}

		if (GI.state == ON) sendCommand(GI, OFF)
		if (LgTvState.state == ON) sendCommand(LgTvPower, OFF)
	}
end


rule "Weather"
when
	System started or
	Time cron "10 */2 * * * ?"
then
	if (weatherTemperatureChartPeriod.state == NULL) {
		postUpdate(weatherTemperatureChartPeriod, 1);
	}

	var String curlCmd = "curl -s \"http://site.com/api/sensorsValues?sensors=2176,2177&uuid=xxx&api_key=xxx\""
	var String json = executeCommandLine(curlCmd, 2000)
	var String value

	value = transform("JS", "weather.js", "temperature|" + json)
	postUpdate(weatherTemperature, value)

	postUpdate(weatherTemperatureMax, weatherTemperature.maximumSince(now.toDateMidnight).state)
	postUpdate(weatherTemperatureMin, weatherTemperature.minimumSince(now.toDateMidnight).state)
	
	value = transform("JS", "weather.js", "humidity|" + json)
	postUpdate(weatherHumidity, value)
end

@yphyph01 I have only one file /etc/openhab2/rules/_default.rules

The curlCmd in your weather rule contains the “”.
In my case that character was the case and my string did work without it.
You could check for the rule to be firing only once by removing this string or only those characters, however the curl command won’t work that way.

@opus I’ve changed

var String curlCmd = "curl -s \"http://site.com/api/sensorsValues?sensors=2176,2177&uuid=xxx&api_key=xxx\""

to

var String curlCmd = 'curl -s "http://site.com/api/sensorsValues?sensors=2176,2177&uuid=xxx&api_key=xxx"'

and right now only Debug rule fire twice and only at hh:mm:40, very interesting… Do you have any idea regarding this?

UPDATE:
Checked once again, it’s not fixed my problem. Some rules fire twice or even tree times!

Sorry, but I have no explanation for this. I had the same problem, even with rules fired multiple times. I could pinpoint the cause in my case to that character,. I didn’t find any reason for that, especially because the rule was running normally when saved after starting OH2.

hotfix implemented for Raspberry Pi3:

sudo nano /etc/rc.local

add this

cmd1="sleep 1m"
cmd2="touch /etc/openhab2/rules/_default.rules"
$cmd1 && $cmd2 &

before

exit 0

I have the same problem on current stable build. The main problem is, that even System started event got fired twice on a fresh openhab2 service start.

Same issue.
System started is fired 3 times after reboot

Cron triggered rules are running three times also. And I don’t have any \ in my rule files anymore. That looked like a problem, described in another thread.

I’m in the same position - eliminated string formatting as the potential problem. I only have this issue with cron rules, not any other rules (and I have a lot!)

Try to fix your string formatting and give a feedback here. Because for me this fix didn’t work.

Fixing string formatting did not helped anyone in this thread as I understand.

So how you plan resolve it?

I’ve resolved rules/sitemaps loading multiple times upon edits - sadly had to ditch my text editor (Atom) for one which saves in a different way.

I haven’t been able to resolve cron jobs firing multiple times. Seems to be a bug.

I’m seeing a similar issue using cron and Astro events. Here is my rule (partial):

rule "Set Time of Day"
when
	System started or
	Time cron "0 0 5,8,22,0 * * ? *" or           					//Times:  5:00, 8:00 , 22:00, Midnight
	Channel 'astro:sun:local:rise#event' triggered END or			//Sunrise
	Channel 'astro:sun:local:plus30:rise#event' triggered END or		//Sunrise Delayed
	Channel 'astro:sun:local:minus30:set#event' triggered START or 	//Early Sunset
	Channel 'astro:sun:local:set#event' triggered START	  		//Sunset
then
    // Sleep for just a bit to make sure we are not exactly on the time period boundary
    Thread::sleep(1000)
	logInfo("Time of Day","Set Triggered")

And here is what I’m seeing in my log file, the logInfo repeated twice with the same time stamp and sometimes the rule seems to fire random times as well

2017-02-21 17:11:01.025 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:11:01.025 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:11:01.072 [INFO ] [e.smarthome.model.script.Time of Day] - Current time of day is now EARLYEVENING
2017-02-21 17:11:01.072 [INFO ] [e.smarthome.model.script.Time of Day] - Current time of day is now EARLYEVENING

2017-02-21 17:14:01.028 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:14:01.028 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered

2017-02-21 17:39:01.029 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:39:01.029 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:39:01.089 [INFO ] [e.smarthome.model.script.Time of Day] - Current time of day is now EVENING
2017-02-21 17:39:01.089 [INFO ] [e.smarthome.model.script.Time of Day] - Current time of day is now EVENING

2017-02-21 17:42:01.021 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered
2017-02-21 17:42:01.024 [INFO ] [e.smarthome.model.script.Time of Day] - Set Triggered