Homekit Camera connection issue since 2024.8.2

Minims commented 2 months ago

The problem

Hello,

Since the upgrade from 2024.8.1 to 2024.8.2, the homekit connection to my somfy indoor camera does not work anymore. Rolling back to 2024.8.1 fix the issue

What version of Home Assistant Core has the issue?

core-2024.8.2

What was the last working version of Home Assistant Core?

core-2024.8.1

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

homekit bridge

Link to integration documentation on our website

https://www.home-assistant.io/integrations/homekit/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2024-08-16 22:37:04.438 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorSocketTransport._call_connection_lost(None) (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1181, in _call_connection_lost
    super()._call_connection_lost(exc)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 901, in _call_connection_lost
    self._protocol.connection_lost(exc)
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 89, in connection_lost
    self._cancel_pending_requests()
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 162, in _cancel_pending_requests
    result.set_exception(AccessoryDisconnectedError("Connection closed"))
asyncio.exceptions.InvalidStateError: invalid state

Additional information

Might be related to :

https://github.com/home-assistant/core/commit/725e2f16f5ee341db04bc0df1e16aba99e7b864d

or / and

https://github.com/home-assistant/core/commit/a23b063922454bdd386dc7ffddd1a4529fc608eb

home-assistant[bot] commented 2 months ago

