Probable issues initialising cache due to likely persistent 429s from Solcast Service - Logging required.

[pajikcz]

Describe the bug just migrated from ozzie to BJreplay integration and cannot fetch data, API key added but is taking too long to initializace and no data fetched, no restart helped.

data are OK on solcast https://toolkit.solcast.com.au/home-pv-system/

message from integration: Solcast PV Forecast API Used became unavailable

running HAOS in all latest versions

Core 2024.6.3 Supervisor 2024.06.0 Operating System 12.3 Frontend 20240610.1

[pajikcz]

update!

i had to regenerate new API key and it is now started working!!! Looks loke old API key was cached etc.

[spgx105]

Not sure if this is connected but I found on a few occasions with the Ozzie version that following an update and restart it wouldn’t collect data. The solution I found was to change the API key in the integration (eg just deleting the last character), waiting for it to initialise, then changing back to the correct key.

After updating to v4.0.29 today I did the same as straight after the update it wasn’t connecting to Solcast.

[pajikcz]

Not sure if this is connected but I found on a few occasions with the Ozzie version that following an update and restart it wouldn’t collect data. The solution I found was to change the API key in the integration (eg just deleting the last character), waiting for it to initialise, then changing back to the correct key.

After updating to v4.0.29 today I did the same as straight after the update it wasn’t connecting to Solcast.

thanks for the hint, we'll see at the next release.

[Timer2000]

I have the same Problem with 4.0 29. I try the 4.0.28 without any Problems.

[bazcurtis]

I have made a new API key, but not getting data. I upgrade from 4.0.26 to 4.0.29. (26) wasn't working either.

[Timer2000]

Go back to 0.28 for a working Version

[Stephens-ely]

I upgraded to 4.0 29 today from 4.0.28 and was unable to collect data afterwards and all sensors showed as unavailable.

I tried reloading the integration, restarting HA and also using the service to reload the data. Nothing worked.

I used the API url in a browser and was able to collect the json without issue.

I went back to 4.0.28 and got data immediately

I suspect there’s an issue with 4.0.29!

latest HA (2024.6.3) running on HA Supervised/Debian/Docker.

[macfr76]

Same issue, I upgraded from 4.0.27 to 4.0.29 and not fetching data anymore.

I reverted to 4.0.28 that was reported working but was still not good. I did reconfigure with the same API key by copy / paste from Solcast website and then it started working again.

[Nilogax]

I'm still on Oziee's 4.0.22 and have been seeing similar issues today. Lots of 429s when my automatic updates run (at times offset from the hour) , but manual calls have been OK. Wondering if this is something at the Solcast end rather than with the integration.

[BJReplay]

Hi everyone, @autoSteve and I have been running .29 for a couple days. It might need a couple of restarts to properly cache arrays and data - and if it gets 429s from the Solcast servers on restart when it is attempting to cache arrays, it may take several attempts to store the data it needs to run properly and ride through future 429s.

What I think you're seeing is that you're hitting a 429 from the Solcast servers on installing 4.0.29, and because on the first (or second) start it is attempting to cache arrays or forecasts, it appears not be working, when it is infact trying to cache data and faililng, due to inability to poll the Solcast servers.

If you have logging, please post log outputs here so we can see what is happening. I might need to update the templates for bugs to request logs.

[autoSteve]

Did any of you check the log when the startup failed?

If you had you would have seen that this is a Solcast issue.

They are getting quite feisty with the 429/too busy errors, and I am doing my level best to try and work around them with retries/caching of whatever can be cached.

But the caches need to exist for the caches to be used...

[BJReplay]

For anyone with this issue with version v.4.0.29 who wants assistance, please add the following to your configuration.yaml and restart HA, and provide us with your log records for solcast.

That will enable us to determine whether there is a bug in the integration or the solcast service is timing out or returning 429.

 logger:
   default: warn
   logs:
     custom_components.solcast_solar: debug

[autoSteve]

Doing some investigating, I have two API keys in my configuration. I get data for the first one, not the one after the comma.

@bazcurtis, you have found a bug with the caching set up.

