ZWave "Node initialising: STATIC_VALUES" after snapshot upgrades

roryd · July 26, 2017, 11:45am

I have an Aeon Labs ZW078 Heavy Duty Switch, and every time I upgrade to the latest snapshot, it goes into “Node initialising: STATIC_VALUES”, and if I check the HABmin Attributes, the firmware version shows as 0.0 (actual version is 3.26).

If I delete and rediscover the device, it reappears properly.

I don’t know if this is relevant, but I noticed that in @chris’s database, the Generic class is shown as:

GENERIC_TYPE_SWITCH_BINARY

But in HABmin, it shows as:

BINARY_SWITCH (as opposed to SWITCH_BINARY)

It’s not critical, as I just need to delete and rediscover it, but I tend to upgrade to the latest snapshot daily, so it’s more of an annoyance.

chris · July 26, 2017, 11:48am

It’s not related - the device class information in the database is not used at all.

In order to debug this, we’d need to look at a log. It’s very likely that you will find that the binding is continually requesting some bit of information from the device that the device is not returning - we need to find out what this is, and then we can deal with it…

roryd · July 31, 2017, 11:28am

I’ve done that now and the log can be viewed here - it’s about 4Mb so give it a minute

It’s node 12 that has the static values warning after upgrading to the latest snapshot.

I should add that the log starts with the “apt upgrade” and subsequent OH restart so the relevant messages are probably a bit further down.

After it all settles down, the following block repeats every 5 seconds in openhab.log:

2017-07-31 15:17:11.812 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 0C 0E 32 02 A1 6C 00 00 00 00 00 00 00 00 00 00 10
2017-07-31 15:17:11.812 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-07-31 15:17:11.813 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 14 00 04 00 0C 0E 32 02 A1 6C 00 00 00 00 00 00 00 00 00 00 10
2017-07-31 15:17:11.813 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 14 00 04 00 0C 0E 32 02 A1 6C 00 00 00 00 00 00 00 00 00 00 10
2017-07-31 15:17:11.814 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0C 0E 32 02 A1 6C 00 00 00 00 00 00 00 00 00 00
2017-07-31 15:17:11.814 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 12: Application Command Request (ALIVE:STATIC_VALUES)
2017-07-31 15:17:11.814 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 12: Incoming command class METER
2017-07-31 15:17:11.814 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Received METER command V3
2017-07-31 15:17:11.814 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Meter: Type=Electric(1), Scale=A(5), Value=0E+1
2017-07-31 15:17:11.815 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-07-31 15:17:11.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-07-31 15:17:11.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0E+1
2017-07-31 15:17:11.815 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_A
2017-07-31 15:17:11.816 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:15a390b5594:node12:meter_current to 0 [DecimalType]
2017-07-31 15:17:11.817 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_A
2017-07-31 15:17:11.817 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_A
2017-07-31 15:17:11.817 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=12, callback=97, payload=0C 04 59 03 00 02
2017-07-31 15:17:11.817 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0C 0E 32 02 A1 6C 00 00 00 00 00 00 00 00 00 00
2017-07-31 15:17:11.818 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=97, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-07-31 15:17:11.818 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-07-31 15:17:11.818 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - STATIC_VALUES: Transaction complete (SendData:Request) success(true)
2017-07-31 15:17:11.818 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - checking initialisation queue. Queue size 0.
2017-07-31 15:17:11.818 [DEBUG] [curityCommandClassWithInitialization] - NODE 12: updating lastSentMessageTimestamp
2017-07-31 15:17:11.818 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-07-31 15:17:11.898 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 0C 0E 32 02 21 64 00 03 61 C4 00 05 00 03 61 C4 9D
2017-07-31 15:17:11.899 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-07-31 15:17:11.900 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 14 00 04 00 0C 0E 32 02 21 64 00 03 61 C4 00 05 00 03 61 C4 9D
2017-07-31 15:17:11.900 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 14 00 04 00 0C 0E 32 02 21 64 00 03 61 C4 00 05 00 03 61 C4 9D
2017-07-31 15:17:11.900 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0C 0E 32 02 21 64 00 03 61 C4 00 05 00 03 61 C4
2017-07-31 15:17:11.900 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 12: Application Command Request (ALIVE:STATIC_VALUES)
2017-07-31 15:17:11.900 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 12: Incoming command class METER
2017-07-31 15:17:11.900 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Received METER command V3
2017-07-31 15:17:11.901 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Meter: Type=Electric(1), Scale=kWh(0), Value=221.636
2017-07-31 15:17:11.901 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-07-31 15:17:11.901 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-07-31 15:17:11.901 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 221.636
2017-07-31 15:17:11.901 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:15a390b5594:node12:meter_kwh to 221.636 [DecimalType]
2017-07-31 15:17:11.902 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_KWh
2017-07-31 15:17:11.902 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_KWh
2017-07-31 15:17:11.903 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_W <> E_KWh
2017-07-31 15:17:11.903 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=12, callback=97, payload=0C 04 59 03 00 02
2017-07-31 15:17:11.903 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0C 0E 32 02 21 64 00 03 61 C4 00 05 00 03 61 C4
2017-07-31 15:17:11.903 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=97, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
2017-07-31 15:17:11.903 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-07-31 15:17:11.903 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - STATIC_VALUES: Transaction complete (SendData:Request) success(true)
2017-07-31 15:17:11.903 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - checking initialisation queue. Queue size 0.
2017-07-31 15:17:11.903 [DEBUG] [curityCommandClassWithInitialization] - NODE 12: updating lastSentMessageTimestamp
2017-07-31 15:17:11.903 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

UPDATE: This seems to happen everytime OH starts, not just after an snapshot upgrade. If I stop and start OH, the device displays the static values message, and if I delete it and rediscover it, it appears fine.