Hey there @bdraco, mind taking a look at this issue as it has been labeled with an integration (homekit) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `homekit` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign homekit` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

homekit documentation homekit source _{^{(message by IssueLinks)}}

bdraco commented 2 months ago

There was a fix for not reconnecting after the connection drops in 2024.8.2 but it looks like your device causes the connection drop code to run in a different order than most other devices.

Can you provide debug logs?

bdraco commented 2 months ago

https://www.home-assistant.io/docs/configuration/troubleshooting/

bdraco commented 2 months ago

https://github.com/Jc2k/aiohomekit/pull/377 will probably fix it, but we will need logs to confirm

maxi1134 commented 2 months ago

Jc2k/aiohomekit#377 will probably fix it, but we will need logs to confirm

I have this issue with atwo Aqara FP2 Sensors:

I get this error in the logs:

2024-08-17 15:14:43.244 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorSocketTransport._call_connection_lost(None) (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1181, in _call_connection_lost
    super()._call_connection_lost(exc)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 901, in _call_connection_lost
    self._protocol.connection_lost(exc)
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 89, in connection_lost
    self._cancel_pending_requests()
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 162, in _cancel_pending_requests
    result.set_exception(AccessoryDisconnectedError("Connection closed"))
asyncio.exceptions.InvalidStateError: invalid state

Minims commented 2 months ago

Here a part of my debug logs

2024-08-17 21:28:07.960 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1 (Identifier): (17 bytes/<class 'bytearray'>) ***
  10 (Signature): (64 bytes/<class 'bytearray'>) ****
]

2024-08-17 21:28:07.960 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (36 bytes/<class 'bytes'>) b'***'
  10 (Signature): (64 bytes/<class 'bytes'>) b'****'
]

2024-08-17 21:28:07.961 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x03
  5 (EncryptedData): (120 bytes/<class 'bytes'>) b'***
]

2024-08-17 21:28:07.961 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 125\r\nContent-Type: application/pairing***'
2024-08-17 21:28:08.268 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'\x06\x01\x04')
2024-08-17 21:28:08.269 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x04
]

2024-08-17 21:28:08.269 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-17 21:28:08.269 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-17 21:28:08.269 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for ***
2024-08-17 21:28:08.269 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session
2024-08-17 21:28:08.269 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for ***
2024-08-17 21:28:08.269 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /resource HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 70\r\nContent-Type: application/hap+json\r\n\r\n{"aid":1,"resource-type":"image","image-width":640,"image-height":480}'
2024-08-17 21:28:08.672 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /resource HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 70\r\nContent-Type: application/hap+json\r\n\r\n{"aid":1,"resource-type":"image","image-width":640,"image-height":480}'
2024-08-17 21:28:09.172 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /resource HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 70\r\nContent-Type: application/hap+json\r\n\r\n{"aid":1,"resource-type":"image","image-width":640,"image-height":480}'
2024-08-17 21:28:09.673 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /resource HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 70\r\nContent-Type: application/hap+json\r\n\r\n{"aid":1,"resource-type":"image","image-width":640,"image-height":480}'
2024-08-17 21:28:10.019 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-17 21:28:10.019 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorSocketTransport._call_connection_lost(None) (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1181, in _call_connection_lost
    super()._call_connection_lost(exc)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 901, in _call_connection_lost
    self._protocol.connection_lost(exc)
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 89, in connection_lost
    self._cancel_pending_requests()
  File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 162, in _cancel_pending_requests
    result.set_exception(AccessoryDisconnectedError("Connection closed"))
asyncio.exceptions.InvalidStateError: invalid state
2024-08-17 21:28:10.020 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-17 21:28:10.020 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-17 21:28:10.040 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x01
  3 (PublicKey): (32 bytes/<class 'bytes'>) b'****'
]

bdraco commented 2 months ago

Should be fixed via #124115 in 2024.8.3

You can run it as a custom component in the mean time:

cd /config
curl -o- -sSL https://gist.githubusercontent.com/bdraco/43f8043cb04b9838383fd71353e99b18/raw/core_integration_pr | bash /dev/stdin -d homekit_controller -p 124115

Minims commented 2 months ago

So i have upgrade to 2024.8.2 and install the https://github.com/home-assistant/core/pull/124115

root:~/config [main]# ls custom_components/homekit_controller/__init__.py
custom_components/homekit_controller/__init__.py

But i have still no camera working :-/ It seems the connexion is looping but without real error.

2024-08-18 08:34:04.495 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-18 08:34:04.495 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-18 08:34:04.495 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-18 08:34:04.546 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:04.546 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 37\r\nContent-Type: application/pairing+****'
2024-08-18 08:34:05.057 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'***')
2024-08-18 08:34:05.057 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:05.058 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:05.059 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:05.059 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:05.059 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 125\r\nContent-Type: application/pairing+***
2024-08-18 08:34:05.365 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'\x06\x01\x04')
2024-08-18 08:34:05.365 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:05.366 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-18 08:34:05.366 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-18 08:34:05.366 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session
2024-08-18 08:34:05.440 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-18 08:34:05.441 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-18 08:34:05.441 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-18 08:34:05.444 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:05.444 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 37\r\nContent-Type: application/pairing+****'
2024-08-18 08:34:05.717 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'***)
2024-08-18 08:34:05.718 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:05.718 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:05.719 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:05.719 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:05.719 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b"POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 125\r\nContent-Type: application/pairing+tlv8\r\n\r\n\x06\x01\x03\x05x\x1d\xabA\xf9\x88$\xb0%\xec\x80E\xe0\x11\xb1\xbe\xe7>x\x97\xea\xd5\x05\xef-\xd9\x0b\xba\xaa\xa3\xbeP\xc7&B[\n\xb0k=\x8c\x85t \xd2\\\x10\x9e\xa1\xab4\xad\xcaA\x85\x87~oq\xb2(X\x80d\x07a\xfdI\x058\x0e\xb1~\x0bCv\xdad\x98\xf73\xf8\xe5@\xc3\xe7\xe6\xac\xda%>|\xba\r+<\xf9>$\xb8/%F'\xe1M\xc2F\x023\xa0ws\x93\xc0;\xa2q\xf59\xbb"
2024-08-18 08:34:06.098 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'\x06\x01\x04')
2024-08-18 08:34:06.098 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:06.098 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-18 08:34:06.098 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-18 08:34:06.098 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session
2024-08-18 08:34:06.139 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-18 08:34:06.140 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-18 08:34:06.140 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-18 08:34:06.179 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:06.180 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 37\r\nContent-Type: application/pairing+***'
2024-08-18 08:34:06.750 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'***')
2024-08-18 08:34:06.751 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:06.751 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
2024-08-18 08:34:06.751 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:06.751 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
2024-08-18 08:34:06.751 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b"POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 125\r\nContent-Type: application/pairing+****."

Minims commented 2 months ago

Latest test, i have roll back to https://github.com/home-assistant/core/pull/123601

and it seems working. i have some reconnection, but i can read the video stream.

root:~/config [main]# curl -o- -sSL https://gist.githubusercontent.com/bdraco/43f8043cb04b9838383fd71353e99b18/raw/core_integration_pr | bash /dev/stdin -d homekit_controller -p 123601

Going to https://github.com/home-assistant/core/pull/123669 and problem is back.

@bdraco can we reopen, or do i need to make a new issue ? thanks.

bdraco commented 2 months ago

Can you provide a link to purchase this device?

Minims commented 2 months ago

Can you provide a link to purchase this device?

Here it is : https://boutique.somfy.fr/somfy-indoor-camera.html

bdraco commented 2 months ago

Sadly it looks like they don’t ship to the US

Minims commented 2 months ago

I have check a bit how it works and i think that on stream start, it opens the shutter if not already opened, then stream.

BUT the stream might work for about 90 to 120 seconds. On stream stop, i think it has to maybe reconnect and re ask for the stream in loop.

this is how the somfy api seems working with the ios application. I think the homekit function works on top of the same calls so might have the same behavior.

so what have change that block the new stream call

aredon commented 2 months ago

I believe I may have a similar issue but I'm unsure what device it is related to. Possibly my Amcrest Cameras? This error filled my logs several million times before I caught the machine freezing up. There was a bunch of spam about closed SSL connections prior to this.

2024-08-18 10:47:22.089 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback None() (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
TypeError: 'NoneType' object is not callable

caesar1987sk commented 2 months ago

I have same issue, with tado gateway It was working in 2024.7.x, after update to 2024.8.2 it's failing

`Logger: homeassistant Source: /usr/src/homeassistant/homeassistant/runner.py:148 First occurred: 17:42:44 (3 occurrences) Last logged: 17:44:02

