openHABian 3.3.0 on rPi4
I have been migrating form OH2 to OH3 over the last couple of weeks…
Adding bindings, creating things and items in the UI; using rules in text files.
I copy the latter and, check what errors out and fix these, with three key issues/fixes to address:
- mail/mqtt actions
- now > ZonedTime
- executeCommandLine
Maybe 4: replace the "last updated " items with a channel config.
All going well.
I have two terminals open on the OH3 machine:
- karaf
- any command line I need to run; e.g. find openhab2 (in some paths that need changing) or a tail on openhab.log
I noticed that one item did not update over night; checked the flow (channel, item) for correctness, felt to look at this later, and for the time being updated it in the karaf console.
Well, it still did not update the item in the sitemap despite karaf saying it did.
A few minutes later, logging stopped, as is frontail logging stopped.
I then ended karaf to run top to see, if the system is still working; which it was. But as I closed kraf, logging continued, actually catching up on what it missed since it stopped.
…
Just to stop again.
Now openhab.log listed the rules file I was working in, and started complaining about other rules. The language server then disconnected from vsCode.
Then I thought, doing all this work and adding tons of stuff (as in migrating from OH2), maybe a OH restart is in order, and issued sudo openhab-cli stop
; which seems to shutdown OH, but also seems to restart it by itself.
All came up seemingly normal, but logging stopped after some 5 minutes. Items are updated.
openhab.log with rules files listed:
2022-11-14 22:10:52.196 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zeva.rules'
2022-11-14 22:10:55.166 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'zeva-3' failed: Script interpreter couldn't be obtained in zeva
2022-11-14 22:11:02.998 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shed.rules'
2022-11-14 22:19:33.697 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Invalid CRC at 8100
2022-11-14 22:19:58.001 [ERROR] [xt.ide.server.concurrent.ReadRequest] - Error during request:
java.lang.RuntimeException: Cannot create a resource for 'java:/Objects/org.openhab.core.items.GenericItem'; a registered resource factory is needed
at org.eclipse.xtext.resource.XtextResourceSet.getResource(XtextResourceSet.java:263) ~[?:?]
at org.eclipse.xtext.ide.server.ProjectManager.getResource(ProjectManager.java:169) ~[?:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.doRead(WorkspaceManager.java:436) ~[?:?]
at org.eclipse.xtext.ide.server.findReferences.WorkspaceResourceAccess.readOnly(WorkspaceResourceAccess.java:36) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.doRead(DocumentSymbolService.java:332) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.getDefinitions(DocumentSymbolService.java:112) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.getDefinitions(DocumentSymbolService.java:99) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$definition$25(LanguageServerImpl.java:607) ~[?:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.doRead(WorkspaceManager.java:438) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.definition(LanguageServerImpl.java:606) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.definition(LanguageServerImpl.java:594) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$definition$24(LanguageServerImpl.java:585) ~[?:?]
at org.eclipse.xtext.ide.server.concurrent.ReadRequest.lambda$doRun$0(ReadRequest.java:66) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
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:829) [?:?]
2022-11-14 22:19:58.189 [ERROR] [xt.ide.server.concurrent.ReadRequest] - Error during request:
java.lang.RuntimeException: Cannot create a resource for 'java:/Objects/org.openhab.core.library.types.DecimalType'; a registered resource factory is needed
at org.eclipse.xtext.resource.XtextResourceSet.getResource(XtextResourceSet.java:263) ~[?:?]
at org.eclipse.xtext.ide.server.ProjectManager.getResource(ProjectManager.java:169) ~[?:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.doRead(WorkspaceManager.java:436) ~[?:?]
at org.eclipse.xtext.ide.server.findReferences.WorkspaceResourceAccess.readOnly(WorkspaceResourceAccess.java:36) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.doRead(DocumentSymbolService.java:332) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.getDefinitions(DocumentSymbolService.java:112) ~[?:?]
at org.eclipse.xtext.ide.server.symbol.DocumentSymbolService.getDefinitions(DocumentSymbolService.java:99) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$definition$25(LanguageServerImpl.java:607) ~[?:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.doRead(WorkspaceManager.java:438) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.definition(LanguageServerImpl.java:606) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.definition(LanguageServerImpl.java:594) ~[?:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$definition$24(LanguageServerImpl.java:585) ~[?:?]
at org.eclipse.xtext.ide.server.concurrent.ReadRequest.lambda$doRun$0(ReadRequest.java:66) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
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:829) [?:?]
2022-11-14 22:21:14.328 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Invalid CRC at 8100
2022-11-14 22:27:06.539 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Invalid CRC at 8100
2022-11-14 22:30:48.161 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: DHCP OK
2022-11-14 22:33:41.316 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rf433rx.rules'
2022-11-14 22:49:05.012 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Invalid CRC at 8100
2022-11-14 22:57:38.286 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Invalid CRC at 8100
2022-11-14 23:59:00.072 [INFO ] [enhab.core.model.script.Modbus.05.01] - Minutes w/o grid...: 120
2022-11-15 00:01:09.260 [INFO ] [nhab.core.model.script.spp_bms.01.00] - Midnight cron resets...
2022-11-15 00:50:35.051 [INFO ] [nhab.core.model.script.RF433TX.01.01] - UNO_RF433TX has rebooted
2022-11-15 00:50:35.111 [INFO ] [nhab.core.model.script.RF433TX.01.02] - TX433 error logged to file
2022-11-15 00:50:35.116 [INFO ] [nhab.core.model.script.RF433TX.01.01] - UNO_RF433TX has rebooted
2022-11-15 00:50:35.147 [INFO ] [nhab.core.model.script.RF433TX.01.02] - TX433 error logged to file
2022-11-15 01:20:12.978 [INFO ] [.myenergi.internal.MyEnergiApiClient] - Re-initializing Api connection after exception caught
java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1a9ae67::DecryptedEndPoint@47c285{l=/192.168.1.68:33090,r=s18.myenergi.net/52.30.172.43:443,OPEN,fill=-,flush=-,to=30362/0}
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:730) ~[?:?]
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.executeApiCallHttpClient(MyEnergiApiClient.java:367) ~[?:?]
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.executeApiCall(MyEnergiApiClient.java:338) ~[?:?]
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.updateZappiSummary(MyEnergiApiClient.java:171) ~[?:?]
at org.openhab.binding.myenergi.internal.handler.MyEnergiZappiHandler.refreshMeasurements(MyEnergiZappiHandler.java:119) ~[?:?]
at org.openhab.binding.myenergi.internal.handler.MyEnergiBaseDeviceHandler.lambda$1(MyEnergiBaseDeviceHandler.java:92) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
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:829) [?:?]
Caused by: java.io.EOFException: HttpConnectionOverHTTP@1a9ae67::DecryptedEndPoint@47c285{l=/192.168.1.68:33090,r=s18.myenergi.net/52.30.172.43:443,OPEN,fill=-,flush=-,to=30362/0}
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:385) ~[?:?]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1620) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:269) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:185) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
... 1 more
2022-11-15 01:20:16.035 [INFO ] [.myenergi.internal.MyEnergiApiClient] - Re-initializing Api connection after code: 0, reason:
2022-11-15 01:20:19.051 [INFO ] [.myenergi.internal.MyEnergiApiClient] - Re-initializing Api connection after code: 0, reason:
2022-11-15 01:20:22.068 [WARN ] [al.handler.MyEnergiBaseDeviceHandler] - Exception from API - myenergi:zappi:api:16181119
org.openhab.binding.myenergi.internal.exception.ApiException: Http error after several attemps: 0 -
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.executeApiCallHttpClient(MyEnergiApiClient.java:400) ~[?:?]
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.executeApiCall(MyEnergiApiClient.java:338) ~[?:?]
at org.openhab.binding.myenergi.internal.MyEnergiApiClient.updateZappiSummary(MyEnergiApiClient.java:171) ~[?:?]
at org.openhab.binding.myenergi.internal.handler.MyEnergiZappiHandler.refreshMeasurements(MyEnergiZappiHandler.java:119) ~[?:?]
at org.openhab.binding.myenergi.internal.handler.MyEnergiBaseDeviceHandler.lambda$1(MyEnergiBaseDeviceHandler.java:92) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
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:829) [?:?]
2022-11-15 02:11:15.867 [INFO ] [nhab.core.model.script.spp_bms.07.01] - ProfitLoss rule triggered...
2022-11-15 02:11:15.877 [INFO ] [nhab.core.model.script.spp_bms.07.02] - ProfitLossTotal yesterday.0.: -154.86
2022-11-15 02:11:15.882 [INFO ] [nhab.core.model.script.spp_bms.07.03] - ProfitLossTotal yesterday.1.: -154.86
2022-11-15 02:11:15.885 [INFO ] [nhab.core.model.script.spp_bms.07.04] - ProfitLoss updated (night)..: 0.09
2022-11-15 02:11:15.887 [INFO ] [nhab.core.model.script.spp_bms.07.05] - ProfitLoss corrections......: 0.00
2022-11-15 02:11:15.889 [INFO ] [nhab.core.model.script.spp_bms.07.06] - ProfitLossTotal new today...: -154.77
2022-11-15 02:11:15.891 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'sppro_bms-5' failed: Could not cast UNDEF to org.openhab.core.library.types.DecimalType; line 214, column 42, length 31 in sppro_bms
2022-11-15 04:15:00.071 [INFO ] [openhab.core.model.script.Shed.10.01] - Cron: is boost required?
2022-11-15 04:15:00.075 [INFO ] [openhab.core.model.script.Shed.10.02] - ... Shed_HWS_Boost_Allowed = NULL
2022-11-15 04:17:52.711 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Response Timed Out at 8100
2022-11-15 06:05:00.589 [INFO ] [enhab.core.model.script.Modbus.01.04] - Modbus error logged to file: Response Timed Out at 8000
2022-11-15 06:42:38.633 [ERROR] [xt.ide.server.concurrent.ReadRequest] - Error during request:
java.lang.IndexOutOfBoundsException: Position [
line = 193
character = 79
] text was : /*
20221015-1927 removed HWS rules; moved to shed.rules
20181225-1420 copied rule file from v1 to v2
all rules within that one .rules file can use these var or val
val - short for "value", gets initialised with a value and the Rules DSL
will prevent reassigning another value to that name
var - short for "variable" , can remain uninitialised (will be null),
can be assigned new values, and can be reassigned to another value
*/
val String logPrefix = "spp_bms."
// ----- 170614 MaxG: Timer for -> late arvo charge reduction
var Timer timerLateArvoChargeDecrement = null
// ------------------------------------------------------------------------
// ----- Rules related to SP PRO, BMS, etc.
// ------------------------------------------------------------------------
rule "SPPRO-BMS system started"
when
System started
then
logInfo(logPrefix + "00.00", "System start or rule file reload for {}", logPrefix)
end
[Info - 10:11:10 am] Connection to server got closed. Server will restart.
[Error - 10:11:10 am] Connection to server is erroring. Shutting down server.
[Error - 10:11:10 am] Connection to server is erroring. Shutting down server.
I am pretty much clueless on where and what to look for.
This is a stock standard openHABian.
No binding was added in the last three days.
Added items and modified these in UI.
I am not running out of space:
Filesystem Size Used Avail Use% Mounted on
/dev/root 15G 5.8G 8.1G 42% /
devtmpfs 1.9G 0 1.9G 0% /dev
tmpfs 1.9G 0 1.9G 0% /dev/shm
tmpfs 778M 1.6M 777M 1% /run
tmpfs 5.0M 0 5.0M 0% /run/lock
/dev/sda1 253M 50M 203M 20% /boot
/dev/zram1 721M 213M 456M 32% /opt/zram/zram1
overlay1 721M 213M 456M 32% /var/lib/openhab/persistence
/dev/zram2 323M 15M 284M 5% /opt/zram/zram2
overlay2 323M 15M 284M 5% /var/lib/influxdb
/dev/zram3 974M 636M 271M 71% /opt/zram/zram3
overlay3 974M 636M 271M 71% /var/log
tmpfs 389M 0 389M 0% /run/user/1000
Any hints appreciated.