[Bug]: Inverter Daily Yield Erroneous values between two inverter polls (30s)

E-Raw commented 1 month ago

Describe the issue

I noticed strange value in the Energy dashboard at first for a few weeks now. It looks like Daily Yield goes crazy sometimes without any apparent reason: 20240514 Energy Dashboard

When I look in the statistics (5 minutes sum), I can see peak values I can manually correct but is is tedious and some days, there is many occurrences of this issue: 20240514 Statistics

When I look at the sensor value, I can see drops on the counter which normally always increase. Those drop sample always occurs between two legit samples (every 30s in my case), see CSV: history.csv

I do not know that value come from and how it produce so much difference in the 5 minute sum statistic sample.

Could you help me understand from where those values come from?

Many Thanks!

Describe your Huawei Solar Setup

Inverter Type: SUN2000-6KTL-M1 Inverter Firmware version: sDongle present: Yes sDongle Type: sDongleA-05 (WiFi / Ethernet) / SDongleA-03 (4G) sDongle Connectivitiy: WiFi sDongle Firmware: Power meter present: three phase Optimizers Present: Yes / No Battery: None Battery Firmware version: Huawei Solar integration version:

How do you connect to the inverter?

Via the SUN2000-<serial_no> WiFi

Upload your Diagnostics File

config_entry-huawei_solar-6d1aad22fec99af2e48cb80687998227(1).json

Upload your relevant debug logs

I do not have debug logs from that period of time as it occurs randomly

Please confirm the following:

[X] I'm running the latest release of Home Assistant.
[X] I'm running the latest release of this integration.
[X] I did not find an existing issue describing this problem.
[X] I did upload the diagnostics-file that I could retrieve from the 'Devices & Services Page'
[X] I did upload the relevant debug logs (via 'Enable Debug Logging'-feature or by manually configuring HA logging)

wlcrs commented 1 month ago

Without debug logs showing the actual bytes being read from the inverter, I will not be able to debug this issue.

E-Raw commented 1 month ago

Hi @wlcrs ! I activated the debug on the integration but so far, no occurrence of the issue. I wonder what is polling/receiving this intermediary sample as it is an additional one between two regular 30s interval samples. note: I removed unnecessary entities I activated in the past which are no longer usefull. Might lighten the polls and "solve" the issue?!

In the meantime, to avoid screwing up my stats, I integrated a custom "Riemann" calculation sensor as indicated in the wiki. The accuracy is really good! On top, integration Daily Yield (with the problem of "corrupted samples" on 22nd of May), on the bottom, Riemann sensor in an utility to get daily yield reset to zero every night.

I'll keep you posted as soon as I have any update! Thank you for the excellent job on this integration! ;-)

E-Raw commented 1 month ago

Hi @wlcrs ! I think i found what's happening to produce those erroneous samples. In fact, the value and reads from the inverter are correct, but the timestamp is wrong... well, let me explain my findings 😃

I got two occurrences of "bad samples" today around 12:53:

In the logs, around that time, I do not see anything next 12:52:58 nor 12:53:28, the exact timestamp of the bad samples, only the regular samples on the other hand, it is exactly 30sec between those two bad samples (I let the default interval set to 30s): from home-assistant.log.1

2024-05-30 12:52:58.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:52:58.637 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 12:53:28.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:53:28.633 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0

I made a search in the entire log for 2024-05-30 12:5 and found a very strange situation, where the "clock" jumps one hour ahead arround 11:52 and go back to normal a bit less than two minutes later:

