Attribute reporting on startup happens before the device is connected (TZ-292)

[nomis]

Typically when a device is restarted some of its attributes will be reset to a different state (e.g. an on/off outlet will be "off" if the power is reconnected).

With other Zigbee devices, if I restart the device I get an immediate report of the state when it reconnects to the network.

There's automatic attribute reporting on startup but it happens before the device is connected. What's happening here is that the min_interval is 5 seconds and it takes more than 5 seconds to connect. This results in attempts to send messages to devices that are unreachable because we're not connected. If the min_interval is 0 then the reporting can happen so early that the failures don't get reported as an event. It then doesn't resend reports until the max_interval is reached.

I have wrapped zb_zcl_send_report_attr_command in order to fix #86 and observe when it sends reports:

2023-09-16 14:44:05.591259 D (539) nutt.ZigbeeDevice: Zigbee stack initialized
2023-09-16 14:44:05.594504 I (539) nutt.ZigbeeDevice: Device address: 40:4c:ca:ff:fe:42:30:78/0xaac6 (network configured)
2023-09-16 14:44:05.599736 D (539) nutt.ZigbeeDevice: Connecting (ZDO Skip Start Up)
2023-09-16 14:44:10.591793 D (5539) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=11 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x408210ee
2023-09-16 14:44:10.599982 W (5539) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.612288 D (5539) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=21 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40821476
2023-09-16 14:44:10.620493 W (5559) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.632590 D (5569) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=31 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x408217fe
2023-09-16 14:44:10.640694 W (5579) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.653150 D (5589) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=61 cluster_id=15 cluster_role=1 attr_id=111 manuf_code=65535 attr=0x40821a14
2023-09-16 14:44:10.661547 W (5599) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.673535 D (5609) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=71 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40821bbe
2023-09-16 14:44:10.685943 D (5619) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=81 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40821d2a
2023-09-16 14:44:10.698415 D (5629) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=12 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40822706
2023-09-16 14:44:10.706701 W (5639) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.718843 D (5649) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=22 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40822a8e
2023-09-16 14:44:10.727164 W (5659) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.739203 D (5669) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=32 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40822e16
2023-09-16 14:44:10.747395 W (5679) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.759883 D (5689) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=62 cluster_id=15 cluster_role=1 attr_id=111 manuf_code=65535 attr=0x4082302c
2023-09-16 14:44:10.768092 W (5709) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.780130 D (5709) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=72 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x4082321e
2023-09-16 14:44:10.793041 D (5729) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=82 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x4082338a
2023-09-16 14:44:10.805138 D (5739) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=13 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40823d66
2023-09-16 14:44:10.813477 W (5749) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.825517 D (5759) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=23 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x408240ee
2023-09-16 14:44:10.833827 W (5769) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.845852 D (5779) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=33 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40824476
2023-09-16 14:44:10.854205 W (5789) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.866573 D (5799) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=63 cluster_id=15 cluster_role=1 attr_id=111 manuf_code=65535 attr=0x4082468c
2023-09-16 14:44:10.874763 W (5809) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.887133 D (5819) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=63 cluster_id=15 cluster_role=1 attr_id=85 manuf_code=65535 attr=0x40824696
2023-09-16 14:44:10.895560 W (5829) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.907585 D (5839) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=73 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40824836
2023-09-16 14:44:10.915967 W (5849) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.927897 D (5859) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=83 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x408249a2
2023-09-16 14:44:10.940253 D (5869) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=14 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x4082537e
2023-09-16 14:44:10.948670 W (5889) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.960674 D (5889) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=24 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40825706
2023-09-16 14:44:10.973090 D (5909) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=34 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40825a8e
2023-09-16 14:44:10.981470 W (5919) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:10.993777 D (5929) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=64 cluster_id=15 cluster_role=1 attr_id=111 manuf_code=65535 attr=0x40825ca4
2023-09-16 14:44:11.006348 D (5939) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=64 cluster_id=15 cluster_role=1 attr_id=85 manuf_code=65535 attr=0x40825cae
2023-09-16 14:44:11.018778 D (5949) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=74 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40825e4e
2023-09-16 14:44:11.027270 W (5959) nutt.ZigbeeDevice: Device unavailable (e0:79:8d:ff:fe:b3:dc:82/0x0000)
2023-09-16 14:44:11.039126 D (5969) nutt.ZigbeeDevice: zb_zcl_send_report_attr_command: ep=84 cluster_id=6 cluster_role=1 attr_id=0 manuf_code=65535 attr=0x40825fba
2023-09-16 14:44:13.821010 D (8759) nutt.ZigbeeDevice: Connecting (BDB Device Reboot)
2023-09-16 14:44:13.821456 I (8769) nutt.ZigbeeDevice: Joined network successfully (6f:06:fc:4a:5b:92:dd:9c/0x8813@26 as 0xaac6)

I can partially work around this by calling zb_zcl_find_reporting_info() and zb_zcl_put_reporting_info() as soon as it connects which has the side effect of resetting the reporting timer so that it runs at the next min_interval. This only produces a good outcome if the min_interval happens to be low enough. (I'm also overriding min_interval to be 0 because I don't like the hard-coded 5s default.)

Ideally it should always send a report immediately on connect if the system has restarted or there was a report attempted while disconnected. There's a zb_zcl_mark_attr_for_reporting() but it doesn't appear to trigger reports.

[xieqinan]

Hello @nomis ,

Regarding the reported attribute issue, if the attribute value is modified before the network startup, the phenomenon you described does indeed occur. This appears to have a minor impact on the Zigbee network, as the report will be transmitted again once it reaches the maximum reporting interval. We plan to optimize this by implementing the following:

1. Introduce a corresponding API for attribute reporting, which will assist users in managing and controlling attribute reports.
2. Restrict the report attribute command before the network is started up.

[nomis]

2. Restrict the report attribute command before the network is started up.

I'm not changing the value before the network is connected, this is the initial power on value.

It could change before the network is connected too (e.g. someone turns the switch on) so that cannot be restricted either.

[xieqinan]

Hello @nomis,

The attributes will not be reported before the Zigbee network starts up in esp-zboss-lib v1.0.0. Please test this behavior.

[nomis]

This appears to work as expected, and I can change the attribute value between:

• esp_zb_start(false) and esp_zb_bdb_start_top_level_commissioning()
• esp_zb_bdb_start_top_level_commissioning() and ESP_ZB_BDB_SIGNAL_STEERING