[SOLVED] Battery Level on AEON ZW089 Door Sensor not shown

speed · October 15, 2015, 2:48pm

Hi

I use an AEON z-stick gen5 with the door sensor ZW089 and I’m not able to get the Battery Level value. Inside habmin I the battery status is UNKNOWN which indicates that no battery level was reported. However if I view the sensor information in OpenZWave Control Panel (the web interface) I see a battery level of 100%.

Is that due to any incompatibility with openhab?

I have also tried to wakeup manually the sensor and I see in habmin that the last wakeup is updated but still no battery level. Not sure if this is also related to the problem but if I change the configuration inside habmin (eg. Wakeup interval from 0 to 60), the line is highlighted yellow and stays like this. I assume that the new configuration was not provided to the sensor for what ever reason. And this is how the openhab.log looks:

[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class ZWAVE_PLUS_INFO
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class ASSOCIATION_GROUP_INFO
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class POWERLEVEL
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class FIRMWARE_UPDATE_MD
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class SECURITY
[ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class ZWAVE_PLUS_INFO
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class ASSOCIATION_GROUP_INFO
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class POWERLEVEL
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class FIRMWARE_UPDATE_MD
[WARN ] [.o.b.z.i.p.c.ZWaveCommandClass] - NODE 3: Unsupported command class SECURITY
[ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
[ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
[ERROR] [WaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!

I assume the Timeout while sending message is due to the new configuration values that can’t be applied. Also here I have tried to wakeup manually the sensor to receive the update, but nothing happened.

Any help is much appreciated.

Thanks

Dima

chris · October 15, 2015, 4:43pm

No - battery level should work fine. How have you configured the items?

Why assume when you can just get a debug log that can tell you exactly what the problem is? I’d really suggest running in debug mode when you have problems as otherwise there’s limited help we can offer…

Chris

speed · October 17, 2015, 9:37am

Thanks Chris.

Here is my items file:

Contact Door_Motion "Sensor [%s]" <frontdoor> (gGroundFloor) { zwave="3:command=SENSOR_BINARY,respond_to_basic=true" }
Number  Door_Battery "Battery [%d %%]" <socket> (gGroundFloor) { zwave="3:command=BATTERY" }

Debug logfile file errors and warnings. I have triggered an event as well as a wakeup on the device (to pull the message queue):

11:03:03.001 [WARN ] [cpr.DefaultAnnotationProcessor:178  ] - Unable to detect annotations. Application may fail to deploy.
11:03:03.750 [WARN ] [sphere.cpr.AtmosphereFramework:941  ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to configure the org.atmosphere.cache.UUIDBroadcasterCache
11:03:15.745 [WARN ] [cpr.DefaultAnnotationProcessor:178  ] - Unable to detect annotations. Application may fail to deploy.
11:03:16.042 [WARN ] [sphere.cpr.AtmosphereFramework:1097 ] -
11:03:16.045 [WARN ] [sphere.cpr.AtmosphereFramework:941  ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to configure the org.atmosphere.cache.UUIDBroadcasterCache
11:03:25.267 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141  ] - NODE 3: Error serializing from file: file does not exist.
11:07:16.208 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class ZWAVE_PLUS_INFO
11:07:16.213 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class ASSOCIATION_GROUP_INFO
11:07:16.215 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class POWERLEVEL
11:07:16.215 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class FIRMWARE_UPDATE_MD
11:07:16.215 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class SECURITY
11:07:22.456 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
11:07:22.914 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class ZWAVE_PLUS_INFO
11:07:22.916 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class ASSOCIATION_GROUP_INFO
11:07:22.917 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class POWERLEVEL
11:07:22.917 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class FIRMWARE_UPDATE_MD
11:07:22.917 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:221  ] - NODE 3: Unsupported command class SECURITY
11:07:27.944 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
11:11:18.312 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!

And here is a grep on battery:

11:03:21.328 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Door_Battery (Type=NumberItem, State=Uninitialized)' with 'ZWaveGenericBindingProvider' reader.
11:03:25.514 [DEBUG] [.z.internal.ZWaveActiveBinding:192  ] - NODE 3: Polling list: item Door_Battery is not completed initialisation
11:07:16.210 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224  ] - NODE 3: Creating new instance of command class BATTERY
11:07:16.210 [DEBUG] [.z.internal.protocol.ZWaveNode:523  ] - NODE 3: Adding command class BATTERY to the list of supported command classes.
11:07:16.313 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:477  ] - NODE 3: Node advancer: VERSION - checking BATTERY, version is 0
11:07:16.453 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:477  ] - NODE 3: Node advancer: VERSION - checking BATTERY, version is 1
11:07:16.545 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:580  ] - NODE 3: Node advancer: STATIC_VALUES - checking BATTERY
11:07:16.755 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:580  ] - NODE 3: Node advancer: STATIC_VALUES - checking BATTERY
11:07:22.915 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224  ] - NODE 3: Creating new instance of command class BATTERY
11:20:41.886 [DEBUG] [.z.internal.ZWaveActiveBinding:192  ] - NODE 3: Polling list: item Door_Battery is not completed initialisation
11:20:41.887 [DEBUG] [.z.internal.ZWaveActiveBinding:192  ] - NODE 3: Polling list: item Door_Battery is not completed initialisation

