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
758 stars 695 forks source link

[BUG] Plaid humidity sensor do not report battery #366

Closed ocalvo closed 4 years ago

ocalvo commented 4 years ago

Describe the bug Spruce humidity sensor Gen1 and Gen3 correctly report humidity and temperature but do not report battery correctly. The reported battery is always 0.

Gen3 model: PLAID SYSTEMS PS-SPRZMS-SLP3

To Reproduce Steps to reproduce the behavior:

  1. Pair a Spruce Sensor Gen1 or Gen3 with home assistant using ZHA integration.
  2. Notice the battery sensor

Expected behavior Battery reported should not be 0

Additional context

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
[0x0000](EZSP): started initialization
[0x0000:ZDO](EZSP): 'async_initialize' stage succeeded
[0x0000](EZSP): power source: Mains
[0x0000](EZSP): completed initialization
[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
Device 0xe440 (00:0d:6f:00:0c:1c:b4:d7) joined the network
[0xe440:zdo] ZDO request ZDOCmd.Device_annce: [0xe440, 00:0d:6f:00:0c:1c:b4:d7, 128]
[0xe440] Requesting 'Node Descriptor'
Tries remaining: 2
[0xe440] Extending timeout for 0x05 request
[0xe440] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4098 maximum_buffer_size=82 maximum_incoming_transfer_size=82 server_mask=0 maximum_outgoing_transfer_size=82 descriptor_capability_field=0>
[0xe440] Discovering endpoints
Tries remaining: 3
[0xe440] Extending timeout for 0x07 request
[0xe440] Discovered endpoints: [1]
[0xe440:1] Discovering endpoint information
Tries remaining: 3
[0xe440] Extending timeout for 0x09 request
[0xe440:1] Discovered endpoint information: <Optional endpoint=1 profile=260 device_type=1029 device_version=0 input_clusters=[0, 1, 3, 1026, 1029] output_clusters=[3, 25]>
[0xe440] Extending timeout for 0x0b request
[0xe440:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=11 command_id=Command.Read_Attributes_rsp>
[0xe440:1] Manufacturer: PLAID SYSTEMS
[0xe440:1] Model: PS-SPRZMS-SLP3
Checking quirks for PLAID SYSTEMS PS-SPRZMS-SLP3 (00:0d:6f:00:0c:1c:b4:d7)
Considering <class 'zhaquirks.plaid.soil.SoilMoisture'>
Found custom device replacement for 00:0d:6f:00:0c:1c:b4:d7: <class 'zhaquirks.plaid.soil.SoilMoisture'>
device - 0xe440:00:0d:6f:00:0c:1c:b4:d7 entering async_device_initialized - is_new_join: True
device - 0xe440:00:0d:6f:00:0c:1c:b4:d7 has joined the ZHA zigbee network
[0xe440](PS-SPRZMS-SLP3): started configuration
[0xe440:ZDO](PS-SPRZMS-SLP3): 'async_configure' stage succeeded
[0xe440] Extending timeout for 0x0d request
[0xe440] Extending timeout for 0x0f request
[0xe440] Extending timeout for 0x11 request
[0xe440:1:0x0001]: bound 'power' cluster: Status.SUCCESS
[0xe440] Extending timeout for 0x13 request
[0xe440:1:0x0402]: bound 'temperature' cluster: Status.SUCCESS
[0xe440] Extending timeout for 0x15 request
[0xe440:1:0x0405]: bound 'humidity' cluster: Status.SUCCESS
[0xe440] Extending timeout for 0x17 request
[0xe440:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=19 command_id=Command.Configure_Reporting_rsp>
[0xe440:1:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xe440] Extending timeout for 0x19 request
[0xe440:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=21 command_id=Command.Configure_Reporting_rsp>
[0xe440:1:0x0402]: reporting 'measured_value' attr on 'temperature' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xe440:1:0x0402]: finished channel configuration
[0xe440] Extending timeout for 0x1b request
[0xe440:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=23 command_id=Command.Configure_Reporting_rsp>
[0xe440:1:0x0405]: reporting 'measured_value' attr on 'humidity' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xe440:1:0x0405]: finished channel configuration
[0xe440] Extending timeout for 0x1d request
[0xe440:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=25 command_id=Command.Configure_Reporting_rsp>
[0xe440:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.INSUFFICIENT_SPACE direction=ReportingDirection.SendReports attrid=33>]]'
[0xe440:1:0x0001]: finished channel configuration
[0xe440:1:0x0000]: bound 'basic' cluster: Status.TABLE_FULL
[0xe440:1:0x0000]: finished channel configuration
[0xe440] Extending timeout for 0x1f request
[0xe440:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[0xe440:1:0x0019]: finished channel configuration
[0xe440:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=31 command_id=Command.Read_Attributes_rsp>
[0xe440:1:0x0000]: initializing channel: from_cache: False
[0xe440:1:0x0001]: 'async_configure' stage succeeded
[0xe440:1:0x0402]: 'async_configure' stage succeeded
[0xe440:1:0x0405]: 'async_configure' stage succeeded
[0xe440:1:0x0000]: 'async_configure' stage succeeded
[0xe440:1:0x0019]: 'async_configure' stage succeeded
[0xe440](PS-SPRZMS-SLP3): completed configuration
[0xe440](PS-SPRZMS-SLP3): stored in registry: ZhaDeviceEntry(name='PLAID SYSTEMS PS-SPRZMS-SLP3', ieee='00:0d:6f:00:0c:1c:b4:d7', last_seen=1590085964.8755488)
[0xe440] Extending timeout for 0x21 request
[0xe440:1:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=33 command_id=Command.Default_Response>
[0xe440:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[0xe440](PS-SPRZMS-SLP3): started initialization
[0xe440:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
[0xe440] Extending timeout for 0x23 request
[0xe440:1:0x0402]: initializing channel: from_cache: False
[0xe440] Extending timeout for 0x25 request
[0xe440:1:0x0405]: initializing channel: from_cache: False
[0xe440] Extending timeout for 0x27 request
[0xe440:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=35 command_id=Command.Read_Attributes_rsp>
[0xe440:1:0x0001]: initializing channel: from_cache: False
[0xe440] Extending timeout for 0x29 request
[0xe440:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=37 command_id=Command.Read_Attributes_rsp>
[0xe440:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=39 command_id=Command.Read_Attributes_rsp>
[0xe440] Extending timeout for 0x2b request
[0xe440:1:0x0019]: initializing channel: from_cache: False
[0xe440:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=41 command_id=Command.Read_Attributes_rsp>
[0xe440:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=43 command_id=Command.Read_Attributes_rsp>
[0xe440:1:0x0000]: initializing channel: from_cache: False
[0xe440:1:0x0001]: 'async_initialize' stage succeeded
[0xe440:1:0x0402]: 'async_initialize' stage succeeded
[0xe440:1:0x0405]: 'async_initialize' stage succeeded
[0xe440:1:0x0000]: 'async_initialize' stage succeeded
[0xe440:1:0x0019]: 'async_initialize' stage succeeded
[0xe440](PS-SPRZMS-SLP3): power source: Battery or Unknown
[0xe440](PS-SPRZMS-SLP3): completed initialization
[0xe440:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=114 command_id=Command.Report_Attributes>
[0xe440:1:0x0402] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=int16s, value=2218>>]]
[0xe440:1:0x0402] Attribute report received: measured_value=2218
[0xe440:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=115 command_id=Command.Report_Attributes>
[0xe440:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=0>>]]
[0xe440:1:0x0405] Attribute report received: measured_value=0
Adminiuga commented 4 years ago

that's already homeassistant core. so the report or response to attribute read should have been prior to that

ocalvo commented 4 years ago

Here are all the reports from the device at address 0x9a7b:

oscar@Oscar-Surface:/mnt/c/dd/Repos/Experiments/hass$ grep 0x9a7b home-assistant.log
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x9a7b](PS-SPRZMS-SLP3): started initialization
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0405]: initializing channel: from_cache: True
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0000]: initializing channel: from_cache: True
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0001]: initializing channel: from_cache: True
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0402]: initializing channel: from_cache: True
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0019]: initializing channel: from_cache: True
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0405]: 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0000]: 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0001]: 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0402]: 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x9a7b:1:0x0019]: 'async_initialize' stage succeeded
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x9a7b](PS-SPRZMS-SLP3): power source: Battery or Unknown
2020-06-03 11:32:11 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x9a7b](PS-SPRZMS-SLP3): completed initialization
2020-06-03 11:33:59 DEBUG (MainThread) [zigpy.device] [0x9a7b] Extending timeout for 0x01 request
2020-06-03 11:33:59 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0c:1c:c7:3c/0x9a7b
2020-06-03 11:33:59 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=1>, 2, b'\x00\x01\x00 \x00')
2020-06-03 11:34:06 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteErrorHandler frame with [<EmberStatus.MAC_INDIRECT_TIMEOUT: 66>, 0x9a7b]
2020-06-03 11:34:06 DEBUG (MainThread) [bellows.zigbee.application] Processing route error: status=EmberStatus.MAC_INDIRECT_TIMEOUT, nwk=0x9a7b
2020-06-03 11:34:10 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=184>, 255, -51, 0x9a7b, 255, 255, b'\x08\x01\x01 \x00\x00 \x00']
2020-06-03 11:34:10 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=1 command_id=Command.Read_Attributes_rsp>
2020-06-03 11:34:12 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=185>, 255, -53, 0x9a7b, 255, 255, b'\x08\x03\n\x00\x00!\x89\x00']
2020-06-03 11:34:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=3 command_id=Command.Report_Attributes>
2020-06-03 11:34:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=137>>]]
2020-06-03 11:34:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] Attribute report received: measured_value=137
2020-06-03 11:34:12 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=3>, 3, b'\x18\x03\x0b\n\x00')
ocalvo commented 4 years ago

