2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00000004800000400100000bacc7ed7fffff191b00ed7f14010401510001040400050000ef00000219000a0002'
2022-06-20 14:36:28 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=11), 172, -57, 0x7fed, 255, 255, b'\x1b\x00\xed\x7f\x14\x01\x04\x01Q\x00\x01\x04\x04\x00\x05\x00\x00\xef\x00\x00\x02\x19\x00\n\x00']
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x7FED ieee=a4:c1:38:4a:ea:11:11:2f is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x1b\x00\xed\x7f\x14\x01\x04\x01Q\x00\x01\x04\x04\x00\x05\x00\x00\xef\x00\x00\x02\x19\x00\n\x00'
2022-06-20 14:36:28 INFO (MainThread) [zigpy.endpoint] [0x7fed:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=81, device_version=1, input_clusters=[4, 5, 61184, 0], output_clusters=[25, 10])
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] Unknown cluster 0xEF00
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0000] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=29, command_id=<GeneralCommand.Read_Attributes: 0>, *is_reply=False)
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0000] Sending request: Read_Attributes(attribute_ids=[4, 5])
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.device] [0x7fed] Extending timeout for 0x1d request
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for a4:c1:38:4a:ea:11:11:2f/0x7fed
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'201ca1a9a52a29b213942925b45591499c4e24abeece6a8bf1c66189fd7e3da7eacdde6f8fffc6dbd5d2698c4623a9ec763ba5ea758241984c2611b1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a251904824c0327e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'031d21a92a2a3aa3487d5e001d6bf193b30b7e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'3c004a0063001e0003000000030003000d000c000200010002000100000000000100000000000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'311da1a92a2a92d67e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7FED, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=29), 30, b'\x00\x1d\x00\x04\x00\x05\x00')
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'142221a9fe2a1661567e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4222a1a9fe2a15b3abe9f17e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 170 (getValue) received: b'0001f2'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'252321a9602a155f26904b25aa5493099d4e27b6f3c96796fdc2638cfc54997e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 242
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 60, MAC_TX_BROADCAST = 74, MAC_RX_UNICAST = 99, MAC_TX_UNICAST_SUCCESS = 30, MAC_TX_UNICAST_RETRY = 3, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 3, APS_DATA_TX_BROADCAST = 3, APS_DATA_RX_UNICAST = 13, APS_DATA_TX_UNICAST_SUCCESS = 12, APS_DATA_TX_UNICAST_RETRY = 2, APS_DATA_TX_UNICAST_FAILED = 1, ROUTE_DISCOVERY_INITIATED = 2, NEIGHBOR_ADDED = 1, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 1, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 2, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5323a1a9602a15a9625b7e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'001b'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6323b1a96b2a155f26904b25aa5493099d4e27b0f3ce672bce7e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ed7f040100000101400100001b1e0000'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 32749, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=27), 30, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7323b1a9112a15b658944a24ab1593499c439b6000b19874dede7e88f87e3fe5fb928a35cacdf7eb8aa101bd2457c88e143ea5ea378415cb7c102380e257147e'
2022-06-20 14:36:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040100000101400100000dbccbed7fffff23181d0104000042105f545a453230305f7368316274616262050000420654533036303102'
2022-06-20 14:36:28 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=13), 188, -53, 0x7fed, 255, 255, b'\x18\x1d\x01\x04\x00\x00B\x10_TZE200_sh1btabb\x05\x00\x00B\x06TS0601']
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0000] Received ZCL frame: b'\x18\x1d\x01\x04\x00\x00B\x10_TZE200_sh1btabb\x05\x00\x00B\x06TS0601'
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=29, command_id=1, *is_reply=True)
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0000] Decoded ZCL frame: Basic:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0004, status=<Status.SUCCESS: 0>, value=TypeValue(type=CharacterString, value='_TZE200_sh1btabb')), ReadAttributeRecord(attrid=0x0005, status=<Status.SUCCESS: 0>, value=TypeValue(type=CharacterString, value='TS0601'))])
2022-06-20 14:36:28 INFO (MainThread) [zigpy.device] [0x7fed] Read model 'TS0601' and manufacturer '_TZE200_sh1btabb' from <Endpoint id=1 in=[groups:0x0004, scenes:0x0005, None:0xEF00, basic:0x0000] out=[ota:0x0019, time:0x000A] status=<Status.ZDO_INIT: 1>>
2022-06-20 14:36:28 INFO (MainThread) [zigpy.device] [0x7fed] Discovered basic device information for <Device model='TS0601' manuf='_TZE200_sh1btabb' nwk=0x7FED ieee=a4:c1:38:4a:ea:11:11:2f is_initialized=True>
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.application] Device is initialized <Device model='TS0601' manuf='_TZE200_sh1btabb' nwk=0x7FED ieee=a4:c1:38:4a:ea:11:11:2f is_initialized=True>
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for _TZE200_sh1btabb TS0601 (a4:c1:38:4a:ea:11:11:2f)
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'ts0601_sh1btabb.TuyaValve'>
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.quirks.registry] Found custom device replacement for a4:c1:38:4a:ea:11:11:2f: <class 'ts0601_sh1btabb.TuyaValve'>
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'sensor' component -> 'Battery' using ['power']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'sensor' component -> 'RSSISensor' using ['basic']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'sensor' component -> 'LQISensor' using ['basic']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnOffTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnLevelConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OffTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'DefaultMoveRateConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'StartUpCurrentLevelConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'select' component -> 'ZHAStartupOnOffSelectEntity' using ['on_off']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnOffTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnLevelConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OnTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'OffTransitionTimeConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'DefaultMoveRateConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'number' component -> 'StartUpCurrentLevelConfigurationEntity' using ['level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=create, device_id=4a2865a9419105f14f181082bdc80c34>
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x7FED:a4:c1:38:4a:ea:11:11:2f entering async_device_initialized - is_new_join: True
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x7FED:a4:c1:38:4a:ea:11:11:2f has joined the ZHA zigbee network
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): started configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:ZDO](TS0601): 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (a4:c1:38:4a:ea:11:11:2f, 1, 0, 4, '_TZE200_sh1btabb') params: FOREIGN KEY constraint failed
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Performing cluster binding
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Configuring cluster attribute reporting
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Successfully configured reporting for '{'on_off': (0, 900, 1)}' on 'on_off' cluster: [ConfigureReportingResponseRecord(status=0)]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Performing cluster binding
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: bound 'level' cluster: Status.SUCCESS
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Configuring cluster attribute reporting
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Successfully configured reporting for '{'current_level': (1, 900, 1)}' on 'level' cluster: [ConfigureReportingResponseRecord(status=0)]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: Configuring cluster attribute reporting
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Performing cluster binding
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: bound 'power' cluster: Status.SUCCESS
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Configuring cluster attribute reporting
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Successfully configured reporting for '{'battery_voltage': (3600, 10800, 1), 'battery_percentage_remaining': (3600, 10800, 1)}' on 'power' cluster: [ConfigureReportingResponseRecord(status=0)]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Performing cluster binding
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: bound 'level' cluster: Status.SUCCESS
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Configuring cluster attribute reporting
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Successfully configured reporting for '{'current_level': (1, 900, 1)}' on 'level' cluster: [ConfigureReportingResponseRecord(status=0)]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: finished channel configuration
2022-06-20 14:36:28 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (a4:c1:38:4a:ea:11:11:2f, 1, 0, 5, 'TS0601') params: FOREIGN KEY constraint failed
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: 'async_configure' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): completed configuration
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): stored in registry: ZhaDeviceEntry(name='_TZE200_sh1btabb TS0601', ieee='a4:c1:38:4a:ea:11:11:2f', last_seen=1655728588.440613)
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): started initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:ZDO](TS0601): 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing uncached channel attributes: ['battery_voltage', 'battery_percentage_remaining'] - from cache[False]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Performing channel specific initialization: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_size', 'battery_quantity']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing channel: from_cache: False
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: finished channel initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): power source: Battery or Unknown
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): completed initialization
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_off_transition_time is not supported - skipping OnOffTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_level is not supported - skipping OnLevelConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_transition_time is not supported - skipping OnTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] off_transition_time is not supported - skipping OffTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] default_move_rate is not supported - skipping DefaultMoveRateConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] start_up_current_level is not supported - skipping StartUpCurrentLevelConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_off_transition_time is not supported - skipping OnOffTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_level is not supported - skipping OnLevelConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] on_transition_time is not supported - skipping OnTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] off_transition_time is not supported - skipping OffTransitionTimeConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] default_move_rate is not supported - skipping DefaultMoveRateConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.number] start_up_current_level is not supported - skipping StartUpCurrentLevelConfigurationEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.components.zha.select] start_up_on_off is not supported - skipping ZHAStartupOnOffSelectEntity entity creation
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=4a2865a9419105f14f181082bdc80c34, changes=via_device_id=None>
2022-06-20 14:36:28 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new light.zha entity: light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off>
2022-06-20 14:36:28 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.zha entity: sensor.tze200_sh1btabb_ts0601_2f1111ea_power
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power>
2022-06-20 14:36:28 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.zha entity: sensor.tze200_sh1btabb_ts0601_2f1111ea_basic_rssi
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_basic_rssi>
2022-06-20 14:36:28 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.zha entity: sensor.tze200_sh1btabb_ts0601_2f1111ea_basic_lqi
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_basic_lqi>
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off, old_state=None, new_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=off; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], off_brightness=None, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:28.844939+02:00>>
2022-06-20 14:36:28 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power, old_state=None, new_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unknown; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:28.852588+02:00>>
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 6, 16387) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 6, 0) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 16) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 17) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 18) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 19) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 20) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 16384) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 8, 0) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 1, 32) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 1, 33) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 1, 49) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 1, 1, 51) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 16) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 17) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 18) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 19) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 20) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 16384) params: FOREIGN KEY constraint failed
2022-06-20 14:36:29 DEBUG (MainThread) [zigpy.appdb] Error handling '_unsupported_attribute_added' event with (a4:c1:38:4a:ea:11:11:2f, 2, 8, 0) params: FOREIGN KEY constraint failed
2022-06-20 14:36:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0323b1a9112a10b2598b4a25aa5592499c4ed8abedce9874f74c62a6ed6fd5edd30c7a445c7e'
2022-06-20 14:36:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2022-06-20 14:36:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0500001f0000000000000000ff000000ffff0a8a012f1111ea4a38c1a4'
2022-06-20 14:36:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST_LOOPBACK: 5>, EmberApsFrame(profileId=0, clusterId=31, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=0), 255, 0, 0x0000, 255, 255, b'\x8a\x01/\x11\x11\xeaJ8\xc1\xa4']
2022-06-20 14:36:31 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Parent_annce: [[a4:c1:38:4a:ea:11:11:2f]]
2022-06-20 14:36:31 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Parent_annce([[a4:c1:38:4a:ea:11:11:2f]])
2022-06-20 14:36:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1323b1a96b2a134ea6944a3aaa5592499c4e27abe9ce67d0447e'
2022-06-20 14:36:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2022-06-20 14:36:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fcff00001f0000000000000000040000'
2022-06-20 14:36:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65532, EmberApsFrame(profileId=0, clusterId=31, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=0), 4, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:32 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 4
2022-06-20 14:36:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2323b1a9112a15b259964a25aa1593499c40c77f00b19874fef46389fe2ef37e'
2022-06-20 14:36:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2022-06-20 14:36:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00000002000000400100000ee0d4ed7fffff0332000002'
2022-06-20 14:36:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=14), 224, -44, 0x7fed, 255, 255, b'2\x00\x00']
2022-06-20 14:36:32 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:36:32 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating Devices ...
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 10971 0189968
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11795 0551968
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11795 1038488
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11959 0075424
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11959 0076432
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11795 0551240
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11795 1034008
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11795 0536088
2022-06-20 14:36:34 INFO (SyncWorker_3) [pyfritzhome.fritzhome] Updating already existing Device 11959 0173312
2022-06-20 14:36:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3323b1a9112a15b259964a25aa1593499c5ec77f00b19874fef56389fe800e7e'
2022-06-20 14:36:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2022-06-20 14:36:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000010e0d4ed7fffff0333000002'
2022-06-20 14:36:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=16), 224, -44, 0x7fed, 255, 255, b'3\x00\x00']
2022-06-20 14:36:37 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:36:37 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'342021a9a52a2add7e'
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4420a1a9a52a29b21794f8258d5591499c4e23abe9ce778bf0c66189fd7e3da7eacdde6f8fffc6dbd5d2698c4623a9ec763ba5ea758241984c2615b1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a251904824eb347e'
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'3c004e00b2002700030000000400040010000d000200010002000100000000000100000000000000000000000000000000000000060000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'452121a9fe2a16fd407e'
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5521a1a9fe2a15b3abc3d17e'
2022-06-20 14:36:38 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 170 (getValue) received: b'0001f2'
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 242
2022-06-20 14:36:38 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 60, MAC_TX_BROADCAST = 78, MAC_RX_UNICAST = 178, MAC_TX_UNICAST_SUCCESS = 39, MAC_TX_UNICAST_RETRY = 3, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 4, APS_DATA_TX_BROADCAST = 4, APS_DATA_RX_UNICAST = 16, APS_DATA_TX_UNICAST_SUCCESS = 13, APS_DATA_TX_UNICAST_RETRY = 2, APS_DATA_TX_UNICAST_FAILED = 1, ROUTE_DISCOVERY_INITIATED = 2, NEIGHBOR_ADDED = 1, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 1, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 6, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_b_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_received=2450557024; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B received @ 2022-06-20T14:36:10.090214+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_received=2450638527; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B received @ 2022-06-20T14:36:40.068728+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_b_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_sent=140312874; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B sent @ 2022-06-20T14:36:10.091625+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_sent=140340923; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B sent @ 2022-06-20T14:36:40.070505+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_received=1853985; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets received @ 2022-06-20T14:36:10.092778+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_received=1854173; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets received @ 2022-06-20T14:36:40.071631+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent=938408; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:10.093927+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent=938574; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:40.072713+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received=158.6; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:10.095266+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received=2.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:40.074001+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent=73.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:10.100417+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent=0.9; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:40.079555+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received=143.9; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:10.102503+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received=6.3; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:40.080926+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent=132.8; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:10.103752+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent=5.5; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:40.082126+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_b_received, old_state=<state sensor.fritz_box_7530_b_received=2450557024; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B received @ 2022-06-20T14:36:10.137396+02:00>, new_state=<state sensor.fritz_box_7530_b_received=2450638527; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B received @ 2022-06-20T14:36:40.112800+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_b_sent, old_state=<state sensor.fritz_box_7530_b_sent=140312874; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B sent @ 2022-06-20T14:36:10.138861+02:00>, new_state=<state sensor.fritz_box_7530_b_sent=140340923; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B sent @ 2022-06-20T14:36:40.114237+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_received, old_state=<state sensor.fritz_box_7530_packets_received=1853985; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets received @ 2022-06-20T14:36:10.140255+02:00>, new_state=<state sensor.fritz_box_7530_packets_received=1854173; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets received @ 2022-06-20T14:36:40.115423+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_sent, old_state=<state sensor.fritz_box_7530_packets_sent=938408; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:10.141547+02:00>, new_state=<state sensor.fritz_box_7530_packets_sent=938574; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:40.116786+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_kib_s_received, old_state=<state sensor.fritz_box_7530_kib_s_received=158.6; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:10.143274+02:00>, new_state=<state sensor.fritz_box_7530_kib_s_received=2.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:40.126392+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_kib_s_sent, old_state=<state sensor.fritz_box_7530_kib_s_sent=73.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:10.154141+02:00>, new_state=<state sensor.fritz_box_7530_kib_s_sent=0.9; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:40.127958+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_s_received, old_state=<state sensor.fritz_box_7530_packets_s_received=143.9; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:10.155377+02:00>, new_state=<state sensor.fritz_box_7530_packets_s_received=6.3; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:40.129418+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_s_sent, old_state=<state sensor.fritz_box_7530_packets_s_sent=132.8; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:10.156572+02:00>, new_state=<state sensor.fritz_box_7530_packets_s_sent=5.5; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:40.130754+02:00>>
2022-06-20 14:36:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7C3F](TH01): Attempting to checkin with device - missed checkins: 2
2022-06-20 14:36:40 DEBUG (MainThread) [zigpy.zcl] [0x7C3F:1:0x0000] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=31, command_id=<GeneralCommand.Read_Attributes: 0>, *is_reply=False)
2022-06-20 14:36:40 DEBUG (MainThread) [zigpy.zcl] [0x7C3F:1:0x0000] Sending request: Read_Attributes(attribute_ids=[4])
2022-06-20 14:36:40 DEBUG (MainThread) [zigpy.device] [0x7c3f] Extending timeout for 0x1f request
2022-06-20 14:36:40 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:12:4b:00:25:10:c7:24/0x7c3f
2022-06-20 14:36:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (00:12:4b:00:25:10:c7:24, True)
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'562621a92a2a317549b14a6eb85593cde07e'
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6626a1a92a2aca127e'
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2022-06-20 14:36:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:36:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7C3F, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=31), 32, b'\x00\x1f\x00\x04\x00')
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'672721a9602a158d25904b25aa5493099d4e27b4cdcb6794fdc263a16f7e'
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7727a1a9602a15ac873d7e'
2022-06-20 14:36:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2022-06-20 14:36:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'001e'
2022-06-20 14:36:42 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA546](TS0201): Device seen - marking the device available and resetting counter
2022-06-20 14:36:42 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA546](TS0201): Update device availability -  device available: True - new availability: True - changed: False
2022-06-20 14:36:42 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0727b1a9112a15b259964a25aa1593499c5cc37e00b19874fef26389fe98d07e'
2022-06-20 14:36:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2022-06-20 14:36:42 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000012e4d5ed7fffff0334000002'
2022-06-20 14:36:42 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=18), 228, -43, 0x7fed, 255, 255, b'4\x00\x00']
2022-06-20 14:36:42 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:36:42 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:36:45 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1727b1a96b2a158d25904b25aa5493099c4e27b5cda867e6d37e'
2022-06-20 14:36:45 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2022-06-20 14:36:45 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'003f7c040100000101400000001e206600'
2022-06-20 14:36:45 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 31807, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=30), 32, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2022-06-20 14:36:45 DEBUG (MainThread) [zigpy.device] [0x7c3f] Delivery error for seq # 0x1f, on endpoint id 1 cluster 0x0000: message send failure
2022-06-20 14:36:45 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=4a2865a9419105f14f181082bdc80c34, changes=area_id=None>
2022-06-20 14:36:47 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2727b5a9772a14b2b4eb6534bbbfd8715dea23b9e77e'
2022-06-20 14:36:47 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2022-06-20 14:36:47 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3727b1a9702af8cd76855bcfe06d53ed9e4dd8547e3f7e'
2022-06-20 14:36:47 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2022-06-20 14:36:47 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0100ed7f2f1111ea4a38c1a404'
2022-06-20 14:36:47 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.false: 0>, 0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2022-06-20 14:36:47 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'ed7f2f1111ea4a38c1a40203ffff'
2022-06-20 14:36:47 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberDeviceUpdate.DEVICE_LEFT: 2>, <EmberJoinDecision.NO_ACTION: 3>, 0xffff]
2022-06-20 14:36:47 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) left the network
2022-06-20 14:36:47 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Update device availability -  device available: True - new availability: False - changed: True
2022-06-20 14:36:47 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Device availability changed and device became unavailable
2022-06-20 14:36:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=a4:c1:38:4a:ea:11:11:2f, unique_id=a4:c1:38:4a:ea:11:11:2f, device_id=4a2865a9419105f14f181082bdc80c34, device_event_type=device_offline>
2022-06-20 14:36:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off, old_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=off; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], off_brightness=None, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:28.844939+02:00>, new_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=unavailable; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:47.905919+02:00>>
2022-06-20 14:36:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power, old_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unknown; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:28.852588+02:00>, new_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:47.907334+02:00>>
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'742421a9a52ac9cb7e'
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4024a1a9a52a55b20b94b925815591499c4e23abe9ce768bf0c66789fe7e3ca7eacdde6f8fffc6dbd4d2698c4623a9ec763ba5ea758241984c261bb1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a251904824aa617e'
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'40005200f3002b00030000000400040011000d000400020003000100000000000100010000000000000000000000000000000000080000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'052521a9fe2a16260d7e'
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5125a1a9fe2a15b3ab50537e'
2022-06-20 14:36:48 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 170 (getValue) received: b'0001f2'
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 242
2022-06-20 14:36:48 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 64, MAC_TX_BROADCAST = 82, MAC_RX_UNICAST = 243, MAC_TX_UNICAST_SUCCESS = 43, MAC_TX_UNICAST_RETRY = 3, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 4, APS_DATA_TX_BROADCAST = 4, APS_DATA_RX_UNICAST = 17, APS_DATA_TX_UNICAST_SUCCESS = 13, APS_DATA_TX_UNICAST_RETRY = 4, APS_DATA_TX_UNICAST_FAILED = 2, ROUTE_DISCOVERY_INITIATED = 3, NEIGHBOR_ADDED = 1, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 1, CHILD_REMOVED = 1, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 8, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0101ed7f2f1111ea4a38c1a404'
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.true: 1>, 0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'ed7f2f1111ea4a38c1a401000000'
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2022-06-20 14:36:51 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) joined the network
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:36:51 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=33, command_id=2, *is_reply=False)
2022-06-20 14:36:51 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request: get_membership(groups=[])
2022-06-20 14:36:51 DEBUG (MainThread) [zigpy.device] [0x7fed] Extending timeout for 0x21 request
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for a4:c1:38:4a:ea:11:11:2f/0x7fed
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:36:51 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7FED, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=33), 34, b'\x01!\x02\x00')
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0022'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'040000130000000000000080e0d4ed7fffff0c35ed7f2f1111ea4a38c1a48002'
2022-06-20 14:36:52 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_NONE: 0>, groupId=0, sequence=128), 224, -44, 0x7fed, 255, 255, b'5\xed\x7f/\x11\x11\xeaJ8\xc1\xa4\x80']
2022-06-20 14:36:52 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x7fed, a4:c1:38:4a:ea:11:11:2f
2022-06-20 14:36:52 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) joined the network
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.device] [0x7fed] Cancelling old group rescan
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Update device availability -  device available: False - new availability: True - changed: True
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Device availability changed and device became available, reinitializing channels
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Device_annce: [0x7FED, a4:c1:38:4a:ea:11:11:2f, 128]
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=35, command_id=2, *is_reply=False)
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request: get_membership(groups=[])
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.device] [0x7fed] Extending timeout for 0x23 request
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for a4:c1:38:4a:ea:11:11:2f/0x7fed
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): started initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:ZDO](TS0601): 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing uncached channel attributes: ['battery_voltage', 'battery_percentage_remaining'] - from cache[False]
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Performing channel specific initialization: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_size', 'battery_quantity']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing channel: from_cache: False
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: finished channel initialization
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ed7f0401040001014001000022220000'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 32749, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=34), 34, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 34
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000401040001010001000081e0d4ed7fffff05192102100002'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=129), 224, -44, 0x7fed, 255, 255, b'\x19!\x02\x10\x00']
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x19!\x02\x10\x00'
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=33, command_id=2, *is_reply=True)
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[])
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received command 0x02 (TSN 33): get_membership_response(capacity=16, groups=[])
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] No explicit handler for cluster command 0x02: get_membership_response(capacity=16, groups=[])
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000401040001010001000082e0d4ed7fffff0518210b020002'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=130), 224, -44, 0x7fed, 255, 255, b'\x18!\x0b\x02\x00']
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x18!\x0b\x02\x00'
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=33, command_id=11, *is_reply=True)
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:36:52 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received command 0x0B (TSN 33): Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): power source: Battery or Unknown
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): completed initialization
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off, old_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=unavailable; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:47.905919+02:00>, new_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=off; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], off_brightness=None, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:52.469391+02:00>>
2022-06-20 14:36:52 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power, old_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:47.907334+02:00>, new_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unknown; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:52.471687+02:00>>
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7FED, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=35), 36, b'\x01#\x02\x00')
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff0000130000000000000080000000'
2022-06-20 14:36:52 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_NONE: 0>, groupId=0, sequence=128), 0, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0023'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ed7f0401040001014001000023240000'
2022-06-20 14:36:52 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 32749, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=35), 36, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000401040001010001000083e0d4ed7fffff05192302100002'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=131), 224, -44, 0x7fed, 255, 255, b'\x19#\x02\x10\x00']
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x19#\x02\x10\x00'
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=35, command_id=2, *is_reply=True)
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[])
2022-06-20 14:36:53 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x30E7:1:0x0b04]: async_update
2022-06-20 14:36:53 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x30E7:1:0x0b04]: Reading attributes in chunks: ['active_power', 'rms_current', 'rms_voltage']
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x30E7:1:0x0b04] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=37, command_id=<GeneralCommand.Read_Attributes: 0>, *is_reply=False)
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x30E7:1:0x0b04] Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x30E7, EmberApsFrame(profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=37), 38, b'\x00%\x00\x0b\x05\x08\x05\x05\x05')
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000401040001010001000084e0d4ed7fffff0518230b020002'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=132), 224, -44, 0x7fed, 255, 255, b'\x18#\x0b\x02\x00']
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x18#\x0b\x02\x00'
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=35, command_id=11, *is_reply=True)
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received command 0x0B (TSN 35): Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0024'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00e7300401040b01014001000024260000'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 12519, EmberApsFrame(profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=36), 38, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000401040b0101400100005ae0d4e730ffff151825010b050029000008050021000005050021f000'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=90), 224, -44, 0x30e7, 255, 255, b'\x18%\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xf0\x00']
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x30E7:1:0x0b04] Received ZCL frame: b'\x18%\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xf0\x00'
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x30E7:1:0x0b04] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=37, command_id=1, *is_reply=True)
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zcl] [0x30E7:1:0x0b04] Decoded ZCL frame: TuyaZBElectricalMeasurement:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=240))])
2022-06-20 14:36:53 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tz3000_gjnozsaz_ts011f_37143d29_electrical_measurement_rms_voltage, old_state=<state sensor.tz3000_gjnozsaz_ts011f_37143d29_electrical_measurement_rms_voltage=238; state_class=measurement, unit_of_measurement=V, device_class=current, friendly_name=_TZ3000_gjnozsaz TS011F 37143d29 electrical_measurement rms_voltage @ 2022-06-20T14:35:53.081931+02:00>, new_state=<state sensor.tz3000_gjnozsaz_ts011f_37143d29_electrical_measurement_rms_voltage=240; state_class=measurement, unit_of_measurement=V, device_class=current, friendly_name=_TZ3000_gjnozsaz TS011F 37143d29 electrical_measurement rms_voltage @ 2022-06-20T14:36:53.301981+02:00>>
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000085e0d4ed7fffff0336000002'
2022-06-20 14:36:53 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=133), 224, -44, 0x7fed, 255, 255, b'6\x00\x00']
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:36:53 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:36:54 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBFE0](TS0201): Device seen - marking the device available and resetting counter
2022-06-20 14:36:54 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBFE0](TS0201): Update device availability -  device available: True - new availability: True - changed: False
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000087e0d4ed7fffff0337000002'
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=135), 224, -44, 0x7fed, 255, 255, b'7\x00\x00']
2022-06-20 14:36:58 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:36:58 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'420055003401370004000000050005001800100004000200030001000000000002000100000000000000000000000000000000000a0000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 170 (getValue) received: b'0001f2'
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 242
2022-06-20 14:36:58 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 66, MAC_TX_BROADCAST = 85, MAC_RX_UNICAST = 308, MAC_TX_UNICAST_SUCCESS = 55, MAC_TX_UNICAST_RETRY = 4, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 5, APS_DATA_TX_BROADCAST = 5, APS_DATA_RX_UNICAST = 24, APS_DATA_TX_UNICAST_SUCCESS = 16, APS_DATA_TX_UNICAST_RETRY = 4, APS_DATA_TX_UNICAST_FAILED = 2, ROUTE_DISCOVERY_INITIATED = 3, NEIGHBOR_ADDED = 1, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 2, CHILD_REMOVED = 1, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 10, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-06-20 14:37:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000089e4d5ed7fffff0338000002'
2022-06-20 14:37:03 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=137), 228, -43, 0x7fed, 255, 255, b'8\x00\x00']
2022-06-20 14:37:03 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:37:03 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating Devices ...
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 10971 0189968
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11795 0551968
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11795 1038488
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11959 0075424
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11959 0076432
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11795 0551240
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11795 1034008
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11795 0536088
2022-06-20 14:37:04 INFO (SyncWorker_0) [pyfritzhome.fritzhome] Updating already existing Device 11959 0173312
2022-06-20 14:37:06 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2ADE](MS01): Device seen - marking the device available and resetting counter
2022-06-20 14:37:06 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2ADE](MS01): Update device availability -  device available: True - new availability: True - changed: False
2022-06-20 14:37:08 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00000002000000400100008b30a8ed7fffff0339000002'
2022-06-20 14:37:08 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=139), 48, -88, 0x7fed, 255, 255, b'9\x00\x00']
2022-06-20 14:37:08 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:37:08 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-06-20 14:37:08 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2022-06-20 14:37:09 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'4200560083013f0004000000050005001a0010000400020003000100000000000200010000000000000000000000000000000000100000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:37:09 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:37:09 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 170 (getValue) received: b'0001f2'
2022-06-20 14:37:09 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 242
2022-06-20 14:37:09 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 66, MAC_TX_BROADCAST = 86, MAC_RX_UNICAST = 387, MAC_TX_UNICAST_SUCCESS = 63, MAC_TX_UNICAST_RETRY = 4, MAC_TX_UNICAST_FAILED = 0, APS_DATA_RX_BROADCAST = 5, APS_DATA_TX_BROADCAST = 5, APS_DATA_RX_UNICAST = 26, APS_DATA_TX_UNICAST_SUCCESS = 16, APS_DATA_TX_UNICAST_RETRY = 4, APS_DATA_TX_UNICAST_FAILED = 2, ROUTE_DISCOVERY_INITIATED = 3, NEIGHBOR_ADDED = 1, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 2, CHILD_REMOVED = 1, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 16, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 0, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 242]
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_b_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_received=2450638527; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B received @ 2022-06-20T14:36:40.068728+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_received=2453704278; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B received @ 2022-06-20T14:37:10.073761+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_b_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_sent=140340923; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B sent @ 2022-06-20T14:36:40.070505+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_b_sent=140528637; unit_of_measurement=B, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 B sent @ 2022-06-20T14:37:10.075151+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_received=1854173; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets received @ 2022-06-20T14:36:40.071631+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_received=1856682; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets received @ 2022-06-20T14:37:10.076272+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent=938574; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:40.072713+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_sent=939928; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets sent @ 2022-06-20T14:37:10.077393+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received=2.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:40.074001+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_received=99.8; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:37:10.078601+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent=0.9; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:40.079555+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_kib_s_sent=6.1; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:37:10.085157+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received=6.3; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:40.080926+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_received=83.6; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s received @ 2022-06-20T14:37:10.086499+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent, old_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent=5.5; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:40.082126+02:00>, new_state=<state sensor.internetgatewaydevicev2_fritz_box_7530_packets_s_sent=45.1; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=InternetGatewayDeviceV2 - FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:37:10.087756+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_b_received, old_state=<state sensor.fritz_box_7530_b_received=2450638527; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B received @ 2022-06-20T14:36:40.112800+02:00>, new_state=<state sensor.fritz_box_7530_b_received=2453704278; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B received @ 2022-06-20T14:37:10.123592+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_b_sent, old_state=<state sensor.fritz_box_7530_b_sent=140340923; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B sent @ 2022-06-20T14:36:40.114237+02:00>, new_state=<state sensor.fritz_box_7530_b_sent=140528637; unit_of_measurement=B, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 B sent @ 2022-06-20T14:37:10.125187+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_received, old_state=<state sensor.fritz_box_7530_packets_received=1854173; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets received @ 2022-06-20T14:36:40.115423+02:00>, new_state=<state sensor.fritz_box_7530_packets_received=1856682; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets received @ 2022-06-20T14:37:10.126500+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_sent, old_state=<state sensor.fritz_box_7530_packets_sent=938574; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets sent @ 2022-06-20T14:36:40.116786+02:00>, new_state=<state sensor.fritz_box_7530_packets_sent=939928; unit_of_measurement=packets, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets sent @ 2022-06-20T14:37:10.127808+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_kib_s_received, old_state=<state sensor.fritz_box_7530_kib_s_received=2.7; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:36:40.126392+02:00>, new_state=<state sensor.fritz_box_7530_kib_s_received=99.8; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s received @ 2022-06-20T14:37:10.129518+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_kib_s_sent, old_state=<state sensor.fritz_box_7530_kib_s_sent=0.9; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:36:40.127958+02:00>, new_state=<state sensor.fritz_box_7530_kib_s_sent=6.1; unit_of_measurement=KiB/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 KiB/s sent @ 2022-06-20T14:37:10.144428+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_s_received, old_state=<state sensor.fritz_box_7530_packets_s_received=6.3; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s received @ 2022-06-20T14:36:40.129418+02:00>, new_state=<state sensor.fritz_box_7530_packets_s_received=83.6; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s received @ 2022-06-20T14:37:10.145952+02:00>>
2022-06-20 14:37:10 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.fritz_box_7530_packets_s_sent, old_state=<state sensor.fritz_box_7530_packets_s_sent=5.5; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:36:40.130754+02:00>, new_state=<state sensor.fritz_box_7530_packets_s_sent=45.1; unit_of_measurement=packets/s, icon=mdi:server-network, friendly_name=FRITZ!Box 7530 packets/s sent @ 2022-06-20T14:37:10.147406+02:00>>
2022-06-20 14:37:13 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0100ed7f2f1111ea4a38c1a404'
2022-06-20 14:37:13 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.false: 0>, 0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2022-06-20 14:37:13 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'ed7f2f1111ea4a38c1a40203ffff'
2022-06-20 14:37:13 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberDeviceUpdate.DEVICE_LEFT: 2>, <EmberJoinDecision.NO_ACTION: 3>, 0xffff]
2022-06-20 14:37:13 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) left the network
2022-06-20 14:37:13 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Update device availability -  device available: True - new availability: False - changed: True
2022-06-20 14:37:13 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Device availability changed and device became unavailable
2022-06-20 14:37:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=a4:c1:38:4a:ea:11:11:2f, unique_id=a4:c1:38:4a:ea:11:11:2f, device_id=4a2865a9419105f14f181082bdc80c34, device_event_type=device_offline>
2022-06-20 14:37:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off, old_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=off; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], off_brightness=None, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:36:52.469391+02:00>, new_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=unavailable; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:37:13.678664+02:00>>
2022-06-20 14:37:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power, old_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unknown; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:36:52.471687+02:00>, new_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:37:13.680267+02:00>>
2022-06-20 14:37:14 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x30E7](TS011F): Device seen - marking the device available and resetting counter
2022-06-20 14:37:14 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x30E7](TS011F): Update device availability -  device available: True - new availability: True - changed: False
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0101ed7f2f1111ea4a38c1a404'
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.true: 1>, 0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'ed7f2f1111ea4a38c1a401000000'
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x7fed, a4:c1:38:4a:ea:11:11:2f, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2022-06-20 14:37:17 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) joined the network
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:37:17 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=39, command_id=2, *is_reply=False)
2022-06-20 14:37:17 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request: get_membership(groups=[])
2022-06-20 14:37:17 DEBUG (MainThread) [zigpy.device] [0x7fed] Extending timeout for 0x27 request
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for a4:c1:38:4a:ea:11:11:2f/0x7fed
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:37:17 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7FED, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=39), 40, b"\x01'\x02\x00")
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'002b'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'04000013000000000000005a84bded7fffff0c3aed7f2f1111ea4a38c1a48002'
2022-06-20 14:37:18 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_NONE: 0>, groupId=0, sequence=90), 132, -67, 0x7fed, 255, 255, b':\xed\x7f/\x11\x11\xeaJ8\xc1\xa4\x80']
2022-06-20 14:37:18 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x7fed, a4:c1:38:4a:ea:11:11:2f
2022-06-20 14:37:18 INFO (MainThread) [zigpy.application] Device 0x7fed (a4:c1:38:4a:ea:11:11:2f) joined the network
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.device] [0x7fed] Cancelling old group rescan
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Update device availability -  device available: False - new availability: True - changed: True
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): Device availability changed and device became available, reinitializing channels
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Device_annce: [0x7FED, a4:c1:38:4a:ea:11:11:2f, 128]
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=41, command_id=2, *is_reply=False)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Sending request: get_membership(groups=[])
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.device] [0x7fed] Extending timeout for 0x29 request
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for a4:c1:38:4a:ea:11:11:2f/0x7fed
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (a4:c1:38:4a:ea:11:11:2f, True)
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): started initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:ZDO](TS0601): 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: initializing uncached channel attributes: ['battery_voltage', 'battery_percentage_remaining'] - from cache[False]
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Performing channel specific initialization: ['battery_voltage', 'battery_percentage_remaining']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: Reading attributes in chunks: ['battery_size', 'battery_quantity']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing channel: from_cache: False
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: Reading attributes in chunks: ['current_level']
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: finished channel initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0006]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0000]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0001]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:1:0x0019]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7FED:2:0x0008]: 'async_initialize' stage succeeded
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): power source: Battery or Unknown
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7FED](TS0601): completed initialization
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off, old_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=unavailable; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:37:13.678664+02:00>, new_state=<state light.tze200_sh1btabb_ts0601_2f1111ea_level_on_off=off; supported_color_modes=[<ColorMode.BRIGHTNESS: 'brightness'>], off_brightness=None, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea level, on_off, supported_features=33 @ 2022-06-20T14:37:18.182021+02:00>>
2022-06-20 14:37:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.tze200_sh1btabb_ts0601_2f1111ea_power, old_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unavailable; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:37:13.680267+02:00>, new_state=<state sensor.tze200_sh1btabb_ts0601_2f1111ea_power=unknown; state_class=measurement, unit_of_measurement=%, device_class=battery, friendly_name=_TZE200_sh1btabb TS0601 2f1111ea power @ 2022-06-20T14:37:18.183561+02:00>>
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ed7f040104000101400100002b280000'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 32749, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=43), 40, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 40
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040104000101000100005b84bded7fffff05192702100002'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=91), 132, -67, 0x7fed, 255, 255, b"\x19'\x02\x10\x00"]
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b"\x19'\x02\x10\x00"
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=39, command_id=2, *is_reply=True)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[])
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received command 0x02 (TSN 39): get_membership_response(capacity=16, groups=[])
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] No explicit handler for cluster command 0x02: get_membership_response(capacity=16, groups=[])
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040104000101000100005c84bded7fffff0518270b020002'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=92), 132, -67, 0x7fed, 255, 255, b"\x18'\x0b\x02\x00"]
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b"\x18'\x0b\x02\x00"
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=39, command_id=11, *is_reply=True)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received command 0x0B (TSN 39): Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x7FED, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=41), 42, b'\x01)\x02\x00')
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'002c'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00ed7f040104000101400100002c2a0000'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 32749, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=44), 42, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040104000101000100005d84bded7fffff05192902100002'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=93), 132, -67, 0x7fed, 255, 255, b'\x19)\x02\x10\x00']
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x19)\x02\x10\x00'
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=41, command_id=2, *is_reply=True)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[])
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040104000101000100005e84bded7fffff0518290b020002'
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=94), 132, -67, 0x7fed, 255, 255, b'\x18)\x0b\x02\x00']
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Received ZCL frame: b'\x18)\x0b\x02\x00'
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=41, command_id=11, *is_reply=True)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.zcl] [0x7FED:1:0x0004] Decoded ZCL frame: Groups:Default_Response(command_id=2, status=<Status.SUCCESS: 0>)
2022-06-20 14:37:18 DEBUG (MainThread) [zigpy.device] [0x7fed] Invalid state on future for 0x29 seq -- probably duplicate response
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff000013000000000000005a000000'
2022-06-20 14:37:18 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_NONE: 0>, groupId=0, sequence=90), 0, <EmberStatus.SUCCESS: 0>, b'']
2022-06-20 14:37:18 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2022-06-20 14:37:19 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2022-06-20 14:37:19 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'44005800b801460004000000060006001e0012000400020003000100000000000300020000000000000000000000000000000000100000000000000000000000000000000000000000000000000000000000'
2022-06-20 14:37:19 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-06-20 14:37:19 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00000002000000400100005f84bded7fffff033b000002'
2022-06-20 14:37:19 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=95), 132, -67, 0x7fed, 255, 255, b';\x00\x00']
2022-06-20 14:37:19 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-06-20 14:37:19 DEBUG (MainThread) [zigpy.zdo] [0x7fed:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])