Editing the config files causes infinate loop

[marcelrv]

When I run the latest OH2 snapshot and modify one of the config files (e.g. demo.items, demo.things, etc) there seems an infinate loop with processing/refreshing.

The only way to stop this is by closing.
e.g.:
08:09:59.840 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items' 08:09:59.841 DEBUG o.e.s.m.i.i.GenericItemProvider[:147] - Processing binding configs for items from model 'demo.items'08:09:59.842 DEBUG o.e.s.m.i.i.GenericItemProvider[:126] - Read items from model 'demo.items' 08:09:59.844 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.sitemap' 08:09:59.846 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items' 08:09:59.847 DEBUG o.e.s.m.i.i.GenericItemProvider[:147] - Processing binding configs for items from model 'demo.items'08:09:59.847 DEBUG o.e.s.m.i.i.GenericItemProvider[:126] - Read items from model 'demo.items' 08:09:59.850 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.sitemap' 08:09:59.852 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items' 08:09:59.854 DEBUG o.e.s.m.i.i.GenericItemProvider[:147] - Processing binding configs for items from model 'demo.items'08:09:59.854 DEBUG o.e.s.m.i.i.GenericItemProvider[:126] - Read items from model 'demo.items' 08:09:59.857 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.sitemap' 08:09:59.859 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items' 08:09:59.860 DEBUG o.e.s.m.i.i.GenericItemProvider[:147] - Processing binding configs for items from model 'demo.items'08:09:59.860 DEBUG o.e.s.m.i.i.GenericItemProvider[:126] - Read items from model 'demo.items' 08:09:59.863 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.sitemap' 08:09:59.865 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items' 08:09:59.866 DEBUG o.e.s.m.i.i.GenericItemProvider[:147] - Processing binding configs for items from model 'demo.items'08:09:59.866 DEBUG o.e.s.m.i.i.GenericItemProvider[:126] - Read items from model 'demo.items' 08:09:59.868 INFO o.e.s.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.sitemap'

[kaikreuzer]

Hi Marcel, I cannot reproduce this effect. I just tried the latest snapshot from https://openhab.ci.cloudbees.com/job/openHAB2/34/ and it all works nicely when changing demo.items. I am using Mac OSX, on which platform are you testing?

[marcelrv]

Hi Kai,

I'm on Win7. java version "1.7.0_45" Java(TM) SE Runtime Environment (build 1.7.0_45-b18) Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

Steps I take to reproduce the issue:
download build#34, extract both distribution-2.0.0-SNAPSHOT-demo.zip and distribution-2.0.0-SNAPSHOT-distribution.zip. Run start_debug.bat
edit demo.items (e.g. add a space or linefeed) and save.
Loop begins.

1 thing I noticed, while it is in the loop, when I replace the files (overwrite it) the loop stops e.g. with the one from the zip, or one saved earlier. I don't quite understand why, So it does not seem to be related to any error in the file itself. Also I played with Unix vs DOS format linefeeds and that also did not influence things.

[kaikreuzer]

Seems to be related to Windows then - I will try to investigate this on a Windows machine next week.

[marcelrv]

Hi Kai,
Indeed, seems to be windows related. When I run the same on linux it is without errors.

[kaikreuzer]

Marcel, I retested this on Windows 8 with

java version "1.7.0_25"
Java(TM) SE Runtime Environment (build 1.7.0_25-b17)
Java HotSpot(TM) Client VM (build 23.25-b01, mixed mode, sharing)

and it works nicely. May I ask you to retest if the problem has disappeared with the alpha release for you as well?

[BnY]

I had the same issue several times now. I cannot guarantee the root cause is the same though. With me the rootcause was in the hidden characters for EOL / EOF which windows uses. (I'm not into the text encoding stuff / don't want to be into it :))

