Comparison method violates its general contract!

Hi Bruce,
thx for reply. It’s the same discussion I googled before :upside_down_face::wink:, but didn’t understand at all, as I’m a “Dummy”, do not understand anything about Java and such stuff.

I only can say that this is my java-version:

[10:59:27] hab@openHABianPi:~$ java -version
openjdk version "1.8.0_222"
OpenJDK Runtime Environment (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)
OpenJDK Client VM (Zulu8.40.0.178-CA-linux_aarch32hf) (build 25.222-b178, mixed mode, Evaluation)
[10:59:36] hab@openHABianPi:~$
1 Like

I have not done a lot with Java myself but I cannot find a better smart home product.

1 Like

Same for me :+1:. But since M3 there are some mystirous things, which I didn’t observe before. So maybe some maintainers or developers (should) know about.
Hope this post reaches them.

1 Like

Bear in mind there could always have been silent failures in this rule, but now you get to hear about them.

My suspicion would fall on these lines

var myTempItemList = gTemp.members.sortBy[state].filter[ i|Integer.parseInt(i.name.split("_").get(1)) > daymin && Integer.parseInt(i.name.split("_").get(1)) <= daymax ]

with their complicated comparisons, relying on all Item names containing parse-able numbers.

I’m sure you have already checked Group memberships, and there’s no reason to think they change from one run of the rule to the next. Is there - you’re not using dynamic group membership changes elsewhere?

But I’m thinking more about what appears to have been observed in the past when using someGroup.members.xx functions. Under some circumstances - which seems to be if the Group is updating in parallel due to a member update - you can get a null return for the “current” Item.
That’s not a problem with a simple comparison like name=="fred", it’s just not equal and there is no error.

But in your case, you do further processing like
Integer.parseInt(i.name.split("_").get(1))
which is going to error if the name it is working on is null.

I don’t know what to suggest, other than opening out those comparisons lambda to include sanity checks and diagnostic reporting.

I will summon @rlkoshak who might remember more about this than me - if it has anything to do with your problem at all.

Thx for reply Rossko.

I first have to say that I was sleeping at the time where the error occurs :stuck_out_tongue_winking_eye:

I do not have dynamic groups. But I do not quite understand of “Changig Group Memberships” from one run to the next.
I didn’t - but if a new item comes to a Group or old left, one has to add/remove it, and this will cause a change in the group.

below I made a snapshot of my openhab.log around the error message (with linecounts)

