Bindings, Hue and Z-Wave stops after Astro Binding triggerd start event

Hardware Server
, ,
#1
  • Platform information:
    • Hardware: Raspberry Pi 3B+
    • OS: Raspberry OS, Buster, latest Updates; Kernel 5.4.51-v7+
    • Java Runtime Environment: Zulu 8.48.1.243-CA-linux_aarch32hf
    • openHAB version: 2.5.7

I have an strange error with the Raspbian Updates released in June and mid July '20. Apter updating the OS openhab looses the connection to (Z-Wave, Hue). I have some rules which changes during the night the lights in the floors and closes the blinds.

The rules are triggerd by the Astro Binding. The Hue Binding changes the light intensity of the Light in the floors.
Usual run:

  1. Lights: astro event trigger -> outside night -> lights switch on -> light intensity 10% -> lights switch off
  2. Blinds: astro event trigger -> outside night -> blinds go down
    At morning same thing happens with lights 100% and blinds up.

After the update of the OS the connection to all Hue lights stops after the light intensity change, same with the z-wave things.

The only way to fix is to restart the RPI, restarting the openhab service don’t change the situation. The OH config wasn’t changed only installting update via apt update && apt upgrade.

The problem started with:

libraspberrypi-bin:armhf (1.20200601-1, 1.20200717-1),
libraspberrypi-dev:armhf (1.20200601-1, 1.20200717-1),
libraspberrypi-doc:armhf (1.20200601-1, 1.20200717-1),
raspberrypi-kernel:armhf (1.20200601-1, 1.20200717-1),
raspberrypi-bootloader:armhf (1.20200601-1, 1.20200717-1),
libraspberrypi0:armhf (1.20200601-1, 1.20200717-1),
libnss3:armhf (2:3.42.1-1+deb10u2,2:3.42.1-1+deb10u3)

The error exists in these versions, the error does not appear in the update between these versions.

Thanks for your help,
Christian

#2

Which version of OH did you upgrade from and to what version of OH did you upgrade to?

#3

The initial OH Version was 2.5.6 now 2.5.7, for testing I tested OH 2.5.5. I suspect the RPI Kernel updates. Actually I’m on the latest stable Versions.
My next test will using and older RPI Image, it’s a little bit pity that the archive.raspberrypi.org doesn’t provide older deb packages for downgradeing.

BR,
Christian

#4

OK… just wanted to be sure. There were somewhat recent changes (prior to these) that cause similar behavior. Since this is more hardware related than Scripts and Rules, I’ve moved your topic to a more fitting category.

@mstormi, have you run into this?

#5

No, and I wholeheartedly doubt it is related to the kernel (I run the same).

I had an issue that kernel modules were missing/installed on the secondary SD so check if yours are there in /lib/modules.

#6

Yes checked, the /lib/modules path, it contains the the modules.
Maybe I’ll used the wrong words. I mean the problem occurs with the actual updates released for raspberry OS. In my initial post i cached the files which breaks OH, during the error persist I can work in OH. The things looks like online, I see the thing operations (on/off) but the change is not executed in the thing, to see an effect on the thing, I need to reboot. After this i works fine untill the triggerd rules start.

#7

What do you see in the openhab.log?

#8

Hi Scot,

here are the logs and the rule. The rule was working fine about 4 month.

