[Closed] Cause for not updating an item, even channel reports a status change

Hello @chris, I again and again have the situation that some of my zwave things do not update my items, even the logfile says that a status event has been processed. Have you an idea, why the program is processing a status change and not updating the item? I see one case not to update an item, when the old and the new value are same. Looks so as the binding no longer knows that an item has been connected to the channel ??
Is there anything I can activate more than DEBUG level for zwave binding for such a case?
I have not actively changed anything for this thing before. Only another restart earlier today (and in the last days).
Currently for me the only solution is mostly to restart OH, sometimes I have to do more (remove and re-discover thing) to get it again working.
Find here one example with 2 status changes of my motion sensor (first sets ON, second sets OFF) and in the event log there is no change of the item in the same time window. I had same case for power plugs too.

2019-02-10 16:15:11.695 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 20 01 FF 2C 
2019-02-10 16:15:11.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 FF 
2019-02-10 16:15:11.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 FF 
2019-02-10 16:15:11.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 16:15:11.721 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 71 05 07 FF 00 FF 07 08 00 00 9E 
2019-02-10 16:15:11.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:15:11.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0A 71 05 07 FF 00 FF 07 08 00 00 
2019-02-10 16:15:11.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-02-10 16:15:11.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:15:11.741 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_BASIC V1 BASIC_SET
2019-02-10 16:15:11.746 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 3: Basic report, value = 255
2019-02-10 16:15:11.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:15:11.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@69c619.
2019-02-10 16:15:11.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:15:11.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:15:11.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0A 71 05 07 FF 00 FF 07 08 00 00 
2019-02-10 16:15:11.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 16:15:11.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:15:11.787 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2019-02-10 16:15:11.791 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:15:11.796 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_ALARM V4 NOTIFICATION_REPORT
2019-02-10 16:15:11.799 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: NOTIFICATION report - 7 = 255, event=8, status=255, plen=0
2019-02-10 16:15:11.804 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: Alarm Type = BURGLAR (7)
2019-02-10 16:15:11.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:15:11.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1167cf5.
2019-02-10 16:15:11.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:15:11.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:15:11.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 16:15:11.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
...
2019-02-10 16:16:29.751 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 20 01 00 D3 
2019-02-10 16:16:29.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 00 
2019-02-10 16:16:29.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 00 
2019-02-10 16:16:29.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 16:16:29.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:16:29.766 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-02-10 16:16:29.769 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:16:29.773 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_BASIC V1 BASIC_SET
2019-02-10 16:16:29.776 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 3: Basic report, value = 0
2019-02-10 16:16:29.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:16:29.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1226ce9.
2019-02-10 16:16:29.785 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 03 0B 71 05 07 00 00 FF 07 00 01 08 00 60 
2019-02-10 16:16:29.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:16:29.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:16:29.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0B 71 05 07 00 00 FF 07 00 01 08 00 
2019-02-10 16:16:29.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 16:16:29.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 16:16:29.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0B 71 05 07 00 00 FF 07 00 01 08 00 
2019-02-10 16:16:29.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 16:16:29.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:16:29.809 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2019-02-10 16:16:29.812 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:16:29.814 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_ALARM V4 NOTIFICATION_REPORT
2019-02-10 16:16:29.817 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: NOTIFICATION report - 7 = 0, event=0, status=255, plen=1
2019-02-10 16:16:29.820 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: Alarm Type = BURGLAR (7)
2019-02-10 16:16:29.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:16:29.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@796eb0.
2019-02-10 16:16:29.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:16:29.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 16:16:29.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 

And for same time window the events log part without updateing my item:

