nitobuendia / oura-custom-component

Oura Custom Component for Home-Assistant. Adds Oura Ring sleep information.
108 stars 25 forks source link

RuntimeError: I/O must be done in the executor - leads to Error 500 #6

Closed denko81 closed 3 years ago

denko81 commented 3 years ago

When I click on the link in notification and click on Accept I get.

500 Internal Server Error Server got itself in trouble

Any ideas?

nitobuendia commented 3 years ago

Hi @denko81 without more details on what steps you took and your configuration, I am afraid it's not possible to troubleshoot. Could you share your config, the URL that's being called and your Oura Cloud set up?

Given the place where this breaks, my top guess is that the URL of your Home-Assistant is not added to the Oura Application under Redirect URIs. See this. Have you added your Home-Assistant URL to the Redirect URIs? The URL should look like something like this http://localhost:8123/oura/oauth/setup but it may differ for you.

denko81 commented 3 years ago

This is my http integration: http: base_url: "https://denisb.duckdns.org:8123" ssl_certificate: /ssl/fullchain.pem ssl_key: /ssl/privkey.pem

This is my Redirect URI in Oura application: https://denisb.duckdns.org:8123/oura/oauth/setup

Allow server-side authentication (grant-type code) and Allow client-side authentication (grant-type token) is checked.

This is my Oura sensor

nitobuendia commented 3 years ago

Thanks. This is helpful. Although I've redacted your client id and secret those are like a password. You may want to regenerate them to avoid issues.

Can you share a screenshot of your Oura Cloud configuration? Particularly the place where you added the Redirect URLs.

Also, what's the exact URL that throws 500?

denko81 commented 3 years ago

This is the screenshoot from cloud.ouraring.com

186486207_162147615844269_4160580310472394980_n

The URL that throws Error 500 is https://denisb.duckdns.org:8123/oura/oauth/setup?code=[redacted]&scope=email%20personal%20daily&state=sleep_quality

nitobuendia commented 3 years ago

Hi @denko81

Assuming that Redirect URIs is all in one line, the set up looks fine to me.

One thing you could try is adding the base domain rather than the whole path. This is, in addition to: https://denisb.duckdns.org:8123/oura/oauth/setup add https://denisb.duckdns.org:8123 - However, the correct one should be the former and I do not think that'd have an impact.

I also understand that you have copied all the files on the repository (api.py, hass_helper.py, manifest.json, sensor.py and views.py) into your custom_components/oura. Is that correct?

If yes, I do not have more ideas. My suggested next steps would be:

  1. I will try to set this up again on a new instance to see if I have any issues setting it up.

  2. If you check Home-Assistant logs after the 500 error, do you see any messages? It might be worth enabling debug logging in your configuration.yaml. I think something like this:

logger:
  default: info
  logs:
    homeassistant.custom_components.oura: debug
    homeassistant.components.sensor: debug
denko81 commented 3 years ago

I just tried to add https://denisb.duckdns.org:8123, with same result.

After I enabled debugging I got this. This error originated from a custom integration.

Logger: aiohttp.server Source: custom_components/oura/views.py:44 Integration: oura (documentation, issues) First occurred: 14:57:41 (1 occurrences) Last logged: 14:57:41

Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request resp = await self._request_handler(request) File "/usr/local/lib/python3.8/site-packages/aiohttp/web_app.py", line 499, in _handle resp = await handler(request) File "/usr/local/lib/python3.8/site-packages/aiohttp/web_middlewares.py", line 119, in impl return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 56, in security_filter_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 18, in request_context_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 74, in ban_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 135, in auth_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 128, in handle result = handler(request, **request.match_info) File "/config/custom_components/oura/views.py", line 44, in get with open(token_file_name, 'w+') as token_file: FileNotFoundError: [Errno 2] No such file or directory: '/config/data/oura-token-cache-sleep_quality.conf'

nitobuendia commented 3 years ago

That log line is extremely helpful. This is a very clear issue and relatively easy to debug.

