8000 Device initialization task can be spawned multiple times · Issue #809 · zigpy/zigpy · GitHub
[go: up one dir, main page]
Skip to content
Device initialization task can be spawned multiple times #809
New issue
New issue
Closed
Closed
Device initialization task can be spawned multiple times#809
Labels
@puddly

Description

@puddly
puddly
opened on Sep 11, 2021

@TheJulianJES reported strange behavior with a device re-joining during initialization and the initialization task somehow being launched twice, causing the device to complete zigpy initialization without being initialized at all:

2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [0, <Bool.true: 1>, 0x45ca, 14:b4:57:ff:fe:91:b3:6b, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'22e2b1a9702adff73227dbdb5502265d9d4e27ab21c57e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'ca456bb391feff57b41401000000'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x45ca, 14:b4:57:ff:fe:91:b3:6b, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]


# Device joins
2021-08-14 01:34:31 INFO (MainThread) [zigpy.application] New device 0x45ca (14:b4:57:ff:fe:91:b3:6b) joined the network

# First initialization is scheduled (3 attempts)
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.device] [0x45ca] Scheduling initialization
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.util] Tries remaining: 3

# Node descriptor is requested (2 attempts)
2021-08-14 01:34:31 INFO (MainThread) [zigpy.device] [0x45ca] Requesting 'Node Descriptor'
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x61 request

2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'23e321a9212a7d5e01c86ab5721e4193e39b7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'33e3a5a9212aea21947e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'34e021a92a2a7d5e01c86ab5721e419382517e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'43e2b1a9112a15b259954a25aa1592499c5dc77f278b9874f8476389fc7e3d83937e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000010000004000000013e0d4ca45ffff05810000000002'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=19), 224, -44, 0x45ca, 255, 255, b'\x81\x00\x00\x00\x00']
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 1: b'\x81\x00\x00\x00\x00'
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.zdo] [0x45ca:zdo] ZDO request ZDOCmd.IEEE_addr_req: [0x0000, 0, 0]
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'53e3b5a9362a7e01c86ab5721e410f827e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'64e0a5a92a2a759e7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 98 (incomingSenderEui64Handler) received: b'6bb391feff57b414'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingSenderEui64Handler frame with [14:b4:57:ff:fe:91:b3:6b]
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'74e3b1a9112a11b259874a25aa5596499c5ac77f278b9874f144a9cc97cdae59149a6a7b0ffd9d357e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'040000130000000004000014e0d4ca45ffff0c82ca456bb391feff57b4148002'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=20), 224, -44, 0x45ca, 255, 255, b'\x82\xcaEk\xb3\x91\xfe\xffW\xb4\x14\x80']
2021-08-14 01:34:31 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x45ca, 14:b4:57:ff:fe:91:b3:6b

# Device announces itself
2021-08-14 01:34:31 INFO (MainThread) [zigpy.application] Device 0x45ca (14:b4:57:ff:fe:91:b3:6b) joined the network
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.device] [0x45ca] Scheduling initialization
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.device] [0x45ca] Canceling old initialize call
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 19: b'\x82\xcaEk\xb3\x91\xfe\xffW\xb4\x14\x80'
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.zdo] [0x45ca:zdo] ZDO request ZDOCmd.Device_annce: [0x45CA, 14:b4:57:ff:fe:91:b3:6b, 128]
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=97), 98, b'a\xcaE')

# Initialize is re-started, 3 tries left
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.util] Tries remaining: 3

# And 2 for the node descriptor
2021-08-14 01:34:31 INFO (MainThread) [zigpy.device] [0x45ca] Requesting 'Node Descriptor'
2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.util] Tries remaining: 2