2019-02-10 16:14:59.375 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 3.5 to 3.4
2019-02-10 16:14:59.382 [vent.ItemStateChangedEvent] - RasPiOpenHAB_CpuLoad changed from 3.5 to 3.4
2019-02-10 16:14:59.389 [vent.ItemStateChangedEvent] - RasPiOpenHAB_MemoryUsedPercent changed from 57.4 to 57.5
2019-02-10 16:19:59.439 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 3.4 to 3.3
2019-02-10 16:19:59.445 [vent.ItemStateChangedEvent] - RasPiOpenHAB_CpuLoad changed from 3.4 to 3.3
2019-02-10 16:19:59.456 [vent.ItemStateChangedEvent] - RasPiOpenHAB_MemoryUsedPercent changed from 57.5 to 57.7
2019-02-10 16:24:59.428 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 3.3 to 3.2
2019-02-10 16:24:59.438 [vent.ItemStateChangedEvent] - RasPiOpenHAB_CpuLoad changed from 3.3 to 3.2
2019-02-10 16:24:59.444 [vent.ItemStateChangedEvent] - RasPiOpenHAB_SensorsCpuTemp changed from 58.0 to 57.5
2019-02-10 16:29:59.461 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 3.2 to 3.1

After a restart of OH:

2019-02-10 16:32:57.435 [temChannelLinkRemovedEvent] - Link 'Buero_Sensor_1_motion => zwave:device:b1506bc3:node3:basic_sensor_binary' has been removed.
...
2019-02-10 16:34:08.363 [.ItemChannelLinkAddedEvent] - Link 'Buero_Sensor_1_motion-zwave:device:b1506bc3:node3:basic_sensor_binary' has been added.
...
2019-02-10 16:35:20.099 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
with OpenHAB log:
2019-02-10 16:35:20.050 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 20 01 FF 2C 
2019-02-10 16:35:20.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 FF 
2019-02-10 16:35:20.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 20 01 FF 
2019-02-10 16:35:20.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 89: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-02-10 16:35:20.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:35:20.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-02-10 16:35:20.071 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:35:20.073 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_BASIC V1 BASIC_SET
2019-02-10 16:35:20.076 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 71 05 07 FF 00 FF 07 08 00 00 9E 
2019-02-10 16:35:20.076 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 3: Basic report, value = 255
2019-02-10 16:35:20.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-02-10 16:35:20.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0A 71 05 07 FF 00 FF 07 08 00 00 
2019-02-10 16:35:20.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BASIC, value = 255
2019-02-10 16:35:20.085 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:b1506bc3:node3:basic_sensor_binary to ON [OnOffType]
2019-02-10 16:35:20.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:35:20.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@768b32.
2019-02-10 16:35:20.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@768b32.
2019-02-10 16:35:20.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-10 16:35:20.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-10 16:35:20.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0A 71 05 07 FF 00 FF 07 08 00 00 
2019-02-10 16:35:20.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 89: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-02-10 16:35:20.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:REQUEST_NIF)
2019-02-10 16:35:20.109 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2019-02-10 16:35:20.111 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-02-10 16:35:20.112 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_ALARM V4 NOTIFICATION_REPORT
2019-02-10 16:35:20.115 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: NOTIFICATION report - 7 = 255, event=8, status=255, plen=0
2019-02-10 16:35:20.117 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: Alarm Type = BURGLAR (7)
2019-02-10 16:35:20.119 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2019-02-10 16:35:20.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 255
2019-02-10 16:35:20.124 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 3: Alarm converter processing NOTIFICATION
2019-02-10 16:35:20.127 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 3: Alarm converter NOTIFICATION event is 8, type OnOffType
2019-02-10 16:35:20.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-02-10 16:35:20.131 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@62c7c9.
2019-02-10 16:35:20.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@62c7c9.
2019-02-10 16:35:20.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-10 16:35:20.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-10 16:35:20.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 16:35:20.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

