search

BJReplay / ha-solcast-solar

Solcast Integration for Home Assistant
Apache License 2.0
191 stars 34 forks source link

problem with migration from Ozzie's version #200

Closed niggles1973 closed 1 month ago

niggles1973 commented 1 month ago

The problem

Hi, I've just installed the latest version 4.2.3 by following the recommended HACS recommended on https://github.com/BJReplay/ha-solcast-solar over the top of 2nd to last version that ozzie published to HACS (which was working perfectly but I was liking the new features coming out)

Looking at the logs; solcast returns 429/try again later; but what I don't understand is when I enter

curl https://api.solcast.com.au/rooftop_sites\?format\=json\&api_key\=\*\*\*\*\*\*Hbie_n (with correct api_key I get the sites JSON data) from the home assistant terminal it works; and I see the site json file; similarly from another webbrowser on another IP address I also gets the sites file.

Is it possible that solcast for home assistant is getting 429 from the solcast api; but the home assistant terminal isn't?

What version of Solcast Integration has the issue?

v4.2.3

What version of Home Assistant are you using?

2024.10.3

Diagnostics information

No response

Logs debug/info/error output

2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar] Auto-update options: {'auto_update': 0}
2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar] Estimate to use options: {'key_estimate': 'estimate'}
2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar] Attribute options: {'attr_brk_estimate': True, 'attr_brk_estimate10': True, 'attr_brk_estimate90': True, 'attr_brk_site': True, 'attr_brk_halfhourly': True, 'attr_brk_hourly': True, 'attr_brk_detailed': False}
2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar] Custom sensor options: {'customhoursensor': 1}
2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar] Hard limit: {'hard_limit': 100000}
2024-10-21 20:54:24.661 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Configuration directory is /config
2024-10-21 20:54:24.662 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Sites cache does not yet exist
2024-10-21 20:54:24.662 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Connecting to https://api.solcast.com.au/rooftop_sites?format=json&api_key=******Hbie_n
2024-10-21 20:54:24.674 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] HTTP session returned status 429/Try again later in __sites_data(), trying cache
2024-10-21 20:54:24.674 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Will retry get sites, retry 1
2024-10-21 20:54:29.698 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] HTTP session returned status 429/Try again later in __sites_data(), trying cache
2024-10-21 20:54:29.699 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Will retry get sites, retry 2
2024-10-21 20:54:34.712 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] HTTP session returned status 429/Try again later in __sites_data(), trying cache
2024-10-21 20:54:34.712 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Will retry get sites, retry 3
2024-10-21 20:54:39.729 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] HTTP session returned status 429/Try again later in __sites_data(), trying cache
2024-10-21 20:54:39.729 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] Retries exhausted gathering sites, last call result: 429/Try again later, using cached data if it exists
2024-10-21 20:54:39.729 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] Cached sites are not yet available for ******Hbie_n to cope with API call failure
2024-10-21 20:54:39.729 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] At least one successful API 'get sites' call is needed, so the integration will not function correctly
2024-10-21 20:54:39.729 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] https://api.solcast.com.au HTTP status error 404/Not found in __sites_data() while gathering sites
2024-10-21 20:54:39.730 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] Exception in __sites_data(): HTTP __sites_data() error: gathering sites: Traceback (most recent call last):
  File "/config/custom_components/solcast_solar/solcastapi.py", line 542, in __sites_data
    raise Exception("HTTP __sites_data() error: gathering sites")
Exception: HTTP __sites_data() error: gathering sites

Additional information

No response

niggles1973 commented 1 month ago

output from curl from home assistant terminal

➜ solcast_solar curl https://api.solcast.com.au/rooftop_sites\?format\=json\&api_key\=othekeyHbie_n

{"sites":[{"name":"Skyline","resource_id":"censored","capacity":30.7,"capacity_dc":33.6,"longitude":147.4,"latitude":-42.8,"azimuth":-34,"tilt":12,"install_date":"2021-12-21T13:00:00.0000000Z","loss_factor":0.7,"tags":[]}],"page_count":1,"current_page":1,"total_records":1}#

autoSteve commented 1 month ago

That is a very interesting question. And is actually spooky @niggles1973, as it is a question that I was trying to answer myself just now.

