search

OpenZWave / open-zwave

a C++ library to control Z-Wave Networks via a USB Z-Wave Controller.
http://www.openzwave.net/
GNU Lesser General Public License v3.0
1.05k stars 916 forks source link

Problem with FLiRS dead nodes every two weeks #2442

Closed calypso2k closed 3 years ago

calypso2k commented 3 years ago

hi, I'm using Domoticz (tried with 1.6-1033-g3661f170 and newest OpenZwave) with Aeotec Stick Gen5 and I have this strange problems with FAKRO windows blinds: every two weeks or so, my blind shows as dead node. Removing and re-adding ANY device (can be ie. zwave bulb) in the network makes blind work again.

Example of log when a blind is in not responding state:

2020-11-01 12:11:30.711 Detail, Node050, AdvanceQueries queryPending=0 queryRetries=0 queryStage=None live=1
2020-11-01 12:11:30.711 Detail, Node050, QueryStage_ProtocolInfo
2020-11-01 12:11:30.711 Detail, Node050, Queuing (Query) Get Node Protocol Info (Node=50): 0x01, 0x04, 0x00, 0x41, 0x32, 0x88
2020-11-01 12:11:30.711 Detail, Node050, Queuing (Query) Query Stage Complete (ProtocolInfo)
2020-11-01 12:11:30.711 Info, Node050, Initializing Node. New Node: false (false)
2020-11-01 12:11:30.769 Detail, Node050, Notification: NodeNew
2020-11-01 12:11:30.770 Detail, Node050, Notification: NodeAdded
2020-11-01 12:12:14.404 Info, Node050, Sending (Query) message (Callback ID=0x00, Expected Reply=0x41) - Get Node Protocol Info (Node=50): 0x01, 0x04, 0x00, 0x41, 0x32, 0x88
2020-11-01 12:12:14.404 Info, Node050, Encrypted Flag is 0
2020-11-01 12:12:14.407 Detail, Node050,   Received: 0x01, 0x09, 0x01, 0x41, 0x53, 0xbc, 0x01, 0x04, 0x11, 0x07, 0x4a
2020-11-01 12:12:14.407 Info, Node050, Received reply to FUNC_ID_ZW_GET_NODE_PROTOCOL_INFO
2020-11-01 12:12:14.408 Info, Node050,   Protocol Info for Node 50:
2020-11-01 12:12:14.408 Info, Node050,     Listening     = false
2020-11-01 12:12:14.408 Info, Node050,     Frequent      = true
2020-11-01 12:12:14.408 Info, Node050,     Beaming       = true
2020-11-01 12:12:14.408 Info, Node050,     Routing       = true
2020-11-01 12:12:14.409 Info, Node050,     Max Baud Rate = 100000
2020-11-01 12:12:14.409 Info, Node050,     Version       = 4
2020-11-01 12:12:14.409 Info, Node050,     Security      = false
2020-11-01 12:12:14.409 Info, Node050,   Basic device class    (0x04) - Routing Slave
2020-11-01 12:12:14.409 Info, Node050,   Generic device Class  (0x11) - Multilevel Switch
2020-11-01 12:12:14.410 Info, Node050,   Specific device class (0x07) - Motor Control Class C
2020-11-01 12:12:14.410 Info, Node050,     COMMAND_CLASS_BASIC will be mapped to COMMAND_CLASS_SWITCH_MULTILEVEL
2020-11-01 12:12:14.410 Info, Node050,   Mandatory Command Classes for Node 50:
2020-11-01 12:12:14.411 Info, Node050,     COMMAND_CLASS_BASIC
2020-11-01 12:12:14.411 Info, Node050,     COMMAND_CLASS_SWITCH_BINARY
2020-11-01 12:12:14.411 Info, Node050,     COMMAND_CLASS_SWITCH_MULTILEVEL
2020-11-01 12:12:14.411 Info, Node050,     COMMAND_CLASS_MANUFACTURER_SPECIFIC
2020-11-01 12:12:14.411 Info, Node050,     COMMAND_CLASS_VERSION
2020-11-01 12:12:14.412 Info, Node050,   Mandatory Command Classes controlled by Node 50:
2020-11-01 12:12:14.412 Info, Node050,     None
2020-11-01 12:12:14.412 Detail, Node050,   Expected reply was received
2020-11-01 12:12:14.412 Detail, Node050,   Message transaction complete
2020-11-01 12:12:14.413 Detail, Node050, Removing current message
2020-11-01 12:12:14.413 Detail, Node050, Notification: NodeProtocolInfo
2020-11-01 12:12:14.413 Detail, Node050, Query Stage Complete (ProtocolInfo)
2020-11-01 12:12:14.413 Detail, Node050, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Probe live=1
2020-11-01 12:12:14.414 Detail, Node050, QueryStage_Probe
2020-11-01 12:12:14.414 Info, Node050, NoOperation::Set - Routing=true
2020-11-01 12:12:14.414 Detail, Node050, Queuing (NoOp) NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x34, 0xc4
2020-11-01 12:12:14.414 Detail, Node050, Queuing (Query) Query Stage Complete (Probe)
2020-11-01 12:12:14.415 Info, Node050, Sending (NoOp) message (Callback ID=0x34, Expected Reply=0x13) - NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x34, 0xc4
2020-11-01 12:12:14.415 Info, Node050, Encrypted Flag is 0
2020-11-01 12:12:14.426 Detail, Node050,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-11-01 12:12:14.426 Detail, Node050,   ZW_SEND_DATA delivered to Z-Wave stack
2020-11-01 12:12:18.629 Detail, Node050,   Received: 0x01, 0x07, 0x00, 0x13, 0x34, 0x01, 0x01, 0xa6, 0x79
2020-11-01 12:12:18.630 Detail, Node050,   ZW_SEND_DATA Request with callback ID 0x34 received (expected 0x34)
2020-11-01 12:12:18.630 Info, Node050, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2020-11-01 12:12:18.630 Warning, Node050, WARNING: Device is not a sleeping node.
2020-11-01 12:12:18.631 Info, Node050, QueryStageRetry stage Probe requested stage Probe max 3 retries 0 pending 1
2020-11-01 12:12:18.631 Detail, Node050,   Expected callbackId was received
2020-11-01 12:12:18.632 Detail, Node050,   Expected reply was received
2020-11-01 12:12:18.632 Detail, Node050,   Message transaction complete
2020-11-01 12:12:18.633 Detail, Node050, Removing current message
2020-11-01 12:12:18.634 Detail, Node050, Notification: Notification - NoOperation
2020-11-01 12:12:19.709 Info, Node050, Skipping Cache Save for Node 50 as its not past QueryStage_CacheLoad
2020-11-01 12:12:27.770 Detail, Node050, Query Stage Complete (Probe)
2020-11-01 12:12:27.771 Detail, Node050, AdvanceQueries queryPending=0 queryRetries=1 queryStage=Probe live=1
2020-11-01 12:12:27.771 Detail, Node050, QueryStage_Probe
2020-11-01 12:12:27.771 Info, Node050, NoOperation::Set - Routing=true
2020-11-01 12:12:27.771 Detail, Node050, Queuing (NoOp) NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x3b, 0xcb
2020-11-01 12:12:27.772 Detail, Node050, Queuing (Query) Query Stage Complete (Probe)
2020-11-01 12:12:27.772 Info, Node050, Sending (NoOp) message (Callback ID=0x3b, Expected Reply=0x13) - NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x3b, 0xcb
2020-11-01 12:12:27.773 Info, Node050, Encrypted Flag is 0
2020-11-01 12:12:27.784 Detail, Node050,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-11-01 12:12:27.785 Detail, Node050,   ZW_SEND_DATA delivered to Z-Wave stack
2020-11-01 12:12:32.094 Detail, Node050,   Received: 0x01, 0x07, 0x00, 0x13, 0x3b, 0x01, 0x01, 0xb0, 0x60
2020-11-01 12:12:32.095 Detail, Node050,   ZW_SEND_DATA Request with callback ID 0x3b received (expected 0x3b)
2020-11-01 12:12:32.095 Info, Node050, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2020-11-01 12:12:32.095 Warning, Node050, WARNING: Device is not a sleeping node.
2020-11-01 12:12:32.096 Info, Node050, QueryStageRetry stage Probe requested stage Probe max 3 retries 1 pending 1
2020-11-01 12:12:32.096 Detail, Node050,   Expected callbackId was received
2020-11-01 12:12:32.096 Detail, Node050,   Expected reply was received
2020-11-01 12:12:32.097 Detail, Node050,   Message transaction complete
2020-11-01 12:12:32.097 Detail, Node050, Removing current message
2020-11-01 12:12:32.098 Detail, Node050, Notification: Notification - NoOperation
2020-11-01 12:13:16.432 Info, Node050, Skipping Cache Save for Node 50 as its not past QueryStage_CacheLoad
2020-11-01 12:13:17.925 Info, Node050, Skipping Cache Save for Node 50 as its not past QueryStage_CacheLoad
2020-11-01 12:13:18.897 Detail, Node050, Query Stage Complete (Probe)
2020-11-01 12:13:18.897 Detail, Node050, AdvanceQueries queryPending=0 queryRetries=2 queryStage=Probe live=1
2020-11-01 12:13:18.898 Detail, Node050, QueryStage_Probe
2020-11-01 12:13:18.898 Info, Node050, NoOperation::Set - Routing=true
2020-11-01 12:13:18.898 Detail, Node050, Queuing (NoOp) NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x5f, 0xaf
2020-11-01 12:13:18.898 Detail, Node050, Queuing (Query) Query Stage Complete (Probe)
2020-11-01 12:13:18.899 Info, Node050, Sending (NoOp) message (Callback ID=0x5f, Expected Reply=0x13) - NoOperation_Set (Node=50): 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x00, 0x00, 0x25, 0x5f, 0xaf
2020-11-01 12:13:18.899 Info, Node050, Encrypted Flag is 0
2020-11-01 12:13:18.909 Detail, Node050,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-11-01 12:13:18.909 Detail, Node050,   ZW_SEND_DATA delivered to Z-Wave stack
2020-11-01 12:13:23.144 Detail, Node050,   Received: 0x01, 0x07, 0x00, 0x13, 0x5f, 0x01, 0x01, 0xa8, 0x1c
2020-11-01 12:13:23.145 Detail, Node050,   ZW_SEND_DATA Request with callback ID 0x5f received (expected 0x5f)
2020-11-01 12:13:23.145 Info, Node050, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2020-11-01 12:13:23.145 Warning, Node050, WARNING: Device is not a sleeping node.
2020-11-01 12:13:23.145 Error, Node050, ERROR: node presumed dead
2020-11-01 12:13:23.156 Info, Node050, Skipping Cache Save for Node 50 as its not past QueryStage_CacheLoad
2020-11-01 12:13:23.161 Info, Node050, QueryStageRetry stage Probe requested stage Probe max 3 retries 2 pending 1
2020-11-01 12:13:23.162 Detail, Node050,   Expected callbackId was received
2020-11-01 12:13:23.162 Detail, Node050,   Expected reply was received
2020-11-01 12:13:23.162 Detail, Node050,   Message transaction complete
2020-11-01 12:13:23.162 Detail, Node050, Removing current message
2020-11-01 12:13:23.163 Detail, Node050, Notification: Notification - NoOperation
2020-11-01 12:13:23.164 Detail, Node050, Notification: Notification - Node Dead
2020-11-01 12:14:58.340 Detail, Node050, Query Stage Complete (Probe)
Fishwaldo commented 3 years ago

You should check all the other nodes that are neighbors of this device support BEAMING and are not battery powered devices (there have been a few battery powered devices that report BEAMING, and thats a bug with the device).

Not much OZW can really do here, as if the device falls off the network, its either a buggy neighbor, or the device itself.

calypso2k commented 3 years ago

Hi, thank you for your answer, I'm sorry that you closed the issue without further conversation.

If I may ask another question:

The question is: what exactly happens that after adding new device to network, FLIRS blinds starts to talk to controler for some time (no devices are moved, newly added device is certainly out of reach of failing FLIRS)?

I'll appreciate if you can answer