Closed mchangsp closed 9 months ago
I also still have this problem, running the exact same versions as @mchangsp. This issue is related to #243 and #289.
Debug logs:
2024-01-31 12:50:06.176 DEBUG (MainThread) [aionefit] Sending msg...GET /ecus/rrc/uiStatus HTTP/1.1\rUser-Agent: NefitEasy\r\r
2024-01-31 12:50:06.462 DEBUG (MainThread) [aionefit] headers: ['HTTP/1.0 200 OK', 'Content-Length: 664', 'Content-Type: application/json', 'connection: close', '']
2024-01-31 12:50:06.463 DEBUG (MainThread) [aionefit] body: [A BUNCH OF BASE64 ENCODED DATA]
2024-01-31 12:50:06.496 DEBUG (MainThread) [aionefit] response: {"id":"/ecus/rrc/uiStatus","type":"uiUpdate","recordable":0,"writeable":0,"value":{"CTD":"2024-01-31T13:50:04+00:00 We","CTR":"room","UMD":"clock","MMT":"15.0","CPM":"auto","CSP":"19","TOR":"off","TOD":"0","TOT":"15.0","TSP":"19.0","IHT":"19.10","IHS":"ok","DAS":"off","TAS":"off","HMD":"off","ARS":"init","FPA":"off","ESI":"off","BAI":"CH","BLE":"false","BBE":"false","BMR":"false","PMR":"false","RS":"off","DHW":"on","HED_EN":"false","HED_DEV":"false","FAH":"false","DOT":"false","HED_DB":""}}
2024-01-31 12:50:06.498 DEBUG (MainThread) [aionefit] Sending msg...GET /ecus/rrc/userprogram/activeprogram HTTP/1.1\rUser-Agent: NefitEasy\r\r
2024-01-31 12:50:06.707 DEBUG (MainThread) [aionefit] headers: ['HTTP/1.0 200 OK', 'Content-Length: 216', 'Content-Type: application/json', 'connection: close', '']
2024-01-31 12:50:06.707 DEBUG (MainThread) [aionefit] body: [A BUNCH OF BASE64 ENCODED DATA]
2024-01-31 12:50:06.719 DEBUG (MainThread) [aionefit] response: {"id":"/ecus/rrc/userprogram/activeprogram","type":"floatValue","recordable":0,"writeable":1,"value":0,"unitOfMeasure":"","minValue":0,"maxValue":2}
2024-01-31 12:50:06.721 DEBUG (MainThread) [aionefit] Sending msg...GET /ecus/rrc/recordings/yearTotal HTTP/1.1\rUser-Agent: NefitEasy\r\r
2024-01-31 12:50:15.726 ERROR (MainThread) [custom_components.nefiteasy] Timeout fetching nefiteasy data
2024-01-31 12:50:15.727 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 9.551 seconds (success: False)
2024-01-31 12:51:15.176 DEBUG (MainThread) [aionefit] Sending msg...GET /ecus/rrc/uiStatus HTTP/1.1\rUser-Agent: NefitEasy\r\r
2024-01-31 12:51:15.185 DEBUG (MainThread) [aionefit.provider.slixmpp_impl] Connection was closed
2024-01-31 12:51:15.185 DEBUG (MainThread) [custom_components.nefiteasy] Unexpected disconnect of 818920313 with Bosch server. Try to reconnect..
2024-01-31 12:51:24.183 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 9.007 seconds (success: False)
2024-01-31 12:52:24.175 DEBUG (MainThread) [custom_components.nefiteasy] Starting reconnect procedure.
2024-01-31 12:52:24.176 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-01-31 12:52:24.177 DEBUG (MainThread) [custom_components.nefiteasy] Waiting for connected event.
2024-01-31 12:52:24.181 DEBUG (MainThread) [custom_components.nefiteasy] Connected successfully.
2024-01-31 12:52:24.181 DEBUG (MainThread) [aionefit] Sending msg...GET /gateway/brandID HTTP/1.1\rUser-Agent: NefitEasy\r\r
2024-01-31 12:52:24.184 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 0.009 seconds (success: False)
2024-01-31 12:52:24.705 DEBUG (MainThread) [aionefit.provider.slixmpp_impl] auth_success event: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl">cnNwYXV0aD1kZWZmN2IyNjA5YTg2Njg4Zjc1YmQ0ZTQ1MGI5ZjEwNg==</success>
2024-01-31 12:53:24.177 DEBUG (MainThread) [custom_components.nefiteasy] Starting reconnect procedure.
2024-01-31 12:53:24.177 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-01-31 12:53:24.178 DEBUG (MainThread) [custom_components.nefiteasy] Connection procedure is already running.
2024-01-31 12:53:24.178 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 0.002 seconds (success: False)
2024-01-31 12:54:24.206 DEBUG (MainThread) [custom_components.nefiteasy] Starting reconnect procedure.
2024-01-31 12:54:24.206 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-01-31 12:54:24.206 DEBUG (MainThread) [custom_components.nefiteasy] Connection procedure is already running.
2024-01-31 12:54:24.206 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 0.000 seconds (success: False)
2024-01-31 12:55:24.176 DEBUG (MainThread) [custom_components.nefiteasy] Starting reconnect procedure.
2024-01-31 12:55:24.177 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-01-31 12:55:24.177 DEBUG (MainThread) [custom_components.nefiteasy] Connection procedure is already running.
2024-01-31 12:55:24.178 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 0.002 seconds (success: False)
Around 12:50:06 I still see request headers and body logged.
At 12:50:15 it logs a timeout after which we don't see any (successful) requests anymore.
At 12:52:24 the reconnect procedure is triggered and it even logs "Connected successfully", but in practice it doesn't seem to be connected. It will start repeating the reconnect procedure, but will only report that it "is already running".
I hope this helps! I wish I could help more, but my Python knowledge is very limited. If needed I could run an early build containing additional debug logging or whatever helps 😀
It makes no sense to me... Once it sends out the "get brand ID" command for verifying connection, there is a timeout of 29 seconds before a timeout is given after which the connection procedure is aborted. Somehow it hangs, but I can't see why yet.
I released 0.4.3 with additional debug logging. See if you can catch the error with this newer version.
Thanks for looking into it. Will install 0.4.3 and try to catch the error
I enabled debug loggging on 0.4.3 and succeeded to catch this:
2024-02-01 06:57:36.410 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 3.297 seconds (success: True)
2024-02-01 06:58:39.420 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 3.308 seconds (success: True)
2024-02-01 06:59:43.175 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 4.063 seconds (success: True)
2024-02-01 07:00:52.115 ERROR (MainThread) [custom_components.nefiteasy] Timeout fetching nefiteasy data
2024-02-01 07:00:52.115 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 9.003 seconds (success: False)
2024-02-01 07:01:22.178 DEBUG (MainThread) [custom_components.nefiteasy] Shutdown connection to Bosch cloud
2024-02-01 07:01:22.178 DEBUG (MainThread) [custom_components.nefiteasy] Initialize Nefit class
2024-02-01 07:01:22.213 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-02-01 07:01:22.213 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to true
2024-02-01 07:01:22.213 DEBUG (MainThread) [custom_components.nefiteasy] Waiting for connected event.
2024-02-01 07:01:22.598 DEBUG (MainThread) [custom_components.nefiteasy] Connected successfully.
2024-02-01 07:01:22.599 DEBUG (MainThread) [custom_components.nefiteasy] Wait for message event
2024-02-01 07:01:39.867 ERROR (SyncWorker_20) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-02-01 07:01:51.600 DEBUG (MainThread) [custom_components.nefiteasy] Did not get a response in time for testing connection.
2024-02-01 07:01:51.600 DEBUG (MainThread) [custom_components.nefiteasy] Successfully verified connection.
2024-02-01 07:01:51.600 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to false
2024-02-01 07:01:56.904 DEBUG (MainThread) [custom_components.nefiteasy] Initialize Nefit class
2024-02-01 07:01:56.938 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-02-01 07:01:56.939 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to true
2024-02-01 07:01:56.939 DEBUG (MainThread) [custom_components.nefiteasy] Waiting for connected event.
2024-02-01 07:01:57.214 DEBUG (MainThread) [custom_components.nefiteasy] Connected successfully.
2024-02-01 07:01:57.215 DEBUG (MainThread) [custom_components.nefiteasy] Wait for message event
2024-02-01 07:02:26.217 DEBUG (MainThread) [custom_components.nefiteasy] Did not get a response in time for testing connection.
2024-02-01 07:02:26.217 DEBUG (MainThread) [custom_components.nefiteasy] Successfully verified connection.
2024-02-01 07:02:26.218 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to false
2024-02-01 07:02:36.624 DEBUG (MainThread) [custom_components.nefiteasy] Initialize Nefit class
2024-02-01 07:02:36.652 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-02-01 07:02:36.652 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to true
2024-02-01 07:02:36.652 DEBUG (MainThread) [custom_components.nefiteasy] Waiting for connected event.
2024-02-01 07:02:37.337 DEBUG (MainThread) [custom_components.nefiteasy] Connected successfully.
2024-02-01 07:02:37.339 DEBUG (MainThread) [custom_components.nefiteasy] Wait for message event
2024-02-01 07:03:06.341 DEBUG (MainThread) [custom_components.nefiteasy] Did not get a response in time for testing connection.
2024-02-01 07:03:06.341 DEBUG (MainThread) [custom_components.nefiteasy] Successfully verified connection.
2024-02-01 07:03:06.341 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to false
2024-02-01 07:03:26.524 DEBUG (MainThread) [custom_components.nefiteasy] Initialize Nefit class
2024-02-01 07:03:26.564 DEBUG (MainThread) [custom_components.nefiteasy] Start connecting.
2024-02-01 07:03:26.564 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to true
2024-02-01 07:03:26.564 DEBUG (MainThread) [custom_components.nefiteasy] Waiting for connected event.
2024-02-01 07:03:26.853 DEBUG (MainThread) [custom_components.nefiteasy] Connected successfully.
2024-02-01 07:03:26.854 DEBUG (MainThread) [custom_components.nefiteasy] Wait for message event
2024-02-01 07:03:27.046 DEBUG (MainThread) [custom_components.nefiteasy] Message event received
2024-02-01 07:03:27.046 DEBUG (MainThread) [custom_components.nefiteasy] Set is connecting to false
2024-02-01 07:03:27.351 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 0.305 seconds (success: True)
2024-02-01 07:03:29.550 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 2.191 seconds (success: True)
2024-02-01 07:03:29.578 WARNING (MainThread) [homeassistant.helpers.entity] Entity None (<class 'custom_components.nefiteasy.climate.NefitThermostat'>) is using deprecated supported features values which will be removed in HA Core 2025.1. Instead it should use <ClimateEntityFeature.TARGET_TEMPERATURE|PRESET_MODE: 17>, please create a bug report at https://github.com/ksya/ha-nefiteasy/issues and reference https://developers.home-assistant.io/blog/2023/12/28/support-feature-magic-numbers-deprecation
2024-02-01 07:03:43.000 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 3.421 seconds (success: True)
2024-02-01 07:04:47.002 DEBUG (MainThread) [custom_components.nefiteasy] Finished fetching nefiteasy data in 3.639 seconds (success: True)
Please note I have the following automation running, when the logging above was done. Without this automation the Nefit client stays disconnected.
alias: Nefit auto reload when unavailable
description: ""
trigger:
- platform: state
entity_id:
- climate.nefit
to: unavailable
for:
hours: 0
minutes: 0
seconds: 30
condition: []
- service: logbook.log
metadata: {}
data:
name: Nefit
message: Nefit became unavailable, reloading
entity_id: climate.nefit
domain: climate
- service: homeassistant.reload_config_entry
target:
entity_id: climate.nefit
data: {}
mode: queued
max: 10
It makes no sense to me... Once it sends out the "get brand ID" command for verifying connection, there is a timeout of 29 seconds before a timeout is given after which the connection procedure is aborted. Somehow it hangs, but I can't see why yet.
I released 0.4.3 with additional debug logging. See if you can catch the error with this newer version.
Oops, now I understand the timeout. I will disable my automation and see how everything goes
I'm also still running the automation that someone suggested on one of the older issues, except I'm no longer automatically reloading the integration and only use it to notify me that it became unavailable. I don't have any hard numbers, but I guess 3 out of 4 times that I get the notification the integration does seem to recover and reconnect successfully.
I'll also install the 0.4.3 version today and see if we can catch something 😁
Thanks for all the efforts so far 🙌🏻
I'm also still running the automation that someone suggested on one of the older issues, except I'm no longer automatically reloading the integration and only use it to notify me that it became unavailable. I don't have any hard numbers, but I guess 3 out of 4 times that I get the notification the integration does seem to recover and reconnect successfully.
I'll also install the 0.4.3 version today and see if we can catch something 😁
Thanks for all the efforts so far 🙌🏻
A. Great minds think alike. I just changed my automation to send me a message only and not automatically reload the integration.
B. It could be the connection between the integration code and the Nefit servers break because the Nefit servers are not available. In that case the integration cannot do anything about it.
C. How can I detect that the Nefit servers are unavailable.?
D. Indeed thanks for all the efforts! Appreciated!
There is an issue with the Nefit server, that’s for sure. They also don’t care because the app always reconnects. Only HA keeps the connection alive for so long and they don’t officially support it.
Having said that, the integration should always be able to reconnect once the server is responding again. Manual resets or automations should not be necessary. Question with these automations is whether they are sufficiently tolerant towards the Nefit server, so not restarting the integration automatically but giving it a few minutes is a good idea to see if it can somewhere recover.
Whenever the integration went offline, I tested if the Nefit Easy app could connect. And guess what, the Nefit app could not make connection as well.
After a while the integration went back online. So I guess everything is working as it should and this issue can be closed.
It makes no sense to me... Once it sends out the "get brand ID" command for verifying connection, there is a timeout of 29 seconds before a timeout is given after which the connection procedure is aborted. Somehow it hangs, but I can't see why yet. I released 0.4.3 with additional debug logging. See if you can catch the error with this newer version.
Oops, now I understand the timeout. I will disable my automation and see how everything goes
This helped. I had the automation also running but it seems now it is captured in 0.4.2 (and 3)? Now disabled the reload automation and see how it goes...
Every now and then the nefiteasy integration is offline. This is the log with Home Assistant 2024.1.5 and nefiteasy 0.4.2
ENDQYUOTE