Unknown parser state with homebridge as accessory

[vilhalmer]

I just upgraded to hass 0.107.5, and during startup I get the following traceback:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 826, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 185, in data_received
    super().data_received(decrypted)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/controller/ip/connection.py", line 84, in data_received
    data = self.current_response.parse(data)
  File "/usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py", line 95, in parse
    raise HttpException("Unknown parser state")
aiohomekit.exceptions.HttpException: Unknown parser state

I took a look at the parser and it seems like the only way this can happen is if more data arrives after STATE_DONE is set.

The only accessory I'm using is actually homebridge, to use another layer of translation that hass can't do natively yet. It's definitely possible that homebridge does something strange compared to a real accessory. I attempted re-pairing just to verify that homebridge is the culprit, and indeed the traceback appeared immediately.

Let me know what info I can provide to help debug this!

[Jc2k]

Congrats on issue #1 ;) Homebridge has been a bit hit and miss so far. It does some stuff I know real HomeKit devices dont (like sending empty events as keep alives even when you havent turned push on at all). Did have a report of it working earlier today though.

I need you to modify your local copy of aiohomekit/http/response.py so that we can see whats in the buffer. Maybe something like this? https://gist.githubusercontent.com/Jc2k/c89e30fdc112b2329b12609bff8a9e07/raw/bee6b2950da45087addc7a8ffec5e3e1799e0a48/response.py

[vilhalmer]

Sorry for the delay, it has been a thoroughly weird week. I'll get this applied and report back.

[vilhalmer]

Is this the right URL? There's no diff between this and the version on master.

[Jc2k]

Oops! Lets try again. I think I mean this one but it's been a few days so I can't really remember what i was thinking...

[vilhalmer]

Here's the full startup log and me toggling the light off and on again at the end: https://paste.sr.ht/~vilhalmer/0a683c69d361fe16f13db811fbabc419429551bc

With the patch the traceback doesn't appear, but it still appears to be polling the state.

In case it's useful, the accessory is using this homebridge plugin: https://github.com/AMoo-Miki/homebridge-tuya-lan at tag 1.5.0-rc.12.

[Jc2k]

So that is a slightly older version of the parser - I suspect the bug was introduced trying to handle some devices that were returning HTML without setting a content-size. (They shouldn't be returning HTML full stop). Let me plug your responses into the test harness and see if they break master. If that doesn't i'll have to instrument the latest version of the parser and get you to try that.

Polling is expected at this stage. I expected some devices to claim to support events but then utterly fail. So at the moment events are on top of polling. The plan is to stabilise things then maybe reduce the frequency of some things getting polled.

Thanks for like to plugin. I don't know enough homebridge for it to help, but it will be interesting to track which plugins work and how well they work in the long run.

[Jc2k]

Reproduced it with this payload:

2020-03-29 17:57:54 DEBUG (MainThread) [aiohomekit.http.response] parse: bytearray(b'HTTP/1.1 207 Multi-Status\r\nContent-Type: application/hap+json\r\nDate: Sun, 29 Mar 2020 21:57:54 GMT\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n33\r\n{"characteristics":[{"aid":2,"iid":10,"status":0}]}\r\n0\r\n\r\nHTTP/1.1 207 Multi-Status\r\nContent-Type: application/hap+json\r\nDate: Sun, 29 Mar 2020 21:57:54 GMT\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n33\r\n{"characteristics":[{"aid":2,"iid":10,"status":0}]}\r\n0\r\n\r\n')

[Jc2k]

Can you try replacing your /usr/local/lib/python3.7/site-packages/aiohomekit/http/response.py with the one from master?

[vilhalmer]

This seems to fix it!

However, when controlling the accessory the state still doesn't update until the next poll interval. I was hoping that the parsing issue was preventing it from setting up events and thus falling back to polling, but maybe homebridge isn't advertising support or similar? (This discussion can go elsewhere if it would make more sense.)

[Jc2k]

There are 2 possibilities where this is a problem on the HA side:

• The characteristic doesn't advertise event support, so we don't turn it on
• Subscribing fails so events get disabled until restart. There would be a log message if this had happened though.

Looking at the logs you sent previously I can see we do try to enable events for characteristic 10 of accessory 2 only. homebridge says this worked. We never see it push any data, though.

Do you have an ios device? That would be the quickest way to tell if this is still something I can help with. Or can you verify with wireshark/tcpdump that the Tuy API pushes something to homebridge when something changes?

[vilhalmer]

I do have iOS, I'll try pairing directly and see which side this is on. I'll open a new issue (or a PR maybe!) if appropriate. Thanks for your assistance, happy to get the traceback resolved either way! :)

[Jc2k]

Brilliant @vilhalmer! Thanks for your help tracking this exception down. Good luck and don't hesitate to reach out if you have any more problems.