Job not sent before timeout

[swlewis]

Z-wave version 3.0.2, Raspberry Pi 3 Model B, RaZberry 1024/2

I have some scenes with 10+ actions and frequently some of them are not carried out. Upon investigation, it seems that they time out before they are sent to the Z-Wave network.

This is an example from the log:

[2019-12-04 08:16:30.973] [zway] Job 0x13 (Security, SwitchBinary Set): Job not sent before timeout
[2019-12-04 08:16:30.973] [zway] Job 0x13 (Security, SwitchBinary Set): Cancelling job: Security, SwitchBinary Set

All of the devices have good connectivity to the controller.

Anybody any ideas why this is happening or what I can do to fix it? I've searched for a job timeout setting, and can't find one.

Any thoughts would be appreciated.

[micky1500]

I'm also getting these timeouts, only since upgrading from 3.0.1 to 3.0.2
Z-wave 3.0.2 on Raspberry Pi 4
A few Log examples :-

[2019-12-03 17:35:34.109] [zway] Adding job: Get background noise level
[2019-12-03 17:35:34.114] [D] [zway] SENDING: ( 01 03 00 3B C7 )
[2019-12-03 17:35:34.318] [zway] Job 0x3b (Get background noise level): No ACK received before timeout
[2019-12-03 17:35:34.318] [D] [zway] SENDING: ( 01 03 00 3B C7 )
[2019-12-03 17:35:34.521] [zway] Job 0x3b (Get background noise level): No ACK received before timeout
[2019-12-03 17:35:34.521] [D] [zway] SENDING: ( 01 03 00 3B C7 )
[2019-12-03 17:35:34.725] [zway] Job 0x3b (Get background noise level): No ACK received before timeout
[2019-12-03 17:35:34.725] [W] [zway] Job 0x3b (Get background noise level) dropped: too many resends
[2019-12-03 17:35:34.725] [D] [zway] Job 0x3b (Get background noise level): fail
[2019-12-03 17:35:34.725] [zway] Removing job: Get background noise level
[2019-12-03 17:35:34.727] [D] [zway] RECEIVED ACK
[2019-12-03 17:35:34.727] [W] [zway] Received ACK, but there's no job awaiting ACK

[2019-11-29 02:40:22.013] [zway] Adding job: Basic Get
[2019-11-29 02:40:22.017] [D] [zway] SENDING (cb 0x30): ( 01 09 00 13 11 02 20 02 25 30 C1 )
[2019-11-29 02:40:22.221] [zway] Job 0x13 (Basic Get): No ACK received before timeout
[2019-11-29 02:40:22.221] [D] [zway] SENDING (cb 0x31): ( 01 09 00 13 11 02 20 02 25 31 C0 )
[2019-11-29 02:40:22.336] [D] [zway] RECEIVED ACK
[2019-11-29 02:40:22.351] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-11-29 02:40:22.351] [D] [zway] SENT ACK
[2019-11-29 02:40:22.351] [D] [zway] Delivered to Z-Wave stack
[2019-11-29 02:40:22.357] [D] [zway] RECEIVED CAN
[2019-11-29 02:40:22.357] [W] [zway] Received CAN, but there's no job awaiting ACK

