Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Problem initiating an Elelabs zigbee dongle; Application frame 83 (setConfigurationValue) received: b'35' #266

Closed
unitware opened this issue May 26, 2020 · 18 comments

Comments

@unitware
Copy link

Hi, I have just purchased the Elelabs USB-dongle and also their RPi shield. both have the same issue and I would appreciate any help in what is going on.

There seems to be a problem setting the channel?
Im just beginning with bellows and home assistant (same problem there) so any hints are appreciated

$ git clone https://github.com/zigpy/bellows.git
$ cd bellows
$ git describe --tags
0.16.a2-20-g191cafe
$ python3 setup.py install
...
$
$ touch db
$
$ bellows -d /dev/ttyUSB0 -b 115200 -v debug form -D db -c 16 
debug: Using selector: EpollSelector
debug: Loading application state from db
debug: Using selector: EpollSelector
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
debug: Send command version: (4,)
debug: Sending: b'004221a850ed2c7e'
debug: Data frame: b'0142a1a8522825d2e23b7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received: b'06023060'
debug: Send command version: (6,)
debug: Sending: b'7d31432157542a7d3315a67e'
debug: Data frame: b'1243a157542a13b069f4b3d37e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received: b'06023060'
debug: Switched to EZSP protocol version 6
debug: EZSP Stack Type: 2, Stack Version: 24624
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_KEY_TABLE_SIZE: 30>, 4)
debug: Sending: b'2240215754790bb65943cb7e'
debug: Data frame: b'2340a157547915fbd27e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
debug: Sending: b'33412157547907b247f69f7e'
debug: Data frame: b'3441a157547915904d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, 3)
debug: Sending: b'4446215754793fb159e15f7e'
debug: Data frame: b'4546a157547915640c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
debug: Sending: b'55472157547910a259e2867e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_MAX_END_DEVICE_CHILDREN: 17>, 32)
debug: Sending: b'66442157547904925969837e'
debug: Data frame: b'6744a157547915e1597e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
debug: Sending: b'7745215754790cb0595fa87e'
debug: Data frame: b'7045a1575479158ac67e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
debug: Sending: b'004a215754797d38b7599a2e7e'
debug: Data frame: b'014aa15754791573c57e'
debug: Sending: b'8160597e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
debug: Sending: b'7d314b2157547938b3592f227e'
debug: Data frame: b'124ba157547915d99c7e'
debug: Sending: b'82503a7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
debug: Sending: b'2248215754797d33a25978647e'
debug: Data frame: b'2348a157547915f6907e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
debug: Sending: b'33492157547919b05925ba7e'
debug: Data frame: b'3449a1575479159d0f7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 16)
debug: Sending: b'444e215754790fa2596c007e'
debug: Data frame: b'454ea1575479200fb87e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received: b'35'
Traceback (most recent call last):
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/bin/bellows", line 11, in <module>
debug: Closed serial connection
    load_entry_point('bellows==0.17.0.dev0', 'console_scripts', 'bellows')()
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/click/decorators.py", line 21, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/application.py", line 44, in form
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/util.py", line 75, in inner
  File "/usr/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
    return future.result()
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/util.py", line 61, in async_inner
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/application.py", line 42, in inner
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 138, in startup
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 88, in initialize
  File "/home/magnus/.espressif/python_env/idf4.1_py3.6_env/lib/python3.6/site-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 230, in _cfg
AssertionError
@Adminiuga
Copy link
Collaborator

1.that is not the most recent version of bellows, this log was collected before Apr 15th?
2. debug: Application frame 83 (setConfigurationValue) received: b'35' -- means the stick is out of memory

The out of memory is strange, cause I'm running on my HUSBZB with 32 source routes without any issues and the same initializes fine on the older elelabs stick I have. I'd escalate with Elelabs, must be something related to this specific firmware as a lot of people are running these parameters without issues.

Alternatively, try a separate venv with "bellows-homeassistant==0.15.2" and "zigpy-homeassistant==0.19.0" before big changes

@Adminiuga
Copy link
Collaborator

or try changing the source route table size to 8 or decrease the number EZSP_CONFIG_MAX_END_DEVICE_CHILDREN is