What is happening is because you have two Solcast accounts the sites cache gets greated for account number one, and then when the sites for account number two get retrieved, or not in this case, (because 429s almost certainly in the log, which really should be looked at to understand what is going wrong), so the sites cache for account number one would be used, which is not right and would cause massive issue for account two.

This is something that I am going to have to fix.

In the meantime, repeatedly restarting until it works will 'fix' it, because 429s will be to blame, and not this integration.

The cache creation for API use counter is even more interesting.

The integration only gets the current count for the first account, and not the second. This is probably okay, unless the two accounts have differing limits.

This is likely something that I will not fix.

[autoSteve]

All, I can confirm that 4.0.29 has a few issues.

• Retry mechanism to use cache is broken, fix is done
• Restarting just now the integration used up all of my remaining API calls for the day by repeatedly getting forecasts for some reason. I am trying to work out why that happened. I suspect others have hit this.

For now, revert to a prior working version until we can sort this out.

@BJReplay, we should probably remove 4.0.29.

[autoSteve]

Further:

Restarting just now did not use up all my API call allowance. It did do three successive forecast GETs. What I think happened is that the automation fired to trigger a forecast while the integration was restarting. This is interesting, and wants looking at, and could probably be prevented.

That is for a later fix and for further investigation.

[autoSteve]

This should help, foks.

@bazcurtis, multiple account caching should be fixed.

https://github.com/BJReplay/ha-solcast-solar/releases/tag/v4.0.30

[autoSteve]

Confirming installing v4.0.30 via HACS has worked. Restart HA and the check for updates will occur.

[maritzhome1]

Thanks for the swift work on the update and fix.

[pajikcz]

Hi there, confirm, v 4.0.30 is working!!! Take a while than data appeared. Thank you.

[autoSteve]

Enjoy the massive improvement that caching and forecast retry brings.

[bazcurtis]

For anyone with this issue with version v.4.0.29 who wants assistance, please add the following to your configuration.yaml and restart HA, and provide us with your log records for solcast.

That will enable us to determine whether there is a bug in the integration or the solcast service is timing out or returning 429.

 logger:
   default: warn
   logs:
     custom_components.solcast_solar: debug

I also ready have this code in my config file for another integration. How do I add the above. The defaults are different. I appreciate it is commented out at the moment. I am always happy to help debug.

# logger:
 # default: info
 # logs:
 #   homeassistant.components.rest_command: debug

[autoSteve]

The defaults are different

Use whatever default that you would like, @bazcurtis. Your choice. If info is your thing, then keep info.

The critical lines to add are

   logs:
     custom_components.solcast_solar: debug

So to be crystal clear, for both:

logger:
  default: info
  logs:
    custom_components.solcast_solar: debug
    homeassistant.components.rest_command: debug

To be even more crystal clear, if you don't want rest_command debug then:

logger:
  default: info
  logs:
    custom_components.solcast_solar: debug
    # homeassistant.components.rest_command: debug

[autoSteve]

Reviewing logs is quite simple, but debug logs cannot be reviewed from the UI. The file /homeassistant/home-assistant.log must be viewed. I find the handiest way is to use the less command from the HAOS command line.

less /homeassistant/home-assistant.log then... F key to follow live (capital F) /SOLCAST to search for and highlight lines containing "SOLCAST" Ctrl-C to exit follow mode PgUp/PgDn/Up/Down to hunt around.

[bazcurtis]

I have install 4.0.30 and all looks good to me. These were my steps

• Upgrade to 4.0.30
• Restart Home Assistant
• No data
• Reload 4.0.30
• Data for both accounts

Thanks for all the help. Really appreciate you taking over this integration

[autoSteve]

@bazcurtis, I'm particularly interested in a test of multiple Solcast accounts, and brilliant to hear it is working. You should end up with two cache files, each named solcast-sites-[acctid].json.

If you could confirm that they exist now in /homeassistant that would be grouse.

[bazcurtis]

