Zwave controller issue with no obvious trigger - Soft restart

billias · December 28, 2018, 6:49pm

Your are right.

Today At about 14:00 I realised the motion sensors doesn’t Trigger (From OK to Alarm ) when motion happens.
This happened on two of these sensors (4 in total)

I took the sensor form the wall and put it on the table. I performed tests on the sensors (moving my hand in front of the sensors.

I began about 14:12 these tests (I had Habpanel open and sometimes clicked the “refresh” button which might be mistake.

While I was moving every about 40 seconds my hand in front of the sensor. The sensor was always not “triggering” motion.
Example: at 14:19:20 the temperature update is because of my hand moving in front of the sensor… but no motion there.
This behaviour on the same test after the NIF+ wake at: 14:28:11.919

Instead i noticed the temperature to be updated! for some reason (in the logs everytime you see a temperature report, is triggered by motion.

The next phases are:

Started Heal 1-2 times. Also woke up the device afterwards. (This you can see it with the heal)

14:19:36.863

Set afterwards the Enable/Disable PIR to Enable (as it was empty).
Last resort was NIF

Between each of these steps I tried to test motion by moving hand in front of me.

In order to avoid myself triggering the sensor’s motion, sensor was turned to the wall and no other motion detection was possible.

I tried to export the logs manually as my exporting to csv was broken. And I did a big mistake copying them twice. Sorry for this mistake !

chris · December 28, 2018, 7:22pm

It’s a little hard to piece this together, but I make the following observations -:

the wakeup earlier in the log (eg at 14:14:57.761) does get detected, but there is nothing to do as the device has already completed the initialisation.
What makes the NIF work later is that you have sent the reinitialise command at 14:22:28.065. Therefore, when you send the NIF, which does the same thing as the WAKEUP, it does something as you have restarted the device initialisation.
There are no changes to association groups, so the problem is not apparently related to associations. Also, other device reports are being sent, so again, it’s probably not related to association groups.
You have set some configuration parameters - parameter 4 being one of them and this parameter disables PIR. Maybe at some stage you had disabled it?
We see motion alarms at 14:23:42.965.

So, I suspect that at some point, you have disabled the PIR. It continued to report luminance/temperature. Waking up the device didn’t make any difference initially, but you changed the configuration, and then sent the NIF/WAKUP which transferred your configuration to enable the PIR, and after this, the PIR is reporting.

Either way, this isn’t directly a binding issue as the binding is correctly translating the PIR messages. For some reason, if not because it was disabled, the PIR was not sending reports, and sending the PIR Enable configuration started it sending these again.

I hope that helps - I might not be completely correct on the above of course as I’m going on what I see in the logs, but I don’t see any problem with the binding, which is correctly translating the messages.

billias · December 28, 2018, 7:36pm

I see. then the device for some reason looses the Enabled PIR. Because I never sent disable.

One more question: somewhere in logs config_4_1 is -1 is this equal to 255?
Manual states 255 = Enable and 0 = Disable. But after a while this is not anymore on enable state?
I will seek for the whole log history for this again. If I find some bit and piece of it changing/been set.

chris · December 28, 2018, 7:38pm

Maybe - or maybe you did send disable, but didn’t realise… PaperUI will send all configuration - if it somehow gets the wrong value, then maybe it get changed… I’m speculating, but this is an issue we see occasionally.

Sorry - what do you mean? What is not in enable (ie where does it show, and what does it show).

billias · December 28, 2018, 7:47pm

My Greek-english… GRRRRRR

For some reason the value in property 4 is empty or becomes for some reason (can it be on nightly heal?) or so. And based on your explanation about PaperUI I suspect when I change something else, IF i do not correct this Empty field… this happens.

Also I found something strange from yesterday night (2018-12-27 23:32:53.885):

2018-12-27 23:32:48.831 DEBUG O.B.Z:  [ZWaveMultiLevelSensorConverter] - NODE 54: Sensor conversion not performed for POWER.
2018-12-27 23:32:48.834 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Updating channel state zwave:device:166c1909e7a:node54:sensor_power to 101.5 [DecimalType]
2018-12-27 23:32:48.839 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Commands processed 1.
2018-12-27 23:32:48.844 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@980c2e.
2018-12-27 23:32:48.846 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:48.848 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:48.850 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-27 23:32:48.852 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:48.855 INFO EVENT:  [me.event.ItemStateChangedEvent] - PlugServer_SensorPower changed from 87.5 to 101.5
2018-12-27 23:32:52.424 INFO EVENT:  [me.event.ItemStateChangedEvent] - ElectricityMeterDSMRV50_DeliveryTariff1 changed from 1467.356 kWh to 1467.357 kWh
2018-12-27 23:32:52.432 INFO EVENT:  [me.event.ItemStateChangedEvent] - ElectricityMeterDSMRV50_ActualPowerDelivery changed from 0.516 kW to 0.488 kW
2018-12-27 23:32:52.479 INFO EVENT:  [me.event.ItemStateChangedEvent] - ElectricityMeterDSMRV50_InstantPowerDeliveryL1 changed from 0.005 kW to 0.004 kW
2018-12-27 23:32:52.484 INFO EVENT:  [me.event.ItemStateChangedEvent] - ElectricityMeterDSMRV50_InstantPowerDeliveryL3 changed from 0.489 kW to 0.484 kW
2018-12-27 23:32:52.794 DEBUG O.B.Z:  [rialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 36 06 31 05 04 22 07 99 BC 00 F5 
2018-12-27 23:32:52.799 INFO EVENT:  [me.event.ItemStateChangedEvent] - ControllerZWave_StartFrames changed from 4984 to 4985
2018-12-27 23:32:52.825 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 07 99 BC 00 
2018-12-27 23:32:52.827 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 07 99 BC 00 
2018-12-27 23:32:52.828 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - lastTransaction null
2018-12-27 23:32:52.829 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Application Command Request (ALIVE:DONE)
2018-12-27 23:32:52.830 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: resetResendCount initComplete=true isDead=false
2018-12-27 23:32:52.831 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-12-27 23:32:52.832 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: SECURITY not supported
2018-12-27 23:32:52.834 DEBUG O.B.Z:  [commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_SENSOR_MULTILEVEL V2 SENSOR_MULTILEVEL_REPORT
2018-12-27 23:32:52.835 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Type = Power(4), Scale = 0
2018-12-27 23:32:52.836 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Value = 194.5
2018-12-27 23:32:52.837 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-12-27 23:32:52.839 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 194.5
2018-12-27 23:32:52.840 DEBUG O.B.Z:  [ZWaveMultiLevelSensorConverter] - NODE 54: Sensor conversion not performed for POWER.
2018-12-27 23:32:52.842 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Updating channel state zwave:device:166c1909e7a:node54:sensor_power to 194.5 [DecimalType]
2018-12-27 23:32:52.843 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Commands processed 1.
2018-12-27 23:32:52.846 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@936952.
2018-12-27 23:32:52.848 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:52.849 INFO EVENT:  [me.event.ItemStateChangedEvent] - PlugServer_SensorPower changed from 101.5 to 194.5
2018-12-27 23:32:52.850 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:52.852 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-27 23:32:52.854 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.507 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update received
2018-12-27 23:32:53.540 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored binding_cmdrepollperiod to 1500 (BigDecimal)
2018-12-27 23:32:53.543 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_11_1 to 0 (BigDecimal)
2018-12-27 23:32:53.547 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_10_1 to 2 (BigDecimal)
2018-12-27 23:32:53.550 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set group_4 to null (null)
2018-12-27 23:32:53.554 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.557 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.560 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.563 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.567 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_REMOVE group=4, node=all
2018-12-27 23:32:53.570 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.573 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.576 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 755 priority from Config to Immediate
2018-12-27 23:32:53.580 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.583 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 755 to queue - size 16
2018-12-27 23:32:53.587 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.590 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_GET group 4
2018-12-27 23:32:53.594 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.596 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.600 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 756 priority from Config to Immediate
2018-12-27 23:32:53.602 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.606 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 756 to queue - size 17
2018-12-27 23:32:53.609 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.613 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set group_1 to null (null)
2018-12-27 23:32:53.615 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.619 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.621 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.624 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.627 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_REMOVE group=1, node=all
2018-12-27 23:32:53.630 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.633 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.637 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 757 priority from Config to Immediate
2018-12-27 23:32:53.639 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.643 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 757 to queue - size 18
2018-12-27 23:32:53.645 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.649 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_GET group 1
2018-12-27 23:32:53.652 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.656 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.658 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 758 priority from Config to Immediate
2018-12-27 23:32:53.665 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.667 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 758 to queue - size 19
2018-12-27 23:32:53.669 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.672 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set group_3 to null (null)
2018-12-27 23:32:53.675 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.677 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.679 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.681 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.684 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_REMOVE group=3, node=all
2018-12-27 23:32:53.686 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.688 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.690 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 759 priority from Config to Immediate
2018-12-27 23:32:53.692 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.695 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 759 to queue - size 20
2018-12-27 23:32:53.697 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.700 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_GET group 3
2018-12-27 23:32:53.702 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.704 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.706 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 760 priority from Config to Immediate
2018-12-27 23:32:53.708 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.710 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 760 to queue - size 21
2018-12-27 23:32:53.712 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.715 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set group_2 to null (null)
2018-12-27 23:32:53.717 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.720 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Current Members ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.728 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.731 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: New Members ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[]]
2018-12-27 23:32:53.734 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_REMOVE group=2, node=all
2018-12-27 23:32:53.737 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.741 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.745 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 761 priority from Config to Immediate
2018-12-27 23:32:53.747 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.751 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 761 to queue - size 22
2018-12-27 23:32:53.755 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.759 DEBUG O.B.Z:  [s.ZWaveAssociationCommandClass] - NODE 44: Creating new message for application command ASSOCIATIONCMD_GET group 2
2018-12-27 23:32:53.762 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.766 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2018-12-27 23:32:53.768 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 762 priority from Config to Immediate
2018-12-27 23:32:53.772 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.775 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 762 to queue - size 23
2018-12-27 23:32:53.778 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.781 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored action_reinit to false (Boolean)
2018-12-27 23:32:53.784 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored wakeup_node to 1 (BigDecimal)
2018-12-27 23:32:53.791 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_12_1 to 0 (BigDecimal)
2018-12-27 23:32:53.795 DEBUG O.B.Z:  [rialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 36 06 31 05 04 22 03 98 BC 00 F0 
2018-12-27 23:32:53.795 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_99_2 to 5320 (BigDecimal)
2018-12-27 23:32:53.799 INFO EVENT:  [me.event.ItemStateChangedEvent] - ControllerZWave_StartFrames changed from 4985 to 4986
2018-12-27 23:32:53.800 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored action_failed to false (Boolean)
2018-12-27 23:32:53.802 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored wakeup_interval to 21600 (BigDecimal)
2018-12-27 23:32:53.805 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored action_remove to false (Boolean)
2018-12-27 23:32:53.808 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored binding_pollperiod to 86400 (BigDecimal)
2018-12-27 23:32:53.811 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set action_heal to true (Boolean)
2018-12-27 23:32:53.814 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Starting heal on node!
2018-12-27 23:32:53.816 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Can not start heal as initialisation is not complete (REQUEST_NIF).
2018-12-27 23:32:53.820 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_1_1 to 20 (BigDecimal)
2018-12-27 23:32:53.822 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_7_2 to 180 (BigDecimal)
2018-12-27 23:32:53.825 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 03 98 BC 00 
2018-12-27 23:32:53.825 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_8_1 to 0 (BigDecimal)
2018-12-27 23:32:53.827 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 03 98 BC 00 
2018-12-27 23:32:53.829 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - lastTransaction null
2018-12-27 23:32:53.830 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Application Command Request (ALIVE:DONE)
2018-12-27 23:32:53.832 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: resetResendCount initComplete=true isDead=false
2018-12-27 23:32:53.833 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-12-27 23:32:53.835 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_9_2 to 10 (BigDecimal)
2018-12-27 23:32:53.835 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: SECURITY not supported
2018-12-27 23:32:53.837 DEBUG O.B.Z:  [commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_SENSOR_MULTILEVEL V2 SENSOR_MULTILEVEL_REPORT
2018-12-27 23:32:53.838 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_2_2 to 30 (BigDecimal)
2018-12-27 23:32:53.839 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Type = Power(4), Scale = 0
2018-12-27 23:32:53.840 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update set config_3_1 to 255 (BigDecimal)
2018-12-27 23:32:53.841 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Value = 92
2018-12-27 23:32:53.843 DEBUG O.B.Z:  [ZWaveConfigurationCommandClass] - NODE 44: Creating new message for application command CONFIGURATION_SET
2018-12-27 23:32:53.843 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-12-27 23:32:53.845 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.845 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 92
2018-12-27 23:32:53.846 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_CONFIGURATION is NOT required to be secured
2018-12-27 23:32:53.847 DEBUG O.B.Z:  [ZWaveMultiLevelSensorConverter] - NODE 54: Sensor conversion not performed for POWER.
2018-12-27 23:32:53.849 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 763 priority from Config to Immediate
2018-12-27 23:32:53.849 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Updating channel state zwave:device:166c1909e7a:node54:sensor_power to 92 [DecimalType]
2018-12-27 23:32:53.851 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.852 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Commands processed 1.
2018-12-27 23:32:53.854 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@9573e3.
2018-12-27 23:32:53.855 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 763 to queue - size 24
2018-12-27 23:32:53.859 INFO EVENT:  [me.event.ItemStateChangedEvent] - PlugServer_SensorPower changed from 194.5 to 92
2018-12-27 23:32:53.862 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.864 DEBUG O.B.Z:  [ZWaveConfigurationCommandClass] - NODE 44: Creating new message for application command CONFIGURATIONCMD_GET
2018-12-27 23:32:53.864 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:53.867 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:53.868 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: SECURITY not supported
2018-12-27 23:32:53.868 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-27 23:32:53.870 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.871 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 44: Command Class COMMAND_CLASS_CONFIGURATION is NOT required to be secured
2018-12-27 23:32:53.874 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Bump transaction 764 priority from Config to Immediate
2018-12-27 23:32:53.877 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Adding to device queue
2018-12-27 23:32:53.879 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 44: Added 764 to queue - size 25
2018-12-27 23:32:53.882 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:53.885 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_4_1 to -1 (BigDecimal)
2018-12-27 23:32:53.888 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored node_id to 44 (BigDecimal)
2018-12-27 23:32:53.891 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_5_2 to 100 (BigDecimal)
2018-12-27 23:32:53.893 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 44: Configuration update ignored config_6_1 to 8 (BigDecimal)
2018-12-27 23:32:53.904 INFO EVENT:  [rthome.event.ThingUpdatedEvent] - Thing 'zwave:device:166c1909e7a:node44' has been updated.
2018-12-27 23:32:53.944 INFO EVENT:  [me.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=group_4, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=group_1, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=config_3_1, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=group_3, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null], ConfigStatusMessage [parameterName=group_2, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]
2018-12-27 23:32:54.795 DEBUG O.B.Z:  [rialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 36 06 31 05 04 22 03 F9 BF 00 92 
2018-12-27 23:32:54.799 INFO EVENT:  [me.event.ItemStateChangedEvent] - ControllerZWave_StartFrames changed from 4986 to 4987
2018-12-27 23:32:54.825 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 03 F9 BF 00 
2018-12-27 23:32:54.827 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=54, callback=0, payload=00 36 06 31 05 04 22 03 F9 BF 00 
2018-12-27 23:32:54.828 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - lastTransaction null
2018-12-27 23:32:54.829 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Application Command Request (ALIVE:DONE)
2018-12-27 23:32:54.830 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: resetResendCount initComplete=true isDead=false
2018-12-27 23:32:54.832 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-12-27 23:32:54.833 DEBUG O.B.Z:  [ve.internal.protocol.ZWaveNode] - NODE 54: SECURITY not supported
2018-12-27 23:32:54.835 DEBUG O.B.Z:  [commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_SENSOR_MULTILEVEL V2 SENSOR_MULTILEVEL_REPORT
2018-12-27 23:32:54.836 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Type = Power(4), Scale = 0
2018-12-27 23:32:54.838 DEBUG O.B.Z:  [veMultiLevelSensorCommandClass] - NODE 54: Sensor Value = 101.7
2018-12-27 23:32:54.839 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-12-27 23:32:54.840 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 101.7
2018-12-27 23:32:54.842 DEBUG O.B.Z:  [ZWaveMultiLevelSensorConverter] - NODE 54: Sensor conversion not performed for POWER.
2018-12-27 23:32:54.843 DEBUG O.B.Z:  [wave.handler.ZWaveThingHandler] - NODE 54: Updating channel state zwave:device:166c1909e7a:node54:sensor_power to 101.7 [DecimalType]
2018-12-27 23:32:54.845 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Commands processed 1.
2018-12-27 23:32:54.847 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - NODE 54: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@30b920.
2018-12-27 23:32:54.849 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:54.850 INFO EVENT:  [me.event.ItemStateChangedEvent] - PlugServer_SensorPower changed from 92 to 101.7
2018-12-27 23:32:54.853 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-12-27 23:32:54.854 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-27 23:32:54.856 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-27 23:32:55.616 DEBUG O.B.Z:  [rialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 34 06 31 05 01 22 00 CD B3 00 AE 
2018-12-27 23:32:55.623 INFO EVENT:  [me.event.ItemStateChangedEvent] - ControllerZWave_StartFrames changed from 4987 to 4988
2018-12-27 23:32:55.645 DEBUG O.B.Z:  [otocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=52, callback=0, payload=00 34 06 31 05 01 22 00 CD B3 00

chris · December 28, 2018, 7:53pm

Where are you looking? What is actually empty?

Yes, this is quite likely.

Sorry, but what have you found that you think is strange? Please tell me what you think is wrong otherwise I don’t know what you are looking for and I have to try to guess what you think is wrong.

I don’t see anything especially strange in here, so please let me know what is wrong in your opinion.

billias · December 28, 2018, 7:57pm

Anstering the Wher I am looking:
Same device Habpanel/paperui (taken now). I didn’t save/change anything (about param 4)

the point I found “awkward”/“strange” Is this:

NODE 44: Configuration update ignored config_4_1 to -1 (BigDecimal)
But I might be wrong there.

chris · December 28, 2018, 9:21pm

Probably this is blank as the value is -1, and -1 is not one of the values in the database. Probably this is related to this issue -:

github.com/openhab/org.openhab.binding.zwave

Signed/unsigned issues with configuration values

opened 03:07PM - 09 Dec 17 UTC

cdjackson

The ZWave standard states that configuration values **MUST** be signed, however …in many cases devices use (for example) a single value of 255. This translates to a value of -1 - even though the standard clearly states devices should treat this as 255. Somehow the binding needs to cope with this. There's no simple way since we don't actually know if the value is meant to be signed directly from the data. One possible option is to perform some sort of normalisation using the config database - if min/max is set to 0/255 then we can say it's unsigned... ![image](https://user-images.githubusercontent.com/1041475/33796746-bd6c9cf8-dcf2-11e7-8f42-bf24abbf625f.png)

It’s a difficult issue since the definition by many device manufacturers is inconsistent with the standards. I’m not sure why this is set to -1. -1 itself is not an issue since -1 is the same as FF as far as the binding is concerned, but not as far as the UI is concerned.

This just means that it didn’t do anything as the value being set was the same as the current value, so it was ignored. We do this to reduce traffic - there’s no sense in sending configuration parameters to set them to the same value they are already set to…

billias · December 28, 2018, 9:29pm

is there a cure for this issue? Update of DB can help cure this?
I believe this is also related to the old devices, as I have a device without temperature sensor (OLD) and behaves the same on this parameter.

chris · December 28, 2018, 9:31pm

Since I don’t know why it is set to -1, I’m not sure how to resolve it. It’s (another) very messy part of ZWave definitions.

I’m not sure why it’s related to old devices ? Can you expand on this statement? It should not be related to any specific type of device.

billias · December 28, 2018, 9:40pm

related = affects (maybe wrong again)

I see the same behaviour in the Old type of this device (DB ID for NEW =973 and OLD = 401).

During some process, for instance Healing process or wake up, is the Binding getting/pull current device parameter values?

chris · December 28, 2018, 10:05pm

I don’t think we can draw any conclusion from this.

No - parameters are not updated other than through external updates.

jphab · December 28, 2018, 10:19pm

Hi billias,

What i have read, it looks like i have similar problems, see again my post

I still can’t get it to work.

chris · December 28, 2018, 10:47pm

Maybe worth looking at this thread which I think is the one where we spent time to get these working…

I think the device does work ok, and we see that here - so long as it’s configured correctly

jphab · December 29, 2018, 2:13pm

I don’t know where to place this, but:

I was looking in the https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list for the NEO Coolcam PD01Z, finally found it at the manufacture Zipato and not at Shenzhen Neo Electronics Co., Ltd.

I also don’t know if this is why some things are not working right?

chris · December 29, 2018, 2:49pm

No - it’s not related. Devices in the database are listed against the manufacturer that the devices themselves report. This is not always the same as listed on the box, but is correct. Often you will also find the same device against multiple manufacturers - it’s just branding…

billias · December 29, 2018, 3:26pm

@Chris this parameter 4 is becoming blank after restarting openhab.
I have a spare device. I will play a bit around with it. and post findings.

Basically these two become blank/empty after restart:

Param 4
Lifeline

chris · December 29, 2018, 3:29pm

As above, this is because the database does not agree with the value. ie the value that is reported is not the same as one that is in the database.

The association problem is a well known issue in the UI but there’s not a lot I can do to resolve this as the widget used is not supported.

billias · December 29, 2018, 3:36pm

Basically on every restart I will need to update this value manually before the NIF happens. this way I will “bypass” this issue.

Can I perform this through CLI?

chris · December 29, 2018, 3:38pm

No - just leave it alone. If you don’t change it, it will be fine.