The full logfind you can find at http://pastebin.com/fkp4rNxR

I don’t see any issue why the battery values are not pulled. I see that the battery command is supported, but never that a value is transmitted.

chris · October 17, 2015, 9:42am

From this log, it shows that the initialisation isn’t completed yet. This will take time (maybe hours) on battery devices unless you wake it up manually. I don’t know this device, but normally theres a button you have to press to do this.

Once it’s initialised, it will update the battery periodically - maybe every few hours - it certainly won’t happen immediately. Once it’s done once though, then OH will be able to display it. This is probably also what ZWay is doing (ie the data is buffered somewhere, and not updated live each time).

speed · October 17, 2015, 10:22am

Thanks Chris

I have mentioned that I did a manual wekeup on the device (holding the button for couple of seconds)

11:07:16.088 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 3: Received Wake Up Request
11:07:16.089 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:182  ] - NODE 3: Received WAKE_UP_NOTIFICATION
11:07:16.089 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:411  ] - NODE 3: Is awake with 0 messages in the wake-up queue.
11:07:16.089 [DEBUG] [b.z.i.protocol.ZWaveController:595  ] - Notifying event listeners: ZWaveWakeUpEvent

And I see that the wakeup values are correctly updated in habmin, but the Battery value still says UNKNOWN.

chris · October 17, 2015, 10:31am

Sorry - I missed that…

The initialisation is not completing - I’ll take a look at why, but maybe there’s a problem with the device that will require a database update…

When you post logs, can you format them by pressing the </> button - it makes it much easier to read - I’ve been editing your posts above to do this

Chris

chris · October 17, 2015, 10:35am

Can you just wake up the device again. It might just not have completed initialisation by the looks of it. There’s a lot of configuration in this device, and it went back to sleep before it completed. Reading the dynamic configuration is one of the last things that is done during configuration, and the device has never completed its initialisation (yet).

So, just try waking it a couple more times and see if that helps. If not, post the log again and I’ll see if it’s getting stuck at a certain point…

speed · October 17, 2015, 10:41am

OK, thanks - I will do so. I saw this formatting appearing and tough “Wow its happening automatically” … I will pay attention in the future.

Back to topic: Just let me know what I need to do in order to provide you all the information for the Database Update. I’m going to re-run a couple of manual wake-up’s. I had the same idea in the past, and a single wake-up didn’t help. But I will report back.

speed · October 17, 2015, 10:53am

