search

djerik / dagen-ha

Home Assistant component for monitoring and administration of Dagen Pool Controller
7 stars 5 forks source link

Error calling service switch/turn_on #5

Open westado opened 3 months ago

westado commented 3 months ago

I added the pull requests "include the pump filter entity as switch" to the integration. This can also be switched on after a Home Assistant restart. However, after about an hour, when you turn it on or off, you get "Error when calling the switch/turn_on service. 401 Missing or invalid authentication" - all other values ​​such as PH and CL continue to be updated.

Attached is the debug 2024-08-01 11:05:15.920 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139745989630928] Unexpected exception Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 241, in handle_call_service response = await hass.services.async_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2731, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2774, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 999, in entity_service_call single_response = await _handle_entity_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1071, in _handle_entity_call result = await task ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/light/init.py", line 628, in async_handle_light_on_service await light.async_turn_on(filter_turn_on_params(light, params)) File "/config/custom_components/dagen/light.py", line 36, in async_turn_on await self._dataservice.turn_on_light() File "/config/custom_components/dagen/coordinator.py", line 38, in turn_on_light await self.api.turn_on_light( self.data.id ) File "/config/custom_components/dagen/dagen.py", line 108, in turn_on_light pool_data = self.__get_pool_as_json(pool_id) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/dagen/dagen.py", line 143, in get_pool_as_json pool = self.get_pool(pool_id) ^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/dagen/dagen.py", line 98, in get_pool return self.client.collection("pools").document(pool_id).get() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/cloud/firestore_v1/document.py", line 402, in get response_iter = self._client._firestore_api.batch_get_documents( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/cloud/firestore_v1/services/firestore/client.py", line 1150, in batch_get_documents response = rpc( ^^^^ File "/usr/local/lib/python3.12/site-packages/google/api_core/gapic_v1/method.py", line 131, in call__ return wrapped_func(*args, *kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 293, in retry_wrapped_func return retry_target( ^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 153, in retry_target _retry_error_helper( File "/usr/local/lib/python3.12/site-packages/google/api_core/retry/retry_base.py", line 212, in _retry_error_helper raise final_exc from source_exc File "/usr/local/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 144, in retry_target result = target() ^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/api_core/timeout.py", line 120, in func_with_timeout return func(args, kwargs) ^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/google/api_core/grpc_helpers.py", line 174, in error_remapped_callable raise exceptions.from_grpc_error(exc) from exc google.api_core.exceptions.Unauthenticated: 401 Missing or invalid authentication.

djerik commented 3 months ago

Does the same thing happen when switching on or off lights?

westado commented 3 months ago

yes it is the same !

fdebrus commented 3 months ago

A token expiration is in the play here, token is valid for 1hr. Next, it needs re-auth to get a new valid one. You would need as well to refresh your firestore document listener.

djerik commented 3 months ago

But this is already implemented and it is working. I debugged on my dev machine and all is as intended. My production machine has been up for 3 weeks and it is still working. Do you have any errors prior to this error? I am considering implementing a check or retry of authentication in these calls, but I would rather find the actual source of the problem.

djerik commented 3 months ago

@westado how are you running HA? What version of HA? can you check available google upgrades with "pip list --outdated" in a terminal?

fdebrus commented 3 months ago

Tried on my HA, I’ve the same problem. Token do not refresh so after token expiration (1hr) commands cannot be sent and the firestore data remains the one from the last snapshot.

I’m running HA Supervised. So I’ve no pip as running in docker, could it be an option to force the Google library version in the manifest ? If this is the cause.

IMG_2164

djerik commented 3 months ago

@fdebrus Why are you running Supervised? It requires much more of you to maintain.

But it should also on Supervised be possible to create a terminal connection and chech the version?

I can add the version requirement yes, but since I dont have an environment with the problem, it is not possible for me to check if it resolves it. Could you fork this repo, change the requirement there and install in parallel with your own repo to see if it solves the problem.

fdebrus commented 3 months ago

Sure, will do. I can change the manifest in the custom_integration folder. Which version shall I try out ?

fdebrus commented 3 months ago

Trying with >=2.32.0 for Google auth and >=2.17.0 for Firestore

fdebrus commented 3 months ago

No change, not working. I can install a new HA instance on another hardware to try out, but not before 3rd week of August. What is the version of HA that is working ?

fdebrus commented 3 months ago

If it helps, the behavior after token expiration is weird getting for example « temperature ».

image

over the flat period, data is not updated. Then it works again.

I’m expecting more data points like

image

djerik commented 3 months ago

Thank you for reporting this. My values where changing so slowly at the time of development, that I did not notice, that the values where not live. It has nothing to do with token expire. The cause was that the entities where not notified correctly. Please test version 1.0.3 that should fix this.

Note; as some values can change with very small increments as shown in your picture, HA will use more DB space to store the values. Please help me consider is some values shoould have a lower precision and hence result in less changes that must be logged.

fdebrus commented 3 months ago

I loaded the latest release but I can’t set it up.

image

djerik commented 3 months ago

I forgot to test the config flow, I hope I will have a look later today

djerik commented 3 months ago

I cannot reproduce.

Any errors in the log? Do you have multiple Dagen components installed? At what step does it fail?

fdebrus commented 3 months ago

No integration installed / install using hacs / restart ha / add integration and immediately gets the message. Here is the error

image

djerik commented 3 months ago

I don't know why - sorry. Have you tried to install an earlier version?

fdebrus commented 3 months ago

No problem, will further troubleshoot as I return from vacation. I only have an iPhone as interface for now….

djerik commented 3 months ago

Sorry, version 1.0.3 contained incorrect import statement. Please update to 1.0.5

fdebrus commented 3 months ago

1.0.5 is installing fine. Will see about invalid auth

fdebrus commented 3 months ago

FYI, Manifest of 1.0.5 has a typo and still reference 1.0.4

fdebrus commented 3 months ago

image

as discussed, will further troubleshoot 3rd week of August… invalid auth still triggers when sending commands

What is weird is that it’s not all the time, sometimes it works, others it fails

image

If you look at data collection, eg temperature. You see flat period (data is not received) then it works again… my guess, when in a flat period we are not connected so data is not received and command cannot be sent. Outside those periods data is reveived and command can be sent.

ArminPrivate commented 3 months ago

Hy there! I rly love the possibility to integrate my DA-GEN but I have also the 401 Error when turning on or off the light when Homeassistant is already running for some time. Fresh after reboot it seems to work home-assistant_dagen_2024-08-18T05-04-10.243Z.log.txt Attaches the debug logs, please ignore the reolink/fronius issues in the logs

Core 2024.8.2 Supervisor 2024.08.0 Operating System 12.4 DA-GEN 1.0.4

westado commented 3 months ago

So I've now tested a lot with the DaGen integration and always get these 404 errors. Now I'm working with the Aquarite integration, which has all the functions integrated and works with Dageb, Bayrol, etc. Simply log in and all the functions are there.

fdebrus commented 3 months ago

@djerik back and ready to debug, could you send me your HA specs ? I have a spare hardware and I will replicate your HA setup to start.

fdebrus commented 3 months ago

Correct me if I'm wrong, We have an API_KEY / Username and a password. This is not an OAUTH2 authentification as we do not have a client_id / client_secret. and google.oauth2.credentials does not have a refresh_handler exposed to be used as a custom refresh mechanism.

My conclusion is that we can get rid of google.oauth2.credentials and manage token_refresh with a custom code.

Will try out.

fdebrus commented 3 months ago

I could not find any better way of managing the token than what I'm already doing see https://github.com/fdebrus/hayward-ha/blob/0.3.0/custom_components/aquarite/application_credentials.py

I'm still interested to undestand why da-gen fails for me while it works for you. I could not find anything other than token expiration not being managed.

djerik commented 3 months ago

@fdebrus I am running HA in Docker on Synology NAS. https://registry.hub.docker.com/r/homeassistant/home-assistant/ image Python Version 3.12.2

djerik commented 3 months ago

Correct me if I'm wrong, We have an API_KEY / Username and a password. This is not an OAUTH2 authentification as we do not have a client_id / client_secret. and google.oauth2.credentials does not have a refresh_handler exposed to be used as a custom refresh mechanism.

My conclusion is that we can get rid of google.oauth2.credentials and manage token_refresh with a custom code.

Will try out.

That is not correct. My code is using the refresh_handler option. The component calls dagen.create(). This first creates an instance of the dagen class Then it calls signin() to do the initial signin against google with api key, user name & password The web call returns token and expiry This is then used when creating the Credentials object, including specifying the refresh_handler=instance.get_token_and_expiry Credentials are then passed to the Firestore Client, and from there it is up to Firestore Client call get_token_and_expiry() when it has expired.

I have debugged my code many times, so I know it calls the refresh handler. If it didnt, neither the update of entities nor the turning on/off of light would work

The only thing I can think of, is that there is a bug in the Google Firestore Client module, that causes its thread to crash, thereby not refreshing neither the data nor the token. When searching for bug reports, I have seen others in the past strugling with similar problems, where Google have made changes to fix it. This was also why I was asking for what version of Google Firestore Client you have, but regardless, any errors should show up in the HA logs.

fdebrus commented 3 months ago

You are right, I was looking at a google documentation where "refresh_handler" was not existing, now I see it. I've setup HA on my synology nas, loaded da-gen. Now waiting for token to expire and will report behavior

fdebrus commented 3 months ago

It works on synology docker… time to compare both HA install now to spot the difference.

fdebrus commented 3 months ago

Synology Python 3.12.4 image

HA Supervised Python 3.12.4 image

No difference, where else to look ??

fdebrus commented 3 months ago

HA Syno image HA Supervised image

fdebrus commented 3 months ago

Here is the debuglog of the supervised. I've added debug message around the token refresh routine. It's refreshing token every now and then but not every hours as it should. Will do more debug as time allow

2024-08-23 16:35:11.466 INFO (MainThread) [homeassistant.setup] Setting up dagen
2024-08-23 16:35:11.466 INFO (MainThread) [homeassistant.setup] Setup of domain dagen took 0.00 seconds
2024-08-23 16:35:11.466 DEBUG (MainThread) [custom_components.dagen.dagen] Attempting to sign in.
2024-08-23 16:35:11.907 DEBUG (MainThread) [custom_components.dagen.dagen] Sign-in successful. Token expires at: 2024-08-23 17:35:11.907772
2024-08-23 16:35:12.193 DEBUG (MainThread) [custom_components.dagen.coordinator] Finished fetching Dagen data in 0.285 seconds (success: True)
2024-08-23 16:35:12.312 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 16:35:14.305 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up dagen.binary_sensor
2024-08-23 16:35:14.306 INFO (MainThread) [homeassistant.components.light] Setting up dagen.light
2024-08-23 16:35:14.306 INFO (MainThread) [homeassistant.components.sensor] Setting up dagen.sensor
2024-08-23 16:35:14.332 DEBUG (MainThread) [custom_components.dagen.coordinator] Finished fetching Dagen data in 0.025 seconds (success: True)
2024-08-23 16:41:45.346 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 16:42:47.033 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 16:53:47.097 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 17:04:47.053 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 17:13:01.254 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 17:14:02.931 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 17:25:03.613 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 17:36:06.580 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 19:31:26.920 DEBUG (Thread-366782 (_run)) [custom_components.dagen.dagen] Attempting to refresh token and expiry.
2024-08-23 19:31:27.224 DEBUG (Thread-366782 (_run)) [custom_components.dagen.dagen] Token refreshed successfully. New expiry: 2024-08-23 20:31:27.224809
2024-08-23 19:31:27.265 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 19:41:06.700 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 19:49:19.976 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 19:50:21.745 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 20:01:22.348 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 20:12:25.386 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 20:20:35.955 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 20:21:37.403 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 22:27:42.247 DEBUG (Thread-706493 (_run)) [custom_components.dagen.dagen] Attempting to refresh token and expiry.
2024-08-23 22:27:42.505 DEBUG (Thread-706493 (_run)) [custom_components.dagen.dagen] Token refreshed successfully. New expiry: 2024-08-23 23:27:42.505309
2024-08-23 22:27:42.554 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 22:37:41.096 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 22:48:44.232 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 22:56:54.569 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 22:57:56.125 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 23:08:56.190 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 23:19:56.942 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 23:28:10.234 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
2024-08-23 23:29:17.824 DEBUG (MainThread) [custom_components.dagen.coordinator] Manually updated Dagen data
fdebrus commented 2 months ago

I cannot get more debug information, nothing is displayed in log, no error. The only extra message I get as the token expire and the refresh_token is not triggered is 

2024-08-26 11:42:41.925 INFO (Thread-9 (_run)) [google.api_core.bidi] Re-established stream
2024-08-26 11:42:42.015 INFO (Thread-9 (_run)) [google.api_core.bidi] Re-established stream
2024-08-26 11:42:42.099 INFO (Thread-9 (_run)) [google.api_core.bidi] Re-established stream
2024-08-26 11:42:42.170 INFO (Thread-9 (_run)) [google.api_core.bidi] Re-established stream
2024-08-26 11:42:42.196 INFO (Thread-9 (_run)) [google.api_core.bidi] Re-established stream
...

I do not see how to drive this further, let me know if you wish for more test and debug but even when setting debug at google libraries level, I get no error... it just call the refresh token routine every now and then and not at each hours as defined by the token expiration time as it should.