Core: Unknown Cluster Errors & Unexpected Response filling log file

[WedHumpDay]

Home Assistant release with the issue:

0.87.0

Last working Home Assistant release (if known):

Unknown

Operating environment (Hass.io/Docker/Windows/etc.):

Hass in VM Environment
Linux ha 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64

Component/platform:

Description of problem:

Seeing Unknown Cluster Errors & Unexpected Response consistently throughout the log file.
The Unexpected responses is immediately followed by Unknown Cluster. Both appear to be in relation as they come in the same for each occurrence. The 'TSN=##' is different for each log entry.
Have not been able to correlate

If needing additional logging, please reach out via PM outlining how to enable to capture.

Displayed Errors:

[0x9351:2] Message on unknown cluster 0x0001
7:17 AM util/async_.py (WARNING)
Unexpected response TSN=103 command=266 args=b' \x00 \x1b'
7:17 AM util/async_.py (WARNING)
[0xb077:2] Message on unknown cluster 0x0001
7:12 AM util/async_.py (WARNING)
Unexpected response TSN=51 command=266 args=b' \x00 \x1b'
7:12 AM util/async_.py (WARNING)
[0x345b:2] Message on unknown cluster 0x0001
7:07 AM util/async_.py (WARNING)
Unexpected response TSN=24 command=266 args=b' \x00 \x1b'
7:07 AM util/async_.py (WARNING)
[0xa0fa:2] Message on unknown cluster 0x0001
7:06 AM util/async_.py (WARNING)
Unexpected response TSN=35 command=266 args=b' \x00 \x1b'
7:06 AM util/async_.py (WARNING)

Log File Output:

2019-02-11 07:06:23 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=35 command=266 args=b' \x00 \x1b'
2019-02-11 07:06:23 WARNING (MainThread) [zigpy.endpoint] [0xa0fa:2] Message on unknown cluster 0x0001

2019-02-11 07:07:38 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=24 command=266 args=b' \x00 \x1b'
2019-02-11 07:07:38 WARNING (MainThread) [zigpy.endpoint] [0x345b:2] Message on unknown cluster 0x0001

2019-02-11 07:12:14 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=51 command=266 args=b' \x00 \x1b'
2019-02-11 07:12:14 WARNING (MainThread) [zigpy.endpoint] [0xb077:2] Message on unknown cluster 0x0001

2019-02-11 07:17:40 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=103 command=266 args=b' \x00 \x1b'
2019-02-11 07:17:40 WARNING (MainThread) [zigpy.endpoint] [0x9351:2] Message on unknown cluster 0x0001

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

Traceback (if applicable):

Additional information:

[cgarwood]

cc @dmulcahey

[dmulcahey]

Is this a device that was just joined? I’ve seen this happen when a device isn’t joined to the network correctly.

[WedHumpDay]

No new devices.. I have validated that none of the devices were trying to rejoin. In fact, I cleared the logs, ensure all devices were online and within 15 minutes it started to populate the messages.

Here are the list of devices. Only have ZHA devices, no ZWave.

[dmulcahey]

@ptdalen what hardware are you running on? are these the only 2 times that this has happened? or has it been happening sporadically and now it just appears to happen faster?

[dmulcahey]

@WedHumpDay can you try something for me?

7:17 AM util/async_.py (WARNING) [0xb077:2] Message on unknown cluster 0x0001

find one of these devices that matches these log entries and reconfigure it.

You can figure out which device the message belongs to by matching up the nwk value on the zha entity more info dialog (or search the states screen) with the first part of the message in the brackets. Ex:

0xb077

That should be the value for the nwk attribute on one of your zha entities.

Once you identify a device, go to the zha config panel and select the device from the list then trigger/activate/trip the device so it is awake and click the reconfigure button.

Then watch the logs for a bit and let me know if you still see Message on unknown cluster messages for that nwk value specifically. If they stop for that device you'll have to do this for the remainder of the devices that exhibit this behavior

[dmulcahey]

