Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Timeout not handled #129

Open
chemelli74 opened this issue May 16, 2024 · 26 comments
Open

Timeout not handled #129

chemelli74 opened this issue May 16, 2024 · 26 comments

Comments

@chemelli74
Copy link

From time to time I see a timeout in my log:

2024-05-16 14:11:13.301 ERROR (MainThread) [custom_components.hpprinter.managers.rest_api] Failed to get /DevMgmt/ProductConfigDyn.xml, Error: Connection timeout to host http://192.168.1.50:80/DevMgmt/ProductConfigDyn.xml, Line: 327
2024-05-16 14:11:16.126 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 258, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 414, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 168, in async_update_listeners
    update_callback()
  File "/config/custom_components/hpprinter/sensor.py", line 63, in _handle_coordinator_update
    self._set_value()
  File "/config/custom_components/hpprinter/sensor.py", line 57, in _set_value
    state = datetime.fromisoformat(state)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: fromisoformat: argument must be str

I think this should be handled from the integration and not just tracing in the log.
@elad-bar
Copy link
Owner

released v2.0.0b8 with fix for it, please check and update

thanks

@chemelli74
Copy link
Author

HI, unfortunately partially still there:

2024-05-18 13:04:34.136 ERROR (MainThread) [custom_components.hpprinter.managers.rest_api] Failed to get /DevMgmt/ProductConfigDyn.xml, Error: Connection timeout to host http://192.168.1.50:80/DevMgmt/ProductConfigDyn.xml, Line: 343

IS the only timeout line I get, all sensors are working fine.

@elad-bar
Copy link
Owner

Can you pls try tobaccess that page directly?

Thanks

@chemelli74
Copy link
Author

Works fine:

image

@elad-bar
Copy link
Owner

when trying to load the page, can you check if it take more than 3 seconds?

thanks

@chemelli74
Copy link
Author 

root@MyHomeCenter:~$ time wget -pq --no-cache --delete-after http://192.168.1.50:80/DevMgmt/ProductConfigDyn.xml

real    0m0.203s
user    0m0.007s
sys     0m0.003s

@elad-bar
Copy link
Owner

Thanks for answering the next question :)
I will increase the timeout to 10 seconds (for now it is defined for 3 seconds), that's the only thing that make sense...
Problem is that i'm abroad and will not be able to do it up until the weekend,
I can redirect you to the specific file that requires that change if you want to test it locally

@chemelli74
Copy link
Author

I can find it myself, no worries.

The bad is that there is something holding the request in your integration as doing it manually it takes way less that 1s

@elad-bar
Copy link
Owner

Agree, can you please increase the timeout set logs to debug and share the logs, i will be able to see what is that process

Thanks

@chemelli74
Copy link
Author

Still

2024-05-22 10:22:43.557 ERROR (MainThread) [custom_components.hpprinter.managers.rest_api] Failed to get /DevMgmt/ProductConfigDyn.xml, Error: Connection timeout to host http://192.168.1.50:80/DevMgmt/ProductConfigDyn.xml, Line: 337

Let me enable debug now

@chemelli74
Copy link
Author

Cannot find any additional info in the log:

2024-05-22 10:58:22.849 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 4.293 seconds (success: True)
2024-05-22 11:03:25.556 ERROR (MainThread) [custom_components.hpprinter.managers.rest_api] Failed to get /DevMgmt/ProductConfigDyn.xml, Error: Connection timeout to host http://192.168.1.50:80/DevMgmt/ProductConfigDyn.xml, Line: 337
2024-05-22 11:03:25.907 DEBUG (MainThread) [custom_components.hpprinter.managers.rest_api] Request to http://192.168.1.50:80/DevMgmt/ConsumableConfigDyn.xml
2024-05-22 11:03:28.059 DEBUG (MainThread) [custom_components.hpprinter.managers.rest_api] Request to http://192.168.1.50:80/DevMgmt/ProductUsageDyn.xml

