TRADFRI cannot be set up - "Unknown error occured"

Eugen68 commented 3 years ago

Home Assistant release with the issue:

0.114.2

Last working Home Assistant release (if known): unknown

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

Synology DSM 6.2.3-25426 Update 2

Integration:

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

Description of problem: When setting up Tradfri, the integration panel to enter the security code comes up. No matter what I enter (correct or incorrect data), it gives shows "Unknown error occured".

Home Assistant is running at stand-alone package, not in Docker. In this case where I could put: environment:

AIOCOAP_CLIENT_TRANSPORT=tinydtls
AIOCOAP_SERVER_TRANSPORT=tinydtls

I did a test with Home Assistant installed on another device in the same network and adding Tradfri works perfectly.

DominikChmiel commented 3 years ago

I can reproduce this issue on my setup, since some versions back the tradfri integration cannot be successfully setup with my installation aswell due to this.

Environment

Home Assistant Core release with the issue: 2020.12.0-2021.1.0
Last working Home Assistant Core release (if known): No exact version, but last successfull usage of Tradfri no more then three months ago
Operating environment (OS/Container/Supervised/Core): Archlinux community package

Traceback/Error logs

Jan 07 22:48:56 <HOST> hass[20913]: 2021-01-07 22:48:56 ERROR (MainThread) [aiohttp.server] Error handling request
Jan 07 22:48:56 <HOST> hass[20913]: Traceback (most recent call last):
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 96, in _get_response
Jan 07 22:48:56 <HOST> hass[20913]:     r = await pr.response
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/protocol.py", line 731, in _run_outer
Jan 07 22:48:56 <HOST> hass[20913]:     await cls._run(app_request, response, weak_observation, protocol, log)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/protocol.py", line 756, in _run
Jan 07 22:48:56 <HOST> hass[20913]:     await protocol.find_remote_and_interface(app_request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/protocol.py", line 299, in find_remote_and_interface
Jan 07 22:48:56 <HOST> hass[20913]:     if await ri.fill_or_recognize_remote(message):
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/tokenmanager.py", line 192, in fill_or_recognize_remote
Jan 07 22:48:56 <HOST> hass[20913]:     return await self.token_interface.fill_or_recognize_remote(message)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/messagemanager.py", line 330, in fill_or_recognize_remote
Jan 07 22:48:56 <HOST> hass[20913]:     remote = await self.message_interface.determine_remote(message)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/transports/tinydtls.py", line 328, in determine_remote
Jan 07 22:48:56 <HOST> hass[20913]:     dtlsparams = self.ctx.client_credentials.credentials_from_request(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/aiocoap/credentials.py", line 274, in credentials_from_request
Jan 07 22:48:56 <HOST> hass[20913]:     raise CredentialsMissingError("No suitable credentials for %s" % uri)
Jan 07 22:48:56 <HOST> hass[20913]: aiocoap.credentials.CredentialsMissingError: No suitable credentials for coaps://gw-<MAC>.fritz.box:5684/15011/9063
Jan 07 22:48:56 <HOST> hass[20913]: During handling of the above exception, another exception occurred:
Jan 07 22:48:56 <HOST> hass[20913]: Traceback (most recent call last):
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request
Jan 07 22:48:56 <HOST> hass[20913]:     resp = await self._request_handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/aiohttp/web_app.py", line 499, in _handle
Jan 07 22:48:56 <HOST> hass[20913]:     resp = await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/aiohttp/web_middlewares.py", line 118, in impl
Jan 07 22:48:56 <HOST> hass[20913]:     return await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/forwarded.py", line 172, in forwarded_middleware
Jan 07 22:48:56 <HOST> hass[20913]:     return await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/request_context.py", line 18, in request_context_middleware
Jan 07 22:48:56 <HOST> hass[20913]:     return await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/ban.py", line 72, in ban_middleware
Jan 07 22:48:56 <HOST> hass[20913]:     return await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/auth.py", line 127, in auth_middleware
Jan 07 22:48:56 <HOST> hass[20913]:     return await handler(request)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/view.py", line 129, in handle
Jan 07 22:48:56 <HOST> hass[20913]:     result = await result
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/config/config_entries.py", line 169, in post
Jan 07 22:48:56 <HOST> hass[20913]:     return await super().post(request, flow_id)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/http/data_validator.py", line 60, in wrapper
Jan 07 22:48:56 <HOST> hass[20913]:     result = await method(view, request, *args, **kwargs)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/helpers/data_entry_flow.py", line 106, in post
Jan 07 22:48:56 <HOST> hass[20913]:     result = await self._flow_mgr.async_configure(flow_id, data)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/data_entry_flow.py", line 155, in async_configure
Jan 07 22:48:56 <HOST> hass[20913]:     result = await self._async_handle_step(flow, cur_step["step_id"], user_input)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/data_entry_flow.py", line 213, in _async_handle_step
Jan 07 22:48:56 <HOST> hass[20913]:     result: Dict = await getattr(flow, method)(user_input)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/tradfri/config_flow.py", line 53, in async_step_auth
Jan 07 22:48:56 <HOST> hass[20913]:     auth = await authenticate(
Jan 07 22:48:56 <HOST> hass[20913]:   File "/usr/lib/python3.9/site-packages/homeassistant/components/tradfri/config_flow.py", line 168, in authenticate
Jan 07 22:48:56 <HOST> hass[20913]:     key = await api_factory.generate_psk(security_code)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 220, in generate_psk
Jan 07 22:48:56 <HOST> hass[20913]:     self._psk = await self.request(command)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 168, in request
Jan 07 22:48:56 <HOST> hass[20913]:     result = await self._execute(api_commands)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 152, in _execute
Jan 07 22:48:56 <HOST> hass[20913]:     _, res = await self._get_response(msg)
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 100, in _get_response
Jan 07 22:48:56 <HOST> hass[20913]:     await self._update_credentials()
Jan 07 22:48:56 <HOST> hass[20913]:   File "/var/lib/hass/deps/lib/python3.9/site-packages/pytradfri/api/aiocoap_api.py", line 236, in _update_credentials
Jan 07 22:48:56 <HOST> hass[20913]:     "psk": self._psk.encode("utf-8"),
Jan 07 22:48:56 <HOST> hass[20913]: AttributeError: 'NoneType' object has no attribute 'encode'

Tracking this down into pytradfri it looks like for generating the authentication token, coap-client is called. https://github.com/home-assistant-libs/pytradfri/blob/master/pytradfri/api/libcoap_api.py#L32

I recreated the corresponding coap-client call yielding the following:

# echo '{"9090": "<Request>"}' | coap-client -u Client_identity -k <Passphrase> -m post -v 7 -f - coaps://192.168.178.29:5684/15011/9063
Jan 07 23:03:21.502 DEBG added 6 protocols, 52 ciphersuites, 19 sig algos and 10 groups into priority list
Jan 07 23:03:21.502 DEBG ***192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: new outgoing session
Jan 07 23:03:21.502 DEBG added 5 protocols, 52 ciphersuites, 16 sig algos and 10 groups into priority list
Jan 07 23:03:21.503 DEBG Keeping ciphersuite cc.ac (GNUTLS_ECDHE_PSK_CHACHA20_POLY1305)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.36 (GNUTLS_ECDHE_PSK_AES_256_CBC_SHA1)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.35 (GNUTLS_ECDHE_PSK_AES_128_CBC_SHA1)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.37 (GNUTLS_ECDHE_PSK_AES_128_CBC_SHA256)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite 00.a9 (GNUTLS_PSK_AES_256_GCM_SHA384)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite cc.ab (GNUTLS_PSK_CHACHA20_POLY1305)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.a5 (GNUTLS_PSK_AES_256_CCM)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite 00.8d (GNUTLS_PSK_AES_256_CBC_SHA1)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite 00.a8 (GNUTLS_PSK_AES_128_GCM_SHA256)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.a4 (GNUTLS_PSK_AES_128_CCM)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite 00.8c (GNUTLS_PSK_AES_128_CBC_SHA1)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite 00.ae (GNUTLS_PSK_AES_128_CBC_SHA256)
Jan 07 23:03:21.503 DEBG Keeping ciphersuite c0.a8 (GNUTLS_PSK_AES_128_CCM_8)
Jan 07 23:03:21.503 DEBG HSK[0x98c840]: sent server name: '192.168.178.29'
Jan 07 23:03:21.504 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 209 bytes
Jan 07 23:03:21.504 DEBG sending CoAP request:
Jan 07 23:03:21.504 DEBG ** 192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: tid=3278: delayed
Jan 07 23:03:21.504 DEBG timeout is set to 90 seconds
Jan 07 23:03:21.504 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: received 60 bytes
Jan 07 23:03:21.504 DEBG Keeping ciphersuite cc.ac (GNUTLS_ECDHE_PSK_CHACHA20_POLY1305)
Jan 07 23:03:21.504 DEBG Keeping ciphersuite c0.36 (GNUTLS_ECDHE_PSK_AES_256_CBC_SHA1)
Jan 07 23:03:21.504 DEBG Keeping ciphersuite c0.35 (GNUTLS_ECDHE_PSK_AES_128_CBC_SHA1)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite c0.37 (GNUTLS_ECDHE_PSK_AES_128_CBC_SHA256)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite 00.a9 (GNUTLS_PSK_AES_256_GCM_SHA384)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite cc.ab (GNUTLS_PSK_CHACHA20_POLY1305)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite c0.a5 (GNUTLS_PSK_AES_256_CCM)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite 00.8d (GNUTLS_PSK_AES_256_CBC_SHA1)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite 00.a8 (GNUTLS_PSK_AES_128_GCM_SHA256)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite c0.a4 (GNUTLS_PSK_AES_128_CCM)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite 00.8c (GNUTLS_PSK_AES_128_CBC_SHA1)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite 00.ae (GNUTLS_PSK_AES_128_CBC_SHA256)
Jan 07 23:03:21.505 DEBG Keeping ciphersuite c0.a8 (GNUTLS_PSK_AES_128_CCM_8)
Jan 07 23:03:21.505 DEBG HSK[0x98c840]: sent server name: '192.168.178.29'
Jan 07 23:03:21.505 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 241 bytes
Jan 07 23:03:21.505 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: received 103 bytes
Jan 07 23:03:21.506 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: received 25 bytes
Jan 07 23:03:21.506 DEBG got psk_identity_hint: ''
Jan 07 23:03:21.506 INFO Identity Hint '' provided
Jan 07 23:03:21.506 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 42 bytes
Jan 07 23:03:21.506 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 14 bytes
Jan 07 23:03:21.506 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 53 bytes
Jan 07 23:03:21.508 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: received 15 bytes
Jan 07 23:03:21.508 WARN Received alert '20': 'Bad record MAC'
Jan 07 23:03:21.508 DEBG ***EVENT: 0x0000
Jan 07 23:03:21.508 DEBG ***192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: session disconnected (reason 3)
Jan 07 23:03:21.508 DEBG *  192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: sent 31 bytes
Jan 07 23:03:21.508 DEBG ***EVENT: 0x0000
Jan 07 23:03:21.508 DEBG ** 192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: tid=3278: not transmitted after disconnect
Jan 07 23:03:21.508 DEBG ***EVENT: 0x0000
Jan 07 23:03:21.508 DEBG ***192.168.178.100:45324 <-> 192.168.178.29:5684 DTLS: session closed

at which point I'm currently stuck. Bad record MAC is as far as I can find out a pretty low level TSL error, that shouldn't really reach a user...

version of coap-client:

coap-client v4.3.0beta -- a small CoAP implementation

During the timeframe where this integration stopped working, there was also a TRADFRI gateway update to version 1.12.34 on my setup, I'd guess it is related.

Is there anything else I can run on my setup to test/debug this?

DominikChmiel commented 3 years ago

@ggravlingen could you give me some pointers where I can start with this error? Should be able to dig through the python side of things myself, just don't have any knowledge about dtls/coap/the lower level stuff here (Tagging you manually since the Codeowners bot seemingly didn't pick up on this one)

ggravlingen commented 3 years ago

I’ve read others having problems with running in VM and Synology. Something with the traffic not getting through. I would try cleaning the integration from the HA config files and see if that helps. I would also try the pytradfri stand-alone lib and see if you can find anything there. Maybe search the GitHub issues and see if you can find the topics where synology is discussed?

Other than that I’m afraid I’m not much of help. I run mine on a raspberry pie and it works fine.

DominikChmiel commented 3 years ago

Thanks for the speedy response - in contrast to the OP I'm also running on a raspberry pi where I run into the same issue as OP

Edit: More precise environment is a rasppi4 with archlinux

And the integration was fully removed from my config files, during re-adding it through the UI I run into the exception posted in the logs above. As for using the standalone lib, I've tried the underlying coap-client call manually even, resulting in the above log

ggravlingen commented 3 years ago

What about your firewall rules? Is your gateway on a separate VLAN?

DominikChmiel commented 3 years ago

Networking setup here is pretty basic, all connected to a single router without any (internal) firewalling. It did also work fine in this setup about 3 months ago (can lookup when exactly it was last triggered if that helps). For a while it was then not working due to an update to python 3.9 (fixed by https://github.com/home-assistant-libs/pytradfri/issues/301 ) but when trying to reactivate it after that fix was merged this issue occured.

blind-oracle commented 3 years ago

Same error here for me, same backtrace

Tradfri with latest firmware
Latest HA running inside a KVM
Simple bridged networking (no traffic problems for sure)

  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 152, in _execute
    _, res = await self._get_response(msg)
  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 116, in _get_response
    await self._update_credentials()
  File "/usr/local/lib/python3.8/site-packages/pytradfri/api/aiocoap_api.py", line 236, in _update_credentials
    "psk": self._psk.encode("utf-8"),
AttributeError: 'NoneType' object has no attribute 'encode'

blind-oracle commented 3 years ago

What's interesting - today it started working by itself when I tried to add the Gateway again...

DominikChmiel commented 3 years ago

After confirming I can setup the tradfri integration fine in a clean docker scenario (which I could) I dove into the source of pytradfri/aiocoap to figure out what went wrong and identified an error/unexpected behavior in my configuration.yaml file:

I had the tradfri section still statically setup (from when the autodiscovery was not yet where it is now) like:

tradfri:
     allow_tradfri_groups: True
     host: "GW-<MAC>.fritz.box"

where I had only a few weeks ago replaced the host from an IP address to a hostname instead.

Adding printouts to the credentials check here: https://github.com/chrysn/aiocoap/blob/master/aiocoap/credentials.py#L285

then gave me:

Command is: <Command post ['15011', '9063']: {'9090': '<request>'}>
Dict is:  {'coaps://GW-<MAC>.fritz.box:5684/15011/9063': {'dtls': {'psk': '<sec-code>', 'client-identity': b'Client_identity'}}}
Checking:  coaps://gw-<mac>.fritz.box:5684/15011/9063  =>  coaps://GW-<MAC>.fritz.box:5684/15011/9063

so that check does not work with case differences in hostname...I guess the lookup pytradfri does for this as input always transform the second part to lowercase, leading to the suitable credentials check failing.

After changing the host in my config to lowercase, I can now successfully setup the integration.

github-actions[bot] commented 3 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

home-assistant / core

TRADFRI cannot be set up - "Unknown error occured" #44117

Environment

Traceback/Error logs