And here only the item changes of the last 3 days. 2 days ago a restart of the system had no impact, but this morning …?

	Line 801: 2019-02-08 12:17:01.632 [temChannelLinkRemovedEvent] - Link 'Buero_Sensor_1_motion => zwave:device:b1506bc3:node3:basic_sensor_binary' has been removed.
	Line 1058: 2019-02-08 12:18:11.478 [.ItemChannelLinkAddedEvent] - Link 'Buero_Sensor_1_motion-zwave:device:b1506bc3:node3:basic_sensor_binary' has been added.
	Line 1518: 2019-02-08 12:18:35.122 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from NULL to OFF
	Line 2026: 2019-02-08 15:04:24.494 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2030: 2019-02-08 15:05:35.308 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2043: 2019-02-08 15:05:53.316 [ome.event.ItemCommandEvent] - Item 'Buero_Sensor_1_motion' received command REFRESH
	Line 2050: 2019-02-08 15:06:16.483 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2059: 2019-02-08 15:08:31.475 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2063: 2019-02-08 15:09:19.203 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2064: 2019-02-08 15:10:36.129 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2065: 2019-02-08 15:12:10.478 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2070: 2019-02-08 15:14:08.239 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2071: 2019-02-08 15:16:02.732 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2101: 2019-02-08 15:27:23.963 [ome.event.ItemCommandEvent] - Item 'Buero_Sensor_1_motion' received command REFRESH
	Line 2121: 2019-02-08 15:30:02.662 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2131: 2019-02-08 15:34:15.815 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2134: 2019-02-08 15:37:27.981 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2135: 2019-02-08 15:37:39.616 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2152: 2019-02-08 15:38:50.433 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2153: 2019-02-08 15:40:13.820 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2163: 2019-02-08 15:41:24.632 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2164: 2019-02-08 15:41:36.472 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2165: 2019-02-08 15:42:58.879 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2166: 2019-02-08 15:43:08.497 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2170: 2019-02-08 15:45:11.176 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2171: 2019-02-08 15:45:23.801 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2181: 2019-02-08 15:46:40.765 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2186: 2019-02-08 15:47:09.069 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2194: 2019-02-08 15:48:21.818 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2195: 2019-02-08 15:48:33.133 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2198: 2019-02-08 15:49:48.175 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2202: 2019-02-08 15:50:22.632 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2207: 2019-02-08 15:51:33.391 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2406: 2019-02-08 17:53:22.900 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2407: 2019-02-08 17:54:33.698 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2408: 2019-02-08 17:54:42.254 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2410: 2019-02-08 17:56:03.182 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 2411: 2019-02-08 17:57:05.342 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 2414: 2019-02-08 17:58:20.352 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4034: 2019-02-09 11:08:00.346 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4044: 2019-02-09 11:09:11.149 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4269: 2019-02-09 13:30:26.067 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4277: 2019-02-09 13:31:36.781 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4307: 2019-02-09 13:39:49.358 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4308: 2019-02-09 13:41:00.092 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4322: 2019-02-09 13:46:26.072 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4329: 2019-02-09 13:47:36.776 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4330: 2019-02-09 13:47:48.316 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4334: 2019-02-09 13:49:10.599 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4337: 2019-02-09 13:52:47.432 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4341: 2019-02-09 13:53:58.152 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4343: 2019-02-09 13:54:29.654 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4344: 2019-02-09 13:55:44.815 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 4400: 2019-02-09 14:06:16.212 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 4409: 2019-02-09 14:08:35.765 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 6301: 2019-02-10 10:02:43.247 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 6315: 2019-02-10 10:04:01.282 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 6768: 2019-02-10 12:04:25.731 [temChannelLinkRemovedEvent] - Link 'Buero_Sensor_1_motion => zwave:device:b1506bc3:node3:basic_sensor_binary' has been removed.
	Line 7025: 2019-02-10 12:09:52.841 [.ItemChannelLinkAddedEvent] - Link 'Buero_Sensor_1_motion-zwave:device:b1506bc3:node3:basic_sensor_binary' has been added.
	Line 7471: 2019-02-10 12:10:12.981 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from NULL to OFF
	Line 8363: 2019-02-10 16:32:57.435 [temChannelLinkRemovedEvent] - Link 'Buero_Sensor_1_motion => zwave:device:b1506bc3:node3:basic_sensor_binary' has been removed.
	Line 8623: 2019-02-10 16:34:08.363 [.ItemChannelLinkAddedEvent] - Link 'Buero_Sensor_1_motion-zwave:device:b1506bc3:node3:basic_sensor_binary' has been added.
	Line 9100: 2019-02-10 16:34:33.133 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from NULL to OFF
	Line 9186: 2019-02-10 16:35:20.099 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 9190: 2019-02-10 16:36:38.128 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF
	Line 9238: 2019-02-10 16:46:10.113 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from OFF to ON
	Line 9239: 2019-02-10 16:47:28.159 [vent.ItemStateChangedEvent] - Buero_Sensor_1_motion changed from ON to OFF

Many thanks, Siggi

