Manual or Setup instructions

ss89 commented 8 months ago

Hi @lhespress

thanks for this great addition to zigpy!

i would love to see a manual/setup instructions for the hardware and example zigpy commands to test whether the setup works in the README.md.

i am trying to make it work for me with a ESP32 devkit + a ESP32-C6 via UART and the unmodified host/ncb example sketch from here:

My assumption is the following:

we need 2 ESP32, one with zigbee capabilities (who would've thought that?)
There is no directly connecting the host computer running zigpy to the esp32-c6 (yet?)
Both espressif sketches need to be configured to use the correct board pins

With this in mind, i would still need to fight the esp32 (host) reboot upon serial connect. Did you encounter this as well or do i need to set something special in the sketch? I did read something about dtr settings that need to be applied to the usb hosts serial app (zigpy in my case).

Hardware setup: ESP32 Pin 4 <-> ESP-C6 Pin 17 ESP32 Pin 5 <-> ESP-C6 Pin 16 ESP32 Ping Gnd <-> ESP-C6 Pin Gnd ESP32 USB <-> PC USB ESP32-C6 USB (both) <-> PC USB

Commands tried ‘zigpy radio --baudrate 115200 /dev/tty.usbserial-1001 eznp info‘ (writing these out of my head, as i'm on the go)

besides some timeout error i finally yesterday also got some other info printed by zigpy before that timeout error, i'll try to post output in ~12 hours.

I believe that the esp32 reboot is the only issue remaining for trying out some zigpy commands with success.

Hedda commented 8 months ago

Be warned that this new zigpy-espzb is in very early development and before this is including in ZHA by default it will be very difficult to migrate away so do not use it for anything other than testing (not for your your primary/production network), and understand that at this point it is only usable for zigpy and ZHA developers for verifying functionality as well as for other developers interested in trying it out and reporting issues to this experimental repository, so do not expect this to be stable at all.

Anyway, until merged it is unlikely that there be any step-by-step instructions unless you write it yourself, however you can find some some pointers on how to install and setup/configure a other expertimental third-party radio library for zigpy and ZHA here:

https://community.home-assistant.io/t/nordic-semi-nrf52840-chips-with-zboss-zigbee-stack-now-usable-as-zigbee-coordinator-for-the-zha-integration-via-new-radio-library-for-zigpy/570196

Specifically this post by stolevegen (Stole) here:

https://community.home-assistant.io/t/nordic-semi-nrf52840-chips-with-zboss-zigbee-stack-now-usable-as-zigbee-coordinator-for-the-zha-integration-via-new-radio-library-for-zigpy/570196/10

Note! Until merged this is depending on these changes to zigpy-cli which needs to be implmeneted as well in order to use it:

https://github.com/zigpy/zigpy-cli/pull/45

A tip is that developers should even be able to test this with zigpy-cli as a stand-alone tool to test sending commands to radio via zigpy-espzb but understand that it is not meant to be used that way so it will be very slow, (as zigpy-cli is not meant to be a complete API for all zigpy functions, instead zigpy-cli is at this point more just a set of common development tools only for debugging and less commonly used tasks that is available and shared for all radios for zigpy), and as for the real implementation you really need to look at the ZHA integration component inside Home Assistant core:

https://github.com/home-assistant/core/tree/dev/homeassistant/components/zha

FYI, for reference also check out these related general instructions on how to install and update new released of libraries in HA:

https://github.com/zigpy/zigpy/blob/dev/CONTRIBUTING.md#testing-new-releases

https://github.com/zigpy/zigpy/blob/dev/CONTRIBUTING.md#setup

https://github.com/zigpy/zigpy-znp/blob/dev/README.md#home-assistant

PS: There is byw also a discussion thread about zigpy-espzb in Home Assistant community forum but it is targeting end-users:

https://community.home-assistant.io/t/esp32-h2-esp32-c6-with-zigbee-ncp-firmware-will-soon-be-usable-as-remote-zigbee-coordinator-for-the-zha-integration-via-new-radio-library-for-zigpy/685638

Hedda commented 8 months ago

My assumption is the following:

we need 2 ESP32, one with zigbee capabilities (who would've thought that?)

Two SoC solution is way it used in Espressif reference hardware design but it is not a must as zigpy only need a serial connection.

You could for example instead design a new USB-only board adapter (similar to all other Zigbee Coordinator USB dongles available on the marker) that uses some kind of USB-to-UART (USB-to-Serial) communication, which is usually done by developers with an external debugger/programmer board with USB-to-UART interface, or on a production board meant for end-users using on-board USB-to-UART bridge/converter chip -> https://docs.espressif.com/projects/esp-idf/en/stable/esp32h2/get-started/establish-serial-connection.html ...preferably a USB-to-Serial converter/bridge chip with programmable EEPROM (such as example Silicon Labs CP210x series like the popular CP2102N and CP2102, FTDI FT231 series, or WCH CH340B) that also allow you to write a unique USB product identifier as that will allow the USB dongle to be automatically discovered via USB discovery -> https://community.home-assistant.io/t/community-help-wanted-to-whitelist-all-compatible-zigbee-and-z-wave-dongles-adapters-for-automatic-usb-discovery-in-home-assistant/344412

On-board USB-to-UART Bridge as for example used if designing ESP32-H2/ESP32-C6 based Zigbee Coordinator USB dongle:

External USB-to-UART Bridge as for example used temporarily under the development of non-USB development boards:

Alternativly you could instead design different kinds of ESP32-H2 to PHY Ethernet boards using a UART-to-Ethernet bridge/converter chip to basically make a network-attached serial adapter for connection using serial-over-IP (i.e. some kind of chip with Ethernet component -> https://docs.espressif.com/projects/esp-idf/en/stable/esp32h2/api-reference/network/esp_eth.html?highlight=ethernet which irronically can be a other ESP32 chip or something purpose build like a W5500 chip or other ESP32 Ethernet PHY chips) -> https://pcbartists.com/design/embedded/esp32-ethernet-phy-chips-supported-by-arduino-esp-idf/

Check out for example this DIY gateway project which aims to create a Serial-over-IP proxy-> https://github.com/zigpy/zigpy/discussions/584

That in essence replaces the second ESP32 board with some kind of SoC that can provide Ethernet PHY and run a serial server:

https://github.com/espressif/esp-zigbee-sdk/tree/main/examples/esp_zigbee_gateway

Those type of network-attached Zigbee Coordinator adapters with Ethernet interface are popular among advanced users, and similar to USB discovery they instead offer ability for automatic Zeroconf network discovery -> https://www.home-assistant.io/integrations/zeroconf/ ( at least in the ZHA integration inside Home Assistant -> https://www.home-assistant.io/integrations/zha#discovery-via-usb-or-zeroconf ). Check out for example these different Ethernet based designs:

PS: Note that with the Zigbee Coordinator you absolutly want to use wired connection end-to-end, as in either a USB-to-UART connection or a Ethernet-to-UART based solution, (and not a WiFi-to-UART solution) for a production Zigbee network. I and most others strongly advise against using a WiFi connection for any serial-over-IP communcations with the ZHA integrations and similar Zigbee gateway host applications. With any serial connection going over WiFi you are sooner or later garanteed to get connection problems that are caused by dopped packages unless the serial protocol and application used has been specifically been built robust enough to handle dropped packages, and there are specific warnings about using Wi-Fi-based Zigbee-to-Serial bridges/gateways as remote Zigbee Coordinator adapters with the ZHA integration and Zigbee2MQTT, see example:

https://www.home-assistant.io/integrations/zha#warning-about-wi-fi-based-zigbee-to-serial-bridgesgateways

https://www.zigbee2mqtt.io/advanced/remote-adapter/connect_to_a_remote_adapter.html

WARNING

WiFi-based Serial-to-IP bridges are not recommended as the serial protocol does not have enough fault-tolerance to handle packet loss or latency delays that can normally occur over WiFi connections.

Hedda commented 8 months ago

Two SoC solution is way it used in Espressif reference hardware design but it is not a must as zigpy only need a serial connection.

You could for example instead design a new USB-only board adapter (similar to all other Zigbee Coordinator USB dongles available on the marker) that uses some kind of USB-to-UART (USB-to-Serial) communication, which is usually done by developers with an external debugger/programmer board with USB-to-UART interface, or on a production board meant for end-users using on-board USB-to-UART bridge/converter chip -> https://docs.espressif.com/projects/esp-idf/en/stable/esp32h2/get-started/establish-serial-connection.html ...preferably a USB-to-Serial converter/bridge chip with programmable EEPROM (such as example Silicon Labs CP210x series like the popular CP2102N and CP2102, FTDI FT231 series, or WCH CH340B) that also allow you to write a unique USB product identifier as that will allow the USB dongle to be automatically discovered via USB discovery -> https://community.home-assistant.io/t/community-help-wanted-to-whitelist-all-compatible-zigbee-and-z-wave-dongles-adapters-for-automatic-usb-discovery-in-home-assistant/344412

@lhespress Does ESP32-C6-DevKit and ESP32-H2-DevKit dev boards not provide such USB-to-UART Bridge interface for that?

Key Component Description:

USB-to-UART Bridge = Single USB-to-UART bridge chip provides transfer rates up to 3 Mbps.
USB Type-C to UART Port = Used for power supply to the board, for flashing applications to the chip, as well as the communication with the ESP32-C6 chip via the on-board USB-to-UART bridge.

https://docs.espressif.com/projects/espressif-esp-dev-kits/en/latest/esp32h2/esp32-h2-devkitm-1/user_guide.html

https://docs.espressif.com/projects/espressif-esp-dev-kits/en/latest/esp32c6/esp32-c6-devkitc-1/user_guide.html

Hedda commented 8 months ago

Alternativly you could instead design different kinds of ESP32-H2 to PHY Ethernet boards using a UART-to-Ethernet bridge/converter chip to basically make a network-attached serial adapter for connection using serial-over-IP (i.e. some kind of chip with Ethernet component, which irronically can be a other ESP32 chip or something purpose build like a W5500 chip or other ESP32 Ethernet PHY chips) -> https://pcbartists.com/design/embedded/esp32-ethernet-phy-chips-supported-by-arduino-esp-idf/

Those type of network-attached Zigbee Coordinator adapters with Ethernet interface are popular among advanced users, and similar to USB discovery they instead offer ability for automatic Zeroconf network discovery -> https://www.home-assistant.io/integrations/zeroconf/ ( at least in the ZHA integration inside Home Assistant -> https://www.home-assistant.io/integrations/zha#discovery-via-usb-or-zeroconf ). Check out for example these different Ethernet based designs:

https://github.com/tube0013/tubeszb_addons

https://github.com/mercenaruss/zigstar_gateways

https://github.com/codm/cc2652p2-tcp-zigbee

https://github.com/cyijun/OpenZ3Gateway

https://zigate.fr/produit/zigate-ethernet/

https://smartlight.me/smart-home-devices/zigbee-devices/smlight-zigbee-lan-adapter-slzb-05en

https://smlight.tech/product/slzb-06/

PS: Note that with the Zigbee Coordinator you absolutly want to use wired connection end-to-end, as in either a USB-to-UART connection or a Ethernet-to-UART based solution, (and not a WiFi-to-UART solution) for a production Zigbee network. I and most others strongly advise against using a WiFi connection for any serial-over-IP communcations with the ZHA integrations and similar Zigbee gateway host applications. With any serial connection going over WiFi you are sooner or later garanteed to get connection problems that are caused by dopped packages unless the serial protocol and application used has been specifically been built robust enough to handle dropped packages, and there are specific warnings about using Wi-Fi-based Zigbee-to-Serial bridges/gateways as remote Zigbee Coordinator adapters with the ZHA integration and Zigbee2MQTT, see example:

https://www.home-assistant.io/integrations/zha#warning-about-wi-fi-based-zigbee-to-serial-bridgesgateways

https://www.zigbee2mqtt.io/advanced/remote-adapter/connect_to_a_remote_adapter.html

WARNING WiFi-based Serial-to-IP bridges are not recommended as the serial protocol does not have enough fault-tolerance to handle packet loss or latency delays that can normally occur over WiFi connections.

See that Espressif Thread Border Router / Zigbee Gateway (ESP Thread BR-Zigbee GW) board supports both Wi-Fi and Ethernet interfaces as backbone link:

https://docs.espressif.com/projects/esp-thread-br/en/latest/hardware_platforms.html

So if want to make it network-attached then do make it a Ethernet based (wired) like the ESP Thread Border Router/Zigbee Gateway Sub-Ethernet (which I believe is based on the mentioned W5500 chip for Ethernet PHY):

PS: If designing a brand new board then check out Olimex's ESP32 gateway series for ideas on slimline Ethernet gateway designs:

https://www.olimex.com/Products/IoT/ESP32/ESP32-GATEWAY/open-source-hardware

https://www.olimex.com/Products/IoT/ESP32/ESP32-POE-ISO/open-source-hardware

https://www.olimex.com/Products/IoT/ESP32/ESP32-POE/open-source-hardware

https://www.olimex.com/Products/IoT/ESP32/ESP32-EVB/open-source-hardware

ss89 commented 8 months ago

Thanks for your extensive response @Hedda.

If i get it the correct way, then to test basic functionality i should be able to connect an FTDI usb serial adapter (or any other usb to serial adapter) and connect its ground and rx/tx (reversed) to the esp32-c6 directly and it should just respond to commands as intended immediately given i configured the rx/tx pins correctly in the example ncp firmware? This i did try now and in fact the esp32-c6 is rebooting all the time.

The second thing i understood is that it should also "just" work via it's usb-c port of the ch343, given i configured the firmware correctly. This i might try tomorrow.

Hedda commented 8 months ago

If i get it the correct way, then to test basic functionality i should be able to connect an FTDI usb serial adapter (or any other usb to serial adapter) and connect its ground and rx/tx (reversed) to the esp32-c6 directly and it should just respond to commands as intended immediately given i configured the rx/tx pins correctly in the example ncp firmware? This i did try now and in fact the esp32-c6 is rebooting all the time.

The second thing i understood is that it should also "just" work via it's usb-c port of the ch343, given i configured the firmware correctly.

Yeah that is how understand it. Just note that since UART / Serial connections are exclusive you can not have more than a single connect to the same UART/Serial interfave, meaning that I believe that you can not have zigpy/ZHA trying to connect the same time you are connecting with for example a debugger?

lhespress commented 8 months ago

@ss89 Please check it as follows steps:

/dev/ttyUSB0: Connect a USB cable to UART port for power supply, output log and download firmware.
/dev/ttyUSB1: Connect an external UART adapter to ESP32-H2-DevKitM-1 ( GND/GND, TX/IO4, RX/IO5) for input command and output response.
Configure the UART by Zigbee Network Co-processor component.
Check the communication between the external UART adapter and ESP32-H2-DevKitM-1 by UART tools. Please check the line if there isn't log as follows:
Testing functionality which will output LOG as follows on /dev/ttyUSB0 using the following command: zigpy -vvv radio --baudrate 115200 znsp /dev/ttyUSB1 backup -z

lhespress commented 8 months ago

Does ESP32-C6-DevKit and ESP32-H2-DevKit dev boards not provide such USB-to-UART Bridge interface for that?

@Hedda Both development boards are two TYPE-C USB ports, one is connected to the chip USB port, and the other is USB-UART0 bridge.

ss89 commented 8 months ago

@ss89 Please check it as follows steps:

/dev/ttyUSB0: Connect a USB cable to UART port for power supply, output log and download firmware.

/dev/ttyUSB1: Connect an external UART adapter to ESP32-H2-DevKitM-1 ( GND/GND, TX/IO4, RX/IO5) for input command and output response.

Configure the UART by Zigbee Network Co-processor component.

Check the communication between the external UART adapter and ESP32-H2-DevKitM-1 by UART tools. Please check the line if there isn't log as follows:

Testing functionality which will output LOG as follows on /dev/ttyUSB0 using the following command: zigpy -vvv radio --baudrate 115200 znsp /dev/ttyUSB1 backup -z

I am in fact receiving 0x1000000000010001 instead of 0x1000000000010000 now.

Here's the full output:

zigpy -vvv radio --baudrate 115200 znsp /dev/tty.usbmodem57770036491 backup -z
2024-03-20 18:32:28.932 my-devices-hostname asyncio DEBUG Using selector: KqueueSelector
2024-03-20 18:32:28.936 my-devices-hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Inovelli object at 0x112637cd0>
2024-03-20 18:32:28.936 my-devices-hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Ledvance object at 0x112637e80>
2024-03-20 18:32:28.936 my-devices-hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Salus object at 0x112637eb0>
2024-03-20 18:32:28.936 my-devices-hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Sonoff object at 0x112637fa0>
2024-03-20 18:32:28.937 my-devices-hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.ThirdReality object at 0x112634f40>
2024-03-20 18:32:28.937 my-devices-hostname zigpy_espzb.uart DEBUG Connecting to /dev/tty.usbmodem57770036491
2024-03-20 18:32:28.937 my-devices-hostname zigpy.serial DEBUG Opening a serial connection to '/dev/tty.usbmodem57770036491' (115200 baudrate)
2024-03-20 18:32:28.955 my-devices-hostname zigpy_espzb.uart DEBUG Connection made
2024-03-20 18:32:28.955 my-devices-hostname zigpy_espzb.uart DEBUG Connected to /dev/tty.usbmodem57770036491
2024-03-20 18:32:28.955 my-devices-hostname zigpy_espzb.api DEBUG Sending 0{} (seq=0)
2024-03-20 18:32:28.955 my-devices-hostname zigpy_espzb.uart DEBUG Send: 00000000000000
2024-03-20 18:32:28.959 my-devices-hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000000010001
2024-03-20 18:32:28.960 my-devices-hostname zigpy_espzb.api WARNING Failed to parse command Command(flags=16, command_id=0, seq=0, payload=b'\x01\x00\x01')
Traceback (most recent call last):
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/api.py", line 734, in data_received
    params, rest = t.deserialize_dict(command.payload, rx_schema)
AttributeError: module 'zigpy.types' has no attribute 'deserialize_dict'
2024-03-20 18:32:28.960 my-devices-hostname zigpy_espzb.api DEBUG Serial '/dev/tty.usbmodem57770036491' connection lost unexpectedly: None
Traceback (most recent call last):
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/bin/zigpy", line 33, in <module>
    sys.exit(load_entry_point('zigpy-cli==0.0.0', 'console_scripts', 'zigpy')())
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/click/decorators.py", line 45, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_cli/cli.py", line 20, in inner
    return loop.run_until_complete(cmd(*args, **kwargs))
  File "/usr/local/Cellar/python@3.10/3.10.9/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
    return future.result()
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_cli/radio.py", line 117, in backup
    await app.connect()
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/zigbee/application.py", line 80, in connect
    await api.connect()
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/api.py", line 598, in connect
    await self.network_init()
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/api.py", line 874, in network_init
    await self.send_command(CommandId.networkinit)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/api.py", line 630, in send_command
    return await self._command(cmd, **kwargs)
  File "/Users/ss89/.espressif/python_env/idf5.2_py3.10_env/lib/python3.10/site-packages/zigpy_espzb/api.py", line 700, in _command
    return await fut
zigpy.exceptions.APIException: Failed to deserialize command: Command(flags=16, command_id=0, seq=0, payload=b'\x01\x00\x01')

lhespress commented 8 months ago

I am in fact receiving 0x1000000000010001 instead of 0x1000000000010000 now.

@ss89 0x1000000000010001 means that the device's resume network operation has finished, but receive the same command again. You need reboot the device after checked the communication by UART tools.

ss89 commented 7 months ago

I tried it with rebooting (now actually with an esp32-h2) and i still get an error that it failed to deserialize the command:

2024-04-06 18:32:01.766 Sebastians-MBP.fritz.box asyncio DEBUG Using selector: KqueueSelector
2024-04-06 18:32:01.770 Sebastians-MBP.fritz.box zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Inovelli object at 0x1124d8160>
2024-04-06 18:32:01.771 Sebastians-MBP.fritz.box zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Ledvance object at 0x1124d8430>
2024-04-06 18:32:01.771 Sebastians-MBP.fritz.box zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Salus object at 0x1124d8460>
2024-04-06 18:32:01.771 Sebastians-MBP.fritz.box zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Sonoff object at 0x1124d8550>
2024-04-06 18:32:01.771 Sebastians-MBP.fritz.box zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.ThirdReality object at 0x1124d85e0>
2024-04-06 18:32:01.771 Sebastians-MBP.fritz.box zigpy_espzb.uart DEBUG Connecting to /dev/tty.usbmodem579B0264851
2024-04-06 18:32:01.772 Sebastians-MBP.fritz.box zigpy.serial DEBUG Opening a serial connection to '/dev/tty.usbmodem579B0264851' (115200 baudrate)
2024-04-06 18:32:01.789 Sebastians-MBP.fritz.box zigpy_espzb.uart DEBUG Connection made
2024-04-06 18:32:01.789 Sebastians-MBP.fritz.box zigpy_espzb.uart DEBUG Connected to /dev/tty.usbmodem579B0264851
2024-04-06 18:32:01.789 Sebastians-MBP.fritz.box zigpy_espzb.api DEBUG Sending 0{} (seq=0)
2024-04-06 18:32:01.790 Sebastians-MBP.fritz.box zigpy_espzb.uart DEBUG Send: 00000000000000
2024-04-06 18:32:01.795 Sebastians-MBP.fritz.box zigpy_espzb.uart DEBUG Frame received: 0x1000000000010000
2024-04-06 18:32:01.795 Sebastians-MBP.fritz.box zigpy_espzb.api WARNING Failed to parse command Command(flags=16, command_id=0, seq=0, payload=b'\x01\x00\x00')
Traceback (most recent call last):
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 734, in data_received
    params, rest = t.deserialize_dict(command.payload, rx_schema)
AttributeError: module 'zigpy.types' has no attribute 'deserialize_dict'
2024-04-06 18:32:01.796 Sebastians-MBP.fritz.box zigpy_espzb.api DEBUG Serial '/dev/tty.usbmodem579B0264851' connection lost unexpectedly: None
Traceback (most recent call last):
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/bin/zigpy", line 8, in <module>
    sys.exit(cli())
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/decorators.py", line 45, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "/Users/sebastian/development/ESP32/zigpy-cli/zigpy_cli/cli.py", line 20, in inner
    return loop.run_until_complete(cmd(*args, **kwargs))
  File "/usr/local/Cellar/python@3.9/3.9.16/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
    return future.result()
  File "/Users/sebastian/development/ESP32/zigpy-cli/zigpy_cli/radio.py", line 117, in backup
    await app.connect()
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/zigbee/application.py", line 80, in connect
    await api.connect()
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 598, in connect
    await self.network_init()
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 874, in network_init
    await self.send_command(CommandId.networkinit)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 630, in send_command
    return await self._command(cmd, **kwargs)
  File "/Users/sebastian/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 700, in _command
    return await fut
zigpy.exceptions.APIException: Failed to deserialize command: Command(flags=16, command_id=0, seq=0, payload=b'\x01\x00\x00')

Is this expected with a fresh Out-of-the-box esp32-h2 that hasn't been used in any way for zigbee purposes yet?

How do i get to get a similar result as you?

lhespress commented 7 months ago

@ss89 Which commit do you used?

Hedda commented 7 months ago

I tried it with rebooting (now actually with an esp32-h2) and i still get an error that it failed to deserialize the command

@ss89 can I suggest maybe consider starting a new issue as those latest posts are starting to get off-topic from the original issue?

lhespress commented 7 months ago

@ss89 I and @puddly are fix some bugs, you can also follow up https://github.com/lhespress/zigpy-espzb/pull/13.

ss89 commented 7 months ago

@ss89 Which commit do you used?

I did use the latest master back then, so likely it was this commit: dcecec5ac93eb2a31e567a465285f48cc6cd064b

@ss89 I and @puddly are fix some bugs, you can also follow up #13.

I will check it out. Might take a bit, as every time i didn't use python related things for a bit homebrew updates break my idf setup.

I'll report back once i got some results, thanks!

ss89 commented 7 months ago

Now this looks a lot better now (backup request):

$ zigpy -vvv radio --baudrate 115200 znsp /dev/tty.usbmodem579B0264851 backup -z

2024-04-27 20:09:49.545 my.devices.hostname asyncio DEBUG Using selector: KqueueSelector
2024-04-27 20:09:49.554 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Inovelli object at 0x10e94d160>
2024-04-27 20:09:49.554 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Ledvance object at 0x10e91deb0>
2024-04-27 20:09:49.554 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Salus object at 0x10e91df10>
2024-04-27 20:09:49.554 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Sonoff object at 0x10e9386a0>
2024-04-27 20:09:49.554 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.ThirdReality object at 0x10e943670>
2024-04-27 20:09:49.555 my.devices.hostname zigpy_espzb.uart DEBUG Connecting to /dev/tty.usbmodem579B0264851
2024-04-27 20:09:49.555 my.devices.hostname zigpy.serial DEBUG Opening a serial connection to '/dev/tty.usbmodem579B0264851' (115200 baudrate)
2024-04-27 20:09:49.572 my.devices.hostname zigpy_espzb.uart DEBUG Connection made
2024-04-27 20:09:49.573 my.devices.hostname zigpy_espzb.uart DEBUG Connected to /dev/tty.usbmodem579B0264851
2024-04-27 20:09:49.573 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkStateReq() (seq=0)
2024-04-27 20:09:49.573 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000200000000
2024-04-27 20:09:49.578 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000020000010002
2024-04-27 20:09:49.578 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkStateRsp(network_state=<NetworkState.CONNECTED: 2>) (seq 0)
2024-04-27 20:09:49.579 my.devices.hostname zigpy_espzb.api DEBUG Resetting via crash...
2024-04-27 20:09:49.579 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=1)
2024-04-27 20:09:49.579 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400010300000014
2024-04-27 20:09:49.599 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000040001010000
2024-04-27 20:09:49.599 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 1)
2024-04-27 20:09:51.609 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=2)
2024-04-27 20:09:51.610 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400020300000014
2024-04-27 20:09:53.411 my.devices.hostname zigpy_espzb.api DEBUG No response to 'FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20)' command with seq 2
2024-04-27 20:09:55.416 my.devices.hostname zigpy_espzb.api DEBUG Reset complete
2024-04-27 20:09:55.417 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkInitReq() (seq=3)
2024-04-27 20:09:55.418 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000000030000
2024-04-27 20:09:55.426 my.devices.hostname zigpy_espzb.uart WARNING Invalid checksum: 0x6ee7, data: 0x4553502d524f4d3a657370333268322d32303232313130310d0a4275696c643a4e6f7620203120323032320d0a7273743a307863202853575f435055292c626f6f743a30786320285350495f464153545f464c4153485f424f4f54290d0a53617665642050433a307834303030333162360d0a53504957503a307865650d0a6d6f64653a44494f2c20636c6f636b206469763a310d0a6c6f61643a307834303834363065302c6c656e3a3078313263380d0a6c6f61643a307834303833636664302c6c656e3a30786430300d0a6c6f61643a307834303833656664302c6c656e3a3078326135630d0a656e74727920307834303833636664300d0a1b5b303b33326d49202833353529206370755f73746172743a20556e69636f7265206170701b5b306d0d0a1b5b303b33336d5720283336342920636c6b3a206573705f70657269705f636c6b5f696e6974282920686173206e6f74206265656e20696d706c656d656e746564207965741b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2050726f20637075207374617274207573657220636f64651b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2063707520667265713a20393630303030303020487a1b5b306d0d0a1b5b303b33326d49202833373229206370755f73746172743a204170706c69636174696f6e20696e666f726d6174696f6e3a1b5b306d0d0a1b5b303b33326d49202833373429206370755f73746172743a2050726f6a656374206e616d653a20202020206573705f7a69676265655f6e63701b5b306d0d0a1b5b303b33326d49202833373929206370755f73746172743a204170702076657273696f6e3a202020202020393630366161341b5b306d0d0a1b5b303b33326d49202833383429206370755f73746172743a20436f6d70696c652074696d653a202020202041707220203620323032342031383a32333a30371b5b306d0d0a1b5b303b33326d49202833393029206370755f73746172743a20454c462066696c65205348413235363a20203631333139393831332e2e2e1b5b306d0d0a1b5b303b33326d49202833393629206370755f73746172743a204553502d4944463a2020202020202020202076352e322e311b5b306d0d0a1b5b303b33326d49202834303129206370755f73746172743a204d696e2063686970207265763a202020202076302e301b5b306d0d0a1b5b303b33326d49202834303529206370755f73746172743a204d61782063686970207265763a202020202076302e3939201b5b306d0d0a1b5b303b33326d49202834313029206370755f73746172743a2043686970207265763a20202020202020202076302e311b5b306d0d0a1b5b303b33326d4920283431352920686561705f696e69743a20496e697469616c697a696e672e2052414d20617661696c61626c6520666f722064796e616d696320616c6c6f636174696f6e3a1b5b306d0d0a1b5b303b33326d4920283432322920686561705f696e69743a204174203430383134434530206c656e2030303033383641302028323235204b6942293a2052414d1b5b306d0d0a1b5b303b33326d4920283432382920686561705f696e69743a204174203430383444333830206c656e20303030303242363020283130204b6942293a2052414d1b5b306d0d0a1b5b303b33326d49202834333629207370695f666c6173683a20646574656374656420636869703a2067656e657269631b5b306d0d0a1b5b303b33326d49202834333929207370695f666c6173683a20666c61736820696f3a2064696f1b5b306d0d0a1b5b303b33336d57202834343329207370695f666c6173683a2044657465637465642073697a6528343039366b29206c6172676572207468616e207468652073697a6520696e207468652062696e61727920696d6167652068656164657228323034386b292e205573696e67207468652073697a6520696e207468652062696e61727920696d616765206865616465722e1b5b306d0d0a1b5b303b33326d4920283435372920736c6565703a20436f6e66696775726520746f2069736f6c61746520616c6c204750494f2070696e7320696e20736c6565702073746174651b5b306d0d0a1b5b303b33326d4920283436332920736c6565703a20456e61626c65206175746f6d6174696320737769746368696e67206f66204750494f20736c65657020636f6e66696775726174696f6e1b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2053746172746564206f6e20435055301b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2043616c6c69
2024-04-27 20:09:55.429 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000003010000
2024-04-27 20:09:55.429 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkInitRsp(status=<Status.SUCCESS: 0>) (seq 3)
2024-04-27 20:09:55.429 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=4)
2024-04-27 20:09:55.430 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400040300000014
2024-04-27 20:09:55.449 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000040004010000
2024-04-27 20:09:55.449 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 4)
2024-04-27 20:09:57.452 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.false: 0>) (seq=5)
2024-04-27 20:09:57.453 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000010005010000
2024-04-27 20:09:57.531 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000010005010000
2024-04-27 20:09:57.532 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 5)
2024-04-27 20:09:59.534 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkRoleGetReq() (seq=6)
2024-04-27 20:09:59.540 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001b00060000
2024-04-27 20:09:59.547 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001b0006010000
2024-04-27 20:09:59.548 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkRoleGetRsp(role=<DeviceType.COORDINATOR: 0>) (seq 6)
2024-04-27 20:09:59.548 my.devices.hostname zigpy_espzb.api DEBUG Sending ShortAddrGetReq() (seq=7)
2024-04-27 20:09:59.548 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001d00070000
2024-04-27 20:09:59.553 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001d00070200feff
2024-04-27 20:09:59.554 my.devices.hostname zigpy_espzb.api DEBUG Received response ShortAddrGetRsp(short_addr=0xFFFE) (seq 7)
2024-04-27 20:09:59.554 my.devices.hostname zigpy_espzb.api DEBUG Sending LongAddrGetReq() (seq=8)
2024-04-27 20:09:59.554 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001f00080000
2024-04-27 20:09:59.560 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001f00080800457e60feffbd4d74
2024-04-27 20:09:59.560 my.devices.hostname zigpy_espzb.api DEBUG Received response LongAddrGetRsp(ieee=74:4d:bd:ff:fe:60:7e:45) (seq 8)
2024-04-27 20:09:59.562 my.devices.hostname zigpy_espzb.api DEBUG Sending PanidGetReq() (seq=9)
2024-04-27 20:09:59.563 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000b00090000
2024-04-27 20:09:59.568 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000b00090200ffff
2024-04-27 20:09:59.568 my.devices.hostname zigpy_espzb.api DEBUG Received response PanidGetRsp(panid=0xFFFF) (seq 9)
2024-04-27 20:09:59.568 my.devices.hostname zigpy_espzb.api DEBUG Sending ExtpanidGetReq() (seq=10)
2024-04-27 20:09:59.568 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000d000a0000
2024-04-27 20:09:59.574 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000d000a08000000000000000000
2024-04-27 20:09:59.574 my.devices.hostname zigpy_espzb.api DEBUG Received response ExtpanidGetRsp(ieee=00:00:00:00:00:00:00:00) (seq 10)
2024-04-27 20:09:59.574 my.devices.hostname zigpy_espzb.api DEBUG Sending CurrentChannelGetReq() (seq=11)
2024-04-27 20:09:59.574 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000013000b0000
2024-04-27 20:09:59.580 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100013000b0100ff
2024-04-27 20:09:59.580 my.devices.hostname zigpy_espzb.api DEBUG Received response CurrentChannelGetRsp(channel=255) (seq 11)
2024-04-27 20:09:59.580 my.devices.hostname zigpy_espzb.api DEBUG Sending PrimaryChannelMaskGetReq() (seq=12)
2024-04-27 20:09:59.580 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000f000c0000
2024-04-27 20:09:59.586 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000f000c040000000000
2024-04-27 20:09:59.586 my.devices.hostname zigpy_espzb.api DEBUG Received response PrimaryChannelMaskGetRsp(channel_mask=<ShiftedChannels.NO_CHANNELS: 0>) (seq 12)
2024-04-27 20:09:59.586 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkUpdateIdGetReq() (seq=13)
2024-04-27 20:09:59.587 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000023000d0000
2024-04-27 20:09:59.591 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100023000d010001
2024-04-27 20:09:59.592 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkUpdateIdGetRsp(nwk_update_id=1) (seq 13)
2024-04-27 20:09:59.592 my.devices.hostname zigpy_espzb.api DEBUG Serial '/dev/tty.usbmodem579B0264851' connection lost unexpectedly: None
Traceback (most recent call last):
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/bin/zigpy", line 8, in <module>
    sys.exit(cli())
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/decorators.py", line 45, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/zigpy_cli/cli.py", line 20, in inner
    return loop.run_until_complete(cmd(*args, **kwargs))
  File "/usr/local/Cellar/python@3.9/3.9.16/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
    return future.result()
  File "/Users/ss89/development/ESP32/zigpy-cli/zigpy_cli/radio.py", line 119, in backup
    backup = await app.backups.create_backup(load_devices=True)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy/backups.py", line 143, in create_backup
    await self.app.load_network_info(load_devices=load_devices)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/zigbee/application.py", line 235, in load_network_info
    raise NetworkNotFormed(f"Channel is invalid: {network_info.channel}")
