Steinel IS-140-2 z-wave: warnings in log

Add-ons Bindings
, ,
1

Hey everyone,

I’d like to understand warnings in the log that my simple openhab setup produces (OH2.1 with recent 2.2-snapshot z-wave binding) for the Steinel motion sensor:
2017-11-16 20:17:25.551 [WARN ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: CommandClass APPLICATION_STATUS (0x22) not implemented by endpoint 2, fallback to main node.

Is it due to some still incorrect information in the device database? Any help greatly appreciated!

The debug log around those warnings looks like this:

2017-11-16 20:17:25.525 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-11-16 20:17:25.526 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 103ms/4167ms.
2017-11-16 20:17:25.527 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-11-16 20:17:25.528 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 02 06 60 0D 01 03 25 02 25 BB 33
2017-11-16 20:17:25.529 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0D 00 13 02 06 60 0D 01 03 25 02 25 BB 33
2017-11-16 20:17:25.537 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.539 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-16 20:17:25.540 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2017-11-16 20:17:25.541 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.542 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.544 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 08 60 0D 02 01 22 01 00 00
2017-11-16 20:17:25.545 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2017-11-16 20:17:25.546 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-11-16 20:17:25.547 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@16c9584 already registered
2017-11-16 20:17:25.548 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2017-11-16 20:17:25.549 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2017-11-16 20:17:25.550 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = APPLICATION_STATUS (0x22)
2017-11-16 20:17:25.551 [WARN ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: CommandClass APPLICATION_STATUS (0x22) not implemented by endpoint 2, fallback to main node.
2017-11-16 20:17:25.552 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 2, calling handleApplicationCommandRequest.
2017-11-16 20:17:25.553 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: Application Status message
2017-11-16 20:17:25.554 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: is busy and will be polled in 2 seconds
2017-11-16 20:17:25.555 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-16 20:17:25.556 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-16 20:17:25.557 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 1800 seconds - start in 2000 milliseconds.
2017-11-16 20:17:25.559 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=187, payload=02 06 60 0D 0
1 03 25 02
2017-11-16 20:17:25.585 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.587 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-16 20:17:25.588 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.589 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 08 60 0D 02 01 22 01 00 00
2017-11-16 20:17:25.592 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2017-11-16 20:17:25.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-11-16 20:17:25.594 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@16c9584 already registered
2017-11-16 20:17:25.595 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2017-11-16 20:17:25.596 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2017-11-16 20:17:25.597 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = APPLICATION_STATUS (0x22)
2017-11-16 20:17:25.598 [WARN ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: CommandClass APPLICATION_STATUS (0x22) not implemented by endpoint 2, fallback to main node.
2017-11-16 20:17:25.599 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 2, calling handleApplicationCommandRequest.
2017-11-16 20:17:25.600 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: Application Status message
2017-11-16 20:17:25.601 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: is busy and will be polled in 2 seconds
2017-11-16 20:17:25.602 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-16 20:17:25.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-16 20:17:25.604 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 1800 seconds - start in 2000 milliseconds.
2017-11-16 20:17:25.606 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=187, payload=02 06 60 0D 0
1 03 25 02
2017-11-16 20:17:25.610 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.612 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-11-16 20:17:25.614 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.615 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0E 00 04 00 02 08 60 0D 02 01 22 01 00 00 B2
2017-11-16 20:17:25.616 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 08 60 0D 02 01 22 01 00 00
2017-11-16 20:17:25.618 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2017-11-16 20:17:25.619 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-11-16 20:17:25.620 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@16c9584 already registered
2017-11-16 20:17:25.621 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2017-11-16 20:17:25.622 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2017-11-16 20:17:25.623 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = APPLICATION_STATUS (0x22)
2017-11-16 20:17:25.624 [WARN ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: CommandClass APPLICATION_STATUS (0x22) not implemented by endpoint 2, fallback to main node.
2017-11-16 20:17:25.626 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 2, calling handleApplicationCommandRequest.
2017-11-16 20:17:25.627 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: Application Status message
2017-11-16 20:17:25.628 [DEBUG] [andclass.ZWaveApplicationStatusClass] - NODE Node 2. Manufacturer 0271, Type 0002, Id 1A72: is busy and will be polled in 2 seconds
2017-11-16 20:17:25.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2017-11-16 20:17:25.630 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2017-11-16 20:17:25.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 1800 seconds - start in 2000 milliseconds.
2017-11-16 20:17:25.632 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=187, payload=02 06 60 0D 01 03 25 02
2017-11-16 20:17:27.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2017-11-16 20:17:27.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:a830b601:node2:switch_binary
2017-11-16 20:17:27.634 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 2: Generating poll message for SWITCH_BINARY, endpoint 0
2017-11-16 20:17:27.634 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET
2017-11-16 20:17:27.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:a830b601:node2:alarm_motion1
2017-11-16 20:17:27.637 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:a830b601:node2:alarm_general1
2017-11-16 20:17:27.638 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:a830b601:node2:sensor_luminance2
2017-11-16 20:17:27.640 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 2: Generating poll message for SENSOR_MULTILEVEL, endpoint 2
2017-11-16 20:17:27.641 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-11-16 20:17:27.643 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 2
2017-11-16 20:17:27.644 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2017-11-16 20:17:27.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:a830b601:node2:switch_binary3
2017-11-16 20:17:27.647 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 2: Generating poll message for SWITCH_BINARY, endpoint 3
2017-11-16 20:17:27.648 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET
2017-11-16 20:17:27.649 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 3
2017-11-16 20:17:27.650 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2017-11-16 20:17:27.652 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-11-16 20:17:27.654 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-11-16 20:17:27.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2

Probably not - the most likely reason is the device hasn’t reported all command classes, but without seeing logs of the initialisation, it’s a little hard to say.

The database isn’t used to add command classes to a device - the device has to tell the binding what it supports - if this doesn’t happen, then the result is normally what you see above.

3

When does the initialisation happen? During inclusion or also also if I’d restart openhab? Currently, this warning is written to the log like every 2 seconds.

4

Initialisation normally just happens when the device is first used by the binding. If you use the “Reinitialise device” option in the thing configuration, it will reinitialise.

5

I did so and here are the logs - would be great if you can check:

6

I can confirm that this is the reason -:

image
image.png1490×222 40.4 KB

Is it actually causing any problem? I would expect associations to be used in general rather than this class. If so, you could just ignore the message for now.

I do note another issue in your log though so I’ll add a PR to fix this in the master branch (it’s fixed in the latest development branch).

7

It’s not causing problems as far as I can see. And, after this “reinitialize device” thing, the warning appears only every 30mins…