Error doing job: Exception in callback _SelectorSocketTransport._call_connection_lost(None) (None) Traceback (most recent call last): File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 1181, in _call_connection_lost super()._call_connection_lost(exc) File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 901, in _call_connection_lost self._protocol.connection_lost(exc) File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 89, in connection_lost self._cancel_pending_requests() File "/usr/local/lib/python3.12/site-packages/aiohomekit/controller/ip/connection.py", line 162, in _cancel_pending_requests result.set_exception(AccessoryDisconnectedError("Connection closed")) asyncio.exceptions.InvalidStateError: invalid state`

Minims commented 2 months ago

updated to 2024.8.3, issue still there. i have roll back to https://github.com/home-assistant/core/pull/123601

bdraco commented 2 months ago

updated to 2024.8.3, issue still there. i have roll back to #123601

Please post the new full traceback. Thanks

home-assistant[bot] commented 2 months ago

Hey there @jc2k, mind taking a look at this issue as it has been labeled with an integration (homekit_controller) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `homekit_controller` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign homekit_controller` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

homekit_controller documentation homekit_controller source _{^{(message by IssueLinks)}}

Minims commented 2 months ago

here it is :

2024-08-25 22:11:01.888 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'*****')
2024-08-25 22:11:01.888 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:01.888 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-25 22:11:01.889 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-25 22:11:01.889 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for XX:XX:XX:XX:XX:XX
2024-08-25 22:11:01.889 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'*****'
2024-08-25 22:11:01.926 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-25 22:11:01.928 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-25 22:11:01.928 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-25 22:11:01.977 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  3 (PublicKey): (32 bytes/<class 'bytes'>) b'*****'
]

2024-08-25 22:11:01.977 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'*****'
2024-08-25 22:11:02.157 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b"\x06\x01\x02\x03 \xd3\xbc{,\xacKt\x1a+6S\xa2\xa6Ze\x11\xe7\t\x0310\x03\xa1\x80\xc4\xa9\xc0\xd0\x96\xc5\x9fl\x05e\xf3\xb8u\xb2\xfd\x1cA\xa9 C\x92\xb4\x02\x16\xa7\xf97B\xbb\xee\\\x90\xde\x89T_g\x88\xa8\'D\xbd#\xf8Wd\x89[\xfd\xd2\xc3{>0\x93\xcf\x87\x06H\x18\xd8\x8b\x86\xc5\xef\xac\x06U\x7f\x18g\r\xc9\xbc\x195\x9f\x13t~\xb6\xfc\x1d(\xd92\x82\x0c\x87\x8d\xaau2\x00J\x0eNe\x99\x01\xac\xed\xee^\x02O\xd8\xfcx\xc2\xfc")
2024-08-25 22:11:02.157 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  3 (PublicKey): (32 bytes/<class 'bytearray'>) 0x*****
  5 (EncryptedData): (101 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:02.157 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1 (Identifier): (17 bytes/<class 'bytearray'>) 0x*****
  10 (Signature): (64 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:02.158 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (36 bytes/<class 'bytes'>) b'*****'
  10 (Signature): (64 bytes/<class 'bytes'>) b'*****'
]

2024-08-25 22:11:02.158 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  5 (EncryptedData): (120 bytes/<class 'bytes'>) b'*****'
]

2024-08-25 22:11:02.158 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'*****'
2024-08-25 22:11:02.426 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'*****')
2024-08-25 22:11:02.426 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:02.426 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-25 22:11:02.426 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-25 22:11:02.426 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for XX:XX:XX:XX:XX:XX
2024-08-25 22:11:02.426 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session
2024-08-25 22:11:02.456 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.
2024-08-25 22:11:02.456 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Starting reconnect loop to ['192.168.1.53']:5052
2024-08-25 22:11:02.456 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Attempting connection to ['192.168.1.53']:5052
2024-08-25 22:11:02.469 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  3 (PublicKey): (32 bytes/<class 'bytes'>) b"****"
]

