search

zigpy / zigpy-cli

Command line interface for zigpy
GNU General Public License v3.0
44 stars 12 forks source link

When I choose zigate to form a network , there is always zigpy.exceptions.NetworkNotFormed appear #18

Closed hwzolin closed 1 year ago

hwzolin commented 1 year ago

Hey all, The dongle I used is NXP 5169 and the firmware The software is downloaded from https://github.com/openlumi/ZiGate/release. If I use this dongle with python third-party library zigate, it can form network and pair zigbee devices normally, and I can control device ON of OFF too。 However, I use the command "zigpy -vvvv radio zigate COM4 form"，it always fail, and wrong message is "zigpy.exceptions.NetworkNotFormed". image I don't know what causes this problem. And when the program starts running, there also appear a warning message "Setting the pan_id is not supported by ZiGate". Em~~~~

Then I use command "zigpy radio zigate COM4 energy-scan", The program reported an error "asyncio.exceptions.TimeoutError" after running for some time. This is what has been bothering me for a long time. image

Can anyone help me to deal these questions? Thank you, very much.

puddly commented 1 year ago

Make sure you're running the latest version of zigpy-cli and zigpy.

Both zigpy -vv radio zigate /dev/... form and zigpy -vv radio zigate /dev/... backup -z - work fine for me with a USB ZiGate.

However, the warning you see is correct: ZiGate does not support setting the PAN ID, meaning it cannot restore a backup, nor can you read the network key to perform a full backup. It does not support the energy scan either.

hwzolin commented 1 year ago

@puddly Thanks for your response. This software version is really up to date . How can I overcome this problem? Buy a USB Zigate? Could you tell me what model you use?

puddly commented 1 year ago

There's nothing you can do without firmware support, it's not something that's fixable from software alone. Don't use the ZiGate if you want to use these features. Use a Texas Instruments CC2652, a Silicon Labs EFR32 stick, or a Conbee II.

That being said, you shouldn't be seeing errors performing a backup. Can you paste the entire output of zigpy -vv radio zigate COM4 backup -z -?

hwzolin commented 1 year ago

@puddly The output messages are here:

2022-09-01 14:06:33.109 mybook asyncio DEBUG Using proactor: IocpProactor 2022-09-01 14:06:33.210 mybook zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from 'D:\software\python\lib\sqlite3\init.py'>: 3.37.2 2022-09-01 14:06:33.260 mybook zigpy_zigate.uart DEBUG Connection made 2022-09-01 14:06:33.262 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_RAWMODE (b'\x01'), waiting for status: True, waiting for response: None 2022-09-01 14:06:33.262 mybook zigpy_zigate.uart DEBUG Send: 0x0002 b'01' 2022-09-01 14:06:33.262 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x02\x00\x01\x02\x01' 2022-09-01 14:06:33.262 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x12\x02\x10\x02\x11\x02\x12\x02\x11' 2022-09-01 14:06:33.262 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_RAWMODE 2022-09-01 14:06:33.277 mybook zigpy_zigate.uart DEBUG Frame received: 800000098b000000020000000000 2022-09-01 14:06:33.277 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000200000000' LQI:0 2022-09-01 14:06:33.277 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 2, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.278 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_TIMESERVER (b'\xa3x\xe9'), waiting for status: True, waiting for response: None 2022-09-01 14:06:33.278 mybook zigpy_zigate.uart DEBUG Send: 0x0016 b'2aa378e9' 2022-09-01 14:06:33.278 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x16\x00\x04\n\xa3x\xe9' 2022-09-01 14:06:33.278 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x16\x02\x10\x02\x14\x02\x1a*\xa3x\xe9' 2022-09-01 14:06:33.278 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_TIMESERVER 2022-09-01 14:06:33.293 mybook zigpy_zigate.uart DEBUG Frame received: 800000099f000000160000000000 2022-09-01 14:06:33.293 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001600000000' LQI:0 2022-09-01 14:06:33.293 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 22, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.293 mybook zigpy_zigate.api DEBUG Sending CommandId.GET_VERSION (b''), waiting for status: True, waiting for response: ResponseId.VERSION_LIST 2022-09-01 14:06:33.294 mybook zigpy_zigate.uart DEBUG Send: 0x0010 b'' 2022-09-01 14:06:33.294 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x10\x00\x00\x10' 2022-09-01 14:06:33.294 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x10\x02\x10\x02\x10\x10' 2022-09-01 14:06:33.294 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.GET_VERSION 2022-09-01 14:06:33.294 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.VERSION_LIST 2022-09-01 14:06:33.309 mybook zigpy_zigate.uart DEBUG Frame received: 8000000999000000100000000000 2022-09-01 14:06:33.309 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001000000000' LQI:0 2022-09-01 14:06:33.309 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 16, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.309 mybook zigpy_zigate.uart DEBUG Frame received: 80100005b40003032100 2022-09-01 14:06:33.309 mybook zigpy_zigate.api DEBUG data received 0x8010 b'00030321' LQI:0 2022-09-01 14:06:33.309 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.VERSION_LIST [3, 801] 2022-09-01 14:06:33.309 mybook zigpy_zigate.api DEBUG Sending CommandId.NETWORK_STATE_REQ (b''), waiting for status: True, waiting for response: ResponseId.NETWORK_STATE_RSP 2022-09-01 14:06:33.309 mybook zigpy_zigate.uart DEBUG Send: 0x0009 b'' 2022-09-01 14:06:33.309 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\t\x00\x00\t' 2022-09-01 14:06:33.309 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x19\x02\x10\x02\x10\x02\x19' 2022-09-01 14:06:33.309 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.NETWORK_STATE_REQ 2022-09-01 14:06:33.309 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NETWORK_STATE_RSP 2022-09-01 14:06:33.340 mybook zigpy_zigate.uart DEBUG Frame received: 8000000980000000090000000000 2022-09-01 14:06:33.340 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000900000000' LQI:0 2022-09-01 14:06:33.340 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 9, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.340 mybook zigpy_zigate.uart DEBUG Frame received: 8009001623000000158d00011df3c18ff73490beb330715dc80f00 2022-09-01 14:06:33.340 mybook zigpy_zigate.api DEBUG data received 0x8009 b'000000158d00011df3c18ff73490beb330715dc80f' LQI:0 2022-09-01 14:06:33.340 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NETWORK_STATE_RSP [0x0000, 00:15:8d:00:01:1d:f3:c1, 36855, 3787736963439746504, 15] 2022-09-01 14:06:33.340 mybook zigpy_zigate.api DEBUG Sending CommandId.GET_DEVICES_LIST (b''), waiting for status: True, waiting for response: ResponseId.GET_DEVICES_LIST_RSP 2022-09-01 14:06:33.340 mybook zigpy_zigate.uart DEBUG Send: 0x0015 b'' 2022-09-01 14:06:33.340 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x15\x00\x00\x15' 2022-09-01 14:06:33.340 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x15\x02\x10\x02\x10\x15' 2022-09-01 14:06:33.340 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.GET_DEVICES_LIST 2022-09-01 14:06:33.340 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.GET_DEVICES_LIST_RSP 2022-09-01 14:06:33.355 mybook zigpy_zigate.uart DEBUG Frame received: 800000099c000000150000000000 2022-09-01 14:06:33.356 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001500000000' LQI:0 2022-09-01 14:06:33.356 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 21, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.356 mybook zigpy_zigate.uart DEBUG Frame received: 801500019400 2022-09-01 14:06:33.356 mybook zigpy_zigate.api DEBUG data received 0x8015 b'' LQI:0 2022-09-01 14:06:33.356 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.GET_DEVICES_LIST_RSP [None] 2022-09-01 14:06:33.356 mybook zigpy.backups DEBUG Adding a new backup NetworkBackup(backup_time=datetime.datetime(2022, 9, 1, 6, 6, 33, 356791, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=34:90:be:b3:30:71:5d:c8, pan_id=0x8FF7, nwk_update_id=0, nwk_manager_id=0x0000, channel=15, channel_mask=<Channels.CHANNEL_15: 32768>, security_level=5, network_key=Key(key=ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff, tx_counter=0, rx_counter=0, seq=0, partner_ieee=ff:ff:ff:ff:ff:ff:ff:ff), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=00:15:8d:00:01:1d:f3:c1), key_table=[], children=[], nwk_addresses={}, stack_specific={}, metadata={'zigate': {'version': '3.21'}}, source='zigpy-zigate@0.9.2'), node_info=NodeInfo(nwk=0x0000, ieee=00:15:8d:00:01:1d:f3:c1, logical_type=<LogicalType.Coordinator: 0>)) 2022-09-01 14:06:33.357 mybook zigpy.backups DEBUG Backup is incomplete, ignoring 2022-09-01 14:06:33.358 mybook zigpy_zigate.api DEBUG Sending CommandId.RESET (b''), waiting for status: True, waiting for response: None 2022-09-01 14:06:33.358 mybook zigpy_zigate.uart DEBUG Send: 0x0011 b'' 2022-09-01 14:06:33.358 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x11\x00\x00\x11' 2022-09-01 14:06:33.358 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x11\x02\x10\x02\x10\x11' 2022-09-01 14:06:33.358 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.RESET { "backup_time": "2022-09-01T06:06:33.356791+00:00", "network_info": { "extended_pan_id": "34:90:be:b3:30:71:5d:c8", "pan_id": "8FF7", "nwk_update_id": 0, "nwk_manager_id": "0000", "channel": 15, "channel_mask": [ 15 ], "security_level": 5, "network_key": { "key": "ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff:ff", "tx_counter": 0, "rx_counter": 0, "seq": 0, "partner_ieee": "ff:ff:ff:ff:ff:ff:ff:ff" }, "tc_link_key": { "key": "5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39", "tx_counter": 0, "rx_counter": 0, "seq": 0, "partner_ieee": "00:15:8d:00:01:1d:f3:c1" }, "key_table": [], "children": [], "nwk_addresses": {}, "stack_specific": {}, "metadata": { "zigate": { "version": "3.21" } }, "source": "zigpy-zigate@0.9.2" }, "node_info": { "nwk": "0000", "ieee": "00:15:8d:00:01:1d:f3:c1", "logical_type": "coordinator" } } 2022-09-01 14:06:33.372 mybook zigpy_zigate.uart DEBUG Frame received: 8000000998000000110000000000 2022-09-01 14:06:33.372 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001100000000' LQI:0 2022-09-01 14:06:33.372 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 17, b'\x00\x00\x00\x00'] 2022-09-01 14:06:33.372 mybook zigpy_zigate.uart DEBUG Closed serial connection