1:2019-09-18 02:50:03.265 [WARN ] [l.protocol.RemoteControllerWebSocket] - WebSocketClient failure: java.lang.InterruptedException
2:2019-09-18 02:52:58.260 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T02:52:58.148+0200 / 1 Log every 2 hours
3:2019-09-18 03:30:27.959 [INFO ] [pse.smarthome.model.script.homematic] -  HM Fenster ZU(ECO,COMFORT) Status York Heizkörper 14.0 °C
4:2019-09-18 03:39:09.200 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T03:09:06.000+0200 / new State 2019-09-18T03:39:08.000+0200: 
5:2019-09-18 03:39:16.966 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
6:2019-09-18 04:39:14.030 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 7.72 Speed: 1.3097337016912625
7:2019-09-18 04:52:58.242 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T04:52:58.147+0200 / 1 Log every 2 hours
8:2019-09-18 06:39:23.007 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 6.52 Speed: 1.3821764427365
9:2019-09-18 06:52:58.234 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T06:52:58.146+0200 / 1 Log every 2 hours
10:2019-09-18 07:09:25.022 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
11:2019-09-18 07:39:27.193 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T07:09:24.000+0200 / new State 2019-09-18T07:39:26.000+0200: 
12:2019-09-18 07:39:34.726 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
13:2019-09-18 08:39:32.388 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
14:2019-09-18 08:39:32.489 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 7.42 Speed: 1.3097337016912625
15:2019-09-18 08:52:58.232 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T08:52:58.146+0200 / 1 Log every 2 hours
16:2019-09-18 09:47:39.843 [INFO ] [pse.smarthome.model.script.homematic] -  HM Fenster AUF Status York Heizkörper ON prev OFF
17:2019-09-18 09:55:48.668 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'castle.sitemap'
18:2019-09-18 10:22:09.065 [INFO ] [pse.smarthome.model.script.cpu-rules] - Fritzbox-Usb nicht gemountet  CPU_RasPi_Temp_num (Type=NumberItem, State=0, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
19:2019-09-18 10:39:42.210 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 12.04 Speed: 1.5066653496036986
20:2019-09-18 10:52:58.222 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T10:52:58.146+0200 / 1 Log every 2 hours
21:2019-09-18 10:55:32.288 [INFO ] [pse.smarthome.model.script.cpu-rules] - Raspberry Office ist Offline und wird in 3 Minuten ausgeschaltet ON
22:2019-09-18 10:58:32.305 [INFO ] [pse.smarthome.model.script.cpu-rules] - Raspberry Office Sonoff_socket_03 (Type=SwitchItem, State=ON, Label=Steckdose RasPi 3b+, Category=light, Groups=[EG_Buro, gPlugSwitch, gSonoff]) wurde ausgeschaltet 
23:2019-09-18 11:39:46.592 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T11:09:43.000+0200 / new State 2019-09-18T11:39:46.000+0200: 
24:2019-09-18 11:39:54.060 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
25:2019-09-18 12:39:51.337 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 14.93 Speed: 1.4710460567094854
26:2019-09-18 12:52:58.223 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T12:52:58.147+0200 / 1 Log every 2 hours
27:2019-09-18 13:16:02.005 [INFO ] [me.model.script.sonoff_firmware_info] - Tasmota Refresh Items Firmware-Release-State in BasicUI : 6.6.0(sonoff)
28:2019-09-18 13:16:02.010 [INFO ] [me.model.script.sonoff_firmware_info] - Rule fired by Channel: astro:sun:local:noon#event triggered START
29:2019-09-18 13:16:02.015 [INFO ] [me.model.script.sonoff_firmware_info] - Sonoff Maintenance: sonoffs
30:2019-09-18 13:16:02.018 [INFO ] [me.model.script.sonoff_firmware_info] - Tasmota Refresh Items Firmware-Release-State : end
31:2019-09-18 14:40:00.471 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 16.27 Speed: 1.5066653496036986
32:2019-09-18 14:52:58.232 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T14:52:58.146+0200 / 1 Log every 2 hours
33:2019-09-18 15:40:05.259 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T15:10:02.000+0200 / new State 2019-09-18T15:40:04.000+0200: 
34:2019-09-18 15:40:12.797 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
35:2019-09-18 16:40:10.936 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 17.01 Speed: 1.5066653496036986
36:2019-09-18 16:52:58.243 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T16:52:58.147+0200 / 1 Log every 2 hours
37:2019-09-18 18:40:20.787 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 16.06 Speed: 1.5066653496036986
38:2019-09-18 18:41:19.660 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'samsungtv:tv:0d1cef01_00dc_1000_960f_90f1aac88a51' to inbox.
39:2019-09-18 18:41:19.666 [INFO ] [rnal.service.RemoteControllerService] - Using WebSocket interface
40:2019-09-18 18:52:58.230 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T18:52:58.146+0200 / 1 Log every 2 hours
41:2019-09-18 19:40:25.933 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T19:10:22.000+0200 / new State 2019-09-18T19:40:25.000+0200: 
42:2019-09-18 19:40:34.425 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
43:2019-09-18 20:40:00.040 [INFO ] [me.model.script.sonoff_firmware_info] - Tasmota Refresh Items Firmware-Release-State in BasicUI : 6.6.0(sonoff)
44:2019-09-18 20:40:00.062 [INFO ] [me.model.script.sonoff_firmware_info] - Rule fired by Channel: astro:sun:local:astroDusk#event triggered START
45:2019-09-18 20:40:00.092 [INFO ] [me.model.script.sonoff_firmware_info] - Sonoff Maintenance: sonoffs
46:2019-09-18 20:40:00.095 [INFO ] [me.model.script.sonoff_firmware_info] - Tasmota Refresh Items Firmware-Release-State : end
47:2019-09-18 20:40:31.530 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 11.52 Speed: 1.3821764427365
48:2019-09-18 20:52:58.261 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T20:52:58.147+0200 / 1 Log every 2 hours
49:2019-09-18 21:40:37.320 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
50:2019-09-18 22:40:43.298 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 9.06 Speed: 1.3097337016912625
51:2019-09-18 22:52:58.266 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-18T22:52:58.147+0200 / 1 Log every 2 hours
52:2019-09-18 23:10:45.908 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
53:2019-09-18 23:40:48.556 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-18T23:10:45.000+0200 / new State 2019-09-18T23:40:48.000+0200: 
54:2019-09-18 23:40:57.682 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
55:2019-09-19 00:00:30.377 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
56:2019-09-19 00:00:30.495 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing3
57:2019-09-19 00:00:30.496 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing2
58:2019-09-19 00:00:30.620 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing
59:2019-09-19 00:00:30.827 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
60:2019-09-19 00:00:30.904 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing1
61:2019-09-19 00:00:30.926 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus90
62:2019-09-19 00:10:51.498 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
63:2019-09-19 00:40:54.185 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 7.43 Speed: 1.3097337016912625
64:2019-09-19 00:47:58.250 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T00:47:58.154+0200 / 1 Log every 2 hours
65:2019-09-19 01:40:59.017 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
66:2019-09-19 02:11:02.549 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'owm forecasting': Comparison method violates its general contract!
67:2019-09-19 02:41:04.279 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 6.37 Speed: 1.2274629673118345
68:2019-09-19 02:47:58.204 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T02:47:58.149+0200 / 1 Log every 2 hours
69:2019-09-19 04:11:12.324 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-19T03:41:09.000+0200 / new State 2019-09-19T04:11:11.000+0200: 
70:2019-09-19 04:11:20.390 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
71:2019-09-19 04:41:15.538 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 5.13 Speed: 1.4302242363422262
72:2019-09-19 04:47:58.212 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T04:47:58.147+0200 / 1 Log every 2 hours
73:2019-09-19 05:11:18.963 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'owm forecasting': Comparison method violates its general contract!
74:2019-09-19 06:11:22.900 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
75:2019-09-19 06:41:25.517 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 4.74 Speed: 1.0986101293797341
76:2019-09-19 06:47:58.191 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T06:47:58.147+0200 / 1 Log every 2 hours
77:2019-09-19 08:41:35.899 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-19T08:11:32.000+0200 / new State 2019-09-19T08:41:35.000+0200: 
78:2019-09-19 08:41:35.935 [INFO ] [rthome.model.script.OWMWindDirection] - Unexpect status '(invalid: UNDEF)'
79:2019-09-19 08:41:36.054 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 6.59 Speed: 1.0986101293797341
80:2019-09-19 08:41:43.785 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
81:2019-09-19 08:47:58.202 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T08:47:58.148+0200 / 1 Log every 2 hours
82:2019-09-19 10:32:22.610 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.avmfritz.internal.handler.DeviceHandler@1901acf': null
83:java.lang.NullPointerException: null
84:	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseThingHandler.handleCommand(AVMFritzBaseThingHandler.java:137) ~[?:?]
85:	at sun.reflect.GeneratedMethodAccessor192.invoke(Unknown Source) ~[?:?]
86:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
87:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
88:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
89:	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [133:org.openhab.core:2.5.0.M3]
90:	at com.sun.proxy.$Proxy636.handleCommand(Unknown Source) [?:?]
91:	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [184:org.openhab.core.thing:2.5.0.M3]
92:	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [184:org.openhab.core.thing:2.5.0.M3]
93:	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
94:	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
95:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
96:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
97:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
98:	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
99:	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
100:	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
101:	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
102:	at java.lang.Thread.run(Thread.java:748) [?:?]
103:2019-09-19 10:32:26.795 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.avmfritz.internal.handler.DeviceHandler@1901acf': null
104:java.lang.NullPointerException: null
105:	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseThingHandler.handleCommand(AVMFritzBaseThingHandler.java:137) ~[?:?]
106:	at sun.reflect.GeneratedMethodAccessor192.invoke(Unknown Source) ~[?:?]
107:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
108:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
109:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
110:	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [133:org.openhab.core:2.5.0.M3]
111:	at com.sun.proxy.$Proxy638.handleCommand(Unknown Source) [?:?]
112:	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [184:org.openhab.core.thing:2.5.0.M3]
113:	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [184:org.openhab.core.thing:2.5.0.M3]
114:	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
115:	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
116:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
117:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
118:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
119:	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
120:	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
121:	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
122:	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
123:	at java.lang.Thread.run(Thread.java:748) [?:?]
124:2019-09-19 10:34:26.091 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.avmfritz.internal.handler.DeviceHandler@6af236': null
125:java.lang.NullPointerException: null
126:	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseThingHandler.handleCommand(AVMFritzBaseThingHandler.java:137) ~[?:?]
127:	at sun.reflect.GeneratedMethodAccessor192.invoke(Unknown Source) ~[?:?]
128:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
129:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
130:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
131:	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [133:org.openhab.core:2.5.0.M3]
132:	at com.sun.proxy.$Proxy673.handleCommand(Unknown Source) [?:?]
133:	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [184:org.openhab.core.thing:2.5.0.M3]
134:	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [184:org.openhab.core.thing:2.5.0.M3]
135:	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
136:	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
137:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
138:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
139:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
140:	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
141:	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
142:	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
143:	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
144:	at java.lang.Thread.run(Thread.java:748) [?:?]
145:2019-09-19 10:41:46.745 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 12.07 Speed: 1.4302242363422262
146:2019-09-19 10:44:53.401 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.avmfritz.internal.handler.DeviceHandler@6af236': null
147:java.lang.NullPointerException: null
148:	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseThingHandler.handleCommand(AVMFritzBaseThingHandler.java:137) ~[?:?]
149:	at sun.reflect.GeneratedMethodAccessor192.invoke(Unknown Source) ~[?:?]
150:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
151:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
152:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
153:	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [133:org.openhab.core:2.5.0.M3]
154:	at com.sun.proxy.$Proxy675.handleCommand(Unknown Source) [?:?]
155:	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [184:org.openhab.core.thing:2.5.0.M3]
156:	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [184:org.openhab.core.thing:2.5.0.M3]
157:	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
158:	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
159:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
160:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
161:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
162:	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
163:	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
164:	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
165:	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
166:	at java.lang.Thread.run(Thread.java:748) [?:?]
167:2019-09-19 10:45:27.532 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.avmfritz.internal.handler.DeviceHandler@6af236': null
168:java.lang.NullPointerException: null
169:	at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseThingHandler.handleCommand(AVMFritzBaseThingHandler.java:137) ~[?:?]
170:	at sun.reflect.GeneratedMethodAccessor192.invoke(Unknown Source) ~[?:?]
171:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
172:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
173:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
174:	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [133:org.openhab.core:2.5.0.M3]
175:	at com.sun.proxy.$Proxy677.handleCommand(Unknown Source) [?:?]
176:	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [184:org.openhab.core.thing:2.5.0.M3]
177:	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [184:org.openhab.core.thing:2.5.0.M3]
178:	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
179:	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
180:	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
181:	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
182:	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [133:org.openhab.core:2.5.0.M3]
183:	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [133:org.openhab.core:2.5.0.M3]
184:	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
185:	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
186:	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
187:	at java.lang.Thread.run(Thread.java:748) [?:?]
188:2019-09-19 10:47:58.209 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T10:47:58.150+0200 / 1 Log every 2 hours
189:2019-09-19 11:28:23.557 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
190:2019-09-19 11:28:23.727 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
191:2019-09-19 11:28:36.044 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'samsungtv:tv:ue48h6890' takes more than 5000ms.
192:2019-09-19 11:28:46.100 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'samsungtv:tv:ue46es300' takes more than 5000ms.
193:2019-09-19 11:30:35.669 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
194:2019-09-19 11:30:35.691 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '48.887211,9.8709123,502'.
195:2019-09-19 11:30:35.697 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
196:2019-09-19 11:30:35.700 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SIUnits'.
197:2019-09-19 11:30:44.262 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'OWMTEST.items'
198:2019-09-19 11:30:44.345 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
199:2019-09-19 11:30:44.380 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.items'
200:2019-09-19 11:30:44.447 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rich_time.items'
201:2019-09-19 11:30:44.500 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonos_test.items'
202:2019-09-19 11:30:44.706 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
203:2019-09-19 11:30:45.825 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm_test.items'
204:2019-09-19 11:30:47.653 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homematic.items'
205:2019-09-19 11:30:48.043 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'samsung.items'
206:2019-09-19 11:30:48.184 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonos.items'
207:2019-09-19 11:30:48.492 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'system.items'
208:2019-09-19 11:30:48.574 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'castle.items'
209:2019-09-19 11:30:49.053 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avm_fritz.items'
210:2019-09-19 11:30:49.632 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff_mqtt2.items'
211:2019-09-19 11:30:49.831 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
212:2019-09-19 11:30:50.493 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
213:2019-09-19 11:30:51.490 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'castle.sitemap'
214:2019-09-19 11:30:52.542 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt2.things'
215:2019-09-19 11:30:52.592 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cpu_tempPI.things'
216:2019-09-19 11:30:52.610 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm.things'
217:2019-09-19 11:30:52.628 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'samsung.things'
218:2019-09-19 11:30:52.645 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.things'
219:2019-09-19 11:30:52.669 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.things'
220:2019-09-19 11:30:52.692 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonos.things'
221:2019-09-19 11:30:52.715 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avm_fritz.things'
222:2019-09-19 11:30:52.750 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
223:2019-09-19 11:30:56.483 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
224:2019-09-19 11:31:00.713 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'calc_test.rules'
225:2019-09-19 11:31:02.162 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm_winddir.rules'
226:2019-09-19 11:31:03.232 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'itemsGroupingTest.rules'
227:2019-09-19 11:31:05.011 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff_firmware_info.rules'
228:2019-09-19 11:31:05.690 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff_glwt_logging.rules'
229:2019-09-19 11:31:11.430 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'datum_testen.rules'
230:2019-09-19 11:31:12.073 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.rules'
231:2019-09-19 11:31:14.749 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm_windchill.rules'
232:2019-09-19 11:31:15.532 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'teile_durch_tausend.rules'
233:2019-09-19 11:31:17.991 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.rules'
234:2019-09-19 11:31:22.351 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test_datetime.rules'
235:2019-09-19 11:31:23.073 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'avm_test.rules'
236:2019-09-19 11:31:24.113 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test_Regen.rules'
237:2019-09-19 11:31:27.159 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cpu.rules'
238:2019-09-19 11:31:27.648 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_spielereien.rules'
239:2019-09-19 11:31:30.139 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dummy4_uom.rules'
240:2019-09-19 11:31:34.483 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homematic.rules'
241:2019-09-19 11:31:39.019 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'owm_forecasting.rules'
242:2019-09-19 11:31:40.083 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff_maintenance.rules'
243:2019-09-19 11:31:42.195 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'startup.rules'
244:2019-09-19 11:31:43.525 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff_status.rules'
245:2019-09-19 11:31:51.045 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.49:8080
246:2019-09-19 11:31:51.050 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.49:8443
247:2019-09-19 11:32:19.648 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
248:2019-09-19 11:32:21.403 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:sun:local' to inbox.
249:2019-09-19 11:32:21.415 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:moon:local' to inbox.
250:2019-09-19 11:32:28.044 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
251:2019-09-19 11:32:28.125 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:local every 300 seconds
252:2019-09-19 11:32:28.693 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
253:2019-09-19 11:32:28.702 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds
254:2019-09-19 11:32:29.025 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
255:2019-09-19 11:32:29.073 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
256:2019-09-19 11:32:29.129 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:local every 300 seconds
257:2019-09-19 11:32:29.140 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:local every 300 seconds
258:2019-09-19 11:32:29.339 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus90
259:2019-09-19 11:32:29.973 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing
260:2019-09-19 11:32:30.554 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing1
261:2019-09-19 11:32:31.081 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing2
262:2019-09-19 11:32:31.390 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:stowing3
263:2019-09-19 11:32:36.948 [INFO ] [smarthome.model.script.startup-rules] -  1 Raspi Office Temp-Status Number ist  : NULL Raspi Office Temp-Status Number String: NULL
264:2019-09-19 11:32:38.467 [INFO ] [smarthome.model.script.startup-rules] -  2 Raspi Office Temp-Status ist 0 oder NULL deshalb Abbruch: NULL
265:2019-09-19 11:32:38.509 [INFO ] [smarthome.model.script.sonoff_status] - Timer wird initialisiert null
266:2019-09-19 11:32:38.552 [INFO ] [marthome.model.script.astro-rules_99] -  Moondistance updated every 5 Minutes by "astro.things " 2019-09-19T11:32:29.189+0200 / 1 Log every 2 hours
267:2019-09-19 11:32:58.466 [INFO ] [smarthome.model.script.startup-rules] -  1 Raspi Office Temp-Status Number ist  : NULL Raspi Office Temp-Status Number String: 
268:2019-09-19 11:32:58.471 [INFO ] [smarthome.model.script.sonoff_status] - Timer läuft bereits: org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1da35b
269:2019-09-19 11:32:58.477 [INFO ] [smarthome.model.script.startup-rules] -  3 Timer wird initialisiert 
270:2019-09-19 11:32:58.472 [INFO ] [pse.smarthome.model.script.cpu-rules] - Fritzbox-Usb nicht gemountet  CPU_RasPi_Temp_num (Type=NumberItem, State=0, Label=CPU-Ras-Pi Temperatur, Category=temperature, Groups=[Chart_Sys_Temp])
271:2019-09-19 11:32:58.484 [INFO ] [smarthome.model.script.sonoff_status] - Timer wird initialisiert org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1da35b
272:2019-09-19 11:33:11.263 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'HM Status Kuechenfenster Erkennung': The name 'ON' cannot be resolved to an item or type; line 38, column 48, length 2
273:2019-09-19 11:33:14.720 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY1:RINCON_949F3E157B8401400' to inbox.
274:2019-09-19 11:33:14.729 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY1:RINCON_5CAAFDC29C0201400' to inbox.
275:2019-09-19 11:33:14.735 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY3:RINCON_5CAAFD54DF8801400' to inbox.
276:2019-09-19 11:33:15.217 [WARN ] [mon.registry.AbstractManagedProvider] - Could not update element with key openweathermap:uvindex:api:local in ManagedThingProvider, because it does not exists.
277:2019-09-19 11:33:15.778 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid OH2_hans and file store '/var/lib/openhab2/mqtt/localhost'
278:2019-09-19 11:33:16.730 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
279:2019-09-19 11:33:16.785 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
280:2019-09-19 11:33:23.350 [INFO ] [smarthome.model.script.startup-rules] -  0 Timer läuft bereits: 
281:2019-09-19 11:33:23.356 [INFO ] [smarthome.model.script.startup-rules] -  1 Raspi Office Temp-Status Number ist  : 0 Raspi Office Temp-Status Number String: 
282:2019-09-19 11:33:23.359 [INFO ] [smarthome.model.script.startup-rules] -  3 Timer wird initialisiert 
283:2019-09-19 11:33:23.367 [INFO ] [smarthome.model.script.sonoff_status] - Timer läuft bereits: org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1cd2cbc
284:2019-09-19 11:33:23.392 [INFO ] [smarthome.model.script.sonoff_status] - Timer wird initialisiert org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1cd2cbc
285:2019-09-19 11:33:45.167 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: NULL / new State 2019-09-19T11:33:31.000+0200: 
286:2019-09-19 11:33:45.229 [INFO ] [pse.smarthome.model.script.windchill] -  I'm alive - Temp: 13.36 Speed: 1.5066653496036986
287:2019-09-19 11:33:56.451 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'owm forecasting': The name 'gHum' cannot be resolved to an item or type; line 80, column 25, length 4
288:2019-09-19 11:34:06.796 [INFO ] [smarthome.model.script.startup-rules] -  0 Timer läuft bereits: 
289:2019-09-19 11:34:06.797 [INFO ] [smarthome.model.script.sonoff_status] - Timer läuft bereits: org.eclipse.smarthome.model.script.internal.actions.TimerImpl@edad56
290:2019-09-19 11:34:06.800 [INFO ] [smarthome.model.script.startup-rules] -  1 Raspi Office Temp-Status Number ist  : 0 Raspi Office Temp-Status Number String: 
291:2019-09-19 11:34:06.803 [INFO ] [smarthome.model.script.sonoff_status] - Timer wird initialisiert org.eclipse.smarthome.model.script.internal.actions.TimerImpl@edad56
292:2019-09-19 11:34:06.803 [INFO ] [smarthome.model.script.startup-rules] -  3 Timer wird initialisiert 
293:2019-09-19 11:35:06.813 [INFO ] [smarthome.model.script.startup-rules] -  4 Timer - Raspi Office Temp-Status is 0 deshalb Abbruch : 0
294:2019-09-19 11:35:36.826 [INFO ] [smarthome.model.script.sonoff_status] - Device Id : sonoffs Command published
295:2019-09-19 11:35:36.833 [INFO ] [smarthome.model.script.sonoff_status] - Timer tSonoffState ist abgearbeitet und wird wieder auf "null" gesetzt: null
296:2019-09-19 12:03:47.144 [INFO ] [arthome.model.script.owm_forecasting] - TriggerItem ist localLastMeasurement_00: / previous State: 2019-09-19T11:33:31.000+0200 / new State 2019-09-19T12:03:37.000+0200: 
297:2019-09-19 12:03:53.596 [INFO ] [arthome.model.script.owm_forecasting] - End   of Process - Aggregation daily Measures: 8
298:2019-09-19 12:40:41.941 [INFO ] [.samsungtv.internal.WakeOnLanUtility] - MAC address of host 192.168.178.23 is 90:f1:aa:c8:8a:51
299:2019-09-19 12:40:41.976 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
300:2019-09-19 12:40:41.994 [INFO ] [rnal.service.RemoteControllerService] - Using None interface

In Line 53 and 54 one can see that the rule triggers and logs “Start and End”, then an Error Message (Line 66), normal Log Line 69/70. Then again Error Message in Line 73 and since then to now normal Messages beginning in Line 77.

I have to say that the Rule triggers normally every half an hour, but only showing every four hours a log to see that it’s still alive.

Do you think, that a diagnostic way could be to integrate a lambda like this

    myTempItemList.members.forEach[ i | logInfo("grouping items", " each Item: {} ", i) ]

before the suspicious Line, could bring me to a solution ? Or what would you suggest ?

Edit:
Item-Names have the Name-Format:

localHourlyForecastTemperature_00
localHourlyForecastTemperature_01
........
localHourlyForecastTemperature_38
localHourlyForecastTemperature_39
localHourlyForecastTemperature_40

This is a new one for me. That error usually points to a mistake in the implementation of the comparison operator which you are not responsible for implementing.

What I have seen is weird errors before while trying to use Group operations (e.g filter, forEach, etc) on a Group that is actively recalculating it’s state in response to one of it’s members changing state. Usually though that’s a NPE. I’ve never seen this particular error before, though as rossko57 says, it may have always been occurring and it’s just now being reported.

I would add a ton of logging lines to see which line in particular is throwing the error. From there perhaps we can figure out a way to rework it to avoid the problem.

The unusual thing here is the fairly complex split and parse operations on the group member name - as part of a comparison - that might lead to a different complaint about an old problem.

If it is something like I’m guessing, it shouldn’t be consitent about popping up in any of the group.member lines.

I’ll try to come up with diagnostic code later.

@rlkoshak @rossko57

Thx for reply to both of you and your help. If you need some more boundary conditions, pls. let me know.

1 Like

:rofl:

I would change this to log every run for the time being.

No, I think the issue arises by “pot luck” during any members operation. So doing an extra one as a sort of pre-scan won’t help.

// The idea is to toughen this expression against surprises
// by doing it longhand
//    var myTempItemList = gTemp.members.sortBy[state].filter[ i|Integer.parseInt(i.name.split("_").get(1)) > daymin && Integer.parseInt(i.name.split("_").get(1)) <= daymax ]

// get a sorted but unfiltered list
    var myTempItemList = gTemp.members.sortBy[state]
    var Number sumTemp = 0
    var avgTemp = 0
    var countTemp = 0
    var minTemp = 100
    var maxTemp = 0
    myTempItemList.forEach[ g |
       // do the filter now
       var thisNamePart = g.name.split("_").get(1)  // I'm not sure if this might error or not
       if (thisNamePart !== null) {
            // should be safe to parse now
            if (Integer.parseInt(thisNamePart) > daymin && Integer.parseInt(thisNamePart) <= daymax) {
                 // now process
                 thisValue = (g.state as Number ).floatValue
                 sumTemp = sumTemp + thisValue
                 if (thisValue > maxTemp) { maxTemp = thisValue }
                 if (thisValue < minTemp) { minTemp = thisValue }
                 countTemp = countTemp + 1  // bump counter
            }  // else filter this one out
       } else {
           logInfo("test", "gTemp name unexpected - " + g.name)
       }
    ]  // end of foreach
    avgTemp = sumTemp / countTemp
    ScriptServiceUtil.getItemRegistry.getItem( "localDayTempAVG_"+counter).postUpdate(avgTemp)                    // store daily average-temperature
    // etc.

This is nasty code and I fear it would need doing to each of your Group sort/filters. What is more, it is not intended to fix anything just maybe pinpoint the failure a bit. And its all about a guess.

I haven’t really got a grip on exactly what your rule does, but it feels overall like something a database ought to be doing. I wonder if there is some comlpletely different way to approach your requirement.

yeah it seems DSL rules should remain simple or they get glitchy. This one smacks of to complex Peter, this is why I’m excited about [edit JSR223] rules or whatever they are called… sorry scott for not remembering the proper name

First of all, thx for your help and the diagnostic code. I will try to integrate into my rule.

So now let me explain what the rule should do (hope in short words).

I’m using the “OpenWeatherMap-Binding” (free Version) to get several Weather-Data. The Problem of the free Version is that you do not get daily values, only values in 3-hour-steps, up to 120 hours (120 / 24 = 5 days), but shifting every 3 hours.

Now I want to know daily measures for today, tomorrow,… up to day 5 for exactly the specific day(s). So I began to create a rule.

The first one I made (with the help of @5iver, @rlkoshak, @vzorglub) , where I learned a lot about generic items from Scott, was about 350 Lines (or more) of code. (a lot of variables,shifting and calculate…)

The second one has had a lot of HashMaps and I could reduce the code down to 250 lines (thx to Rich for his help and his endurance).

This version is more or less based on a great idea of @Udo_Hartmann. So I can learn from him something about the Grouping-Methods. Now the code has (more or less) 80 lines, doing the same as the both others.

So here I calculate the number of items for the specific days and which one is the last item of the specific day:

val day  = -1 
    val day0 = 7 - (now.getHourOfDay / 3).intValue 
    val day1 = day0 + 8
    val day2 = day1 + 8
    val day3 = day2 + 8
    val day4 = day3 + 8
    val Number day5 = 40

Therefore the items look like

Number:Temperature   localHourlyForecastTemperature_00        "Aktuelle Temperatur [%.1f %unit%]"                              <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:current#temperature" }
Number:Temperature   localHourlyForecastTemperature_01        "Temperatur in 03 Stunden[%.1f %unit%]"                          <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:forecastHours03#temperature" }
Number:Temperature   localHourlyForecastTemperature_02        "Temperatur in 06 Stunden [%.1f %unit%]"                         <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:forecastHours06#temperature" }
Number:Temperature   localHourlyForecastTemperature_03        "Temperatur in 09 Stunden [%.1f %unit%]"                         <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:forecastHours09#temperature" }
.................
Number:Temperature   localHourlyForecastTemperature_39        "Temperatur in 12 Stunden [%.1f %unit%]"                         <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:forecastHours117#temperature" }
Number:Temperature   localHourlyForecastTemperature_40        "Temperatur in 15 Stunden [%.1f %unit%]"                         <temperature>   (gOWM1,gTemp)        { channel="openweathermap:weather-and-forecast:api:local:forecastHours120#temperature" }

for the later “Splitting and Changing Part” in the Grouping-Section and summarizing the daily measures.

So after I understand that genius idea it was not very hard to realize.

Maybe it’s hard and complex for DSL :crazy_face::wink:, but not for me anymore. I learned a lot in that time, when corresponding with you all. I’m still a newbie (and dummy) and as my nick-name says (fibu = financial accountant - now retired) I still have no idea about programming and that stuff, but I know there’s always a “helping hand” here in the community (and of course in the german one too) and that’s why I like this software (openHAB) even with all corners and edges.

So one more time, many thanks for your help.

Cheers,
Peter

BTW: The error didn’t came up anymore 'til now. If one of you wants to have my setup(items,rules,thing) for testing purposes; any time

1 Like
2 Likes

Given it’s a sporadic problem, I doubt anyone can reproduce without narrowing down. It’s likely a race condition dependant on host system performance and activity.

Okay, so you have 40 Items ( of each type) pinned to fixed times of day, and as a rolling forecast from OWM comes in you map it to the fixed Items.

Can I ask why? I’m just wondering if it easier to calculate which element of the rolling forecast to look at, instead of copying data around. Might not help if you are charting for example.
I expect you’ve been through all this already.

Thx, for answering.
I know both. Yours, which is very powerful(JSR223-Jython), but at the moment to much stuff for me and my little RPi. As it’s very interesting how it handles dynamic items and groups, i will keep an eye on it :wink:.

The first solutions of @shutterfreak are similar to my first rules. And his latest has some global functions, which is even very interesting to learn from, but to much stuff for me too, to understand, so I have to think about it and tinkering with it.

The main difference is that I use the complete range of the forecasting-period up to 120 hours, beginning with actual values. But one can easy change, if changing the variable

val day  = -1

from -1 to 0 to begin with the 3-hour items.

It’s the other way around. I have up to 40 items(depends on the settings in the owm.things), but not fixed times. Every 3 hours all items changes their position. E.g. 3-hours becomes now current, 6-hours becomes 3-hours,…etc.

Hope I explained it understandable.

Try it… I bet you it uses less resources than an equivalent DSL rule! By too much for you, do you mean installing Jython?! It would take minutes to setup, and you’ve been working on this since December? But go ahead and reinvent the wheel… as many times as you’d like… maybe work on fire next :slight_smile:.

2 Likes

You are quite right :cry: My latest projects were to migrate some bindings from V1.xx to V2.xx (e.g. MQTT) or changing from Jessie to Stretch. So that’s all new stuff for me.

But this will be my next project … and I count on you then :wink:

1 Like

It’s worth noting that Scott’s version of those Rules have been released as part of the Community section of the Helper Libraries for JSR223 Rules. it creates all the Items needed for you and does all the work. All you need to do is copy it to the right folder and it does all the work for you.

Definitely keep an eye on the Helper Libraries. As the NGRE and JSR23 Rules become more the standard, the past approach of copy and pasting Rules from the forum will go away. You will just need to copy a folder to the right place and you are done. I’ve already submitted about 10 PRs to the library with similar library capabilities, most recently MQTT 2.5 eventbus.

I had no idea what that meant. :smiley:

I’ll second Scott’s recommendation to give the library a try. We want to move away from requiring users like you from needing to get this deep into coding stuff like this so you can focus on your home automation rather than messing with data manipulation. For JSR223 you just need to copy a folder and maybe make a change to a configuration file. For NGRE you will find and install a Rule Template the same as you do bindings (I hope).

In my relatively limited experience, loading and using Python on the RPi doesn’t take significantly more than .rules and the Helper library has a nice little feature built in that prevents your files from loading until all the rst of OH is ready for your Rules to start running.

1 Like

Just want to say that I was a Financial Accountant(german: Finanzbuchhalter), so don’t know anything about Programming and such stuff. (but very interested in learning)