openhab.log ###################################################
2020-07-28 23:18:10.913 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home
2020-07-28 23:18:10.961 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2020-07-28 23:18:11.078 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2020-07-28 23:18:11.103 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:18:12.347 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2020-07-28 23:18:40.968 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing ‘zwave:serial_zstick:6bfce7b4’ takes more than 5000ms.
2020-07-28 23:18:41.992 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2020-07-28 23:18:42.729 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2020-07-28 23:18:42.768 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2020-07-28 23:18:42.805 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-07-28 23:19:40.686 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.items’
2020-07-28 23:19:41.717 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘rrd4j.persist’
2020-07-28 23:19:42.778 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.sitemap’
2020-07-28 23:19:43.330 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘tradfri.things’
2020-07-28 23:19:43.503 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘modbus.things’
2020-07-28 23:19:43.558 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.things’
2020-07-28 23:19:47.773 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-07-28 23:19:50.616 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.10:8080
2020-07-28 23:19:50.620 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.10:8443
2020-07-28 23:19:54.955 [WARN ] [iscovery.TradfriDiscoveryParticipant] - Discovered Tradfri gateway doesn’t have an IP address: [ServiceInfoImpl@12660985 name: ‘gw-b8d7af2b20f3._coap._udp.local.’ address: ‘(null):0’ status: ‘DNS: JmDNS-/192.168.1.10 [/192.168.1.10] state: probing 1 task: null’, has NO data
gw-b8d7af2b20f3._coap._udp.local.: ]
2020-07-28 23:19:55.274 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 15 seconds
2020-07-28 23:19:55.433 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 15 seconds
2020-07-28 23:19:59.317 [INFO ] [ternal.handler.TradfriGatewayHandler] - Received pre-shared key for gateway ‘192.168.1.19’
2020-07-28 23:20:04.458 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=FORECASTIO,apiKey=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa]
2020-07-28 23:20:04.461 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=OPENWEATHERMAP,apiKey=aaaaaaaaaaaaaaaaaaaaaaaaaaaaa]
2020-07-28 23:20:04.463 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=FORECASTIO,language=de,updateInterval=5,latitude=50.828483,longitude=7.214354,locationId=home,name=Lohmar]
2020-07-28 23:20:06.200 [INFO ] [b.core.service.AbstractActiveService] - FritzboxTr064 Refresh Service has been started
2020-07-28 23:20:06.232 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2020-07-28 23:20:06.863 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.051 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-28 23:20:07.310 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.383 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.577 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 5 minutes
2020-07-28 23:20:08.022 [INFO ] [io.hueemulation.internal.ConfigStore] - Using discovery ip 192.168.3.10
2020-07-28 23:20:08.025 [INFO ] [io.hueemulation.internal.ConfigStore] - Hue Emulation pairing disabled
2020-07-28 23:20:09.605 [WARN ] [ulation.internal.HueEmulationService] - The UPnP Server service has not been started!
2020-07-28 23:20:09.614 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-07-28 23:20:10.293 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 127.0.0.1:8080
2020-07-28 23:20:10.578 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-07-28 23:20:11.070 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-07-28 23:20:11.256 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2020-07-28 23:20:12.152 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:20:16.838 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-07-28 23:20:16.839 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-07-28 23:20:17.307 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2020-07-28 23:20:17.666 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-07-28 23:20:17.916 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-07-28 23:20:19.969 [WARN ] [.serialmessage.ZWaveCommandProcessor] - SerialMessage class null is not implemented!
2020-07-28 23:20:19.971 [WARN ] [ve.internal.protocol.ZWaveController] - TODO: Implement processing of Request Message = – (0xa)
2020-07-28 23:20:19.975 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 13: Not initialized (ie node unknown), ignoring message.
2020-07-28 23:20:19.978 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 13: Not initialized (ie node unknown), ignoring message.
2020-07-28 23:20:20.824 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 16: Restore from config: Error. Data invalid, ignoring config.
2020-07-28 23:20:20.844 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 4: Restore from config: Error. Data invalid, ignoring config.
2020-07-28 23:20:22.208 [ERROR] [io.openhabcloud.internal.CloudClient] - Error connecting to the openHAB Cloud instance: {}
io.socket.engineio.client.EngineIOException: xhr poll error
at io.socket.engineio.client.Transport.onError(Transport.java:63) [bundleFile:?]
at io.socket.engineio.client.transports.PollingXHR.access$100(PollingXHR.java:26) [bundleFile:?]
at io.socket.engineio.client.transports.PollingXHR$6$1.run(PollingXHR.java:140) [bundleFile:?]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [bundleFile:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_262]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_262]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_262]
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_262]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_262]
at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:1.8.0_262]
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:467) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:461) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1146) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl.access$300(SSLSocketImpl.java:72) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:833) ~[?:1.8.0_262]
at okio.Okio$2.read(Okio.java:139) ~[?:?]
at okio.AsyncTimeout$2.read(AsyncTimeout.java:237) ~[?:?]
at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345) ~[?:?]
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217) ~[?:?]
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211) ~[?:?]
at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189) ~[?:?]
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:75) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:185) ~[?:?]
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:135) ~[?:?]
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
… 3 more
2020-07-28 23:20:22.285 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:20:22.515 [WARN ] [okhttp3.OkHttpClient ] - A connection to https://myopenhab.org/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);
2020-07-28 23:20:23.781 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:21:12.555 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02BR_display.rules’
2020-07-28 23:21:13.669 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02BR_Rollo.rules’
2020-07-28 23:21:18.028 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘aurora.rules’
2020-07-28 23:21:19.261 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02brlight.rules’
2020-07-28 23:21:19.422 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘presence.rules’
2020-07-28 23:21:19.428 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model ‘presence.rules’ is either empty or cannot be parsed correctly!
2020-07-28 23:21:21.303 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘lights_floor.rules’
2020-07-28 23:21:26.054 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.rules’
2020-07-28 23:21:27.172 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02WC_Light.rules’
2020-07-28 23:50:05.395 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-29 00:16:03.223 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-29 06:53:01.872 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home
2020-07-29 06:53:02.084 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2020-07-29 06:53:02.122 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = a89b7181-43e5-4d9a-a07c-d77a74869f96, base URL = http://localhost:8080)
2020-07-29 06:53:02.636 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down

