search

zigpy / zha-device-handlers

ZHA device handlers bridge the functionality gap created when manufacturers deviate from the ZCL specification, handling deviations and exceptions by parsing custom messages to and from Zigbee devices.
Apache License 2.0
777 stars 703 forks source link

[BUG] Smartenergy cluster: Instantaneous demand and Summation delivered error in log #2165

Closed CSRLabs closed 1 year ago

CSRLabs commented 1 year ago

Describe the bug Home Assistant core 2023.2.1 - Python 3.10.9 Using a DIY device based on PTVO firmware with a custom quirk I get the following error in the log:

2023-02-03 22:02:51.579 WARNING (MainThread) [homeassistant.components.sensor] Entity sensor.csrlabs_pzem004t_instantaneous_demand (<class 'homeassistant.components.zha.sensor.SmartEnergyMetering'>) is using native unit of measurement 'None' which is not a valid unit for the device class ('power') it is using; expected one of ['W', 'kW']; Please update your configuration if your entity is manually configured, otherwise create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+zha%22
2023-02-03 22:02:51.587 WARNING (MainThread) [homeassistant.components.sensor] Entity sensor.csrlabs_pzem004t_summation_delivered (<class 'homeassistant.components.zha.sensor.SmartEnergySummation'>) is using native unit of measurement 'None' which is not a valid unit for the device class ('energy') it is using; expected one of ['MJ', 'GJ', 'kWh', 'MWh', 'Wh']; Please update your configuration if your entity is manually configured, otherwise create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+zha%22

And the correspondent entities are missing the unit of measurement

quirk

This is the relevant code in the quirk

class SmartEnergyCluster(LocalDataCluster, Metering):

    cluster_id = Metering.cluster_id
    CURRENT_SUMM_DELIVERED_VALUE_ID = 0x0000
    INSTANTANEOUS_DEMAND_VALUE_ID = 0x0400

    POWER_WATT = 0x0000

    """Setting unit of measurement."""
    _CONSTANT_ATTRIBUTES = {0x0300: POWER_WATT}

    def __init__(self, *args, **kwargs):
        """Init."""
        super().__init__(*args, **kwargs)
        self.endpoint.device.energy_bus.add_listener(self)

    def energy_reported(self, value):
        """Energy reported."""
        self._update_attribute(self.CURRENT_SUMM_DELIVERED_VALUE_ID, value)

    def instantaneous_demand(self, value):
        """Instantaneous power demand reported."""
        self._update_attribute(self.INSTANTANEOUS_DEMAND_VALUE_ID, value)

The device was working fine before the upgrade.

Any idea on how to fix this or adjust the quirk code is welcome

javicalle commented 1 year ago

Not sure if can be related to the summation_formatting/demand_formatting or the multiplier/divisor attributes: https://github.com/home-assistant/core/blob/fc38b4327f0ce153ac757492959eba9aefbcbc1a/homeassistant/components/zha/sensor.py#L483-L490

I would try to set values to check.

CSRLabs commented 1 year ago

I inserted this code in the quirk to set multiplier and divisor

_CONSTANT_ATTRIBUTES = {
        0x0300: 0,  # unit_of_measure: kWh
        0x0301: 1,  # multiplier
        0x0302: 1000,  # divisor
        0x0303: 0b0_0100_011,  # summation_formatting (read from plug)
        0x0306: 0,  # metering_device_type: electri
}

I deleted and re-paired the device, but it seems it doesn't help as I'm now getting these errors:

2023-02-04 10:46:39.569 ERROR (MainThread) [homeassistant.util.logging] Exception in async_set_state when dispatching '00:12:4b:00:25:9c:36:80:1:0x0702_attribute_updated': (0, 'current_summ_delivered', 0.001)
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 177, in async_set_state
    self.async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 566, in async_write_ha_state
    self._async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 607, in _async_write_ha_state
    state = self._stringify_state(available)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 572, in _stringify_state
    if (state := self.state) is None:
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/sensor/__init__.py", line 466, in state
    value = self.native_value
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 172, in native_value
    return self.formatter(raw_state)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 486, in formatter
    return self._channel.summa_formatter(value)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/core/channels/smartenergy.py", line 243, in _formatter_function
    assert self._summa_format
AssertionError

2023-02-04 10:46:39.625 ERROR (MainThread) [homeassistant.util.logging] Exception in async_set_state when dispatching '00:12:4b:00:25:9c:36:80:1:0x0702_attribute_updated': (1024, 'instantaneous_demand', 0.0)
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 177, in async_set_state
    self.async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 566, in async_write_ha_state
    self._async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 607, in _async_write_ha_state
    state = self._stringify_state(available)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 572, in _stringify_state
    if (state := self.state) is None:
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/sensor/__init__.py", line 466, in state
    value = self.native_value
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 172, in native_value
    return self.formatter(raw_state)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 437, in formatter
    return self._channel.demand_formatter(value)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/core/channels/smartenergy.py", line 245, in _formatter_function
    assert self._format_spec
