Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

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

Closed
ocalvo opened this issue Jun 2, 2020 · 78 comments
Closed

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

ocalvo opened this issue Jun 2, 2020 · 78 comments

Comments

@ocalvo
Copy link

ocalvo commented Jun 2, 2020

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
@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

I needed to reactivate this bug

@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

[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
[0xe440](PS-SPRZMS-SLP3): Attempting to checkin with device - missed checkins: 2
[0xe440] Extending timeout for 0x05 request
Device 0x84f9 (00:0d:6f:00:0c:1c:b4:d7) joined the network
Device 00:0d:6f:00:0c:1c:b4:d7 changed id (0xe440 => 0x84f9)
[0x84f9:zdo] ZDO request ZDOCmd.Device_annce: [0x84f9, 00:0d:6f:00:0c:1c:b4:d7, 128]
device - 34041:00:0d:6f:00:0c:1c:b4:d7 entering async_device_initialized - is_new_join: False
device - 34041:00:0d:6f:00:0c:1c:b4:d7 has been reset and re-added or its nwk address changed
skipping discovery for previously discovered device - 34041:00:0d:6f:00:0c:1c:b4:d7
[34041](PS-SPRZMS-SLP3): started configuration
[34041:ZDO](PS-SPRZMS-SLP3): 'async_configure' stage succeeded
[0x84f9] Extending timeout for 0x07 request
[0x84f9] Extending timeout for 0x09 request
[0x84f9] Extending timeout for 0x0b request
[34041](PS-SPRZMS-SLP3): started initialization
[34041:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
[34041:1:0x0405]: bound 'humidity' cluster: Status.SUCCESS
[0x84f9] Extending timeout for 0x0d request
[34041:1:0x0001]: bound 'power' cluster: Status.SUCCESS
[0x84f9] Extending timeout for 0x0f request
[34041:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
[34041:1:0x0000]: finished channel configuration
[0x84f9] Extending timeout for 0x11 request
[0x84f9: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.Configure_Reporting_rsp>
[34041:1:0x0405]: reporting 'measured_value' attr on 'humidity' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[34041:1:0x0405]: finished channel configuration
[0x84f9] Extending timeout for 0x13 request
[0x84f9: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=15 command_id=Command.Configure_Reporting_rsp>
[0x84f9: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=17 command_id=Command.Read_Attributes_rsp>
[34041:1:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0x84f9] Extending timeout for 0x15 request
[34041:1:0x0000]: initializing channel: from_cache: False
[0x84f9] Extending timeout for 0x17 request
[34041:1:0x0402]: bound 'temperature' cluster: Status.TABLE_FULL
[0x84f9] Extending timeout for 0x19 request
[0x84f9: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=21 command_id=Command.Configure_Reporting_rsp>
[34041:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[34041:1:0x0001]: finished channel configuration
[34041:1:0x0405]: initializing channel: from_cache: False
[0x84f9] Extending timeout for 0x1b request
[34041:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[34041:1:0x0019]: finished channel configuration
[0x84f9] Extending timeout for 0x1d request
[0x84f9: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=25 command_id=Command.Configure_Reporting_rsp>
[34041:1:0x0402]: reporting 'measured_value' attr on 'temperature' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.INSUFFICIENT_SPACE direction=ReportingDirection.SendReports attrid=0>]]'
[34041:1:0x0402]: finished channel configuration
[0x84f9] Extending timeout for 0x1f request
[34041:1:0x0405]: 'async_configure' stage succeeded
[34041:1:0x0001]: 'async_configure' stage succeeded
[34041:1:0x0000]: 'async_configure' stage succeeded
[34041:1:0x0402]: 'async_configure' stage succeeded
[34041:1:0x0019]: 'async_configure' stage succeeded
[34041](PS-SPRZMS-SLP3): completed configuration
[34041](PS-SPRZMS-SLP3): stored in registry: ZhaDeviceEntry(name='PLAID SYSTEMS PS-SPRZMS-SLP3', ieee='00:0d:6f:00:0c:1c:b4:d7', last_seen=1591120231.0971005)
[0x84f9] Extending timeout for 0x21 request
[0x84f9: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=27 command_id=Command.Read_Attributes_rsp>
[0x84f9: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=29 command_id=Command.Read_Attributes_rsp>
[34041:1:0x0001]: initializing channel: from_cache: False
[0x84f9] Extending timeout for 0x23 request
[34041:1:0x0402]: initializing channel: from_cache: False
[0x84f9] Extending timeout for 0x25 request
[0x84f9: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>
[34041:1:0x0000]: initializing channel: from_cache: False
[34041:1:0x0019]: initializing channel: from_cache: False
[0x84f9: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>
[34041:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[0x84f9: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>
[0x84f9: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>
[34041:1:0x0405]: 'async_initialize' stage succeeded
[34041:1:0x0001]: 'async_initialize' stage succeeded
[34041:1:0x0000]: 'async_initialize' stage succeeded
[34041:1:0x0402]: 'async_initialize' stage succeeded
[34041:1:0x0019]: 'async_initialize' stage succeeded
[34041](PS-SPRZMS-SLP3): power source: Battery or Unknown
[34041](PS-SPRZMS-SLP3): completed initialization
[0x84f9] Delivery error for seq # 0x05, on endpoint id 1 cluster 0x0000: message send failure
[0x84f9: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=4 command_id=Command.Report_Attributes>
[0x84f9:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=945>>]]
[0x84f9:1:0x0405] Attribute report received: measured_value=945

@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

Device info:

{
  "node_descriptor": "<NodeDescriptor 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>",
  "endpoints": {
    "1": {
      "profile_id": 260,
      "device_type": "0x0405",
      "in_clusters": [
        "0x0000",
        "0x0001",
        "0x0003",
        "0x0402",
        "0x0405"
      ],
      "out_clusters": [
        "0x0003",
        "0x0019"
      ]
    }
  },
  "manufacturer": "PLAID SYSTEMS",
  "model": "PS-SPRZMS-SLP3",
  "class": "zhaquirks.plaid.soil.SoilMoisture"
}

@Adminiuga
Copy link
Contributor

Seems like there's already device quirk for it and battery percent remaining attribute was configured successfuly for the reporting.
How long device has been on the network?

@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

Months
I have 3 of these.
I removed one of the devices to test in an isolated environment and provide logs.

@Adminiuga
Copy link
Contributor

Do you have a second zigbee stick for this isolated environment? And is it venv, hassio or docker? in other words how easily can you modify the source files to test a few things.

I'm concerned that binding table is limited on this device, as it keeps throwing

[0xe440:1:0x0000]: bound 'basic' cluster: Status.TABLE_FULL
[0xe440:1:0x0000]: finished channel configuration
[0xe440:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[0xe440:1:0x0019]: finished channel configuration

in one log, and in the other

[34041:1:0x0402]: bound 'temperature' cluster: Status.TABLE_FULL
[34041:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[34041:1:0x0019]: finished channel configuration

on different clusters, depending on configuration order.

@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

Yes, I have a second ZigBee stick running hass on a developer environment using windows Linux subststem so I can tweak very easyly.
Let me know what you want to change.

@tube0013
Copy link
Contributor

tube0013 commented Jun 2, 2020

I have a plaid sensor not yet in production and a test box (the one with the zzh stick) I can mess with. this sensor reports the battery voltage on the mains attribute for some reason.

@Adminiuga
Copy link
Contributor

@tube0013 can you provide full debug logs of a such report?

@tube0013
Copy link
Contributor

tube0013 commented Jun 2, 2020

sure, let me move i'll move it over to my test box. my memory was the voltage was not sent very often even when triggering it.

@ocalvo
Copy link
Author

ocalvo commented Jun 2, 2020

How do I activate "full debug logs"?

@Adminiuga
Copy link
Contributor

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

I had issues getting this pair on my test box oh well I'll deal with those another day.... put it back on my prod box had to pull the battery and re-insert to get a voltage.

this is immediately after re-inserting the battery:

2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zdo] [0x648a:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:0d:6f:00:0a:ff:73:23, 0, 0]
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a: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=2 command_id=Command.Report_Attributes>
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=2997>>]]
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0001] Attribute report received: mains_voltage=2997
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a: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=1 command_id=Command.Report_Attributes>
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=0>>]]
2020-06-02 21:12:15 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0405] Attribute report received: measured_value=0
2020-06-02 21:12:16 DEBUG (MainThread) [zigpy.zcl] [0x648a: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=1 command_id=Command.Report_Attributes>
2020-06-02 21:12:16 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=0>>]]
2020-06-02 21:12:16 DEBUG (MainThread) [zigpy.zcl] [0x648a:1:0x0405] Attribute report received: measured_value=0

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

Spruce support were generally pretty good they even took a look at the quirk at the time I had a ticket open with them, the rep I worked with did not know why it reports voltage on the mains attribute....

image

@Adminiuga
Copy link
Contributor

Impressive. Kudos to their support for at least trying to be helpful

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

they mentioned that they gotten another ticket from a HA user at the same time, so demand was showing lol.

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

[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 0xc187 (00:0d:6f:00:0c:1c:c7:3c) joined the network
[0xc187:zdo] ZDO request ZDOCmd.Device_annce: [0xc187, 00:0d:6f:00:0c:1c:c7:3c, 128]
[0xc187] Requesting 'Node Descriptor'
Tries remaining: 2
[0xc187] Extending timeout for 0x09 request
[0xc187] 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>
[0xc187] Discovering endpoints
Tries remaining: 3
[0xc187] Extending timeout for 0x0b request
[0xc187] Discovered endpoints: [1]
[0xc187:1] Discovering endpoint information
Tries remaining: 3
[0xc187] Extending timeout for 0x0d request
[0xc187: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]>
[0xc187] Extending timeout for 0x0f request
[0xc187: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>
[0xc187:1] Manufacturer: PLAID SYSTEMS
[0xc187: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 - 0xc187:00:0d:6f:00:0c:1c:c7:3c entering async_device_initialized - is_new_join: True
device - 0xc187:00:0d:6f:00:0c:1c:c7:3c has joined the ZHA zigbee network
[0xc187](PS-SPRZMS-SLP3): started configuration
[0xc187:ZDO](PS-SPRZMS-SLP3): 'async_configure' stage succeeded
[0xc187] Extending timeout for 0x11 request
[0xc187] Extending timeout for 0x13 request
[0xc187] Extending timeout for 0x15 request
[0x0000:zdo] ZDO request ZDOCmd.Mgmt_NWK_Update_rsp: [<Status.SUCCESS: 0>, <Channels.ALL_CHANNELS: 134215680>, 21, 10, [209, 212, 180, 199, 231, 196, 176, 184, 221, 196, 213, 175, 221, 203, 206, 194]]
[0x0000:zdo] Unsupported ZDO request:ZDOCmd.Mgmt_NWK_Update_rsp
[0xc187] Delivery error for seq # 0x11, on endpoint id 0 cluster 0x0021: message send failure
[0xc187:1:0x0405]: Failed to bind 'humidity' cluster: [0xc187:0:0x0021]: Message send failure
[0xc187] Extending timeout for 0x17 request
[0xc187] Delivery error for seq # 0x13, on endpoint id 0 cluster 0x0021: message send failure
[0xc187:1:0x0001]: Failed to bind 'power' cluster: [0xc187:0:0x0021]: Message send failure
[0xc187] Extending timeout for 0x19 request
[0xc187] Delivery error for seq # 0x15, on endpoint id 0 cluster 0x0021: message send failure
[0xc187:1:0x0000]: Failed to bind 'basic' cluster: [0xc187:0:0x0021]: Message send failure
[0xc187:1:0x0000]: finished channel configuration
[0xc187] Extending timeout for 0x1b request
[0xc187] Delivery error for seq # 0x17, on endpoint id 1 cluster 0x0405: message send failure
[0xc187:1:0x0405]: failed to set reporting for 'measured_value' attr on 'humidity' cluster: [0xc187:1:0x0405]: Message send failure
[0xc187:1:0x0405]: finished channel configuration
[0xc187] Extending timeout for 0x1d request
[0xc187] Delivery error for seq # 0x19, on endpoint id 1 cluster 0x0001: message send failure
[0xc187:1:0x0001]: failed to set reporting for 'battery_voltage' attr on 'power' cluster: [0xc187:1:0x0001]: Message send failure
[0xc187] Extending timeout for 0x1f request
[0xc187] Delivery error for seq # 0x1b, on endpoint id 1 cluster 0x0000: message send failure
[0xc187:1:0x0000]: initializing channel: from_cache: False
[0xc187] Extending timeout for 0x21 request
[0xc187:1:0x0402]: bound 'temperature' cluster: Status.SUCCESS
[0xc187] Extending timeout for 0x23 request
[0xc187: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=31 command_id=Command.Configure_Reporting_rsp>
[0xc187:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.INSUFFICIENT_SPACE direction=ReportingDirection.SendReports attrid=33>]]'
[0xc187:1:0x0001]: finished channel configuration
[0xc187:1:0x0019]: bound 'ota' cluster: Status.TABLE_FULL
[0xc187:1:0x0019]: finished channel configuration
[0xc187: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=35 command_id=Command.Configure_Reporting_rsp>
[0xc187:1:0x0402]: reporting 'measured_value' attr on 'temperature' cluster: 30/900/50: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
[0xc187:1:0x0402]: finished channel configuration
[0xc187:1:0x0405]: 'async_configure' stage succeeded
[0xc187:1:0x0001]: 'async_configure' stage succeeded
[0xc187:1:0x0000]: 'async_configure' stage succeeded
[0xc187:1:0x0402]: 'async_configure' stage succeeded
[0xc187:1:0x0019]: 'async_configure' stage succeeded
[0xc187](PS-SPRZMS-SLP3): completed configuration
[0xc187](PS-SPRZMS-SLP3): stored in registry: ZhaDeviceEntry(name='PLAID SYSTEMS PS-SPRZMS-SLP3', ieee='00:0d:6f:00:0c:1c:c7:3c', last_seen=1591154229.4287667)
[0xc187] Extending timeout for 0x25 request
[0xc187: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>
[0xc187:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
[0xc187](PS-SPRZMS-SLP3): started initialization
[0xc187:ZDO](PS-SPRZMS-SLP3): 'async_initialize' stage succeeded
[0xc187:1:0x0405]: initializing channel: from_cache: False
[0xc187] Extending timeout for 0x27 request
[0xc187] Extending timeout for 0x29 request
[0xc187] Extending timeout for 0x2b request
[0xc187: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=2 command_id=Command.Report_Attributes>
[0xc187:1:0x0402] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=int16s, value=2295>>]]
[0xc187:1:0x0402] Attribute report received: measured_value=2295
[0xc187: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=3 command_id=Command.Report_Attributes>
[0xc187:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=152>>]]
[0xc187:1:0x0405] Attribute report received: measured_value=152
[0xc187: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.Report_Attributes>
[0xc187:1:0x0001] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=3076>>]]
[0xc187:1:0x0001] Attribute report received: mains_voltage=3076
[0xc187: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>
[0xc187:1:0x0402]: initializing channel: from_cache: False
[0xc187] Extending timeout for 0x2f request
[0xc187: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>
[0xc187:1:0x0001]: initializing channel: from_cache: False
[0xc187] Extending timeout for 0x31 request
[0xc187: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>
[0xc187:1:0x0000]: initializing channel: from_cache: False
[0xc187:1:0x0019]: initializing channel: from_cache: False
[0xc187: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=47 command_id=Command.Read_Attributes_rsp>
[0xc187: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=49 command_id=Command.Read_Attributes_rsp>
[0xc187:1:0x0405]: 'async_initialize' stage succeeded
[0xc187:1:0x0001]: 'async_initialize' stage succeeded
[0xc187:1:0x0000]: 'async_initialize' stage succeeded
[0xc187:1:0x0402]: 'async_initialize' stage succeeded
[0xc187:1:0x0019]: 'async_initialize' stage succeeded
[0xc187](PS-SPRZMS-SLP3): power source: Battery or Unknown
[0xc187](PS-SPRZMS-SLP3): completed initialization
[0xc187: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=5 command_id=Command.Report_Attributes>
[0xc187:1:0x0402] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=int16s, value=2289>>]]
[0xc187:1:0x0402] Attribute report received: measured_value=2289
[0xc187: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=6 command_id=Command.Report_Attributes>
[0xc187:1:0x0405] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint16_t, value=358>>]]
[0xc187:1:0x0405] Attribute report received: measured_value=358

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

What does it mean that it uses the "Power endpoint with Main"?

@Adminiuga
Copy link
Contributor

What does it mean that it uses the "Power endpoint with Main"?

what you are referring to?

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

In the conversation with Plaid support, the specialist said: "it is using the Mains attribute within the Power Cluster"
What does this means? (Bear with me, I am just trying to learn)

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

It basically means the sensor reports its battery voltage on the zigbee attribute meant for mains voltage in the zigbee spec. In the zigbee spec there are defined clusters and attributes, when device follow them everything should just work, however some device like this one deviate from the spec in this case sending the battery voltage on the mains voltage attribute.

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

Ahh, and the mains voltage attribute is meant for NON battery operated devices?

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

yes

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

How do I verify/test this in my dev environment?

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

you can try and request the mains voltage attribute from power cluster in the ZHA config panel. I've had mixed results doing this, as the device does not send the voltage very often. you have to wake up the device when you query it, I do this by hitting it with the magnet, as I hit the button to request it.

@Adminiuga
Copy link
Contributor

https://zigbeealliance.org/wp-content/uploads/2019/12/07-5123-06-zigbee-cluster-library-specification.pdf PDF page 110

There's already quirk which translates mains voltage into battery ones, although IIRC regular battery voltage is in 100mV (0.1V) and plaid seems to report in mV, so it should divide the actual value by /100 prior sending it as a battery voltage 🤷

@tube0013 do you get battery voltage?

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

I have tried that, what value to use for the zigbee?
When I click on "get zigbee attr" nothing happens?

image

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

not reliably, I got it above after pulling and re-inserting the battery. In the past (my original issue for this) I was able to query it but I have yet been able to do that again. It is super "shy" about sending voltage.

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

Does the current quirk take into count the 3volt battery as well, as I don't think battery size is sent

@tube0013
Copy link
Contributor

tube0013 commented Jun 3, 2020

@ocalvo you can test it by requesting the Temperature or Humidity via their clusters, it will be much more responsive for those, wake it and request at the same time.

@Adminiuga
Copy link
Contributor

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

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

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
Copy link
Author

ocalvo commented Jun 3, 2020

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
Copy link
Contributor

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

@ocalvo
Copy link
Author

ocalvo commented Jun 3, 2020

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
Copy link
Contributor

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
Copy link
Contributor

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

@tube0013
Copy link
Contributor

tube0013 commented Jun 4, 2020

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
Copy link
Contributor

tube0013 commented Jun 4, 2020

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
Copy link
Contributor

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
Copy link
Contributor

tube0013 commented Jun 4, 2020

yes don't get anything when I request that attribute

@Adminiuga
Copy link
Contributor

Do you get None ???

@ocalvo
Copy link
Author

ocalvo commented Jun 4, 2020

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

yep, got one. need to automate watering.
Try this version #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
Copy link
Contributor

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

@ocalvo
Copy link
Author

ocalvo commented Jun 14, 2020

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
Copy link
Contributor

tube0013 commented Jun 14, 2020

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

@ocalvo
Copy link
Author

ocalvo commented Jun 14, 2020

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

@tube0013
Copy link
Contributor

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
Copy link
Author

ocalvo commented Jun 14, 2020

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
Copy link
Author

ocalvo commented Jun 14, 2020

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
Copy link
Author

ocalvo commented Jun 14, 2020

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
Copy link
Contributor

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
Copy link
Author

ocalvo commented Jun 14, 2020

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

@dmulcahey
Copy link
Collaborator

@Adminiuga is this resolved? Good to close?

@Adminiuga
Copy link
Contributor

Yes, seems to work.

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

No branches or pull requests

4 participants