@bazcurtis, I'm particularly interested in a test of multiple Solcast accounts, and brilliant to hear it is working. You should end up with two cache files, each named solcast-sites-[acctid].json.

If you could confirm that they exist now in /homeassistant that would be grouse.

I do have two caches with the name of the API keys

[autoSteve]

I do have two caches with the name of the API keys

Then may your life be hopefully rid of 429/we're busy errors, @bazcurtis!

[gcoan]

The critical lines to add are

logs: custom_components.solcast_solar: debug

I think it'd be worth adding this to the readme, or to the issues form template in GitHub?

[autoSteve]

worth adding this to the readme

@BJReplay is way ahead of you. It's now in the issue report template.

Plus I have added a Troubleshooting FAQ discussion that also features a logs mention.

We're blind and guessing without debug logs...

README.md update ain't a bad idea, but that assumes that folks that have been running this integration for some time actually read it... implausible.

[macfr76]

Same issue, I upgraded from 4.0.27 to 4.0.29 and not fetching data anymore.

I reverted to 4.0.28 that was reported working but was still not good. I did reconfigure with the same API key by copy / paste from Solcast website and then it started working again.

i did upgrade successfully from 4.0.28 to 4.0.31, it went fine. Thanks a lot for the job you do :)

[ffm777]

I also had the problems described above because of 2 solcast accounts (I have 4 planes of panels with different orientations). I currently have 4.0.30 installed and it works. My problem however is that the integration keeps eating up API calls. I guess because of automatic retries. The old integration didn't do automatic retries when the API call failed which I very much prefer. If for whatever reason an API call fails then I don't mind and would rather go for the next planned data retrieval 2 hours later than the integration repeating the API call on its own and then suddenly all of my 10 daily API calls are gone.

[autoSteve]

Debug logs, please, @ffm777. I got nothin'. If the API call fails, then from what I've seen, no foul: no eat call quota, so I doubt that's it. Please don't just blame retries out of hand, but that may very well be behind this. It may be that there are complexities for multiple-account situations, of which I do not fall into for testing because that is a no-no from a Solcast T&C POV.

But without debug logs, yeah. I got nothin'. Not. A. Thing. Nothing.

I would prefer this to be created as a separate issue, because it seems vaguely related, but quite different. And of interest.

[ffm777]

Ok. Understood. Let me observe the next couple of days and if the issue persists, then I open up a new issue with debug logs.

[autoSteve]

Sweet as.

open up a new issue with debug logs

I'd advise you to set up debug logging today for the Solcast integration so that you can capture any oddities in the near future. Cheers!

Post 2 of https://github.com/BJReplay/ha-solcast-solar/discussions/38

[florie1706]

Don't know if this is a similar error, but I just updated from oziee's last version to the latest from @BJReplay

But I just have zeros on all entities

debug log says:

2024-06-17 17:02:41.131 DEBUG (MainThread) [custom_components.solcast_solar] Solcast Migrating from version 7
2024-06-17 17:02:41.131 DEBUG (MainThread) [custom_components.solcast_solar] Solcast Migration to version 7 successful
2024-06-17 17:02:41.133 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST apiCacheEnabled=False, solcast-sites.json=False
2024-06-17 17:02:41.133 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - connecting to - https://api.solcast.com.au/rooftop_sites?format=json&api_key=REDACTED
2024-06-17 17:02:41.485 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - sites_data code http_session returned data type is <class 'dict'>
2024-06-17 17:02:41.485 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - sites_data code http_session returned status 200
2024-06-17 17:02:41.486 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - writing sites data cache
2024-06-17 17:02:41.490 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - sites_data Exception error: Traceback (most recent call last):
  File "/config/custom_components/solcast_solar/solcastapi.py", line 148, in sites_data
    async with aiofiles.open(apiCacheFileName, 'w') as f:
  File "/usr/local/lib/python3.12/site-packages/aiofiles/base.py", line 98, in __aenter__
    self._obj = await self._coro
                ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiofiles/threadpool/__init__.py", line 94, in _open
    f = yield from loop.run_in_executor(executor, cb)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/homeassistant/util/loop.py", line 131, in protected_loop_func
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
PermissionError: [Errno 13] Permission denied: 'solcast-sites.json'