2024-08-25 22:11:02.469 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b"POST /pair-verify HTTP/1.1\r\nHost: 192.168.1.53\r\nContent-Length: 37\r\nContent-Type: application/pairing+tlv80+***"
2024-08-25 22:11:02.825 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'*****')
2024-08-25 22:11:02.826 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  3 (PublicKey): (32 bytes/<class 'bytearray'>) 0x*****
  5 (EncryptedData): (101 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:02.826 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  1 (Identifier): (17 bytes/<class 'bytearray'>) 0x*****
  10 (Signature): (64 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:02.826 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (36 bytes/<class 'bytes'>) b'*****'
  10 (Signature): (64 bytes/<class 'bytes'>) b'*****'
]

2024-08-25 22:11:02.826 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
  5 (EncryptedData): (120 bytes/<class 'bytes'>) b'*****'
]

2024-08-25 22:11:02.827 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw request: b'*****'
2024-08-25 22:11:03.057 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.53: raw response: bytearray(b'*****')
2024-08-25 22:11:03.058 DEBUG (MainThread) [aiohomekit.protocol.tlv] receiving [
  6 (State): (1 bytes/<class 'bytearray'>) 0x*****
]

2024-08-25 22:11:03.058 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Secure connection to 192.168.1.53:5052 established
2024-08-25 22:11:03.058 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{}
2024-08-25 22:11:03.058 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for XX:XX:XX:XX:XX:XX
2024-08-25 22:11:03.058 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session

The first connexion is working. i see the strem for about 90s. Then on reconnection it's looping on connected/lost and there is no more stream

Minims commented 2 months ago

FYI it seems rolling back this on line 577 fix my issue. but don't know why.

https://github.com/Jc2k/aiohomekit/blob/fcb57093465167d22eefdeabf62802a6b1ac8a1e/aiohomekit/controller/ip/connection.py#L577

        loop = asyncio.get_running_loop()

to

        loop = asyncio.get_event_loop()

bdraco commented 2 months ago

That would imply there is a bug that is creating a second event loop.

bdraco commented 2 months ago

2024-08-25 22:11:03.058 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session in your log is interesting

bdraco commented 2 months ago

Would you please post the full log. It looks like the device is dropping the connection when the library tries to subscribe and it ends up in an endless loop.

Minims commented 2 months ago

Do you need the data in bytearray i removed ? Or do i need to wait for more logs ?

bdraco commented 2 months ago

Do you need the data in bytearray i removed ? Or do i need to wait for more logs ?

I need the log entries before and after. The large bytearray can be trimmed if you like but it doesn't really matter as its the encrypted camera image.

Minims commented 2 months ago

It is a bit long log.txt

bdraco commented 2 months ago

Its definitely a loop of connect, establish, get disconnected, connect again..

bdraco commented 2 months ago

It seem as soon as it tries to register for events the device drops the connection

2024-08-26 22:33:04.169 INFO (MainThread) [aiohomekit.controller.ip.pairing] This device does not support push, so only polling operations will be supported during this session 2024-08-26 22:33:04.274 DEBUG (MainThread) [aiohomekit.controller.ip.connection] Connection HomeKitConnection(host='192.168.1.53', port=5052) lost.

bdraco commented 2 months ago

I'm not going to be able to figure out a good solution without the device.

amazon.co.uk had one. I ordered it and it should be here Sept 28th

Minims commented 2 months ago

I'm not going to be able to figure out a good solution without the device.

amazon.co.uk had one. I ordered it and it should be here Sept 28th

Many thanks for your support, waiting for your feedback :-) Tell me if you need more informations / details to debug this camera.

bdraco commented 1 month ago

The camera showed up much sooner than expected. Unfortunately everything works as expected

Maybe you have an older firmware? Firmware: 2.9.0

Minims commented 1 month ago

I have the same version 2.9.0. It works at the beginning.

I open the shutter, get the video then after a few moment, lets say 5 min after this first check, i try to see the video again and it fails with the logs i sent (shutter stay open during this time). I will retry with 2024.9.0. And i will try to repair the camera too.

Minims commented 1 month ago

Hello,

I'm still debugging this and I have just remembered that i have go2rtc in proxy mode for this camera: https://github.com/AlexxIT/go2rtc?tab=readme-ov-file#module-homekit

Camera <> HA <> go2rtc <> Apple Home

It seems better if go2rtc is disable with version 2024.9.0.

So, I think the issue might be that HA & go2rtc are both connecting to the camera. The old code might allow reconnection from HA or go2rtc or manage multiple connections ??

Since the update introduce in 2024.8.2 i would says the reconnection patch break this old behavior. Don't know if the code can be updated in to handle this case.

Thanks.

home-assistant / core