I have some rules that once in a while start to misbehave … and never return to normal behaviour … even if potential problematic JSON-input seems to return to normal.
Instead I’m forced to restart openhab …seemingly every 2-3 days.
2020-06-02 07:19:07.585 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Aktualisierung von Wetterdaten-Aussentemperatur': 4096
2020-06-02 07:19:12.609 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': 4096
Sometimes the error code is 2048 instead of 4096, see logs below.
On startup the rules work like a charm for say 2-3 days … but then suddenly they spit out errors and I’m stuck tracing the problem down.
What does the error code “4096” or even “2048” tell me?
I’ve seen mainly “null” related problems in other forum posts on “ntime.internal.engine.RuleEngineImpl”. So my items seem to exist … maybe the state is corrupted?
One of the rules goes like this … the other is rather similar. The rule should fire only on changes to the item.
rule "Meter HH - Ermittle EUR fuer akt. Tag und Vortag"
when
Item iENERGY_METER1_HH_ZAEHLER changed
then
var Number TMP_kw_AKTUELL
var Number TMP_kw_VORTAG
var Number TMP_kw_TAG
var Number TMP_Kosten_VORTAG
var Number TMP_Kosten_TAG
var Number TMP_APreis = 0.2553 // pro kWh
var Number TMP_GPreis = 121.560 // pro Jahr
TMP_kw_AKTUELL = iENERGY_METER1_HH_ZAEHLER.state as DecimalType
TMP_kw_VORTAG = iENERGY_METER1_HH_ZAEHLER.minimumSince(now.withTimeAtStartOfDay.minusDays(1)).state as DecimalType
TMP_kw_TAG = iENERGY_METER1_HH_ZAEHLER.minimumSince(now.withTimeAtStartOfDay).state as DecimalType
TMP_kw_VORTAG = (TMP_kw_TAG - TMP_kw_VORTAG) / 1000.0
TMP_kw_TAG = (TMP_kw_AKTUELL - TMP_kw_TAG) / 1000.0
iENERGY_METER1_HH_ZAEHLER_KWH_VORTAG.postUpdate(TMP_kw_VORTAG)
iENERGY_METER1_HH_ZAEHLER_KWH_TAG.postUpdate(TMP_kw_TAG)
TMP_Kosten_VORTAG = TMP_kw_VORTAG * TMP_APreis + (TMP_GPreis / 365)
TMP_Kosten_TAG = TMP_kw_TAG * TMP_APreis + (TMP_GPreis / 365)
iENERGY_METER1_HH_KOSTEN_VORTAG.postUpdate(TMP_Kosten_VORTAG)
iENERGY_METER1_HH_KOSTEN_TAG.postUpdate(TMP_Kosten_TAG)
end
The trigger item iENERGY_METER1_HH_ZAEHLER is fed every 10 seconds by a json-transformation via html. I suspect some problems on that side triggering the whole mess … but I’m not sure.
Number iENERGY_METER1_HH_ZAEHLER "HH Zähler [%,.1f Wh]" { http="<[http://some.internal.domain.de%3A8084:10000:JSONPATH($.data[?(@.uuid=='a8da012a-9eb4-49ed-b7f3-38c95142a901')].tuples[0][1])]" }
The complete logs, when the problem starts are like this … the 17h log entry is still fine … then after a quite phase the first sign of a problem occurs on 21:43 in the logs …
The rules acts on a “null” item-instance … the same moment some JsonSyntax errors are logged. DataFormatEx produces errors … some function expected a [0-9a-fA-F] format but got some “0xff” bytes.
2020-05-28 17:31:43.575 [INFO ] [.openhab.action.prowl.internal.Prowl] - API call succeeded. 994 api calls left.
2020-05-28 21:43:40.943 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter WP - Ermittle EUR fuer akt. Tag und Vortag': null
2020-05-28 21:43:40.949 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': com.google.gson.JsonSyntax
Exception: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 37331 path $.results[0].series[0].values[1232][1]
2020-05-28 21:56:45.488 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter WP - Ermittle EUR fuer akt. Tag und Vortag': java.util.zip.DataFormatEx
ception: invalid distance too far back
2020-05-28 21:56:45.488 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': Expected leading [0-9a-fA-
F] character but was 0xff
2020-05-28 22:03:27.824 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': null
2020-05-28 22:03:27.824 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter WP - Ermittle EUR fuer akt. Tag und Vortag': com.google.gson.JsonSyntax
Exception: com.google.gson.stream.MalformedJsonException: Unterminated array at line 2 column 2 path $.results[0].series[0].values[2446][1]
2020-05-28 23:39:49.720 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': null
2020-05-28 23:39:49.720 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter WP - Ermittle EUR fuer akt. Tag und Vortag': com.google.gson.JsonSyntax
Exception: com.google.gson.stream.MalformedJsonException: Unterminated array at line 1 column 34662 path $.results[0].series[0].values[1302]
2020-05-28 23:39:53.177 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Aktualisierung von Wetterdaten-Aussentemperatur': 2048
2020-05-28 23:39:59.717 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Meter HH - Ermittle EUR fuer akt. Tag und Vortag': 2048
2020-05-28 23:40:01.548 [ERROR] [org.influxdb.impl.BatchProcessor ] - Batch could not be sent. Data will be lost
retrofit.RetrofitError: 2048
at retrofit.RetrofitError.unexpectedError(RetrofitError.java:44) ~[retrofit-1.9.0.jar:?]
at retrofit.RestAdapter$RestHandler.invokeRequest(RestAdapter.java:400) ~[retrofit-1.9.0.jar:?]
at retrofit.RestAdapter$RestHandler.invoke(RestAdapter.java:240) ~[retrofit-1.9.0.jar:?]
at org.influxdb.impl.$Proxy141.writePoints(Unknown Source) ~[?:?]
One related follow-up error is like this … influx is not able to persist any item any more.
2020-06-02 07:19:00.996 [ERROR] [org.influxdb.impl.BatchProcessor ] - Batch could not be sent. Data will be lost retrofit.RetrofitError: 4096
Another rrd4j persistence job seems to work and produce graphics as expected.
MfG
Peter
