OH2 Z-Wave refactoring and testing... and SECURITY

security
zwave
Tags: #<Tag:0x00007fd31161c768> #<Tag:0x00007fd31161c628>

(Mark) #3096

It’s within about 15 feet of the controller. It seems to be communicating fine.

  • Looking at the HABmin UI, everything looks correct
  • When I wake it up, I can see the binding receive the NIF
  • During initialization, I see the binding send the WAKE_UP_INTERVAL_GET, but it gets no response
  • When I press a numbered button, I see the binding receive the SCENE_ACTIVATION command, but the binding complains about SCENE_ACTIVATION command class not found

(Mark) #3097

What do you see when you press a scene button?


(Chris Jackson) #3098

Yes.


(Scott Rushworth) #3099

Restarted the binding and it came up fine… and XML was there. SCENE_ACTIVATION is properly reported and item linked to the channel is updated. Not seeing the same issue. Charge it up?

I’ll try this proper… delete the Thing and XML, and then restart OH before discovering.


(Chris Jackson) #3100

Sorry - I’ve not had the chance to look at this yet as I had to go out last night. I’ll try and take a look tonight.

I think this is normal. The NIF is also used as a wakeup - so the NIF is processed, then the binding sets the device awake.

No - this class isn’t supported, but it isn’t needed (unless you think otherwise?). It’s a strange command class and certainly the fact that it isn’t supported will have no impact on the use of the device.


(Mark) #3101

It has a full charge. :slightly_frowning_face:

I see this when I press a scene button. What do you see?

2018-07-03 08:22:07.272 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 5F 04 2B 01 01 00 81 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 95: Application Command Request (ALIVE:SET_WAKEUP)
2018-07-03 08:22:07.273 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 95: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-07-03 08:22:07.273 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 95: Command class COMMAND_CLASS_SCENE_ACTIVATION not found.
2018-07-03 08:22:07.274 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 95: Commands processed 1.

(Mark) #3102

No worries.

Ok. I realized this after looking at the code.

Ok, that makes sense to me.


(Scott Rushworth) #3103
2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: SECURITY not supported
2018-07-03 08:15:09.982 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Received COMMAND_CLASS_SCENE_ACTIVATION V0 SCENEACTIVATION_SET
2018-07-03 08:15:09.982 [DEBUG] [ocol.commandclass.ZWaveSceneActivationCommandClass] - NODE 212: Scene activation: Scene 1, Time 0
2018-07-03 08:15:09.982 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-03 08:15:09.982 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SCENE_ACTIVATION, value = 1
2018-07-03 08:15:09.983 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Updating channel state zwave:device:07cb40a2:node212:scene_number to 1 [DecimalType]
2018-07-03 08:15:09.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Commands processed 1.

BTW, I’m on zwave 2.4.0.201807021829 and snapshot 1304.


(Mark) #3104

I’m on zwave 2.3.0.201807011259, snapshot 1302

What do you see before this line?

2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0

Edit: I’m going to install the same zwave version you’re running.


(Scott Rushworth) #3105

I’m grepping NODE 212, so let me know if yu want the raw data…

2018-07-03 08:12:46.198 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Device initialisation complete.
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: ProtocolInfo
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Listening = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Routing   = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Beaming   = true
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Version   = 3
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: FLIRS     = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Security  = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Max Baud  = 40000
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Basic    = BASIC_TYPE_CONTROLLER
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Generic  = GENERIC_TYPE_GENERIC_CONTROLLER
2018-07-03 08:12:46.287 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Specific = SPECIFIC_TYPE_PORTABLE_REMOTE_CONTROLLER
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Version = 1, version set. Enabling extra functionality.
2018-07-03 08:12:46.287 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Creating new instance of command class COMMAND_CLASS_BASIC
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2018-07-03 08:12:46.287 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@5e8387de
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init transaction completed with response COMPLETE
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer - advancing to INIT_NEIGHBORS
2018-07-03 08:12:46.288 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2018-07-03 08:12:46.288 [DEBUG] [.protocol.serialmessage.GetRoutingInfoMessageClass] - NODE 212: Request routing info
2018-07-03 08:15:09.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Application Command Request (ALIVE:INIT_NEIGHBORS)
2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0

(Mark) #3106

Hmm. You have this.

2018-07-03 08:15:09.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Application Command Request (ALIVE:INIT_NEIGHBORS)

And I have this. Mine can’t seem to get past this stage of initialization…

2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 95: Application Command Request (ALIVE:SET_WAKEUP)

(Scott Rushworth) #3107

After deleting the Thing and XML, restarting and discovering, that is where I am too. The device is still in my Inbox and Unknown.

After adding it from the Inbox, the device was identified somehow. Maybe something was cached? There was nothing for identification in the log, and previously it was unknown. Strange.

And I also see this repeatedly on wakeup…

