Zwave node could not resolve thingtype

First of all: sorry if I didn’t provide enough information, this is the first time i’m doing something like this.
I’ve been trying to connect my Everspring AN157 (which should be in the database) to my raspberry pi with z-wave.me stick through OH2. I installed habmin, including and excluding devices worked and I connected my AN157, which is now called node2. It does show up as an unknown device, so that could be a problem, altough the node2.xml file did show it should support Switch_Binary, which is what i want it to do. I currently eddit the demofiles from Openhab 2 to make changes in the sitemap and items. So in the items I added { zwave=“2:command=SWITCH_BINARY” } to the Switch Light_FF_Bed_Ceiling item. My understanding was that now, if I flicked the switch in the Basic UI for the bedroom ceiling switch, the switch should receive the command and turn on/off. When I look at the logs I get this warning/error:

14:36:37.309 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
14:36:37.999 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 0060:0104:0001::1.1
14:36:38.017 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 2: Already processed another send data request for this callback Id, ignoring.
14:36:42.987 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
14:36:42.988 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.

I’ll try to provide additional information as quickly as possible, thanks in advance for looking into this.

I have the exact same problem. I installed on a fresh Raspberry the new Openhab2 via apt-get and set up my zwave network. All my devices are marked as unknown. When I check the log I see the following lines

2016-09-17 14:27:44.595 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:7e584173:node2' to inbox.
2016-09-17 14:27:44.619 [WARN ] [rialmessage.IdentifyNodeMessageClass] - Got IdentifyNodeMessage without request, ignoring. Last message was SendData.
2016-09-17 14:27:49.614 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-09-17 14:27:49.620 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-09-17 14:27:51.870 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-09-17 14:27:54.630 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2016-09-17 14:27:54.631 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-09-17 14:27:54.759 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  (10)
2016-09-17 14:27:59.719 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-09-17 14:27:59.720 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-09-17 14:27:59.767 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  (10)
2016-09-17 14:28:04.723 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2016-09-17 14:28:04.725 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-09-17 14:28:04.776 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  (10)
2016-09-17 14:28:06.874 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-09-17 14:28:09.731 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2016-09-17 14:28:09.732 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-09-17 14:28:09.774 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 06 02 61 00 20  (10)
2016-09-17 14:28:14.734 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=9, payload=02 02 86 11 
2016-09-17 14:29:30.031 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 0097:6943:4501::0.32

All my devices are shown as “unknown device” and when I check the properties in HABmin, I don’t see manufacture nor more information. My devices are one Fibaro Motion Sensor, one Fibaro Dimmer, zwo TAPHome plug switch. They used to work fine in the zwave binding 1.7.

What can I do next, to resolve my problem?

BR
Felix

I’m not really sure about that - it looks different…

This error normally indicates that the controller can’t communicate with the device and without any communication, well, not much is going to work. You should try and resolve this first…

Next I would enable debug logging - logs without debug only really tell you there’s a problem, but they don’t help at all in finding out why there’s a problem.

Thanks for your quick response. I set DEBUG on and also restarted my device. Personally I don’t see anything wrong in the logfile, also the XML files have all the information.

I really don’t wanna waste your time, but I already tried a lot and cannot find the reason of the problem. What else can I check out?

Thanks a lot for your help. It’s been very appreciated.

/Felix

Here the entry of HABmin

The content of node2.xml:

<node>
  <deviceClass>
    <basicDeviceClass>ROUTING_SLAVE</basicDeviceClass>
    <genericDeviceClass>BINARY_SWITCH</genericDeviceClass>
    <specificDeviceClass>POWER_SWITCH_BINARY</specificDeviceClass>
  </deviceClass>
  <homeId>0xf8d1ad57</homeId>
  <nodeId>2</nodeId>
  <version>4</version>
  <manufacturer>0x97</manufacturer>
  <deviceId>0x4501</deviceId>
  <deviceType>0x6943</deviceType>
  <listening>true</listening>
  <frequentlyListening>false</frequentlyListening>
  <routing>true</routing>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <nodeInformationFrame>
    <commandClass>SWITCH_BINARY</commandClass>
    <commandClass>VERSION</commandClass>
    <commandClass>METER</commandClass>
    <commandClass>MANUFACTURER_SPECIFIC</commandClass>
    <commandClass>CONFIGURATION</commandClass>
    <commandClass>ASSOCIATION</commandClass>
    <commandClass>PROTECTION</commandClass>
    <commandClass>POWERLEVEL</commandClass>
    <commandClass>SENSOR_MULTILEVEL</commandClass>
    <commandClass>SWITCH_ALL</commandClass>
  </nodeInformationFrame>
  <supportedCommandClasses>
    <entry>
      <commandClass>SWITCH_ALL</commandClass>
      <switchAllCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <isGetSupported>true</isGetSupported>
        <mode>SWITCH_ALL_INCLUDE_ON_OFF</mode>
      </switchAllCommandClass>
    </entry>
    <entry>
      <commandClass>CONFIGURATION</commandClass>
      <configurationCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <configParameters/>
      </configurationCommandClass>
    </entry>
    <entry>
      <commandClass>MANUFACTURER_SPECIFIC</commandClass>
      <manufacturerSpecificCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <initSerialNumber>false</initSerialNumber>
      </manufacturerSpecificCommandClass>
    </entry>
    <entry>
      <commandClass>METER</commandClass>
      <meterCommandClass>
        <version>2</version>
        <instances>1</instances>
        <versionSupported>2</versionSupported>
        <meterType>ELECTRIC</meterType>
        <meterScales>
          <meterScale>E_W</meterScale>
          <meterScale>E_KWh</meterScale>
        </meterScales>
        <canReset>true</canReset>
        <isGetSupported>true</isGetSupported>
        <isSupportRequestSupported>true</isSupportRequestSupported>
      </meterCommandClass>
    </entry>
    <entry>
      <commandClass>ASSOCIATION</commandClass>
      <associationCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <maxGroups>1</maxGroups>
      </associationCommandClass>
    </entry>
    <entry>
      <commandClass>PROTECTION</commandClass>
      <protectionCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <localModes/>
        <rfModes/>
      </protectionCommandClass>
    </entry>
    <entry>
      <commandClass>POWERLEVEL</commandClass>
      <powerLevelCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <powerLevel>0</powerLevel>
        <powerTimeout>0</powerTimeout>
      </powerLevelCommandClass>
    </entry>
    <entry>
      <commandClass>BASIC</commandClass>
      <basicCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <isGetSupported>true</isGetSupported>
      </basicCommandClass>
    </entry>
    <entry>
      <commandClass>VERSION</commandClass>
      <versionCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <libraryType>LIB_SLAVE_ROUTING</libraryType>
        <protocolVersion>2.97</protocolVersion>
        <applicationVersion>0.32</applicationVersion>
      </versionCommandClass>
    </entry>
    <entry>
      <commandClass>NO_OPERATION</commandClass>
      <noOperationCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
      </noOperationCommandClass>
    </entry>
    <entry>
      <commandClass>SENSOR_MULTILEVEL</commandClass>
      <multiLevelSensorCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <sensors>
          <entry>
            <multilevelSensorType>TEMPERATURE</multilevelSensorType>
            <multilevelSensor>
              <sensorType>TEMPERATURE</sensorType>
              <initialised>true</initialised>
            </multilevelSensor>
          </entry>
        </sensors>
        <isGetSupported>true</isGetSupported>
      </multiLevelSensorCommandClass>
    </entry>
    <entry>
      <commandClass>SWITCH_BINARY</commandClass>
      <binarySwitchCommandClass>
        <version>1</version>
        <instances>1</instances>
        <versionSupported>1</versionSupported>
        <isGetSupported>true</isGetSupported>
      </binarySwitchCommandClass>
    </entry>
  </supportedCommandClasses>
  <securedCommandClasses/>
  <associationGroups>
    <entry>
      <int>1</int>
      <associationGroup>
        <index>1</index>
        <associations/>
      </associationGroup>
    </entry>
  </associationGroups>
  <nodeNeighbors>
    <int>1</int>
    <int>3</int>
    <int>4</int>
    <int>5</int>
  </nodeNeighbors>
  <lastSent>2016-09-17 16:27:45.396 UTC</lastSent>
  <lastReceived>2016-09-17 16:27:45.438 UTC</lastReceived>
</node>

Some debug output:

2016-09-17 16:27:45.062 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.077 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 03 00 00 02 EA 
2016-09-17 16:27:45.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.079 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 00 00 02 00 00 E4 
2016-09-17 16:27:45.079 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 03 00 00 02 00 00 E4 
2016-09-17 16:27:45.080 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=03 00 00 02 
2016-09-17 16:27:45.080 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 3, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is ALIVE. Init stage is PING.
2016-09-17 16:27:45.081 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2016-09-17 16:27:45.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2016-09-17 16:27:45.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting ONLINE
2016-09-17 16:27:45.082 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Status event during initialisation - Node is ALIVE
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(1), free to send(false)
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 10000
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2016-09-17 16:27:45.083 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2016-09-17 16:27:45.084 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is ALIVE
2016-09-17 16:27:45.084 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=2, callback=3, payload=02 01 00 
2016-09-17 16:27:45.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=03 00 00 02 
2016-09-17 16:27:45.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=3, expected=SendData, cancelled=false        transaction complete!
2016-09-17 16:27:45.085 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.085 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(0), free to send(true)
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 10000
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PING try 2: stageAdvanced(false)
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to DETAILS
2016-09-17 16:27:45.087 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.088 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Restored from file - skipping static initialisation
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to GET_CONFIGURATION
2016-09-17 16:27:45.088 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.089 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - GET_CONFIGURATION try 0: stageAdvanced(true)
2016-09-17 16:27:45.091 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - thing is null!
2016-09-17 16:27:45.092 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to DYNAMIC_VALUES
2016-09-17 16:27:45.092 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.092 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DYNAMIC_VALUES try 0: stageAdvanced(true)
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_ALL
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking CONFIGURATION
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking METER
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found    METER
2016-09-17 16:27:45.094 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of METER
2016-09-17 16:27:45.094 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2016-09-17 16:27:45.095 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2016-09-17 16:27:45.095 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2016-09-17 16:27:45.096 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking ASSOCIATION
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking PROTECTION
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found    PROTECTION
2016-09-17 16:27:45.097 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of PROTECTION
2016-09-17 16:27:45.097 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Creating new message for command PROTECTION_GET
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found    POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 2: Creating new message for application command POWERLEVEL_GET
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking BASIC
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking VERSION
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found    SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Creating new message for command SENSOR_MULTI_LEVEL_GET
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_BINARY
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found    SWITCH_BINARY
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of SWITCH_BINARY
2016-09-17 16:27:45.102 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET
2016-09-17 16:27:45.102 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - queued 6 frames
2016-09-17 16:27:45.103 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 52ms/173ms.
2016-09-17 16:27:45.103 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.103 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 32 01 10 25 0C ED 
2016-09-17 16:27:45.104 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 32 01 10 25 0C ED 
2016-09-17 16:27:45.113 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.113 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.114 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2016-09-17 16:27:45.115 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.115 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2016-09-17 16:27:45.116 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.129 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0C 00 00 02 E5 
2016-09-17 16:27:45.130 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.131 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0C 00 00 02 00 00 EB 
2016-09-17 16:27:45.131 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0C 00 00 02 00 00 EB 
2016-09-17 16:27:45.132 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0C 00 00 02 
2016-09-17 16:27:45.132 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 12, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.133 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=12, payload=02 03 32 01 10 
2016-09-17 16:27:45.133 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0C 00 00 02 
2016-09-17 16:27:45.134 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=12, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2016-09-17 16:27:45.141 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6 
2016-09-17 16:27:45.143 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.143 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6 
2016-09-17 16:27:45.144 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6 
2016-09-17 16:27:45.144 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0A 32 02 21 14 00 00 00 00 00 00 
2016-09-17 16:27:45.144 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.145 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class METER
2016-09-17 16:27:45.145 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Received METER command V2
2016-09-17 16:27:45.147 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2016-09-17 16:27:45.147 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2016-09-17 16:27:45.147 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2016-09-17 16:27:45.148 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0E+1
2016-09-17 16:27:45.148 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=12, payload=02 03 32 01 10 
2016-09-17 16:27:45.149 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0A 32 02 21 14 00 00 00 00 00 00 
2016-09-17 16:27:45.149 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=12, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2016-09-17 16:27:45.149 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 6.
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 5.
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(5), free to send(true)
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 5
2016-09-17 16:27:45.150 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.151 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 47ms/173ms.
2016-09-17 16:27:45.151 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.151 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 32 01 00 25 0D FC 
2016-09-17 16:27:45.151 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 32 01 00 25 0D FC 
2016-09-17 16:27:45.161 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.162 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.162 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2016-09-17 16:27:45.163 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.164 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2016-09-17 16:27:45.164 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.177 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0D 00 00 02 E4 
2016-09-17 16:27:45.178 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.179 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0D 00 00 02 00 00 EA 
2016-09-17 16:27:45.179 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0D 00 00 02 00 00 EA 
2016-09-17 16:27:45.180 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0D 00 00 02 
2016-09-17 16:27:45.181 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 13, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.182 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=13, payload=02 03 32 01 00 
2016-09-17 16:27:45.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0D 00 00 02 
2016-09-17 16:27:45.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=13, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2016-09-17 16:27:45.191 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C 
2016-09-17 16:27:45.192 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.193 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C 
2016-09-17 16:27:45.193 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C 
2016-09-17 16:27:45.194 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 
2016-09-17 16:27:45.194 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.195 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class METER
2016-09-17 16:27:45.195 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Received METER command V2
2016-09-17 16:27:45.196 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=kWh(0), Value=0.00001
2016-09-17 16:27:45.197 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2016-09-17 16:27:45.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2016-09-17 16:27:45.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.00001
2016-09-17 16:27:45.198 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=13, payload=02 03 32 01 00 
2016-09-17 16:27:45.198 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 
2016-09-17 16:27:45.199 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=13, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2016-09-17 16:27:45.199 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 5.
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 4.
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(4), free to send(true)
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 4
2016-09-17 16:27:45.201 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 49ms/173ms.
2016-09-17 16:27:45.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.202 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 75 02 25 0E B9 
2016-09-17 16:27:45.202 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 75 02 25 0E B9 
2016-09-17 16:27:45.211 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.212 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.212 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2016-09-17 16:27:45.213 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.214 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2016-09-17 16:27:45.214 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.227 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0E 00 00 02 E7 
2016-09-17 16:27:45.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.229 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0E 00 00 02 00 00 E9 
2016-09-17 16:27:45.230 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0E 00 00 02 00 00 E9 
2016-09-17 16:27:45.230 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0E 00 00 02 
2016-09-17 16:27:45.230 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 14, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=14, payload=02 02 75 02 
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0E 00 00 02 
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=14, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2016-09-17 16:27:45.238 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 75 03 00 85 
2016-09-17 16:27:45.239 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.240 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 02 03 75 03 00 85 
2016-09-17 16:27:45.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 02 03 75 03 00 85 
2016-09-17 16:27:45.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 75 03 00 
2016-09-17 16:27:45.242 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.242 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class PROTECTION
2016-09-17 16:27:45.243 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Received PROTECTION command V1
2016-09-17 16:27:45.243 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2016-09-17 16:27:45.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2016-09-17 16:27:45.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = PROTECTION, value = UNPROTECTED
2016-09-17 16:27:45.244 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Received protection report local:UNPROTECTED
2016-09-17 16:27:45.245 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=14, payload=02 02 75 02 
2016-09-17 16:27:45.245 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 75 03 00 
2016-09-17 16:27:45.246 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=14, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2016-09-17 16:27:45.246 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.246 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 4.
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 3.
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(3), free to send(true)
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 3
2016-09-17 16:27:45.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.248 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 46ms/173ms.
2016-09-17 16:27:45.248 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.249 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 73 02 25 0F BE 
2016-09-17 16:27:45.249 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 73 02 25 0F BE 
2016-09-17 16:27:45.258 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2016-09-17 16:27:45.259 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.260 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 