puddly commented 1 year ago

It looks fine to me, it generates a backup with all the info the ZiGate allows to be read.

hwzolin commented 1 year ago

@puddly It is strange, May be my firmware is wrong? Could you provide the firmware you used?

puddly commented 1 year ago

I test with the ZiGate+ v2, which uses the JN5189, not the JN5168. The firmwares are different. But according to the log, everything is functional. What is not working?

Can you attach the log file for zigpy -vv radio zigate COM4 form?

hwzolin commented 1 year ago

Mine is NXP JN5169.

Just now my colleague asked me to try the zipgpy-zigate reinstall, and then I tried again, and this time there was no NetworkNotFormed error. However, there are still warning messages for "Setting the pan_id is not supported by ZiGate" message. The full log is as follows：

2022-09-01 14:31:05.362 mybook asyncio DEBUG Using proactor: IocpProactor 2022-09-01 14:31:05.467 mybook zigpy.appdb DEBUG SQLite version for <module 'sqlite3' from 'D:\software\python\lib\sqlite3\init.py'>: 3.37.2 2022-09-01 14:31:05.509 mybook zigpy_zigate.uart DEBUG Connection made 2022-09-01 14:31:05.509 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_RAWMODE (b'\x01'), waiting for status: True, waiting for response: None 2022-09-01 14:31:05.510 mybook zigpy_zigate.uart DEBUG Send: 0x0002 b'01' 2022-09-01 14:31:05.510 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x02\x00\x01\x02\x01' 2022-09-01 14:31:05.510 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x12\x02\x10\x02\x11\x02\x12\x02\x11' 2022-09-01 14:31:05.510 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_RAWMODE 2022-09-01 14:31:05.531 mybook zigpy_zigate.uart DEBUG Frame received: 800000098b000000020000000000 2022-09-01 14:31:05.531 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000200000000' LQI:0 2022-09-01 14:31:05.531 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 2, b'\x00\x00\x00\x00'] 2022-09-01 14:31:05.532 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_TIMESERVER (b'\xa3~\xa9'), waiting for status: True, waiting for response: None 2022-09-01 14:31:05.532 mybook zigpy_zigate.uart DEBUG Send: 0x0016 b'2aa37ea9' 2022-09-01 14:31:05.532 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x16\x00\x04L\xa3~\xa9' 2022-09-01 14:31:05.532 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x16\x02\x10\x02\x14L*\xa3~\xa9' 2022-09-01 14:31:05.532 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_TIMESERVER 2022-09-01 14:31:05.562 mybook zigpy_zigate.uart DEBUG Frame received: 800000099f000000160000000000 2022-09-01 14:31:05.562 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001600000000' LQI:0 2022-09-01 14:31:05.562 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 22, b'\x00\x00\x00\x00'] 2022-09-01 14:31:05.562 mybook zigpy_zigate.api DEBUG Sending CommandId.GET_VERSION (b''), waiting for status: True, waiting for response: ResponseId.VERSION_LIST 2022-09-01 14:31:05.562 mybook zigpy_zigate.uart DEBUG Send: 0x0010 b'' 2022-09-01 14:31:05.562 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x10\x00\x00\x10' 2022-09-01 14:31:05.562 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x10\x02\x10\x02\x10\x10' 2022-09-01 14:31:05.562 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.GET_VERSION 2022-09-01 14:31:05.562 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.VERSION_LIST 2022-09-01 14:31:05.594 mybook zigpy_zigate.uart DEBUG Frame received: 8000000999000000100000000000 2022-09-01 14:31:05.594 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001000000000' LQI:0 2022-09-01 14:31:05.594 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 16, b'\x00\x00\x00\x00'] 2022-09-01 14:31:05.594 mybook zigpy_zigate.uart DEBUG Frame received: 80100005b40003032100 2022-09-01 14:31:05.594 mybook zigpy_zigate.api DEBUG data received 0x8010 b'00030321' LQI:0 2022-09-01 14:31:05.594 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.VERSION_LIST [3, 801] 2022-09-01 14:31:05.594 mybook zigpy_zigate.zigbee.application WARNING Setting the pan_id is not supported by ZiGate 2022-09-01 14:31:05.594 mybook zigpy_zigate.api DEBUG Sending CommandId.ERASE_PERSISTENT_DATA (b''), waiting for status: False, waiting for response: ResponseId.PDM_LOADED 2022-09-01 14:31:05.594 mybook zigpy_zigate.uart DEBUG Send: 0x0012 b'' 2022-09-01 14:31:05.595 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x12\x00\x00\x12' 2022-09-01 14:31:05.595 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x12\x02\x10\x02\x10\x12' 2022-09-01 14:31:05.595 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.PDM_LOADED 2022-09-01 14:31:05.968 mybook zigpy_zigate.uart DEBUG Frame received: 03020002030000 2022-09-01 14:31:05.968 mybook zigpy_zigate.api DEBUG data received 0x302 b'00' LQI:0 2022-09-01 14:31:05.968 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.PDM_LOADED [0] 2022-09-01 14:31:05.968 mybook zigpy_zigate.uart DEBUG Frame received: 80070002850000 2022-09-01 14:31:05.968 mybook zigpy_zigate.api DEBUG data received 0x8007 b'00' LQI:0 2022-09-01 14:31:05.969 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NODE_FACTORY_NEW_RESTART [<FactoryNewRestartStatus.Startup: 0>] 2022-09-01 14:31:06.964 mybook zigpy_zigate.api DEBUG Sending CommandId.RESET (b''), waiting for status: True, waiting for response: ResponseId.NODE_FACTORY_NEW_RESTART 2022-09-01 14:31:06.964 mybook zigpy_zigate.uart DEBUG Send: 0x0011 b'' 2022-09-01 14:31:06.964 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x11\x00\x00\x11' 2022-09-01 14:31:06.964 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x11\x02\x10\x02\x10\x11' 2022-09-01 14:31:06.965 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.RESET 2022-09-01 14:31:06.965 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NODE_FACTORY_NEW_RESTART 2022-09-01 14:31:06.994 mybook zigpy_zigate.uart DEBUG Frame received: 8000000998000000110000000000 2022-09-01 14:31:06.995 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001100000000' LQI:0 2022-09-01 14:31:06.995 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 17, b'\x00\x00\x00\x00'] 2022-09-01 14:31:07.089 mybook zigpy_zigate.uart DEBUG Frame received: 03020002030000 2022-09-01 14:31:07.089 mybook zigpy_zigate.api DEBUG data received 0x302 b'00' LQI:0 2022-09-01 14:31:07.090 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.PDM_LOADED [0] 2022-09-01 14:31:07.104 mybook zigpy_zigate.uart DEBUG Frame received: 80070002850000 2022-09-01 14:31:07.104 mybook zigpy_zigate.api DEBUG data received 0x8007 b'00' LQI:0 2022-09-01 14:31:07.104 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NODE_FACTORY_NEW_RESTART [<FactoryNewRestartStatus.Startup: 0>] 2022-09-01 14:31:07.104 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_CHANNELMASK (b'\x00\x00\x80\x00'), waiting for status: True, waiting for response: None 2022-09-01 14:31:07.104 mybook zigpy_zigate.uart DEBUG Send: 0x0021 b'00008000' 2022-09-01 14:31:07.104 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00!\x00\x04\xa5\x00\x00\x80\x00' 2022-09-01 14:31:07.104 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10!\x02\x10\x02\x14\xa5\x02\x10\x02\x10\x80\x02\x10' 2022-09-01 14:31:07.104 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_CHANNELMASK 2022-09-01 14:31:07.151 mybook zigpy_zigate.uart DEBUG Frame received: 80000009a8000000210000000000 2022-09-01 14:31:07.151 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000002100000000' LQI:0 2022-09-01 14:31:07.151 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 33, b'\x00\x00\x00\x00'] 2022-09-01 14:31:07.152 mybook zigpy_zigate.api DEBUG Sending CommandId.SET_EXT_PANID (b'\xe0%\xe9\x84Wj8~'), waiting for status: True, waiting for response: None 2022-09-01 14:31:07.152 mybook zigpy_zigate.uart DEBUG Send: 0x0020 b'e025e984576a387e' 2022-09-01 14:31:07.152 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00 \x00\x08\xfb\xe0%\xe9\x84Wj8~' 2022-09-01 14:31:07.152 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10 \x02\x10\x02\x18\xfb\xe0%\xe9\x84Wj8~' 2022-09-01 14:31:07.152 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.SET_EXT_PANID 2022-09-01 14:31:07.182 mybook zigpy_zigate.uart DEBUG Frame received: 80000009a9000000200000000000 2022-09-01 14:31:07.183 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000002000000000' LQI:0 2022-09-01 14:31:07.183 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 32, b'\x00\x00\x00\x00'] 2022-09-01 14:31:07.183 mybook zigpy_zigate.api DEBUG Sending CommandId.START_NETWORK (b''), waiting for status: True, waiting for response: ResponseId.NETWORK_JOINED_FORMED 2022-09-01 14:31:07.184 mybook zigpy_zigate.uart DEBUG Send: 0x0024 b'' 2022-09-01 14:31:07.184 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00$\x00\x00$' 2022-09-01 14:31:07.184 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10$\x02\x10\x02\x10$' 2022-09-01 14:31:07.185 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.START_NETWORK 2022-09-01 14:31:07.185 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NETWORK_JOINED_FORMED 2022-09-01 14:31:07.245 mybook zigpy_zigate.uart DEBUG Frame received: 80000009ad000000240000000000 2022-09-01 14:31:07.245 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000002400000000' LQI:0 2022-09-01 14:31:07.245 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 36, b'\x00\x00\x00\x00'] 2022-09-01 14:31:07.539 mybook zigpy_zigate.uart DEBUG Frame received: 8024000d1101000000158d00011df3c10f00 2022-09-01 14:31:07.540 mybook zigpy_zigate.api DEBUG data received 0x8024 b'01000000158d00011df3c10f' LQI:0 2022-09-01 14:31:07.540 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NETWORK_JOINED_FORMED [1, 0x0000, 00:15:8d:00:01:1d:f3:c1, 15] 2022-09-01 14:31:07.541 mybook zigpy_zigate.zigbee.application WARNING Starting network got status 1, wait... 2022-09-01 14:31:08.538 mybook zigpy_zigate.api DEBUG Sending CommandId.NETWORK_STATE_REQ (b''), waiting for status: True, waiting for response: ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:08.538 mybook zigpy_zigate.uart DEBUG Send: 0x0009 b'' 2022-09-01 14:31:08.538 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\t\x00\x00\t' 2022-09-01 14:31:08.538 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x19\x02\x10\x02\x10\x02\x19' 2022-09-01 14:31:08.538 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.NETWORK_STATE_REQ 2022-09-01 14:31:08.538 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:08.569 mybook zigpy_zigate.uart DEBUG Frame received: 8000000980000000090000000000 2022-09-01 14:31:08.569 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000900000000' LQI:0 2022-09-01 14:31:08.569 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 9, b'\x00\x00\x00\x00'] 2022-09-01 14:31:08.569 mybook zigpy_zigate.uart DEBUG Frame received: 80090016c6000000158d00011df3c12e1de025e984576a387e0f00 2022-09-01 14:31:08.569 mybook zigpy_zigate.api DEBUG data received 0x8009 b'000000158d00011df3c12e1de025e984576a387e0f' LQI:0 2022-09-01 14:31:08.569 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NETWORK_STATE_RSP [0x0000, 00:15:8d:00:01:1d:f3:c1, 11805, 16151572393245685886, 15] 2022-09-01 14:31:09.547 mybook zigpy_zigate.api DEBUG Sending CommandId.NETWORK_STATE_REQ (b''), waiting for status: True, waiting for response: ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:09.548 mybook zigpy_zigate.uart DEBUG Send: 0x0009 b'' 2022-09-01 14:31:09.549 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\t\x00\x00\t' 2022-09-01 14:31:09.549 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x19\x02\x10\x02\x10\x02\x19' 2022-09-01 14:31:09.549 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.NETWORK_STATE_REQ 2022-09-01 14:31:09.550 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:09.579 mybook zigpy_zigate.uart DEBUG Frame received: 8000000980000000090000000000 2022-09-01 14:31:09.579 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000900000000' LQI:0 2022-09-01 14:31:09.579 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 9, b'\x00\x00\x00\x00'] 2022-09-01 14:31:09.579 mybook zigpy_zigate.uart DEBUG Frame received: 80090016c6000000158d00011df3c12e1de025e984576a387e0f00 2022-09-01 14:31:09.579 mybook zigpy_zigate.api DEBUG data received 0x8009 b'000000158d00011df3c12e1de025e984576a387e0f' LQI:0 2022-09-01 14:31:09.579 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NETWORK_STATE_RSP [0x0000, 00:15:8d:00:01:1d:f3:c1, 11805, 16151572393245685886, 15] 2022-09-01 14:31:10.591 mybook zigpy_zigate.api DEBUG Sending CommandId.NETWORK_STATE_REQ (b''), waiting for status: True, waiting for response: ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:10.591 mybook zigpy_zigate.uart DEBUG Send: 0x0009 b'' 2022-09-01 14:31:10.591 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\t\x00\x00\t' 2022-09-01 14:31:10.591 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x02\x19\x02\x10\x02\x10\x02\x19' 2022-09-01 14:31:10.592 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.NETWORK_STATE_REQ 2022-09-01 14:31:10.592 mybook zigpy_zigate.api DEBUG Wait for response ResponseId.NETWORK_STATE_RSP 2022-09-01 14:31:10.622 mybook zigpy_zigate.uart DEBUG Frame received: 8000000980000000090000000000 2022-09-01 14:31:10.622 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000000900000000' LQI:0 2022-09-01 14:31:10.622 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 9, b'\x00\x00\x00\x00'] 2022-09-01 14:31:10.623 mybook zigpy_zigate.uart DEBUG Frame received: 80090016c6000000158d00011df3c12e1de025e984576a387e0f00 2022-09-01 14:31:10.623 mybook zigpy_zigate.api DEBUG data received 0x8009 b'000000158d00011df3c12e1de025e984576a387e0f' LQI:0 2022-09-01 14:31:10.623 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.NETWORK_STATE_RSP [0x0000, 00:15:8d:00:01:1d:f3:c1, 11805, 16151572393245685886, 15] 2022-09-01 14:31:10.625 mybook zigpy_zigate.api DEBUG Sending CommandId.RESET (b''), waiting for status: True, waiting for response: None 2022-09-01 14:31:10.625 mybook zigpy_zigate.uart DEBUG Send: 0x0011 b'' 2022-09-01 14:31:10.625 mybook zigpy_zigate.uart DEBUG Frame to send: b'\x00\x11\x00\x00\x11' 2022-09-01 14:31:10.625 mybook zigpy_zigate.uart DEBUG Frame escaped: b'\x02\x10\x11\x02\x10\x02\x10\x11' 2022-09-01 14:31:10.625 mybook zigpy_zigate.api DEBUG Wait for status to command CommandId.RESET 2022-09-01 14:31:10.652 mybook zigpy_zigate.uart DEBUG Frame received: 8000000998000000110000000000 2022-09-01 14:31:10.653 mybook zigpy_zigate.api DEBUG data received 0x8000 b'0000001100000000' LQI:0 2022-09-01 14:31:10.653 mybook zigpy_zigate.zigbee.application DEBUG zigate_callback_handler ResponseId.STATUS [<Status.Success: 0>, 0, 17, b'\x00\x00\x00\x00'] 2022-09-01 14:31:10.654 mybook zigpy_zigate.uart DEBUG Closed serial connection