When asking for the battery voltage and waking up the device with the magnet:

2020-06-03 11:41:59 DEBUG (MainThread) [zigpy.device] [0x9a7b] Extending timeout for 0x04 request
2020-06-03 11:41:59 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0c:1c:c7:3c/0x9a7b
2020-06-03 11:41:59 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=4>, 5, b'\x00\x04\x00 \x00')
2020-06-03 11:42:06 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteErrorHandler frame with [<EmberStatus.MAC_INDIRECT_TIMEOUT: 66>, 0x9a7b]
2020-06-03 11:42:06 DEBUG (MainThread) [bellows.zigbee.application] Processing route error: status=EmberStatus.MAC_INDIRECT_TIMEOUT, nwk=0x9a7b
2020-06-03 11:42:09 DEBUG (MainThread) [zigpy.device] [0x9a7b] Extending timeout for 0x06 request
2020-06-03 11:42:09 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0c:1c:c7:3c/0x9a7b
2020-06-03 11:42:09 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=6>, 7, b'\x00\x06\x00 \x00')
2020-06-03 11:42:10 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=186>, 255, -51, 0x9a7b, 255, 255, b'\x08\x04\x01 \x00\x00 \x00']
2020-06-03 11:42:10 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=4 command_id=Command.Read_Attributes_rsp>
2020-06-03 11:42:10 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=187>, 255, -51, 0x9a7b, 255, 255, b'\x08\x06\x01 \x00\x00 \x00']
2020-06-03 11:42:10 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=6 command_id=Command.Read_Attributes_rsp>
2020-06-03 11:42:10 DEBUG (MainThread) [zigpy.device] [0x9a7b] Extending timeout for 0x08 request
2020-06-03 11:42:10 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0c:1c:c7:3c/0x9a7b
2020-06-03 11:42:10 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=8>, 9, b'\x00\x08\x00 \x00')
2020-06-03 11:42:11 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=188>, 255, -53, 0x9a7b, 255, 255, b'\x08\x08\x01 \x00\x00 \x00']
2020-06-03 11:42:11 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=8 command_id=Command.Read_Attributes_rsp>
2020-06-03 11:42:12 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=189>, 255, -52, 0x9a7b, 255, 255, b'\x08\x04\n\x00\x00!\x89\x00']
2020-06-03 11:42:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=4 command_id=Command.Report_Attributes>
2020-06-03 11:42:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=137>>]]
2020-06-03 11:42:12 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] Attribute report received: measured_value=137
2020-06-03 11:42:12 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=4>, 10, b'\x18\x04\x0b\n\x00')
Adminiuga commented 4 years ago