events.log ###################################################
2020-07-29 05:59:57.355 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-07-29T05:58:57.295+0200 to 2020-07-29T05:59:57.301+0200
2020-07-29 06:00:00.016 [vent.ChannelTriggeredEvent] - astro:sun:nightlight:rise#event triggered START
2020-07-29 06:00:00.020 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2020-07-29 06:00:00.030 [ome.event.ItemCommandEvent] - Item ‘SceneF2_Hallway_Light_Night’ received command OFF
2020-07-29 06:00:00.120 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_dm’ received command 100
2020-07-29 06:00:00.124 [vent.ItemStateChangedEvent] - SceneF2_Hallway_Light_Night changed from ON to OFF
2020-07-29 06:00:00.131 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_co’ received command 15
2020-07-29 06:00:00.135 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become 100
2020-07-29 06:00:00.186 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_dm’ received command 100
2020-07-29 06:00:00.257 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_dm’ received command 100
2020-07-29 06:00:00.262 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_co’ received command 15
2020-07-29 06:00:00.286 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_dm’ received command 100
2020-07-29 06:00:00.291 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_co’ received command 15
2020-07-29 06:00:00.294 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_co predicted to become 15
2020-07-29 06:00:00.296 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become 100
2020-07-29 06:00:00.332 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:00.334 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become 100
2020-07-29 06:00:00.347 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_co predicted to become 0
2020-07-29 06:00:00.349 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become 100
2020-07-29 06:00:00.378 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_co predicted to become 0
2020-07-29 06:00:00.380 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 0 to 100
2020-07-29 06:00:00.382 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 0 to 100
2020-07-29 06:00:00.384 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 0 to 100
2020-07-29 06:00:01.675 [vent.ItemStateChangedEvent] - F2_Hallway_Light_sw changed from OFF to ON
2020-07-29 06:00:01.678 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:01.680 [vent.ItemStateChangedEvent] - F2_Hallway_Light_swday changed from OFF to ON
2020-07-29 06:00:01.682 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:01.709 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_swday’ received command ON
2020-07-29 06:00:01.712 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 100 to 28
2020-07-29 06:00:01.714 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_swday predicted to become ON
2020-07-29 06:00:02.499 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:02.501 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 28 to 100
2020-07-29 06:00:02.504 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_sw changed from OFF to ON
2020-07-29 06:00:02.506 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 100 to 28
2020-07-29 06:00:03.554 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 28 to 100
2020-07-29 06:00:03.851 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.4 to 83.2
2020-07-29 06:00:04.679 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:04.681 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:04.683 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:08.335 [vent.ItemStateChangedEvent] - Temperature changed from 13.43 to 13.46
2020-07-29 06:00:08.338 [vent.ItemStateChangedEvent] - Clouds changed from 31.00 to 30.00
2020-07-29 06:00:08.341 [vent.ItemStateChangedEvent] - LastUpdate changed from 2020-07-29T05:55:08.293+0200 to 2020-07-29T06:00:08.274+0200
2020-07-29 06:00:08.344 [vent.ItemStateChangedEvent] - ObservationTime changed from 2020-07-29T05:55:08.000+0200 to 2020-07-29T06:00:08.000+0200
2020-07-29 06:00:10.486 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 0.030017317704953698 to 0.06399685064567535
2020-07-29 06:00:13.850 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 83.2 to 76.2
2020-07-29 06:00:15.189 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_dm’ received command OFF
2020-07-29 06:00:15.233 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_dm’ received command OFF
2020-07-29 06:00:15.249 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_dm’ received command OFF
2020-07-29 06:00:15.251 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become OFF
2020-07-29 06:00:15.274 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_dm’ received command OFF
2020-07-29 06:00:15.304 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become OFF
2020-07-29 06:00:15.335 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become OFF
2020-07-29 06:00:15.345 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become OFF
2020-07-29 06:00:15.360 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 100 to 0
2020-07-29 06:00:15.361 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 0
2020-07-29 06:00:15.363 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 100 to 0
2020-07-29 06:00:15.364 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 100 to 0

lights_floor.rules ###################################################################
//####################################################################################################################################

rule “Beleuchtung_Nacht”

when

    Channel 'astro:sun:home:set#event' triggered START

then {

        FF_Hallway_Light_dm.sendCommand(1)

        FF_Hallway_Light_co.sendCommand(60)

        F2_Hallway_Light_dm.sendCommand(1)

        // Treppe UG

        GF_Hallway2_Light_dm.sendCommand(1)

        GF_Hallway2_Light_co.sendCommand(60)

        // Flur UG

        GF_Hallway3_Light_dm.sendCommand(1)

        GF_Hallway3_Light_co.sendCommand(60)

        // warten zum ausschalten

        Thread::sleep(15000)

        FF_Hallway_Light_dm.sendCommand(OFF)

        F2_Hallway_Light_dm.sendCommand(OFF)

        GF_Hallway2_Light_dm.sendCommand(OFF)

        GF_Hallway3_Light_dm.sendCommand(OFF)            

        }

end

rule “Beleuchtung_Tag”

when

    Channel 'astro:sun:home:rise#event' triggered START

then {

        FF_Hallway_Light_dm.sendCommand(100)

        FF_Hallway_Light_co.sendCommand(15)

        F2_Hallway_Light_dm.sendCommand(100)

        // Treppe UG

        GF_Hallway2_Light_dm.sendCommand(100)

        GF_Hallway2_Light_co.sendCommand(15)

        // Flur UG

        GF_Hallway3_Light_dm.sendCommand(100)

        GF_Hallway3_Light_co.sendCommand(15)

        // warten zum ausschalten

        Thread::sleep(15000)

        FF_Hallway_Light_dm.sendCommand(OFF)

        F2_Hallway_Light_dm.sendCommand(OFF)

        GF_Hallway2_Light_dm.sendCommand(OFF)

        GF_Hallway3_Light_dm.sendCommand(OFF)           

    }

end

//####################################################################################################################################

rule “Beleuchtung_TagScene”

when

    Channel 'astro:sun:nightlight:rise#event' triggered START

then {

        SceneF2_Hallway_Light_Night.sendCommand(OFF)            

    }

end

rule “Beleuchtung_NachtScene”

when

    Channel 'astro:sun:nightlight:set#event' triggered START

then {

        SceneF2_Hallway_Light_Night.sendCommand(ON)         

    }

end

//####################################################################################################################################