[2019-11-30 07:35:01.400] [core] Daylight: Schedule update executed
[2019-11-30 07:35:01.440] [zway] Job 0x13 (SwitchMultilevel Set): No ACK received before timeout
[2019-11-30 07:35:01.440] [D] [zway] SENDING (cb 0xbc): ( 01 0A 00 13 11 03 26 01 00 25 BC 4A )
[2019-11-30 07:35:01.479] [core] [BaseModule-9] Set lastLevel to on for Daylight_22 (was off)
[2019-11-30 07:35:01.544] [I] [core] [BaseModule-9] Set lastLevel to off for ConditionSwitch_18 (was on)
[2019-11-30 07:35:01.608] [I] [core] --- Code_Device_switchBinary_244 performCommand processing: {"0":"off"}
[2019-11-30 07:35:01.645] [I] [zway] Job 0x13 (SwitchMultilevel Set): No ACK received before timeout
[2019-11-30 07:35:01.645] [D] [zway] SENDING (cb 0xbd): ( 01 0A 00 13 11 03 26 01 00 25 BD 4B )
[2019-11-30 07:35:01.821] [D] [zway] RECEIVED ACK
[2019-11-30 07:35:01.826] [D] [zway] RECEIVED: ( 01 05 01 3B AE A8 C6 )
[2019-11-30 07:35:01.826] [D] [zway] SENT ACK
[2019-11-30 07:35:01.826] [W] [zway] Received response, but there's no matching request (funcId = 0x3b)
[2019-11-30 07:35:01.828] [D] [zway] RECEIVED CAN
[2019-11-30 07:35:01.829] [W] [zway] Received CAN, but there's no job awaiting ACK
[2019-11-30 07:35:01.829] [D] [zway] RECEIVED CAN
[2019-11-30 07:35:01.829] [W] [zway] Received CAN, but there's no job awaiting ACK
[2019-11-30 07:35:01.829] [D] [zway] RECEIVED CAN
[2019-11-30 07:35:01.829] [W] [zway] Received CAN, but there's no job awaiting ACK
[2019-11-30 07:35:01.921] [D] [zway] RECEIVED: ( 01 05 01 3B AE A8 C6 )
[2019-11-30 07:35:01.921] [D] [zway] SENT ACK
[2019-11-30 07:35:01.921] [W] [zway] Received response, but there's no matching request (funcId = 0x3b)
[2019-11-30 07:35:03.595] [I] [core] Notification: device-info (device-OnOff): {"dev":"All Curtains BASH","l":"off","location":13}
[2019-11-30 07:35:03.806] [I] [core] --- ZWayVDev_zway_39-2-37 performCommand processing: {"0":"off"}
[2019-11-30 07:35:03.806] [I] [zway] Adding job: SwitchBinary Set
[2019-11-30 07:35:03.806] [I] [zway] Adding job: SwitchBinary Get
[2019-11-30 07:35:03.806] [I] [core] --- ZWayVDev_zway_10-0-38 performCommand processing: {"0":"exact","1":{"level":0}}
[2019-11-30 07:35:03.806] [I] [zway] Adding job: SwitchMultilevel Set
[2019-11-30 07:35:03.806] [I] [zway] Adding job: SwitchMultilevel Get
[2019-11-30 07:35:03.806] [I] [core] --- HTTP_Device_switchMultilevel_273 performCommand processing: {"0":"exact","1":{"level":21}}
[2019-11-30 07:35:03.810] [I] [core] Notification: device-info (device-status): {"dev":"Nextion Brightness","l":"21%","location":10}
[2019-11-30 07:35:03.963] [I] [core] [BaseModule-9] Set lastLevel to off for Code_Device_switchBinary_244 (was on)
[2019-11-30 07:35:04.026] [I] [core] [BaseModule-9] Set lastLevel to 21 for HTTP_Device_switchMultilevel_273 (was 2)
[2019-11-30 07:35:06.671] [D] [zway] Job 0x13: deleted from queue
[2019-11-30 07:35:08.423] [D] [zway] Job 0x13: deleted from queue
[2019-11-30 07:35:08.433] [D] [zway] Job 0x13: deleted from queue
[2019-11-30 07:35:20.814] [D] [zway] Job 0x3b: deleted from queue
[2019-11-30 07:35:22.366] [I] [zway] Job 0x13 (SwitchMultilevel Set): No RESPONSE received before timeout
[2019-11-30 07:35:22.366] [W] [zway] Job 0x13 (SwitchMultilevel Set) dropped: too many resends
[2019-11-30 07:35:22.366] [D] [zway] Job 0x13 (SwitchMultilevel Set): fail
[2019-11-30 07:35:22.366] [I] [zway] Removing job: SwitchMultilevel Set
[2019-11-30 07:35:22.366] [D] [zway] SENDING (cb 0xbe): ( 01 09 00 13 11 02 26 02 25 BE 49 )
[2019-11-30 07:35:22.377] [D] [zway] RECEIVED ACK
[2019-11-30 07:35:22.382] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-11-30 07:35:22.382] [D] [zway] SENT ACK
[2019-11-30 07:35:22.382] [D] [zway] Delivered to Z-Wave stack
[2019-11-30 07:35:22.525] [D] [zway] RECEIVED: ( 01 18 00 13 BE 00 00 0E 00 B8 7F 7F 7F 7F 01 01 03 00 00 00 00 02 01 00 00 FC )
[2019-11-30 07:35:22.525] [D] [zway] SENT ACK
[2019-11-30 07:35:22.526] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2019-11-30 07:35:22.526] [D] [zway] SendData Response with callback 0xbe received: received by recipient
[2019-11-30 07:35:22.526] [D] [zway] SETDATA devices.17.data.lastSendInternal = **********
[2019-11-30 07:35:22.526] [D] [zway] SETDATA devices.17.data.lastSend = 32623474 (0x01f1cb72)
[2019-11-30 07:35:22.526] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2019-11-30 07:35:22.526] [I] [zway] Waiting for job reply: SwitchMultilevel Get
[2019-11-30 07:35:22.526] [D] [zway] SENDING (cb 0xbf): ( 01 0E 00 13 27 07 60 0D 00 02 25 01 00 25 BF 13 )
[2019-11-30 07:35:22.537] [W] [zway] Received SOF, while awaiting ACK

[PoltoS]

A lot of CAN and No ACK - this looks like a USB/Serial communication problem. Is there something running on the same port in parallel?