Per logs, reading battery voltage return 0, essentially what is seen in the state.

ocalvo commented 4 years ago 
2020-06-03 13:53:36 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=14>, 255, -49, 0x9a7b, 255, 255, b'\x08\x03\n\x00\x00!\x89\x00']
2020-06-03 13:53:36 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=3 command_id=Command.Report_Attributes>
2020-06-03 13:53:36 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=137>>]]
2020-06-03 13:53:36 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] Attribute report received: measured_value=137
2020-06-03 13:53:36 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=3>, 15, b'\x18\x03\x0b\n\x00')
2020-06-03 14:53:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=15>, 255, -48, 0x9a7b, 255, 255, b'\x08\x04\n \x00 \x00!\x00 \x00']
2020-06-03 14:53:32 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=4 command_id=Command.Report_Attributes>
2020-06-03 14:53:32 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=32 value=<TypeValue type=uint8_t, value=0>>, <Attribute attrid=33 value=<TypeValue type=uint8_t, value=0>>]]
2020-06-03 14:53:32 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] Attribute report received: battery_voltage=0, battery_percentage_remaining=0
2020-06-03 14:53:32 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=4>, 16, b'\x18\x04\x0b\n\x00')
2020-06-03 14:53:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=16>, 255, -48, 0x9a7b, 255, 255, b'\x08\x05\n\x00\x00!\x89\x00']
2020-06-03 14:53:37 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=5 command_id=Command.Report_Attributes>
2020-06-03 14:53:37 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=137>>]]
2020-06-03 14:53:37 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] Attribute report received: measured_value=137
2020-06-03 14:53:37 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=5>, 17, b'\x18\x05\x0b\n\x00')
2020-06-03 15:53:38 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=17>, 255, -49, 0x9a7b, 255, 255, b'\x08\x06\n\x00\x00!\x89\x00']
2020-06-03 15:53:38 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=6 command_id=Command.Report_Attributes>
2020-06-03 15:53:38 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=137>>]]
2020-06-03 15:53:38 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0405] Attribute report received: measured_value=137
2020-06-03 15:53:38 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9a7b, <EmberApsFrame profileId=260 clusterId=1029 sourceEndpoint=1 destinationEndpoint=1 options=320 groupId=0 sequence=6>, 18, b'\x18\x06\x0b\n\x00')
Adminiuga commented 4 years ago

