search

cdpuk / givenergy-local

Home Assistant integration for local access to GivEnergy inverter and battery systems
MIT License
47 stars 14 forks source link

Entity statuses are intermittently unavailable #79

Closed DevOpsFu closed 2 months ago

DevOpsFu commented 5 months ago

Hardware and versions

Describe the bug

I've noticed that the entity statuses will become unavailable for 10-20 seconds every 2-3 minutes. This does not appear to be related to dropouts in the inverter connectivity - running a continuous ping to the inverter does not show any loss of connectivity or increased latency during the periods when the entity statuses become unavailable.

image

Debug log

2024-02-11 14:20:03.862 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=0)
2024-02-11 14:20:04.102 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.framer] Found next frame: 0x59590001009e0102..., buffer_len=164
2024-02-11 14:20:04.102 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Processing 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=0)
2024-02-11 14:20:04.103 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.model.plant] Handling 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=0)
2024-02-11 14:20:04.112 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=180)
2024-02-11 14:20:04.341 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.framer] Found next frame: 0x59590001009e0102..., buffer_len=164
2024-02-11 14:20:04.342 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Processing 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=180)
2024-02-11 14:20:04.342 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.model.plant] Handling 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=180)
2024-02-11 14:20:04.363 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=60)
2024-02-11 14:20:04.609 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.framer] Found next frame: 0x59590001009e0102..., buffer_len=164
2024-02-11 14:20:04.610 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Processing 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=60)
2024-02-11 14:20:04.611 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.model.plant] Handling 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=60)
2024-02-11 14:20:04.631 DEBUG (MainThread) [custom_components.givenergy_local.coordinator] Finished fetching Inverter data in 0.773 seconds (success: True)
2024-02-11 14:20:04.639 DEBUG (MainThread) [custom_components.givenergy_local] Scheduled next update for charge_slot_1 at 2024-02-12 00:32:00
2024-02-11 14:20:04.661 DEBUG (MainThread) [custom_components.givenergy_local] Scheduled next update for charge_slot_2 at 2024-02-12 00:01:00
2024-02-11 14:20:06.656 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.framer] Found next frame: 0x5959000100450102..., buffer_len=75
2024-02-11 14:20:13.858 INFO (MainThread) [custom_components.givenergy_local.coordinator] Fetching data from 172.20.50.100 (attempt=1/3, full_refresh=False)
2024-02-11 14:20:13.862 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=0)
2024-02-11 14:20:14.114 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=180)
2024-02-11 14:20:14.364 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 1): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=60)
2024-02-11 14:20:14.864 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=0), attempting retry 1 of 2
2024-02-11 14:20:14.866 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 2): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=0)
2024-02-11 14:20:15.115 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=180), attempting retry 1 of 2
2024-02-11 14:20:15.119 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 2): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=180)
2024-02-11 14:20:15.366 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=60), attempting retry 1 of 2
2024-02-11 14:20:15.369 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 2): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=60)
2024-02-11 14:20:15.868 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=0), attempting retry 2 of 2
2024-02-11 14:20:15.870 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 3): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=0)
2024-02-11 14:20:16.121 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=180), attempting retry 2 of 2
2024-02-11 14:20:16.125 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 3): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=180)
2024-02-11 14:20:16.371 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=60), attempting retry 2 of 2
2024-02-11 14:20:16.374 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Request sent (attempt 3): 2:4/ReadInputRegistersRequest(slave_address=0x32 base_register=60)
2024-02-11 14:20:16.872 WARNING (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Timeout awaiting 2:4/ReadInputRegistersResponse(slave_address=0x32 base_register=0) after 3 tries at 1s, giving up
2024-02-11 14:20:16.873 ERROR (MainThread) [custom_components.givenergy_local.coordinator] Closing connection due to expected error: 
2024-02-11 14:20:16.874 DEBUG (MainThread) [custom_components.givenergy_local.givenergy_modbus.client.client] Disconnecting and cleaning up
2024-02-11 14:20:16.876 ERROR (MainThread) [custom_components.givenergy_local.coordinator] Error fetching Inverter data: Connection closed due to expected error
2024-02-11 14:20:16.877 DEBUG (MainThread) [custom_components.givenergy_local.coordinator] Finished fetching Inverter data in 3.019 seconds (success: False)

I have tried tweaking the interval up to 30 seconds as mentioned in issue https://github.com/cdpuk/givenergy-local/issues/76 but this has had no effect.

DevOpsFu commented 5 months ago

I'm not sure this is an issue related to the integration itself. It looks like it's either a local problem on my network or an issue with the givenergy_modbus library. I'm doing some basic tests, pulling the battery percentage every few seconds and the results are very flaky.

100
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
Returned base register (0) does not match that from request (60).
Returned base register (60) does not match that from request (120).
100
Did not receive expected response type: ReadInputRegistersResponse != ReadHoldingRegistersResponse
Did not receive expected response type: ReadInputRegistersResponse != ReadHoldingRegistersResponse
Returned base register (120) does not match that from request (0).
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
100
Did not receive expected response type: ReadInputRegistersResponse != ReadHoldingRegistersResponse
Returned base register (120) does not match that from request (180).
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
100
Did not receive expected response type: ReadInputRegistersResponse != ReadHoldingRegistersResponse
Returned base register (120) does not match that from request (0).
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
Did not receive expected response type: ReadHoldingRegistersResponse != ReadInputRegistersResponse
cdpuk commented 5 months ago

From v2.x onwards the integration uses a newer (but unreleased) version of the givenergy_modbus code. If you're running a standalone debug script against the library, you're using the old code. There were a few teething issues with early 2.x versions, but these seem largely resolved for everyone else now.

The debug logs certainly suggest the inverter isn't responding within a timely manner. I can see each request is hitting the 1 second timeout before being attempted a couple more times.

Nothing else trying to read data in parallel? Sometimes I've seen that cause problems.

Does it work any better against v1.9.1?

You could also try a tweak to this line to add a timeout=2.0 (or similar) to extend the timeout of individual requests. Though in my experience, either you get a response in <200 milliseconds, or not at all. This timeout value can't be too large - if the total time to perform a refresh exceeds 10 seconds, you'll hit another timeout.

DevOpsFu commented 5 months ago

Thanks for responding @cdpuk . I have downgraded to 1.9.1 as you suggested, and it's perfect - no unavailable periods on any entities. Looking at the givenergy_modbus repository, it seems that the responses I was seeing when using the library directly are unfortunately expected and need to be worked around.

pskillen commented 2 months ago

FWIW, my inverter updated to newer firmware last week and that immediately fixed this issue issue. According to the changelog this isn't even the most recent firmware (no idea what's going on there), but at least it's fixed.

I suspect this issue was something to do with the inverter, since I get regular timeouts even when going via https://givenegy.cloud

image
cdpuk commented 2 months ago

Great to hear. I get the feeling there must be some underlying design problems that GE seem to be fighting with, and this seems to manifest itself in connection reliability issues every now and then.