vol.Optional(c.CONFIG_MAX_END_DEVICE_CHILDREN.name, default=32): vol.All(

@unitware
Copy link
Author

unitware commented May 26, 2020 via email

@unitware
Copy link
Author

Alternatively, try a separate venv with "bellows-homeassistant==0.15.2" and "zigpy-homeassistant==0.19.0" before big changes

Running on old versions work, can I do this in a recent homeassistant install in any way?

or try changing the source route table size to 8 or decrease the number EZSP_CONFIG_MAX_END_DEVICE_CHILDREN 

This did not work (not sure I did it correctly though, I changed the constant in bellows/types/named.py

@Adminiuga
Copy link
Collaborator

Nope, that's wrong. You should change default values for that parameter in https://github.com/zigpy/bellows/blob/191cafe5ffad9bcb3dfe72dedeb78c25c2760b9c/bellows/config/ezsp.py

Alternatively, if using with home assistant 0.110 or newer, add to configuration.yaml

zha:
  zigpy_config:
    ezsp_config:
      - CONFIG_SOURCE_ROUTE_TABLE_SIZE: 8

Although personally, I'd reduce the number of max end devices, 32 is way too high and increase source routes number to 16

@unitware
Copy link
Author

Thanks I'm getting somewhere now, but without the dash in the config:

zha:
  zigpy_config:
    ezsp_config:
      CONFIG_SOURCE_ROUTE_TABLE_SIZE: 8

Is there a way to set the channel and network key this way to? I'm running hassio and I cant get the bellows to install without gcc (pycryptodome setup).

@Adminiuga
Copy link
Collaborator

you would need to form the network again, meaning you would have to re-pair all the devices. ATM not possible to update the network key or channel.

  1. stop HA
  2. run bellows -d /dev/ttyUSB-your-zigbee-device leave -- this will kill the current network
  3. run bellows -d /dev/ttyUSB-your-zigbee-device form -c 15 --network-key 1,2,3,4,5,6,,16

or you could put under zigpy_config:

zigpy_config:
  network:
    key: [1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16]   ## 16 bytes of network key
    channel: 15

and restart HA

@Adminiuga
Copy link
Collaborator

Don't think so, it's not supported by all radios yet

@unitware
Copy link
Author

unitware commented Jun 4, 2020

Hi, I'm still struggling a bit. now I can start bellows most of the times but it is sometimes failing on startup/initiation

magnus@uw-build-ubuntu:~/work/bellows/bellows$ bellows -d /dev/ttyUSB0 -b 115200 -vDEBUG permit -D db 
debug: Using selector: EpollSelector
debug: Loading application state from db
debug: Checking quirks for None None (cc:cc:cc:ff:fe:a5:f3:56)
debug: Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Found custom device replacement for cc:cc:cc:ff:fe:a5:f3:56: <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Using selector: EpollSelector
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
debug: Send command version: (4,)
debug: Sending: b'004221a850ed2c7e'
debug: Data frame: b'0142a1a8522825d2e23b7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received: b'06023060'
debug: Send command version: (6,)
debug: Sending: b'7d31432157542a7d3315a67e'
debug: Data frame: b'1243a157542a13b069f4b3d37e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received: b'06023060'
debug: Switched to EZSP protocol version 6
debug: EZSP Stack Type: 2, Stack Version: 24624
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
debug: Sending: b'2240215754797d38b7596ac97e'
debug: Data frame: b'2340a157547915fbd27e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
debug: Sending: b'33412157547938b359dfc57e'
debug: Data frame: b'3441a157547915904d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
debug: Sending: b'44462157547907b2472bf77e'
debug: Data frame: b'4546a157547915640c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
debug: Sending: b'55472157547910a259e2867e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
debug: Sending: b'66442157547919b05908357e'
debug: Data frame: b'6744a157547915e1597e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
debug: Sending: b'7745215754797d33a25955eb7e'
debug: Data frame: b'7045a1575479158ac67e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 8)
debug: Sending: b'004a215754790fba592a817e'
debug: Data frame: b'014aa15754791573c57e'
debug: Sending: b'8160597e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, 3)
debug: Sending: b'7d314b215754793fb159ccd07e'
debug: Data frame: b'124ba157547915d99c7e'
debug: Sending: b'82503a7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
debug: Sending: b'2248215754790cb05972277e'
debug: Data frame: b'2348a15754792090667e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'35'
error: Couldn't start application
Shutting down ControllerApplication
debug: Closed serial connection
Traceback (most recent call last):
  File "/usr/local/bin/bellows", line 11, in <module>
    load_entry_point('bellows==0.17.0.dev0', 'console_scripts', 'bellows')()
  File "/usr/local/lib/python3.6/dist-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.6/dist-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.6/dist-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.6/dist-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.6/dist-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/local/lib/python3.6/dist-packages/click/decorators.py", line 21, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/application.py", line 63, in permit
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/util.py", line 75, in inner
  File "/usr/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/util.py", line 59, in async_inner
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/cli/util.py", line 137, in setup_application
  File "/usr/local/lib/python3.6/dist-packages/zigpy/application.py", line 65, in new
    await app.startup(auto_form)
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 138, in startup
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 88, in initialize
  File "/usr/local/lib/python3.6/dist-packages/bellows-0.17.0.dev0-py3.6.egg/bellows/zigbee/application.py", line 230, in _cfg
AssertionError

When I get it past that I'm experiencing some other fault that might be related but also might be due to the fact that I'm trying to join a new door lock that I am developing. any hints on why it is leaving the network after the initial handshake is greatly appreciated. (should I open a new ticket for this? kept it here until the startup is rock solid). When running the door lock with another controller (nrodic nrf52840 cli example applicatrion) then it is working. debug output and sniffer log:

leave_after_join.pcap.zip

magnus@uw-build-ubuntu:~/work/bellows/bellows$ bellows -d /dev/ttyUSB0 -b 115200 -vDEBUG permit -D db 
debug: Using selector: EpollSelector
debug: Loading application state from db
debug: Checking quirks for None None (cc:cc:cc:ff:fe:a5:f3:56)
debug: Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Found custom device replacement for cc:cc:cc:ff:fe:a5:f3:56: <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Using selector: EpollSelector
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
debug: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
debug: Send command version: (4,)
debug: Sending: b'004221a850ed2c7e'
debug: Data frame: b'0142a1a8522825d2e23b7e'
debug: Sending: b'8160597e'
debug: Application frame 0 (version) received: b'06023060'
debug: Send command version: (6,)
debug: Sending: b'7d31432157542a7d3315a67e'
debug: Data frame: b'1243a157542a13b069f4b3d37e'
debug: Sending: b'82503a7e'
debug: Application frame 0 (version) received: b'06023060'
debug: Switched to EZSP protocol version 6
debug: EZSP Stack Type: 2, Stack Version: 24624
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_KEY_TABLE_SIZE: 30>, 4)
debug: Sending: b'2240215754790bb65943cb7e'
debug: Data frame: b'2340a157547915fbd27e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
debug: Sending: b'3341215754797d38b75995c77e'
debug: Data frame: b'3441a157547915904d7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_PAN_ID_CONFLICT_REPORT_THRESHOLD: 34>, 2)
debug: Sending: b'44462157547937b0597bcf7e'
debug: Data frame: b'4546a157547915640c7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
debug: Sending: b'55472157547938b359fda37e'
debug: Data frame: b'5647a157547915ce557e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, 3)
debug: Sending: b'6644215754793fb1590f627e'
debug: Data frame: b'6744a157547915e1597e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 8)
debug: Sending: b'7745215754790fba59e9337e'
debug: Data frame: b'7045a1575479158ac67e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
debug: Sending: b'004a2157547910a259cf097e'
debug: Data frame: b'014aa15754791573c57e'
debug: Sending: b'8160597e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
debug: Sending: b'7d314b215754797d33a25969577e'
debug: Data frame: b'124ba157547915d99c7e'
debug: Sending: b'82503a7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
debug: Sending: b'2248215754790cb05972277e'
debug: Data frame: b'2348a157547915f6907e'
debug: Sending: b'83401b7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
debug: Sending: b'33492157547907b247e8457e'
debug: Data frame: b'3449a1575479159d0f7e'
debug: Sending: b'8430fc7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
debug: Sending: b'444e2157547919b059f8d27e'
debug: Data frame: b'454ea157547915694e7e'
debug: Sending: b'8520dd7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT: 19>, 60)
debug: Sending: b'554f21575479068e594e147e'
debug: Data frame: b'564fa157547915c3177e'
debug: Sending: b'8610be7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT_SHIFT: 27>, 8)
debug: Sending: b'664c215754790eba593fd77e'
debug: Data frame: b'674ca157547915ec1b7e'
debug: Sending: b'87009f7e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command setConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>, 255)
debug: Sending: b'774d21575479144d59ce2d7e'
debug: Data frame: b'704da15754791587847e'
debug: Sending: b'8070787e'
debug: Application frame 83 (setConfigurationValue) received: b'00'
debug: Send command getConfigurationValue: (<EzspConfigId.CONFIG_APS_UNICAST_MESSAGE_COUNT: 3>,)
debug: Sending: b'00522157547816fde07e'
debug: Data frame: b'0152a157547815b859dd417e'
debug: Sending: b'8160597e'
debug: Application frame 82 (getConfigurationValue) received: b'000a00'
debug: APS_UNICAST_MESSAGE_COUNT is set to 10
debug: Send command addEndpoint: (1, 260, 48879, 0, 0, 1, [], [1280])
debug: Sending: b'7d31532157542814b6587bf425aa54924c90f77e'
debug: Data frame: b'1253a157542815f3d47e'
debug: Sending: b'82503a7e'
debug: Application frame 2 (addEndpoint) received: b'00'
debug: Ezsp adding endpoint: [<EzspStatus.SUCCESS: 0>]
debug: Send command setConcentrator: (False, <EmberConcentratorType.HIGH_RAM_CONCENTRATOR: 65529>, 600, 1800, 2, 5, 0)
debug: Sending: b'22502157543a154ba6cc482dad57974943f37e'
debug: Data frame: b'2350a157543a15b9c97e'
debug: Sending: b'83401b7e'
debug: Application frame 16 (setConcentrator) received: b'00'
debug: Set concentrator type: [<EmberStatus.SUCCESS: 0>]
debug: Send command networkInit: ()
debug: Sending: b'33512157543def3e7e'
debug: Data frame: b'3451a557543d15c2c77e'
debug: Sending: b'8430fc7e'
debug: Data frame: b'4451b1575433856b4c7e'
debug: Application frame 23 (networkInit) received: b'00'
debug: Send command getNetworkParameters: ()
debug: Sending: b'8520dd7e'
debug: Application frame 25 (stackStatusHandler) received: b'90'
debug: Sending: b'455621575402872b7e'
debug: Data frame: b'5556a157540215b365087b0f38834e3dd7662fbbedce678bfd3e9c8e494b7e'
debug: Sending: b'8610be7e'
debug: Application frame 40 (getNetworkParameters) received: b'00013c9c312a92d6dc744b2808100000000000f8ff07'
debug: Send command setPolicy: (<EzspPolicyId.TC_KEY_REQUEST_POLICY: 5>, <EzspDecisionId.GENERATE_NEW_TC_LINK_KEY: 82>)
debug: Sending: b'56572157547f10e03ea27e'
debug: Data frame: b'6657a157547f1527fa7e'
debug: Sending: b'87009f7e'
debug: Application frame 85 (setPolicy) received: b'00'
debug: Send command setPolicy: (<EzspPolicyId.APP_KEY_REQUEST_POLICY: 6>, <EzspDecisionId.ALLOW_APP_KEY_REQUESTS: 97>)
debug: Sending: b'67542157547f7d33d3b44c7e'
debug: Data frame: b'7754a157547f1566007e'
debug: Sending: b'8070787e'
debug: Application frame 85 (setPolicy) received: b'00'
debug: Send command setPolicy: (<EzspPolicyId.TRUST_CENTER_POLICY: 0>, <EzspDecisionId.ALLOW_PRECONFIGURED_KEY_JOINS: 1>)
debug: Sending: b'70552157547f15b330817e'
debug: Data frame: b'0055a157547f15be857e'
debug: Sending: b'8160597e'
debug: Application frame 85 (setPolicy) received: b'00'
debug: Send command getNodeId: ()
debug: Sending: b'015a2157540d915e7e'
debug: Data frame: b'115aa157540d15b2026a7e'
debug: Sending: b'82503a7e'
debug: Application frame 39 (getNodeId) received: b'0000'
debug: Send command getEui64: ()
debug: Sending: b'125b2157540cff4a7e'
debug: Data frame: b'225ba157540c4341fc6ab5e9669915597e'
debug: Sending: b'83401b7e'
debug: Application frame 38 (getEui64) received: b'56f3a5feffcccccc'
Device 0x0000 (cc:cc:cc:ff:fe:a5:f3:56) joined the network
debug: Skip initialization for existing device cc:cc:cc:ff:fe:a5:f3:56
debug: EZSP nwk=0x0000, IEEE=cc:cc:cc:ff:fe:a5:f3:56
debug: Send command getConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>,)
debug: Starting EZSP watchdog
debug: Sending: b'2358215754787d339d337e'
debug: Data frame: b'3358a157547815a25992e07e'
debug: Sending: b'8430fc7e'
debug: Application frame 82 (getConfigurationValue) received: b'001000'
debug: Send command getMulticastTableEntry: (0,)
debug: Sending: b'34592157544915a0ce7e'
debug: Data frame: b'4459a157544915b259944d427e'
debug: Sending: b'8520dd7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[0] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (1,)
debug: Sending: b'455e215754491444ae7e'
debug: Data frame: b'555ea157544915b25994073a7e'
debug: Sending: b'8610be7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[1] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (2,)
debug: Sending: b'565f2157544917de947e'
debug: Data frame: b'665fa157544915b25994f04d7e'
debug: Sending: b'87009f7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[2] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (3,)
debug: Sending: b'675c2157544916e1b97e'
debug: Data frame: b'775ca157544915b2599426da7e'
debug: Sending: b'8070787e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[3] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (4,)
debug: Sending: b'705d215754497d31fac17e'
debug: Data frame: b'005da157544915b259940e827e'
debug: Sending: b'8160597e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[4] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (5,)
debug: Sending: b'016221575449103c6f7e'
debug: Data frame: b'1162a157544915b2599499077e'
debug: Sending: b'82503a7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[5] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (6,)
debug: Sending: b'1263215754497d33a6557e'
debug: Data frame: b'2263a157544915b259946e707e'
debug: Sending: b'83401b7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[6] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (7,)
debug: Sending: b'2360215754491299787e'
debug: Data frame: b'3360a157544915b25994b8e77e'
debug: Sending: b'8430fc7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[7] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (8,)
debug: Sending: b'3461215754491d03087e'
debug: Data frame: b'4461a157544915b2599490bf7e'
debug: Sending: b'8520dd7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[8] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (9,)
debug: Sending: b'4566215754491ce7687e'
debug: Data frame: b'5566a157544915b25994dac77e'
debug: Sending: b'8610be7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[9] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (10,)
debug: Sending: b'5667215754491f7d5d527e'
debug: Data frame: b'6667a157544915b259942db07e'
debug: Sending: b'87009f7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[10] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (11,)
debug: Sending: b'6764215754491e427f7e'
debug: Data frame: b'7764a157544915b25994fb277e'
debug: Sending: b'8070787e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[11] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (12,)
debug: Sending: b'7065215754491959077e'
debug: Data frame: b'0065a157544915b25994d37f7e'
debug: Sending: b'8160597e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[12] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (13,)
debug: Sending: b'016a215754497d38b0257e'
debug: Data frame: b'116aa157544915b25994b0f87e'
debug: Sending: b'82503a7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[13] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (14,)
debug: Sending: b'126b215754491b2a1f7e'
debug: Data frame: b'226ba157544915b25994478f7e'
debug: Sending: b'83401b7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[14] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command getMulticastTableEntry: (15,)
debug: Sending: b'2368215754497d3a15327e'
debug: Data frame: b'3368a157544915b2599491187e'
debug: Sending: b'8430fc7e'
debug: Application frame 99 (getMulticastTableEntry) received: b'00000000'
debug: MulticastTableEntry[15] = <EmberMulticastTableEntry multicastId=0x0000 endpoint=0 networkIndex=0>
debug: Send command sendBroadcast: (<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, <EmberApsFrame profileId=0 clusterId=54 sourceEndpoint=0 destinationEndpoint=0 options=0 groupId=0 sequence=1>, 0, 2, b'\x01\x1e\x00')
debug: Sending: b'34692157541ce94d59947c25aa5592499c4e26abefcd6695fd71ad7e'
debug: Data frame: b'4469a157541c158ca3717e'
debug: Sending: b'8520dd7e'
debug: Application frame 54 (sendBroadcast) received: b'003e'
debug: Data frame: b'5469b157546f10b259a24a25aa5592499c70d8abedce9874fec77d89dee27e'
debug: Sending: b'8610be7e'
debug: Application frame 69 (incomingMessageHandler) received: b'05000036000000000000003eff000000ffff03011e00'
debug: Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST_LOOPBACK: 5>, <EmberApsFrame profileId=0 clusterId=54 sourceEndpoint=0 destinationEndpoint=0 options=0 groupId=0 sequence=62>, 255, 0, 0x0000, 255, 255, b'\x01\x1e\x00']
debug: [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [30, <Bool.false: 0>]
debug: Data frame: b'6469b1575415134ea6944a13aa5592499c4e2795efce67e61d7e'
debug: Sending: b'87009f7e'
debug: Application frame 63 (messageSentHandler) received: b'06fcff000036000000000000003e020000'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65532, <EmberApsFrame profileId=0 clusterId=54 sourceEndpoint=0 destinationEndpoint=0 options=0 groupId=0 sequence=62>, 2, <EmberStatus.SUCCESS: 0>, b'']
debug: Send command permitJoining: (30,)
debug: Sending: b'476e215754080bd6e27e'
debug: Data frame: b'756ea1575408153ea37e'
debug: Sending: b'8070787e'
debug: Application frame 34 (permitJoining) received: b'00'
Joins are permitted for the next 30s...
debug: Data frame: b'056eb557540915b31c0ea77fc5a6e67f52ba23dad27e'
debug: Sending: b'8160597e'
debug: Application frame 35 (childJoinHandler) received: b'0001459aed5a6ff37436cef404'
debug: Received childJoinHandler frame with [0, <Bool.true: 1>, 0x9a45, f4:ce:36:74:f3:6f:5a:ed, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
debug: Data frame: b'156eb15754ee502859944bbc9a7e'
debug: Sending: b'82503a7e'
debug: Application frame 196 (changeSourceRouteHandler) received: b'459a000001'
debug: Received changeSourceRouteHandler frame with [0x9a45, 0x0000, <Bool.true: 1>]
debug: Data frame: b'256eb157540e5028b4ce25d6de635cbd9d4e27aba06a7e'
debug: Sending: b'83401b7e'
debug: Application frame 36 (trustCenterJoinHandler) received: b'459aed5a6ff37436cef401000000'
debug: Received trustCenterJoinHandler frame with [0x9a45, f4:ce:36:74:f3:6f:5a:ed, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
debug: Data frame: b'356eb5575448f8e836673e1364a18dfc7e'
debug: Sending: b'8430fc7e'
debug: Application frame 98 (incomingSenderEui64Handler) received: b'ed5a6ff37436cef4'
debug: Received incomingSenderEui64Handler frame with [f4:ce:36:74:f3:6f:5a:ed]
debug: Data frame: b'456eb157546f11b259874a25aa5596499c24d874a8549874f1c72613112450549ffb109b0ffd0e6f7e'
debug: Sending: b'8520dd7e'
debug: Application frame 69 (incomingMessageHandler) received: b'04000013000000000400006affdf459affff0c01459aed5a6ff37436cef48002'
debug: Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, <EmberApsFrame profileId=0 clusterId=19 sourceEndpoint=0 destinationEndpoint=0 options=1024 groupId=0 sequence=106>, 255, -33, 0x9a45, 255, 255, b'\x01E\x9a\xedZo\xf3t6\xce\xf4\x80']
ZDO Device announce: 0x9a45, f4:ce:36:74:f3:6f:5a:ed
Device 0x9a45 (f4:ce:36:74:f3:6f:5a:ed) joined the network
debug: [0x9a45:zdo] ZDO request ZDOCmd.Device_annce: [0x9a45, f4:ce:36:74:f3:6f:5a:ed, 128]
[0x9a45] Requesting 'Node Descriptor'
debug: Tries remaining: 2
debug: [0x9a45] Extending timeout for 0x03 request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'556f21575454f8e836673e7d3364a19316d27e'
debug: Data frame: b'566fa157545410d67e'
debug: Sending: b'8610be7e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=3>, 4, b'\x03E\x9a')
debug: Sending: b'666c2157541e15f7c3944a27aa5592099d4e27a8e9cd64ce67337d317e'
debug: Data frame: b'676ca157541e15f298f27e'
debug: Sending: b'87009f7e'
debug: Application frame 52 (sendUnicast) received: b'0040'
debug: Data frame: b'776cb157541515f7c3944a27aa5592099d4e27ebe9ce67cf247e'
debug: Sending: b'8070787e'
debug: Application frame 63 (messageSentHandler) received: b'00459a0000020000004001000040040000'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=64>, 4, <EmberStatus.SUCCESS: 0>, b'']
debug: Data frame: b'076cb5575448f8e836673e1364a1aac07e'
debug: Sending: b'8160597e'
debug: Application frame 98 (incomingSenderEui64Handler) received: b'ed5a6ff37436cef4'
debug: Received incomingSenderEui64Handler frame with [f4:ce:36:74:f3:6f:5a:ed]
debug: Data frame: b'176cb157546f15b25996ca25aa159f499c25d874a8549874ecc563cc667c7f2bdfdfb2108fffeba4d5d26beadf7e'
debug: Sending: b'82503a7e'
debug: Application frame 69 (incomingMessageHandler) received: b'00000002800000400d00006bffdf459affff110300459a02408c34126c7f00002c7f000002'
debug: Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32770 sourceEndpoint=0 destinationEndpoint=0 options=3392 groupId=0 sequence=107>, 255, -33, 0x9a45, 255, 255, b'\x03\x00E\x9a\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00']
[0x9a45] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=140 manufacturer_code=4660 maximum_buffer_size=108 maximum_incoming_transfer_size=127 server_mask=11264 maximum_outgoing_transfer_size=127 descriptor_capability_field=0>
[0x9a45] Discovering endpoints
debug: Tries remaining: 3
debug: [0x9a45] Extending timeout for 0x05 request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'726d21575454f8e836673e7d3364a19305937e'
debug: Data frame: b'206da15754549c287e'
debug: Sending: b'83401b7e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=5>, 6, b'\x05E\x9a')
debug: Sending: b'03722157541e15f7c3944a20aa5592099d4e27aeebcd62ce6779687e'
debug: Data frame: b'3172a157541e15f3c68f7e'
debug: Sending: b'8430fc7e'
debug: Application frame 52 (sendUnicast) received: b'0041'
debug: Data frame: b'4172b157541515f7c3944a20aa5592099d4e27eaebce675e2e7e'
debug: Sending: b'8520dd7e'
debug: Application frame 63 (messageSentHandler) received: b'00459a0000050000004001000041060000'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=65>, 6, <EmberStatus.SUCCESS: 0>, b'']
debug: Data frame: b'5172b5575448f8e836673e1364a1de6a7e'
debug: Sending: b'8610be7e'
debug: Application frame 98 (incomingSenderEui64Handler) received: b'ed5a6ff37436cef4'
debug: Received incomingSenderEui64Handler frame with [f4:ce:36:74:f3:6f:5a:ed]
debug: Data frame: b'6172b157546f15b25991ca25aa159f499c23d874a8549874fbc363cc667f37a54d0b7e'
debug: Sending: b'87009f7e'
debug: Application frame 69 (incomingMessageHandler) received: b'00000005800000400d00006dffdf459affff060500459a010802'
debug: Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32773 sourceEndpoint=0 destinationEndpoint=0 options=3392 groupId=0 sequence=109>, 255, -33, 0x9a45, 255, 255, b'\x05\x00E\x9a\x01\x08']
[0x9a45] Discovered endpoints: [8]
[0x9a45:8] Discovering endpoint information
debug: Tries remaining: 3
debug: [0x9a45] Extending timeout for 0x07 request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'177321575454f8e836673e7d3364a193a13b7e'
debug: Data frame: b'7273a1575454ac0e7e'
debug: Sending: b'8070787e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=0 clusterId=4 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=7>, 8, b'\x07E\x9a\x08')
debug: Sending: b'20702157541e15f7c3944a21aa5592099d4e27ace5ca60ce67ceda627e'
debug: Data frame: b'0370a157541e15f14f547e'
debug: Sending: b'8160597e'
debug: Application frame 52 (sendUnicast) received: b'0043'
debug: Data frame: b'1370b15754b1f8e836673e1364a194098a7e'
debug: Sending: b'82503a7e'
debug: Application frame 155 (zigbeeKeyEstablishmentHandler) received: b'ed5a6ff37436cef406'
debug: Received zigbeeKeyEstablishmentHandler frame with [f4:ce:36:74:f3:6f:5a:ed, <EmberKeyStatus.TC_RESPONDED_TO_KEY_REQUEST: 6>]
debug: Data frame: b'2370b157541515f7c3944a21aa5592099d4e27e8e5ce671ba07e'
debug: Sending: b'83401b7e'
debug: Application frame 63 (messageSentHandler) received: b'00459a0000040000004001000043080000'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=0 clusterId=4 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=67>, 8, <EmberStatus.SUCCESS: 0>, b'']
debug: Data frame: b'3370b5575448f8e836673e1364a1141e7e'
debug: Sending: b'8430fc7e'
debug: Application frame 98 (incomingSenderEui64Handler) received: b'ed5a6ff37436cef4'
debug: Received incomingSenderEui64Handler frame with [f4:ce:36:74:f3:6f:5a:ed]
debug: Data frame: b'4370b157546f15b25990ca25aa159f499c21d874a8549874e4c163cc666a37a3eac7de6f89ffc7d8d5d3688d4626a9e8763ba7abdd7e'
debug: Sending: b'8520dd7e'
debug: Application frame 69 (incomingMessageHandler) received: b'00000004800000400d00006fffdf459affff190700459a140804010a0000060000030001010100050004000002'
debug: Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32772 sourceEndpoint=0 destinationEndpoint=0 options=3392 groupId=0 sequence=111>, 255, -33, 0x9a45, 255, 255, b'\x07\x00E\x9a\x14\x08\x04\x01\n\x00\x00\x06\x00\x00\x03\x00\x01\x01\x01\x00\x05\x00\x04\x00\x00']
[0x9a45:8] Discovered endpoint information: <Optional endpoint=8 profile=260 device_type=10 device_version=0 input_clusters=[0, 3, 257, 1, 5, 4] output_clusters=[]>
debug: [0x9a45] Extending timeout for 0x09 request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'357121575454f8e836673e7d3364a19387347e'
debug: Data frame: b'5471a157545450647e'
debug: Sending: b'8610be7e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=320 groupId=0 sequence=9>, 10, b'\x00\t\x00\x04\x00\x05\x00')
debug: Sending: b'46762157541e15f7c3904b25aa5d9a099d4e27a2e7c96782fdc2638cfc2bbd7e'
debug: Data frame: b'6576a157541e15f783c47e'
debug: Sending: b'87009f7e'
debug: Application frame 52 (sendUnicast) received: b'0045'
debug: Data frame: b'7576b557540915b21c0ea77fc5a6e67f52ba234ba47e'
debug: Sending: b'8070787e'
debug: Application frame 35 (childJoinHandler) received: b'0000459aed5a6ff37436cef404'
debug: Received childJoinHandler frame with [0, <Bool.false: 0>, 0x9a45, f4:ce:36:74:f3:6f:5a:ed, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
debug: Data frame: b'0576b157540e5028b4ce25d6de635cbd9e4dd854092c7e'
debug: Sending: b'8160597e'
debug: Application frame 36 (trustCenterJoinHandler) received: b'459aed5a6ff37436cef40203ffff'
debug: Received trustCenterJoinHandler frame with [0x9a45, f4:ce:36:74:f3:6f:5a:ed, <EmberDeviceUpdate.DEVICE_LEFT: 2>, <EmberJoinDecision.NO_ACTION: 3>, 0xffff]
Device 0x9a45 (f4:ce:36:74:f3:6f:5a:ed) left the network
debug: Send command nop: ()
debug: Sending: b'51772157542fcc247e'
debug: Data frame: b'1677a157542fb34d7e'
debug: Sending: b'82503a7e'
debug: Application frame 5 (nop) received: b''
debug: Send command nop: ()
debug: Sending: b'62742157542fc39a7e'
debug: Data frame: b'2774a157542f37b37e'
debug: Sending: b'83401b7e'
debug: Application frame 5 (nop) received: b''
debug: Data frame: b'3774b157541515f7c3904b25aa5d9a099c4e27eee7a8678e287e'
debug: Sending: b'8430fc7e'
debug: Application frame 63 (messageSentHandler) received: b'00459a04010000080840000000450a6600'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=64 groupId=0 sequence=69>, 10, <EmberStatus.DELIVERY_FAILED: 102>, b'']
debug: [0x9a45] Delivery error for seq # 0x09, on endpoint id 8 cluster 0x0000: message send failure
debug: [0x9a45] Extending timeout for 0x0b request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'747521575454f8e836673e7d3364a193fe647e'
debug: Data frame: b'4075a1575454c5477e'
debug: Sending: b'8520dd7e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=320 groupId=0 sequence=11>, 12, b'\x00\x0b\x00\x04\x00')
debug: Sending: b'057a2157541e15f7c3904b25aa5d9a099d4e27a0e1cb6780fdc263a7307e'
debug: Data frame: b'517aa157541e15f4a87d7e'
debug: Sending: b'8610be7e'
debug: Application frame 52 (sendUnicast) received: b'0046'
debug: Data frame: b'617ab157541515f7c3904b25aa5d9a099c4e27ede1a8673ab37e'
debug: Sending: b'87009f7e'
debug: Application frame 63 (messageSentHandler) received: b'00459a04010000080840000000460c6600'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=64 groupId=0 sequence=70>, 12, <EmberStatus.DELIVERY_FAILED: 102>, b'']
debug: [0x9a45] Delivery error for seq # 0x0b, on endpoint id 8 cluster 0x0000: message send failure
debug: [0x9a45] Extending timeout for 0x0d request
debug: Extending timeout for f4:ce:36:74:f3:6f:5a:ed/0x9a45
debug: Send command setExtendedTimeout: (f4:ce:36:74:f3:6f:5a:ed, True)
debug: Sending: b'177b21575454f8e836673e7d3364a1934a507e'
debug: Data frame: b'727ba1575454ae237e'
debug: Sending: b'8070787e'
debug: Application frame 126 (setExtendedTimeout) received: b''
debug: Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a45, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=320 groupId=0 sequence=13>, 14, b'\x00\r\x00\x05\x00')
debug: Sending: b'20782157541e15f7c3904b25aa5d9a099d4e27a6e3cb6786fdc363d72f7e'
debug: Data frame: b'0378a157541e15f59c7d7e'
debug: Sending: b'8160597e'
debug: Application frame 52 (sendUnicast) received: b'0047'
debug: Send command nop: ()
debug: Sending: b'31792157542f5c947e'
debug: Data frame: b'1479a157542ff7a57e'
debug: Sending: b'82503a7e'
debug: Application frame 5 (nop) received: b''
debug: Data frame: b'2479b157541515f7c3904b25aa5d9a099c4e27ece3a867b4d17e'
debug: Sending: b'83401b7e'
debug: Application frame 63 (messageSentHandler) received: b'00459a04010000080840000000470e6600'
debug: Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 39493, <EmberApsFrame profileId=260 clusterId=0 sourceEndpoint=8 destinationEndpoint=8 options=64 groupId=0 sequence=71>, 14, <EmberStatus.DELIVERY_FAILED: 102>, b'']
debug: [0x9a45] Delivery error for seq # 0x0d, on endpoint id 8 cluster 0x0000: message send failure
debug: [0x9a45:8] Manufacturer: None
debug: [0x9a45:8] Model: None
debug: Checking quirks for None None (f4:ce:36:74:f3:6f:5a:ed)
debug: Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Fail because endpoint list mismatch: {1} {8}
debug: Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Fail because endpoint list mismatch: {1} {8}
debug: Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
debug: Fail because endpoint list mismatch: {1} {8}
Done
Shutting down ControllerApplication
debug: Cancelling watchdog
debug: Closed serial connection
magnus@uw-build-ubuntu:~/work/bellows/bellows$ 