2024-06-17 17:02:41.491 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - getting API limit and usage from solcast
2024-06-17 17:02:42.066 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - writing usage cache
2024-06-17 17:02:42.068 ERROR (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - sites_usage error: Traceback (most recent call last):
  File "/config/custom_components/solcast_solar/solcastapi.py", line 215, in sites_usage
    async with aiofiles.open(apiCacheFileName, 'w') as f:
  File "/usr/local/lib/python3.12/site-packages/aiofiles/base.py", line 98, in __aenter__
    self._obj = await self._coro
                ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiofiles/threadpool/__init__.py", line 94, in _open
    f = yield from loop.run_in_executor(executor, cb)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/homeassistant/util/loop.py", line 131, in protected_loop_func
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
PermissionError: [Errno 13] Permission denied: 'solcast-usage.json'

2024-06-17 17:02:42.068 DEBUG (MainThread) [custom_components.solcast_solar.solcastapi] SOLCAST - load_saved_data site count is zero! 
2024-06-17 17:02:42.068 INFO (MainThread) [custom_components.solcast_solar] Solcast Integration version number: v4.0.31
2024-06-17 17:02:42.069 DEBUG (MainThread) [custom_components.solcast_solar.coordinator] Finished fetching solcast_solar data in 0.000 seconds (success: True)
2024-06-17 17:02:42.111 INFO (MainThread) [custom_components.solcast_solar] SOLCAST - Solcast API data UTC times are converted to Europe/Berlin

That said I use the latest docker image of linuxserver.io for Home Assistant.

[autoSteve]

Don't know if this is a similar error

Ja, ja, @florie1706. This is most foreign to me. Permission dened? WT?

Anyone seen this?

This bothers me: SOLCAST - load_saved_data site count is zero! And: PermissionError: [Errno 13] Permission denied: 'solcast-sites.json'

Bless you, if that's what you're into for providing a debug log. This is the way.

[autoSteve]

Right @florie1706.

This is categoricaly weird.

This says that you cannot write the cache files on startup... What environment are you running???

This may need a separate issue created.

[florie1706]

I run Home assistant in a docker container with an image of linuxserver.io -> https://github.com/linuxserver/docker-homeassistant but that seemed never to be a problem. I tried to generate the json files with 777 permission in the main folder, but that did not seem to work either.

[autoSteve]

Totally not my thing. HAOS here for the win.

This I will need to think about a lot, but it seems a basic permissions issue in not being able to write the caches.

#dockerhelp!...

[autoSteve]

You may need to revert to oziee's latest @florie1706 until I naval gaze this, or anyone else has a suggestion...

[gcoan]

You may need to revert to oziee's latest @florie1706 until I naval gaze this, or anyone else has a suggestion...

I'm wondering whether it is a pathname/home directory problem @autoSteve

When we run with HAOS it runs with a current directory of /config and I think (didn't check) that the file name is just written as solcast-sites.json - i.e. not a fully qualified path.

If @florie1706 runs as a docker linux container maybe it's running with a current directory of say / which it doesn't have permissions to?

So either change the docker initialisation to set the current directory to be consistent with HAOS or use a fully qualified pathname for the cache files? Of course fully qualified paths may cause other problems, I don't know what the Home Assistant 'standard' is.

The current directory could equally be /homeassistant which is symbolically linked at least on HAOS to /config. Got a recollection that the pathnames/folder structure changed in the last 6 months or so??

[florie1706]

In my /config within the container, there is already a new solcast.json (which comes from your current version 4.0.31) and an old sites.json from may which I recon came from oziee's integration. Both have a 644 permission and the local host user is owner, so there should not be a big permission problem as these files in the /config are not root owned or so. Anyway can I just create theses files manually? Where should they go?

[gcoan]

In my /config within the container, there is already a new solcast.json (which comes from your current version 4.0.31) and an old sites.json from may which I recon came from oziee's integration. Both have a 644 permission and the local host user is owner, so there should not be a big permission problem as these files in the /config are not root owned or so. Anyway can I just create theses files manually? Where should they go?

The sites.json file has been renamed to solcast-sites.json so you should be able to rename it OK and get past the sites file error, but the integration then creates solcast-usage.json so if there is a permissions issue it'll fail at that step.

If you can manually create it, it contains:

{"daily_limit": 10, "daily_limit_consumed": 8}

Obviously change as per your limit and consumed today.

What's the permissions to the /config folder?

[florie1706]

drwxr-xr-x 16 abc users 4.0K Jun 17 22:27 config

abc users point to the standard host user. all other files, custom integrations etc. have these permissions too without a problem.

Sadly, manually renaming states.json and manually generating solcast-usage.json within /config does not solve the permission issue.

-> Reverted back to oziee's last release, working again.

[BJReplay]

I run Home assistant in a docker container with an image of linuxserver.io -> https://github.com/linuxserver/docker-homeassistant but that seemed never to be a problem.

I won't knock linuxserver images, because I use one constantly - I use their rdesktop image because it just works to server up a remote desktop server (that, coincidently I use to server a customised home assistant dashboard to a original surface RT tablet that can't render the dashboard on it's OG edge browser or ie browser, but can run and RDP client to the linux rdesktop server running a proper browser).

That said, the yaml for the docker compose for the linuxserver and the native docker image for homeassistant is almost identical other than the image name, and I'm not sure that you get much if anything out of the linuxserver image that you don't get in the base image.

Can you please provide your docker compose yml (with any sensitive data redacted).

Could the problem be the mapping of the config volume in the compose back to the host? I know it seems unlikely, but I can't think of much else.

[florie1706]

version: '3'
services:
  homeassistant:
    container_name: homeassistant_app
    image: linuxserver/homeassistant
    volumes:
      - homeassistant:/config
      - /etc/localtime:/etc/localtime:ro
    environment:
      TZ: ${TZ}
      PUID: ${PUID}
      PGID: ${PGID}
    restart: unless-stopped
    network_mode: host
    healthcheck:
      test: ["CMD", "curl", "-f", "http://localhost:8123"]
      interval: 2m
      timeout: 10s
      retries: 3
      start_period: 40s
    depends_on:
      mariadb:
        condition: service_healthy
        restart: true
      influxdb:
        condition: service_healthy
        restart: true

volumes:
  homeassistant:

That is the part regarding HA itself. I would say "nothing special" and also the old integration was able to write its json file and other (official) integrations have their conf files in the /config directory.

I wont blame linuxserver for that, I love their image and it just works with everything. I think it is something else ?!? Because even when I create the files manually with 777 permission it does not work :(

I don't use HACS, I install custom integrations manually to the custom_components folder. This folder and every subfolder and file have also abc:user as owner with normal permission

[BJReplay]

I don't use HACS, I install custom integrations manually to the custom_components folder. This folder and every subfolder and file have also abc:user as owner with normal permission

OK, that's helpful.

So, it appears that you have homeassistant as a volume defined externally to the homeassistant service definition (you've got the volume listed at the bottom of your snippet, but only the name, not the full definition).

I'm assuming that custom_components is a folder in the volume mounted as config?

Can you include the rest of your external volume definition, please?

[florie1706]

In the volumes section there are just other volume names like "esphome" etc. but no extra information. That is what I have on every docker compose yaml for other services etc.

"homeassistant" is the volume mounted to /config. custom_components is a subfolder of /config

[autoSteve]

I wonder if the files are trying to be written to /homeassistant for some reason, and not /config. Is /config a symlink to /homeassistant like HAOS arranges it? I've not devled into the depths, so this is just a stab. What happens if you create a /homeassistant folder should you not have one?

[autoSteve]

file name is just written as solcast-sites.json

Good thought, @gcoan. @florie1706, what happens if you change "solcast-sites.json" to "/config/solcast-sites.json"? (edit: in custom_components/solcast_solar/solcastapi.py)

Another thought, is solcast-usage.json getting created in /config?