Closed ffm777 closed 4 months ago
@ffm777 Did you notice the API Limit Exceeded warning on line 25 of the file?
What's your API call quota, @ffm777? 50? 10?
And what is the content of your /config/solcast-usage.json? Does it match your expected quota? Does this file even exist?
Not getting the forecast should not result in a fail to get the rooftop site total today, but I can't yet see what is causing this.
The value should just not change.
@ffm777, are you clever enough to update some code as a test, please?
I had rigged /homeassistant/custom_components/solcast_solar/solcastapi.py
to simply return when an API use limit had been reached.
What this change below to the function http_data() does is to build the forecast using the last forecasts data that had been successfully gatherered. This is where the 'tally' is included (but I'm not sure why it went missing).
Replace http_data() with the below, restart integration and then intentionally bust through the API limit at the end of the day. Or do it at a time of day when 10/10 calls should already be used up so that you don't waste any. (I just did so, and what my log read is below the code.)
Note that this code also prevents frequent forecast acquisition, not gathering if fifteen minutes since last has not elapsed. That is experimental code to try and avoid another issue that another user and I encountered, so if it impacts you then remove those two lines near the top.
async def http_data(self, dopast = False):
"""Request forecast data via the Solcast API."""
if self.get_last_updated_datetime() + timedelta(minutes=15) < dt.now(timezone.utc):
_LOGGER.warning(f"SOLCAST - not requesting forecast because time is within fifteen minutes of last update ({self.get_last_updated_datetime().astimezone(self._tz)})")
return
lastday = dt.now(self._tz) + timedelta(days=7)
lastday = lastday.replace(hour=23,minute=59).astimezone(timezone.utc)
failure = False
for site in self._sites:
_LOGGER.debug(f"SOLCAST - API polling for rooftop {site['resource_id']}")
#site=site['resource_id'], apikey=site['apikey'],
result = await self.http_data_call(site['resource_id'], site['apikey'], dopast)
if not result:
failure = True
self._data["version"] = _JSON_VERSION
if not failure:
self._data["last_updated"] = dt.now(timezone.utc).isoformat()
#await self.sites_usage()
#self._data["weather"] = self._weather
self._loaded_data = True
await self.buildforcastdata()
await self.serialize_data()
2024-06-18 15:41:06.417 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Service call: update_forecasts
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - API polling for rooftop b68d-c05a-c2b3-2cf9
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Polling API for rooftop_id b68d-c05a-c2b3-2cf9
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - fetch_data code url - https://api.solcast.com.au/rooftop_sites/b68d-c05a-c2b3-2cf9/forecasts
2024-06-18 15:41:06.417 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - API limit exceeded, not getting forecast
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - API polling for rooftop 83d5-ab72-2a9a-2397
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Polling API for rooftop_id 83d5-ab72-2a9a-2397
2024-06-18 15:41:06.417 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - fetch_data code url - https://api.solcast.com.au/rooftop_sites/83d5-ab72-2a9a-2397/forecasts
2024-06-18 15:41:06.417 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - API limit exceeded, not getting forecast
2024-06-18 15:41:06.432 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-18 contains all 48 records
2024-06-18 15:41:06.433 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-19 contains all 48 records
2024-06-18 15:41:06.435 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-20 contains all 48 records
2024-06-18 15:41:06.436 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-21 contains all 48 records
2024-06-18 15:41:06.436 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-22 contains all 48 records
2024-06-18 15:41:06.438 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - Data for 2024-06-23 contains all 48 records
I will test.
But I have also discovered another error concerning the API used counter. When using 2 API keys, then the calls are added. This should not be the case. For example, today I made 4 API calls to each of my accounts. With my quota of 10 calls, I still have 6 calls per account left. However, the integration counts 8 API calls used, which is not correct. When using 2 API keys, then the integration should not add the API call from both accounts but rather should only count the calls to one of the accounts!
That was also the reason why yesterday evening the integration said that the API limit is exceeded, which it was not. I checked my solcast accounts and there were still API calls left!
When using 2 API keys
This is fair and square a bug. I'll take a look.
I'll need to add separate counters for each API key.
Righto, @ffm777. Commit https://github.com/BJReplay/ha-solcast-solar/commit/9373df609385ce2bd3d3187c4f89edbc0275fac3 is experimental.
This alters solcastapi.py to account for multiple API key site usage information, and I'd appreciate a test from someone who actually has this set-up. Initial test for one site/two arrays is good for me.
I have also incorporated the experimental code above.
The code tracks the individual quotas, not assuming that both sites have the same quota. e.g. Someone might have 50 for their initial site, and 10 for a new hobbyist site.
In the above example, asking the integration "how many calls can I make?" it would answer: 60, and for usage, the sum of both sites. That is what it is.
So grab solcastapi.py from the commit, make a backup of your current file, replace, and re-start to see what happens!
You should get two files in /config called solcast-usage-[sitekey].json, unlike everyone else with one site that just has a solcast-usage.json file. If this works, you can delete /config/solcast-usage.json.
Hold off @ffm777 .
The experimental "do not call within fifteen minutes of last call" is not working...
2024-06-18 19:55:54.973 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - not requesting forecast because time is within fifteen minutes of last update (2024-06-18 15:40:24.855591+10:00)
I started testing the new version. First API call looks good. No more errors. API counter is also correct.
Only minor thing that I discovered is a Solcast warning "SOLCAST - Retries exhausted gathering rooftop sites data, last call result: 429, using cached data if it exists" when I restarted HA to enable the new version. Does the integration try to retrieve data on start-up? I would prefer the integration only calling the API when triggered by the update_forecasts service.
I would prefer
Nope, @ffm777.
And it looks like it used the cached rooftop sites data perfectly, so no foul, and that makes me smile.
There are some API calls that do not count against your daily quota. And I will use them. Chiefly for the question "How many calls am I allowed?", and that is un-metered. Secondly, "What rooftop sites do I have?", and again un-metered.
You have to be able to ask those questions before you can interact with the API, so they let you at will. Unless they're busy...
And therein lies the MOST COMMON cause of 429 errors. "Go AWAY hobbyist! We're A LITTLE BUSY RIGHT NOW BECAUSE OF ALL YOU HOBBYISTS!" (tell your mates, please...)
So... enter autoSteve's caching code.
If either call fails, then I get the data out of a cache. If the cache doesn't exist? Well, I guess folks raise an issue here, and we tell them to go restart a few times, and review logs, and re-think things if it isn't an integration problem, which is most of the time, and probably why Oziee committed GitHub suicide. 🤣
So no.
I have to make that call to see whether anything has changed. It if fails? No problemo, unless there's been a change...
As an aside, the sequence is:
I have built in a 'back-off' retry for the forecast get to cope with "GO AWAY! We're busy" from Solcast. Basically this delays for 30+(random 0-30 secs), then 60+(random 0-30 secs), then 120+(random 0-30 secs), etc. for five times.
You won't notice that delay, and it usually succeeds, so probably won't even go hunting for it in the logs. But I'll bet you see it from time-to-time if you do actually look.
Finally, the reason that I didn't do a back-off retry for initial rooftop sites and API quota use. That would introduce potential significant delay for the startup of the integration. And it's not that important as long as the info has been gathered on a prior restart.
Do let me know how things go over the next day, @ffm777.
If it's all pleasing for you then I'll raise a pull request for inclusion in the next version.
I updated to V4.0.31 last night, which ran OK. I have an automation that only updates once per day at Sunrise - 7 minutes, so reasonably random from the perspective of limiting Solcast calls. I had a "Unable to get sensor value 'tally'" error when I looked at the logs from that time earlier today, and as a test I've just made a service call to Solcast PV Forecast: Update and got the same error. However, if I check the contents of the solcast.json file, a 'tally' entry exists for each of my roofs, and each has a sensible value. I have so far today used 6 of my 10 Solcast api calls
solcast.json file:
Log: 2024-06-18 22:45:57.267 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Service call: update_forecasts 2024-06-18 22:46:00.339 ERROR (MainThread) [custom_components.solcast_solar.sensor] SOLCAST - unable to get sensor value 'tally' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 463, in _handle_coordinator_update self._sensor_data = self.coordinator.get_site_sensor_value( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 162, in get_site_sensor_value return self.solcast.get_rooftop_site_total_today(roof_id) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 387, in get_rooftop_site_total_today return self._data["siteinfo"][rooftopid]["tally"]
KeyError: 'tally'
2024-06-18 22:46:00.343 ERROR (MainThread) [custom_components.solcast_solar.sensor] SOLCAST - unable to get sensor value 'tally' Traceback (most recent call last):
File "/config/custom_components/solcast_solar/sensor.py", line 463, in _handle_coordinator_update
self._sensor_data = self.coordinator.get_site_sensor_value(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/solcast_solar/coordinator.py", line 162, in get_site_sensor_value
return self.solcast.get_rooftop_site_total_today(roof_id)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/solcast_solar/solcastapi.py", line 387, in get_rooftop_site_total_today
return self._data["siteinfo"][rooftopid]["tally"]
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^
KeyError: 'tally'
Hope this is of some help
Hey, @ProphetOfDoom.
4.0.31 does not include this code for http_data() in solcastapi.py. That is currently in a draft pull request.
If you change this section of code and restart Solcast integration do things go better?
async def http_data(self, dopast = False):
"""Request forecast data via the Solcast API."""
if self.get_last_updated_datetime() + timedelta(minutes=15) > dt.now(timezone.utc):
_LOGGER.warning(f"SOLCAST - not requesting forecast because time is within fifteen minutes of last update ({self.get_last_updated_datetime().astimezone(self._tz)})")
return
lastday = dt.now(self._tz) + timedelta(days=7)
lastday = lastday.replace(hour=23,minute=59).astimezone(timezone.utc)
failure = False
for site in self._sites:
_LOGGER.debug(f"SOLCAST - API polling for rooftop {site['resource_id']}")
#site=site['resource_id'], apikey=site['apikey'],
result = await self.http_data_call(site['resource_id'], site['apikey'], dopast)
if not result:
failure = True
self._data["version"] = _JSON_VERSION
if not failure:
self._data["last_updated"] = dt.now(timezone.utc).isoformat()
#await self.sites_usage()
#self._data["weather"] = self._weather
self._loaded_data = True
await self.buildforcastdata()
await self.serialize_data()
@autoSteve Just gave your suggestion a whirl
Actions:
Log entries filtered by "solcast" (so no solcast errors or warnings):
2024-06-19 02:04:53.483 INFO (MainThread) [homeassistant.setup] Setting up solcast_solar 2024-06-19 02:04:53.483 INFO (MainThread) [homeassistant.setup] Setup of domain solcast_solar took 0.00 seconds 2024-06-19 02:04:55.860 INFO (MainThread) [custom_components.solcast_solar] Solcast Integration version number: v4.0.31 2024-06-19 02:04:59.910 INFO (MainThread) [homeassistant.components.sensor] Setting up solcast_solar.sensor 2024-06-19 02:05:00.025 INFO (MainThread) [homeassistant.components.select] Setting up solcast_solar.select 2024-06-19 02:05:00.027 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Solcast API data UTC times are converted to Europe/London 2024-06-19 02:05:18.342 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Initialized trigger Solcast PV Forecast
File updates:
API Calls:
Roof tallys:
I'll leave it at that for now and see what happens when my solcast automation runs at (sunrise - 7) mins, which is about 04:30 BST and let you know later today
Do let me know how things go over the next day, @ffm777.
Hi Steve, I did 2 more update calls. The one last night went well. No problems. However, the first one this morning failed with the attached errors. The last error (AttributeError: 'int' object has no attribute 'items') repeats itself over and over. Will restart HA and see how it goes.
...first one this morning failed...
Replace this function in coordinator.py, @ffm777. You too, @ProphetOfDoom. I missed setting the API count to zero at midnight for each account. I'll also commit this into the draft pull.
async def update_utcmidnight_usage_sensor_data(self, *args):
try:
for k in self.solcast._api_used.keys():
self.solcast._api_used[k] = 0
self.async_update_listeners()
except Exception:
#_LOGGER.error("SOLCAST - update_utcmidnight_usage_sensor_data: %s", traceback.format_exc())
pass
Actually not, @ProphetOfDoom. I don't think you're running this proposed code. Just 4.0.31 with the mod above, so don't.
Replace this function in coordinator.py
Ok. Replaced the code and restarted. Let's see how it goes. I keep you posted. The update call after restarting the integration this morning (before replacing the code) also went well. No problems.
System details: Core 2024.6.3 Supervisor 2024.06.0 Operating System 12.4 Frontend 20240610.1
http_data() in solcastapi.py updated as posted above
Solcast automation ran at 04:46 BST
solcast.json file updated solcast-sites.json file not updated solcast-usage.json file updated
2 api calls used out of 10
all sensors populated solcast.json file shows roof tallys as 19.7577 kWh and 16.8201 kWh Solcast diagnostic section shows NE Roof as 16.82 kWh and SW Roof as 19.76 kWh
Solcast entries in log file: 2024-06-19 04:46:04.575 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Solcast PV Forecast: Running automation actions 2024-06-19 04:46:04.576 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Solcast PV Forecast: Executing step call service 2024-06-19 04:46:04.576 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Service call: update_forecasts
Looks encouraging, @ProphetOfDoom.
All still running smoothly, @ffm777 & @ProphetOfDoom? We've had a UTC counter reset by now, so any more "tally" or midnight reset issues?
All still running smoothly, @ffm777
Almost. All update calls went well. But on one of my update calls this morning, I received a tally error when the Solcast API was busy. See attached logs. But all update calls worked and values were updated correctly.
That debug log is likely going to be SUPER helpful @ffm777.
The "tally" issues happen between retries. Whoa.
So the "tally" key in the dict must go missing between the start of poll and end of poll, whether that be a success or a failure.
Great capture!
@autoSteve System details: Core 2024.6.3 Supervisor 2024.06.0 Operating System 12.4 Frontend 20240610.1
http_data() in solcastapi.py updated as posted above
Solcast automation ran at 04:46 BST
solcast.json file updated solcast-sites.json file not updated solcast-usage.json file updated
2 api calls used out of 10
all sensors populated solcast.json file shows roof tallys as 14.4478 kWh and 13.6408 kWh Solcast diagnostic section shows NE Roof as 13.64 kWh and SW Roof as 14.45 kWh
Solcast entries in log file: 2024-06-20 04:46:13.984 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Solcast PV Forecast: Running automation actions 2024-06-20 04:46:13.984 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Solcast PV Forecast: Executing step call service 2024-06-20 04:46:13.984 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Service call: update_forecasts
I assume that if you wanted any detailed debug logging I would not only have to set my configuration.yaml like this:
#
Set logger level
logger:
default: info
logs:
custom_components.solcast-solar: debug
but also turn on "Enable debug logging" in the Solcast configuration dialog
Sooo... @ffm777.
The "unable to get sensor value 'tally'" messages presumably go away after a successful forecast poll, yes? You don't show what happens after ultimate success in the log, so presumably it was uninteresting.
This has really got me scratching my head, but I will find it...
Some time between a commencement of poll, and the ultimate result of the poll, whether successful or not, the value self._data["siteinfo"][rooftopid]["tally"] goes away. I cannot see why at the moment. If there is an appreciable delay (like because Solcast is busy), then HA tries to read this sensor value, and it doesn't exist, so the exception occurs.
Yet, it should persist the http_data() call from all the code staring that I've done.
I continue to stare with a furrowed brow... Any other staring from anyone else would be appreciated.
The "unable to get sensor value 'tally'" messages presumably go away after a successful forecast poll, yes? You don't show what happens after ultimate success in the log, so presumably it was uninteresting.
Yes. After the successful forecast poll they go away. My system ran two more forecasts updates at 11:45 am and 2:35 pm which were both uneventful. Everything went smoothly. No more tally errors.
Thought as much.
At this stage I have absolutely nothing to explain why it is happening. HA calls http_data(), which calls http_data_call() for each rooftop, which then calls fetch_data() for each rooftop.
At no stage is self._data["siteinfo"][rooftopid]["tally"] or self._data["siteinfo"][rooftopid] or self._data["siteinfo"] messed with before a successful call is had from what I can see.
So there is something that I can not see yet that is causing it to be temporarily lost.
The good thing is at least that the integration works just fine even with the error. So no crashes or anything. But of course. Would be nice to get rid of that error.
I could just suppress it... (Evil laugh...) But no. I will not.
For now, I just cannot explain this loss of "tally" during the retry. I have spent literally hours staring at the code and can come up with nothing, which is exasperating given I do Python for a day job. This integration code is not that complex! Fresh eyes tomorrow, I guess...
@autoSteve Just a mad thought. @ffm777 has two api keys. Does handling one "interfere" with the data of the other in some way?
It's not mad at all. I had the same thought, @ProphetOfDoom. It was @ffm777's second account call of two that failed, and that resulted in retry with "tally" issues for the duration. The first account was all good with no retry.
I have one account, and have never seen this, ever, so there may definitely be something behind that.
If it was the first account of two retrying and getting the "tally" thing, then fair enough, although I've still got nothing if this happens. But should it always be the second account on retry doing this??? THEN I have something. Well, then I have not much of something, because that would not make sense, but at least it's a pattern to chase...
I just can't see what could be behind it in the code. Gha!
It is also interesting (to me) that account two, rooftop one completely failed even after back-off retry, virtually confirming that the Solcast API is getting real hard for hobbyists to work with, necessitating lengthy retries. I was right to code this. This poll was around the turn of the hour, giving up at around seven minutes past the hour. That's not flash from a service provider point of view. Then account two, rooftop two succeeded after a couple of retries at around eight and a half minutes past the hour.
Same thing almost happened to me yesterday with one account and two arrays.
I might need to be even more feisty and extend the back-off retry for one more iteration.
(But I digress from "I got nothin'"...)
Today I set my automation for on-the-hour forecast gather to try and examine failure / retry scenarios.
All of them have succeeded without any retry. 🤦🏻😂
So as I said, I cannot see why the 'tally' is going missing.
Attempted mitigation time, given it appears to be transient while the retry is occurring.
Try the following:
Replace line 399 in solcastapi.py, which is:
return self._data["siteinfo"][rooftopid]["tally"]
with this...
if self._data["siteinfo"][rooftopid].get("tally") == None: _LOGGER.warning(f"SOLCAST - 'Tally' is currently unavailable for rooftop {rooftopid}")
return self._data["siteinfo"][rooftopid].get("tally")
If 'tally' cannot be found, then None
will be returned, but at least something will be, which will hopefully side-step the error. (It may cause a different error, though, if a number is always required.) (The site sensor will just show as 'Unknown'...)
(Edited. Sorry.)
I just switched to 4.0.32. Let's see how it goes. Didn't have any more tally errors yesterday and today. Thanks @autoSteve for your efforts to get everything working nicely and smoothly again!
🫰 @ffm777. The work-around for 'tally' missing just results in the site sensor showing as Unknown. Does anyone ever use that anyway??? I certainly don't...
For me, it's these...
Updated to V4.0.32 and restarted HA. Reminder that my solcast automation is set to run at Sunrise - 7 mins, so approx 04:46 BST
solcast.json file NOT updated solcast-sites.json file updated solcast-usage.json file updated
2 api calls used out of 10
all sensors populated solcast.json file shows roof tallys as 13.8112 kWh and 17.5111 kWh Solcast diagnostic section shows NE Roof as 17.51 kWh and SW Roof as 13.81 kWh
Solcast entries in log file: 2024-06-21 14:16:35.064 INFO (MainThread) [homeassistant.setup] Setting up solcast_solar 2024-06-21 14:16:35.065 INFO (MainThread) [homeassistant.setup] Setup of domain solcast_solar took 0.00 seconds 2024-06-21 14:16:36.660 INFO (MainThread) [custom_components.solcast_solar] Solcast Integration version number: v4.0.32 2024-06-21 14:16:39.540 INFO (MainThread) [homeassistant.components.sensor] Setting up solcast_solar.sensor 2024-06-21 14:16:39.653 INFO (MainThread) [homeassistant.components.select] Setting up solcast_solar.select 2024-06-21 14:16:39.654 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Solcast API data UTC times are converted to Europe/London 2024-06-21 14:16:58.041 INFO (MainThread) [homeassistant.components.automation.solcast_pv_forecast] Initialized trigger Solcast PV Forecast
All looking good so far, thanks to all.
So, @ProphetOfDoom, Your Solcast diagnostics will maybe show 'Unknown' for the NE/SW Roofs during times where the integration is retrying a forecast poll. And that's a real 'maybe'. I can't explain why it happens, but it just does. Once the retrying is done the values will come back.
At least it doesn't error out now.
Given the pre-release v4.0.32, could I get you to respond favourably or not in that discussion whether the whole 'tally' thing has been mitigated now? I'm trying to gather data points that will help inform GA of that release.
I already posted under "Discussion". 4.0.32 seems to work fine on my end, but I did get the tally warning this morning. See attached log.
Not calling this as closed yet. Yes, there is a work-around in v4.0.32+, which makes it go away with a warning, but I am not happy with why it is happening at all. It should not be so.
I'm fairly certain that the whole 'tally' thing is a thing of the past in v4.0.34, so closing this.
I added a separate dictionary to hold the current tally, which will not be interfered with by a forecast get/retry sequence.
The integration successfully makes API calls to solcast servers when HA is restarted. However, with the next call a couple of hours later I get errors. From the debug info it looks as if the API call is successful at first, but then later the integration produces an error "SOLCAST - unable to get sensor value 'tally' Traceback". See attached debug info.
I'm using 2 API keys at the same time, because I have 4 planes with different orientations.
Solcast Integration Version I'm on version 4.0.31 Solcast_Debug.txt