rule “Beleuchtung_Nachtmodus_aus_an”

when

Item F2_Hallway_Light_sw changed to ON

then

if (SceneF2_Hallway_Light_Night.state == OFF) {

    F2_Hallway_Light_swday.sendCommand(ON)

}

end

rule “Beleuchtung_Nachtmodus_aus_aus”

when

Item F2_Hallway_Light_sw changed to OFF

then

{   

    F2_Hallway_Light_swday.sendCommand(OFF)

}

end

//####################################################################################################################################

#9

Please use code fences (see #12 here). Without them, logs and code are pretty much unreadable. You can edit your previous posts to add them.

#10

I think this all boils down to an issue with your Z-Wave network or configuration of the binding, since the Astro binding is triggering and your rule is executing. Do your Z-Wave Things show as ONLINE?

#11

All things are schown online, but not working.
Z-Wave are the blinds, handled by another rule.

One rule handle only Hue and another the z-ware. The first executed rule, is the Hue (zigbee) rule.

This is the oh.log between the Restart yesterday evening and this morning

2020-07-28 23:18:10.913 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home
2020-07-28 23:18:10.961 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2020-07-28 23:18:11.078 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2020-07-28 23:18:11.103 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:18:12.347 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2020-07-28 23:18:40.968 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing ‘zwave:serial_zstick:6bfce7b4’ takes more than 5000ms.
2020-07-28 23:18:41.992 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2020-07-28 23:18:42.729 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2020-07-28 23:18:42.768 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2020-07-28 23:18:42.805 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2020-07-28 23:19:40.686 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.items’
2020-07-28 23:19:41.717 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘rrd4j.persist’
2020-07-28 23:19:42.778 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.sitemap’
2020-07-28 23:19:43.330 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘tradfri.things’
2020-07-28 23:19:43.503 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘modbus.things’
2020-07-28 23:19:43.558 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.things’
2020-07-28 23:19:47.773 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-07-28 23:19:50.616 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.10:8080
2020-07-28 23:19:50.620 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.10:8443
2020-07-28 23:19:54.955 [WARN ] [iscovery.TradfriDiscoveryParticipant] - Discovered Tradfri gateway doesn’t have an IP address: [ServiceInfoImpl@12660985 name: ‘gw-b8d7af2b20f3._coap._udp.local.’ address: ‘(null):0’ status: ‘DNS: JmDNS-/192.168.1.10 [/192.168.1.10] state: probing 1 task: null’, has NO data
gw-b8d7af2b20f3._coap._udp.local.: ]
2020-07-28 23:19:55.274 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 15 seconds
2020-07-28 23:19:55.433 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 15 seconds
2020-07-28 23:19:59.317 [INFO ] [ternal.handler.TradfriGatewayHandler] - Received pre-shared key for gateway ‘192.168.1.19’
2020-07-28 23:20:04.458 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=FORECASTIO,apiKey=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa]
2020-07-28 23:20:04.461 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=OPENWEATHERMAP,apiKey=aaaaaaaaaaaaaaaaaaaaaaaaaaaaa]
2020-07-28 23:20:04.463 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=FORECASTIO,language=de,updateInterval=5,latitude=50.828483,longitude=7.214354,locationId=home,name=Lohmar]
2020-07-28 23:20:06.200 [INFO ] [b.core.service.AbstractActiveService] - FritzboxTr064 Refresh Service has been started
2020-07-28 23:20:06.232 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2020-07-28 23:20:06.863 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.051 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-28 23:20:07.310 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.383 [INFO ] [rnal.service.RemoteControllerService] - Using None interface
2020-07-28 23:20:07.577 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 5 minutes
2020-07-28 23:20:08.022 [INFO ] [io.hueemulation.internal.ConfigStore] - Using discovery ip 192.168.3.10
2020-07-28 23:20:08.025 [INFO ] [io.hueemulation.internal.ConfigStore] - Hue Emulation pairing disabled
2020-07-28 23:20:09.605 [WARN ] [ulation.internal.HueEmulationService] - The UPnP Server service has not been started!
2020-07-28 23:20:09.614 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-07-28 23:20:10.293 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 127.0.0.1:8080
2020-07-28 23:20:10.578 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-07-28 23:20:11.070 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-07-28 23:20:11.256 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2020-07-28 23:20:12.152 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:20:16.838 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-07-28 23:20:16.839 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-07-28 23:20:17.307 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2020-07-28 23:20:17.666 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-07-28 23:20:17.916 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-07-28 23:20:19.969 [WARN ] [.serialmessage.ZWaveCommandProcessor] - SerialMessage class null is not implemented!
2020-07-28 23:20:19.971 [WARN ] [ve.internal.protocol.ZWaveController] - TODO: Implement processing of Request Message = – (0xa)
2020-07-28 23:20:19.975 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 13: Not initialized (ie node unknown), ignoring message.
2020-07-28 23:20:19.978 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 13: Not initialized (ie node unknown), ignoring message.
2020-07-28 23:20:20.824 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 16: Restore from config: Error. Data invalid, ignoring config.
2020-07-28 23:20:20.844 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 4: Restore from config: Error. Data invalid, ignoring config.
2020-07-28 23:20:22.208 [ERROR] [io.openhabcloud.internal.CloudClient] - Error connecting to the openHAB Cloud instance: {}
io.socket.engineio.client.EngineIOException: xhr poll error
at io.socket.engineio.client.Transport.onError(Transport.java:63) [bundleFile:?]
at io.socket.engineio.client.transports.PollingXHR.access$100(PollingXHR.java:26) [bundleFile:?]
at io.socket.engineio.client.transports.PollingXHR$6$1.run(PollingXHR.java:140) [bundleFile:?]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [bundleFile:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_262]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_262]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_262]
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_262]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_262]
at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:1.8.0_262]
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:467) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:461) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1146) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl.access$300(SSLSocketImpl.java:72) ~[?:1.8.0_262]
at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:833) ~[?:1.8.0_262]
at okio.Okio$2.read(Okio.java:139) ~[?:?]
at okio.AsyncTimeout$2.read(AsyncTimeout.java:237) ~[?:?]
at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345) ~[?:?]
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217) ~[?:?]
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211) ~[?:?]
at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189) ~[?:?]
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:75) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92) ~[?:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67) ~[?:?]
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:185) ~[?:?]
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:135) ~[?:?]
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
… 3 more
2020-07-28 23:20:22.285 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:20:22.515 [WARN ] [okhttp3.OkHttpClient ] - A connection to https://myopenhab.org/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);
2020-07-28 23:20:23.781 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = aaaaaaaaaaaaaaaaaaaaaaaaaaaaaa, base URL = http://localhost:8080)
2020-07-28 23:21:12.555 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02BR_display.rules’
2020-07-28 23:21:13.669 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02BR_Rollo.rules’
2020-07-28 23:21:18.028 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘aurora.rules’
2020-07-28 23:21:19.261 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02brlight.rules’
2020-07-28 23:21:19.422 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘presence.rules’
2020-07-28 23:21:19.428 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model ‘presence.rules’ is either empty or cannot be parsed correctly!
2020-07-28 23:21:21.303 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘lights_floor.rules’
2020-07-28 23:21:26.054 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘fasanenweg.rules’
2020-07-28 23:21:27.172 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘02WC_Light.rules’
2020-07-28 23:50:05.395 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-29 00:16:03.223 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-29 06:53:01.872 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Deleting weatherJob-home
2020-07-29 06:53:02.084 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2020-07-29 06:53:02.122 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = a89b7181-43e5-4d9a-a07c-d77a74869f96, base URL = http://localhost:8080)
2020-07-29 06:53:02.636 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down