zigpy.exceptions.NetworkNotFormed: Channel is invalid: 255

My assumption is that it is (expectedly) failing due to me never having setup a network, however i do get a lot more successful responses from the device now.

I'll try some more in the upcoming days!

ss89 commented 7 months ago

Doing a reset request seems to fail, even though it succeeds (not sure whether this is intended due to the mentioned command sequence + "crash" to reset implementation).

$ zigpy -vvv radio --baudrate 115200 znsp /dev/tty.usbmodem579B0264851 reset

2024-04-28 13:03:36.981 my.devices.hostname asyncio DEBUG Using selector: KqueueSelector
2024-04-28 13:03:36.991 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Inovelli object at 0x11254d0a0>
2024-04-28 13:03:36.991 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Ledvance object at 0x1125395e0>
2024-04-28 13:03:36.991 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Salus object at 0x11251ddf0>
2024-04-28 13:03:36.992 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Sonoff object at 0x11251dd00>
2024-04-28 13:03:36.992 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.ThirdReality object at 0x112544640>
2024-04-28 13:03:36.992 my.devices.hostname zigpy_espzb.uart DEBUG Connecting to /dev/tty.usbmodem579B0264851
2024-04-28 13:03:36.992 my.devices.hostname zigpy.serial DEBUG Opening a serial connection to '/dev/tty.usbmodem579B0264851' (115200 baudrate)
2024-04-28 13:03:37.009 my.devices.hostname zigpy_espzb.uart DEBUG Connection made
2024-04-28 13:03:37.010 my.devices.hostname zigpy_espzb.uart DEBUG Connected to /dev/tty.usbmodem579B0264851
2024-04-28 13:03:37.010 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkStateReq() (seq=0)
2024-04-28 13:03:37.010 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000200000000
2024-04-28 13:03:37.015 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000020000010002
2024-04-28 13:03:37.016 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkStateRsp(network_state=<NetworkState.CONNECTED: 2>) (seq 0)
2024-04-28 13:03:37.016 my.devices.hostname zigpy_espzb.api DEBUG Resetting via crash...
2024-04-28 13:03:37.016 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=1)
2024-04-28 13:03:37.016 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400010300000014
2024-04-28 13:03:37.035 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000040001010000
2024-04-28 13:03:37.036 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 1)
2024-04-28 13:03:39.038 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=2)
2024-04-28 13:03:39.045 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400020300000014
2024-04-28 13:03:40.847 my.devices.hostname zigpy_espzb.api DEBUG No response to 'FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20)' command with seq 2
2024-04-28 13:03:42.850 my.devices.hostname zigpy_espzb.api DEBUG Reset complete
2024-04-28 13:03:42.851 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkInitReq() (seq=3)
2024-04-28 13:03:42.851 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000000030000
2024-04-28 13:03:42.860 my.devices.hostname zigpy_espzb.uart WARNING Invalid checksum: 0x6ee7, data: 0x4553502d524f4d3a657370333268322d32303232313130310d0a4275696c643a4e6f7620203120323032320d0a7273743a307863202853575f435055292c626f6f743a30786320285350495f464153545f464c4153485f424f4f54290d0a53617665642050433a307834303030333162360d0a53504957503a307865650d0a6d6f64653a44494f2c20636c6f636b206469763a310d0a6c6f61643a307834303834363065302c6c656e3a3078313263380d0a6c6f61643a307834303833636664302c6c656e3a30786430300d0a6c6f61643a307834303833656664302c6c656e3a3078326135630d0a656e74727920307834303833636664300d0a1b5b303b33326d49202833353529206370755f73746172743a20556e69636f7265206170701b5b306d0d0a1b5b303b33336d5720283336342920636c6b3a206573705f70657269705f636c6b5f696e6974282920686173206e6f74206265656e20696d706c656d656e746564207965741b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2050726f20637075207374617274207573657220636f64651b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2063707520667265713a20393630303030303020487a1b5b306d0d0a1b5b303b33326d49202833373229206370755f73746172743a204170706c69636174696f6e20696e666f726d6174696f6e3a1b5b306d0d0a1b5b303b33326d49202833373429206370755f73746172743a2050726f6a656374206e616d653a20202020206573705f7a69676265655f6e63701b5b306d0d0a1b5b303b33326d49202833373929206370755f73746172743a204170702076657273696f6e3a202020202020393630366161341b5b306d0d0a1b5b303b33326d49202833383429206370755f73746172743a20436f6d70696c652074696d653a202020202041707220203620323032342031383a32333a30371b5b306d0d0a1b5b303b33326d49202833393129206370755f73746172743a20454c462066696c65205348413235363a20203631333139393831332e2e2e1b5b306d0d0a1b5b303b33326d49202833393629206370755f73746172743a204553502d4944463a2020202020202020202076352e322e311b5b306d0d0a1b5b303b33326d49202834303129206370755f73746172743a204d696e2063686970207265763a202020202076302e301b5b306d0d0a1b5b303b33326d49202834303529206370755f73746172743a204d61782063686970207265763a202020202076302e3939201b5b306d0d0a1b5b303b33326d49202834313029206370755f73746172743a2043686970207265763a20202020202020202076302e311b5b306d0d0a1b5b303b33326d4920283431352920686561705f696e69743a20496e697469616c697a696e672e2052414d20617661696c61626c6520666f722064796e616d696320616c6c6f636174696f6e3a1b5b306d0d0a1b5b303b33326d4920283432322920686561705f696e69743a204174203430383134434530206c656e2030303033383641302028323235204b6942293a2052414d1b5b306d0d0a1b5b303b33326d4920283432382920686561705f696e69743a204174203430383444333830206c656e20303030303242363020283130204b6942293a2052414d1b5b306d0d0a1b5b303b33326d49202834333629207370695f666c6173683a20646574656374656420636869703a2067656e657269631b5b306d0d0a1b5b303b33326d49202834333929207370695f666c6173683a20666c61736820696f3a2064696f1b5b306d0d0a1b5b303b33336d57202834343329207370695f666c6173683a2044657465637465642073697a6528343039366b29206c6172676572207468616e207468652073697a6520696e207468652062696e61727920696d6167652068656164657228323034386b292e205573696e67207468652073697a6520696e207468652062696e61727920696d616765206865616465722e1b5b306d0d0a1b5b303b33326d4920283435372920736c6565703a20436f6e66696775726520746f2069736f6c61746520616c6c204750494f2070696e7320696e20736c6565702073746174651b5b306d0d0a1b5b303b33326d4920283436332920736c6565703a20456e61626c65206175746f6d6174696320737769746368696e67206f66204750494f20736c65657020636f6e66696775726174696f6e1b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2053746172746564206f6e20435055301b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2043616c6c69
2024-04-28 13:03:42.865 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000003010000
2024-04-28 13:03:42.866 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkInitRsp(status=<Status.SUCCESS: 0>) (seq 3)
2024-04-28 13:03:42.866 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=4)
2024-04-28 13:03:42.866 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400040300000014
2024-04-28 13:03:42.886 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000040004010000
2024-04-28 13:03:42.886 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 4)
2024-04-28 13:03:44.888 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.false: 0>) (seq=5)
2024-04-28 13:03:44.889 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000010005010000
2024-04-28 13:03:44.904 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000010005010000
2024-04-28 13:03:44.904 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 5)
2024-04-28 13:03:44.916 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x2000050069010000
2024-04-28 13:03:44.916 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=0) (seq 105)
2024-04-28 13:03:44.929 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000400730b00457e60feffbd4d74d6ec0c
2024-04-28 13:03:44.930 my.devices.hostname zigpy_espzb.api DEBUG Received indication FormNetworkInd(extended_panid=my:ex:te:nd:ed:pa:n0:id, panid=0xSHORTPAN, channel=12) (seq 115)
2024-04-28 13:03:45.517 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500cb0100b4
2024-04-28 13:03:45.519 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=180) (seq 203)
2024-04-28 13:03:46.907 my.devices.hostname zigpy_espzb.api DEBUG Serial '/dev/tty.usbmodem579B0264851' connection lost unexpectedly: None
Traceback (most recent call last):
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/bin/zigpy", line 8, in <module>
    sys.exit(cli())
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/click/decorators.py", line 45, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "/Users/ss89/development/ESP32/zigpy-cli/zigpy_cli/cli.py", line 20, in inner
    return loop.run_until_complete(cmd(*args, **kwargs))
  File "/usr/local/Cellar/python@3.9/3.9.16/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
    return future.result()
  File "/Users/ss89/development/ESP32/zigpy-cli/zigpy_cli/radio.py", line 160, in reset
    await app.reset_network_info()
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/zigbee/application.py", line 146, in reset_network_info
    await self._api.leave_network()
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 319, in leave_network
    await self.send_command(commands.LeaveNetworkReq)
  File "/Users/ss89/development/ESP32/zigpy-cli/venv/lib/python3.9/site-packages/zigpy_espzb/api.py", line 111, in send_command
    command_id = COMMAND_SCHEMA_TO_COMMAND_ID[type(command)]