2021-08-14 01:34:31 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x64 request
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'40e121a9602a15781c944a27aa5592099d4e27ca8fcd0641b8bc467e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'05e1a1a9602a15364d547e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0084'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=32769, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=129), 99, b'\x81\x00d\xf3\xa5\xfe\xff\xcc\xcc\xcc\x00\x00\x00\x00')
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'51e621a9602a15781c944a242a5592099d4e272a8ec0e68b9935c67703b2f36bebcdde6f102f7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'16e6a1a9602a1537b1f07e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0085'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'62e721a92a2a7d5e01c86ab5721e419340bf7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'27e7a1a92a2a7c4b7e'
2021-08-14 01:34:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=100), 101, b'd\xcaE')
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'73e421a9602a15781c944a27aa5592099d4e27cf88cd0341b87afc7e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'30e4a1a9602a15341ad37e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0086'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'40e4b1a9112a15b25996ca25aa1593499c5bc77f278b9874eca76343b97c7f2783df8c3d8fffeb89d5d26b51867e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000028000004001000015e0d4ca45ffff116100ca450240806812525200002c52000002'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32770, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=21), 224, -44, 0x45ca, 255, 255, b'a\x00\xcaE\x02@\x80h\x12RR\x00\x00,R\x00\x00']
2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 32770: b'a\x00\xcaE\x02@\x80h\x12RR\x00\x00,R\x00\x00'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'50e4b1a96b2a15781c944a27aa5592099d4e272f8fce67b8747e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca450000020000004001000084620000'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=132), 98, <EmberStatus.SUCCESS: 0>, b'']
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'60e4b1a96b2a15781c944a242a5592099d4e272e8ece67255f7e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'70e4b1a9112a15b25996ca25aa1593499c58c77f278b9874eca26343b97c7f2783df8c3d8fffeb89d5d26bfd197e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca450000018000004001000085630000'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=32769, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=133), 99, <EmberStatus.SUCCESS: 0>, b'']

# Node descriptor response is received
2021-08-14 01:34:32 INFO (MainThread) [zigpy.device] [0x45ca] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress: 128>, manufacturer_code=4712, maximum_buffer_size=82, maximum_incoming_transfer_size=82, server_mask=11264, maximum_outgoing_transfer_size=82, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=False, *is_receiver_on_when_idle=False, *is_router=False, *is_security_capable=False)

# Now the endpoints are being discovered
2021-08-14 01:34:32 INFO (MainThread) [zigpy.device] [0x45ca] Discovering endpoints
2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.util] Tries remaining: 3

2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x66 request
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'00e4b1a96b2a15781c944a27aa5592099d4e272d88ce6721227e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000028000004001000016e0d4ca45ffff116400ca450240806812525200002c52000002'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32770, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=22), 224, -44, 0x45ca, 255, 255, b'd\x00\xcaE\x02@\x80h\x12RR\x00\x00,R\x00\x00']
2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 32770: b'd\x00\xcaE\x02@\x80h\x12RR\x00\x00,R\x00\x00'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca450000020000004001000086650000'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=134), 101, <EmberStatus.SUCCESS: 0>, b'']
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'01e521a92a2a7d5e01c86ab5721e4193e2457e'

# How did this happen????
2021-08-14 01:34:32 INFO (MainThread) [zigpy.device] [0x45ca] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress: 128>, manufacturer_code=4712, maximum_buffer_size=82, maximum_incoming_transfer_size=82, server_mask=11264, maximum_outgoing_transfer_size=82, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=False, *is_receiver_on_when_idle=False, *is_router=False, *is_security_capable=False)
2021-08-14 01:34:32 INFO (MainThread) [zigpy.device] [0x45ca] Discovering endpoints
2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.util] Tries remaining: 3

2021-08-14 01:34:32 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x68 request
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'11e5a1a92a2a9aa57e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=102), 103, b'f\xcaE')
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'12ea21a9602a15781c944a20aa5592099d4e27cd8acd0141b8ac467e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows
10000
.uart] Data frame: b'22eaa1a9602a15358a687e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0087'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'23eb21a92a2a7d5e01c86ab5721e4193d2847e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'33eba1a92a2aeb457e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=104), 105, b'h\xcaE')
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'34e821a9602a15781c944a20aa5592099d4e27c384cd0f41b82c5b7e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'44e8a1a9602a153a16177e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0088'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'54e8b1a96b2a134fa6944a36aa559249984e27bf12a867a16f7e'
2021-08-14 01:34:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff0000130000000004000014ff6600'
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65533, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=20), 255, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2021-08-14 01:34:32 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 255
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'64e8b1a9112a15b25991ca25aa1593499c59c77f278b9874fba06343b97f3ea5b4267e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'74e8b1a96b2a15781c944a20aa5592099d4e272c8ace67dd107e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000058000004001000017e0d4ca45ffff066600ca45010102'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32773, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=23), 224, -44, 0x45ca, 255, 255, b'f\x00\xcaE\x01\x01']
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 32773: b'f\x00\xcaE\x01\x01'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca450000050000004001000087670000'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=135), 103, <EmberStatus.SUCCESS: 0>, b'']