This are the events logged in the morning, during the light rule execution. The Lights (zigbee, hue) in the floor are switched on at 100%, for OH the lights are shown as switched off.
The thing status is online.
The execution of the bilds will run at 6:30 but this is not running anymore.

2020-07-29 05:59:57.355 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-07-29T05:58:57.295+0200 to 2020-07-29T05:59:57.301+0200
2020-07-29 06:00:00.016 [vent.ChannelTriggeredEvent] - astro:sun:nightlight:rise#event triggered START
2020-07-29 06:00:00.020 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START
2020-07-29 06:00:00.030 [ome.event.ItemCommandEvent] - Item ‘SceneF2_Hallway_Light_Night’ received command OFF
2020-07-29 06:00:00.120 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_dm’ received command 100
2020-07-29 06:00:00.124 [vent.ItemStateChangedEvent] - SceneF2_Hallway_Light_Night changed from ON to OFF
2020-07-29 06:00:00.131 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_co’ received command 15
2020-07-29 06:00:00.135 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become 100
2020-07-29 06:00:00.186 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_dm’ received command 100
2020-07-29 06:00:00.257 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_dm’ received command 100
2020-07-29 06:00:00.262 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_co’ received command 15
2020-07-29 06:00:00.286 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_dm’ received command 100
2020-07-29 06:00:00.291 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_co’ received command 15
2020-07-29 06:00:00.294 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_co predicted to become 15
2020-07-29 06:00:00.296 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become 100
2020-07-29 06:00:00.332 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:00.334 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become 100
2020-07-29 06:00:00.347 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_co predicted to become 0
2020-07-29 06:00:00.349 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become 100
2020-07-29 06:00:00.378 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_co predicted to become 0
2020-07-29 06:00:00.380 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 0 to 100
2020-07-29 06:00:00.382 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 0 to 100
2020-07-29 06:00:00.384 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 0 to 100
2020-07-29 06:00:01.675 [vent.ItemStateChangedEvent] - F2_Hallway_Light_sw changed from OFF to ON
2020-07-29 06:00:01.678 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:01.680 [vent.ItemStateChangedEvent] - F2_Hallway_Light_swday changed from OFF to ON
2020-07-29 06:00:01.682 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:01.709 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_swday’ received command ON
2020-07-29 06:00:01.712 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 100 to 28
2020-07-29 06:00:01.714 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_swday predicted to become ON
2020-07-29 06:00:02.499 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:02.501 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 28 to 100
2020-07-29 06:00:02.504 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_sw changed from OFF to ON
2020-07-29 06:00:02.506 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 100 to 28
2020-07-29 06:00:03.554 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 28 to 100
2020-07-29 06:00:03.851 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.4 to 83.2
2020-07-29 06:00:04.679 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:04.681 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 1
2020-07-29 06:00:04.683 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 100
2020-07-29 06:00:08.335 [vent.ItemStateChangedEvent] - Temperature changed from 13.43 to 13.46
2020-07-29 06:00:08.338 [vent.ItemStateChangedEvent] - Clouds changed from 31.00 to 30.00
2020-07-29 06:00:08.341 [vent.ItemStateChangedEvent] - LastUpdate changed from 2020-07-29T05:55:08.293+0200 to 2020-07-29T06:00:08.274+0200
2020-07-29 06:00:08.344 [vent.ItemStateChangedEvent] - ObservationTime changed from 2020-07-29T05:55:08.000+0200 to 2020-07-29T06:00:08.000+0200
2020-07-29 06:00:10.486 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 0.030017317704953698 to 0.06399685064567535
2020-07-29 06:00:13.850 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 83.2 to 76.2