Ok, I did 4 manual wake-up’s and battery level is still at unknown. Also the issue will the timeouts on sending message is still there and didn’t improve with the additional wake-up’s. I hope the log is not too long otherwise I will use postbin next time:

12:42:11.998 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 08 00 04 00 03 02 84 07 71 
12:42:11.999 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:11.999 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:12.000 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71 
12:42:12.001 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 08 00 04 00 03 02 84 07 71 
12:42:12.002 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 02 84 07 
12:42:12.002 [DEBUG] [ApplicationCommandMessageClass:38   ] - NODE 3: Application Command Request (ALIVE:GET_CONFIGURATION)
12:42:12.003 [DEBUG] [ApplicationCommandMessageClass:56   ] - NODE 3: Incoming command class WAKE_UP
12:42:12.003 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 3: Received Wake Up Request
12:42:12.004 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:182  ] - NODE 3: Received WAKE_UP_NOTIFICATION
12:42:12.004 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:411  ] - NODE 3: Is awake with 1 messages in the wake-up queue.
12:42:12.005 [DEBUG] [b.z.i.protocol.ZWaveController:595  ] - Notifying event listeners: ZWaveWakeUpEvent
12:42:12.006 [DEBUG] [.z.internal.ZWaveActiveBinding:433  ] - ZwaveIncomingEvent
12:42:12.006 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034 ] - NODE 3: Wakeup during initialisation.
12:42:12.007 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267  ] - NODE 3: Node advancer - GET_CONFIGURATION: queue length(1), free to send(false)
12:42:12.007 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 21
12:42:12.008 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 1
12:42:12.008 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0
12:42:12.008 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240  ] - NODE 3: Node advancer - queued packet. Queue length is 1
12:42:12.009 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 03 03 70 05 FF 25 15 5C 
12:42:12.009 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 22
12:42:12.009 [DEBUG] [WaveController$ZWaveSendThread:1228 ] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 70 05 FF 25 15 5C 
12:42:12.009 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 1
12:42:12.027 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 04 01 13 01 E8 
12:42:12.028 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:12.028 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:12.029 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8 
12:42:12.030 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 04 01 13 01 E8 
12:42:12.030 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:42:12.030 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 3: Sent Data successfully placed on stack.
12:42:12.047 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 07 00 13 15 00 00 02 FC 
12:42:12.050 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:12.050 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:12.051 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 15 00 00 02 00 00 F2 
12:42:12.052 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 09 00 13 15 00 00 02 00 00 F2 
12:42:12.052 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 15 00 00 02 
12:42:12.053 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 3: SendData Request. CallBack ID = 21, Status = Transmission complete and ACK received(0)
12:42:12.053 [WARN ] [b.z.i.p.s.SendDataMessageClass:77   ] - NODE 3: Already processed another send data request for this callback Id, ignoring.
12:42:17.012 [DEBUG] [o.b.z.i.protocol.SerialMessage:109  ] - NODE 255: Creating empty message of class = SendDataAbort (0x16), type = Request (0x00)
12:42:17.013 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 03 00 16 EA 
12:42:17.014 [DEBUG] [WaveController$ZWaveSendThread:1254 ] - NODE 3: Sending ABORT Message = 01 03 00 16 EA 
12:42:17.401 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
12:42:17.402 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:435  ] - NODE 3: Is sleeping
12:42:17.402 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:42:17.403 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0
12:42:17.403 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:237  ] - NODE 3: Message already on the wake-up queue. Removing original.
12:42:17.404 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:42:22.024 [DEBUG] [z.internal.ZWaveNetworkMonitor:353  ] - Network Monitor: No nodes to ping!
12:42:54.068 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 08 00 04 00 03 02 84 07 71 
12:42:54.071 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:54.071 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:54.071 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71 
12:42:54.072 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 08 00 04 00 03 02 84 07 71 
12:42:54.072 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 02 84 07 
12:42:54.073 [DEBUG] [ApplicationCommandMessageClass:38   ] - NODE 3: Application Command Request (ALIVE:GET_CONFIGURATION)
12:42:54.073 [DEBUG] [ApplicationCommandMessageClass:56   ] - NODE 3: Incoming command class WAKE_UP
12:42:54.073 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 3: Received Wake Up Request
12:42:54.073 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:182  ] - NODE 3: Received WAKE_UP_NOTIFICATION
12:42:54.074 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:411  ] - NODE 3: Is awake with 1 messages in the wake-up queue.
12:42:54.074 [DEBUG] [b.z.i.protocol.ZWaveController:595  ] - Notifying event listeners: ZWaveWakeUpEvent
12:42:54.074 [DEBUG] [.z.internal.ZWaveActiveBinding:433  ] - ZwaveIncomingEvent
12:42:54.075 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034 ] - NODE 3: Wakeup during initialisation.
12:42:54.075 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267  ] - NODE 3: Node advancer - GET_CONFIGURATION: queue length(1), free to send(false)
12:42:54.075 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 23
12:42:54.075 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 1
12:42:54.076 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240  ] - NODE 3: Node advancer - queued packet. Queue length is 1
12:42:54.076 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 24
12:42:54.076 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 2
12:42:54.077 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 1
12:42:54.077 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 03 03 70 05 FF 25 18 51 
12:42:54.078 [DEBUG] [WaveController$ZWaveSendThread:1228 ] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 70 05 FF 25 18 51 
12:42:54.092 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 04 01 13 01 E8 
12:42:54.094 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:54.094 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:54.095 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8 
12:42:54.095 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 04 01 13 01 E8 
12:42:54.095 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:42:54.095 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 3: Sent Data successfully placed on stack.
12:42:54.110 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 07 00 13 18 00 00 02 F1 
12:42:54.113 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:42:54.113 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:42:54.113 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 18 00 00 02 00 00 FF 
12:42:54.114 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 09 00 13 18 00 00 02 00 00 FF 
12:42:54.114 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 18 00 00 02 
12:42:54.114 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 3: SendData Request. CallBack ID = 24, Status = Transmission complete and ACK received(0)
12:42:54.114 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 03 03 70 05 FF 
12:42:54.115 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 18 00 00 02 
12:42:54.115 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
12:42:59.079 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 1 attempts left!
12:42:59.080 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:435  ] - NODE 3: Is sleeping
12:42:59.080 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:42:59.081 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0
12:42:59.081 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:237  ] - NODE 3: Message already on the wake-up queue. Removing original.
12:42:59.081 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:43:18.398 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 08 00 04 00 03 02 84 07 71 
12:43:18.401 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:18.401 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:18.402 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71 
12:43:18.403 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 08 00 04 00 03 02 84 07 71 
12:43:18.403 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 02 84 07 
12:43:18.403 [DEBUG] [ApplicationCommandMessageClass:38   ] - NODE 3: Application Command Request (ALIVE:GET_CONFIGURATION)
12:43:18.404 [DEBUG] [ApplicationCommandMessageClass:56   ] - NODE 3: Incoming command class WAKE_UP
12:43:18.404 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 3: Received Wake Up Request
12:43:18.404 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:182  ] - NODE 3: Received WAKE_UP_NOTIFICATION
12:43:18.404 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:411  ] - NODE 3: Is awake with 1 messages in the wake-up queue.
12:43:18.404 [DEBUG] [b.z.i.protocol.ZWaveController:595  ] - Notifying event listeners: ZWaveWakeUpEvent
12:43:18.404 [DEBUG] [.z.internal.ZWaveActiveBinding:433  ] - ZwaveIncomingEvent
12:43:18.404 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034 ] - NODE 3: Wakeup during initialisation.
12:43:18.404 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267  ] - NODE 3: Node advancer - GET_CONFIGURATION: queue length(1), free to send(false)
12:43:18.404 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333  ] - NODE 3: Node advancer: loop - GET_CONFIGURATION try 2: stageAdvanced(false)
12:43:18.418 [DEBUG] [ZWaveConfigurationCommandClass:160  ] - NODE 3: Creating new message for application command CONFIGURATIONCMD_GET
12:43:18.419 [DEBUG] [o.b.z.i.protocol.SerialMessage:109  ] - NODE 3: Creating empty message of class = SendData (0x13), type = Request (0x00)
12:43:18.419 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 25
12:43:18.419 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 1
12:43:18.419 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240  ] - NODE 3: Node advancer - queued packet. Queue length is 1
12:43:18.419 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 26
12:43:18.419 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 2
12:43:18.419 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 1
12:43:18.420 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 03 03 70 05 FF 25 1A 53 
12:43:18.420 [DEBUG] [WaveController$ZWaveSendThread:1228 ] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 70 05 FF 25 1A 53 
12:43:18.436 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 04 01 13 01 E8 
12:43:18.439 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:18.439 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:18.440 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8 
12:43:18.440 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 04 01 13 01 E8 
12:43:18.441 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:43:18.441 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 3: Sent Data successfully placed on stack.
12:43:18.455 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 07 00 13 1A 00 00 02 F3 
12:43:18.456 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:18.456 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:18.457 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 1A 00 00 02 00 00 FD 
12:43:18.457 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 09 00 13 1A 00 00 02 00 00 FD 
12:43:18.457 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 1A 00 00 02 
12:43:18.457 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 3: SendData Request. CallBack ID = 26, Status = Transmission complete and ACK received(0)
12:43:18.458 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 03 03 70 05 FF 
12:43:18.458 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 1A 00 00 02 
12:43:18.458 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
12:43:23.421 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
12:43:23.422 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:435  ] - NODE 3: Is sleeping
12:43:23.422 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:43:23.423 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0
12:43:23.423 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:237  ] - NODE 3: Message already on the wake-up queue. Removing original.
12:43:23.423 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:43:42.655 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 08 00 04 00 03 02 84 07 71 
12:43:42.657 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:42.657 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:42.658 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71 
12:43:42.658 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 08 00 04 00 03 02 84 07 71 
12:43:42.658 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 03 02 84 07 
12:43:42.658 [DEBUG] [ApplicationCommandMessageClass:38   ] - NODE 3: Application Command Request (ALIVE:GET_CONFIGURATION)
12:43:42.658 [DEBUG] [ApplicationCommandMessageClass:56   ] - NODE 3: Incoming command class WAKE_UP
12:43:42.658 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:136  ] - NODE 3: Received Wake Up Request
12:43:42.658 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:182  ] - NODE 3: Received WAKE_UP_NOTIFICATION
12:43:42.659 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:411  ] - NODE 3: Is awake with 1 messages in the wake-up queue.
12:43:42.659 [DEBUG] [b.z.i.protocol.ZWaveController:595  ] - Notifying event listeners: ZWaveWakeUpEvent
12:43:42.659 [DEBUG] [.z.internal.ZWaveActiveBinding:433  ] - ZwaveIncomingEvent
12:43:42.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034 ] - NODE 3: Wakeup during initialisation.
12:43:42.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267  ] - NODE 3: Node advancer - GET_CONFIGURATION: queue length(1), free to send(false)
12:43:42.659 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 27
12:43:42.659 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 1
12:43:42.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240  ] - NODE 3: Node advancer - queued packet. Queue length is 1
12:43:42.659 [DEBUG] [b.z.i.protocol.ZWaveController:898  ] - Callback ID = 28
12:43:42.660 [DEBUG] [b.z.i.protocol.ZWaveController:580  ] - Enqueueing message. Queue length = 2
12:43:42.660 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 1
12:43:42.660 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 03 03 70 05 FF 25 1C 55 
12:43:42.661 [DEBUG] [WaveController$ZWaveSendThread:1228 ] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 70 05 FF 25 1C 55 
12:43:42.681 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 04 01 13 01 E8 
12:43:42.684 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:42.684 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:42.684 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8 
12:43:42.685 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 04 01 13 01 E8 
12:43:42.685 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:43:42.685 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 3: Sent Data successfully placed on stack.
12:43:42.694 [DEBUG] [eController$ZWaveReceiveThread:1441 ] - Receive Message = 01 07 00 13 1C 00 00 02 F5 
12:43:42.696 [DEBUG] [eController$ZWaveReceiveThread:1365 ] - Receive queue ADD: Length=1
12:43:42.696 [DEBUG] [b.z.i.protocol.ZWaveController:1123 ] - Receive queue TAKE: Length=0
12:43:42.697 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 1C 00 00 02 00 00 FB 
12:43:42.697 [DEBUG] [b.z.i.protocol.ZWaveController:1124 ] - Process Message = 01 09 00 13 1C 00 00 02 00 00 FB 
12:43:42.698 [DEBUG] [b.z.i.protocol.ZWaveController:190  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 1C 00 00 02 
12:43:42.698 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 3: SendData Request. CallBack ID = 28, Status = Transmission complete and ACK received(0)
12:43:42.698 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 03 03 70 05 FF 
12:43:42.698 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 1C 00 00 02 
12:43:42.698 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
12:43:47.663 [ERROR] [WaveController$ZWaveSendThread:1269 ] - NODE 3: Timeout while sending message. Requeueing - 2 attempts left!
12:43:47.664 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:435  ] - NODE 3: Is sleeping
12:43:47.664 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:43:47.665 [DEBUG] [WaveController$ZWaveSendThread:1171 ] - Took message from queue for sending. Queue length = 0
12:43:47.665 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:237  ] - NODE 3: Message already on the wake-up queue. Removing original.
12:43:47.665 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:241  ] - NODE 3: Putting message SendData in wakeup queue.
12:43:52.028 [DEBUG] [z.internal.ZWaveNetworkMonitor:353  ] - Network Monitor: No nodes to ping!

