Aeon Minimotes: Z-Wave Issues? Odd

Dan_Bellandi · July 6, 2016, 9:09pm

I have 4 Aeon Minimotes that I have configured to use “Scene Mode” rather than the default “Group Mode”.

A few times lately one of the remotes (different ones) will get into a state where OH2 will consider it Offline and not respond to messages from the remote. Button presses and wakeups do not function properly.

The only solution I’ve found is deleting the Thing in OH2 and re-adding it. The remotes themselves are somewhat finicky to add and generally require a few attempts of dropping/adding while waking the remotes up.

When the Thing is re-added it is assigned the same node number (makes sense as it was never excluded) and of course the name of the Thing is not remembered. Odder is the fact that the remote has reverted to operating in the default “Group Mode”.

Here is the z-wave log of a remote that is operating properly (Node 34) when a button is pressed:

2016-07-06 07:08:34.756 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 22 04 2B 01 01 00 FC
2016-07-06 07:08:34.756 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-06 07:08:34.756 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 22 04 2B 01 01 00 FC
2016-07-06 07:08:34.756 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 22 04 2B 01 01 00 FC
2016-07-06 07:08:34.756 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 22 04 2B 01 01 00
2016-07-06 07:08:34.756 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DONE)
2016-07-06 07:08:34.756 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Starting initialisation from DONE
2016-07-06 07:08:34.757 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@50ed4d9f already registered
2016-07-06 07:08:34.757 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class SCENE_ACTIVATION
2016-07-06 07:08:34.757 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - Received Scene Activation for Node ID = 34
2016-07-06 07:08:34.757 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - Scene Activation Set
2016-07-06 07:08:34.757 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - Scene activation node from node 34: Scene 1, Time 0
2016-07-06 07:08:34.757 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2016-07-06 07:08:34.757 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 34: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2016-07-06 07:08:34.757 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 34: Got a value event from Z-Wave network, endpoint = 0, command class = SCENE_ACTIVATION, value = 1
2016-07-06 07:08:34.757 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 34: Updating channel state zwave:device:d7ab0833:node34:scene_number to 1 [DecimalType]
2016-07-06 07:08:34.757 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 37: Transaction not completed: node address inconsistent.  lastSent=37, incoming=255

And the log of a remote that is in the state described above (Node 30) when a button is pressed:

2016-07-06 07:08:42.643 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 1E 04 2B 01 05 00 C4
2016-07-06 07:08:42.643 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-06 07:08:42.643 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 1E 04 2B 01 05 00 C4
2016-07-06 07:08:42.644 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 1E 04 2B 01 05 00 C4
2016-07-06 07:08:42.644 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 1E 04 2B 01 05 00
2016-07-06 07:08:42.644 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 30: Not initialized yet, ignoring message.

Log of the broken node when a wakeup is attempted:

2016-07-06 07:13:30.803 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 11 00 49 84 1E 0B 01 01 01 86 72 70 9B EF 85 2B 26 4F
2016-07-06 07:13:30.803 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-06 07:13:30.804 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 49 84 1E 0B 01 01 01 86 72 70 9B EF 85 2B 26 4F
2016-07-06 07:13:30.804 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 11 00 49 84 1E 0B 01 01 01 86 72 70 9B EF 85 2B 26 4F
2016-07-06 07:13:30.804 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 1E 0B 01 01 01 86 72 70 9B EF 85 2B 26
2016-07-06 07:13:30.804 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 30: Application update request. Node information received.
2016-07-06 07:13:30.804 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 30: Application update request. Node not known!
2016-07-06 07:13:30.804 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-07-06 07:13:30.805 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovered
2016-07-06 07:13:30.805 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveInclusionEvent
2016-07-06 07:13:30.805 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Newly included node already initialising at DONE
2016-07-06 07:13:30.805 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=34, callback=90, payload=22 02 84 08
2016-07-06 07:13:30.805 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 1E 0B 01 01 01 86 72 70 9B EF 85 2B 26
2016-07-06 07:13:30.806 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=90, expected=SendData, cancelled=false      MISMATCH
2016-07-06 07:13:30.822 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 04 1E 02 84 07 68
2016-07-06 07:13:30.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-06 07:13:30.823 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 04 1E 02 84 07 68
2016-07-06 07:13:30.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 04 1E 02 84 07 68
2016-07-06 07:13:30.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=04 1E 02 84 07
2016-07-06 07:13:30.824 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 30: Not initialized yet, ignoring message.

Note the Node 11 messages. This is a battery device on my network (Fibaro Motion Sensor). When a Minimote is in this state these “extraneous” messages appear to always be present on a wakeup attempt. Other times a remote has broken it has been different nodes although it seems to usually/always be a battery device.

I don’t know if this is an OH2 issue, z-wave binding issue, or Aeon Minimote issue, or some combination.

chris · July 7, 2016, 9:22pm

The error with the node 11 messages is a bug in the binding - I’ll add a fix. However, I don’t think this will impact anything else other than node 11.

Dan_Bellandi · July 9, 2016, 11:13am

Thanks, Chris. I was guessing that part might just be more of a side effect. It seemed odd though that those other node messages wouldn’t appear when waking up a “working” Minimote.

Do you have any guesses as to what might be happening that the Minimote gets in this state? Looking at the log messages it seems as the problem would be earlier as everything looks the same except for the broken one the message is ignored because the node is not initialized. Next time it happens I will capture the log for the node at startup.

The fact that the Minimote loses its configuration of “Scene Mode” makes me suspect that it may be an issue with the Minimote itself because I don’t think the binding would do that from dropping/adding the Thing?

chris · July 9, 2016, 11:18am

This error should only occur if the binding doesn’t know about the device - eg it’s not actually included into the network. It’s hard to tell this without a larger log - specifically, during startup there is a list of known nodes and it would be good to see if node 30 is listed - I suspect it might not be?

Dan_Bellandi · July 9, 2016, 11:46am

I’ll check and capture the startup logs next time it happens, I think it might not be either – I do remember that the node xml is not updated.