(I had to shorten it, but some communication take clearly place)

The first log you posted has some ERROR entries with lots of timeouts - that’s normally a bad sign…

Yes - clearly something is wrong since the image doesn’t have the information. This comes from another place but they should be in sync. What version of the binding are you using? If it’s more than a couple of days old I would suggest to update as I fixed a bug that might be the cause.

After getting really frustrated about it I set up a fresh system today. I installed openhab2-offline via apt-get. So I guess it’s from today.

Can you check the version of the binding - just to be sure as I don’t know when these get built. At the moment the bindings are only building manually and I don’t know about the apt build.

binding-zwave - 2.0.0.b4

Do you need to know it more detailed? If yes, how can I find it?

This error was fixed 2 days ago, so I’m guessing your version isn’t up to date.

No, that’s fine - you’re using the beta version, so this is definitely out of date and won’t have the recent updates.

I’m afraid to ask how to get a latest .jar file? Do I have to compile for myself, or is there a way to download a latest build?

Sorry for my noob question and thank you very much for your help.

The easiest / best way is if you’re using the online snapshot version. In this case you can just uninstall the binding, and install the binding using HABmin/PaperUI Extensions control.

However, as you’re using the beta version, this won’t work, and as you’re using the offline version, it also won’t work…

Unforutnatly, it’s not especially easy to upgrade so I would probably recommend to just change to use the snapshot online version.

I guess this answer is why :wink:

There is a thread on updating the runtime which is useful -:

I think you said you installed using apt-get though, so this might not be applicable.