Zwave meter keeps timing out

noemark1 · July 24, 2016, 3:27pm

All-

I have a Raspberry Pi 3 with an Aeotec Zstick5 that I am using with several light switches and and Aeon labs Zwave smart energy meter. The lights work great, and I receive regular updates from the meter as well. The problem is that the following message repeats in my log every time the power meter is queried:

11:21:06.253 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 2 attempts left!
11:21:06.255 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:21:11.258 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
11:21:11.259 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:21:16.265 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 0 attempts left!
11:21:16.266 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:21:26.465 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 2 attempts left!
11:21:26.466 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:21:31.469 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
11:21:31.470 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:21:36.474 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 0 attempts left!
11:21:36.476 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.

I attach my item configuration and my debug log showing materials proximal to one of the failures. The system works fine, but my logs fill up rapidly.

Many thanks,

-Mark

Configuration:
################################ Z-Wave Binding ######################################

The Z-Wave controller port. Valid values are e.g. COM1 for Windows and /dev/ttyS0 or

/dev/ttyUSB0 for Linux

zwave:port=/dev/ttyACM0

Z-Wave nightly heal time. This is the hour (eg 2AM) at which the automatic nightly

network heal will be performed.

zwave:healtime=2
zwave:aliveCheckPeriod=500
zwave:pollingQueue=20

Note the same thing happens when the pollingQueue is set to the default value of 2

Items related to power meter:
Number Energy “House Energy Consumption [%.2f kWh]” (Power) { zwave=“16:command=meter,meter_scale=E_kWh,refresh_interval=20” }
Number Voltage “House Voltage [%.2f V]” (Power) { zwave=“16:command=meter,meter_scale=E_V,refresh_interval=20” }
Number Amperage “House Amperage [%.2f A]” (Power) { zwave=“16:command=meter,meter_scale=E_A,refresh_interval=20” }
Number HousePower “House Power [%.2f W]” (Power) { zwave=“16:command=meter,meter_scale=E_W,refresh_interval=20” }
Number PowerFactor “Power Factor [%.2f PF]” (Power) { zwave=“16:command=meter,meter_scale=E_Power_Factor,refresh_interval=20” }