The issue seems to be that the directory /config/data/ doesn't exist and therefore raises an unexpected error leading to a 500 error.

This weekend I added this commit which might solve this issue as (1) it uses relative path in case your config is located in a different directory and (2) it creates the path before trying to write to the file.

Could you kindly update the files from the component (i.e. update to the last version of custom_component/oura/) and see if the error persists?

Thanks for your help!

denko81 commented 3 years ago

I'm quite sure that I already ready use that version but I will reinstall.

nitobuendia commented 3 years ago

Thanks for that. Two quick notes:

  1. This change was done this weekend. So unless you had updated it less than 3d ago, the change wouldn't be there yet.

  2. When you say reinstalling, do you mean copying all the files/code into the custom_components folder? Do note that this is not distributed in HACS or alike (although I think some people did fork the project and may have tried to add it).

denko81 commented 3 years ago

Yes, I mean copying all the files/code into the custom_components folder.

denko81 commented 3 years ago

I tried with the latest version of the custom component and had same result.

I tried then to manually create the /config/data/oura-token-cache-sleep_quality.conf and got the 500 again.

In the logs I now got this: Logger: aiohttp.server Source: util/async_.py:140 First occurred: 13:38:20 (2 occurrences) Last logged: 13:40:49

Error handling request Traceback (most recent call last):

  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request
    resp = await self._request_handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_app.py", line 499, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_middlewares.py", line 119, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 56, in security_filter_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 18, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 74, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 135, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 128, in handle
    result = handler(request, **request.match_info)
  File "/config/custom_components/oura/views.py", line 47, in get
    self._sensor.update()  # Forces exchanging code for access token.
  File "/config/custom_components/oura/sensor.py", line 273, in update
    oura_data = self._api.get_sleep_data(start_date, end_date)
  File "/config/custom_components/oura/api.py", line 71, in get_sleep_data
    self._get_access_token_data_from_file()
  File "/config/custom_components/oura/api.py", line 158, in _get_access_token_data_from_file
    self._get_access_token_from_code(token_data.get('code'))
  File "/config/custom_components/oura/api.py", line 268, in _get_access_token_from_code
    access_token_data = self._request_access_token_with_code(code)
  File "/config/custom_components/oura/api.py", line 251, in _request_access_token_with_code
    response = requests.post(
  File "/usr/local/lib/python3.8/site-packages/requests/api.py", line 119, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/api.py", line 61, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 699, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 394, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 234, in request
    super(HTTPConnection, self).request(method, url, body=body, headers=headers)
  File "/usr/local/lib/python3.8/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.8/http/client.py", line 1263, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 214, in putrequest
    return _HTTPConnection.putrequest(self, method, url, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 151, in protected_loop_func
    check_loop()
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 140, in check_loop
    raise RuntimeError(
RuntimeError: I/O must be done in the executor; Use `await hass.async_add_executor_job()` at custom_components/oura/api.py, line 251: response = requests.post(
nitobuendia commented 3 years ago

@denko81 Thanks for checking and confirming. The error cut before getting to the Oura part. Do you mind editing to include the full response? You may need to attach in a text fine it if it's getting trimmed. Thanks!

denko81 commented 3 years ago

It's not cut. It ends with Screenshot_20210518-165315_Firefox Beta

nitobuendia commented 3 years ago

Got it. Thanks.

The good news is that this is a different error. The original error reported in this comment is solved. The bad news is that there's still another error thrown that needs fixing.

This is related to some changes a few versions back to make components async to avoid blocking the main thread. The relate documentation is this one. I created #7 for that migration, but I will keep your issue open for now, so we can ensure it works for you too.

nitobuendia commented 3 years ago

I've created this async_wrapper branch. I've implemented this logic before in another component and this worked as an easy fix. I believe this should solve the I/O issue here too.

However, I haven't merged yet as I didn't have enough time to verify the fix yet. If you're willing to give it a try earlier, it would be very helpful. You could copy sensor.py from the new branch into yours or see the differences here.

If you do, let me know if it worked or if you got a different error. Otherwise, I will let you know when I can reproduce the issue and validate the fix (in a few days probably).

Thanks again for your help and I hope we can get it working for you soon!

denko81 commented 3 years ago

No, problem. I will try it right now.

denko81 commented 3 years ago

I´m still getting the 500. I am getting this in the logg:

Logger: aiohttp.server
Source: util/async_.py:140
First occurred: 18:26:40 (1 occurrences)
Last logged: 18:26:40

Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request
    resp = await self._request_handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_app.py", line 499, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_middlewares.py", line 119, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 56, in security_filter_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 18, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 74, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 135, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 128, in handle
    result = handler(request, **request.match_info)
  File "/config/custom_components/oura/views.py", line 47, in get
    self._sensor.update()  # Forces exchanging code for access token.
  File "/config/custom_components/oura/sensor.py", line 275, in update
    oura_data = self._api.get_sleep_data(start_date, end_date)
  File "/config/custom_components/oura/api.py", line 71, in get_sleep_data
    self._get_access_token_data_from_file()
  File "/config/custom_components/oura/api.py", line 158, in _get_access_token_data_from_file
    self._get_access_token_from_code(token_data.get('code'))
  File "/config/custom_components/oura/api.py", line 268, in _get_access_token_from_code
    access_token_data = self._request_access_token_with_code(code)
  File "/config/custom_components/oura/api.py", line 251, in _request_access_token_with_code
    response = requests.post(
  File "/usr/local/lib/python3.8/site-packages/requests/api.py", line 119, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/api.py", line 61, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 699, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.8/site-packages/urllib3/connectionpool.py", line 394, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 234, in request
    super(HTTPConnection, self).request(method, url, body=body, headers=headers)
  File "/usr/local/lib/python3.8/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.8/http/client.py", line 1263, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/local/lib/python3.8/site-packages/urllib3/connection.py", line 214, in putrequest
    return _HTTPConnection.putrequest(self, method, url, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 151, in protected_loop_func
    check_loop()
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 140, in check_loop
    raise RuntimeError(
RuntimeError: I/O must be done in the executor; Use `await hass.async_add_executor_job()` at custom_components/oura/api.py, line 251: response = requests.post(

And this:

Logger: homeassistant.util.async_
Source: util/async_.py:132
First occurred: 18:26:40 (1 occurrences)
Last logged: 18:26:40

Detected I/O inside the event loop. This is causing stability issues. Please report issue to the custom component author for oura doing I/O at custom_components/oura/api.py, line 251: response = requests.post(
nitobuendia commented 3 years ago

Got it. Thanks for checking. It seems the fix didn't work. Re-reading, it seems didn't come from the update() method but from the views, where the change was not applied yet. I will have a look, but the fix should be similar.

PS: We no longer need more details on your config. These error messages is all we need. I would also recommend you to reset your client_id and client_secret as those got exposed here.

nitobuendia commented 3 years ago

@denko81 I've been able to reproduce the issue. I've added new changes and validated them on my Home-Assistant instance. Changes affected are on sensor.py and views.py. If you can update those files, remove your data/oura-token-cache-xxxx.conf token then restart the instance. I believe it should work. Let me know otherwise.

denko81 commented 3 years ago

It's working. Thanks!

nitobuendia commented 3 years ago

Thanks a lot for confirming, and the back and forth here to get to the root issue. It certainly has helped to fix the issue and it hopefully will help others who may have encountered this too!

leikoilja commented 2 years ago

@nitobuendia, i encountered the same issue with the token file not being found: image Fresh install of the integration today. To be fair I don't even have data directory under my config dir.

Edit: manual ssh to the HA container and creating config/data directory fixed the issue for me. Suggestion: add to the integration initialization create of useconfig/data` directory instead of failing it it's not existent :)

Thanks for the integration 💯

nitobuendia commented 2 years ago

@leikoilja I've split this to #11 - let's continue there! Thanks.