AssertionError
javicalle commented 1 year ago

Could you test just removing the summation_formatting? I will try to check latter.

CSRLabs commented 1 year ago

@javicalle done, deleted and re-paired device. Now the quirk looks like this:

_CONSTANT_ATTRIBUTES = {
        0x0300: 0,  # unit_of_measure: kWh
        0x0301: 1,  # multiplier
        0x0302: 1000,  # divisor
        0x0306: 0,  # metering_device_type: electric
}

but I still get the same errors and no unit of measurement.

javicalle commented 1 year ago

Ummmm, have you deleted the __pycache__ folder inside the custom quirks folder? You shouldn't get any errors because of the summation_formatting. Be sure to delete it, restart HA and repair.

CSRLabs commented 1 year ago

Deleted __pycache__ restarted HA deleted device, re-paired, same error as above.

TheJulianJES commented 1 year ago

Can you provide the diagnostic information for the device (after a re-pair with the custom quirks)?

CSRLabs commented 1 year ago

This is the log with device pairing:

2023-02-04 18:23:50.184 INFO (MainThread) [zigpy_znp.zigbee.application] Permitting joins for 254 seconds
2023-02-04 18:23:50.187 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=6, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, data=Serialized[b'\x06\xfe\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:23:50.194 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=254, TCSignificance=0)
2023-02-04 18:23:50.205 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:23:50.209 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2023-02-04 18:23:50.213 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=6, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x06\xFE\x00')
2023-02-04 18:23:50.220 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2023-02-04 18:23:50.224 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=32822, data=Serialized[b'\x03\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:23:50.226 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2023-02-04 18:23:50.227 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2023-02-04 18:23:50.239 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:23:57.685 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.TCDevInd.Callback(SrcNwk=0x3FBB, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:23:57.688 INFO (MainThread) [zigpy_znp.zigbee.application] TC device join: ZDO.TCDevInd.Callback(SrcNwk=0x3FBB, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:23:57.691 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x3FBB, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2023-02-04 18:23:57.699 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:01.241 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-02-04 18:24:01.249 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-02-04 18:24:02.690 INFO (MainThread) [zigpy.application] New device 0x3fbb (00:12:4b:00:25:9c:36:80) joined the network
2023-02-04 18:24:02.692 DEBUG (MainThread) [zigpy.device] [0x3fbb] Scheduling initialization
2023-02-04 18:24:02.696 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:02.697 INFO (MainThread) [zigpy.device] [0x3fbb] Requesting 'Node Descriptor'
2023-02-04 18:24:02.698 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2023-02-04 18:24:02.699 DEBUG (MainThread) [zigpy.device] [0x3fbb] Extending timeout for 0x07 request
2023-02-04 18:24:02.699 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x3FBB), dst_ep=0, source_route=None, extended_timeout=True, tsn=7, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x07\xbb?'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:02.702 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x3FBB, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:02.715 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.FAIL: 1>)
2023-02-04 18:24:02.720 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x3FBB, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2023-02-04 18:24:02.733 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:04.037 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x3FBB), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=7, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x07\xBB\x3F')
2023-02-04 18:24:04.045 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:18.783 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.TCDevInd.Callback(SrcNwk=0x352B, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:24:18.784 INFO (MainThread) [zigpy_znp.zigbee.application] TC device join: ZDO.TCDevInd.Callback(SrcNwk=0x352B, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:24:18.785 INFO (MainThread) [zigpy.application] Device 0x352b (00:12:4b:00:25:9c:36:80) joined the network
2023-02-04 18:24:18.785 DEBUG (MainThread) [zigpy.application] Device 00:12:4b:00:25:9c:36:80 changed id (0x3fbb => 0x352b)
2023-02-04 18:24:18.787 DEBUG (MainThread) [zigpy.device] [0x352b] Scheduling initialization
2023-02-04 18:24:18.787 DEBUG (MainThread) [zigpy.device] [0x352b] Canceling old initialize call
2023-02-04 18:24:18.789 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:18.790 INFO (MainThread) [zigpy.device] [0x352b] Requesting 'Node Descriptor'
2023-02-04 18:24:18.791 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2023-02-04 18:24:18.791 DEBUG (MainThread) [zigpy.device] [0x352b] Extending timeout for 0x08 request
2023-02-04 18:24:18.792 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x352B), dst_ep=0, source_route=None, extended_timeout=True, tsn=8, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x08+5'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:18.794 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x352B, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:18.804 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:18.807 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x352B, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2023-02-04 18:24:18.813 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:18.814 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x352B), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=8, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x08\x2B\x35')
2023-02-04 18:24:18.829 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:31.255 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-02-04 18:24:31.261 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-02-04 18:24:33.364 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.TCDevInd.Callback(SrcNwk=0x315E, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:24:33.365 INFO (MainThread) [zigpy_znp.zigbee.application] TC device join: ZDO.TCDevInd.Callback(SrcNwk=0x315E, SrcIEEE=00:12:4b:00:25:9c:36:80, ParentNwk=0x0000)
2023-02-04 18:24:33.365 INFO (MainThread) [zigpy.application] Device 0x315e (00:12:4b:00:25:9c:36:80) joined the network
2023-02-04 18:24:33.366 DEBUG (MainThread) [zigpy.application] Device 00:12:4b:00:25:9c:36:80 changed id (0x352b => 0x315e)
2023-02-04 18:24:33.367 DEBUG (MainThread) [zigpy.device] [0x315e] Scheduling initialization
2023-02-04 18:24:33.368 DEBUG (MainThread) [zigpy.device] [0x315e] Canceling old initialize call
2023-02-04 18:24:33.370 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.371 INFO (MainThread) [zigpy.device] [0x315e] Requesting 'Node Descriptor'
2023-02-04 18:24:33.372 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2023-02-04 18:24:33.372 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x09 request
2023-02-04 18:24:33.373 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=9, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\t^1'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.376 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.387 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.391 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x315E, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2023-02-04 18:24:33.396 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.398 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=9, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x09\x5E\x31')
2023-02-04 18:24:33.431 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.580 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, NodeDescriptor=NullableNodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle: 136>, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11264, maximum_outgoing_transfer_size=160, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=False, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False))
2023-02-04 18:24:33.583 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.586 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32770, SecurityUse=0, TSN=9, MacDst=0x0000, Data=b'\x00\x5E\x31\x02\x40\x88\x00\x00\x50\xA0\x00\x00\x2C\xA0\x00\x00')
2023-02-04 18:24:33.587 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0x315E, NWK=0x315E, IEEE=00:12:4b:00:25:9c:36:80, Capabilities=<MACCapabilities.AllocateShortAddrDuringAssocNeeded|RXWhenIdle: 136>)
2023-02-04 18:24:33.591 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.592 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.true: 1>, ClusterId=19, SecurityUse=0, TSN=0, MacDst=0x0000, Data=b'\x5E\x31\x80\x36\x9C\x25\x00\x4B\x12\x00\x88')
2023-02-04 18:24:33.595 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=9, profile_id=0, cluster_id=32770, data=Serialized[b'\t\x00^1\x02@\x88\x00\x00P\xa0\x00\x00,\xa0\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.598 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32770: b'\t\x00^1\x02@\x88\x00\x00P\xa0\x00\x00,\xa0\x00\x00'
2023-02-04 18:24:33.601 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=0, profile_id=0, cluster_id=19, data=Serialized[b'\x00^1\x806\x9c%\x00K\x12\x00\x88'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.602 INFO (MainThread) [zigpy.application] Device 0x315e (00:12:4b:00:25:9c:36:80) joined the network
2023-02-04 18:24:33.603 DEBUG (MainThread) [zigpy.device] [0x315e] Scheduling initialization
2023-02-04 18:24:33.604 DEBUG (MainThread) [zigpy.device] [0x315e] Canceling old initialize call
2023-02-04 18:24:33.605 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 19: b'\x00^1\x806\x9c%\x00K\x12\x00\x88'
2023-02-04 18:24:33.606 DEBUG (MainThread) [zigpy.zdo] [0x315e:zdo] ZDO request ZDOCmd.Device_annce: [0x315E, 00:12:4b:00:25:9c:36:80, 136]
2023-02-04 18:24:33.607 INFO (MainThread) [zigpy.device] [0x315e] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle: 136>, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11264, maximum_outgoing_transfer_size=160, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=False, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)
2023-02-04 18:24:33.609 INFO (MainThread) [zigpy.device] [0x315e] Discovering endpoints
2023-02-04 18:24:33.610 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.611 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0a request
2023-02-04 18:24:33.612 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=10, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\n^1'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.613 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.615 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.615 INFO (MainThread) [zigpy.device] [0x315e] Discovering endpoints
2023-02-04 18:24:33.616 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.616 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0b request
2023-02-04 18:24:33.617 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=11, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\x0b^1'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.651 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.654 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.659 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.661 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=5, TSN=10, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0A\x5E\x31')
2023-02-04 18:24:33.695 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.697 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=5, TSN=11, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0B\x5E\x31')
2023-02-04 18:24:33.745 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.748 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ActiveEpRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, ActiveEndpoints=[1, 2, 3])
2023-02-04 18:24:33.750 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.751 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ActiveEpRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, ActiveEndpoints=[1, 2, 3])
2023-02-04 18:24:33.751 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.752 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32773, SecurityUse=0, TSN=10, MacDst=0x0000, Data=b'\x00\x5E\x31\x03\x01\x02\x03')
2023-02-04 18:24:33.753 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=10, profile_id=0, cluster_id=32773, data=Serialized[b'\n\x00^1\x03\x01\x02\x03'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.754 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32773: b'\n\x00^1\x03\x01\x02\x03'
2023-02-04 18:24:33.756 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32773, SecurityUse=0, TSN=11, MacDst=0x0000, Data=b'\x00\x5E\x31\x03\x01\x02\x03')
2023-02-04 18:24:33.757 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=11, profile_id=0, cluster_id=32773, data=Serialized[b'\x0b\x00^1\x03\x01\x02\x03'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.758 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32773: b'\x0b\x00^1\x03\x01\x02\x03'
2023-02-04 18:24:33.760 INFO (MainThread) [zigpy.device] [0x315e] Discovered endpoints: [1, 2, 3]
2023-02-04 18:24:33.761 INFO (MainThread) [zigpy.device] [0x315e] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=2 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=3 in=[] out=[] status=<Status.NEW: 0>>]
2023-02-04 18:24:33.761 INFO (MainThread) [zigpy.endpoint] [0x315e:1] Discovering endpoint information
2023-02-04 18:24:33.762 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.762 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0c request
2023-02-04 18:24:33.763 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=12, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x0c^1\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.764 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.766 INFO (MainThread) [zigpy.device] [0x315e] Discovered endpoints: [1, 2, 3]
2023-02-04 18:24:33.767 INFO (MainThread) [zigpy.device] [0x315e] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=2 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=3 in=[] out=[] status=<Status.NEW: 0>>]
2023-02-04 18:24:33.768 INFO (MainThread) [zigpy.endpoint] [0x315e:1] Discovering endpoint information
2023-02-04 18:24:33.768 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.768 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0d request
2023-02-04 18:24:33.769 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=13, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\r^1\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.773 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.775 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.780 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.781 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=12, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0C\x5E\x31\x01')
2023-02-04 18:24:33.796 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.797 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=13, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0D\x5E\x31\x01')
2023-02-04 18:24:33.812 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.859 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65534, device_version=0, input_clusters=[0, 20, 7], output_clusters=[0, 18]))
2023-02-04 18:24:33.862 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.864 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65534, device_version=0, input_clusters=[0, 20, 7], output_clusters=[0, 18]))
2023-02-04 18:24:33.864 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.866 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=12, MacDst=0x0000, Data=b'\x00\x5E\x31\x12\x01\x04\x01\xFE\xFF\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00')
2023-02-04 18:24:33.868 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=12, profile_id=0, cluster_id=32772, data=Serialized[b'\x0c\x00^1\x12\x01\x04\x01\xfe\xff\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.869 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x0c\x00^1\x12\x01\x04\x01\xfe\xff\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00'
2023-02-04 18:24:33.872 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=13, MacDst=0x0000, Data=b'\x00\x5E\x31\x12\x01\x04\x01\xFE\xFF\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00')
2023-02-04 18:24:33.874 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=13, profile_id=0, cluster_id=32772, data=Serialized[b'\r\x00^1\x12\x01\x04\x01\xfe\xff\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.876 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\r\x00^1\x12\x01\x04\x01\xfe\xff\x00\x03\x00\x00\x14\x00\x07\x00\x02\x00\x00\x12\x00'
2023-02-04 18:24:33.878 INFO (MainThread) [zigpy.endpoint] [0x315e:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65534, device_version=0, input_clusters=[0, 20, 7], output_clusters=[0, 18])
2023-02-04 18:24:33.880 INFO (MainThread) [zigpy.endpoint] [0x315e:2] Discovering endpoint information
2023-02-04 18:24:33.880 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.881 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0e request
2023-02-04 18:24:33.881 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=14, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x0e^1\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.882 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.885 INFO (MainThread) [zigpy.endpoint] [0x315e:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65534, device_version=0, input_clusters=[0, 20, 7], output_clusters=[0, 18])
2023-02-04 18:24:33.887 INFO (MainThread) [zigpy.endpoint] [0x315e:2] Discovering endpoint information
2023-02-04 18:24:33.887 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:33.888 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x0f request
2023-02-04 18:24:33.888 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=15, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x0f^1\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.902 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.904 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:33.909 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:33.911 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=14, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0E\x5E\x31\x02')
2023-02-04 18:24:33.931 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.932 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=15, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x0F\x5E\x31\x02')
2023-02-04 18:24:33.981 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:33.984 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=2, profile=260, device_type=65534, device_version=0, input_clusters=[20, 12], output_clusters=[]))
2023-02-04 18:24:33.985 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.987 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=2, profile=260, device_type=65534, device_version=0, input_clusters=[20, 12], output_clusters=[]))
2023-02-04 18:24:33.987 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:33.989 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=14, MacDst=0x0000, Data=b'\x00\x5E\x31\x0C\x02\x04\x01\xFE\xFF\x00\x02\x14\x00\x0C\x00\x00')
2023-02-04 18:24:33.991 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=14, profile_id=0, cluster_id=32772, data=Serialized[b'\x0e\x00^1\x0c\x02\x04\x01\xfe\xff\x00\x02\x14\x00\x0c\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:33.993 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x0e\x00^1\x0c\x02\x04\x01\xfe\xff\x00\x02\x14\x00\x0c\x00\x00'
2023-02-04 18:24:33.995 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=15, MacDst=0x0000, Data=b'\x00\x5E\x31\x0C\x02\x04\x01\xFE\xFF\x00\x02\x14\x00\x0C\x00\x00')
2023-02-04 18:24:33.998 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=15, profile_id=0, cluster_id=32772, data=Serialized[b'\x0f\x00^1\x0c\x02\x04\x01\xfe\xff\x00\x02\x14\x00\x0c\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.000 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x0f\x00^1\x0c\x02\x04\x01\xfe\xff\x00\x02\x14\x00\x0c\x00\x00'
2023-02-04 18:24:34.002 INFO (MainThread) [zigpy.endpoint] [0x315e:2] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=2, profile=260, device_type=65534, device_version=0, input_clusters=[20, 12], output_clusters=[])
2023-02-04 18:24:34.004 INFO (MainThread) [zigpy.endpoint] [0x315e:3] Discovering endpoint information
2023-02-04 18:24:34.004 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:34.005 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x10 request
2023-02-04 18:24:34.005 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=16, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x10^1\x03'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.006 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:34.010 INFO (MainThread) [zigpy.endpoint] [0x315e:2] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=2, profile=260, device_type=65534, device_version=0, input_clusters=[20, 12], output_clusters=[])
2023-02-04 18:24:34.011 INFO (MainThread) [zigpy.endpoint] [0x315e:3] Discovering endpoint information
2023-02-04 18:24:34.012 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-02-04 18:24:34.012 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x11 request
2023-02-04 18:24:34.013 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=0, source_route=None, extended_timeout=True, tsn=17, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x11^1\x03'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.017 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:34.019 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x315E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2023-02-04 18:24:34.024 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2023-02-04 18:24:34.027 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=16, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x10\x5E\x31\x03')
2023-02-04 18:24:34.047 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:34.048 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=17, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x11\x5E\x31\x03')
2023-02-04 18:24:34.084 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:34.087 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=3, profile=260, device_type=65534, device_version=0, input_clusters=[12], output_clusters=[]))
2023-02-04 18:24:34.087 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:34.089 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=16, MacDst=0x0000, Data=b'\x00\x5E\x31\x0A\x03\x04\x01\xFE\xFF\x00\x01\x0C\x00\x00')
2023-02-04 18:24:34.091 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=16, profile_id=0, cluster_id=32772, data=Serialized[b'\x10\x00^1\n\x03\x04\x01\xfe\xff\x00\x01\x0c\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.093 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x10\x00^1\n\x03\x04\x01\xfe\xff\x00\x01\x0c\x00\x00'
2023-02-04 18:24:34.096 INFO (MainThread) [zigpy.endpoint] [0x315e:3] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=3, profile=260, device_type=65534, device_version=0, input_clusters=[12], output_clusters=[])
2023-02-04 18:24:34.099 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x12 request
2023-02-04 18:24:34.099 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=1, source_route=None, extended_timeout=True, tsn=18, profile_id=260, cluster_id=0, data=Serialized[b'\x00\x12\x00\x04\x00\x05\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.101 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=0, TSN=18, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x00\x12\x00\x04\x00\x05\x00')
2023-02-04 18:24:34.108 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x315E, Status=<Status.SUCCESS: 0>, NWK=0x315E, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=3, profile=260, device_type=65534, device_version=0, input_clusters=[12], output_clusters=[]))
2023-02-04 18:24:34.109 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-02-04 18:24:34.125 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x315E, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=17, MacDst=0x0000, Data=b'\x00\x5E\x31\x0A\x03\x04\x01\xFE\xFF\x00\x01\x0C\x00\x00')
2023-02-04 18:24:34.126 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=17, profile_id=0, cluster_id=32772, data=Serialized[b'\x11\x00^1\n\x03\x04\x01\xfe\xff\x00\x01\x0c\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.128 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x11\x00^1\n\x03\x04\x01\xfe\xff\x00\x01\x0c\x00\x00'
2023-02-04 18:24:34.130 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:34.131 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=18)
2023-02-04 18:24:34.138 INFO (MainThread) [zigpy.endpoint] [0x315e:3] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=3, profile=260, device_type=65534, device_version=0, input_clusters=[12], output_clusters=[])
2023-02-04 18:24:34.141 DEBUG (MainThread) [zigpy.device] [0x315e] Extending timeout for 0x13 request
2023-02-04 18:24:34.141 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), dst_ep=1, source_route=None, extended_timeout=True, tsn=19, profile_id=260, cluster_id=0, data=Serialized[b'\x00\x13\x00\x04\x00\x05\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-02-04 18:24:34.144 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x315E), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=0, TSN=19, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x00\x13\x00\x04\x00\x05\x00')
2023-02-04 18:24:34.150 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=0, SrcAddr=0x315E, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=4356730, TSN=0, Data=b'\x18\x12\x01\x04\x00\x00\x42\x07\x43\x53\x52\x4C\x61\x62\x73\x05\x00\x00\x42\x08\x70\x7A\x65\x6D\x30\x30\x34\x74', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:34.153 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=0, data=Serialized[b'\x18\x12\x01\x04\x00\x00B\x07CSRLabs\x05\x00\x00B\x08pzem004t'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2023-02-04 18:24:34.157 INFO (MainThread) [zigpy.device] [0x315e] Read model 'pzem004t' and manufacturer 'CSRLabs' from <Endpoint id=1 in=[basic:0x0000, multistate_value:0x0014, on_off_config:0x0007] out=[basic:0x0000, multistate_input:0x0012] status=<Status.ZDO_INIT: 1>>
2023-02-04 18:24:34.158 INFO (MainThread) [zigpy.device] [0x315e] Discovered basic device information for <Device model='pzem004t' manuf='CSRLabs' nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=True>
2023-02-04 18:24:34.158 DEBUG (MainThread) [zigpy.application] Device is initialized <Device model='pzem004t' manuf='CSRLabs' nwk=0x315E ieee=00:12:4b:00:25:9c:36:80 is_initialized=True>
2023-02-04 18:24:34.161 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for CSRLabs pzem004t (00:12:4b:00:25:9c:36:80)
2023-02-04 18:24:34.162 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'CSRLabs.pzem004t.pzem004t'>
2023-02-04 18:24:34.162 DEBUG (MainThread) [zigpy.quirks.registry] Found custom device replacement for 00:12:4b:00:25:9c:36:80: <class 'CSRLabs.pzem004t.pzem004t'>
2023-02-04 18:24:34.197 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-02-04 18:24:34.198 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=19)
2023-02-04 18:24:34.198 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=0, SrcAddr=0x315E, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=80, SecurityUse=<Bool.false: 0>, TimeStamp=4359468, TSN=0, Data=b'\x18\x13\x01\x04\x00\x00\x42\x07\x43\x53\x52\x4C\x61\x62\x73\x05\x00\x00\x42\x08\x70\x7A\x65\x6D\x30\x30\x34\x74', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:34.199 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (00:12:4b:00:25:9c:36:80, 1, 0, 4, 'CSRLabs') params: FOREIGN KEY constraint failed
2023-02-04 18:24:34.200 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=0, data=Serialized[b'\x18\x13\x01\x04\x00\x00B\x07CSRLabs\x05\x00\x00B\x08pzem004t'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=80, rssi=None)
2023-02-04 18:24:34.205 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (00:12:4b:00:25:9c:36:80, 1, 0, 5, 'pzem004t') params: FOREIGN KEY constraint failed
2023-02-04 18:24:49.081 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=12, SrcAddr=0x315E, SrcEndpoint=2, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=5286513, TSN=0, Data=b'\x18\x00\x0A\x55\x00\x39\xCD\xCC\x5C\x43\x6F\x00\x18\x00\x1C\x00\x42\x01\x56', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:49.083 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=12, data=Serialized[b'\x18\x00\nU\x009\xcd\xcc\\Co\x00\x18\x00\x1c\x00B\x01V'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2023-02-04 18:24:49.097 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=12, SrcAddr=0x315E, SrcEndpoint=2, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=5286829, TSN=0, Data=b'\x18\x01\x0A\x55\x00\x39\x00\x00\x00\x00\x6F\x00\x18\x00\x1C\x00\x42\x01\x41', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:49.099 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=12, SrcAddr=0x315E, SrcEndpoint=2, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=5287184, TSN=0, Data=b'\x18\x02\x0A\x55\x00\x39\x00\x00\x80\x3F\x6F\x00\x18\x00\x1C\x00\x42\x02\x57\x68', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:49.101 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=12, SrcAddr=0x315E, SrcEndpoint=2, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=5287796, TSN=0, Data=b'\x18\x03\x0A\x55\x00\x39\x00\x00\x00\x00\x6F\x00\x18\x00\x1C\x00\x42\x01\x57', MacSrcAddr=0x315E, MsgResultRadius=29)
2023-02-04 18:24:49.105 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=12, data=Serialized[b'\x18\x01\nU\x009\x00\x00\x00\x00o\x00\x18\x00\x1c\x00B\x01A'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2023-02-04 18:24:49.117 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=12, data=Serialized[b'\x18\x02\nU\x009\x00\x00\x80?o\x00\x18\x00\x1c\x00B\x02Wh'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2023-02-04 18:24:49.136 ERROR (MainThread) [homeassistant.util.logging] Exception in async_set_state when dispatching '00:12:4b:00:25:9c:36:80:1:0x0702_attribute_updated': (0, 'current_summ_delivered', 0.001)
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 177, in async_set_state
    self.async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 566, in async_write_ha_state
    self._async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 607, in _async_write_ha_state
    state = self._stringify_state(available)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 572, in _stringify_state
    if (state := self.state) is None:
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/sensor/__init__.py", line 466, in state
    value = self.native_value
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 172, in native_value
    return self.formatter(raw_state)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 486, in formatter
    return self._channel.summa_formatter(value)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/core/channels/smartenergy.py", line 243, in _formatter_function
    assert self._summa_format
AssertionError

2023-02-04 18:24:49.154 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x315E), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=12, data=Serialized[b'\x18\x03\nU\x009\x00\x00\x00\x00o\x00\x18\x00\x1c\x00B\x01W'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2023-02-04 18:24:49.167 ERROR (MainThread) [homeassistant.util.logging] Exception in async_set_state when dispatching '00:12:4b:00:25:9c:36:80:1:0x0702_attribute_updated': (1024, 'instantaneous_demand', 0.0)
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 177, in async_set_state
    self.async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 566, in async_write_ha_state
    self._async_write_ha_state()
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 607, in _async_write_ha_state
    state = self._stringify_state(available)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/helpers/entity.py", line 572, in _stringify_state
    if (state := self.state) is None:
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/sensor/__init__.py", line 466, in state
    value = self.native_value
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 172, in native_value
    return self.formatter(raw_state)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/sensor.py", line 437, in formatter
    return self._channel.demand_formatter(value)
  File "/srv/homeassistant/lib/python3.10/site-packages/homeassistant/components/zha/core/channels/smartenergy.py", line 245, in _formatter_function
    assert self._format_spec
AssertionError

The first time the device is seen by HA the two entities with errors appear as unknown as you can see below:

quirk

Following HA restart the two entities are OK but with no unit of measurement and in the log I see two entries complaining for unit of measurement 'None'

CSRLabs commented 1 year ago

Here is the quick I'm currently testing

PZEM-004T

TheJulianJES commented 1 year ago

Can you provide the diagnostic information txt file? It can be downloaded on the device page under the three dots -> download diagnostic information.

CSRLabs commented 1 year ago

Here is the file

zha-536e57d62c4c1ef339dbddd9d9b8ce02-CSRLabs pzem004t-062b94e387c1e11ee615e8d55bc5421e.json.txt

TheJulianJES commented 1 year ago

Can you add back 0x0303: 0b0_0100_011, # summation_formatting, then restart HA after you've changed the quirk, remove the device and wait a minute or so before adding it back (re-pairing alone is not enough). Then send the logs here if it still errors out (and a new diagnostic file). Also, try to read that summation_formatting attribute through the UI. It's under the three dots -> Manage Zigbee device -> Clusters. Then post a screenshot of what it returns (and try to restart HA again after having read the attribute (which caches it)).

Also, make sure you check the type of attributers you're setting in the LocalDataCluster. For example, rms_voltage needs to be an integer. So you need to round() it first. See https://github.com/zigpy/zha-device-handlers/pull/2041 for reference.

Btw., I don't think you need to use Bus anymore. You should be able to just do something like this:

self.endpoint.smartenergy_metering.update_attribute(Metering.attributes_by_name["current_summ_delivered"], value)

(You'd still need the LocalDataClusters, but nothing with bus stuff)

You can find all names here: https://github.com/zigpy/zigpy/blob/dev/zigpy/zcl/clusters/measurement.py, https://github.com/zigpy/zigpy/blob/dev/zigpy/zcl/clusters/smartenergy.py, https://github.com/zigpy/zigpy/blob/dev/zigpy/zcl/clusters/homeautomation.py (and maybe in other files in the clusters folder)

CSRLabs commented 1 year ago

@TheJulianJES thanks for taking care of this. Adding back 0x0303: 0b0_0100_011, # summation_formatting did not change anything, still the same behavior. I will take some time to study your third line advice and possibly change my quirk accordingly. BTW, it would be of great help if you could point me to an example quirk (a similar energy monitor device or so) that proved to work properly with the latest version of HA

CSRLabs commented 1 year ago

@TheJulianJES reading the values from "Manage Zigbee Device" seemed to fix the unit of measurement issue, see the screenshot below:

summation_formatting unit summation_delivered

So that means that the user always needs to do this manual action to make the device working? Is there any way to complete the device pairing from inside the quirk without needing any extra action from the UI?

TheJulianJES commented 1 year ago

These values are read automatically on pairing. How did you remove the device from ZHA before re-pairing it?

CSRLabs commented 1 year ago

I went on devices and then clicked on the red bin "Remove"

remove

Then restarted HA, cliked Add Device and powered on my device, and it paired.

CSRLabs commented 1 year ago

I eventually found a way to fix this, I'm not sure whether this is actually the right way, but it works for me. In the quirk I added this code to force attribute update for constant attributes, when the MeteringCluster class gets initialized

def __init__(self, *args, **kwargs):
        """Init."""
        super().__init__(*args, **kwargs)
        self.endpoint.device.consumption_bus.add_listener(self)

        # initialize constant attributes
        self._update_attribute(self.UNIT_OF_MEASUREMENT, 0)
        self._update_attribute(self.MULTIPLIER, 1)
        self._update_attribute(self.DIVISOR, 1000)
        self._update_attribute(self.SUMMATION_FORMATTING, 0b0_0100_011)
        self._update_attribute(self.METERING_DEVICE_TYPE, 0)

To simulate a "fresh pairing" and get rid of all device traces I followed these steps

deleted .homeassistant profile started HA reinstalled ZigBee integration choosing to erase network settings and create a new network re-paired device

The device pairs nicely, and all entities are available from the beginning without any additional manual action. No errors in the log.

quirk

I see also that it is still not possible to choose the precision (decimal digits) for voltage and current (at least I did not find a way) so my quirk still has a class patching to achieve this. I know it's a dirty way to do it but it works for now.

from homeassistant.components.zha.sensor import ElectricalMeasurement as EM

def myformatter(self, value: int) -> int | float:
    """Return 'normalized' value."""
    multiplier = getattr(self._channel, f"{self._div_mul_prefix}_multiplier")
    divisor = getattr(self._channel, f"{self._div_mul_prefix}_divisor")
    value = float(value * multiplier) / divisor
    return round(value, self._decimals)

EM.formatter = myformatter

quirk here

https://github.com/CSRLabs/PZEM-004T

TheJulianJES commented 1 year ago

I eventually found a way to fix this, I'm not sure whether this is actually the right way

It's not. Like mentioned, the attributes are read when initially pairing the device: https://github.com/home-assistant/core/blob/04e05af44cbea2156d904d0d34e4e0d41c9725c1/homeassistant/components/zha/core/channels/smartenergy.py#L91-L98 It's likely that the device wasn't correctly removed (from zigbee.db) yet. Wait a minute or so after removing the device from ZHA before re-pairing it. The quirk needs to be present during pairing though.

To simulate a "fresh pairing" and get rid of all device traces I followed these steps

The attribute readings are saved in the zigbee.db file (which intentionally isn't deleted when deleting the integration).

I see also that it is still not possible to choose the precision (decimal digits) for voltage and current

ZCL has limitations, but ac_current_divisor and ac_voltage_divisor on the EM cluster should work if I'm correct.

CSRLabs commented 1 year ago

@TheJulianJES thanks for following up. I'm building a fresh HA system. I will try to remove the _update_attribute additional code from the quirk and pair the device one more time. Not sure if it is worth mentioning, the coordinator I'm using is based on CC2652P with latest 20221226 Koenkk FW.

github-actions[bot] commented 1 year ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.