the switch off command what is initialized now from the rule is not executed on the light, the stay switched on. no other light is switchable anymore from OH, after restart it’s working fine.

2020-07-29 06:00:15.189 [ome.event.ItemCommandEvent] - Item ‘FF_Hallway_Light_dm’ received command OFF
2020-07-29 06:00:15.233 [ome.event.ItemCommandEvent] - Item ‘F2_Hallway_Light_dm’ received command OFF
2020-07-29 06:00:15.249 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway2_Light_dm’ received command OFF
2020-07-29 06:00:15.251 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become OFF
2020-07-29 06:00:15.274 [ome.event.ItemCommandEvent] - Item ‘GF_Hallway3_Light_dm’ received command OFF
2020-07-29 06:00:15.304 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become OFF
2020-07-29 06:00:15.335 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become OFF
2020-07-29 06:00:15.345 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become OFF
2020-07-29 06:00:15.360 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 100 to 0
2020-07-29 06:00:15.361 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 100 to 0
2020-07-29 06:00:15.363 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 100 to 0
2020-07-29 06:00:15.364 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 100 to 0

This is the rule which handles the lights, seen in events.log.


rule "Beleuchtung_Tag"
	when
		Channel 'astro:sun:home:rise#event' triggered START
	then {
			FF_Hallway_Light_dm.sendCommand(100)
			FF_Hallway_Light_co.sendCommand(15)
			F2_Hallway_Light_dm.sendCommand(100)
			// Treppe UG
            GF_Hallway2_Light_dm.sendCommand(100)
            GF_Hallway2_Light_co.sendCommand(15)
            // Flur UG
            GF_Hallway3_Light_dm.sendCommand(100)
            GF_Hallway3_Light_co.sendCommand(15)
            // warten zum ausschalten
            Thread::sleep(15000)
			FF_Hallway_Light_dm.sendCommand(OFF)
			F2_Hallway_Light_dm.sendCommand(OFF)
			GF_Hallway2_Light_dm.sendCommand(OFF)
            GF_Hallway3_Light_dm.sendCommand(OFF)			
		}
end
//####################################################################################################################################

Sorry for the wrong format in my last post. :frowning:

#12

Could you be more specific about what you mean by “not working”?

Do the restarts occur at the same time every day? What was the time of the restart on 07-27? Are you using an SD card? So, after the restarts, neither zwave or Hue devices respond to changes in the UI or rules?

#13

What do the lights actually do?
Where in “OH” are you looking, to see what they are shown as?

Picking one example light, I can see your rule that turns it on at sunrise

events

Interpretation -

  • Sunrise event, triggers rules, issues commands to dozens of lights
  • Item gets command 100
  • Autoupdate predicts state
  • Prediction applied to Item state
    That’s all over in a few milliseconds. Almost 2 seconds later -
  • Item gets update from real device, it hasn’t done the command yet, is still in old state
    A second after that -
  • Item gets update from real device, it has done the command now.

This all looks ordinary enough for dimming devices and a busy network handling many commands.

  • Note that at 06:00:13.850 your network is still dealing with the effects on other devices of handling a dozen commands

Now, for some reason, 15 seconds after sunrise, you issue more commands. Is this some other rule at work, that you haven’t shown us? Something to do with scenes perhaps?

  • Item recives command, 0 this time
  • Autoupdate does its prediction
  • Prediction applied to Item
  • Unless you have cut off more events.log here - there is no obvious response from the device this time. Although you would have to find out if it actually responded only with 0 state this time, so there was no change to be logged.

Maybe the device doesn’t like conflicting commands within a few seconds.
Maybe the binding or network is still busy handling the previous stuff. Maybe this new command is lost, maybe it is just queued and delayed - you would have to look closer to find out.

In summary, I’m not too surprised things go wrong if you issue a couple of dozen commands within a few seconds.
What is the purpose of turn on then off for a few seconds?
What triggers that off command -is that the thing that has changed for you, less time allowed for first action to complete before throwing more at it?
Astronomical events change in time over 4 months.

#14

I checked all astro things an rules if the is something running at same time, but there is nothing
At night runs the “Beleuchtung_Nacht” rule, the “Thread::sleep(15000)” is exactly for waiting the network to handle all commands.

The sense of this rules is changeing the light intensity during day and night. Because the Hue hub don’t do this I handle this with OH.
rules

