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 918 forks source link

Fibaro Button (FGPB-101) Problems #2614

Closed igorlopez closed 2 years ago

igorlopez commented 2 years ago

I have the FGPB-101 button connected to a Rasberry PI3 with a RaZberry Hat. The button is found during initialisation of the network but when I press the button I am getting the following response: 

2021-08-11 15:03:12.973 Detail, Node002,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x02, 0x05, 0x5b, 0x03, 0x28, 0x80, 0x01, 0x7e, 0x00, 0x7e   
2021-08-11 15:03:12.973 Detail,    
2021-08-11 15:03:12.973 Info, Node002, Received Central Scene set from node 2: scene id=1 in 7680 seconds. Sending event notification.   
2021-08-11 15:03:12.973 Warning, Node002, No ValueID created for Scene 1

I am running latest master built on the Pi and am using the openzwave python repo to interface with nodes and the python callbacks does not happen for SIGNAL_VALUE_CHANGED but it does so with another node.

Pasting in part of what is written to the console when my python app is starting(running debug level for python logger):

2021-08-11 15:02:43.470 Always, OpenZwave Version 1.4.3428 Starting Up
DEBUG:openzwave:Use sqlite version : ('3.27.2',)
INFO:openzwave:Start Openzwave network.
2021-08-11 15:02:43.475 Info, Setting Up Provided Network Key for Secure Communications
2021-08-11 15:02:43.475 Warning, Failed - Network Key Not Set
2021-08-11 15:02:43.476 Info, mgr,     Added driver for controller /dev/ttyUSB20
2021-08-11 15:02:43.476 Info,   Opening controller /dev/ttyUSB20
2021-08-11 15:02:43.476 Info, Trying to open serial port /dev/ttyUSB20 (attempt 1)
2021-08-11 15:02:43.476 Info, Serial port /dev/ttyUSB20 opened (attempt 1)
...
2021-08-11 15:02:43.613 Info, mgr,     Driver with Home ID of 0xf5c1e3ad is now ready.
2021-08-11 15:02:43.613 Info, 
2021-08-11 15:02:43.623 Info, Node002, CentralScene - Created 0
2021-08-11 15:02:43.628 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2021-08-11 15:02:43.628 Info, contrlr,     Node 001 - Known
2021-08-11 15:02:43.629 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2021-08-11 15:02:43.629 Detail, Node001, QueryStage_CacheLoad
2021-08-11 15:02:43.629 Info, Node001, Node Identity Codes: 0147:0400:0002
2021-08-11 15:02:43.629 Detail, Node001, QueryStage_Associations
2021-08-11 15:02:43.629 Detail, Node001, QueryStage_Neighbors
2021-08-11 15:02:43.629 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2021-08-11 15:02:43.630 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2021-08-11 15:02:43.631 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2021-08-11 15:02:43.631 Info, contrlr,     Node 002 - Known
2021-08-11 15:02:43.631 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2021-08-11 15:02:43.631 Detail, Node002, QueryStage_CacheLoad
2021-08-11 15:02:43.631 Info, Node002, Node Identity Codes: 010f:0f01:1000
2021-08-11 15:02:43.631 Info, Node002, NoOperation::Set - Routing=true
2021-08-11 15:02:43.632 Detail, Node002, Queuing (NoOp) NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xca
2021-08-11 15:02:43.632 Detail, Node002, Queuing (Query) Query Stage Complete (CacheLoad)
2021-08-11 15:02:43.662 Detail, Node002, Notification: NodeAdded
2021-08-11 15:02:43.668 Detail, Node002, Notification: NodeProtocolInfo
2021-08-11 15:02:43.671 Detail, Node002, Notification: EssentialNodeQueriesComplete
2021-08-11 15:02:43.676 Detail, Node002, Notification: ValueAdded          <--- 46 different ValueAdded with different ValueID, GetCommandClassId, GetType
2021-08-11 15:02:43.964 Detail, Node002, Notification: Group               <---  4 groups  groupIdx 1:4
2021-08-11 15:02:43.987 Detail, Node002, Notification: NodeNaming
...
2021-08-11 15:02:44.541 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2021-08-11 15:02:44.543 Detail, contrlr, Removing current message
2021-08-11 15:02:44.544 Detail, 
2021-08-11 15:02:44.544 Info, Node001, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2021-08-11 15:02:44.550 Detail, Node001,   Received: 0x01, 0x20, 0x01, 0x80, 0x06, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x58
2021-08-11 15:02:44.550 Detail, 
2021-08-11 15:02:44.550 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2021-08-11 15:02:44.551 Info, Node001,     Neighbors of this node are:
2021-08-11 15:02:44.551 Info, Node001,     Node 2
2021-08-11 15:02:44.551 Info, Node001,     Node 3
2021-08-11 15:02:44.551 Detail,   Expected reply was received
2021-08-11 15:02:44.551 Detail,   Message transaction complete
2021-08-11 15:02:44.551 Detail, 
2021-08-11 15:02:44.551 Detail, Node001, Removing current message
2021-08-11 15:02:44.551 Detail, 
2021-08-11 15:02:44.551 Info, Node002, Sending (NoOp) message (Callback ID=0x0a, Expected Reply=0x13) - NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xca
2021-08-11 15:02:44.558 Detail, Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2021-08-11 15:02:44.558 Detail, Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2021-08-11 15:02:49.057 Detail, Node002,   Received: 0x01, 0x18, 0x00, 0x13, 0x0a, 0x01, 0x01, 0xc2, 0x00, 0x7f, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x01, 0x07, 0x00, 0x00, 0x00, 0x00, 0x02, 0x0a, 0x00, 0x00, 0x4d
2021-08-11 15:02:49.058 Detail, Node002,   ZW_SEND_DATA Request with callback ID 0x0a received (expected 0x0a)
2021-08-11 15:02:49.058 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2021-08-11 15:02:49.058 Info, Node002,   Node 2 has been marked as asleep
2021-08-11 15:02:49.058 Info, Node002, Node not responding - moving QueryStageComplete command to Wake-Up queue
2021-08-11 15:02:49.058 Detail, Node002, Notification: Notification - NoOperation
2021-08-11 15:02:49.062 Detail, Node002, Notification: Notification - Node Asleep