well, you sensor does report battery % remaining and battery_voltage, but both are 0

2020-06-03 14:53:32 DEBUG (MainThread) [zigpy.zcl] [0x9a7b:1:0x0001] Attribute report received: battery_voltage=0, battery_percentage_remaining=0

I wonder if your device version is different from Tube's . if you navigate to HA Configuration -> Devices -> pick soil sensor, what firmware number if any do you get? image

2nd: give it more time and then filter by [0x9a7b:1:0x0001] I wanna see if it ever reports mains voltage.

Adminiuga commented 4 years ago

by give it more time i mean like 24 hours. if it reports it, it won't report often

tube0013 commented 4 years ago

There are different versions, I have the gen3 sensor which has the magnet sensor on the top. I believe the gen2 sensor has it on the side. As described here

https://support.spruceirrigation.com/knowledge-base/re-join-spruce-sensor-to-the-network/

tube0013 commented 4 years ago

here is what I get:

image

I also queried most of the attributes in the basic and beyond the model/manufacturer it reported the date_code: image

device seems to be chatty right now lol... battery-percent remaining:

image

still not sending mains-voltage when requesting.

Adminiuga commented 4 years ago

as it was mentioned: run debug logs for 24 hours. Then filter by 0x9a7b:1:0x0001 and maybe gen 2 does not report at all, who knows

BTW, did you try to get mains_voltage attribute?

tube0013 commented 4 years ago

yes don't get anything when I request that attribute

Adminiuga commented 4 years ago

Do you get None ???

ocalvo commented 4 years ago

There are different versions, I have the gen3 sensor which has the magnet sensor on the top. I believe the gen2 sensor has it on the side. As described here

https://support.spruceirrigation.com/knowledge-base/re-join-spruce-sensor-to-the-network/