@chemelli74
Copy link
Author

Seems to oscillate a lot:

2024-05-22 10:43:07.781 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 5.226 seconds (success: True)
2024-05-22 10:48:12.468 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 4.913 seconds (success: True)
2024-05-22 10:53:18.148 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 5.593 seconds (success: True)
2024-05-22 10:58:22.849 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 4.293 seconds (success: True)
2024-05-22 11:03:28.137 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 5.582 seconds (success: True)
2024-05-22 11:08:33.582 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 5.027 seconds (success: True)
2024-05-22 11:13:38.351 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 4.797 seconds (success: True)
2024-05-22 11:18:41.415 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 2.859 seconds (success: True)
2024-05-22 11:23:44.040 DEBUG (MainThread) [custom_components.hpprinter.managers.ha_coordinator] Finished fetching HP Printer data in 2.484 seconds (success: True)

@elad-bar
Copy link
Owner

Pls post a full debug log not parts of it, otherwise i cannot understand what happens in code

Fact that total update time is more than 3 seconds doesn't indicate an issue, timeout is per request while in single update there are multiple http request that each of them can be timed out.

I didn't experience any timeout that's the reason i'm asking for that information

Thanks

@elad-bar
Copy link
Owner

@chemelli74 is it still relevant?

thanks

@chemelli74
Copy link
Author

I still see it from time to time, I think there is something blocking the refresh and this is the reason it's so slow.

@elad-bar
Copy link
Owner

What machine are you running ha on? How many integrations do you have? I'm thinking maybe limitation of threads (as there are 5-6 endpoint to collect the data from)

@elad-bar
Copy link
Owner

found out that ProductUsageDyn loading time can take up to 4.5 seconds at my network, printer from postman,
timeout set to 5 seconds, which supposed to be enough, pls check latest and update

thanks

@chemelli74
Copy link
Author

found out that ProductUsageDyn loading time can take up to 4.5 seconds at my network,

Only inside the integration, look at #129

@elad-bar
Copy link
Owner

4.5 seconds is for ProductUsageDyn measured in postman not HA

same test as you conducted above for both resources:

user@host:~# time wget -pq --no-cache --delete-after http://IP/DevMgmt/ProductUsageDyn.xml

real    0m4.577s
user    0m0.003s
sys     0m0.002s
user@host:~# time wget -pq --no-cache --delete-after http://IP/DevMgmt/ProductConfigDyn.xml

real    0m0.485s
user    0m0.002s
sys     0m0.002s

if it would happen for different resources i would go with the assumption that something is blocking one of the threads that leads to the error, but since it's specific resource, maybe you can run the same test as load test, or just enable debug log level in logs,
i have added in v2.0.2 timing for each of the calls (regardless ok, timeout or 404).

@chemelli74
Copy link
Author

Side note:
Seems that with v2.0.2 I have again all entities doubled;
Did you change again the unique id ?

Can you please add a migration method when this happen ?
It's a pain to fix everything at every update.

Thank you in advance

@elad-bar elad-bar mentioned this issue Jun 20, 2024
Closed
@elad-bar
Copy link
Owner

no, it was done at 2.0.1 but i also expirenced it when upgraded to 2.0.2

@elad-bar
Copy link
Owner

the method is to delete those entities, you can do it in the entity tab in device & services

@elad-bar
Copy link
Owner

did you manage to check it with v2.0.2 or above?

thanks

@chemelli74
Copy link
Author

the method is to delete those entities, you can do it in the entity tab in device & services

The method is to use the migrate in config_flow ;-)
Should not be done manually by users.

@chemelli74
Copy link
Author

did you manage to check it with v2.0.2 or above?

thanks

Installed but need a bit of time to enable debug and check.
Sorry for being slow.

@chemelli74
Copy link
Author

With debug enabled I don't experience the timeout error anymore
Will try now without.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@elad-bar @chemelli74