//####################################################################################################################################
rule "Beleuchtung_Nacht"
	when
		Channel 'astro:sun:home:set#event' triggered START
	then {
			FF_Hallway_Light_dm.sendCommand(1)
			FF_Hallway_Light_co.sendCommand(60)
			F2_Hallway_Light_dm.sendCommand(1)
			// Treppe UG
			GF_Hallway2_Light_dm.sendCommand(1)
			GF_Hallway2_Light_co.sendCommand(60)
			// Flur UG
			GF_Hallway3_Light_dm.sendCommand(1)
			GF_Hallway3_Light_co.sendCommand(60)
			// warten zum ausschalten
			Thread::sleep(15000)
			FF_Hallway_Light_dm.sendCommand(OFF)
			F2_Hallway_Light_dm.sendCommand(OFF)
			GF_Hallway2_Light_dm.sendCommand(OFF)
			GF_Hallway3_Light_dm.sendCommand(OFF)
			}
end

rule "Beleuchtung_Tag"
	when
		Channel 'astro:sun:home:rise#event' triggered START
	then {
			FF_Hallway_Light_dm.sendCommand(100)
			FF_Hallway_Light_co.sendCommand(15)
			F2_Hallway_Light_dm.sendCommand(100)
			// Treppe UG
			GF_Hallway2_Light_dm.sendCommand(100)
			GF_Hallway2_Light_co.sendCommand(15)
			// Flur UG
			GF_Hallway3_Light_dm.sendCommand(100)
			GF_Hallway3_Light_co.sendCommand(15)
			// warten zum ausschalten
			Thread::sleep(15000)
			FF_Hallway_Light_dm.sendCommand(OFF)
			F2_Hallway_Light_dm.sendCommand(OFF)
			GF_Hallway2_Light_dm.sendCommand(OFF)
			GF_Hallway3_Light_dm.sendCommand(OFF)
		}
end
//####################################################################################################################################

rule "Beleuchtung_TagScene"
	when
		Channel 'astro:sun:nightlight:rise#event' triggered START
	then {
			SceneF2_Hallway_Light_Night.sendCommand(OFF)
		}
end

rule "Beleuchtung_NachtScene"
	when
		Channel 'astro:sun:nightlight:set#event' triggered START
	then {
			SceneF2_Hallway_Light_Night.sendCommand(ON)
		}
end
//####################################################################################################################################

rule "Beleuchtung_Nachtmodus_aus_an"
when
	Item F2_Hallway_Light_sw changed to ON
then
    if (SceneF2_Hallway_Light_Night.state == OFF) {
		F2_Hallway_Light_swday.sendCommand(ON)
	}
end

rule "Beleuchtung_Nachtmodus_aus_aus"
when
	Item F2_Hallway_Light_sw changed to OFF
then
	{	
		F2_Hallway_Light_swday.sendCommand(OFF)
	}
end
//####################################################################################################################################

events.log