2024-05-30 11:52:29.840 WARNING (Thread-4) [pychromecast.socket_client] [Salon(192.168.103.217):8009] Heartbeat timeout, resetting connection
2024-05-30 11:52:32.986 WARNING (MainThread) [homeassistant.components.androidtv_remote] Disconnected from Salon at 192.168.103.217
2024-05-30 11:52:49.699 ERROR (MainThread) [homeassistant.components.octoprint.coordinator] Error requesting octoprint-e6558f65cc31adc64ec11fc3e045eae3 data: Cannot connect to host 192.168.103.29:5000 ssl:default [Connect call failed ('192.168.103.29', 5000)]
2024-05-30 11:52:55.466 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 11:52:55.547 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 11:52:59.873 ERROR (Thread-4) [pychromecast.socket_client] [Salon(192.168.103.217):8009] Failed to connect to service HostServiceInfo(host='192.168.103.217', port=8009), retrying in 5.0s
2024-05-30 12:52:38.325 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/backports/aiohttp_resolver.py", line 67, in resolve
[...]
  File "/usr/local/lib/python3.12/site-packages/pyunifiprotect/api.py", line 358, in api_request_raw
    response = await self.request(
               ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pyunifiprotect/api.py", line 340, in request
    raise NvrError(
pyunifiprotect.exceptions.NvrError: Error requesting data from 192.168.103.249: Cannot connect to host 192.168.103.249:443 ssl:False [Connect call failed ('192.168.103.249', 443)]
**2024-05-30 12:52:58.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:52:58.637 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 12:53:28.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:53:28.633 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0**
2024-05-30 11:54:13.260 WARNING (MainThread) [homeassistant.components.http.ban] Login attempt or request with invalid authentication from supervisor (172.30.32.2). Requested URL: '/api/core/state'. (HomeAssistantSupervisor/2024.05.1 aiohttp/3.9.5 Python/3.12)
2024-05-30 11:54:25.466 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 11:54:25.567 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0

So to recap, two samples were made at 11:52:58 and 11:53:28 "realtime" but with timestamp in HA DB of 12:52:58 and 12:53:28!!! I realized then they were the right values at the wrong time in the graph! So it screw up all the data as this total_increasing should never have decreasing values but in that case, I guess it is more related to a global clock issue in HA: the other services/containers running at that time suffers of the same symptoms. with entries in the logs one hour ahead for about a minute. Might be linked to daylight saving time or timezone mixed with a network issue...?!

May I ask you some advice on what to do with that?

wlcrs commented 1 month ago

Closing this issue as it is caused by the clock of the HA machine jumping around.

I do not have any advice on how to fix that.

alexdelli commented 3 weeks ago

Hi @wlcrs ! I think i found what's happening to produce those erroneous samples. In fact, the value and reads from the inverter are correct, but the timestamp is wrong... well, let me explain my findings 😃

I got two occurrences of "bad samples" today around 12:53:

In the logs, around that time, I do not see anything next 12:52:58 nor 12:53:28, the exact timestamp of the bad samples, only the regular samples on the other hand, it is exactly 30sec between those two bad samples (I let the default interval set to 30s): from home-assistant.log.1
2024-05-30 12:52:58.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:52:58.637 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 12:53:28.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:53:28.633 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
I made a search in the entire log for 2024-05-30 12:5 and found a very strange situation, where the "clock" jumps one hour ahead arround 11:52 and go back to normal a bit less than two minutes later:
2024-05-30 11:52:29.840 WARNING (Thread-4) [pychromecast.socket_client] [Salon(192.168.103.217):8009] Heartbeat timeout, resetting connection
2024-05-30 11:52:32.986 WARNING (MainThread) [homeassistant.components.androidtv_remote] Disconnected from Salon at 192.168.103.217
2024-05-30 11:52:49.699 ERROR (MainThread) [homeassistant.components.octoprint.coordinator] Error requesting octoprint-e6558f65cc31adc64ec11fc3e045eae3 data: Cannot connect to host 192.168.103.29:5000 ssl:default [Connect call failed ('192.168.103.29', 5000)]
2024-05-30 11:52:55.466 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 11:52:55.547 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 11:52:59.873 ERROR (Thread-4) [pychromecast.socket_client] [Salon(192.168.103.217):8009] Failed to connect to service HostServiceInfo(host='192.168.103.217', port=8009), retrying in 5.0s
2024-05-30 12:52:38.325 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/backports/aiohttp_resolver.py", line 67, in resolve
[...]
  File "/usr/local/lib/python3.12/site-packages/pyunifiprotect/api.py", line 358, in api_request_raw
    response = await self.request(
               ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pyunifiprotect/api.py", line 340, in request
    raise NvrError(
pyunifiprotect.exceptions.NvrError: Error requesting data from 192.168.103.249: Cannot connect to host 192.168.103.249:443 ssl:False [Connect call failed ('192.168.103.249', 443)]
**2024-05-30 12:52:58.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:52:58.637 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
2024-05-30 12:53:28.551 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 12:53:28.633 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0**
2024-05-30 11:54:13.260 WARNING (MainThread) [homeassistant.components.http.ban] Login attempt or request with invalid authentication from supervisor (172.30.32.2). Requested URL: '/api/core/state'. (HomeAssistantSupervisor/2024.05.1 aiohttp/3.9.5 Python/3.12)
2024-05-30 11:54:25.466 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064 with length 52 from slave 0
2024-05-30 11:54:25.567 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32000 with length 20 from slave 0
So to recap, two samples were made at 11:52:58 and 11:53:28 "realtime" but with timestamp in HA DB of 12:52:58 and 12:53:28!!! I realized then they were the right values at the wrong time in the graph! So it screw up all the data as this total_increasing should never have decreasing values but in that case, I guess it is more related to a global clock issue in HA: the other services/containers running at that time suffers of the same symptoms. with entries in the logs one hour ahead for about a minute. Might be linked to daylight saving time or timezone mixed with a network issue...?!

May I ask you some advice on what to do with that?

I had the same issue, but I don't know why and how to solve.

alexdelli commented 3 weeks ago

Solved by reinstalling the integration

wlcrs / huawei_solar