Rules still loading/running twice

Hi,

I’m still having issues with rules being loaded/running twice. Cron jobs execute twice in many cases, which seems to be because the rules are loaded twice - I can see this when I edit/save a rules file, as the model is refreshed twice in the logs.

It’s been suggested this is because of errors in a rules file, or particular formatting characters, but I still have the problem if I delete all the content in the rule, e.g. :

// Refresh CPU utilisation every 30 mins, after 59 seconds
rule "Update CPU utilisation"
when
	Time cron "50 0/30 * * * ?"
then
	var String output1
	var String output2
	var String output3
end

Is this a common problem, or something weird with my system? I’m using the release version of OH2.0, but I’ve had this ever since I started with OH2 four months ago.

Dan

Does a reboot change the behavior?

What editor are you using? I encountered one case with a user where their editor was saving a swap file with the same extension as the file (e.g. it would save a .myrulesfile.rules as you edit myrulesfile.rules). Thus you end up with two copies of your rules file being loaded and active at the same time (I don’t remember the editor that did this, it wasn’t vi, vim, pico, or nano).

Thanks, Rich, that’s helpful.

I edit with Atom. It looks like when it saves a file, openHAB registers it having been edited twice (although there is only one file created). Nano doesn’t do this, and neither does geany. It looks like others have experienced this with Atom in the past.

Surprising if this would cause rules to run twice, given that it just seems to be registered by openHAB as two saves of the same file. But if you think the issues are linked then perhaps I have to stop using Atom, which would be a shame…

Dan

I bet that Atom uses a swap file that ends in .rules as opposed to other editors that change the extension (e.g. vim uses .swp). If that is the case then what is happening is openHAB is actually loading two different files, your “real” .rules file and the temporary file created by Atom. But even if it is triggering two file events for every save what might be happening is that OH starts to read the file then gets the second save causing it to load the same file in another thread. As a result the file ends up being loaded twice which probably results in two copies of the rules living in OH.

How irritating - I really like Atom. I tried Sublime Text 3 instead. That had exactly the same problem, but there’s an option to “save via writing to an alternate file, then change its name to the original file”. I switched this to “true” and Sublime Text seems to work fine with OH.

So I’ve now definitely fixed the problem of rules loading multiple times when I edit them. However my cron rules still run multiple times…

My System started event is always triggered twice also.

I also always get these when saving (using the eclipse editor):

2017-02-17 14:00:14.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model ‘zwave.items’
2017-02-17 14:00:14.665 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model ‘zwave.items’

I sometimes also get “duplicate field” messages when this happens:

_2017-02-17 14:00:17.459 [WARN ] [.rule.jvmmodel.RulesJvmModelInferrer] - Duplicate field: ‘MotionSensor_DS’. Ignoring ‘org.eclipse.smarthome.core.library.items.SwitchItem’

I’m not sure if this is related to me saving the files through CIFS/Samba…
When I edited the file with ‘nano’ I also got the problem, but seems to only happen once after I’ve done a save in the eclipse editor. The second attempt with nano produced only one load.

(Running a simple “touch zwave.items” only made it load once regardless)…:confused:

I have the same issue - rules refreshed twice every time I edit them. I’m using vim as my editor.

Doing a touch on the files refreshes them once.

Something that may be related is that my files all live on a NAS and are NFS mounted on my Rpi OH2 server. If I edit these files on a machine other than the OH2 server it doesn’t pick up that they’ve changed and reload them, despite the fact that the last modified timestamp has been updated.

I didn’t have this issue when I was running OH1 so something has changed in the way it detects config file changes.

Indeed something changed. Before OH 1 would poll for updates. That lead to a number of problems. OH 2 uses file events I think to detect changes to files and I suspect NFS and CIFS mounted volumes do not provide these events.

I’ve noticed something similar when trying to tail -f a log file from another machine through a CIFS mount. It won’t follow on the other machine.

I have the same problem. Some of my rules execute twice. I did a full restart, and now I see that most of the rules also load twice…

Is this OK???

2017-12-06 17:17:04.639 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alive.items’
2017-12-06 17:17:12.802 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'esps.items’
2017-12-06 17:17:18.350 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'central.items’
2017-12-06 17:17:37.894 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist’
2017-12-06 17:19:19.851 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'power.rules’
2017-12-06 17:19:39.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'car.rules’
2017-12-06 17:27:45.013 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alive.items’
2017-12-06 17:27:51.188 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'esps.items’
2017-12-06 17:27:56.369 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'central.items’
2017-12-06 17:28:09.281 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist’
2017-12-06 17:29:41.074 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'power.rules’
2017-12-06 17:30:30.802 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'car.rules’
2017-12-06 17:31:39.143 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alive.rules’
2017-12-06 17:31:51.616 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alert.rules’
2017-12-06 17:32:13.244 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'central.rules’
2017-12-06 17:32:35.152 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dnevna.rules’
2017-12-06 17:33:16.525 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ota.rules’
2017-12-06 17:33:37.356 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shades.rules’
2017-12-06 17:33:53.461 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'gate.rules’
2017-12-06 17:36:10.464 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘mysite.sitemap’

Do you notice that the rules the run twice come from the files that load twice? Or is there no correlation?

Hard to be 100% sure… But I would say YES. Because they are not executed twice every time, only sometimes.

This is odd. If you are on the SNAPSHOT, file an issue on the eclipse smarthome repo. If not, you can try upgrading to the snapshot and see if it is still a problem.

No, I am not on a SNAPSHOT… will try to update

Tired of the same flaw, I made some investigations:

  1. Editing in-place (locally, VI) => Loading, Refresh, Refresh
  2. Moving back and forth => Loading
  3. Touch’ing the file => Refresh
  4. Editing with vi -n (no swap file) => Loading, Refresh, Refresh
  5. Cat’ing file into current file => Refresh, Refresh

Boils down the trigger is set to CREATE and MODIFY. Quick search proves this:


I submitted an issue: