Values reading 'unknown' since last core update
booti101 opened this issue · 14 comments
Since i updated HA to Core 2023.8.2, values around the battery management have been reading as unknown.
I have had this before after an update, but it usually sorts itself after a day, once it has gathered fresh data.
This time its been about 5 days and a few reboots, but still coming back as unknown.
Not the end of the world, but i dont know if, when or how much battery charge the system may be adding overnight
@booti101 thanks, looks like it's struggling to get the forecast. Can you include some logs please?
I can, if you could guide me please. Not sure where to grab them from. Sorry
Settings -> System -> Logs.
Thanks for the prompt reply Nathan
Is this what we are looking for?
Logger: homeassistant.components.recorder.db_schema
Source: components/recorder/db_schema.py:584
Integration: Recorder (documentation, issues)
First occurred: 02:00:16 (9 occurrences)
Last logged: 08:30:24
State attributes for sensor.foxess_em_forecast exceed maximum size of 16384 bytes. This can cause database performance issues; Attributes will not be stored
State attributes for sensor.octopus_energy_electricity_20e5370959_xxxxxx_export_current_rate exceed maximum size of 16384 bytes. This can cause database performance issues; Attributes will not be stored
State attributes for sensor.octopus_energy_electricity_20e5370959_xxxxxx_current_rate exceed maximum size of 16384 bytes. This can cause database performance issues; Attributes will not be stored
State attributes for sensor.octopus_energy_gas_e6e00883212020_xxxxxx_current_rate exceed maximum size of 16384 bytes. This can cause database performance issues; Attributes will not be stored
@nathanmarlor Hi Nathan,
Sorry to say my EM also stopped today - it followed me updating to HA 2023.8.3 and the latest Foxess modbus (which uses a later version of pymodbus) and just realised that it was no longer working properly.
It still resets the inverter stop times when it starts, and is running the schedule for solcast but the rest of the sensors are unknown.
I've uploaded this error from my logs, when I get 5 mins tomorrow. i'll turn full debugging on and do a bit more digging around.
2023-08-19 17:30:00.324 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/config/custom_components/foxess_em/average/average_controller.py", line 70, in async_refresh
await self._model.refresh()
File "/config/custom_components/foxess_em/average/average_model.py", line 44, in refresh
await self._update_history(self._tracked_sensors[sensor])
File "/config/custom_components/foxess_em/average/average_model.py", line 52, in _update_history
await self._update_item(sensor.primary)
File "/config/custom_components/foxess_em/average/average_model.py", line 83, in _update_item
values_dict = [
^
TypeError: 'NoneType' object is not iterable
@FozzieUK oh dear! I'm away at the moment but will do some digging into what's changed between HA versions when I'm back.
Thanks Fozzie for help with your log files. I’m not to sure where to search for what Nathan needed.
Thanks for looking Nathan. Hope you enjoy your time off.
@FozzieUK oh dear! I'm away at the moment but will do some digging into what's changed between HA versions when I'm back.
@nathanmarlor Hi, sorry to say but my problem was a result of 2+2 = 5, after I updated to 2023.8.3 it stopped working - I added some debug code to trace the error and it was in the load sensor - several weeks ago I decided I didn't need to keep all the history for this to reduce my db size, so I excluded sensor.load_power from the logger ready for the next restart (I forgot) - the update restart caused it to lose it's history and when the average_controller cannot get it's history the house_load sensor doesn't get created, and later on you just get a 'NoneType' error - strangely enough because it doesn't exist...duh...... anyway, added it back in, allowed it to rebuild some history and after the restart it's working again so not a problem with the latest release - sorry to bother you whilst your away 😊 have a good time,.
@booti101 So turns out my error was self inflicted although I learned from that that the loss of a main sensor can cause similar results to yours, going back to what Nathan said to start - it looks in your case more like your forecast that is failing.
Assuming it's not the latest HA version - have you made any recent changes to exclude sensors from logger?, removed or added any other integrations recently ?
If we can increase your logging level we may get a better clue in your logs, if you look in your configuration.yaml file somewhere near the top you may have 2 lines that says -
logger:
default: warn
If you do can you add the extra lines below, if you don't have it just add the entire section of code to your configuration.yaml, check it's ok to restart and then restart.
logger:
default: warn
logs:
custom_components.foxess_em: debug
Once it has restarted give it a few minutes and it will have added much more information to your logs, to see that you will need to go to Settings, System, Logs and click on the button that says 'Load Full Logs'
The lines we are interested in will have the following tag in it 'DEBUG (MainThread) [custom_components.foxess_em.xxxxxxxx'
Can you copy and paste what you see below, particularly anything that appears to be in error state.
Hi Both
Thanks for the tips and direction @FozzieUK
I have made the change for the log files and rebooted, this is what I am seeing in the log files now. Nothing has been added or removed from the system that I can think of, but I will have upgraded any HACS installs at the time I did the 2023.8.2 update.
When I did the 2023.8.3 update to see if that helped, I also upgraded Fox EM integration and SolCast. I think SolCast is now broken, but it was working when this issue first came to light.
foxess_em
Version: 1.8.0
This is a custom integration!
If you have any issues with this you need to open an issue here:
https://github.com/nathanmarlor/foxess_em/issues
2023-08-21 09:16:22.418 DEBUG (MainThread) [custom_components.foxess_em] Initialising Modbus Serial service
2023-08-21 09:16:22.429 DEBUG (MainThread) [custom_components.foxess_em.fox.fox_modbus] Connecting to modbus - ({'connection_type': 'Modbus Serial', 'port': '/dev/ttyUSB0', 'baudrate': 9600})
2023-08-21 09:16:23.789 DEBUG (MainThread) [custom_components.foxess_em.fox.fox_modbus_service] Requesting start force charge from Fox Modbus
2023-08-21 09:16:23.789 DEBUG (MainThread) [custom_components.foxess_em.fox.fox_modbus_service] Setting single charge window - 01:30:00 / 08:30:00
2023-08-21 09:16:23.790 DEBUG (MainThread) [custom_components.foxess_em.fox.fox_modbus] Writing register: (41001, [1, 286, 2078, 0, 0, 0], 247)
2023-08-21 09:16:23.929 DEBUG (MainThread) [custom_components.foxess_em.fox.fox_modbus] Sucessful write to holding register: WriteMultipleRegisterResponse (41001,6)
2023-08-21 09:16:24.012 DEBUG (SyncWorker_1) [custom_components.foxess_em.battery.battery_controller] Refreshing battery model
Ok, thanks - I think it’s the fact that Solcast is broken, is the same issue with EM.
The logs so far all look ok - If you wait another 60 minutes, then go back and check your logs you should have some more entries that relate to EM, can you post those please.
Are you still able to log into the solcast website with your email address, just in case they have de-activated your account for some reason.
Hi @FozzieUK
Yes i can get into the SolCast site OK.
I have been going through the integration notes for Solcast and found this
v3.1.0
no more auto polling.. its now up to every one to create an automation to poll for data when you want. This is due to so many users now only have 10 api calls a day
I am guessing this is where it 'broke'
EDIT: Found their GitHub page and an automation that does the API poll, so this is back in place now.
Will see if that brings the EM back online in a few hours and report back
@booti101 FYI you can't run EM and Solcast together as they'll both use up your available API calls. It's one or the other I'm afraid!
@nathanmarlor ok, didnt know that. I have been running SolCast since the StealthChestnut version and for about 6 months along side EM. I guess it just used up my API calls before the day ended.
Could this be the issue then in EM, if SolCast needs us to manually poll the API, or does EM do this already?
Log files from the last two hours running, since i fixed the SolCast polling. Dont know if this first bit it EM related?
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/sensor/init.py", line 591, in state
numerical_value = int(value)
^^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'unknown'
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/template_entity.py", line 397, in _async_template_startup
result_info.async_refresh()
File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 1022, in async_refresh
self._refresh(None)
File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 1202, in _refresh
self.hass.async_run_hass_job(self._job, event, updates)
File "/usr/src/homeassistant/homeassistant/core.py", line 625, in async_run_hass_job
hassjob.target(*args)
File "/usr/src/homeassistant/homeassistant/helpers/template_entity.py", line 366, in _handle_results
self.async_write_ha_state()
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 746, in async_write_ha_state
self._async_write_ha_state()
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 808, in _async_write_ha_state
state = self._stringify_state(available)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 752, in _stringify_state
if (state := self.state) is None:
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/sensor/init.py", line 595, in state
raise ValueError(
ValueError: Sensor sensor.available_battery has device class 'None', state class 'None' unit 'kWh' and suggested precision 'None' thus indicating it has a numeric value; however, it has the non-numeric value: 'unknown' (<class 'str'>)
2023-08-21 09:41:30.166 DEBUG (MainThread) [custom_components.foxess_em.forecast.forecast_controller] Forecast cache is 10 days, 15:42:25.998562 old
2023-08-21 09:41:30.167 DEBUG (MainThread) [custom_components.foxess_em.forecast.forecast_controller] Refreshing forecast data
2023-08-21 09:41:30.167 DEBUG (MainThread) [custom_components.foxess_em.forecast] Retrieving available sites
2023-08-21 09:41:30.168 DEBUG (MainThread) [custom_components.foxess_em.average.average_controller] Refreshing averages model
2023-08-21 09:41:30.168 DEBUG (MainThread) [custom_components.foxess_em.battery.battery_controller] Refreshing battery model
2023-08-21 09:41:31.776 ERROR (MainThread) [custom_components.foxess_em.forecast.forecast_controller] TypeError("'NoneType' object is not subscriptable")
2023-08-21 09:41:31.777 DEBUG (MainThread) [custom_components.foxess_em.forecast.forecast_controller] Refreshing Solcast site info
2023-08-21 09:41:31.778 DEBUG (MainThread) [custom_components.foxess_em.forecast] Retrieving API call status
2023-08-21 09:41:32.916 ERROR (MainThread) [custom_components.foxess_em.forecast.forecast_controller] TypeError("'NoneType' object is not subscriptable")
2023-08-21 09:41:32.917 DEBUG (MainThread) [custom_components.foxess_em.battery.battery_controller] Refreshing battery model
2023-08-21 09:41:33.377 DEBUG (MainThread) [custom_components.foxess_em.average.average_controller] Finished refreshing averages model, notifying listeners
2023-08-21 09:41:33.377 DEBUG (MainThread) [custom_components.foxess_em.battery.battery_controller] Refreshing battery model
2023-08-21 09:41:35.756 DEBUG (SyncWorker_4) [custom_components.foxess_em.battery.battery_controller] Refreshing battery model
Haha, fixed it
Sorry, had a lightbulb moment from your earlier comment @nathanmarlor
From memory I thought EM was integrating with SolCast as a separate integration. I have just remembered that I had to rebuild my SolCast profile the other week. I updated their integration, but never thought to put the new API key in the EM integration as well.
Done that now and its showing data again.
Thanks for the assistance even while away from home, greatly appreciated
Also @FozzieUK thanks for your help with the log files sir.