In the past I noticed when editing files through notepad++ on windows, I got into the endless loop when I loaded them after a transfer with SCP. Then I "worked around" the issue by just creating new files on the Raspberry Pi (that's my archlinux config running openhab) using nano. All went fine for the passed months.

Somehow last week "something" triggered the endless loop again. Since I don't recall editing a file in windows, I thought this must have a different rootcause. So I downloaded openhab 1.6.0 just an hour ago, but the issue persists as I transfer my config files from one dir to the new install.
Logging:

1970-01-01 01:15:25.861 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:15:35.984 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:15:46.278 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:15:56.422 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:16:06.531 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:16:16.662 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'
1970-01-01 01:16:26.764 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'zwave.items'

Now I opened one of the "items files" again using VI and see again strange EOL characters. Example:

Group   Alles^M
Group   Woonkamer       (Alles) ^M
Group   Keuken  (Alles) ^M
Group   Verlichting     (Alles) ^M
Group   Hal (Alles)^M
^M
String  VoiceCommand^M
Switch  ItemLampDressoir "Lamp dressoir" (Woonkamer,Verlichting) { zwave="2:command=switch_binary" }^M

EDIT: The characters are not visible in nano! I removed the special characters with vi and the problem is immediately gone.

Hope it helps...

[BnY]

Now I reverted to the 1.5.0 config because Z-Wave seems to be broken in the latest repo. I see the problem again even when I do not have the ^M endings in the file. It seems like it's related to the creation date of the file. I have to trouble getting the correct date and time from a NTP server at startup of Archlinux.

All the files the system starts "refresing" have a creation date which is in the future. As soon as I open it and save it. It stops refreshing the model...

Just to give you all info. Don't want to send someone into the wrong path :)

-rw-r--r-- 1 root root  261 Jan  1 01:14 VoiceCommands.ignore
-rw-r--r-- 1 root root 1145 Jan  1 01:35 Heating.rules
-rw-r--r-- 1 root root  228 Jan  1 01:36 System.rules
-rw-r--r-- 1 root root  225 Jun 16  2014 README
-rw-r--r-- 1 root root  164 Nov 11  2014 Security.rules
[root@alarmpi rules]# date
Thu Jan  1 01:37:39 CET 1970

EDIT: Confirmed. Re-saved all the config files and my system is operational again. Heating is essential in the winter ;)

[kaikreuzer]

All the files the system starts "refresing" have a creation date which is in the future.

Thanks for your analysis! This is very interesting and a date in the future might indeed explain the effect. How does it happen that the date is in the future? Simply by having non-sychronized environments?

[BnY]

Yes. I didn't setup ntp in a persistent manner yet on archLinux. Therefore after I reboot my raspberry ends up at epoch timestart 1-1-1970...

[kaikreuzer]

That explains :-)
So not sure if there is anything to do about that - shall we close this issue?

[marcelrv]

Hi Kai,

I did indeed some more investigation. The source of the issue comes from the AbstractWatchQueueReader. In there the event is triggered many times without me touching the file actually before it was just when I edited a file, now it just continues to loop on
18:21:48.647 DEBUG o.e.s.c.d.i.ConfigDispatcher[:236] - Processing config file 'runtime.cfg'
18:21:48.803 DEBUG o.e.s.c.d.i.ConfigDispatcher[:236] - Processing config file 'logging.cfg'

I did not really find any cause of this behavior, the code looks straight from the java documentation.
Maybe it is some strange behavior of my virus scanner or something. I don't see this on my other laptop.

[kaikreuzer]

@marcelrv So in your case it is not due to a timestamp in the future?

[marcelrv]

No, indeed. my laptop is configured with normal time settings incl ntp updates as far as I know.
Is there a setting that I can stop the scanning fully, as this renders the laptop unusable with OH

[kaikreuzer]

No, afaik there is no such option. Feel free to enter a feature request for this (best directly in ESH https://bugs.eclipse.org/bugs/buglist.cgi?product=SmartHome&component=Core).

[marcelrv]

Quick update on this older issue (no solution though :( )

For now I believe the rootcause of the issue is the interaction of OH2 with the file and with the installed virus scanner (McAfee On-Access scan). I believe OH causes the virusscanner to be triggered and somehow that triggers again the processing in OH

21:11:48.963 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'logging.cfg'
21:11:48.971 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'runtime.cfg'
21:11:48.979 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'logging.cfg'
21:11:48.988 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'runtime.cfg'
21:11:48.996 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'logging.cfg'
21:11:49.004 [DEBUG] [.c.d.internal.ConfigDispatcher:222 ] - Processing config file 'runtime.cfg'

Issue made in the ESH list https://bugs.eclipse.org/bugs/show_bug.cgi?id=465285