@ptdalen Please move your issue to its own issue as it is a different issue.

[ptdalen]

Moving my comments :-)
For reference, I'm running on older i3 computer running ubuntu in a VENV. This has happened only twice in the past several months, and both times were while I was on vacation, and the zigbee devices had not reported (on/off/open/closed, etc) for a week. Otherwise they have been very stable

[WedHumpDay]

@dmulcahey

Found the entry. Oddly enough, this is a motion & temperature sensor sitting in a closet and no movement in there.

---

zha.zha_centralite_motion_sensor_a_0e0595b4 | online | ieee: 00:0d:6f:00:0e:05:95:b4 nwk: 0xb077 lqi: 253 friendly_name: Motion/Temperature - Study Closet rssi: -74

Performed your steps as indicated:
1) Cleared the log files
2) Tripped the sensor
3) Reconfigured Node

Log Files:

---

---

2019-02-11 17:03:35 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/tasks.py", line 241, in _step
    result = coro.throw(exc)
  File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/components/zha/binary_sensor.py", line 147, in async_configure
    await self._ias_zone_cluster.write_attributes({'cie_addr': ieee})
  File "/srv/homeassistant/lib/python3.5/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/srv/homeassistant/lib/python3.5/site-packages/bellows/zigbee/application.py", line 241, in request
    v = await send_fut
  File "/usr/lib/python3.5/asyncio/futures.py", line 380, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.5/asyncio/tasks.py", line 304, in _wakeup
    future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
zigpy.exceptions.DeliveryError: Message send failure: EmberStatus.DELIVERY_FAILED
2019-02-11 17:03:36 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=229 command=32801 args=[<Status.SUCCESS: 0>]
2019-02-11 17:03:40 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=234 command=7 args=[[<ConfigureReportingResponseRecord status=0 direction=0 attrid=0>]]
2019-02-11 17:04:01 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=48 command=266 args=b' \x00 \x1b'
2019-02-11 17:04:01 WARNING (MainThread) [zigpy.endpoint] [0x9351:2] Message on unknown cluster 0x0001

---

While writing this reply there are couple new entries:

[0xb077:2] Message on unknown cluster 0x0001
5:12 PM util/async_.py (WARNING)
Unexpected response TSN=3 command=266 args=b' \x00 \x1b'
5:12 PM util/async_.py (WARNING)

[dmulcahey]

Can you bring the device near the coordinator and try again? Also, is there a button on it that you can tap every so often to keep it awake?

[WedHumpDay]

Sensor moved within inches of coordinator.
I kept pressing the side button to keep awake and ensure motion was occurring during the process.
Also notice a bunch of NUL's on the first line of the home-assistant.log file.

---

[0x345b:2] Message on unknown cluster 0x0001
6:39 PM util/async_.py (WARNING)
Unexpected response TSN=78 command=266 args=b' \x00 \x1b'
6:39 PM util/async_.py (WARNING)
Unexpected response TSN=9 command=11 args=[0, <Status.SUCCESS: 0>]
6:39 PM util/async_.py (WARNING)
Failed to parse message (b'080404701000') on cluster 1280, because 112 is not a valid Status
6:38 PM util/async_.py (ERROR)
Error doing job: Task exception was never retrieved
6:38 PM components/zha/binary_sensor.py (ERROR)
Unexpected response TSN=1 command=32801 args=[<Status.SUCCESS: 0>]
6:38 PM util/async_.py (WARNING)

---

2019-02-11 18:38:50 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=1 command=32801 args=[<Status.SUCCESS: 0>]
2019-02-11 18:38:54 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/tasks.py", line 241, in _step
    result = coro.throw(exc)
  File "/srv/homeassistant/lib/python3.5/site-packages/homeassistant/components/zha/binary_sensor.py", line 147, in async_configure
    await self._ias_zone_cluster.write_attributes({'cie_addr': ieee})
  File "/srv/homeassistant/lib/python3.5/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/srv/homeassistant/lib/python3.5/site-packages/bellows/zigbee/application.py", line 241, in request
    v = await send_fut
  File "/usr/lib/python3.5/asyncio/futures.py", line 380, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/usr/lib/python3.5/asyncio/tasks.py", line 304, in _wakeup
    future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