I have one Gen1 and 2 Gen3. The Gen1 and Gen3 are in "production". The other Gen3 is in my test environment.

Adminiuga commented 4 years ago

I'm running of solutions. Configured attribute reporting for the mains_voltage attribute, but it still won't report it. It was reporting the batter_voltage regularly though, the only problem it was reporting 0V

tube0013 commented 4 years ago

I can set pull in the changed quirk tonight and test. Did you pick one of these up? I've found the battery reporting to be non-existent sometimes and yet other times it has reported it frequently.

Adminiuga commented 4 years ago

yep, got one. need to automate watering. Try this version https://github.com/zigpy/zha-device-handlers/pull/377

This substitutes requests for battery_voltage attribue. Was 4 hours since joined the sensor, but it did not report it yet. It was reporting battery voltage like once in 4 hours. Gonna wait till tomorrow

tube0013 commented 4 years ago

Pulled the battery, waited about 5 secs put it back in, waited a few seconds, and hit it with the magnet..... image

ocalvo commented 4 years ago

Pulled the battery, waited about 5 secs put it back in, waited a few seconds, and hit it with the magnet..... image

Can you share the version of soil.py that you are using? I would like to test this in my end.

tube0013 commented 4 years ago

it is the version #377 linked above I also updated #376

ocalvo commented 4 years ago

Is there anything I have to do to update the files other that copy init.py and soil.py ?

tube0013 commented 4 years ago

I delete the py_cache folders and then update the files, then restart ha.

I run supervised and use the portainer addon to get a command line inside the ha container to make the changes.

ocalvo commented 4 years ago

I am running in Windows 10 with wsl. I have:

  1. Stop hass
  2. Deleted both pycache folders
  3. Copy the files from github
  4. Restart hass
  5. Remove battery, wait 5 seconds
  6. Use the magnet to force device update.

Same result, device reports between 0 and -1 (Note I using Gen3 device) image

ocalvo commented 4 years ago