I built the retry mechanism for sites get. And I have been struggling with 429s for three hours or so on restart.

I too get a curl response. Mostly. Sometimes it is 429, though.

Forecast fetches at the moment do not go well. 429 city.

Fetches on my production rig occurred flawlessly throughout the day. (GMT+11).

niggles1973 commented 1 month ago

well we are both not going mad then :)

I just did 6 CURLs in a row; and haven't gotten a single 429/ (nor have I managed to get any in the last hour or so in trying to work out the above)

autoSteve commented 1 month ago

Welcome aboard, @niggles1973, BTW!

autoSteve commented 1 month ago

I adjusted the code to do twenty retries, 0.5 second delay between each. All 429. curl works at the time... Gah!

If you know anything about aiohttp now would be time time to speak up.

BJReplay commented 1 month ago

I wonder if there is something in the headers of the integration requests (perhaps @billy-solcast can comment) that Solcast is using to throttle those requests that isn't present in the (by definition) much simpler curl requests (even when from within the HA terminal which I didn't know was a thing until now) that is allowing them to succeed more often?

niggles1973 commented 1 month ago

I'm thinking headers as well (but I'm not across aiohttp) - just having a Quick Look at the code but will need to head off soon for the night (hello from Hobart BTW)

niggles1973 commented 1 month ago

try forcing the user-agent

User-Agent: curl/8.9.1

autoSteve commented 1 month ago

Interesting.

I just spoofed a Windows 10 browser as the user agent. Got an immediate "200"...

May have been a fluke. Reverted and got ... 429s.

autoSteve commented 1 month ago

User-Agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36

autoSteve commented 1 month ago

Updated code if you want to get going with us quickly @niggles1973.

Line 439-ish in solcastapi.py...

                        while retry >= 0:
                            headers = {
                                'Accept': 'application/json',
                                'User-Agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36'
                            }
                            resp: ClientResponse = await self._aiohttp_session.get(url=url, params=params, ssl=False, headers=headers)
niggles1973 commented 1 month ago

heh :) funny story; chatgpt literally just told me to put the same code in

autoSteve commented 1 month ago

Sooo... @BJReplay. Add this header to all Solcast calls? Push as v4.2.4? Solcast must have pushed a change.

niggles1973 commented 1 month ago

yep; confirmed; all working now thanks for your help @autoSteve

autoSteve commented 1 month ago

I simplified the user agent to Mozilla/5.0. Works. Reverted. No works.

Deffo a v4.2.4 'emergency' bump. I will stash the prevailing v4.2.4 multi-hard limit proposal and work this @BJReplay.

BJReplay commented 1 month ago

What about any user agent?

Like Solcast HA Integration/4.0, @autoSteve

autoSteve commented 1 month ago

Nah. They'd get wise to that... 😉

BJReplay commented 1 month ago

Nah. They'd get wise to that...

It depends on whether it is intentional, or badly configured caching / WAF.

My gut feeling is WAF / caching.

It would be interesting to see if they throttle it now for you or you go back to top speed.

autoSteve commented 1 month ago

I won't know until I rebase on the proposed 4.2.4 code, but I am tipping four hours of 429s will melt away. (Maybe we should have called it v4.2.9... 🤣)

autoSteve commented 1 month ago

PR for multi-API-key hard limit concurs. 429s resolved. All 200s, baby. Specific request headers for the win with aiohttp.

I am off and developing again...

autoSteve commented 1 month ago

Pleasing per-site/API key hard limit calculation times on forecast fetch. Ahh... Thought it would be quicker given the optimisation, but it is what it is. Fast.