I mean I have one possible explanation for this behavior: This motion sensor is a battery driven thing, so the binding was waiting today for a NIF from the thing. Can it be that in such a case the item of the thing is not updated?

It’s impossible really to comment without knowing what version of the binding you are using, and what the device is that is sending the report. The binding matches reports against channels so I can’t just look at a log in isolation of other information.

Sorry.

Hello @chris, sorry for forgetting the basic.
The thing is a Vision ZSE40.

openhab> bundle:list | grep ZWave
247 x Active x  80 x 2.5.0.201901280820     x ZWave Binding

Find attached a link to the openhab logfile. There you can see for node 3 a phase of no state updates on the items.
https://1drv.ms/u/s!Apfsw6uW4hjmg4JKODjUWxZuE1dVnQ

@chris I wonder if this is related to the issue I was seeing when sometimes the framework doesn’t reliably/consistently call channelLinked. From what I’ve seen, sometimes the framework doesn’t call channelLinked for some things, sometimes it doesn’t call channelLinked for all things. See my post here.

As you can see from my edits in that post, I’ve seen this behavior several times now. While I was focused on the lack of polling due to this issue, isn’t it also true that the channel state won’t be updated if the binding doesn’t think the channel is linked (because it hasn’t been informed of the linkage by the framework)?

:slight_smile: I see following in my log file, which could be a hint of common cause:

2019-02-10 16:09:19.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2019-02-10 16:09:19.050 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

Can it be that this initialisation phase (caused by heal request or system restart) and parallel status events and/or parameter changes cause an issue? I do not know all these details, but I would assume that during the initialisation phase the thing should not sleep. But when I read the logfile correct it goes sleeping within the initialisation phase.

It could be. I thought that maybe the channels might not have been configured correctly, but it looks like it should be ok. So, maybe it is the fact that the channel isn’t linked.

This is only related to polling - not to the processing of the notifications.

Ideally, but it’s not possible to stop it, so the binding manages this. It’s not related to this issue though - the device can sleep, and the fact that it’s initialisation isn’t complete doesn’t stop the binding from processing the notifications.

You could try unlinking the channel, and relinking it to see if that solves the issue (working on Marks theory).

@chris: I will search for such a situation and then unlink the items and relink (I have items defined in file).
By the way, I found another node within above logfile (step 3) which stopped updating the items (sending each 5 minutes its meters), node 36:


With next restart the updates again have been done …

Hello @chris, I was able to reproduce the issue of losing channels:
I put my controller in exclusion mode via PaperUI, but did then nothing more. Then many (I have not checked if all) of my devices miss the “State Update” row in the logfiles from that point of time.
I have updated my items file with a space and saved it. No change.
I have removed the items of my node 3, saved, wait shortly, added the items again -> still no channel connected …


How can we now go on? Can I test something else to come closer to the source of the issue?
Normally I do not put my controller in “Remove” mode, but it may be that same case is happening with other action.

Update: putting controller in “Synchronize Net” also doesn’t link channels
Update 2: deleting a thing in PaperUI (items remain unchanged) and add it by discovery again resets the channel for this thing and all is ok. Other things remain with unlinked channels.
Update 3: Even the item state is not updating, I can switch from my sitemap the power switches to on and off. But way back does not work …
Update 4: Heal Device does not solve the channel issue; Reinitialize Device does also not solve the iussue.

I have a similiar/ same issue. When i edit the items file, remove the channels and readd them the link reappears.

I have updated to version 1522 and currently my system is running stable.
And putting the controller in excusion mode does not show the same results as a few days ago. Hopefully something in the base system has been changed. I cross my fingers …

Hi, I have a similar situation with a fgs223. I need to use this to control a fgrm that runs a roller shutter. The thing is that I want to use it by pressing long on each of the two buttons connected to the fgs223 (one click turns the light in the room).
If I press and hold the key button I see nothing in log like it suppose to see 1.0 or 2.0. I also see nothing on double click so the fgs223 isn’t updating its status.
Any suggestion pls? Thanks.

Hello @ewgor,
it would be good to get some background of your setup, e.g. which version ae you running, how are your parameters set for the FGS223.
Have you set param 20 to “momentary” (=0) and 28/29 to “All” (=15)?