Comparing the different ValueAdded blocks between the Fibaro button and the Telldus Power Outlet gives diff in supported commandClasses (regarding switch) FGPB101 Button

TZWP-102 Plug-in Switch

And I have seen a lot of issues with handling of central scenes.

What can I do to debug deeper? Since I have not read the Z-Wave specification I do not now how the system is supposed to work.

Another diff between the nodes is that the FGPB-101 goes into sleep mode but awakes when button is pressed, e.g. one can see the message being sent to the controller but no notification/callback was issued. When I press the button on the Telldus power outlet I get a lot more info in the console:

2021-08-11 15:03:21.378 Detail, Node003,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x03, 0x03, 0x20, 0x03, 0xff, 0xc9, 0x00, 0xe5
2021-08-11 15:03:21.378 Detail, 
2021-08-11 15:03:21.378 Info, Node003, Received Basic report from node 3: level=255
2021-08-11 15:03:21.378 Detail, Node003, Queuing (Send) SwitchBinaryCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x25, 0x02, 0x25, 0x14, 0xf2
2021-08-11 15:03:21.378 Detail, 
2021-08-11 15:03:21.378 Info, Node003, Sending (Send) message (Callback ID=0x14, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=3): 0x01, 0x09, 0x00, 0x13, 0x03, 0x02, 0x25, 0x02, 0x25, 0x14, 0xf2
2021-08-11 15:03:21.384 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2021-08-11 15:03:21.384 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2021-08-11 15:03:21.402 Detail, Node003,   Received: 0x01, 0x18, 0x00, 0x13, 0x14, 0x00, 0x00, 0x01, 0x00, 0xc9, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x29
2021-08-11 15:03:21.403 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x14 received (expected 0x14)
2021-08-11 15:03:21.403 Info, Node003, Request RTT 24 Average Request RTT 24
2021-08-11 15:03:21.403 Detail,   Expected callbackId was received
2021-08-11 15:03:21.419 Detail, Node003,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x03, 0x03, 0x25, 0x03, 0xff, 0xc9, 0x00, 0xe0
2021-08-11 15:03:21.419 Detail, 
2021-08-11 15:03:21.419 Info, Node003, Response RTT 40 Average Response RTT 222
2021-08-11 15:03:21.419 Info, Node003, Received SwitchBinary report from node 3: level=On
2021-08-11 15:03:21.419 Detail, Node003, Refreshed Value: old value=false, new value=true, type=bool
2021-08-11 15:03:21.419 Detail, Node003, Changes to this value are not verified
2021-08-11 15:03:21.419 Detail, Node003,   Expected reply and command class was received
2021-08-11 15:03:21.419 Detail, Node003,   Message transaction complete
2021-08-11 15:03:21.419 Detail, 
2021-08-11 15:03:21.419 Detail, Node003, Removing current message
2021-08-11 15:03:21.419 Detail, Node003, Notification: ValueChanged
igorlopez commented 2 years ago

Ok, some further studies into why the start of the network shows this: 2021-08-11 15:02:43.470 Always, OpenZwave Version 1.4.3428 Starting Up I checked in my open-zwave repo where I did build the libs and there I can see in the source that it should have been: 2021-08-11 15:02:43.470 Always, OpenZwave Version 1.6-1930-ga8aa6341 Starting Up instead so it looks like that when I start the network from my python application it somehow uses a lib (not named libopenzwave.so) that is for version 1.4 which I know lacks support for Central Scenes so I think this issue can be closed and I need to find out what lib the python module is actually talking to.