zigpy.exceptions.DeliveryError: Message send failure: EmberStatus.DELIVERY_FAILED
2019-02-11 18:38:59 ERROR (MainThread) [bellows.zigbee.application] Failed to parse message (b'080404701000') on cluster 1280, because 112 is not a valid Status
2019-02-11 18:39:04 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=9 command=11 args=[0, <Status.SUCCESS: 0>]
2019-02-11 18:39:09 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=78 command=266 args=b' \x00 \x1b'
2019-02-11 18:39:09 WARNING (MainThread) [zigpy.endpoint] [0x345b:2] Message on unknown cluster 0x0001
2019-02-11 18:42:49 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=91 command=266 args=b' \x00 \x1b'
2019-02-11 18:42:49 WARNING (MainThread) [zigpy.endpoint] [0xb077:2] Message on unknown cluster 0x0001

[WedHumpDay]

Looking further at this, appears this is occurring with all the same type sensors.. So far I have correlated the 'nwk' entries to:

Sylvania Smart Home E21266 72923 Sylvania LIGHTIFY Motion and Temperature Sensor, White
https://www.amazon.com/gp/product/B01LXPGXQ1/ref=ppx_yo_dt_b_asin_title_o01__o00_s00?ie=UTF8&psc=1

0x345b
0xb077
0x9351
0xa0fa

---

2019-02-11 18:39:09 WARNING (MainThread) [zigpy.endpoint] [0x345b:2] Message on unknown cluster 0x0001
2019-02-11 18:42:49 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=91 command=266 args=b' \x00 \x1b'
2019-02-11 18:42:49 WARNING (MainThread) [zigpy.endpoint] [0xb077:2] Message on unknown cluster 0x0001
2019-02-11 18:49:16 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=80 command=266 args=b' \x00 \x1b'
2019-02-11 18:49:16 WARNING (MainThread) [zigpy.endpoint] [0x9351:2] Message on unknown cluster 0x0001

---

I havent seen this in 0.85.x., cannot recall if this was in 0.86.x.
Anything else you like for me try?

[dmulcahey]

Maybe completely remove one and rejoin it. If that doesn’t work I’ll have to take a closer look.

[WedHumpDay]

@dmulcahey
This is interesting....
Looks like the motion sensor entity is no longer available after removing and rejoining the sensor.

I usually have 4 entries:

• Online status
• Motion
• Battery
• Temperature

Now, only have 3 entries:

• Online status
• Battery
• Temperature

Motion entity is missing! Could the reason for the Unexpected Response be because its not truly finding the original ZHA motion entity? Why would this change after removal and rejoining?

Removed - binary_sensor.centralite_motion_sensor_a_0e0595b4_2
Rejoined - zha.zha_0e0595b4

[dmulcahey]

Ok that’s confusing. Can you remove the device again and then set the logging config for bellows, Zigpy and zha to debug, restart HA and rejoin it? Put the full log (from the restart on) on pastebin or something similar and link it here.

[WedHumpDay]

@dmulcahey
Morning, ran through your request.

Log Link Removed

After 1st restart and performing rejoin, entities restored. Exception to the online, came up as: zha.zha_0e0595b4

Here is what interesting again.
Performed a 2nd restart and ALL entities are back to normal. This time, left the sensor joined for the restart.

[ptdalen]

I'm seeing this error in my logs, but dont know how to remove the Unknown cluster. 0x8038 does not correlate to anything I can find.

2019-02-11 08:25:56 WARNING (MainThread) [zigpy.zdo] Unknown ZDO cluster 0x8038
2019-02-11 08:25:56 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=0 command=32824 args=b'\x00\x00\xf8\xff\x07\x16\x00\t\x00\x10\xcd\xba\xc2\xb4\xc9\xbd\xbf\xbc\xb9\xbc\xb7\xdc\xdd\xd7\xbb\xad'