2024-10-21 23:06:41.395 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] HTTP data call processing took 0.065 seconds
2024-10-21 23:06:41.396 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Hard limit for individual API keys: True
2024-10-21 23:06:41.397 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Hard limit for API key ******sxdNS5: 5.0
2024-10-21 23:06:41.399 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Earliest period: 2024-10-21 00:00:00, latest period: 2024-10-28 23:30:00
2024-10-21 23:06:41.405 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Hard limit for API key ******bvvHxW: 5.0
2024-10-21 23:06:41.408 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Earliest period: 2024-10-21 00:00:00, latest period: 2024-10-28 23:30:00
2024-10-21 23:06:41.413 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Build hard limit processing took 0.017 seconds for dampened
2024-10-21 23:06:41.475 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Build per-site and total processing took 0.025 seconds for dampened
2024-10-21 23:06:41.482 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Hard limit for API key ******sxdNS5: 5.0
2024-10-21 23:06:41.484 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Earliest period: 2024-10-21 00:00:00, latest period: 2024-10-28 23:30:00
2024-10-21 23:06:41.490 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Hard limit for API key ******bvvHxW: 5.0
2024-10-21 23:06:41.492 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Earliest period: 2024-10-21 00:00:00, latest period: 2024-10-28 23:30:00
2024-10-21 23:06:41.519 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Build hard limit processing took 0.037 seconds for un-dampened
2024-10-21 23:06:41.695 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Build per-site and total processing took 0.039 seconds for un-dampened
2024-10-21 23:06:41.710 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Forecast data from 2024-10-21 to 2024-10-28 contains all 48 intervals
2024-10-21 23:06:41.710 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Calculating splines
BJReplay commented 1 month ago

My gut feeling is WAF / caching.

@autoSteve they're using Amazon cloudfront.

My guess (but it is only a guess) is that any well formed user agent will work.

I have got around this problem for accessing the Tesla owner API with the internal name / version number of a my own application: userAgent:=My.Application.Info.Version.ToString

autoSteve commented 1 month ago

It interests me that this issue is an issue raised on migrating from Ozzie's version.

The exact same call (less retries, etc.) was being performed by his. No specific request headers. It has got to be a recent change. Were both forks were susceptible? Were we always susceptible? Prolly. I have seen a lot of 429s in the past.

We gonna release v4.2.4 or hit the hay?

billy-solcast commented 1 month ago

Hey all,

Adding some context here. We don't do any specific limiting/restricting on headers, as all of the work is done by the WAF. So it could be entirely out of coincidence.

@niggles1973 if you want to send me (support@solcast.com) your toolkit account details, I can have a look at our logs and trace back from there.

BJReplay commented 1 month ago

Thanks, @billy-solcast, appreciate the insight. Our observations are that your WAF is apparently rate limiting requests that come with the default header set by Home Assistant, but if we replace them, we don't get rate limited. Whether that is a planned, learned, or accidental behaviour is TBA.

niggles1973 commented 1 month ago

I’ve replied to @billy-solcast with my site details via support@solcast

billy-solcast commented 1 month ago

From what I've had a look at our logs, most of the API calls on the 21st UTC, were between 6am and 12am (UTC), which is the time where most of the 429's are coming from.

It varies day to day, but it looks like the 6am API calls (Europe) and 12am (Americas), are the majority of API calls, which makes sense given it's about dawn in the respective timezones, but it also means that those are the periods where the majority of 429's are likely to occur.

The header stuff is interesting, because for the logs, I saw it work in both instances throughout the day. So I can't say for sure what would have allowed some request to go through and others not.

niggles1973 commented 1 month ago

I've chatted to @billy-solcast seperately; I've enabled some bebug logging as billy was seeing a lot more 489/ than I was expecting for my site (but I was running the original Ozzie code prior to last night) - my node forecast updated is fairly simplistic and should be playing nice with the solcast api.

@autoSteve and I both saw it with our own eyes last night; as soon as we changed the User Agent we avoided the 489/ even when swapping between curl (user agent) and aiohttp (without user agent) in rapid succession - with user agent worked; without user agent didn't (repeatedly)

image

BJReplay commented 1 month ago

@niggles1973 the new release is out - if you Update Information on the integration within HACS, it should see the new version, and from there, prompt you to update (via a notification in settings, and then to restart).

image

niggles1973 commented 1 month ago

thanks; have updated to 4.2.4 and enabled debug logging

2024-10-22 18:04:55.245 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Fetching forecast 2024-10-22 18:04:55.327 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] API returned 'try later' (status 429), pausing 17 seconds before retry 2024-10-22 18:05:12.328 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] Fetching forecast 2024-10-22 18:05:12.380 WARNING (MainThread) [custom_components.solcast_solar.solcastapi] API returned 'try later' (status 429), pausing 43 seconds before retry