Rules not triggered after several rule edits

[DriesA]

Hi,

Sometimes, when I edit a .rules-file, the rules in that file are not triggered anymore. It doesn’t happen after one edit, but when I edit the file like 4/5 times (because of troubleshooting). The only “workaround” I’ve found is to restart OH.

I don’t think it depends on the complexity of the rule. I could simulate it with a rule file (test.rules) that has this rule in it: `rule "test"

when
Item TEST_Trigger changed from OFF to ON then logInfo("test","Test rule triggered - 4th edit") end`

The system allows me to trigger this rule after a first edit. But after a few changes, I can’t get this rule triggered anymore until a restart. I don’t see errors in my log.

I don't think it's related, but I have to mention that I do edit my rules via Notepad++ (Samba share), which means I get these errors: 2017-11-21 19:41:37.089 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-21 19:41:37.092 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'test.rules' is either empty or cannot be parsed correctly! 2017-11-21 19:41:37.259 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'

But I've always had them (also before the problem I'm reporting now).

What I also tried after a .rules-file is frozen: log on via SSH and touch the file. The log shows that the file is being refreshed. But it is not triggered anymore.

In the community, there is one other person reporting the same issue.

I'm running OH 2.2 Snapshot #1094. I've had this problem already for several months. During the first weeks, I assumed it was something I was doing. But that means I can't tell you exactly which release introduced this problem. Sorry for that.

I guess you need more info to troubleshoot this. Let me know what you need.

[triller-telekom]

What I also tried after a .rules-file is frozen: log on via SSH and touch the file. The log shows that the file is being refreshed. But it is not triggered anymore.

Does this problem also happen if you leave out the samba/notepad part? I.e. if you edit the file via vim through ssh several times?

[DriesA]

Hi @triller-telekom ,

Thank you for coming back on this.

I just did some more tests. The first edit was using Samba/Notepad+. After the edit it works fine, The next 4 edits were done using nano. After the 4th modification to test.rules, the rule is not triggered anymore (untill restart).

2017-11-25 11:00:28.143 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:00:28.145 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'test.rules' is either empty or cannot be parsed correctly! 2017-11-25 11:00:28.317 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules' 2017-11-25 11:01:14.495 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered ABC 2017-11-25 11:01:15.496 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered DEF 2017-11-25 11:02:46.466 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:03:07.813 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered DEF 2017-11-25 11:03:08.814 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered GHI 2017-11-25 11:03:28.832 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:03:34.803 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered GHI 2017-11-25 11:03:35.804 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered JKL 2017-11-25 11:04:09.313 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:04:55.176 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:04:55.457 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules'

[DriesA]

I just changed the rule to:

`rule "test"

when
Item TEST_Trigger changed then logInfo("test","Test rule triggered - 4a") Thread::sleep(1000) logInfo("test","Test rule triggered - 4b")
end`

Since someone on the community hinted it would be related to the trigger (Item TEST_Trigger changed from OFF to ON).

All edits are done via Nano. Also here, the 4th edit does not trigger the rule anymore:

2017-11-25 11:11:05.241 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered JKL2 2017-11-25 11:11:06.242 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered MNO2 2017-11-25 11:11:47.969 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:11:52.054 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 1a 2017-11-25 11:11:52.448 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 1a 2017-11-25 11:11:53.056 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 1b 2017-11-25 11:11:53.450 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 1b 2017-11-25 11:12:17.274 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:12:19.986 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 2a 2017-11-25 11:12:20.987 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 2b 2017-11-25 11:12:41.740 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:12:41.964 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules' 2017-11-25 11:12:45.701 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 3a 2017-11-25 11:12:46.702 [INFO ] [.eclipse.smarthome.model.script.test] - Test rule triggered - 3b 2017-11-25 11:13:07.018 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.rules'

[DriesA]

Sorry to provide updates in smaller bits. But I now realized that, when this rule is not triggered anymore, none of my other rules are triggered (also rules in the other .rules file). I didn't notice that before, since I did a reboot to continue working on that particular rule that stopped being triggered.

[TheKorn2]

I've experienced this rule quite a bit, and here are a few more data points to flesh out the problem a bit... (Sorry, no solutions in sight!)

1. This problem existed in openhab 1.x. To wit, I'm still running 1.8, and I get this error often. So it's not something new in 2.x.
2. Samba has nothing to do with this error. For example, I just got this error while restarting openhab where it choked on a file that had a timestamp four days old. (No editors open, OH system has even been rebooted since that time!) Nothing was open in Samba. I'm pretty sure no machines had even connected via Samba when it happened.
3. Multiple touches for the file failed, then eventually cause the rule to reload correctly. Absolutely nothing else was done to the file; no edits, nothing. (i.e. the file was able to be correctly parsed the entire time.) In addition, the file was able to bet cat'd the entire time via a command line.
4. I've experienced it enough that I've actually given up on openhab's rule auto reloading. It fails enough that I can't trust it when editing rules, and have to go tail my log files every change to make sure they reload correctly.
5. filesystem is ext4, no mount options except remount-ro (standard option)

[flaviocosta-net]

@TheKorn2, just to add a detail of what I observed with plain ESH, not with OH: touching the file or otherwise opening and saving it without making any changes to the code usually does not trigger a model reload. I need to actually change something (e.g. put a different label on the sitemap) if I want to make sure the model is actually reloaded.

I don't know if that same behavior applies to rule files and if it is also what we should observe in openHAB (rather than in the ESH framework), but you may want to take this into consideration since this apparently expected behavior may be influencing the analysis/understanding of this issue.

[TheKorn2]

Sorry, I was being sloppy with my language before.

When I say it failed in 3 and 4, what I'm seeing is that openhab is attempting to reload the file every time I touch or modify it, and that behavior is consistent for rules, items, or what-have-you. It's this attempted reload that often fails with a 'file can't be parsed or is empty' reply, and resulting spew onto the log. I'm not having any instances of touching/modifying a file and OH not at least attempting to do something intelligent with the new file. (It's still falling on its face, but it at least tried to run!)

And just to reiterate, the file isn't blank and/or unparseable. When a file fails I'll simply run touch on the file, OH will attempt to re-read the file and then read it correctly. Sometimes it takes a great number of touches (5-10) before it works, but it always works.