[dmulcahey]

@ptdalen that's a Management Network Update Notify operation... what type of stick do you have and are you running custom libs for bellows or zigpy (ex: Yoda-x versions?)

[ptdalen]

I have a HUSBZB-1, but I'm not running other than standard stuff. The closest I have to non standard is the Hue custom component, but I just use that for a few hue things

[WedHumpDay]

@dmulcahey - Let me know once you have review the log file. I would like to close the provided link.

[dmulcahey]

I saved it... go ahead and kill it if you want.

[dshokouhi]

I think one of my devices (iris contact sensor) is experiencing this issue too. I keep seeing the following errors about every 10 minutes

2019-02-20 12:50:05 WARNING (MainThread) [bellows.zigbee.application] Unexpected response TSN=27 command=266 args=b' \x00 \x1c'
2019-02-20 12:50:05 WARNING (MainThread) [zigpy.endpoint] [0x35f0:2] Message on unknown cluster 0x0001

I see we mentioned to find the device (35f0 in this case) and reconfigure the node in the ZHA panel, when I do that I get this error which seems to be different. I am keeping the device awake by opening and closing the sensor every few seconds, not sure if that is correct for this device.

2019-02-20 12:55:09 ERROR (MainThread) [bellows.zigbee.application] Failed to parse message (b'082104701000') on cluster 1280, because 112 is not a valid Status
2019-02-20 12:55:19 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/zha/binary_sensor.py", line 147, in async_configure
    await self._ias_zone_cluster.write_attributes({'cie_addr': ieee})
  File "/srv/homeassistant/lib/python3.6/site-packages/zigpy/device.py", line 89, in request
    expect_reply=expect_reply,
  File "/srv/homeassistant/lib/python3.6/site-packages/bellows/zigbee/application.py", line 245, in request
    v = await asyncio.wait_for(reply_fut, timeout)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 362, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

The device in question actually has 0 issues and works as expected so not sure what these errors are about. It is also 5 ft away from the controller so its very close. I am also on 0.87.1 have not updated to 0.88 yet not sure if its resolved there I plan to update in a few days.

[dmulcahey]

@dshokouhi the unexpected response messages happen sometimes from retransmissions of messages and can be safely ignored. I am going to talk to the other folks about making these debug instead of warning so that we can avoid the log noise.

the other message is a timeout during reconfiguration. It works still because it was already successfully configured from when it joined. There is no need to reconfigure the devices from the "unexpected" warnings.

[ghost]

I was searching for this error and came across this issue. I have 3 Philips Hue color globes (gen 3) and A Hue Go Lamp connected via ZHA and I am getting the same error on each device. Each device was removed and newly added using the Permit function in the panel in Hassio 0.88.0.
I reset each globe to factory default before the Permit was done.

Unexpected response TSN=26 command=1 args=[[ReadAttributeRecord attrid=0 status=0 value=Bool.false]]
6:05 PM __main__.py (WARNING)
Unexpected response TSN=23 command=1 args=[[ReadAttributeRecord attrid=16394 status=0 value=31]]
6:05 PM __main__.py (WARNING)
Unexpected response TSN=9 command=1 args=[[ReadAttributeRecord attrid=0 status=134]]
6:05 PM __main__.py (WARNING)
Unexpected response TSN=2 command=1 args=[[ReadAttributeRecord attrid=0 status=0 value=90]]
6:05 PM __main__.py (WARNING)

I have 4 Philips Hue devices connected, 2 Hue GU10 Spots, 1 A19 color and 1 Hue Go Lamp, so it appears there is an error line for each device.

[dmulcahey]

Again, these aren’t errors. We’ll see what we can do to change the log level to reduce the noise in the logs.

[dmulcahey]

@Adminiuga I think we only fixed half of this. We should bump "unknown cluster" to debug as well.

[dmulcahey]

fixed by linked pr directly above.