Excessive logging when the solar inverter goes offline at night

[gedger]

Description

Originally the Solarman integration would log a single message that the inverter couldn't be contacted but in the current version 24.12.22 there is excessive logging continuously until the inverter comes back on line.

Reproduction Steps

Arrange for the inverter to go off-line.

Log

home-assistant_solarman_2025-01-07T16-55-30.186Z.log

Version

24.12.22

Home Assistant Core Version

2024.12.5

Home Assistant Operating System Version

N/A

[davidrapan]

fix: Excessive logging during discovery flow should do.

[gedger]

Will test today and report back tomorrow.

[gedger]

Much, much improved 👏 but still generates 17 log messages, will try and get a debug log tomorrow.

[gedger]

Spoke to soon, keeps logging, now up to 84 tries.

home-assistant_solarman_2025-01-08T17-53-37.393Z.log

edit: debug log added

[davidrapan]

So this other part is because of the row

ha-solarman/custom_components/solarman/api.py

Line 127 in 036a5df

if scount == 0:

which often results in your case in success because you are not making request w/ every iteration.

Could you test my theory by temporarily changing your custom file so that one sensor is requested w/ each iteration: update_interval: 5?

[gedger]

To clarify, I currently have a single default_update interval of 30 seconds for all sensors. So you want me to try adding an update_interval: 5 to one sensor?

solis_1p8k-5g.yaml.zip

[davidrapan]

So you want me to try adding an update_interval: 5 to one sensor?

Yes.

[gedger]

That has reduced the logging to a single log message which is good but with the debug log enabled you can see that the integration is continually trying to connect to the inverter and flooding the network with discovery messages every few seconds which is not great as the inverter won't come on line for 14 hours.

home-assistant_solarman_2025-01-09T17-03-17.868Z.log

[davidrapan]

with the debug log enabled you can see that the integration is continually trying to connect to the inverter

This is the same behavior as before. 😉 Few packets per 5 seconds is really very, very, very far from flooding. 😆

Edit: Now you can try to insert between rows 127 and 128 of api.py following:

            if not self.modbus.reader_task or self.modbus.reader_task.done():
                raise Exception(f"[{self.config.serial}] No scheduled requests found, aborting.")

It should cause returning an Exception instead of a success w/ no connection and no scheduled requests.

But it feels kinda hacky though...

[gedger]

Thanks I'll try that and also the removal of discovery discussed in #344. Will the need to have a 5 sec update_interval on one sensor be removed in the future?

😄 #72 😄

[davidrapan]

Will the need to have a 5 sec update_interval on one sensor be removed in the future?

Ehm, the code in previous post is exactly for that..

[gedger]

Sorry, I haven't had my morning pot of coffee yet....

[SgtHugoStiglitz]

Hi all,

I recently noticed that my HomeAssistant sometimes behaves sluggish. I thought this was related to some HA update itself and so I waited.
Also I did not always notice the sluggish behavior.

Yesterday night I was working with some stuff in my HA and noticed again that my system behaves very sluggish so I wanted to find the reason.

I disabled a lot of integrations and add-ons but nothing helped.

Then today during the day I wanted to check again - there was no sluggish behavior of Homeassistant - Which got me thinking...

So this evening - once I noticed that HA is once more "slow", I disabled the Solarman integration.

And voila - The system is now running "smooth".

So I enabled the Debug-Logging for Solarman and observed the system.

What I noticed, whenever Solarman is searching for the Inverter - HA is "Waiting" for Solarman to finish the cycle - which makes the whole HA-Webinterface unresponsive during this time!

I can pinpoint the behavior to this message in the logs:

2025-01-10 18:26:14.170 INFO (MainThread) [custom_components.solarman.api] [3839565393] Connecting to 192.168.x.x:8899

Whenever this Thread "active" the whole system does not react anymore. I think HA is "Waiting" for this Thread to finish?

As this Thread has a timeout of approximately 3 seconds, the whole HA system is unresponsive for 3 seconds every 5 seconds 5 times in a row. Then there seems to be some "Wait-time" before the integration tries the same cycle again.

You are right, that 5 calls over the period of 20 seconds is not a lot, but when HA completely hangs during this time, it is not so good.

I could try to create a video for you, but maybe you can reproduce the Behavior yourself?

Steps to reproduce:

• Add an Inverter to the Integration which currently is offline
• Enable debug logging
• Have your HA open and Logged-in In a browser
• Open the Logs in a Separate Window (so you can observe the logs whilst using the HA Web interface)
• Wait for the "INFO (MainThread) [custom_components.solarman.api] [3839565393] Connecting to 192.168.x.x:8899" Message to appear in the logs
• Now try to switch to a different Tab or settings Screen in HA. You will notice a "Loading" icon until the Log-message switches to "DEBUG (MainThread) [custom_components.solarman.api] [3839565393] Querying 03 ~ 0000 - 0022 | 0x0000 - 0x0016 #023 failed, attempts left: 4 [NoSocketAvailableError: Cannot open connection to 192.168.x.x]"

During these 3-4 seconds the whole HA-web interface (Maybe even the whole system) becomes unresponsive.

I think reducing the amount of retries or increasing the time between retries is just a "Hotfix" but not a solution. The integration should not block the HA-Webinterface from working.

If you have questions or need a Video, please let me know.

And before I go: THANK YOU VERY MUCH FOR YOUR INTEGRATION! I am very thankful that you invest your time to create and maintain such an awesome Integration!

Kind regards
Michael

[davidrapan]

I could try to create a video for you, but maybe you can reproduce the Behavior yourself?

No I'm really not able to reproduce this behavior.