@Adminiuga
Copy link
Collaborator

Hard to say why it is leaving. Take zigbee packet capture when joining both to bellows and to Nordic controller and compare. Unfortunately with zigbee, when device is leaving is does not provide a reason to the other party. If you can enable debug on the lock itself, then maybe it could provide more insight in what exactly it did not like.

@Adminiuga
Copy link
Collaborator

Elelabs stick seems to be running protocol version 6, EZSP 6.0.3 stack. Could be related to ZB3.0 interop?

@unitware
Copy link
Author

unitware commented Jun 5, 2020

Thanks, I'm new to this and have little knowledge on the EZSP stack versions. Is 6.0.3 an old or new one? Can I get hold of a correct version somehow? (Elelabs have yet to answer my first email, but might respond if I have a more specific question, but my hopes are not to high at the moment)

What usb-adapter / rpi-shield is best today? I mainly selected the elelabs since there were hints of support for the closure/door_lock cluster which is my main interest at this time.

@Yoda-x
Copy link
Contributor

Yoda-x commented Jun 5, 2020

EZSP stack version 6 had a significant change for the end-device-poll-timeout registry compared to 5.
I used the elelab usb stick without problems after below change in the in init procedure: to check the stack version

 self._stackversion = await e.version()
 ....
 if self._stackversion > 0x64ff:
     await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT, 9)
     # with ezsp_callback_handlerstack 6.5 timeout changes
     # timeout_shift is gone
     # The timeout corresponding to a nonzero value N is 2^N minutes
 else:
     await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT, 120)
     await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT_SHIFT, 8)`

@unitware
Copy link
Author

unitware commented Jun 5, 2020

thanks, the version seems to be 24 624 (0x6030)

debug: Application frame 0 (version) received: b'06023060'
debug: Switched to EZSP protocol version 6
debug: EZSP Stack Type: 2, Stack Version: 24624

Should the old way be used? or was the check >= 0x64ff in error?
I did this diff to my code, still not working (the device leaves after the transport key):

diff --git a/bellows/zigbee/application.py b/bellows/zigbee/application.py
index f4a1426..09c5f97 100644
--- a/bellows/zigbee/application.py
+++ b/bellows/zigbee/application.py
@@ -88,11 +88,20 @@ class ControllerApplication(zigpy.application.ControllerApplication):
             await self._cfg(t.EzspConfigId[config], value)
 
         c = t.EzspConfigId
+
         if self._ezsp.ezsp_version >= 7:
             await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT, 8)
+
+        elif self._ezsp.ezsp_version > 6:
+            await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT, 9)
+             # with ezsp_callback_handlerstack 6.5 timeout changes
+             # timeout_shift is gone
+             # The timeout corresponding to a nonzero value N is 2^N minutes
+
         else:
             await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT, 60)
             await self._cfg(c.CONFIG_END_DEVICE_POLL_TIMEOUT_SHIFT, 8)
+
         await self._cfg(
             t.EzspConfigId.CONFIG_PACKET_BUFFER_COUNT,
             ezsp_config[c.CONFIG_PACKET_BUFFER_COUNT.name],

@Adminiuga
Copy link
Collaborator

This should be fixed in 0.18.0 (ha 0.113.x)

@Yuubari
Copy link

Yuubari commented Sep 8, 2020

I get the exact same issue on bellows 0.18.1 and homeassistant 0.114.4 with Elelabs USB adaptor:

2020-09-08 16:13:57 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2020-09-08 16:13:58 DEBUG (bellows.thread_0) [bellows.uart] Resetting ASH
2020-09-08 16:13:58 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'1ac038bc7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command version: (4,)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'004221a850ed2c7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0142a1a8522825d2e23b7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 0 (version) received: b'06023060'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command version: (6,)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d31432157542a7d3315a67e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1243a157542a13b069f4b3d37e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 0 (version) received: b'06023060'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Switched to EZSP protocol version 6
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] EZSP Stack Type: 2, Stack Version: 24624
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'22402157547919b059c46e7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2340a157547915fbd27e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'3341215754797d33a25999b07e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3441a157547915904d7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'44462157547910a2591d887e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4546a157547915640c7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'55472157547938b359fda37e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5647a157547915ce557e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, 3)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'6644215754793fb1590f627e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6744a157547915e1597e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7745215754790cb0595fa87e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7045a1575479158ac67e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_KEY_TABLE_SIZE: 30>, 4)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'004a215754790bb659b32c7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'014aa15754791573c57e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d314b215754797d38b75965207e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'124ba157547915d99c7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'22482157547907b247174b7e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2348a157547915f6907e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'00'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 16)
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'3349215754790fa259b1687e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3449a157547920fbf97e'
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-09-08 16:13:59 DEBUG (MainThread) [bellows.ezsp] Application frame 83 (setConfigurationValue) received: b'35'
2020-09-08 16:13:59 ERROR (MainThread) [zigpy.application] Couldn't start application
2020-09-08 16:13:59 DEBUG (bellows.thread_0) [bellows.uart] Closed serial connection

@Adminiuga
Copy link
Collaborator

Should be fixed HA beta version.
or add to configuraiton.yaml

zha:
  zigpy_config:
    ezsp_config:
      CONFIG_SOURCE_ROUTE_TABLE_SIZE: 8

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants