home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.15k stars 29.83k forks source link

Restarting Home Assistant during the night causes inverters to stay unavailable #95354

Closed weitzelb closed 1 year ago

weitzelb commented 1 year ago

The problem

If Home Assistant is restarted during a period when the inverter does not produce any power, its entity is shown as unavailable and it is staying unavailable, even when solar production is back up. A full restart of Home Assistant while the inverter is up and producing power for the entities to become available again and the integration to query the inverter for it's current production.

I am not familiar with the development of Home Assistant integrations but I did try to look into it to the best of my abilities. I did notice that on each restart the inverters are setup based on the response of the Fronius system.
https://github.com/home-assistant/core/blob/90c1263501de63098ba989d19301e1d745cbcbaa/homeassistant/components/fronius/__init__.py#L98 Seemingly it only uses this response to identify inverters to communicate with. During non-production the system will never be contained. (Compare additional logs provided) Resulting in the existing device and its entities to be shown as unavailable. And they will stay that way even when the inverter goes back online after sunrise.

What version of Home Assistant Core has the issue?

core-2023.6.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

Fronius

Link to integration documentation on our website

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

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logfile after restart while not producing solar power:
2023-06-26 22:03:08.960 DEBUG (MainThread) [pyfronius] using highest supported API version API_VERSION.V1
2023-06-26 22:03:08.961 DEBUG (MainThread) [pyfronius] Get current logger info data for GetLoggerInfo.cgi
2023-06-26 22:03:11.555 DEBUG (MainThread) [pyfronius] Converting Logger info: '{'CO2Factor': 0.0, 'CO2Unit': 'kg', 'CashCurrency': 'EUR', 'CashFactor': 0.0, 'DefaultLanguage': 'en', 'DeliveryFactor': 0.25, 'HWVersion': '2.4D', 'PlatformID': 'wilma', 'ProductID': 'fronius-datamanager-card', 'SWVersion': '3.16.7-1', 'TimezoneLocation': 'Berlin', 'TimezoneName': 'CEST', 'UTCOffset': 7200, 'UniqueID': '240.1367697'}'
2023-06-26 22:03:11.555 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_logger_fronius.mine.de data in 3.249 seconds (success: True)
2023-06-26 22:03:11.555 DEBUG (MainThread) [pyfronius] Get inverter info data for GetInverterInfo.cgi
2023-06-26 22:03:12.906 DEBUG (MainThread) [pyfronius] Converting inverter info: '{}'
2023-06-26 22:03:12.906 DEBUG (MainThread) [pyfronius] Get current system meter data for GetMeterRealtimeData.cgi?Scope=System
2023-06-26 22:03:14.217 DEBUG (MainThread) [pyfronius] Converting system meter data: '{}'
2023-06-26 22:03:14.217 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_meters_fronius.mine.de data in 1.311 seconds (success: True)
2023-06-26 22:03:14.217 DEBUG (MainThread) [pyfronius] Get current system ohmpilot data for GetOhmPilotRealtimeData.cgi?Scope=System
2023-06-26 22:03:16.157 DEBUG (MainThread) [pyfronius] Converting system ohmpilot data: '{}'
2023-06-26 22:03:16.158 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_ohmpilot_fronius.mine.de data in 1.940 seconds (success: True)
2023-06-26 22:03:16.158 DEBUG (MainThread) [pyfronius] Get current power flow data for GetPowerFlowRealtimeData.fcgi
2023-06-26 22:03:16.947 DEBUG (MainThread) [pyfronius] Converting system power flow data: '{'Inverters': {}, 'Site': {'E_Day': None, 'E_Total': None, 'E_Year': None, 'Meter_Location': 'unknown', 'Mode': 'produce-only', 'P_Akku': None, 'P_Grid': None, 'P_Load': None, 'P_PV': None, 'rel_Autonomy': None, 'rel_SelfConsumption': None}, 'Version': '12'}'
2023-06-26 22:03:16.947 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_power_flow_fronius.mine.de data in 0.789 seconds (success: True)

Logfile after restart while producing solar power:
2023-06-27 11:50:47.731 DEBUG (MainThread) [homeassistant.components.fronius] Call init_devices dev True 
2023-06-27 11:50:48.342 DEBUG (MainThread) [pyfronius] using highest supported API version API_VERSION.V1
2023-06-27 11:50:48.342 DEBUG (MainThread) [pyfronius] Get current logger info data for GetLoggerInfo.cgi
2023-06-27 11:50:50.125 DEBUG (MainThread) [pyfronius] Converting Logger info: '{'CO2Factor': 0.05, 'CO2Unit': 'kg', 'CashCurrency': 'EUR', 'CashFactor': 0.0, 'DefaultLanguage': 'en', 'DeliveryFactor': 0.25, 'HWVersion': '2.4D', 'PlatformID': 'wilma', 'ProductID': 'fronius-datamanager-card', 'SWVersion': '3.16.7-1', 'TimezoneLocation': 'Berlin', 'TimezoneName': 'CEST', 'UTCOffset': 7200, 'UniqueID': '240.1367697'}'
2023-06-27 11:50:50.125 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_logger_fronius.mine.de data in 2.394 seconds (success: True)
2023-06-27 11:50:50.125 DEBUG (MainThread) [homeassistant.components.fronius] FroniusSolarNet _get_inverter_infos
2023-06-27 11:50:50.125 DEBUG (MainThread) [pyfronius] Get inverter info data for GetInverterInfo.cgi
2023-06-27 11:50:53.289 DEBUG (MainThread) [pyfronius] Converting inverter info: '{'1': {'CustomName': 'I', 'DT': 174, 'ErrorCode': 0, 'PVPower': 6500, 'Show': 1, 'StatusCode': 7, 'UniqueID': '203200'}}'
2023-06-27 11:50:53.289 DEBUG (MainThread) [homeassistant.components.fronius.coordinator] InverterupdateCoordinator Init at FroniusDeviceInfo(device_info={'identifiers': {('fronius', '203200')}, 'manufacturer': 'Fronius', 'model': 'IG Plus 70 V-2', 'name': 'IG Plus 70 V-2', 'via_device': ('fronius', 'solar_net_240.1367697')}, solar_net_id='1', unique_id='203200')
2023-06-27 11:50:53.289 DEBUG (MainThread) [pyfronius] Get current inverter data for GetInverterRealtimeData.cgi?Scope=Device&DeviceId=1&DataCollection=CommonInverterData
2023-06-27 11:50:57.916 DEBUG (MainThread) [pyfronius] Converting inverter data from '{'DAY_ENERGY': {'Unit': 'Wh', 'Value': 15000}, 'DeviceStatus': {'ErrorCode': 0, 'LEDColor': 2, 'LEDState': 0, 'MgmtTimerRemainingTime': -1, 'StateToReset': False, 'StatusCode': 7}, 'FAC': {'Unit': 'Hz', 'Value': 49.98}, 'IAC': {'Unit': 'A', 'Value': 8.98}, 'IDC': {'Unit': 'A', 'Value': 7}, 'PAC': {'Unit': 'W', 'Value': 2147}, 'TOTAL_ENERGY': {'Unit': 'Wh', 'Value': 1111}, 'UAC': {'Unit': 'V', 'Value': 231}, 'UDC': {'Unit': 'V', 'Value': 326}, 'YEAR_ENERGY': {'Unit': 'Wh', 'Value': 1111}}'

Additional information

Having a look at core.device_registry, I noticed that inverter is registered and stays registered after if was discovered once. Even during a night-time reboot this entry stays present. Also containing the data manager card.

{ "area_id": null, "config_entries": [ "e3ba852f1d7fc4687a231b97e49ed2ae" ], "configuration_url": "http://fronius.mine.de", "connections": [], "disabled_by": null, "entry_type": null, "hw_version": null, "id": "f62e4f6520993fd6ca97eb46f7d5b0af", "identifiers": [ [ "fronius", "solar_net_xxxxxxx" ] ], "manufacturer": "Fronius", "model": "fronius-datamanager-card", "name_by_user": null, "name": "SolarNet", "sw_version": "3.16.7-1", "via_device_id": null }, { "area_id": "dach", "config_entries": [ "e3ba852f1d7fc4687a231b97e49ed2ae" ], "configuration_url": null, "connections": [], "disabled_by": null, "entry_type": null, "hw_version": null, "id": "ff0ab9c67690dd5db829cb04b7ca0309", "identifiers": [ [ "fronius", "11111" ] ], "manufacturer": "Fronius", "model": "IG Plus 70 V-2", "name_by_user": "PV Garten", "name": "IG Plus 70 V-2", "sw_version": null, "via_device_id": "f62e4f6520993fd6ca97eb46f7d5b0af" }

It seems that on startup the previously registered inverters are not loaded from the device registry. Thus the integration does not attempt to query them, even when the inverter comes back online after sunrise. As a workaround I would need to reboot Home Assistant every morning. This however does break other things running at that time.

home-assistant[bot] commented 1 year ago

Hey there @nielstron, @farmio, mind taking a look at this issue as it has been labeled with an integration (fronius) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `fronius` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign fronius` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


fronius documentation fronius source (message by IssueLinks)

farmio commented 1 year ago

Hi 👋! What exact set of devices are you using? Is this a standalone datamanager device? Are the devices running the latest firmware?

weitzelb commented 1 year ago

Hi 👋! What exact set of devices are you using? Is this a standalone datamanager device? Are the devices running the latest firmware? Hi :)

It's a simple setup that consists of a single inverter with a data manager card. The inverter is an IG Plus 70 V-2 I have for 15+ years. It's not on the latest firmware and Fronius changelog does not show anything even closely related to this behaviour.

Once the sun is down that inverter shuts off and completely disappears. Pressumably a design choise. Throughout all the firmware updates over the past 15+ years, this behaviour has never changed.

The only thing accessible is the UI from the data manager showing you that currently no inverter is connected. Which is consistent with the response (manual and integration based call) of GetInverterInfo.cgi during this time. Once the sun is up the inverter boots again and is accesible through the API and the data logger UI.

farmio commented 1 year ago

From the Fronius API documentation:

4.6 GetInverterInfo request This request provides information about all inverters that are currently being monitored by the logging device. So this means that inverters which are currently not online are also reported by this request, provided these inverters have been seen by the logging device within the last 24 hours.

Therefore I assumed it is safe to only query this once on startup and use the inverters reported by this request. If the datamanager would be offline (like it is with Symo devices when they shut down at night), the integration wouldn't be loaded at all.

I'd recommend to update the datamanager firmware to see if it responds differently then.

weitzelb commented 1 year ago

From the Fronius API documentation:

4.6 GetInverterInfo request This request provides information about all inverters that are currently being monitored by the logging device. So this means that inverters which are currently not online are also reported by this request, provided these inverters have been seen by the logging device within the last 24 hours.

Therefore I assumed it is safe to only query this once on startup and use the inverters reported by this request. If the datamanager would be offline (like it is with Symo devices when they shut down at night), the integration wouldn't be loaded at all.

I'd recommend to update the datamanager firmware to see if it responds differently then.

It is safe to query the data manager any time and receive a (technically) valid response. The datamanager is always online thus the integration will load like you mentioned. It's shown as separate device within the integration. See the two registered devices in the original post. The datamanager will only come offline if you manually shutdown the inverter with its main power switch.

However it won't report the inverter during sundown. Even though the response is empty, it is (technically) a valid response because the inverter is physically offline and can not be found therefore. This behaviour persisted through previous firmware but I can provide an update after sundown. on the latest one.

Regarding your assumption to query once on startup and use said response. (Context) I would make the assumption that a solar setup is something one considers permanent. It's unlikely to change frequently, if it changes at all during its lifetime. Correct? Even if it was changed once or twice we can safely assume, Home Assistant is restarted more often than a solar setup changes.

Right now the integration calls get_inverter_infos() on every startup. It makes sense! It might just be the initial use of the integration and no device was ever discovered. What it receives as return value might not be correct though. As during sundown we know the inverter is missing from the response. The integration currently regards that response as it's single source of truth and thus (potentially) changes setup/configuration on every restart. Disregarding previously found inverters. It is unlikely for the inverters to be physically removed though. It is more likely they are just offline. The rational to increase the time between polls after 3 failed attempts is in line with that thought. (A) It might just be offline but still exists afterall. I'd suggest to load previously identified devices from the stored configuration and call get_inverter_infos() in addition. If the physical inverter was really removed, a user would still need to manually remove the device from home assistant anyhow. The way it currently works would not change that either. It seems reasonable to just call GetInverterRealtimeData.cgi on a previously discovered device instead. We are back to (A) waiting for it to come online.

I hope that makes sense?

weitzelb commented 1 year ago

Good evening @farmio. The situation is exactly the same after the firmware update. The inverter is not listed in the response from GetInverterInfo.cgi after it has gone offline. I did verify with a manual call. It has the following response.

{ "Body" : { "Data" : {} }, "Head" : { "RequestArguments" : {}, "Status" : { "Code" : 0, "Reason" : "", "UserMessage" : "" }, "Timestamp" : "2023-06-27T21:48:52+02:00" } } So if during sundown a Home Assistant restart is performed, the inverter is not going to be added and polled by the integration.

This evening I learned something more about the time it goes "offline". Contraty to my initial belive (it was just too late then I guess), the inveter does not become unavailable when not porducing any more AC power. However it is reported by GetInverterInfo.cgi as long as there is some DC input from the panels. f1 f2 If not restarted it will cycle through its connections attempts. Thats the state to be restored after a reboot during sundown I'd suggest. As it seems to be the most consistent with the current design of the adapter. I do not think cycling through for GetInverterInfo.cgi constantly to detect changes is reasonable for the reasons state in my previous post. It's a rather persistent setup afterall.

2023-06-27 21:43:57.044 DEBUG (MainThread) [pyfronius] Get current inverter data for GetInverterRealtimeData.cgi?Scope=Device&DeviceId=1&DataCollection=CommonInverterData 2023-06-27 21:43:58.077 DEBUG (MainThread) [pyfronius] Get current inverter data for GetInverterRealtimeData.cgi?Scope=Device&DeviceId=1&DataCollection=CommonInverterData 2023-06-27 21:43:58.928 DEBUG (MainThread) [pyfronius] Get current inverter data for GetInverterRealtimeData.cgi?Scope=Device&DeviceId=1&DataCollection=CommonInverterData 2023-06-27 21:43:59.977 DEBUG (MainThread) [homeassistant.components.fronius] Finished fetching fronius_inverter_1_fronius.meins.de data in 2.933 seconds (success: False)

farmio commented 1 year ago

Hi 👋! Sorry for coming back to you so late, it's a busy time currently 😬

I do not think cycling through for GetInverterInfo.cgi constantly to detect changes is reasonable

I think it is the better way to go. We wouldn't need to do any cleanup of the ConfigEntry ever (eg. when an inverter was replaced) and the integration would work just fine if set up initially at night - after getting a new response from GetInverterInfo it would just start querying the device.

1 request per hour would probably be enough, but since it is local anyway, more would also be fine.

The situation is exactly the same after the firmware update.

Did you update the Dataloggers firmware explicitly? (It is independent of the inverters).

I think you could file a bug report to Fronius since it doesn't behave the expected way according to the API documentation. Maybe you would at least get an explanation. (Although my experience with Fronius customer support for API questions leaves much to be desired 😕).

All models we have tests for seem to always be online since they have Smartmeters connected and thus "Night Mode" active.

weitzelb commented 1 year ago

Hi 👋! Sorry for coming back to you so late, it's a busy time currently 😬

Hi, no worries. My temporary workaround does help, although a crontab to restart the home assistant service at 7:30 isn't elegant. Plus I started reading some on home assistant development and that's a plus ;)

1 request per hour would probably be enough, but since it is local anyway, more would also be fine.

Anything that does address this issue is fine. I was just brainstorming some possibilities. Some integrations send many more requests than 1 request per hour. Locally, that can absolutely be neglected in terms of ressource consumption.

Did you update the Dataloggers firmware explicitly? (It is independent of the inverters).

Yes, the datalogger through the web interface on http://fronius.mine.de/#/fw_update

All models we have tests for seem to always be online since they have Smartmeters connected and thus "Night Mode" active.

I do not have a fronius smartmeter in my setup. Just the inverter with the data logger card in its expansion slot. Thus there is no night mode with this model. Instead it is just off. With my SMA inverter it is more easy, that one is always accessible.

(Although my experience with Fronius customer support for API questions leaves much to be desired 😕)

I am just happy there is a local API available :) I don't like devices, especially related to the house that only have an "online"-API or nothing at all.

farmio commented 1 year ago

Plus I started reading some on home assistant development and that's a plus

So do you feel comfortable to make the changes? I'd be happy to review, and also help out on discord if you have specific questions. I just can't get to it myself in the next couple of weeks / months.

I am just happy there is a local API available

Imho it's still a bug in the API implementation that could be fixed by them 🤷

weitzelb commented 1 year ago

So do you feel comfortable to make the changes? I'd be happy to review, and also help out on discord if you have specific questions. I just can't get to it myself in the next couple of weeks / months.

Sure, sounds like a good plan. I'll give it a shot nad look into it during the week.