KeyError: <class 'type'>

Forming a network succeeds from the command line side, but the logs state that the connection to the board would be lost. As i see in one of the last output lines that it tries to do a backup (which failed for me priorly already), i could assume that this is not an error forming the network but only to backing it up - just guesses here.

Manually backing up after form works now for me.

zigpy -vvv radio --baudrate 115200 znsp /dev/tty.usbmodem579B0264851 form
2024-04-28 13:15:01.317 my.devices.hostname asyncio DEBUG Using selector: KqueueSelector                                                                                                           ─╯
2024-04-28 13:15:01.325 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Inovelli object at 0x111e710a0>
2024-04-28 13:15:01.325 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Ledvance object at 0x111e41df0>
2024-04-28 13:15:01.325 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Salus object at 0x111e41e50>
2024-04-28 13:15:01.325 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.Sonoff object at 0x111e5d610>
2024-04-28 13:15:01.325 my.devices.hostname zigpy.ota DEBUG Registering new OTA provider: <zigpy.ota.providers.ThirdReality object at 0x111e69610>
2024-04-28 13:15:01.326 my.devices.hostname zigpy_espzb.uart DEBUG Connecting to /dev/tty.usbmodem579B0264851
2024-04-28 13:15:01.326 my.devices.hostname zigpy.serial DEBUG Opening a serial connection to '/dev/tty.usbmodem579B0264851' (115200 baudrate)
2024-04-28 13:15:01.343 my.devices.hostname zigpy_espzb.uart DEBUG Connection made
2024-04-28 13:15:01.343 my.devices.hostname zigpy_espzb.uart DEBUG Connected to /dev/tty.usbmodem579B0264851
2024-04-28 13:15:01.343 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkStateReq() (seq=0)
2024-04-28 13:15:01.343 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000200000000
2024-04-28 13:15:01.349 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000020000010002
2024-04-28 13:15:01.349 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkStateRsp(network_state=<NetworkState.CONNECTED: 2>) (seq 0)
2024-04-28 13:15:01.349 my.devices.hostname zigpy_espzb.api DEBUG Resetting via crash...
2024-04-28 13:15:01.349 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=1)
2024-04-28 13:15:01.349 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400010300000014
2024-04-28 13:15:03.151 my.devices.hostname zigpy_espzb.api DEBUG No response to 'FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20)' command with seq 1
2024-04-28 13:15:05.153 my.devices.hostname zigpy_espzb.api DEBUG Reset complete
2024-04-28 13:15:05.155 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkInitReq() (seq=2)
2024-04-28 13:15:05.157 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000000020000
2024-04-28 13:15:05.166 my.devices.hostname zigpy_espzb.uart WARNING Invalid checksum: 0x6ee7, data: 0x4553502d524f4d3a657370333268322d32303232313130310d0a4275696c643a4e6f7620203120323032320d0a7273743a307863202853575f435055292c626f6f743a30786320285350495f464153545f464c4153485f424f4f54290d0a53617665642050433a307834303030333162360d0a53504957503a307865650d0a6d6f64653a44494f2c20636c6f636b206469763a310d0a6c6f61643a307834303834363065302c6c656e3a3078313263380d0a6c6f61643a307834303833636664302c6c656e3a30786430300d0a6c6f61643a307834303833656664302c6c656e3a3078326135630d0a656e74727920307834303833636664300d0a1b5b303b33326d49202833353529206370755f73746172743a20556e69636f7265206170701b5b306d0d0a1b5b303b33336d5720283336342920636c6b3a206573705f70657269705f636c6b5f696e6974282920686173206e6f74206265656e20696d706c656d656e746564207965741b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2050726f20637075207374617274207573657220636f64651b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2063707520667265713a20393630303030303020487a1b5b306d0d0a1b5b303b33326d49202833373229206370755f73746172743a204170706c69636174696f6e20696e666f726d6174696f6e3a1b5b306d0d0a1b5b303b33326d49202833373429206370755f73746172743a2050726f6a656374206e616d653a20202020206573705f7a69676265655f6e63701b5b306d0d0a1b5b303b33326d49202833373929206370755f73746172743a204170702076657273696f6e3a202020202020393630366161341b5b306d0d0a1b5b303b33326d49202833383429206370755f73746172743a20436f6d70696c652074696d653a202020202041707220203620323032342031383a32333a30371b5b306d0d0a1b5b303b33326d49202833393029206370755f73746172743a20454c462066696c65205348413235363a20203631333139393831332e2e2e1b5b306d0d0a1b5b303b33326d49202833393629206370755f73746172743a204553502d4944463a2020202020202020202076352e322e311b5b306d0d0a1b5b303b33326d49202834303129206370755f73746172743a204d696e2063686970207265763a202020202076302e301b5b306d0d0a1b5b303b33326d49202834303529206370755f73746172743a204d61782063686970207265763a202020202076302e3939201b5b306d0d0a1b5b303b33326d49202834313029206370755f73746172743a2043686970207265763a20202020202020202076302e311b5b306d0d0a1b5b303b33326d4920283431352920686561705f696e69743a20496e697469616c697a696e672e2052414d20617661696c61626c6520666f722064796e616d696320616c6c6f636174696f6e3a1b5b306d0d0a1b5b303b33326d4920283432322920686561705f696e69743a204174203430383134434530206c656e2030303033383641302028323235204b6942293a2052414d1b5b306d0d0a1b5b303b33326d4920283432382920686561705f696e69743a204174203430383444333830206c656e20303030303242363020283130204b6942293a2052414d1b5b306d0d0a1b5b303b33326d49202834333629207370695f666c6173683a20646574656374656420636869703a2067656e657269631b5b306d0d0a1b5b303b33326d49202834333929207370695f666c6173683a20666c61736820696f3a2064696f1b5b306d0d0a1b5b303b33336d57202834343329207370695f666c6173683a2044657465637465642073697a6528343039366b29206c6172676572207468616e207468652073697a6520696e207468652062696e61727920696d6167652068656164657228323034386b292e205573696e67207468652073697a6520696e207468652062696e61727920696d616765206865616465722e1b5b306d0d0a1b5b303b33326d4920283435372920736c6565703a20436f6e66696775726520746f2069736f6c61746520616c6c204750494f2070696e7320696e20736c6565702073746174651b5b306d0d0a1b5b303b33326d4920283436332920736c6565703a20456e61626c65206175746f6d6174696320737769746368696e67206f66204750494f20736c65657020636f6e66696775726174696f6e1b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2053746172746564206f6e20435055301b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2043616c6c69
2024-04-28 13:15:05.168 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000002010000
2024-04-28 13:15:05.168 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkInitRsp(status=<Status.SUCCESS: 0>) (seq 2)
2024-04-28 13:15:05.168 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=3)
2024-04-28 13:15:05.169 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400030300000014
2024-04-28 13:15:05.188 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000040003010000
2024-04-28 13:15:05.188 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 3)
2024-04-28 13:15:07.192 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.false: 0>) (seq=4)
2024-04-28 13:15:07.193 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000010004010000
2024-04-28 13:15:07.209 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000010004010000
2024-04-28 13:15:07.210 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 4)
2024-04-28 13:15:07.220 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500a9010000
2024-04-28 13:15:07.220 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=0) (seq 169)
2024-04-28 13:15:07.233 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x200004006a0b00457e60feffbd4d74d6ec0c
2024-04-28 13:15:07.233 my.devices.hostname zigpy_espzb.api DEBUG Received indication FormNetworkInd(extended_panid=my:ex:te:nd:ed:pa:n0:id, panid=0xSHORTPAN, channel=12) (seq 106)
2024-04-28 13:15:07.821 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500e90100b4
2024-04-28 13:15:07.821 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=180) (seq 233)
2024-04-28 13:15:09.215 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.true: 1>) (seq=5)
2024-04-28 13:15:09.216 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000010005010001
2024-04-28 13:15:09.238 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000010005010000
2024-04-28 13:15:09.238 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 5)
2024-04-28 13:15:09.248 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x200005008a010000
2024-04-28 13:15:09.248 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=0) (seq 138)
2024-04-28 13:15:11.240 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkRoleGetReq() (seq=6)
2024-04-28 13:15:11.242 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001b00060000
2024-04-28 13:15:11.248 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001b0006010000
2024-04-28 13:15:11.249 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkRoleGetRsp(role=<DeviceType.COORDINATOR: 0>) (seq 6)
2024-04-28 13:15:11.249 my.devices.hostname zigpy_espzb.api DEBUG Sending ShortAddrGetReq() (seq=7)
2024-04-28 13:15:11.249 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001d00070000
2024-04-28 13:15:11.255 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001d000702000000
2024-04-28 13:15:11.255 my.devices.hostname zigpy_espzb.api DEBUG Received response ShortAddrGetRsp(short_addr=0x0000) (seq 7)
2024-04-28 13:15:11.255 my.devices.hostname zigpy_espzb.api DEBUG Sending LongAddrGetReq() (seq=8)
2024-04-28 13:15:11.256 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001f00080000
2024-04-28 13:15:11.261 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001f00080800457e60feffbd4d74
2024-04-28 13:15:11.261 my.devices.hostname zigpy_espzb.api DEBUG Received response LongAddrGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id) (seq 8)
2024-04-28 13:15:11.265 my.devices.hostname zigpy_espzb.api DEBUG Sending PanidGetReq() (seq=9)
2024-04-28 13:15:11.265 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000b00090000
2024-04-28 13:15:11.270 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000b00090200d6ec
2024-04-28 13:15:11.270 my.devices.hostname zigpy_espzb.api DEBUG Received response PanidGetRsp(panid=0xSHORTPAN) (seq 9)
2024-04-28 13:15:11.271 my.devices.hostname zigpy_espzb.api DEBUG Sending ExtpanidGetReq() (seq=10)
2024-04-28 13:15:11.271 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000d000a0000
2024-04-28 13:15:11.276 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000d000a0800457e60feffbd4d74
2024-04-28 13:15:11.277 my.devices.hostname zigpy_espzb.api DEBUG Received response ExtpanidGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id) (seq 10)
2024-04-28 13:15:11.277 my.devices.hostname zigpy_espzb.api DEBUG Sending CurrentChannelGetReq() (seq=11)
2024-04-28 13:15:11.278 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000013000b0000
2024-04-28 13:15:11.283 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100013000b01000c
2024-04-28 13:15:11.283 my.devices.hostname zigpy_espzb.api DEBUG Received response CurrentChannelGetRsp(channel=12) (seq 11)
2024-04-28 13:15:11.283 my.devices.hostname zigpy_espzb.api DEBUG Sending PrimaryChannelMaskGetReq() (seq=12)
2024-04-28 13:15:11.283 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000f000c0000
2024-04-28 13:15:11.289 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000f000c040000000000
2024-04-28 13:15:11.289 my.devices.hostname zigpy_espzb.api DEBUG Received response PrimaryChannelMaskGetRsp(channel_mask=<ShiftedChannels.NO_CHANNELS: 0>) (seq 12)
2024-04-28 13:15:11.289 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkUpdateIdGetReq() (seq=13)
2024-04-28 13:15:11.289 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000023000d0000
2024-04-28 13:15:11.294 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100023000d010001
2024-04-28 13:15:11.294 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkUpdateIdGetRsp(nwk_update_id=1) (seq 13)
2024-04-28 13:15:11.295 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkKeyGetReq() (seq=14)
2024-04-28 13:15:11.295 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000017000e0000
2024-04-28 13:15:11.301 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100017000e1000e18ee703a9828d1e7d2d177b2b236558
2024-04-28 13:15:11.302 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkKeyGetRsp(nwk_key=e1:8e:e7:03:a9:82:8d:1e:7d:2d:17:7b:2b:23:65:58) (seq 14)
2024-04-28 13:15:11.302 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkFrameCounterGetReq() (seq=15)
2024-04-28 13:15:11.302 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000019000f0000
2024-04-28 13:15:11.307 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100019000f040088130000
2024-04-28 13:15:11.308 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkFrameCounterGetRsp(nwk_frame_counter=5000) (seq 15)
2024-04-28 13:15:11.308 my.devices.hostname zigpy_espzb.api DEBUG Sending LinkKeyGetReq() (seq=16)
2024-04-28 13:15:11.308 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002700100000
2024-04-28 13:15:11.316 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002700101800457e60feffbd4d745a6967426565416c6c69616e63653039
2024-04-28 13:15:11.316 my.devices.hostname zigpy_espzb.api DEBUG Received response LinkKeyGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id, key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39) (seq 16)
2024-04-28 13:15:11.317 my.devices.hostname zigpy_espzb.api DEBUG Sending TrustCenterAddressGetReq() (seq=17)
2024-04-28 13:15:11.317 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002500110000
2024-04-28 13:15:11.322 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002500110800ab9809ffff2e2100
2024-04-28 13:15:11.323 my.devices.hostname zigpy_espzb.api DEBUG Received response TrustCenterAddressGetRsp(trust_center_addr=00:21:2e:ff:ff:09:98:ab) (seq 17)
2024-04-28 13:15:11.323 my.devices.hostname zigpy_espzb.api DEBUG Sending SecurityModeGetReq() (seq=18)
2024-04-28 13:15:11.323 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002900120000
2024-04-28 13:15:11.328 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000290012010000
2024-04-28 13:15:11.329 my.devices.hostname zigpy_espzb.api DEBUG Received response SecurityModeGetRsp(security_mode=<SecurityMode.NO_SECURITY: 0>) (seq 18)
2024-04-28 13:15:11.329 my.devices.hostname zigpy_espzb.api DEBUG Sending AddEndpointReq(endpoint=1, profile_id=260, device_id=<DeviceType.IAS_CONTROL: 1024>, app_flags=0, input_cluster_count=5, output_cluster_count=4, input_cluster_list=[0, 6, 10, 25, 1281], output_cluster_list=[1, 32, 1280, 1282]) (seq=19)
2024-04-28 13:15:11.329 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000001131a000104010004000504000006000a00190001050100200000050205
2024-04-28 13:15:11.406 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000113010000
2024-04-28 13:15:11.407 my.devices.hostname zigpy_espzb.api DEBUG Received response AddEndpointRsp(status=<Status.SUCCESS: 0>) (seq 19)
2024-04-28 13:15:11.407 my.devices.hostname zigpy.device DEBUG [0x0000] Scheduling initialization
2024-04-28 13:15:11.408 my.devices.hostname zigpy.util DEBUG Tries remaining: 5
2024-04-28 13:15:11.408 my.devices.hostname zigpy.device INFO [0x0000] Requesting 'Node Descriptor'
2024-04-28 13:15:11.408 my.devices.hostname zigpy.device DEBUG [0x0000] Extending timeout for 0x01 request
2024-04-28 13:15:11.409 my.devices.hostname zigpy_espzb.zigbee.application DEBUG Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 408989, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=True, tsn=1, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x01\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-04-28 13:15:11.409 my.devices.hostname zigpy_espzb.api DEBUG Sending ApsDataRequestReq(dst_addr=00:00:00:00:00:00:00:00, dst_endpoint=0, src_endpoint=0, address_mode=<ExtendedAddrMode.MODE_16_ENDP_PRESENT: 2>, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, tx_options=<TransmitOptions.NONE: 0>, use_alias=<Bool.false: 0>, alias_src_addr=00:00:00:00:00:00:00:00, alias_seq_num=1, radius=0, asdu_length=3, asdu=b'\x01\x00\x00') (seq=20)
2024-04-28 13:15:11.409 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000000314220000000000000000000000020000020000000000000000000000010003000000010000
2024-04-28 13:15:11.443 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000314010000
2024-04-28 13:15:11.443 my.devices.hostname zigpy_espzb.api DEBUG Received response ApsDataRequestRsp(status=<Status.SUCCESS: 0>) (seq 20)
2024-04-28 13:15:11.448 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x200001034a2700050000000000000000000000000000000000000000000002000000007402000003000000010000
2024-04-28 13:15:11.448 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=2, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=628, asdu_length=3, asdu=b'\x01\x00\x00') (seq 74)
2024-04-28 13:15:11.448 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 448952, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=2, data=Serialized[b'\x01\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.451 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 2: Serialized[b'\x01\x00\x00']
2024-04-28 13:15:11.452 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2024-04-28 13:15:11.452 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2024-04-28 13:15:11.455 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103bc35000500000000000000000000000000000000000000000000028000000075020000110000000100000000400f34126c4d06412c4d0600
2024-04-28 13:15:11.455 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=32770, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=629, asdu_length=17, asdu=b'\x01\x00\x00\x00\x00@\x0f4\x12lM\x06A,M\x06\x00') (seq 188)
2024-04-28 13:15:11.455 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 455682, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32770, data=Serialized[b'\x01\x00\x00\x00\x00@\x0f4\x12lM\x06A,M\x06\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.456 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 32770: Serialized[b'\x01\x00\x00\x00\x00@\x0f4\x12lM\x06A,M\x06\x00']
2024-04-28 13:15:11.456 my.devices.hostname 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.RxOnWhenIdle|MainsPowered|FullFunctionDevice|AlternatePanCoordinator: 15>, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=1613, server_mask=11329, maximum_outgoing_transfer_size=1613, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=False, *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)
2024-04-28 13:15:11.456 my.devices.hostname zigpy.device INFO [0x0000] Discovering endpoints
2024-04-28 13:15:11.456 my.devices.hostname zigpy_espzb.zigbee.application DEBUG Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 456627, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=2, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\x02\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-04-28 13:15:11.456 my.devices.hostname zigpy_espzb.api DEBUG Sending ApsDataRequestReq(dst_addr=00:00:00:00:00:00:00:00, dst_endpoint=0, src_endpoint=0, address_mode=<ExtendedAddrMode.MODE_16_ENDP_PRESENT: 2>, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, tx_options=<TransmitOptions.NONE: 0>, use_alias=<Bool.false: 0>, alias_src_addr=00:00:00:00:00:00:00:00, alias_seq_num=2, radius=0, asdu_length=3, asdu=b'\x02\x00\x00') (seq=21)
2024-04-28 13:15:11.457 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000000315220000000000000000000000020000050000000000000000000000020003000000020000
2024-04-28 13:15:11.491 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000315010000
2024-04-28 13:15:11.492 my.devices.hostname zigpy_espzb.api DEBUG Received response ApsDataRequestRsp(status=<Status.SUCCESS: 0>) (seq 21)
2024-04-28 13:15:11.496 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103592700050000000000000000000000000000000000000000000005000000007702000003000000020000
2024-04-28 13:15:11.497 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=5, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=631, asdu_length=3, asdu=b'\x02\x00\x00') (seq 89)
2024-04-28 13:15:11.497 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 497364, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=5, data=Serialized[b'\x02\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.497 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 5: Serialized[b'\x02\x00\x00']
2024-04-28 13:15:11.497 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Active_EP_req: [0x0000]
2024-04-28 13:15:11.497 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Active_EP_req([0x0000])
2024-04-28 13:15:11.503 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103582b000500000000000000000000000000000000000000000000058000000078020000070000000200000002f2f2
2024-04-28 13:15:11.503 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=32773, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=632, asdu_length=7, asdu=b'\x02\x00\x00\x00\x02\xf2\xf2') (seq 88)
2024-04-28 13:15:11.503 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 503606, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32773, data=Serialized[b'\x02\x00\x00\x00\x02\xf2\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.503 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 32773: Serialized[b'\x02\x00\x00\x00\x02\xf2\xf2']
2024-04-28 13:15:11.503 my.devices.hostname zigpy.device INFO [0x0000] Discovered endpoints: [242, 242]
2024-04-28 13:15:11.503 my.devices.hostname zigpy.device INFO [0x0000] Initializing endpoints [<Endpoint id=242 in=[] out=[] status=<Status.NEW: 0>>]
2024-04-28 13:15:11.503 my.devices.hostname zigpy.endpoint INFO [0x0000:242] Discovering endpoint information
2024-04-28 13:15:11.504 my.devices.hostname zigpy_espzb.zigbee.application DEBUG Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 504062, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x03\x00\x00\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-04-28 13:15:11.504 my.devices.hostname zigpy_espzb.api DEBUG Sending ApsDataRequestReq(dst_addr=00:00:00:00:00:00:00:00, dst_endpoint=0, src_endpoint=0, address_mode=<ExtendedAddrMode.MODE_16_ENDP_PRESENT: 2>, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, tx_options=<TransmitOptions.NONE: 0>, use_alias=<Bool.false: 0>, alias_src_addr=00:00:00:00:00:00:00:00, alias_seq_num=3, radius=0, asdu_length=4, asdu=b'\x03\x00\x00\xf2') (seq=22)
2024-04-28 13:15:11.504 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000000316230000000000000000000000020000040000000000000000000000030004000000030000f2
2024-04-28 13:15:11.540 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000316010000
2024-04-28 13:15:11.541 my.devices.hostname zigpy_espzb.api DEBUG Received response ApsDataRequestRsp(status=<Status.SUCCESS: 0>) (seq 22)
2024-04-28 13:15:11.545 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103732800050000000000000000000000000000000000000000000004000000007b02000004000000030000f2
2024-04-28 13:15:11.546 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=4, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=635, asdu_length=4, asdu=b'\x03\x00\x00\xf2') (seq 115)
2024-04-28 13:15:11.546 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 546358, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=4, data=Serialized[b'\x03\x00\x00\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.557 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 4: Serialized[b'\x03\x00\x00\xf2']
2024-04-28 13:15:11.557 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 242]
2024-04-28 13:15:11.557 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 242])
2024-04-28 13:15:11.557 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103013500050000000000000000000000000000000000000000000004800000007b02000011000000030000000cf2e0a1660000012100012100
2024-04-28 13:15:11.558 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=32772, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=635, asdu_length=17, asdu=b'\x03\x00\x00\x00\x0c\xf2\xe0\xa1f\x00\x00\x01!\x00\x01!\x00') (seq 1)
2024-04-28 13:15:11.558 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 558279, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32772, data=Serialized[b'\x03\x00\x00\x00\x0c\xf2\xe0\xa1f\x00\x00\x01!\x00\x01!\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.558 my.devices.hostname zigpy.application DEBUG Received frame on uninitialized device <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=False> from ep 0 to ep 0, cluster 32772: Serialized[b'\x03\x00\x00\x00\x0c\xf2\xe0\xa1f\x00\x00\x01!\x00\x01!\x00']
2024-04-28 13:15:11.558 my.devices.hostname zigpy.endpoint INFO [0x0000:242] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=242, profile=41440, device_type=102, device_version=0, input_clusters=[33], output_clusters=[33])
2024-04-28 13:15:11.558 my.devices.hostname zigpy.device INFO [0x0000] Read model None and manufacturer None from <Endpoint id=242 in=[green_power:0x0021] out=[green_power:0x0021] status=<Status.ZDO_INIT: 1>>
2024-04-28 13:15:11.558 my.devices.hostname zigpy.device INFO [0x0000] Discovered basic device information for <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=True>
2024-04-28 13:15:11.558 my.devices.hostname zigpy.application DEBUG Device is initialized <Device model=None manuf=None nwk=0x0000 ieee=my:ex:te:nd:ed:pa:n0:id is_initialized=True>
2024-04-28 13:15:11.558 my.devices.hostname zigpy.quirks.registry DEBUG Checking quirks for None None (my:ex:te:nd:ed:pa:n0:id)
2024-04-28 13:15:11.559 my.devices.hostname zigpy_espzb.zigbee.application DEBUG Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 559190, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=4, profile_id=0, cluster_id=<ZDOCmd.Mgmt_NWK_Update_req: 0x0038>, data=Serialized[b'\x04\x00\xf8\xff\x07\x04\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-04-28 13:15:11.559 my.devices.hostname zigpy_espzb.api DEBUG Sending ApsDataRequestReq(dst_addr=00:00:00:00:00:00:00:00, dst_endpoint=0, src_endpoint=0, address_mode=<ExtendedAddrMode.MODE_16_ENDP_PRESENT: 2>, profile_id=0, cluster_id=<ZDOCmd.Mgmt_NWK_Update_req: 0x0038>, tx_options=<TransmitOptions.NONE: 0>, use_alias=<Bool.false: 0>, alias_src_addr=00:00:00:00:00:00:00:00, alias_seq_num=4, radius=0, asdu_length=7, asdu=b'\x04\x00\xf8\xff\x07\x04\x01') (seq=23)
2024-04-28 13:15:11.559 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000003172600000000000000000000000200003800000000000000000000000400070000000400f8ff070401
2024-04-28 13:15:11.594 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000317010000
2024-04-28 13:15:11.594 my.devices.hostname zigpy_espzb.api DEBUG Received response ApsDataRequestRsp(status=<Status.SUCCESS: 0>) (seq 23)
2024-04-28 13:15:11.599 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x200001031e2b00050000000000000000000000000000000000000000000038000000007e020000070000000400f8ff070401
2024-04-28 13:15:11.599 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:00, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=56, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=638, asdu_length=7, asdu=b'\x04\x00\xf8\xff\x07\x04\x01') (seq 30)
2024-04-28 13:15:11.599 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 11, 599730, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=56, data=Serialized[b'\x04\x00\xf8\xff\x07\x04\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:11.600 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Mgmt_NWK_Update_req: [NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=4, ScanCount=1)]
2024-04-28 13:15:11.600 my.devices.hostname zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_NWK_Update_req([NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=4, ScanCount=1)])
2024-04-28 13:15:16.054 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000103943f0005008f00000000000000000000000000000000000000003880000000a00300001b000000040000f8ff0703000000108a8b928a8f8b8a8a8b8b8a8b8c8b8b8a
2024-04-28 13:15:16.056 my.devices.hostname zigpy_espzb.api DEBUG Received indication ApsDataIndicationInd(network_state=<NetworkState.INDICATION: 5>, dst_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, dst_addr=00:00:00:00:00:00:00:8f, dst_ep=0, src_addr_mode=<ExtendedAddrMode.MODE_DST_ADDR_ENDP_NOT_PRESENT: 0>, src_addr=00:00:00:00:00:00:00:00, src_ep=0, profile_id=0, cluster_id=32824, indication_status=<TXStatus.SUCCESS: 0>, security_status=0, lqi=0, rx_time=928, asdu_length=27, asdu=b'\x04\x00\x00\xf8\xff\x07\x03\x00\x00\x00\x10\x8a\x8b\x92\x8a\x8f\x8b\x8a\x8a\x8b\x8b\x8a\x8b\x8c\x8b\x8b\x8a') (seq 148)
2024-04-28 13:15:16.059 my.devices.hostname zigpy.application DEBUG Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 4, 28, 11, 15, 16, 58942, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x008F), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32824, data=Serialized[b'\x04\x00\x00\xf8\xff\x07\x03\x00\x00\x00\x10\x8a\x8b\x92\x8a\x8f\x8b\x8a\x8a\x8b\x8b\x8a\x8b\x8c\x8b\x8b\x8a'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=0, rssi=None)
2024-04-28 13:15:16.061 my.devices.hostname zigpy.util INFO Optimal channel is 20
2024-04-28 13:15:16.061 my.devices.hostname zigpy.util DEBUG Channel scores: {11: 887.8000000000001, 12: 1345.8000000000002, 13: 1378.8000000000002, 14: 1347.8999999999999, 15: 453.90000000000003, 16: 1341.3000000000002, 17: 1331.1, 18: 1329.8999999999999, 19: 1335.3000000000002, 20: 445.2, 21: 1331.6999999999998, 22: 1337.3999999999999, 23: 1343.1, 24: 1338.6, 25: 445.3, 26: 886.4}
2024-04-28 13:15:16.061 my.devices.hostname zigpy.application DEBUG Forming a new network
2024-04-28 13:15:16.061 my.devices.hostname zigpy.backups DEBUG Restoring backup NetworkBackup(version=1, backup_time=datetime.datetime(2024, 4, 28, 11, 15, 16, 61920, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=my:ex:te:nd:ed:pa:n0:id, pan_id=3028, nwk_update_id=0, nwk_manager_id=0, channel=20, channel_mask=<Channels.CHANNEL_20: 1048576>, security_level=5, network_key=Key(key=c2:40:78:19:98:ac:d7:f4:9c:a4:27:10:b5:34:87:bf, 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=ff:ff:ff:ff:ff:ff:ff:ff), key_table=[], children=[], nwk_addresses={}, stack_specific={}, metadata={}, source=None), node_info=NodeInfo(nwk=0, ieee=ff:ff:ff:ff:ff:ff:ff:ff, logical_type=<LogicalType.Coordinator: 0>, model=None, manufacturer=None, version=None))
2024-04-28 13:15:16.062 my.devices.hostname zigpy_espzb.api DEBUG Resetting via crash...
2024-04-28 13:15:16.062 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=24)
2024-04-28 13:15:16.063 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400180300000014
2024-04-28 13:15:17.865 my.devices.hostname zigpy_espzb.api DEBUG No response to 'FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20)' command with seq 24
2024-04-28 13:15:19.867 my.devices.hostname zigpy_espzb.api DEBUG Reset complete
2024-04-28 13:15:19.869 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkInitReq() (seq=25)
2024-04-28 13:15:19.870 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000000190000
2024-04-28 13:15:19.879 my.devices.hostname zigpy_espzb.uart WARNING Invalid checksum: 0x6ee7, data: 0x4553502d524f4d3a657370333268322d32303232313130310d0a4275696c643a4e6f7620203120323032320d0a7273743a307863202853575f435055292c626f6f743a30786320285350495f464153545f464c4153485f424f4f54290d0a53617665642050433a307834303030333162360d0a53504957503a307865650d0a6d6f64653a44494f2c20636c6f636b206469763a310d0a6c6f61643a307834303834363065302c6c656e3a3078313263380d0a6c6f61643a307834303833636664302c6c656e3a30786430300d0a6c6f61643a307834303833656664302c6c656e3a3078326135630d0a656e74727920307834303833636664300d0a1b5b303b33326d49202833353529206370755f73746172743a20556e69636f7265206170701b5b306d0d0a1b5b303b33336d5720283336342920636c6b3a206573705f70657269705f636c6b5f696e6974282920686173206e6f74206265656e20696d706c656d656e746564207965741b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2050726f20637075207374617274207573657220636f64651b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2063707520667265713a20393630303030303020487a1b5b306d0d0a1b5b303b33326d49202833373229206370755f73746172743a204170706c69636174696f6e20696e666f726d6174696f6e3a1b5b306d0d0a1b5b303b33326d49202833373429206370755f73746172743a2050726f6a656374206e616d653a20202020206573705f7a69676265655f6e63701b5b306d0d0a1b5b303b33326d49202833373929206370755f73746172743a204170702076657273696f6e3a202020202020393630366161341b5b306d0d0a1b5b303b33326d49202833383429206370755f73746172743a20436f6d70696c652074696d653a202020202041707220203620323032342031383a32333a30371b5b306d0d0a1b5b303b33326d49202833393029206370755f73746172743a20454c462066696c65205348413235363a20203631333139393831332e2e2e1b5b306d0d0a1b5b303b33326d49202833393629206370755f73746172743a204553502d4944463a2020202020202020202076352e322e311b5b306d0d0a1b5b303b33326d49202834303129206370755f73746172743a204d696e2063686970207265763a202020202076302e301b5b306d0d0a1b5b303b33326d49202834303529206370755f73746172743a204d61782063686970207265763a202020202076302e3939201b5b306d0d0a1b5b303b33326d49202834313029206370755f73746172743a2043686970207265763a20202020202020202076302e311b5b306d0d0a1b5b303b33326d4920283431352920686561705f696e69743a20496e697469616c697a696e672e2052414d20617661696c61626c6520666f722064796e616d696320616c6c6f636174696f6e3a1b5b306d0d0a1b5b303b33326d4920283432322920686561705f696e69743a204174203430383134434530206c656e2030303033383641302028323235204b6942293a2052414d1b5b306d0d0a1b5b303b33326d4920283432382920686561705f696e69743a204174203430383444333830206c656e20303030303242363020283130204b6942293a2052414d1b5b306d0d0a1b5b303b33326d49202834333629207370695f666c6173683a20646574656374656420636869703a2067656e657269631b5b306d0d0a1b5b303b33326d49202834333929207370695f666c6173683a20666c61736820696f3a2064696f1b5b306d0d0a1b5b303b33336d57202834343329207370695f666c6173683a2044657465637465642073697a6528343039366b29206c6172676572207468616e207468652073697a6520696e207468652062696e61727920696d6167652068656164657228323034386b292e205573696e67207468652073697a6520696e207468652062696e61727920696d616765206865616465722e1b5b306d0d0a1b5b303b33326d4920283435372920736c6565703a20436f6e66696775726520746f2069736f6c61746520616c6c204750494f2070696e7320696e20736c6565702073746174651b5b306d0d0a1b5b303b33326d4920283436332920736c6565703a20456e61626c65206175746f6d6174696320737769746368696e67206f66204750494f20736c65657020636f6e66696775726174696f6e1b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2053746172746564206f6e20435055301b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2043616c6c69
2024-04-28 13:15:19.880 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000000019010000
2024-04-28 13:15:19.880 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkInitRsp(status=<Status.SUCCESS: 0>) (seq 25)
2024-04-28 13:15:19.881 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=26)
2024-04-28 13:15:19.881 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000004001a0300000014
2024-04-28 13:15:19.900 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100004001a010000
2024-04-28 13:15:19.901 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 26)
2024-04-28 13:15:21.903 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkRoleSetReq(role=<DeviceType.COORDINATOR: 0>) (seq=27)
2024-04-28 13:15:21.904 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001c001b010000
2024-04-28 13:15:21.911 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001c001b010000
2024-04-28 13:15:21.911 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkRoleSetRsp(status=<Status.SUCCESS: 0>) (seq 27)
2024-04-28 13:15:21.912 my.devices.hostname zigpy_espzb.api DEBUG Sending ShortAddrSetReq(short_addr=0x0000) (seq=28)
2024-04-28 13:15:21.912 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001e001c02000000
2024-04-28 13:15:21.918 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001e001c010000
2024-04-28 13:15:21.918 my.devices.hostname zigpy_espzb.api DEBUG Received response ShortAddrSetRsp(status=<Status.SUCCESS: 0>) (seq 28)
2024-04-28 13:15:21.919 my.devices.hostname zigpy_espzb.api DEBUG Sending LongAddrGetReq() (seq=29)
2024-04-28 13:15:21.919 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001f001d0000
2024-04-28 13:15:21.925 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001f001d08000000000000000000
2024-04-28 13:15:21.925 my.devices.hostname zigpy_espzb.api DEBUG Received response LongAddrGetRsp(ieee=00:00:00:00:00:00:00:00) (seq 29)
2024-04-28 13:15:21.926 my.devices.hostname zigpy_espzb.api DEBUG Sending UsePredefinedNwkPanidSetReq(predefined=<Bool.true: 1>) (seq=30)
2024-04-28 13:15:21.926 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002b001e010001
2024-04-28 13:15:21.931 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002b001e010000
2024-04-28 13:15:21.931 my.devices.hostname zigpy_espzb.api DEBUG Received response UsePredefinedNwkPanidSetRsp(status=<Status.SUCCESS: 0>) (seq 30)
2024-04-28 13:15:21.931 my.devices.hostname zigpy_espzb.api DEBUG Sending PanidSetReq(panid=0xSHORTPAN) (seq=31)
2024-04-28 13:15:21.932 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000c001f0200d40b
2024-04-28 13:15:21.937 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000c001f010000
2024-04-28 13:15:21.937 my.devices.hostname zigpy_espzb.api DEBUG Received response PanidSetRsp(status=<Status.SUCCESS: 0>) (seq 31)
2024-04-28 13:15:21.938 my.devices.hostname zigpy_espzb.api DEBUG Sending ExtpanidSetReq(ieee=my:ex:te:nd:ed:pa:n0:id) (seq=32)
2024-04-28 13:15:21.938 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000e002008001f56b5e4ebeef94c
2024-04-28 13:15:21.944 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000e0020010000
2024-04-28 13:15:21.944 my.devices.hostname zigpy_espzb.api DEBUG Received response ExtpanidSetRsp(status=<Status.SUCCESS: 0>) (seq 32)
2024-04-28 13:15:21.945 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkUpdateIdSetReq(nwk_update_id=0) (seq=33)
2024-04-28 13:15:21.945 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000240021010000
2024-04-28 13:15:21.950 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000240021010000
2024-04-28 13:15:21.950 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkUpdateIdSetRsp(status=<Status.SUCCESS: 0>) (seq 33)
2024-04-28 13:15:21.950 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkKeySetReq(nwk_key=c2:40:78:19:98:ac:d7:f4:9c:a4:27:10:b5:34:87:bf) (seq=34)
2024-04-28 13:15:21.951 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001800221000c240781998acd7f49ca42710b53487bf
2024-04-28 13:15:21.962 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000180022010000
2024-04-28 13:15:21.962 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkKeySetRsp(status=<Status.SUCCESS: 0>) (seq 34)
2024-04-28 13:15:21.963 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkFrameCounterSetReq(nwk_frame_counter=0) (seq=35)
2024-04-28 13:15:21.963 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001a0023040000000000
2024-04-28 13:15:21.969 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001a0023010000
2024-04-28 13:15:21.969 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkFrameCounterSetRsp(status=<Status.SUCCESS: 0>) (seq 35)
2024-04-28 13:15:21.969 my.devices.hostname zigpy_espzb.api DEBUG Sending TrustCenterAddressSetReq(trust_center_addr=00:00:00:00:00:00:00:00) (seq=36)
2024-04-28 13:15:21.969 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000026002408000000000000000000
2024-04-28 13:15:21.979 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000260024010000
2024-04-28 13:15:21.980 my.devices.hostname zigpy_espzb.api DEBUG Received response TrustCenterAddressSetRsp(status=<Status.SUCCESS: 0>) (seq 36)
2024-04-28 13:15:21.980 my.devices.hostname zigpy_espzb.api DEBUG Sending LinkKeySetReq(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39) (seq=37)
2024-04-28 13:15:21.980 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000028002510005a6967426565416c6c69616e63653039
2024-04-28 13:15:21.992 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000280025010000
2024-04-28 13:15:21.993 my.devices.hostname zigpy_espzb.api DEBUG Received response LinkKeySetRsp(status=<Status.SUCCESS: 0>) (seq 37)
2024-04-28 13:15:21.993 my.devices.hostname zigpy_espzb.api DEBUG Sending SecurityModeSetReq(security_mode=<SecurityMode.PRECONFIGURED_NETWORK_KEY: 1>) (seq=38)
2024-04-28 13:15:21.993 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002a0026010001
2024-04-28 13:15:21.998 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002a0026010000
2024-04-28 13:15:21.998 my.devices.hostname zigpy_espzb.api DEBUG Received response SecurityModeSetRsp(status=<Status.SUCCESS: 0>) (seq 38)
2024-04-28 13:15:21.999 my.devices.hostname zigpy_espzb.api DEBUG Sending PrimaryChannelMaskSetReq(channel_mask=<ShiftedChannels.CHANNEL_20: 1048576>) (seq=39)
2024-04-28 13:15:21.999 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000100027040000001000
2024-04-28 13:15:22.005 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000100027010000
2024-04-28 13:15:22.005 my.devices.hostname zigpy_espzb.api DEBUG Received response PrimaryChannelMaskSetRsp(status=<Status.SUCCESS: 0>) (seq 39)
2024-04-28 13:15:22.005 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.true: 1>) (seq=40)
2024-04-28 13:15:22.005 my.devices.hostname zigpy_espzb.uart DEBUG Send: 0000010028010001
2024-04-28 13:15:22.021 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000010028010000
2024-04-28 13:15:22.021 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 40)
2024-04-28 13:15:22.033 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x2000050047010000
2024-04-28 13:15:22.033 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=0) (seq 71)
2024-04-28 13:15:22.046 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x200004000e0b00457e60feffbd4d74d6ec0c
2024-04-28 13:15:22.046 my.devices.hostname zigpy_espzb.api DEBUG Received indication FormNetworkInd(extended_panid=my:ex:te:nd:ed:pa:n0:id, panid=0xSHORTPAN, channel=12) (seq 14)
2024-04-28 13:15:22.635 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500380100b4
2024-04-28 13:15:22.637 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=180) (seq 56)
2024-04-28 13:15:24.023 my.devices.hostname zigpy_espzb.api DEBUG Resetting via crash...
2024-04-28 13:15:24.025 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=41)
2024-04-28 13:15:24.026 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000400290300000014
2024-04-28 13:15:25.828 my.devices.hostname zigpy_espzb.api DEBUG No response to 'FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20)' command with seq 41
2024-04-28 13:15:27.832 my.devices.hostname zigpy_espzb.api DEBUG Reset complete
2024-04-28 13:15:27.833 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkInitReq() (seq=42)
2024-04-28 13:15:27.834 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000000002a0000
2024-04-28 13:15:27.842 my.devices.hostname zigpy_espzb.uart WARNING Invalid checksum: 0x6ee7, data: 0x4553502d524f4d3a657370333268322d32303232313130310d0a4275696c643a4e6f7620203120323032320d0a7273743a307863202853575f435055292c626f6f743a30786320285350495f464153545f464c4153485f424f4f54290d0a53617665642050433a307834303030333162360d0a53504957503a307865650d0a6d6f64653a44494f2c20636c6f636b206469763a310d0a6c6f61643a307834303834363065302c6c656e3a3078313263380d0a6c6f61643a307834303833636664302c6c656e3a30786430300d0a6c6f61643a307834303833656664302c6c656e3a3078326135630d0a656e74727920307834303833636664300d0a1b5b303b33326d49202833353529206370755f73746172743a20556e69636f7265206170701b5b306d0d0a1b5b303b33336d5720283336342920636c6b3a206573705f70657269705f636c6b5f696e6974282920686173206e6f74206265656e20696d706c656d656e746564207965741b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2050726f20637075207374617274207573657220636f64651b5b306d0d0a1b5b303b33326d49202833373129206370755f73746172743a2063707520667265713a20393630303030303020487a1b5b306d0d0a1b5b303b33326d49202833373229206370755f73746172743a204170706c69636174696f6e20696e666f726d6174696f6e3a1b5b306d0d0a1b5b303b33326d49202833373429206370755f73746172743a2050726f6a656374206e616d653a20202020206573705f7a69676265655f6e63701b5b306d0d0a1b5b303b33326d49202833373929206370755f73746172743a204170702076657273696f6e3a202020202020393630366161341b5b306d0d0a1b5b303b33326d49202833383429206370755f73746172743a20436f6d70696c652074696d653a202020202041707220203620323032342031383a32333a30371b5b306d0d0a1b5b303b33326d49202833393129206370755f73746172743a20454c462066696c65205348413235363a20203631333139393831332e2e2e1b5b306d0d0a1b5b303b33326d49202833393629206370755f73746172743a204553502d4944463a2020202020202020202076352e322e311b5b306d0d0a1b5b303b33326d49202834303129206370755f73746172743a204d696e2063686970207265763a202020202076302e301b5b306d0d0a1b5b303b33326d49202834303529206370755f73746172743a204d61782063686970207265763a202020202076302e3939201b5b306d0d0a1b5b303b33326d49202834313029206370755f73746172743a2043686970207265763a20202020202020202076302e311b5b306d0d0a1b5b303b33326d4920283431352920686561705f696e69743a20496e697469616c697a696e672e2052414d20617661696c61626c6520666f722064796e616d696320616c6c6f636174696f6e3a1b5b306d0d0a1b5b303b33326d4920283432322920686561705f696e69743a204174203430383134434530206c656e2030303033383641302028323235204b6942293a2052414d1b5b306d0d0a1b5b303b33326d4920283432382920686561705f696e69743a204174203430383444333830206c656e20303030303242363020283130204b6942293a2052414d1b5b306d0d0a1b5b303b33326d49202834333629207370695f666c6173683a20646574656374656420636869703a2067656e657269631b5b306d0d0a1b5b303b33326d49202834333929207370695f666c6173683a20666c61736820696f3a2064696f1b5b306d0d0a1b5b303b33336d57202834343329207370695f666c6173683a2044657465637465642073697a6528343039366b29206c6172676572207468616e207468652073697a6520696e207468652062696e61727920696d6167652068656164657228323034386b292e205573696e67207468652073697a6520696e207468652062696e61727920696d616765206865616465722e1b5b306d0d0a1b5b303b33326d4920283435372920736c6565703a20436f6e66696775726520746f2069736f6c61746520616c6c204750494f2070696e7320696e20736c6565702073746174651b5b306d0d0a1b5b303b33326d4920283436332920736c6565703a20456e61626c65206175746f6d6174696320737769746368696e67206f66204750494f20736c65657020636f6e66696775726174696f6e1b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2053746172746564206f6e20435055301b5b306d0d0a1b5b303b33326d49202834373029206d61696e5f7461736b3a2043616c6c69
2024-04-28 13:15:27.844 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100000002a010000
2024-04-28 13:15:27.844 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkInitRsp(status=<Status.SUCCESS: 0>) (seq 42)
2024-04-28 13:15:27.844 my.devices.hostname zigpy_espzb.api DEBUG Sending FormNetworkReq(role=<DeviceType.COORDINATOR: 0>, install_code_policy=<Bool.false: 0>, max_children=20) (seq=43)
2024-04-28 13:15:27.845 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000004002b0300000014
2024-04-28 13:15:27.864 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100004002b010000
2024-04-28 13:15:27.864 my.devices.hostname zigpy_espzb.api DEBUG Received response FormNetworkRsp(status=<Status.SUCCESS: 0>) (seq 43)
2024-04-28 13:15:29.867 my.devices.hostname zigpy_espzb.api DEBUG Sending StartReq(autostart=<Bool.true: 1>) (seq=44)
2024-04-28 13:15:29.869 my.devices.hostname zigpy_espzb.uart DEBUG Send: 000001002c010001
2024-04-28 13:15:29.885 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100001002c010000
2024-04-28 13:15:29.885 my.devices.hostname zigpy_espzb.api DEBUG Received response StartRsp(status=<Status.SUCCESS: 0>) (seq 44)
2024-04-28 13:15:29.896 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500e6010000
2024-04-28 13:15:29.896 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=0) (seq 230)
2024-04-28 13:15:29.909 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000400010b00457e60feffbd4d74d6ec0c
2024-04-28 13:15:29.910 my.devices.hostname zigpy_espzb.api DEBUG Received indication FormNetworkInd(extended_panid=my:ex:te:nd:ed:pa:n0:id, panid=0xSHORTPAN, channel=12) (seq 1)
2024-04-28 13:15:30.499 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x20000500c90100b4
2024-04-28 13:15:30.501 my.devices.hostname zigpy_espzb.api DEBUG Received indication PermitJoiningInd(duration=180) (seq 201)
2024-04-28 13:15:31.888 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkRoleGetReq() (seq=45)
2024-04-28 13:15:31.889 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001b002d0000
2024-04-28 13:15:31.896 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001b002d010000
2024-04-28 13:15:31.896 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkRoleGetRsp(role=<DeviceType.COORDINATOR: 0>) (seq 45)
2024-04-28 13:15:31.897 my.devices.hostname zigpy_espzb.api DEBUG Sending ShortAddrGetReq() (seq=46)
2024-04-28 13:15:31.897 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001d002e0000
2024-04-28 13:15:31.902 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001d002e02000000
2024-04-28 13:15:31.903 my.devices.hostname zigpy_espzb.api DEBUG Received response ShortAddrGetRsp(short_addr=0x0000) (seq 46)
2024-04-28 13:15:31.903 my.devices.hostname zigpy_espzb.api DEBUG Sending LongAddrGetReq() (seq=47)
2024-04-28 13:15:31.903 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001f002f0000
2024-04-28 13:15:31.909 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001f002f0800457e60feffbd4d74
2024-04-28 13:15:31.909 my.devices.hostname zigpy_espzb.api DEBUG Received response LongAddrGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id) (seq 47)
2024-04-28 13:15:31.912 my.devices.hostname zigpy_espzb.api DEBUG Sending PanidGetReq() (seq=48)
2024-04-28 13:15:31.912 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000b00300000
2024-04-28 13:15:31.917 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000b00300200d6ec
2024-04-28 13:15:31.917 my.devices.hostname zigpy_espzb.api DEBUG Received response PanidGetRsp(panid=0xSHORTPAN) (seq 48)
2024-04-28 13:15:31.917 my.devices.hostname zigpy_espzb.api DEBUG Sending ExtpanidGetReq() (seq=49)
2024-04-28 13:15:31.918 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000d00310000
2024-04-28 13:15:31.923 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000d00310800457e60feffbd4d74
2024-04-28 13:15:31.923 my.devices.hostname zigpy_espzb.api DEBUG Received response ExtpanidGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id) (seq 49)
2024-04-28 13:15:31.924 my.devices.hostname zigpy_espzb.api DEBUG Sending CurrentChannelGetReq() (seq=50)
2024-04-28 13:15:31.924 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001300320000
2024-04-28 13:15:31.929 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x100013003201000c
2024-04-28 13:15:31.929 my.devices.hostname zigpy_espzb.api DEBUG Received response CurrentChannelGetRsp(channel=12) (seq 50)
2024-04-28 13:15:31.929 my.devices.hostname zigpy_espzb.api DEBUG Sending PrimaryChannelMaskGetReq() (seq=51)
2024-04-28 13:15:31.929 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00000f00330000
2024-04-28 13:15:31.935 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10000f0033040000000000
2024-04-28 13:15:31.935 my.devices.hostname zigpy_espzb.api DEBUG Received response PrimaryChannelMaskGetRsp(channel_mask=<ShiftedChannels.NO_CHANNELS: 0>) (seq 51)
2024-04-28 13:15:31.936 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkUpdateIdGetReq() (seq=52)
2024-04-28 13:15:31.936 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002300340000
2024-04-28 13:15:31.941 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000230034010001
2024-04-28 13:15:31.941 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkUpdateIdGetRsp(nwk_update_id=1) (seq 52)
2024-04-28 13:15:31.941 my.devices.hostname zigpy_espzb.api DEBUG Sending NetworkKeyGetReq() (seq=53)
2024-04-28 13:15:31.942 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001700350000
2024-04-28 13:15:31.948 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10001700351000e18ee703a9828d1e7d2d177b2b236558
2024-04-28 13:15:31.948 my.devices.hostname zigpy_espzb.api DEBUG Received response NetworkKeyGetRsp(nwk_key=e1:8e:e7:03:a9:82:8d:1e:7d:2d:17:7b:2b:23:65:58) (seq 53)
2024-04-28 13:15:31.948 my.devices.hostname zigpy_espzb.api DEBUG Sending NwkFrameCounterGetReq() (seq=54)
2024-04-28 13:15:31.948 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00001900360000
2024-04-28 13:15:31.954 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000190036040088130000
2024-04-28 13:15:31.954 my.devices.hostname zigpy_espzb.api DEBUG Received response NwkFrameCounterGetRsp(nwk_frame_counter=5000) (seq 54)
2024-04-28 13:15:31.954 my.devices.hostname zigpy_espzb.api DEBUG Sending LinkKeyGetReq() (seq=55)
2024-04-28 13:15:31.954 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002700370000
2024-04-28 13:15:31.961 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002700371800457e60feffbd4d745a6967426565416c6c69616e63653039
2024-04-28 13:15:31.961 my.devices.hostname zigpy_espzb.api DEBUG Received response LinkKeyGetRsp(ieee=my:ex:te:nd:ed:pa:n0:id, key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39) (seq 55)
2024-04-28 13:15:31.962 my.devices.hostname zigpy_espzb.api DEBUG Sending TrustCenterAddressGetReq() (seq=56)
2024-04-28 13:15:31.962 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002500380000
2024-04-28 13:15:31.968 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x10002500380800ab9809ffff2e2100
2024-04-28 13:15:31.968 my.devices.hostname zigpy_espzb.api DEBUG Received response TrustCenterAddressGetRsp(trust_center_addr=00:21:2e:ff:ff:09:98:ab) (seq 56)
2024-04-28 13:15:31.968 my.devices.hostname zigpy_espzb.api DEBUG Sending SecurityModeGetReq() (seq=57)
2024-04-28 13:15:31.968 my.devices.hostname zigpy_espzb.uart DEBUG Send: 00002900390000
2024-04-28 13:15:31.973 my.devices.hostname zigpy_espzb.uart DEBUG Frame received: 0x1000290039010000
2024-04-28 13:15:31.973 my.devices.hostname zigpy_espzb.api DEBUG Received response SecurityModeGetRsp(security_mode=<SecurityMode.NO_SECURITY: 0>) (seq 57)
2024-04-28 13:15:31.973 my.devices.hostname zigpy.backups DEBUG Adding a new backup NetworkBackup(version=1, backup_time=datetime.datetime(2024, 4, 28, 11, 15, 31, 973984, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=my:ex:te:nd:ed:pa:n0:id, pan_id=0xSHORTPAN, nwk_update_id=1, nwk_manager_id=0x0000, channel=12, channel_mask=<Channels.NO_CHANNELS: 0>, security_level=0, network_key=Key(key=e1:8e:e7:03:a9:82:8d:1e:7d:2d:17:7b:2b:23:65:58, tx_counter=5000, 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:21:2e:ff:ff:09:98:ab), key_table=[], children=[], nwk_addresses={}, stack_specific={}, metadata={}, source='zigpy-espzb@0.0.1'), node_info=NodeInfo(nwk=0x0000, ieee=my:ex:te:nd:ed:pa:n0:id, logical_type=<LogicalType.Coordinator: 0>, model='ESP32H2', manufacturer='Espressif Systems', version='0x00000000'))
2024-04-28 13:15:31.976 my.devices.hostname zigpy_espzb.api DEBUG Serial '/dev/tty.usbmodem579B0264851' connection lost unexpectedly: None

Energy-scanning seems to work just fine for me 👍

Permitting MIGHT work, not sure as i only have one device (IKEA LED2201G8) and it can not pair. Might be related to used channal upon forming (12 instead of 15/20/25).

At this point i wish switching channels was implemented, so i could test out whether any other channel would make it pair.

So far: thanks @lhespress and @puddly!

lhespress / zigpy-espzb

Manual or Setup instructions #6