Portion of debug log above one failure:
11:17:05.047 [DEBUG] [b.z.i.protocol.ZWaveController:938 ] - Callback ID = 100
11:17:05.048 [DEBUG] [b.z.i.protocol.ZWaveController:620 ] - Enqueueing message. Queue length = 5
11:17:05.049 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 4
11:17:05.051 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 0A 00 13 10 03 32 01 30 25 64 B7
11:17:05.052 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 32 01 30 25 64 B7
11:17:05.062 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
11:17:05.063 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:05.063 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:17:05.065 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 04 01 13 01 E8
11:17:05.066 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
11:17:05.068 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
11:17:05.069 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38 ] - NODE 16: Sent Data successfully placed on stack.
11:17:05.078 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 64 00 00 03 8C
11:17:05.080 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:05.080 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:17:05.082 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 09 00 13 64 00 00 03 00 00 82
11:17:05.083 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 64 00 00 03 00 00 82
11:17:05.084 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 64 00 00 03
11:17:05.086 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ] - NODE 16: SendData Request. CallBack ID = 100, Status = Transmission complete and ACK received($
11:17:05.087 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:17:05.088 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 64 00 00 03
11:17:05.089 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
11:17:07.746 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:17:10.054 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
11:17:10.055 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:17:10.055 [DEBUG] [b.z.i.protocol.ZWaveController:938 ] - Callback ID = 101
11:17:10.056 [DEBUG] [b.z.i.protocol.ZWaveController:620 ] - Enqueueing message. Queue length = 5
11:17:10.056 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 4
11:17:10.057 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 0A 00 13 10 03 32 01 30 25 65 B6
11:17:10.057 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 32 01 30 25 65 B6
11:17:10.066 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
11:17:10.068 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:05.080 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:05.080 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:17:05.082 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 09 00 13 64 00 00 03 00 00 82
11:17:05.083 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 64 00 00 03 00 00 82
11:17:05.084 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 64 00 00 03
11:17:05.086 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ] - NODE 16: SendData Request. CallBack ID = 100, Status = Transmission complete and ACK received($
11:17:05.087 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:17:05.088 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 64 00 00 03
11:17:05.089 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
11:17:07.746 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:17:10.054 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
11:17:10.055 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.
11:17:10.055 [DEBUG] [b.z.i.protocol.ZWaveController:938 ] - Callback ID = 101
11:17:10.056 [DEBUG] [b.z.i.protocol.ZWaveController:620 ] - Enqueueing message. Queue length = 5
11:17:10.056 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 4
11:17:10.057 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 0A 00 13 10 03 32 01 30 25 65 B6
11:17:10.057 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 32 01 30 25 65 B6
11:17:10.066 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
11:17:10.068 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:10.068 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:17:10.069 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 04 01 13 01 E8
11:17:10.069 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
11:17:10.070 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
11:17:10.071 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38 ] - NODE 16: Sent Data successfully placed on stack.
11:17:10.083 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 65 00 00 02 8C
11:17:10.084 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:17:10.084 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:17:10.086 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 09 00 13 65 00 00 02 00 00 82
11:17:10.087 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 65 00 00 02 00 00 82
11:17:10.088 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 65 00 00 02
11:17:10.088 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ] - NODE 16: SendData Request. CallBack ID = 101, Status = Transmission complete and ACK received($
11:17:10.089 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:17:10.090 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 65 00 00 02
11:17:10.091 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
11:17:12.747 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:17:15.061 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 0 attempts left!
11:17:15.062 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 16: Got an error while sending data. Resending message.

chris · July 24, 2016, 3:34pm

Can you provide the actual model of the device.

It’s possible that the device doesn’t support these requests since it seems the request is probably getting to the device and it’s probably just not responding.

When you post logs, please format them with the </> button as it’s hard to interpret without formatting.

noemark1 · July 24, 2016, 5:40pm

Chris-

It is a DSB28-ZWUS from Aeon.

Regarding the logs, I was not aware there was a button for this. I now see there are several - is the correct one the preformatted text button? I can repost my logs if needed.

The data does appear on my Openhab site. It appears that for some reason it is trying to access the device three times and then timing out, but I do get all of the data that is requested in my items list.

Many thanks,

-Mark

chris · July 24, 2016, 6:00pm

Annoyingly, the forum removed the bit where I said which button (I needed to wrap it in quotes). It’s the one </>.

My suspicion is that the device doesn’t respond to polling, and probably you also have associations configured, so the device periodically sends the information. This would mean you get the errors when polling, but the information still updates since it sends unsolicited.

noemark1 · July 24, 2016, 9:41pm

Chris-

When I remove the polling interval from the items related to the power meter, then I only get an initial reading from the meter. It does not update periodically. I was able to use the same power meter with an older Zstick 2 without this problem. However, the Zstick 2 was not reliable for other nodes in my house (presumably a lower power radio). The Zstick 5 has shown itself to be more reliable with the exception of this issue. It’s not a problem other than the logs filling up. I suppose I could just turn off logging, but that is not my preferred solution…

Many thanks,

-Mark

chris · July 24, 2016, 9:57pm

I don’t expect the issue will be related to the stick, so it’s likely either the device, or a bug in the binding.

In the log above, from what I can tell anyway, the messages are timing out, so I expect this means there is no response. Maybe if you can provide a full debug log and I’ll take a better look.

noemark1 · July 24, 2016, 10:52pm

Chris-
The debug log is shown around the error - the full log is quite long, but if you tell me how to upload a file I will do that. Hopefully I formatted it correctly this time.

Many thanks,

-Mark

11:14:58.390 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:14:58.391 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8
11:14:58.392 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
11:14:58.393 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
11:14:58.394 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 16: Sent Data successfully placed on stack.
11:14:58.406 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 2F 00 00 03 C7
11:14:58.409 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:14:58.409 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:14:58.411 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 2F 00 00 03 00 00 C9
11:14:58.413 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 2F 00 00 03 00 00 C9
11:14:58.414 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 2F 00 00 03
11:14:58.415 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 16: SendData Request. CallBack ID = 47, Status = Transmission complete and ACK received(0)
11:14:58.417 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:14:58.418 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 2F 00 00 03
11:14:58.419 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
11:15:02.612 [DEBUG] [z.internal.ZWaveNetworkMonitor:315  ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:15:03.380 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 2 attempts left!
11:15:03.381 [ERROR] [b.z.i.p.s.SendDataMessageClass:158  ] - NODE 16: Got an error while sending data. Resending message.
11:15:03.381 [DEBUG] [b.z.i.protocol.ZWaveController:938  ] - Callback ID = 52
11:15:03.382 [DEBUG] [b.z.i.protocol.ZWaveController:620  ] - Enqueueing message. Queue length = 5
11:15:03.382 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 4
11:15:03.382 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 10 03 32 01 30 25 34 E7
11:15:03.383 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 32 01 30 25 34 E7
11:15:03.392 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
11:15:03.393 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:15:03.393 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:15:03.394 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8
11:15:03.395 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
11:15:03.396 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
11:15:03.396 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 16: Sent Data successfully placed on stack.
11:15:03.409 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 34 00 00 02 DD
11:15:03.411 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:15:03.411 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:15:03.412 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 34 00 00 02 00 00 D3
11:15:03.413 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 34 00 00 02 00 00 D3
11:15:03.414 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 34 00 00 02
11:15:03.414 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 16: SendData Request. CallBack ID = 52, Status = Transmission complete and ACK received(0)
11:15:03.415 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:15:03.416 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 34 00 00 02
11:15:03.417 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
1
11:15:07.614 [DEBUG] [z.internal.ZWaveNetworkMonitor:315  ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:15:08.384 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
11:15:08.385 [ERROR] [b.z.i.p.s.SendDataMessageClass:158  ] - NODE 16: Got an error while sending data. Resending message.
11:15:08.385 [DEBUG] [b.z.i.protocol.ZWaveController:938  ] - Callback ID = 53
11:15:08.385 [DEBUG] [b.z.i.protocol.ZWaveController:620  ] - Enqueueing message. Queue length = 5
11:15:08.386 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 4
11:15:08.386 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 0A 00 13 10 03 32 01 30 25 35 E6
11:15:08.387 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 32 01 30 25 35 E6
11:15:08.395 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
11:15:08.396 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:15:08.397 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:15:08.397 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 04 01 13 01 E8
11:15:08.398 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
11:15:08.398 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
11:15:08.398 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38   ] - NODE 16: Sent Data successfully placed on stack.
11:15:08.413 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 35 00 00 02 DC
11:15:08.416 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
11:15:08.416 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
11:15:08.417 [DEBUG] [o.b.z.i.protocol.SerialMessage:233  ] - Assembled message buffer = 01 09 00 13 35 00 00 02 00 00 D2
11:15:08.417 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 35 00 00 02 00 00 D2
11:15:08.417 [DEBUG] [b.z.i.protocol.ZWaveController:192  ] - Message: class = SendData (0x13), type = Request (0x00), payload = 35 00 00 02
11:15:08.418 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74   ] - NODE 16: SendData Request. CallBack ID = 53, Status = Transmission complete and ACK received(0)
11:15:08.418 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63   ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 10 03 32 01 30
11:15:08.419 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64   ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 35 00 00 02
11:15:08.419 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65   ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=f$
11:15:12.616 [DEBUG] [z.internal.ZWaveNetworkMonitor:315  ] - Network Monitor: Queue length is 4 - deferring network monitor functions.
11:15:13.388 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 16: Timeout while sending message. Requeueing - 0 attempts left!
11:15:13.388 [ERROR] [b.z.i.p.s.SendDataMessageClass:158  ] - NODE 16: Got an error while sending data. Resending message.

chris · July 25, 2016, 6:26am

Can you email me the log and I’ll take a look (chris -at- cd-jackson.com).

When formatting the log in the forum, you need to ensure they whole log is highlighted before pressing the </> button, and there also needs to be a clear line above the log. I’ve reformatted your last message so you can see the difference with the first message.

noemark1 · July 25, 2016, 11:27am

Thank you Chris. I appreciate your help - with this and the text formatting issues. I just sent the full log as requested.

-Mark

chris · July 25, 2016, 4:17pm

So the device is systematically not responding to the power factor requests, but it is responding to all other requests. I don’t think that this device supports power factor - the manual states -:

 Include wattage, KWH, voltage and current.

I think if you remove this item your problem will be solved

noemark1 · July 25, 2016, 9:52pm

Chris-

That solved the problem. Thank you for your help! Where did you find that info. in my log?

Many thanks,

-Mark

chris · July 25, 2016, 10:48pm

Yep. I would highly recommend using the online log viewer as it will display things in a (reasonably!) user friendly format.

The following shows an example - we can see the Amps and Watts working fine, but then the Power Factor gets the ack from the device, but never sends the data, and this is systematic through the file…

noemark1 · July 26, 2016, 12:10pm

Thank you Chris - I was not aware of this tool, and it certainly makes quick work of diagnosis!

Many thanks,

-Mark