2020-07-29 21:19:00.004 [vent.ChannelTriggeredEvent] - astro:sun:nightlight:daylight#event triggered END
2020-07-29 21:19:00.014 [vent.ChannelTriggeredEvent] - astro:sun:home:daylight#event triggered END
2020-07-29 21:19:00.019 [vent.ChannelTriggeredEvent] - astro:sun:fenster02br:daylight#event triggered END
2020-07-29 21:19:00.022 [vent.ChannelTriggeredEvent] - astro:sun:fensterwz:daylight#event triggered END
2020-07-29 21:19:00.026 [vent.ChannelTriggeredEvent] - astro:sun:home:set#event triggered START
2020-07-29 21:19:00.031 [vent.ItemStateChangedEvent] - Day_Phase changed from DAYLIGHT to SUN_SET
2020-07-29 21:19:00.168 [ome.event.ItemCommandEvent] - Item 'FF_Hallway_Light_dm' received command 1
2020-07-29 21:19:00.176 [ome.event.ItemCommandEvent] - Item 'FF_Hallway_Light_co' received command 60
2020-07-29 21:19:00.238 [ome.event.ItemCommandEvent] - Item 'F2_Hallway_Light_dm' received command 1
2020-07-29 21:19:00.258 [ome.event.ItemCommandEvent] - Item 'GF_Hallway2_Light_dm' received command 1
2020-07-29 21:19:00.267 [ome.event.ItemCommandEvent] - Item 'GF_Hallway2_Light_co' received command 60
2020-07-29 21:19:00.298 [ome.event.ItemCommandEvent] - Item 'GF_Hallway3_Light_dm' received command 1
2020-07-29 21:19:00.307 [ome.event.ItemCommandEvent] - Item 'GF_Hallway3_Light_co' received command 60
2020-07-29 21:19:00.310 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become 1
2020-07-29 21:19:00.355 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_co predicted to become 15
2020-07-29 21:19:00.359 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become 1
2020-07-29 21:19:00.397 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become 1
2020-07-29 21:19:00.412 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_co predicted to become 0
2020-07-29 21:19:00.415 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become 1
2020-07-29 21:19:00.437 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_co predicted to become 0
2020-07-29 21:19:00.440 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 0 to 1
2020-07-29 21:19:00.443 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 0 to 1
2020-07-29 21:19:00.445 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 0 to 1
2020-07-29 21:19:00.448 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 0 to 1
2020-07-29 21:19:01.853 [vent.ItemStateChangedEvent] - FF_Hallway_Light_sw changed from OFF to ON
2020-07-29 21:19:01.856 [vent.ItemStateChangedEvent] - F2_Hallway_Light_sw changed from OFF to ON
2020-07-29 21:19:01.860 [vent.ItemStateChangedEvent] - F2_Hallway_Light_swday changed from OFF to ON
2020-07-29 21:19:02.167 [ome.event.ItemCommandEvent] - Item 'F2_Hallway_Light_swday' received command ON
2020-07-29 21:19:02.170 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_swday predicted to become ON
2020-07-29 21:19:02.557 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_sw changed from OFF to ON
2020-07-29 21:19:04.440 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.2 to 80.8
2020-07-29 21:19:05.060 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.4342474976992164 to -0.46815591026760567
2020-07-29 21:19:14.445 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 80.8 to 62.2
2020-07-29 21:19:15.113 [ome.event.ItemCommandEvent] - Item 'FF_Hallway_Light_dm' received command OFF
2020-07-29 21:19:15.163 [ome.event.ItemCommandEvent] - Item 'F2_Hallway_Light_dm' received command OFF
2020-07-29 21:19:15.179 [ome.event.ItemCommandEvent] - Item 'GF_Hallway2_Light_dm' received command OFF
2020-07-29 21:19:15.202 [ome.event.ItemCommandEvent] - Item 'GF_Hallway3_Light_dm' received command OFF
2020-07-29 21:19:15.204 [nt.ItemStatePredictedEvent] - FF_Hallway_Light_dm predicted to become OFF
2020-07-29 21:19:15.230 [nt.ItemStatePredictedEvent] - F2_Hallway_Light_dm predicted to become OFF
2020-07-29 21:19:15.255 [nt.ItemStatePredictedEvent] - GF_Hallway2_Light_dm predicted to become OFF
2020-07-29 21:19:15.264 [nt.ItemStatePredictedEvent] - GF_Hallway3_Light_dm predicted to become OFF
2020-07-29 21:19:15.277 [vent.ItemStateChangedEvent] - FF_Hallway_Light_dm changed from 1 to 0
2020-07-29 21:19:15.279 [vent.ItemStateChangedEvent] - F2_Hallway_Light_dm changed from 1 to 0
2020-07-29 21:19:15.281 [vent.ItemStateChangedEvent] - GF_Hallway2_Light_dm changed from 1 to 0
2020-07-29 21:19:15.282 [vent.ItemStateChangedEvent] - GF_Hallway3_Light_dm changed from 1 to 0
2020-07-29 21:19:20.058 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.46815591026760567 to -0.5020245514462545
2020-07-29 21:19:23.077 [vent.ItemStateChangedEvent] - Current_DateTime changed from 2020-07-29T21:18:23.043+0200 to 2020-07-29T21:19:23.049+0200
2020-07-29 21:19:23.081 [vent.ItemStateChangedEvent] - NTP_time changed from 2020-07-29T21:18:23.043+0200 to 2020-07-29T21:19:23.049+0200
2020-07-29 21:19:23.084 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-07-29T21:18:23.043+0200 to 2020-07-29T21:19:23.049+0200
2020-07-29 21:19:24.444 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.2 to 62.6
2020-07-29 21:19:34.448 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.6 to 63
2020-07-29 21:19:35.055 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.5020245514462545 to -0.5358848387837719
2020-07-29 21:19:44.439 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 63 to 64.6
2020-07-29 21:19:50.045 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.5358848387837719 to -0.5697098707152228
2020-07-29 21:19:54.440 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 64.6 to 64.5
2020-07-29 21:20:04.440 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 64.5 to 78
2020-07-29 21:20:05.072 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.5697098707152228 to -0.6035919717065578
2020-07-29 21:20:14.442 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 78 to 61.9
2020-07-29 21:20:20.071 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.6035919717065578 to -0.6373891371542383
2020-07-29 21:20:23.090 [vent.ItemStateChangedEvent] - Current_DateTime changed from 2020-07-29T21:19:23.049+0200 to 2020-07-29T21:20:23.063+0200
2020-07-29 21:20:23.094 [vent.ItemStateChangedEvent] - NTP_time changed from 2020-07-29T21:19:23.049+0200 to 2020-07-29T21:20:23.063+0200
2020-07-29 21:20:23.098 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-07-29T21:19:23.049+0200 to 2020-07-29T21:20:23.063+0200
2020-07-29 21:20:24.440 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 61.9 to 73.9
2020-07-29 21:20:34.434 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 73.9 to 62.2
2020-07-29 21:20:35.044 [vent.ItemStateChangedEvent] - Sun_Elevation changed from -0.6373891371542383 to -0.67112382053976
2020-07-29 21:20:44.442 [vent.ItemStateChangedEvent] - F2_Office_AC01_watts changed from 62.2 to 68.6
#15

Oh yes, I’d missed that.
Alright, so your morning rule turns on lots of lights.
Then fifteen seconds later, turns them off again.

We can see in your events.log that your system is still busy dealing with the first commands after at least fourteen seconds.
Maybe you should wait a little longer.

#16

Hi guys, I tested yesterday a lot of different scenarios for fixing my problem.

The short-term solution for me was using the 2020-05-27-raspios-buster-lite-armhf OS image uncomment “deb http://archive.raspberrypi.org/debian/ buster main” in “/etc/apt/sources.list.d/raspi.list” before updating/upgrading and installing the system. My actual Kernel for the system is “4.19.118-v7+”.

I have now two absolutely identic systems, excepting the updates provided by the archive.raspberrypi.org repo, one with 4.19.118-v7+ and one with 5.4.51-v7+ Kernel, the system with the 5.4.51-v7+ stops working. Honestly, I’m not very happy about this solution.