# Endpoints are being initialized
2021-08-14 01:34:33 INFO (MainThread) [zigpy.device] [0x45ca] Discovered endpoints: [1]
2021-08-14 01:34:33 INFO (MainThread) [zigpy.device] [0x45ca] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2021-08-14 01:34:33 INFO (MainThread) [zigpy.endpoint] [0x45ca:1] Discovering endpoint information
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x6a request
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'40e921a92a2a7d5e01c86ab5721e4193707d5e7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'04e8b1a9112a15b25991ca25aa1593499c56c77f278b9874fbae6343b97f3ea563a07e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000058000004001000018e0d4ca45ffff066800ca45010102'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32773, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=24), 224, -44, 0x45ca, 255, 255, b'h\x00\xcaE\x01\x01']
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 32773: b'h\x00\xcaE\x01\x01'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'14e8b1a96b2a15781c944a20aa5592099d4e272384ce67b3cb7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca450000050000004001000088690000'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=136), 105, <EmberStatus.SUCCESS: 0>, b'']
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'25e9a1a92a2a38a37e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=106), 107, b'j\xcaE\x01')

# Endpoints are being initialized again. The new init process replaces all of the endpoints.
2021-08-14 01:34:33 INFO (MainThread) [zigpy.device] [0x45ca] Discovered endpoints: [1]
2021-08-14 01:34:33 INFO (MainThread) [zigpy.device] [0x45ca] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2021-08-14 01:34:33 INFO (MainThread) [zigpy.endpoint] [0x45ca:1] Discovering endpoint information
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2021-08-14 01:34:33 DEBUG (MainThread) [zigpy.device] [0x45ca] Extending timeout for 0x6c request
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'53ee21a9602a15781c944a21aa5592099d4e27c186ca0d41b8c763867e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'36eea1a9602a153b98b97e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0089'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:91:b3:6b/0x45ca
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:91:b3:6b, True)
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'64ef21a92a2a7d5e01c86ab5721e41937d5dbf7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'47efa1a92a2a217e7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x45CA, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=108), 109, b'l\xcaE\x01')
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'75ec21a9602a15781c944a21aa5592099d4e27c780ca0b41b8c7f4227e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'50eca1a9602a1538c54a7e'
2021-08-14 01:34:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2021-08-14 01:34:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'008a'
2021-08-14 01:34:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'60ecb1a9112a15b25990ca25aa1593499c57c77f278b9874e4ac6343b96a3ea3eacfdd6f8affc7dad5d1698e4226aded753ba767aa7e'
2021-08-14 01:34:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2021-08-14 01:34:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000048000004001000019e0d4ca45ffff196a00ca4514010401020300050000010003000204050401030002'
2021-08-14 01:34:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=25), 224, -44, 0x45ca, 255, 255, b'j\x00\xcaE\x14\x01\x04\x01\x02\x03\x00\x05\x00\x00\x01\x00\x03\x00\x02\x04\x05\x04\x01\x03\x00']
2021-08-14 01:34:34 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False> from ep 0 to ep 0, cluster 32772: b'j\x00\xcaE\x14\x01\x04\x01\x02\x03\x00\x05\x00\x00\x01\x00\x03\x00\x02\x04\x05\x04\x01\x03\x00'
2021-08-14 01:34:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'70ecb1a96b2a15781c944a21aa5592099d4e272286ce672a127e'
2021-08-14 01:34:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2021-08-14 01:34:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ca4500000400000040010000896b0000'
2021-08-14 01:34:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 17866, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=137), 107, <EmberStatus.SUCCESS: 0>, b'']
2021-08-14 01:34:34 INFO (MainThread) [zigpy.endpoint] [0x45ca:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=770, device_version=0, input_clusters=[0, 1, 3, 1026, 1029], output_clusters=[3])

# The endpoint cannot have a NEW status here, but since it was replaced it does, causing the model info to not be queried correctly
2021-08-14 01:34:34 INFO (MainThread) [zigpy.device] [0x45ca] Read model None and manufacturer None from <Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>
2021-08-14 01:34:34 INFO (MainThread) [zigpy.device] [0x45ca] Discovered basic device information for <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False>

# ???
2021-08-14 01:34:34 DEBUG (MainThread) [zigpy.application] Device is initialized <Device model=None manuf=None nwk=0x45CA ieee=14:b4:57:ff:fe:91:b3:6b is_initialized=False>

I haven't written a unit test to reproduce the problem yet and the existing test suite never spawns two concurrent initialization tasks. Possibly related to https://bugs.python.org/issue42130?

Metadata

Metadata

Assignees

No one assigned

    Labels

    stale

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions
      0