Here is the config of the sensor:

chris · October 17, 2015, 11:00am

It looks like it’s ‘sticking’ on a request for parameter 255. It never gets a response, so it keeps trying and it never progresses to the DYNAMIC stage… You could try waking it up a few more times - it should eventually give up on this stage and move on…

I’ll try and find the manual for this device - my suspicion is that CFG 255 either doesn’t exist, or is WRITE_ONLY and the database needs updating to reflect this…

speed · October 17, 2015, 11:04am

Here is the manual I have found so far.

Engineering Spec - ZW089_V1.13.pdf (245.5 KB)

chris · October 17, 2015, 11:06am

Thanks. It doesn’t say anything about write only, but it’s clearly not responding to the request so I’ll update the database to stop it requesting this parameter. That will hopefully allow it to finish initialisation

chris · October 17, 2015, 11:11am

speed · October 17, 2015, 11:13am

Thanks Chris. And you are right! It gave up after the 8 retry or so and the initialisation completed.

13:07:17.251 [WARN ] [WaveController$ZWaveSendThread:1278 ] - NODE 3: Too many retries. Discarding message: Message: class = SendData (0x13), type = Request (0x00), payload = 03 03 70 05 FF

Battery level is now shown.

Many Thanks Chris! Is your commit now needed to speed-up things or do you need any additional test you want me to perform on the device to solve this?

chris · October 17, 2015, 11:15am

If you grab tomorrows snapshot off cloudbees it should solve the problem. However, now that it’s initialised once, it won’t go through this process again unless the XML file is deleted so it should be nice and quick now (ie just a single wakeup hopefully!).

speed · October 17, 2015, 11:19am

Great thanks for that! Will change topic to [SOLVED]