2018-07-03 09:16:49.052 [DEBUG] [otocol.serialmessage.ApplicationUpdateMessageClass] - NODE 212: Application update request. Node information received. Transaction null
2018-07-03 09:16:49.052 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Unsupported command class COMMAND_CLASS_ASSOCIATION_COMMAND_CONFIGURATION
2018-07-03 09:16:49.052 [DEBUG] [otocol.serialmessage.ApplicationUpdateMessageClass] - NODE 212: Application update - no transaction.
2018-07-03 09:16:49.083 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Application Command Request (ALIVE:SET_WAKEUP)
2018-07-03 09:16:49.084 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Is awake with 0 messages in the queue
2018-07-03 09:16:49.084 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Creating WakeupTimerTask
2018-07-03 09:16:49.085 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2018-07-03 09:16:49.087 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 212: Node Status event - Node is AWAKE
2018-07-03 09:16:49.088 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Commands processed 1.
2018-07-03 09:16:49.089 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@43c79bed.
2018-07-03 09:16:49.089 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction 1328  ApplicationCommandHandler.
2018-07-03 09:16:49.090 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : state >> WAIT_RESPONSE
2018-07-03 09:16:49.090 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : node  >> 61
2018-07-03 09:16:49.091 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : class >> 132 == 49.
2018-07-03 09:16:49.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : commd >> 7 == 5.
2018-07-03 09:16:49.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Ignoring transaction since not waiting for data.
2018-07-03 09:16:59.085 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:16:59.085 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: WakeupTimerTask 0 Messages waiting, state SET_WAKEUP
2018-07-03 09:16:59.085 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: WakeupTimerTask First iteration
2018-07-03 09:17:09.085 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:17:09.086 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: WakeupTimerTask 0 Messages waiting, state SET_WAKEUP
2018-07-03 09:17:09.086 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: No more messages, go back to sleep
2018-07-03 09:17:09.086 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 212: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2018-07-03 09:17:09.086 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Encapsulating message, endpoint 0
2018-07-03 09:17:09.086 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: SECURITY not supported
2018-07-03 09:17:09.086 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2018-07-03 09:17:09.086 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@51ff786b
2018-07-03 09:17:09.088 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Adding to device queue
2018-07-03 09:17:09.088 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Added to queue - size 46
2018-07-03 09:17:23.805 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:17:23.805 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 212: Sending REQUEST Message = 01 09 00 13 D4 02 84 08 25 1B 81 
2018-07-03 09:17:23.821 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 212: sentData successfully placed on stack.
2018-07-03 09:17:23.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: TID 1338: Transaction not completed
2018-07-03 09:17:23.980 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 212: SendData Request. CallBack ID = 27, Status = Transmission complete, no ACK received(1)
2018-07-03 09:17:23.980 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 212: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
2018-07-03 09:17:23.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Response processed after 165ms
2018-07-03 09:17:23.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: TID 1338: Transaction completed
2018-07-03 09:17:23.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: notifyTransactionResponse TID:1338 DONE
2018-07-03 09:17:23.981 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-03 09:17:23.983 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: -- To notify -- COMPLETE
2018-07-03 09:17:23.984 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Went to sleep COMPLETE

So it goes to sleep, with something being added to the queue, but then on wakeup, there is nothing in the queue, and at stage SET_WAKEUP. There are no more messages, so it is told to go back to sleep. But then something is added to the queue!?


(Mark) #3108

Very strange, indeed.

I have a node.xml, but it looks like this. :worried:

<node>
  <homeId>xxxxxxxxx</homeId>
  <nodeId>96</nodeId>
  <version>3</version>
  <manufacturer>0x7fffffff</manufacturer>
  <deviceId>0x7fffffff</deviceId>
  <deviceType>0x7fffffff</deviceType>
  <listening>false</listening>
  <frequentlyListening>false</frequentlyListening>
  <routing>false</routing>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <sleepDelay>1000</sleepDelay>
  <associationGroups class="concurrent-hash-map"/>
  <endpoints class="concurrent-hash-map">
    <entry>
      <int>0</int>
      <endPoint>
        <deviceClass>
          <basicDeviceClass>BASIC_TYPE_CONTROLLER</basicDeviceClass>
          <genericDeviceClass>GENERIC_TYPE_GENERIC_CONTROLLER</genericDeviceClass>
          <specificDeviceClass>SPECIFIC_TYPE_PORTABLE_REMOTE_CONTROLLER</specificDeviceClass>
        </deviceClass>
        <endpointId>0</endpointId>
        <secureCommandClasses/>
        <supportedCommandClasses class="concurrent-hash-map">
          <entry>
            <commandClass>COMMAND_CLASS_BASIC</commandClass>
            <COMMAND__CLASS__BASIC>
              <version>0</version>
              <instances>1</instances>
              <versionSupported>0</versionSupported>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__BASIC>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_NO_OPERATION</commandClass>
            <COMMAND__CLASS__NO__OPERATION>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__NO__OPERATION>
          </entry>
        </supportedCommandClasses>
      </endPoint>
    </entry>
  </endpoints>
  <nodeNeighbors/>
  <lastReceived>2018-07-03 13:09:24.464 UTC</lastReceived>
