JjS
November 16, 2015, 8:22am
1
I noticed that after some time of running (say two and a half days) openHAB is no longer controlling the z-wave devices. I can change their states in the GUI, I see it reflected in the log, but the phisical items do not react. The same applies to the commands send by rules (i.e. via cron).
Oddly enough, I still see in the debug log entries like:06:39:32.992 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ] - ZwaveIncomingEvent 06:39:32.992 [INFO ] [runtime.busevents :26 ] - Salon_Lamp1_El_W state updated to 0.1 06:39:32.992 [DEBUG] [WaveController$ZWaveSendThread:1287 ] - NODE 17: Response processed after 50ms/4686ms.
so the z-wave network seems to be operational.
After restarting openHAB service everything gets back to normal.
My setup is OH 1.8 compiled from GIT Hub sources two days ago, running on VirtualBox guest CentOS 7, with Aeon Labs Gen5 USB z-wave controller.
Any hints how to nail down the problem?
JjS
November 28, 2015, 8:59am
2
Happened again, so I bump the topic. After some time the z-wave network stops responding to command. This can be spotted by lack of any updates comming from the network. Last message that was processed properly was at 07:08:47.909
Now the last z-wave related entries in the log look like this:07:08:47.723 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:109 ] - NODE 4: Received Meter Request 07:08:47.723 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:157 ] - NODE 4: Meter: Type=Electric(1), Scale=V(4), Value=229.168 07:08:47.723 [DEBUG] [b.z.i.protocol.ZWaveController:595 ] - Notifying event listeners: ZWaveMeterValueEvent 07:08:47.723 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ] - ZwaveIncomingEvent 07:08:47.724 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 229.168 07:08:47.808 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 14 00 04 00 04 0E 32 02 A1 6C 00 00 06 B5 00 00 00 00 00 00 AB 07:08:47.809 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1 07:08:47.809 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0 07:08:47.809 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 14 00 04 00 04 0E 32 02 A1 6C 00 00 06 B5 00 00 00 00 00 00 AB 07:08:47.809 [DEBUG] [b.z.i.protocol.ZWaveController:190 ] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 04 0E 32 02 A1 6C 00 00 06 B5 00 00 00 00 00 00 07:08:47.809 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:109 ] - NODE 4: Received Meter Request 07:08:47.809 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:157 ] - NODE 4: Meter: Type=Electric(1), Scale=A(5), Value=1.717 07:08:47.809 [DEBUG] [b.z.i.protocol.ZWaveController:595 ] - Notifying event listeners: ZWaveMeterValueEvent 07:08:47.809 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ] - ZwaveIncomingEvent 07:08:47.809 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 1.717 07:08:47.908 [DEBUG] [ZWaveMultiLevelSwitchConverter:91 ] - NODE 38: Generating poll message for SWITCH_MULTILEVEL for node 0 endpoint {} 07:08:47.909 [DEBUG] [b.z.i.protocol.ZWaveController:898 ] - Callback ID = 38 07:08:47.909 [DEBUG] [b.z.i.protocol.ZWaveController:580 ] - Enqueueing message. Queue length = 1 07:08:47.909 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0 07:08:47.909 [DEBUG] [WaveController$ZWaveSendThread:1228 ] - NODE 38: Sending REQUEST Message = 01 09 00 13 26 02 26 02 25 26 E6 07:08:47.909 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 18 00 04 00 04 12 60 0D 01 00 32 02 21 64 00 04 1E 2F 00 05 00 04 1E 2F E9 07:08:52.909 [DEBUG] [i.c.ZWaveBinarySwitchConverter:70 ] - NODE 18: Generating poll message for SWITCH_BINARY, endpoint 2 07:08:52.909 [DEBUG] [.ZWaveBinarySwitchCommandClass:125 ] - NODE 18: Creating new message for application command SWITCH_BINARY_GET 07:08:52.909 [DEBUG] [.z.internal.protocol.ZWaveNode:623 ] - NODE 18: Encapsulating message, instance / endpoint 2 07:08:52.909 [DEBUG] [ZWaveMultiInstanceCommandClass:560 ] - NODE 18: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2 07:08:52.909 [DEBUG] [b.z.i.protocol.ZWaveController:898 ] - Callback ID = 39 07:08:52.909 [DEBUG] [b.z.i.protocol.ZWaveController:580 ] - Enqueueing message. Queue length = 1 07:10:12.916 [DEBUG] [z.internal.ZWaveNetworkMonitor:341 ] - NODE 4: Sending periodic PING. 07:10:12.916 [DEBUG] [c.ZWaveNoOperationCommandClass:72 ] - NODE 4: Creating new message for command No Operation 07:10:12.916 [DEBUG] [b.z.i.protocol.ZWaveController:898 ] - Callback ID = 40 07:10:12.916 [DEBUG] [b.z.i.protocol.ZWaveController:580 ] - Enqueueing message. Queue length = 2 07:10:17.916 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 07:10:22.916 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 07:10:27.917 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 07:10:32.918 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 07:10:37.918 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 07:10:42.918 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions.
After restarting openHAB system resumes normal operation.
Any hints?