hwzolin commented 1 year ago

@puddly However when I run "zigpy radio zigate COM4 energy-scan", there will still be errors

2022-09-01 14:40:23.157 mybook zigpy.device INFO [0x0000] Requesting 'Node Descriptor' 2022-09-01 14:40:23.201 mybook zigpy.device INFO [0x0000] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.Coordinator: 0>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle|MainsPowered|FullFunctionDevice|AlternatePanCoordinator: 143>, manufacturer_code=4423, maximum_buffer_size=127, maximum_incoming_transfer_size=0, server_mask=11329, maximum_outgoing_transfer_size=0, descriptor_capability_field=<DescriptorCapability.NONE: 0>, allocate_address=True, is_alternate_pan_coordinator=True, is_coordinator=True, is_end_device=False, is_full_function_device=True, is_mains_powered=True, is_receiver_on_when_idle=True, is_router=False, *is_security_capable=False) 2022-09-01 14:40:23.202 mybook zigpy.device INFO [0x0000] Discovering endpoints 2022-09-01 14:40:23.247 mybook zigpy.device INFO [0x0000] Discovered endpoints: [1, 11, 10, 110, 21, 8, 3] 2022-09-01 14:40:23.247 mybook zigpy.device INFO [0x0000] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=11 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=10 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=110 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=21 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=8 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=3 in=[] out=[] status=<Status.NEW: 0>>] 2022-09-01 14:40:23.247 mybook zigpy.endpoint INFO [0x0000:1] Discovering endpoint information 2022-09-01 14:40:23.296 mybook zigpy.endpoint INFO [0x0000:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=2112, device_version=0, input_clusters=[0, 3, 25, 15, 1281], output_clusters=[2819, 0, 768, 4, 3, 8, 6, 5, 1794, 1280, 25, 513, 1025, 1024, 1030, 1027, 1029, 1026, 516, 1, 2821, 4096]) 2022-09-01 14:40:23.297 mybook zigpy.endpoint INFO [0x0000:11] Discovering endpoint information 2022-09-01 14:40:23.343 mybook zigpy.endpoint INFO [0x0000:11] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=11, profile=260, device_type=2112, device_version=0, input_clusters=[0, 25], output_clusters=[0]) 2022-09-01 14:40:23.343 mybook zigpy.endpoint INFO [0x0000:10] Discovering endpoint information 2022-09-01 14:40:23.403 mybook zigpy.endpoint INFO [0x0000:10] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=10, profile=260, device_type=2112, device_version=0, input_clusters=[0, 3, 516], output_clusters=[2819, 0, 768, 4, 3, 8, 6, 5, 257, 1794, 1280, 25, 513, 1025, 1024, 1030, 1027, 1029, 1026, 516, 1, 2821, 4096]) 2022-09-01 14:40:23.403 mybook zigpy.endpoint INFO [0x0000:110] Discovering endpoint information 2022-09-01 14:40:23.449 mybook zigpy.endpoint INFO [0x0000:110] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=110, profile=260, device_type=2112, device_version=0, input_clusters=[0, 3, 516], output_clusters=[2819, 0, 768, 4, 3, 8, 6, 5, 257, 1794, 1280, 25, 513, 1025, 1024, 1030, 1027, 1029, 1026, 516, 1, 2821, 4096]) 2022-09-01 14:40:23.449 mybook zigpy.endpoint INFO [0x0000:21] Discovering endpoint information 2022-09-01 14:40:23.513 mybook zigpy.endpoint INFO [0x0000:21] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=21, profile=260, device_type=0, device_version=0, input_clusters=[0, 3, 516], output_clusters=[2819, 0, 768, 4, 3, 8, 6, 5, 257, 1794, 1280, 25, 513, 1025, 1024, 1030, 1027, 1029, 1026, 516, 1, 2821, 4096]) 2022-09-01 14:40:23.514 mybook zigpy.endpoint INFO [0x0000:8] Discovering endpoint information 2022-09-01 14:40:23.558 mybook zigpy.endpoint INFO [0x0000:8] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=8, profile=260, device_type=0, device_version=0, input_clusters=[], output_clusters=[1]) 2022-09-01 14:40:23.559 mybook zigpy.endpoint INFO [0x0000:3] Discovering endpoint information 2022-09-01 14:40:23.606 mybook zigpy.endpoint INFO [0x0000:3] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=3, profile=260, device_type=0, device_version=0, input_clusters=[0, 25], output_clusters=[0]) 2022-09-01 14:40:23.606 mybook zigpy.device INFO [0x0000] Already have model and manufacturer info 2022-09-01 14:40:23.606 mybook zigpy.device INFO [0x0000] Discovered basic device information for 2022-09-01 14:40:23.635 mybook zigpy_cli.radio INFO Running scan... Traceback (most recent call last): File "D:\software\python\lib\asyncio\tasks.py", line 458, in wait_for return fut.result() asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "E:\projects\zigtest\main.py", line 18, in sys.exit(cli()) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 1130, in call return self.main(args, kwargs) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 1055, in main rv = self.invoke(ctx) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 1404, in invoke return ctx.invoke(self.callback, ctx.params) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\core.py", line 760, in invoke return __callback(args, kwargs) File "D:\software\python\ENVS\zig_install\lib\site-packages\click\decorators.py", line 38, in new_func return f(get_current_context().obj, *args, *kwargs) File "D:\software\python\ENVS\zig_install\lib\site-packages\zigpy_cli\cli.py", line 19, in inner return loop.run_until_complete(cmd(args, kwargs)) File "D:\software\python\lib\asyncio\base_events.py", line 646, in run_until_complete return future.result() File "D:\software\python\ENVS\zig_install\lib\site-packages\zigpy_cli\radio.py", line 168, in energy_scan rsp = await app.get_device(nwk=nwk).zdo.Mgmt_NWK_Update_req( File "D:\software\python\ENVS\zig_install\lib\site-packages\zigpy\device.py", line 325, in request return await asyncio.wait_for(req.result, timeout) File "D:\software\python\lib\asyncio\tasks.py", line 460, in wait_for raise exceptions.TimeoutError() from exc asyncio.exceptions.TimeoutError

puddly commented 1 year ago

Both of these are expected and are limitations of the ZiGate firmware:

  1. ZiGate does not support setting the PAN ID. There is no command in the firmware to do it.
  2. ZiGate does not support energy scanning.
hwzolin commented 1 year ago

@puddly Em.....Do you mean that I can not add device by ZiGate?

puddly commented 1 year ago

No, I just mean that those two options are not supported. The ZiGate firmware ignores zigpy's random PAN ID and substitutes its own. Everything else should work (more or less).

hwzolin commented 1 year ago

@puddly Okay, I get it. Thank you very much for your patience in answering my questions.