Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OH3.0.0 stable: DSL Rules are removed after reload of other .rules and .items files with same file prefix #2022

Closed
petrows opened this issue Dec 28, 2020 · 17 comments · Fixed by #2077
Closed

OH3.0.0 stable: DSL Rules are removed after reload of other .rules and .items files with same file prefix #2022

petrows opened this issue Dec 28, 2020 · 17 comments · Fixed by #2077

Comments

@petrows
Copy link

petrows commented Dec 28, 2020 •
edited

I have issue similar to #1829 , but with different behavior:

My setup

Problems

  • Reload of rules DSL file may remove all other rules from other files matching the pattern name-XXX.rules, e.g. reloading of light.rules file also removes rules from files light-astrocolor.rules and light-sunrize.rules
  • Reload of items files with same name as rules files may remove rules from this file, e.g. reloading of heating.items removes all rules from heating.rules.

Examples how i can reproduce this:

Just after start, all rules are loaded (56 rules total):

openhab> openhab:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS         
----------------------------------------------------------------------------------------------------
1      common-1                            System started                      IDLE           
2      common-2                            Presence master                     IDLE           
3      common-3                            Waterleak                           IDLE           
4      common-4                            Test devices responce time          IDLE           
5      common-5                            Fridge start at friday              IDLE           
6      common-6                            Fridge stop at sunday               IDLE           
7      gen-1                               Marina Desktop light apply color on ON IDLE           
8      gen-2                               Treppe Up light apply color on ON   IDLE           
9      gen-3                               Treppe Down light apply color on ON IDLE           
10     gen-4                               Petro Desktop light apply color on ON IDLE           
11     heating-1                           Heating safe switch                 IDLE           
12     heating-2                           Heating NIGHT                       IDLE           
13     heating-3                           Heating MORNING                     IDLE           
14     heating-4                           Heating DAY                         IDLE           
15     heating-5                           Heating EVENING                     IDLE           
16     heating-6                           Auto command                        IDLE           
17     heating-7                           Heating NS boost switch             IDLE           
18     heating-8                           Heating presense switch             IDLE           
19     heating-9                           Heating master switch               IDLE           
20     light-1                             Ligth master mode                   IDLE           
21     light-10                            KG Lager light changed              IDLE           
22     light-2                             Ligth master mode status            IDLE           
23     light-3                             Light safe switch                   IDLE           
24     light-4                             KG safe switch                      IDLE           
25     light-5                             NS follow table power               IDLE           
26     light-6                             BZ force both lights work together  IDLE           
27     light-7                             Sunset Rule                         IDLE
28     light-8                             Petro desktop power                 IDLE
29     light-9                             KG Treppe light changed             IDLE
30     light-astrocolor-1                  Astrocolor: Reset lamps state       IDLE
31     light-astrocolor-2                  Astrocolor: Set lamps color according to daytime IDLE
32     light-sunrise-1                     Sinrise emulation auto off          IDLE
33     light-sunrise-2                     Sinrise emulation start             IDLE
34     motion-1                            KG Motion detect treppe             IDLE
35     motion-2                            KG Motion detect Lager              IDLE
36     notification-1                      Online notify                       IDLE
37     notification-2                      LowBattery notify                   IDLE
38     notification-3                      Sunset Rule 2                       IDLE
39     remote-1                            Spiegel control SW                  IDLE
40     remote-2                            House verlassen SW                  IDLE
41     remote-3                            KG Ladder BOTTOM btn                IDLE
42     remote-4                            KG Ladder UP btn                    IDLE
43     remote-5                            KG Lager btn                        IDLE
44     remote-6                            Petro desktop remote                IDLE
45     remote-7                            Marina desktop remote               IDLE
46     remote-8                            SZ remote sw                        IDLE
47     remote-9                            KU Arbeitlicht SW                   IDLE
48     washmachine-1                       Washmachine power                   IDLE
49     yeelight-1                          Yeelight 1 power                    IDLE
50     yeelight-2                          Yeelight 1 brightness               IDLE
51     yeelight-3                          Yeelight 1 color temp               IDLE
52     yeelight-4                          Yeelight 1 color                    IDLE
53     yeelight-5                          mi-lamp-2.pws power                 IDLE
54     yeelight-6                          mi-lamp-2.pws brightness            IDLE
55     yeelight-7                          mi-lamp-2.pws color temp            IDLE
56     zigbee-1                            Coordinator log                     IDLE
----------------------------------------------------------------------------------------------------

In ~10 seconds 4 rules are removed (52 rules left). Removed:

openhab> openhab:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS
----------------------------------------------------------------------------------------------------
1      common-1                            System started                      IDLE
2      common-2                            Presence master                     IDLE
3      common-3                            Waterleak                           IDLE
4      common-4                            Test devices responce time          IDLE
5      common-5                            Fridge start at friday              IDLE
6      common-6                            Fridge stop at sunday               IDLE
7      gen-1                               Marina Desktop light apply color on ON IDLE
8      gen-2                               Treppe Up light apply color on ON   IDLE
9      gen-3                               Treppe Down light apply color on ON IDLE
10     gen-4                               Petro Desktop light apply color on ON IDLE
11     heating-1                           Heating safe switch                 IDLE
12     heating-2                           Heating NIGHT                       IDLE
13     heating-3                           Heating MORNING                     IDLE
14     heating-4                           Heating DAY                         IDLE
15     heating-5                           Heating EVENING                     IDLE
16     heating-6                           Auto command                        IDLE
17     heating-7                           Heating NS boost switch             IDLE
18     heating-8                           Heating presense switch             IDLE
19     heating-9                           Heating master switch               IDLE
20     light-1                             Ligth master mode                   IDLE
21     light-10                            KG Lager light changed              IDLE
22     light-2                             Ligth master mode status            IDLE
23     light-3                             Light safe switch                   IDLE
24     light-4                             KG safe switch                      IDLE
25     light-5                             NS follow table power               IDLE
26     light-6                             BZ force both lights work together  IDLE
27     light-7                             Sunset Rule                         IDLE
28     light-8                             Petro desktop power                 IDLE
29     light-9                             KG Treppe light changed             IDLE
30     motion-1                            KG Motion detect treppe             IDLE
31     motion-2                            KG Motion detect Lager              IDLE
32     notification-1                      Online notify                       IDLE
33     notification-2                      LowBattery notify                   IDLE
34     notification-3                      Sunset Rule 2                       IDLE
35     remote-1                            Spiegel control SW                  IDLE
36     remote-2                            House verlassen SW                  IDLE
37     remote-3                            KG Ladder BOTTOM btn                IDLE
38     remote-4                            KG Ladder UP btn                    IDLE
39     remote-5                            KG Lager btn                        IDLE
40     remote-6                            Petro desktop remote                IDLE
41     remote-7                            Marina desktop remote               IDLE
42     remote-8                            SZ remote sw                        IDLE
43     remote-9                            KU Arbeitlicht SW                   IDLE
44     washmachine-1                       Washmachine power                   IDLE
45     yeelight-1                          Yeelight 1 power                    IDLE
46     yeelight-2                          Yeelight 1 brightness               IDLE
47     yeelight-3                          Yeelight 1 color temp               IDLE
48     yeelight-4                          Yeelight 1 color                    IDLE
49     yeelight-5                          mi-lamp-2.pws power                 IDLE
50     yeelight-6                          mi-lamp-2.pws brightness            IDLE
51     yeelight-7                          mi-lamp-2.pws color temp            IDLE
52     zigbee-1                            Coordinator log                     IDLE
----------------------------------------------------------------------------------------------------

If i will update removed file "light-astrocolor.rules" with white space change:

[INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'light-astrocolor.rules'

Rules return back to list (only from this file - nr 30 and 31):

openhab> openhab:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS
----------------------------------------------------------------------------------------------------
1      common-1                            System started                      IDLE
2      common-2                            Presence master                     IDLE
3      common-3                            Waterleak                           IDLE
4      common-4                            Test devices responce time          IDLE
5      common-5                            Fridge start at friday              IDLE
6      common-6                            Fridge stop at sunday               IDLE
7      gen-1                               Marina Desktop light apply color on ON IDLE
8      gen-2                               Treppe Up light apply color on ON   IDLE
9      gen-3                               Treppe Down light apply color on ON IDLE
10     gen-4                               Petro Desktop light apply color on ON IDLE
11     heating-1                           Heating safe switch                 IDLE
12     heating-2                           Heating NIGHT                       IDLE
13     heating-3                           Heating MORNING                     IDLE
14     heating-4                           Heating DAY                         IDLE
15     heating-5                           Heating EVENING                     IDLE
16     heating-6                           Auto command                        IDLE
17     heating-7                           Heating NS boost switch             IDLE
18     heating-8                           Heating presense switch             IDLE
19     heating-9                           Heating master switch               IDLE
20     light-1                             Ligth master mode                   IDLE
21     light-10                            KG Lager light changed              IDLE
22     light-2                             Ligth master mode status            IDLE
23     light-3                             Light safe switch                   IDLE
24     light-4                             KG safe switch                      IDLE
25     light-5                             NS follow table power               IDLE
26     light-6                             BZ force both lights work together  IDLE
27     light-7                             Sunset Rule                         IDLE
28     light-8                             Petro desktop power                 IDLE
29     light-9                             KG Treppe light changed             IDLE
30     light-astrocolor-1                  Astrocolor: Reset lamps state       IDLE
31     light-astrocolor-2                  Astrocolor: Set lamps color according to daytime IDLE
32     motion-1                            KG Motion detect treppe             IDLE
33     motion-2                            KG Motion detect Lager              IDLE
34     notification-1                      Online notify                       IDLE
35     notification-2                      LowBattery notify                   IDLE
36     notification-3                      Sunset Rule 2                       IDLE
37     remote-1                            Spiegel control SW                  IDLE
38     remote-2                            House verlassen SW                  IDLE
39     remote-3                            KG Ladder BOTTOM btn                IDLE
40     remote-4                            KG Ladder UP btn                    IDLE
41     remote-5                            KG Lager btn                        IDLE
42     remote-6                            Petro desktop remote                IDLE
43     remote-7                            Marina desktop remote               IDLE
44     remote-8                            SZ remote sw                        IDLE
45     remote-9                            KU Arbeitlicht SW                   IDLE
46     washmachine-1                       Washmachine power                   IDLE
47     yeelight-1                          Yeelight 1 power                    IDLE
48     yeelight-2                          Yeelight 1 brightness               IDLE
49     yeelight-3                          Yeelight 1 color temp               IDLE
50     yeelight-4                          Yeelight 1 color                    IDLE
51     yeelight-5                          mi-lamp-2.pws power                 IDLE
52     yeelight-6                          mi-lamp-2.pws brightness            IDLE
53     yeelight-7                          mi-lamp-2.pws color temp            IDLE
54     zigbee-1                            Coordinator log                     IDLE
----------------------------------------------------------------------------------------------------

And, they are functional (reacting on command openhab:things trigger astro:sun:home:set#event START) with proper log messages.

Here is the interesting part!

Updating of file light removes light-astrocolor again:

[INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'light.rules'
openhab> openhab:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS
----------------------------------------------------------------------------------------------------
1      common-1                            System started                      IDLE
2      common-2                            Presence master                     IDLE
3      common-3                            Waterleak                           IDLE
4      common-4                            Test devices responce time          IDLE
5      common-5                            Fridge start at friday              IDLE
6      common-6                            Fridge stop at sunday               IDLE
7      gen-1                               Marina Desktop light apply color on ON IDLE
8      gen-2                               Treppe Up light apply color on ON   IDLE
9      gen-3                               Treppe Down light apply color on ON IDLE
10     gen-4                               Petro Desktop light apply color on ON IDLE
11     heating-1                           Heating safe switch                 IDLE
12     heating-2                           Heating NIGHT                       IDLE
13     heating-3                           Heating MORNING                     IDLE
14     heating-4                           Heating DAY                         IDLE
15     heating-5                           Heating EVENING                     IDLE
16     heating-6                           Auto command                        IDLE
17     heating-7                           Heating NS boost switch             IDLE
18     heating-8                           Heating presense switch             IDLE
19     heating-9                           Heating master switch               IDLE
20     light-1                             Ligth master mode                   IDLE
21     light-10                            KG Lager light changed              IDLE
22     light-2                             Ligth master mode status            IDLE
23     light-3                             Light safe switch                   IDLE
24     light-4                             KG safe switch                      IDLE
25     light-5                             NS follow table power               IDLE
26     light-6                             BZ force both lights work together  IDLE
27     light-7                             Sunset Rule                         IDLE
28     light-8                             Petro desktop power                 IDLE
29     light-9                             KG Treppe light changed             IDLE
30     motion-1                            KG Motion detect treppe             IDLE
31     motion-2                            KG Motion detect Lager              IDLE
32     notification-1                      Online notify                       IDLE
33     notification-2                      LowBattery notify                   IDLE
34     notification-3                      Sunset Rule 2                       IDLE
35     remote-1                            Spiegel control SW                  IDLE
36     remote-2                            House verlassen SW                  IDLE
37     remote-3                            KG Ladder BOTTOM btn                IDLE
38     remote-4                            KG Ladder UP btn                    IDLE
39     remote-5                            KG Lager btn                        IDLE
40     remote-6                            Petro desktop remote                IDLE
41     remote-7                            Marina desktop remote               IDLE
42     remote-8                            SZ remote sw                        IDLE
43     remote-9                            KU Arbeitlicht SW                   IDLE
44     washmachine-1                       Washmachine power                   IDLE
45     yeelight-1                          Yeelight 1 power                    IDLE
46     yeelight-2                          Yeelight 1 brightness               IDLE
47     yeelight-3                          Yeelight 1 color temp               IDLE
48     yeelight-4                          Yeelight 1 color                    IDLE
49     yeelight-5                          mi-lamp-2.pws power                 IDLE
50     yeelight-6                          mi-lamp-2.pws brightness            IDLE
51     yeelight-7                          mi-lamp-2.pws color temp            IDLE
52     zigbee-1                            Coordinator log                     IDLE
----------------------------------------------------------------------------------------------------

Rules from light-astrocolor disappears again. Also, they are not reacting on trigger anymore.

Please, let me know, if i can help you with some logs or something.
@petrows petrows changed the title OH3.0.0 stable: DSL Rules are broken after reload of other .rules files OH3.0.0 stable: DSL Rules are broken after reload of other .rules files with same file prefix Dec 28, 2020
petrows added a commit to petrows/smarthome-openhab that referenced this issue Dec 28, 2020
@petrows
Fix rules isse by renaming files and clear conflicting Rules DSL ids
56235c4 
This probably workarounds and issue from openhab/openhab-core#2022
@petrows
Copy link
Author

petrows commented Dec 28, 2020

Looks like this issue is related with naming and rules ID's. I have renamed light-astrocolor to astrocolor and light-sunrize to sunrize and i can't reproduce issue anymore. Looks like there were conflicting ID's from light-something and light-N from auto-generated ID's provided by file scanner.

@petrows
Copy link
Author

petrows commented Dec 28, 2020

I also had some spontaneous drops rules from light.rules file, but i can't reproduce it easily. Anyway, it looks related to this issue. Will update issue if something changed.

@petrows petrows changed the title OH3.0.0 stable: DSL Rules are broken after reload of other .rules files with same file prefix OH3.0.0 stable: DSL Rules are removed after reload of other .rules files with same file prefix Dec 29, 2020
@petrows
Copy link
Author

petrows commented Dec 29, 2020

Next day: all DSL rules from light.rules spontaneously removed:

openhab> openhab:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS
----------------------------------------------------------------------------------------------------
1      astrocolor-1                        Astrocolor: Reset lamps state       IDLE
2      astrocolor-2                        Astrocolor: Set lamps color according to daytime IDLE
3      common-1                            System started                      IDLE
4      common-2                            Presence master                     IDLE
5      common-3                            Waterleak                           IDLE
6      common-4                            Test devices responce time          IDLE
7      common-5                            Fridge start at friday              IDLE
8      common-6                            Fridge stop at sunday               IDLE
9      gen-1                               Marina Desktop light apply color on ON IDLE
10     gen-2                               Treppe Up light apply color on ON   IDLE
11     gen-3                               Treppe Down light apply color on ON IDLE
12     gen-4                               Petro Desktop light apply color on ON IDLE
13     heating-1                           Heating safe switch                 IDLE
14     heating-2                           Heating NIGHT                       IDLE
15     heating-3                           Heating MORNING                     IDLE
16     heating-4                           Heating DAY                         IDLE
17     heating-5                           Heating EVENING                     IDLE
18     heating-6                           Auto command                        IDLE
19     heating-7                           Heating NS boost switch             IDLE
20     heating-8                           Heating presense switch             IDLE
21     heating-9                           Heating master switch               IDLE
22     motion-1                            KG Motion detect treppe             IDLE
23     motion-2                            KG Motion detect Lager              IDLE
24     notification-1                      Online notify                       IDLE
25     notification-2                      LowBattery notify                   IDLE
26     remote-1                            Spiegel control SW                  IDLE
27     remote-2                            House verlassen SW                  IDLE
28     remote-3                            KG Ladder BOTTOM btn                IDLE
29     remote-4                            KG Ladder UP btn                    IDLE
30     remote-5                            KG Lager btn                        IDLE
31     remote-6                            Petro desktop remote                IDLE
32     remote-7                            Marina desktop remote               IDLE
33     remote-8                            SZ remote sw                        IDLE
34     remote-9                            KU Arbeitlicht SW                   IDLE
35     sunrise-1                           Sinrise emulation auto off          IDLE
36     sunrise-2                           Sinrise emulation start             IDLE
37     washmachine-1                       Washmachine power                   IDLE
38     yeelight-1                          Yeelight 1 power                    IDLE
39     yeelight-2                          Yeelight 1 brightness               IDLE
40     yeelight-3                          Yeelight 1 color temp               IDLE
41     yeelight-4                          Yeelight 1 color                    IDLE
42     yeelight-5                          mi-lamp-2.pws power                 IDLE
43     yeelight-6                          mi-lamp-2.pws brightness            IDLE
44     yeelight-7                          mi-lamp-2.pws color temp            IDLE
45     zigbee-1                            Coordinator log                     IDLE
----------------------------------------------------------------------------------------------------

Latest log message related to any of light rules was at 15:11 (now it is 19:40). At 15:25 i have added one new group and moved item there:

2020-12-29 15:25:31.706 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'light.items'

Also, reproduced issue on other files set. If i change heating.items file, heating rules are also removed. And light rules are returned back without any reloading log message.

I will enable debug logging and see.

@petrows
Copy link
Author

petrows commented Dec 29, 2020 •
edited

Debug log: renamed file heating2.items to heating.items, it causes removal of all heating rules.

Debug log:

19:55:49.723 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'openhab:automation listRules'
19:55:49.726 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: 'openhab:automation listRules' returned 'null'
19:55:57.323 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@672e0fd8{/192.168.80.27:41372<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1af7984c[p=HttpParser{s=END,0 of -1},g=HttpGenerator@706bca34{s=COMMITTED}]=>HttpChannelOverHttp@3167f134{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=2010012} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
19:55:57.323 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@672e0fd8{/192.168.80.27:41372<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1af7984c[p=HttpParser{s=END,0 of -1},g=HttpGenerator@706bca34{s=COMMITTED}]=>HttpChannelOverHttp@3167f134{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=2010013} idle timeout expired
19:55:57.324 [DEBUG] [org.eclipse.jetty.io.FillInterest    ] - onFail FillInterest@132b4699{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) [bundleFile:9.4.20.v20190813]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
19:55:57.326 [DEBUG] [org.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@672e0fd8{/192.168.80.27:41372<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30003/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1af7984c[p=HttpParser{s=END,0 of -1},g=HttpGenerator@706bca34{s=COMMITTED}]=>HttpChannelOverHttp@3167f134{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=2010016}
19:56:01.609 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@2d96242c{/127.0.0.1:39218<->/127.0.0.1:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@30e0c279[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1e9a3115{s=COMMITTED}]=>HttpChannelOverHttp@19a755c{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/events/states,age=29190181} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
19:56:01.610 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@2d96242c{/127.0.0.1:39218<->/127.0.0.1:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@30e0c279[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1e9a3115{s=COMMITTED}]=>HttpChannelOverHttp@19a755c{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/events/states,age=29190182} idle timeout expired
19:56:01.611 [DEBUG] [org.eclipse.jetty.io.FillInterest    ] - onFail FillInterest@660ad884{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) [bundleFile:9.4.20.v20190813]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
19:56:01.612 [DEBUG] [org.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@2d96242c{/127.0.0.1:39218<->/127.0.0.1:8080,OPEN,fill=-,flush=-,to=30002/30000}{io=0/0,kio=0,kro=1}->HttpConnection@30e0c279[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1e9a3115{s=COMMITTED}]=>HttpChannelOverHttp@19a755c{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/events/states,age=29190184}
19:56:02.576 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=-,to=20451/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2136895} idle timeout check, elapsed: 20451 ms, remaining: 9549 ms
19:56:07.368 [DEBUG] [ipse.xtext.util.OnChangeEvictingCache] - Clear 57 cache entries for resource heating2.items after 1903 hits and 57 misses (quota: 97%)
19:56:07.369 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'heating.items'
19:56:07.371 [DEBUG] [ser.antlr.AbstractInternalAntlrParser] - Parsing took: 0 ms
19:56:07.371 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
19:56:07.372 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - doLinkModel took: 1ms
19:56:07.372 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
19:56:07.374 [DEBUG] [ipse.xtext.util.OnChangeEvictingCache] - Clear 57 cache entries for resource tmp_heating.items after 99 hits and 57 misses (quota: 63%)
19:56:07.376 [DEBUG] [ser.antlr.AbstractInternalAntlrParser] - Parsing took: 1 ms
19:56:07.376 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
19:56:07.377 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - doLinkModel took: 1ms
19:56:07.377 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
19:56:07.379 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_temp_auto' changed from NULL to 23.0
19:56:07.416 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.422 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.434 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.server.AsyncContextState$1@67a40c11 startThread=false
19:56:07.434 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.server.AsyncContextState$1@67a40c11 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.438 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=294,c=32768,r=294]={<<<event: event\ndata...Id":"control2"}>>>:"control2"}"Chri...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.478 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_boost' changed from NULL to OFF
19:56:07.478 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@40e55fd0] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
19:56:07.480 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_kg_lbatt' changed from NULL to OFF
19:56:07.481 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 294 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=25355/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141800}
19:56:07.490 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=294 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.490 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@40e55fd0] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
19:56:07.491 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: event\ndata: ...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.496 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@111fa08e] generate: FLUSH (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
19:56:07.498 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 2 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=7/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141816}
19:56:07.501 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=2 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.496 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.499 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_kg_mode' changed from NULL to MANUAL
19:56:07.492 [DEBUG] [ipse.xtext.util.OnChangeEvictingCache] - Clear 58 cache entries for resource heating2.items after 282 hits and 58 misses (quota: 82%)
19:56:07.504 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_kg_sensor' changed from NULL to 23.5
19:56:07.505 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_all' changed from 15.8 to 14.0 through hz_kg_set
19:56:07.506 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_auto' changed from 18.5 to 23.0 through hz_kg_set
19:56:07.507 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_kg_set' changed from NULL to 23.0
19:56:07.508 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_kg_valve' changed from NULL to 54.0
19:56:07.510 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_valve' changed from 21.8 to 27.0 through hz_kg_valve
19:56:07.502 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@111fa08e] generate: DONE (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
19:56:07.511 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.server.AsyncContextState$1@67a40c11 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.507 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.522 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.server.AsyncContextState$1@501aabd9 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.522 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ku_lbatt' changed from NULL to OFF
19:56:07.522 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.server.AsyncContextState$1@501aabd9 startThread=false
19:56:07.522 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=294,c=32768,r=294]={<<<event: event\ndata...Id":"control2"}>>>:"control2"}"Chri...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.528 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@3505c60f] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
19:56:07.529 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 294 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=27/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141848}
19:56:07.530 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=294 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.530 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@3505c60f] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
19:56:07.531 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: event\ndata: ...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.532 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@68f76053] generate: FLUSH (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
19:56:07.533 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 2 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141852}
19:56:07.530 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ku_mode' changed from NULL to MANUAL
19:56:07.534 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=2 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.535 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ku_sensor' changed from NULL to 24.6
19:56:07.535 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@68f76053] generate: DONE (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
19:56:07.537 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ku_set' changed from NULL to 23.0
19:56:07.538 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.server.AsyncContextState$1@501aabd9 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.537 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.538 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_all' changed from 14.0 to 17.0 through hz_ku_set
19:56:07.539 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ku_valve' changed from NULL to 34.0
19:56:07.540 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_valve' changed from 27.0 to 29.3 through hz_ku_valve
19:56:07.545 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.566 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.server.AsyncContextState$1@341126f1 startThread=false
19:56:07.566 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.server.AsyncContextState$1@341126f1 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.574 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.578 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_fs_lbatt' changed from NULL to OFF
19:56:07.579 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_fs_mode' changed from NULL to MANUAL
19:56:07.581 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_fs_sensor' changed from NULL to 24.7
19:56:07.582 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=294,c=32768,r=294]={<<<event: event\ndata...Id":"control2"}>>>:"control2"}"Chri...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.584 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@7f8c3a1d] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
19:56:07.586 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_fs_set' changed from NULL to 23.0
19:56:07.587 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_all' changed from 17.0 to 18.5 through hz_fs_set
19:56:07.588 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_fs_valve' changed from NULL to 21.0
19:56:07.586 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 294 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=51/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141905}
19:56:07.592 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_valve' changed from 29.3 to 27.3 through hz_fs_valve
19:56:07.590 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=294 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.595 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@7f8c3a1d] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
19:56:07.596 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: event\ndata: ...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.597 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_lbatt' changed from NULL to OFF
19:56:07.598 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@69a7a65] generate: FLUSH (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
19:56:07.599 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 2 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=8/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141918}
19:56:07.600 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=2 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.602 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@69a7a65] generate: DONE (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
19:56:07.604 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_mode' changed from NULL to MANUAL
19:56:07.604 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=294,c=32768,r=294]={<<<event: event\ndata...Id":"control2"}>>>:"control2"}"Chri...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.606 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_sensor' changed from NULL to 25.9
19:56:07.608 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@574155f9] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
19:56:07.609 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_set' changed from NULL to 5.0
19:56:07.611 [DEBUG] [ser.antlr.AbstractInternalAntlrParser] - Parsing took: 2 ms
19:56:07.610 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_all' changed from 18.5 to 15.8 through hz_ns_set
19:56:07.613 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_auto' changed from 23.0 to 18.5 through hz_ns_set
19:56:07.614 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
19:56:07.615 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - doLinkModel took: 1ms
19:56:07.615 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
19:56:07.612 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 294 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=11/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141931}
19:56:07.617 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=294 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.618 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@574155f9] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
19:56:07.618 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_valve' changed from NULL to 0.0
19:56:07.619 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_valve' changed from 27.3 to 21.8 through hz_ns_valve
19:56:07.619 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: event\ndata: ...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:07.620 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@589f6260] generate: FLUSH (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
19:56:07.623 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 2 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=5/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2141942}
19:56:07.623 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=2 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:07.624 [DEBUG] [text.validation.ResourceValidatorImpl] - Syntax check OK! Resource: file:///openhab/conf/items/heating.items
19:56:07.622 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.625 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@589f6260] generate: DONE (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
19:56:07.625 [DEBUG] [text.validation.ResourceValidatorImpl] - Syntax check OK! Resource: file:///openhab/conf/items/heating.items
19:56:07.626 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.server.AsyncContextState$1@341126f1 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:07.644 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.649 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.692 [DEBUG] [org.apache.felix.configadmin         ] - getConfiguration(pid=org.openhab.addons)
19:56:07.693 [DEBUG] [org.apache.felix.configadmin         ] - Found cached configuration org.openhab.addons bound to mvn:org.openhab.core.bundles/org.openhab.core.karaf/3.0.0
19:56:07.745 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.749 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.778 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.783 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.907 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.911 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.923 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.926 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.947 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.950 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.961 [DEBUG] [xt.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Number'
19:56:07.965 [DEBUG] [xt.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Number' result: Number
19:56:07.973 [INFO ] [org.openhab.core.model.script.heating] - Auto temp -> 23.0
19:56:07.973 [INFO ] [org.openhab.core.model.script.heating] - Heating NS boost -> OFF
19:56:07.974 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'g_hz_auto' received command 23.0
19:56:07.975 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'hz_kg_set' received command 23.0
19:56:07.975 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'hz_ku_set' received command 23.0
19:56:07.976 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'hz_fs_set' received command 23.0
19:56:07.976 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'hz_ns_set' received command 23.0
19:56:07.978 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'ns_boost_power_sw' received command OFF
19:56:07.978 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'hz_ns_mode' received command MANUAL
19:56:07.983 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'ns_boost_power_sw' predicted to become OFF
19:56:07.984 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'hz_ns_set' changed from 5.0 to 23.0
19:56:07.985 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_all' changed from 15.8 to 19.4 through hz_ku_set
19:56:07.985 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_hz_auto' changed from 18.5 to 23.0 through hz_ku_set
19:56:08.003 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.server.AsyncContextState$1@1b1f9676 startThread=false
19:56:08.003 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.server.AsyncContextState$1@1b1f9676 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:08.004 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=294,c=32768,r=294]={<<<event: event\ndata...Id":"control2"}>>>:"control2"}"Chri...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:08.004 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@23059555] generate: FLUSH (null,[p=0,l=294,c=32768,r=294],false)@COMMITTED
19:56:08.007 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 294 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=382/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2142326}
19:56:08.008 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=294 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:08.008 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@23059555] generate: DONE (null,[p=294,l=294,c=32768,r=0],false)@COMMITTED
19:56:08.009 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@58fad0f5[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: event\ndata: ...itch_battery","} complete=false committing=false callback=Blocker@9cb0386{null}
19:56:08.009 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@6b6ee816] generate: FLUSH (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
19:56:08.010 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 2 SocketChannelEndPoint@5e2f3af0{/127.0.0.1:35238<->/127.0.0.1:8080,OPEN,fill=-,flush=W,to=2/30000}{io=0/0,kio=0,kro=1}->HttpConnection@73c07c62[p=HttpParser{s=END,0 of -1},g=HttpGenerator@22c686af{s=COMMITTED}]=>HttpChannelOverHttp@5c22897d{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=https://home.pws/rest/sitemaps/events/202fa668-d149-4b11-b7d3-6758df589fe0?sitemap=control2&pageid=control2,age=2142329}
19:56:08.011 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=2 remaining=0 WriteFlusher@3ac5ad0e{WRITING}->null
19:56:08.011 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@6cd2491b[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@6b6ee816] generate: DONE (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
19:56:08.012 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.server.AsyncContextState$1@1b1f9676 in QueuedThreadPool[qtp1906723026]@71a648d2{STARTED,2<=13<=50,i=5,r=4,q=0}[ReservedThreadExecutor@35e4929a{s=1/4,p=0}]
19:56:08.043 [DEBUG] [y.jsonpath.internal.path.CompiledPath] - Evaluating path: $['linkquality']
19:56:08.043 [DEBUG] [y.jsonpath.internal.path.CompiledPath] - Evaluating path: $['update_available']
19:56:08.045 [DEBUG] [y.jsonpath.internal.path.CompiledPath] - Evaluating path: $['state']
19:56:08.046 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ns_boost_power_link' changed from 15.0 to 24.0
19:56:08.047 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'g_zigbee_link' changed from 59.9 to 60.2 through ns_boost_power_link
19:56:08.788 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@126a58e6{/192.168.80.27:56452<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@50cf3d36[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1f12aca3{s=COMMITTED}]=>HttpChannelOverHttp@4d700a88{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=16290089} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
19:56:08.789 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@126a58e6{/192.168.80.27:56452<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@50cf3d36[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1f12aca3{s=COMMITTED}]=>HttpChannelOverHttp@4d700a88{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=16290090} idle timeout expired
19:56:08.789 [DEBUG] [org.eclipse.jetty.io.FillInterest    ] - onFail FillInterest@7d0e355a{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) [bundleFile:9.4.20.v20190813]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
19:56:08.790 [DEBUG] [org.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@126a58e6{/192.168.80.27:56452<->/192.168.80.7:8080,OPEN,fill=-,flush=-,to=30002/30000}{io=0/0,kio=0,kro=1}->HttpConnection@50cf3d36[p=HttpParser{s=END,0 of -1},g=HttpGenerator@1f12aca3{s=COMMITTED}]=>HttpChannelOverHttp@4d700a88{r=1,c=true,c=false/false,a=ASYNC_WAIT,uri=//home.pws:8080/rest/events?topics=smarthome/items,age=16290091}
19:56:09.017 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'heating.items'
19:56:09.019 [DEBUG] [ser.antlr.AbstractInternalAntlrParser] - Parsing took: 1 ms
19:56:09.019 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
19:56:09.019 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - doLinkModel took: 0ms
19:56:09.020 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 1ms
19:56:09.022 [DEBUG] [ipse.xtext.util.OnChangeEvictingCache] - Clear 57 cache entries for resource tmp_heating.items after 99 hits and 57 misses (quota: 63%)
19:56:09.022 [DEBUG] [ipse.xtext.util.OnChangeEvictingCache] - Clear 57 cache entries for resource heating.items after 11695 hits and 57 misses (quota: 99%)
19:56:09.024 [DEBUG] [ser.antlr.AbstractInternalAntlrParser] - Parsing took: 1 ms
19:56:09.024 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
19:56:09.025 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - doLinkModel took: 1ms
19:56:09.025 [DEBUG] [t.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
19:56:09.995 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'openhab:automation listRules'
19:56:09.998 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: 'openhab:automation listRules' returned 'null'

Interesting, that log has messages from Rules after update:

19:56:07.973 [INFO ] [org.openhab.core.model.script.heating] - Auto temp -> 23.0
19:56:07.973 [INFO ] [org.openhab.core.model.script.heating] - Heating NS boost -> OFF

But this rules are not more exist (they are not listed by openhab:automation listRules)

petrows added a commit to petrows/smarthome-openhab that referenced this issue Dec 29, 2020
@petrows
Rename rules files and items to have unique filenames.
105a36b 
Probably fixes issues:
 - openhab/openhab-core#2022
 - openhab/openhab-core#1829
@petrows
Copy link
Author

petrows commented Dec 29, 2020

I have renamed my model files to be a bit more unique (like light -> light_control and etc). Looks like i cant reproduce rules removal, at least easily. Will keep my eyes open on situation.

@petrows petrows changed the title OH3.0.0 stable: DSL Rules are removed after reload of other .rules files with same file prefix OH3.0.0 stable: DSL Rules are removed after reload of other .rules and .items files with same file prefix Dec 29, 2020
@magcode
Copy link

magcode commented Jan 1, 2021 •
edited

Thanks for your efforts. I saw equal issues with disapearing rules.
I took your hint and renamed my items and rules files. Now the issue is gone.

@kaikreuzer
Copy link
Member

If someone would be able to find an easily reproducible case on a clean OH setup, it would be awesome and I'll quickly look into fixing it. Atm, I am not yet really clear on where to look at and what could possibly make the issue appear, so it is a bit hard to look at it.
@petrows You sound as if you are pretty close to isolating a failing scenario - please don't give up ;-)

@magcode
Copy link

magcode commented Jan 1, 2021 •
edited

Steps to reproduce:

  1. install plain vanilla oh 3.0.0 stable release
  2. create file "windows.items" with content:
Contact windowItemOne "windowItemOne"
  1. create file "window.rules" with content
rule "windowrule1"
    when
        Item windowItemOne changed from CLOSED to OPEN
    then
        logInfo("xyz", "Nothing")
end
  1. start openhab
  2. look at http://localhost:8080/#!/settings/items/ -> one item found
  3. look at http://localhost:8080/#!/settings/rules/ -> one rule found
  4. change "windows.items"
Contact windowItemOne "windowItemOne xy"
  1. look at http://localhost:8080/#!/settings/rules/ -> rule disappeared

This problem does not happen if you name the rule file "ventana.rules" in step 3.

@apella12
Copy link

apella12 commented Jan 2, 2021

I did have a problem with a disappearing rule on OH3.0. I can't say for sure it is the same as described above, so this is just moral support
I had a rule "motion-1" and "motion-k-1" and "motion-k-1" would disappear if "motion-1" was edited. A few years back on OH, I was initially not aware that rules needed to be unique and struggled for a bit with disappearing rules on a thermostat until I ran across that in the documentation, so I suspected, since OH3 added -1, -2, -3, etc. to the items in the rule file, it was somehow parsing "motion-k-1" as "motion-1". Anyhow I changed the name of "motion-k-1" to "kitchen-1" and the problem went away.
At this point the rules are stable, but I was going to go through them and remove the "-" within the rule name and replace with "*" or "_", but haven't done that yet.

@kaikreuzer
Copy link
Member

@magcode I did your steps, but in step 8 I still see the rule and it does not disappear... I changed the items file 3 times, but still the rule stayed there.

@J-N-K
Copy link
Member

J-N-K commented Jan 3, 2021

Which OS are you using, @magcode? You are ok MacOS, @kaikreuzer, correct?

@magcode
Copy link

magcode commented Jan 3, 2021

This OH instance was started in WSL/Ubuntu on Windows. But I got the same issues on my "production" instance on "native" Debian.

2021-01-03_16-36-32.mp4

@kaikreuzer
Copy link
Member

Yes, I am on MacOS, but I doubt that the OS makes any difference.
I was now able to see the rule disappearing when changing step 2 to using "window.items" as a filename. But the rule automatically appeared again after 30 seconds when the RulesRefresher kicked in. Will have a look why it disappeared in the first place.

@kaikreuzer kaikreuzer mentioned this issue Jan 5, 2021
Merged
@kaikreuzer
Copy link
Member

Thank you all for the examples - I was able to identify two bugs in the code, which should both be solved by #2077!

@fuetti
Copy link

fuetti commented Jan 21, 2021

So this fix should be in the 3.1.0 SNAPSHOT already, right? Because now it seems the rules get loaded but they get duplicate rule IDs?

grafik

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/rules-disappear-when-items-are-reloaded/114984/8

@openhab-bot
Copy link
Collaborator

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/openhab-3-notification-rules-scripts/119277/17

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
7 participants
@kaikreuzer @J-N-K @openhab-bot @petrows @magcode @fuetti @apella12