</node>

(Scott Rushworth) #3109

I found where the binding had identified the device, so that’s sorted. After another OH restart, I found this…

2018-07-03 09:31:46.125 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer - advancing to SET_WAKEUP
2018-07-03 09:31:46.125 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-07-03 09:31:46.127 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer: SET_WAKEUP - Interval is currently 0. Set to 3600
2018-07-03 09:31:46.127 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer: SET_WAKEUP - Set wakeup node to controller (1), period 3600
2018-07-03 09:31:46.127 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 212: Creating new message for command WAKE_UP_INTERVAL_SET to 3600s, node 1
2018-07-03 09:31:46.127 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: ZWaveCommandClassTransactionPayload - send to node
2018-07-03 09:31:46.127 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Encapsulating message, endpoint 0
2018-07-03 09:31:46.131 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: SECURITY not supported
2018-07-03 09:31:46.131 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2018-07-03 09:31:46.131 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@b1c2e79
2018-07-03 09:31:46.131 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Adding to device queue
2018-07-03 09:31:46.131 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Added to queue - size 10
2018-07-03 09:31:52.295 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:31:52.295 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: WakeupTimerTask 1 Messages waiting, state SET_WAKEUP
2018-07-03 09:32:02.295 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:32:02.296 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: WakeupTimerTask 1 Messages waiting, state SET_WAKEUP
2018-07-03 09:32:03.137 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: listening == false, frequentlyListening == false, awake == true
2018-07-03 09:32:03.138 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 212: Sending REQUEST Message = 01 0D 00 13 D4 06 84 04 00 0E 10 01 25 92 1B 
2018-07-03 09:32:03.153 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 212: sentData successfully placed on stack.
2018-07-03 09:32:03.154 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: TID 432: Transaction not completed
2018-07-03 09:32:03.169 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 212: SendData Request. CallBack ID = 146, Status = Transmission complete and ACK received(0)
2018-07-03 09:32:03.169 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Response processed after 21ms
2018-07-03 09:32:03.169 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: TID 432: Transaction completed
2018-07-03 09:32:03.170 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: notifyTransactionResponse TID:432 DONE
2018-07-03 09:32:03.170 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-03 09:32:03.178 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: -- To notify -- COMPLETE
2018-07-03 09:32:03.180 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7a8ce240
2018-07-03 09:32:03.180 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init transaction completed with response COMPLETE
2018-07-03 09:32:03.180 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 212: Creating new message for application command WAKE_UP_INTERVAL_GET

From there, it goes through the SET_WAKEUP loop. IIRC, but I’m not sure from where I learned it, these devices do not report their WAKEUP_INTERVAL even if set, so maybe that is the cause of the loop.

Have you restarted OH or zwave binding? Actually, drop in the new version and it will restart. I still don’t have an XML. :frowning: OH! and I forgot to mention… my minimote is being marked as dead!


(Mark) #3110

So I think we should restore the NOGET setting to the database, if for no other reason than to eliminate that as a variable.

Yes, I just did a restart of OH with the latest binding – 2.4.0.201807021829.

As an aside, it is odd that after a restart there are so many nodes that come up dead, then after a while all is good.


(Dan Cunningham) #3111

Done.


(Scott Rushworth) #3112

I’ll modify my device XML (in the jar) and see if that helps before making the change in the db.


(Chris Jackson) #3113

I’ve finally had the chance to look at this log, and I would agree that at least the first issue is it’s not responding to the WAKEUP_GET command… Since you’re already working to remove that, let me know how it goes…


(Mark) #3114

I’ve updated the DB – changed WAKE_UP config from ADD to NOGET.


(Scott Rushworth) #3115

I built a jar, reversing the changes from here, and it made it past SET_WAKEUP, but seemed to get stuck at GET_NEIGHBORS. This is strange because this device is a secondary controller. After restarting OH again, the device completed initialization, but I am now getting this when trying to use it (SCENE_ACTIVATION is also missing from the xml)…

2018-07-03 16:38:35.541 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-07-03 16:38:35.541 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Command class COMMAND_CLASS_SCENE_ACTIVATION not found.
2018-07-03 16:38:35.542 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Commands processed 1.
2018-07-03 16:38:35.542 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7e8ed6f3.
2018-07-03 16:38:35.542 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction 635  null.
2018-07-03 16:38:35.542 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : state >> ABORTED
2018-07-03 16:38:35.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : node  >> 112
2018-07-03 16:38:35.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : class >> 43 == null.
2018-07-03 16:38:35.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Checking transaction : commd >> 1 == 0.
2018-07-03 16:38:35.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Ignoring transaction since not waiting for data.