Yes, but what about the others? Or are they working ok?
So those devices are configured ok in the database.
If I look at one of these events -:
2018-12-16 20:21:34.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-16 20:21:39.236 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 14 09 71 05 00 00 00 FF 07 08 00 6D
2018-12-16 20:21:39.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 09 71 05 00 00 00 FF 07 08 00
2018-12-16 20:21:39.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 09 71 05 00 00 00 FF 07 08 00
2018-12-16 20:21:39.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-16 20:21:39.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2018-12-16 20:21:39.570 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2018-12-16 20:21:39.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2018-12-16 20:21:39.584 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_ALARM
2018-12-16 20:21:39.593 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2018-12-16 20:21:39.604 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 20: NOTIFICATION report - 0 = 0, event=8, status=255, plen=0
2018-12-16 20:21:39.607 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 20: Alarm Type = BURGLAR (0)
2018-12-16 20:21:39.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2018-12-16 20:21:39.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18962ac.
2018-12-16 20:21:39.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-16 20:21:39.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-16 20:21:39.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-16 20:21:39.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-16 20:21:59.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@a23f09
The processing itself looks fine, but I see nothing at all from the converter which is what processes the alarms and converts this to the channel data. The converter gets called for each channel that is linked, and nearly the first line is a log statement which shows that the converter is not called -:
logger.debug("NODE {}: Alarm converter processing {}", eventAlarm.getNodeId(), eventAlarm.getReportType());
The fact that this is not being called seems to indicate that the channels are not linked. Are you sure that the channels are configured correctly, and is there any error when the binding starts?
after i upgraded it looks like motion are reported again
debug.log (671.0 KB) (its a.gz)
Events from 21:30 -> 22:30 should indicate that
tbh, i dont know why its so flicky.
IĀ“m running openhabian on a rapi 3b 1.2 with the razbian z-wave module.
I use PaperUI to create the items binding the channels. IĀ“m not sure how you are to do that wrong as i accept the default name and values.
I get no error as create the items.
Whatās interesting is that in this log, there are no channel updates to ANY channel before 20:50, then all channels work. This is not just linked to alarms - it was also all other channels (battery, thermostat, sensors,ā¦).
So, I think thereās something else going on - at least based on the logs youāve provided, the issue does not appear to be related to alarms.
See below - before 20:50 and after -:
If I look in the logs, I see at this time all your channels are linked -:
2018-12-16 20:49:59.135 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:faba8aa8:node8:basic_switch_binary linked - polling started.
2018-12-16 20:49:59.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:faba8aa8:node8:thermostat_setpoint_heating linked - polling started.
2018-12-16 20:49:59.135 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=473, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2018-12-16 20:49:59.145 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:faba8aa8:node8:config_decimal_param2 linked - polling started.
2018-12-16 20:49:59.164 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:faba8aa8:node8:thermostat_mode linked - polling started.
So, my guess is that something is causing the links to get lost. It could be a binding issue, or it could be external. I think itās unlikely to be the binding, but I could be wrong.
Hopefully the above has given you something to work on and see what you can findā¦
Cheers
Chris
@chris
Thank you for your time analyzing the logs.
If there are any external interferes that may cause outages that are known please let me know.
Timeline is correct. When i came home around 20:30 ish nothing worked. then i pulled down the latest openhab release from the openhabian-client. And 
(s) jumped arround again.
The bindings are probably ok as you say. They do work and make the things report. It may be something else in the server code that make things stop. idk as i only been using this system for less than a week.
Is there anyone else in the dev team that may be interested in the findings (or lack of them)?
I think we need to understand what is happening first. Either itās a binding issue, and then Iām interested, and no-one else will be, or itās an external issue, and then others will be interested, and Iāll probably let them get on with it 
Weāre still basically in the same position we were earlier - you need to get a log that captures part of the log working, and then it not working. You can use the log viewer on my website to view logs. You can search for the STATE UPDATE messages and see if they seem to stop at some point.
Once you can capture this, Iām happy to look at the logs and see whatās happening.
1 Like
Cheers Chris.
I will keep you posted with any findings.
1 Like
Woke up this morning (miracles do happen), House didnĀ“t. No sensors reported motion, and i had to manually turn on lights. WAF factor is dropping rapidly. I went ahead and rebooted the controller. The aeotecĀ“s reported in and motion activaton works. Fibaros did not.
All nodes were stuck in this state for some time.
Looked like they had lost their chan to item binding as well from looking in HABmin, PaperUI was all green. After some time, linkage appear to be normal again and sensors are working.
Could this be a result of the 2AM network heal?
Maybe Battery sensors need some TLC before they start working again after some time of inactivity?
I wired an aeotec sensor to test the thesis further.
Looks like my NODE 19 is struggling with something.
2018-12-17 04:17:32.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-17 04:17:32.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=DeleteReturnRoute[71], type=Response[1], dest=255, callback=0,$
2018-12-17 04:17:32.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=DeleteReturnRoute[71], type=Response[1], dest=255, callback=0, payload=00
2018-12-17 04:17:32.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1145: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 143
2018-12-17 04:17:32.097 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-17 04:17:32.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1145: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 143
2018-12-17 04:17:32.100 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=DeleteReturnRoute[71], type=Response[1], dest=255, callback=0, payload=00
2018-12-17 04:17:32.102 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 19: Got DeleteReturnRoute response.
2018-12-17 04:17:32.104 [DEBUG] [essage.DeleteReturnRouteMessageClass] - NODE 19: DeleteReturnRoute command failed.
2018-12-17 04:17:32.105 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1145: Transaction CANCELLED
2018-12-17 04:17:32.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-12-17 04:17:32.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: CANCEL while sending message. Requeueing - 2 attempts left!
2018-12-17 04:17:32.111 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1145: Transaction RESET with 2 retries remaining.
2018-12-17 04:17:32.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2018-12-17 04:17:32.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Added 1145 to queue - size 13
2018-12-17 04:17:32.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-12-17 04:17:32.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: TID 1145: Transaction not completed
2018-12-17 04:17:32.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-17 04:17:32.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-12-17 04:17:32.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-17 04:17:32.361 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 47 13 90 3E
2018-12-17 04:17:32.363 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 47 13 90 3E
2018-12-17 04:17:32.385 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-17 04:17:32.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-17 04:17:32.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-17 04:17:32.393 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 47 00 BD
2018-12-17 04:17:32.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-17 04:17:32.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-17 04:17:32.392 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-17 04:17:32.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue emptyGiven we donāt know what is happening, anything is possible, but in general, no - it should not be related.
There are basically two reasonably separated parts of the binding - the ZWave protocol, and the OH channels and interfaces. Things like the network heal have no influence on the OH side - they run solely in the protocol section, so there should be no interaction.
But you have a log right? If so, what does it show? It should be easy to tell when this happened if its the same thing I saw in your log from yesterday as NO channels were updating.
morning.log (108.9 KB) (.gz)
I used your log analyze tool. But from what i could tell everything looked like normal traffic. I can not tell from where the devices stop sending data.
The log is captured before i rebooted the Pi, and stuff started to work again.
The devices donāt stop sending data - that is always working. The data is sent, and the binding receives and processes the data, but it is not sent to the channels, so itās not available in the logs. Either the channels are unlinked, or something has gone wrong in the binding and itās lost the list of channels.
In this log, it was not normal - ever - so whatever the issue is occurred before this log started. This log has no channels at allā¦
Ok thats good in a way. So when i restart the pi, openhab get restarted and the channels get linked proper.
Same thing probably happened yesterday when i upgraded.
As I mentioned earlier, when i create the channel to item binding im using PaperUI and just accepting the default values. Maybe I should try to generate the links in HABmin?
The log leading to the last log i posted, maybe there are some clues there.
midnight-morning.log (835.6 KB) (.gz)
It should make no difference - HABmin an PaperUI use exactly the same commands to generate the links.
This reminds me of something I saw a long time ago, but havenāt experienced in quite a while. It was so long ago that I donāt even remember if it was the old version of the binding or the new one. I had seen a couple cases where the channels were not being linked when the binding started. I noticed it because none of my nodes were being polled. But, in those instances, it affected all my channels, not just the channels for one/some nodes. Probably unrelated to thisā¦
Hereās the post from back in July. Looks like it was on the new version of the binding.
I donāt think itās an issue with channel links - it looks like the internal messaging between the ZWave protocol part of the binding, and the OH part is not working.
@JAFone if you get a chance, can you do a grep over your logs for the following -:
Controller failed to register event handler
My guess at the moment is that there is some sort of issue during initialisation where the event listener is not registering. Or, it might be getting removedā¦
This last log was useful and does narrow things down a bit, but we basically still need to capture a log that shows this issue starting - does it start when the binding starts, or does it start at some other random time.
Another thing to grep for is -:
Attempting to add listener when controller is null
No such messages.
IĀ“ll let debug run over the night to see if i get the same issue tomorrow.
Ok, then we just need to catch when it starts to happen. Itās pretty obvious from the log viewer at least.