Remove and added the device from the network:

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
[0x0000](EZSP): started initialization
[0x0000:ZDO](EZSP): 'async_initialize' stage succeeded
[0x0000](EZSP): power source: Mains
[0x0000](EZSP): completed initialization
Device 0xff0c (00:0d:6f:00:0c:1c:c7:3c) joined the network
[0xff0c:zdo] ZDO request ZDOCmd.Device_annce: [0xff0c, 00:0d:6f:00:0c:1c:c7:3c, 128]
[0xff0c] Requesting 'Node Descriptor'
Tries remaining: 2
[0xff0c] Extending timeout for 0x09 request
[0xff0c] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4098 maximum_buffer_size=82 maximum_incoming_transfer_size=82 server_mask=0 maximum_outgoing_transfer_size=82 descriptor_capability_field=0>
[0xff0c] Discovering endpoints
Tries remaining: 3
[0xff0c] Extending timeout for 0x0b request
[0xff0c] Discovered endpoints: [1]
[0xff0c:1] Discovering endpoint information
Tries remaining: 3
[0xff0c] Extending timeout for 0x0d request
[0xff0c:1] Discovered endpoint information: <Optional endpoint=1 profile=260 device_type=1029 device_version=0 input_clusters=[0, 1, 3, 1026, 1029] output_clusters=[3, 25]>
[0xff0c] Extending timeout for 0x0f request
[0xff0c:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=15 command_id=Command.Read_Attributes_rsp>
[0xff0c:1] Manufacturer: PLAID SYSTEMS
[0xff0c:1] Model: PS-SPRZMS-SLP3
Checking quirks for PLAID SYSTEMS PS-SPRZMS-SLP3 (00:0d:6f:00:0c:1c:c7:3c)
Considering <class 'zhaquirks.plaid.soil.SoilMoisture'>
Found custom device replacement for 00:0d:6f:00:0c:1c:c7:3c: <class 'zhaquirks.plaid.soil.SoilMoisture'>
device - 0xff0c:00:0d:6f:00:0c:1c:c7:3c entering async_device_initialized - is_new_join: True
device - 0xff0c:00:0d:6f:00:0c:1c:c7:3c has joined the ZHA zigbee network
[0xff0c](PS-SPRZMS-SLP3): started configuration
[0xff0c:ZDO](PS-SPRZMS-SLP3): 'async_configure' stage succeeded
[0xff0c] Extending timeout for 0x11 request
[0xff0c] Extending timeout for 0x13 request
[0xff0c] Extending timeout for 0x15 request
[0xff0c:1:0x0405]: bound 'humidity' cluster: Status.SUCCESS
[0xff0c] Extending timeout for 0x17 request
[0xff0c:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
[0xff0c:1:0x0000]: finished channel configuration
[0xff0c] Extending timeout for 0x19 request
[0xff0c:1:0x0402]: bound 'temperature' cluster: Status.TABLE_FULL
[0xff0c] Extending timeout for 0x1b request
[0xff0c:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=23 command_id=Command.Configure_Reporting_rsp>
[0xff0c:1:0x0405]: reporting 'measured_value' attr on 'humidity' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xff0c:1:0x0405]: finished channel configuration
[0xff0c] Extending timeout for 0x1d request
[0xff0c:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=25 command_id=Command.Read_Attributes_rsp>
[0xff0c:1:0x0000]: initializing channel: from_cache: False
[0xff0c] Extending timeout for 0x1f request
[0xff0c:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=27 command_id=Command.Configure_Reporting_rsp>
[0xff0c:1:0x0402]: reporting 'measured_value' attr on 'temperature' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xff0c:1:0x0402]: finished channel configuration
[0xff0c:1:0x0001]: bound 'power' cluster: Status.SUCCESS
[0xff0c] Extending timeout for 0x21 request
[0xff0c:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[0xff0c:1:0x0019]: finished channel configuration
[0xff0c:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=33 command_id=Command.Configure_Reporting_rsp>
[0xff0c:1:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xff0c] Extending timeout for 0x23 request
[0xff0c:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=35 command_id=Command.Configure_Reporting_rsp>
[0xff0c:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.INSUFFICIENT_SPACE direction=ReportingDirection.SendReports attrid=33>]]'
[0xff0c:1:0x0001]: finished channel configuration
[0xff0c:1:0x0405]: 'async_configure' stage succeeded
[0xff0c:1:0x0000]: 'async_configure' stage succeeded
[0xff0c:1:0x0402]: 'async_configure' stage succeeded
[0xff0c:1:0x0001]: 'async_configure' stage succeeded
[0xff0c:1:0x0019]: 'async_configure' stage succeeded
[0xff0c](PS-SPRZMS-SLP3): completed configuration
[0xff0c](PS-SPRZMS-SLP3): stored in registry: ZhaDeviceEntry(name='PLAID SYSTEMS PS-SPRZMS-SLP3', ieee='00:0d:6f:00:0c:1c:c7:3c', last_seen=1592101415.4353373)
[0xff0c] Extending timeout for 0x25 request
[0xff0c:1:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=37 command_id=Command.Default_Response>
[0xff0c:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[0xff0c](PS-SPRZMS-SLP3): started initialization
[0xff0c:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
[0xff0c:1:0x0405]: initializing channel: from_cache: False
[0xff0c] Extending timeout for 0x27 request
[0xff0c] Extending timeout for 0x29 request
[0xff0c:1:0x0402]: initializing channel: from_cache: False
[0xff0c] Extending timeout for 0x2b request
[0xff0c:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=39 command_id=Command.Read_Attributes_rsp>
[0xff0c] Extending timeout for 0x2d request
[0xff0c:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=41 command_id=Command.Read_Attributes_rsp>
[0xff0c:1:0x0000]: initializing channel: from_cache: False
[0xff0c:1:0x0019]: initializing channel: from_cache: False
[0xff0c:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=43 command_id=Command.Read_Attributes_rsp>
[0xff0c:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=45 command_id=Command.Read_Attributes_rsp>
[0xff0c:1:0x0001]: initializing channel: from_cache: False
[0xff0c] Extending timeout for 0x2f request
[0xff0c:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=47 command_id=Command.Read_Attributes_rsp>
[0xff0c:1:0x0405]: 'async_initialize' stage succeeded
[0xff0c:1:0x0000]: 'async_initialize' stage succeeded
[0xff0c:1:0x0402]: 'async_initialize' stage succeeded
[0xff0c:1:0x0001]: 'async_initialize' stage succeeded
[0xff0c:1:0x0019]: 'async_initialize' stage succeeded
[0xff0c](PS-SPRZMS-SLP3): power source: Battery or Unknown
[0xff0c](PS-SPRZMS-SLP3): completed initialization
[0xff0c:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=11 command_id=Command.Report_Attributes>
[0xff0c:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=133>>]]
[0xff0c:1:0x0405] Attribute report received: measured_value=133
[0xff0c:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=13 command_id=Command.Report_Attributes>
[0xff0c:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=134>>]]
[0xff0c:1:0x0405] Attribute report received: measured_value=134
ocalvo commented 4 years ago

Hmm, the second time that I re added the device I got a different result: image

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
Device 0xff0c (00:0d:6f:00:0c:1c:c7:3c) left the network
Device 0x15d5 (00:0d:6f:00:0c:1c:c7:3c) joined the network
Device 00:0d:6f:00:0c:1c:c7:3c changed id (0xff0c => 0x15d5)
[0x15d5:zdo] ZDO request ZDOCmd.Device_annce: [0x15d5, 00:0d:6f:00:0c:1c:c7:3c, 128]
[5589](PS-SPRZMS-SLP3): started initialization
[5589:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
device - 5589:00:0d:6f:00:0c:1c:c7:3c entering async_device_initialized - is_new_join: False
device - 5589:00:0d:6f:00:0c:1c:c7:3c has been reset and re-added or its nwk address changed
skipping discovery for previously discovered device - 5589:00:0d:6f:00:0c:1c:c7:3c
[5589](PS-SPRZMS-SLP3): started configuration
[5589:ZDO](PS-SPRZMS-SLP3): 'async_configure' stage succeeded
[5589:1:0x0405]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x36 request
[0x15d5] Extending timeout for 0x38 request
[5589:1:0x0402]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x3a request
[0x15d5:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=54 command_id=Command.Read_Attributes_rsp>
[0x15d5] Extending timeout for 0x3c request
[0x15d5:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=56 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0000]: initializing channel: from_cache: False
[5589:1:0x0019]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x3e request
[0x15d5:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=58 command_id=Command.Read_Attributes_rsp>
[0x15d5] Extending timeout for 0x40 request
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=60 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0001]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x42 request
[5589:1:0x0405]: bound 'humidity' cluster: Status.SUCCESS
[0x15d5] Extending timeout for 0x44 request
[5589:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
[5589:1:0x0000]: finished channel configuration
[0x15d5] Extending timeout for 0x46 request
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=66 command_id=Command.Read_Attributes_rsp>
[0x15d5] Extending timeout for 0x48 request
[5589:1:0x0405]: 'async_initialize' stage succeeded
[5589:1:0x0000]: 'async_initialize' stage succeeded
[5589:1:0x0402]: 'async_initialize' stage succeeded
[5589:1:0x0001]: 'async_initialize' stage succeeded
[5589:1:0x0019]: 'async_initialize' stage succeeded
[5589](PS-SPRZMS-SLP3): power source: Battery or Unknown
[5589](PS-SPRZMS-SLP3): completed initialization
[0x15d5:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=68 command_id=Command.Configure_Reporting_rsp>
[0x15d5:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=70 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0405]: reporting 'measured_value' attr on 'humidity' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[5589:1:0x0405]: finished channel configuration
[0x15d5] Extending timeout for 0x4a request
[5589:1:0x0000]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x4c request
[5589:1:0x0402]: bound 'temperature' cluster: Status.SUCCESS
[0x15d5] Extending timeout for 0x4e request
[5589:1:0x0001]: bound 'power' cluster: Status.TABLE_FULL
[0x15d5] Extending timeout for 0x50 request
[5589:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[5589:1:0x0019]: finished channel configuration
[0x15d5:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=78 command_id=Command.Configure_Reporting_rsp>
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=80 command_id=Command.Configure_Reporting_rsp>
[5589:1:0x0402]: reporting 'measured_value' attr on 'temperature' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[5589:1:0x0402]: finished channel configuration
[5589:1:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0x15d5] Extending timeout for 0x52 request
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=82 command_id=Command.Configure_Reporting_rsp>
[5589:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.INSUFFICIENT_SPACE direction=ReportingDirection.SendReports attrid=33>]]'
[5589:1:0x0001]: finished channel configuration
[5589:1:0x0405]: 'async_configure' stage succeeded
[5589:1:0x0000]: 'async_configure' stage succeeded
[5589:1:0x0402]: 'async_configure' stage succeeded
[5589:1:0x0001]: 'async_configure' stage succeeded
[5589:1:0x0019]: 'async_configure' stage succeeded
[5589](PS-SPRZMS-SLP3): completed configuration
[5589](PS-SPRZMS-SLP3): stored in registry: ZhaDeviceEntry(name='PLAID SYSTEMS PS-SPRZMS-SLP3', ieee='00:0d:6f:00:0c:1c:c7:3c', last_seen=1592101619.4950278)
[0x15d5] Extending timeout for 0x54 request
[0x15d5:1:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=84 command_id=Command.Default_Response>
[5589:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[5589](PS-SPRZMS-SLP3): started initialization
[5589:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
[5589:1:0x0405]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x56 request
[0x15d5] Extending timeout for 0x58 request
[5589:1:0x0402]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x5a request
[0x15d5:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=86 command_id=Command.Read_Attributes_rsp>
[0x15d5] Extending timeout for 0x5c request
[0x15d5:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=88 command_id=Command.Read_Attributes_rsp>
[0x15d5:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=90 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0000]: initializing channel: from_cache: False
[5589:1:0x0019]: initializing channel: from_cache: False
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=92 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0001]: initializing channel: from_cache: False
[0x15d5] Extending timeout for 0x5e request
[0x15d5:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=94 command_id=Command.Read_Attributes_rsp>
[5589:1:0x0405]: 'async_initialize' stage succeeded
[5589:1:0x0000]: 'async_initialize' stage succeeded
[5589:1:0x0402]: 'async_initialize' stage succeeded
[5589:1:0x0001]: 'async_initialize' stage succeeded
[5589:1:0x0019]: 'async_initialize' stage succeeded
[5589](PS-SPRZMS-SLP3): power source: Battery or Unknown
[5589](PS-SPRZMS-SLP3): completed initialization
[0x15d5:1:0x0405] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=20 command_id=Command.Report_Attributes>
[0x15d5:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=134>>]]
[0x15d5:1:0x0405] Attribute report received: measured_value=134
[0x15d5:1:0x0402] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=21 command_id=Command.Report_Attributes>
[0x15d5:1:0x0402] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=int16s, value=2555>>]]
[0x15d5:1:0x0402] Attribute report received: measured_value=2555
Adminiuga commented 4 years ago

actually I've got mains_voltage attribute reports (three) overnight. I think it reports it ~6hours

2020-06-13 20:53:03 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=111 command_id=Command.Report_Attributes>
2020-06-13 20:53:03 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=3106>>]]
2020-06-13 20:53:03 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] Attribute report received: mains_voltage=3106
2020-06-14 02:52:05 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=125 command_id=Command.Report_Attributes>
2020-06-14 02:52:05 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=3115>>]]
2020-06-14 02:52:05 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] Attribute report received: mains_voltage=3115
2020-06-14 08:51:00 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=12 command_id=Command.Report_Attributes>
2020-06-14 08:51:00 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=3113>>]]
2020-06-14 08:51:00 DEBUG (MainThread) [zigpy.zcl] [0xcf5a:1:0x0001] Attribute report received: mains_voltage=3113

With the new quirk in, you would need to reconfigure device, so it configures attribute reporting on mains_voltage attribute. Easiest way is to remove sensor from ZHA (make sure device disappears) and then reset and rejoin the sensor. Reconfiguring it through the UI, may fail if the device is sleeping through it.

ocalvo commented 4 years ago

Success, after removing the device and re adding an manually reconfigure it, the battery now reports: image

dmulcahey commented 4 years ago

@Adminiuga is this resolved? Good to close?

Adminiuga commented 4 years ago

Yes, seems to work.