wlcrs / huawei_solar

Home Assistant integration for Huawei Solar inverters via Modbus
GNU Affero General Public License v3.0
550 stars 88 forks source link

[Bug]: Periodic Dropping of a slave inverter #248

Closed JohnMcLear closed 1 year ago

JohnMcLear commented 1 year ago

Describe the issue

Periodically my slave 3 drops off. I have 1 master (0[dongle], 6[master],2[slave],3[slave]). I'm running b7 of this integration

Could it be a wiring issue?

Bescribe your Huawei Solar Setup

Inverter Type: 6KL1-1 Inverter Firmware version: 125 SDongle present: yes Power meter present: single phase Battery: LUNA2000 10kWh x 3 (2 on each inverter) Battery Firmware version: 130 afaik

How do you connect to the inverter?

Via the SDongle, wireless connection

Upload your Diagnostics File

config_entry-huawei_solar-e7dae940ac3400b9f936d9adb24424b7.json.txt

Upload your relevant debug logs

Logger: custom_components.huawei_solar
Source: helpers/update_coordinator.py:168
Integration: Huawei Solar
First occurred: 6 January 2023 at 08:11:11 (289 occurrences)
Last logged: 11:55:24

    Error fetching TA2270270016_data_update_coordinator data: Could not update TA2270270016 values: Modbus client is not connected to the inverter.
    Error fetching TA2270269658_data_update_coordinator data: Could not update TA2270269658 values: Got error while reading from register 32064 with length 52: Exception Response(131, 3, IllegalAddress)
    Timeout fetching TA2270269658_data_update_coordinator data
    Timeout fetching TA2270270016_data_update_coordinator data
    Timeout fetching 102180067169_data_update_coordinator data


### Please confirm the following:

- [X] The problem is still present in 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 increased the logging configuration, restarted HA, and have copied all relevant log lines from the 'Full Logs' into the textarea.
wlcrs commented 1 year ago

From the limited information that you are giving me, it looks like a hardware problem. Otherwise it would also fail for the other slaves

JohnMcLear commented 1 year ago

Sorry it took a while, I wanted to get more info, the issue exists on master, slave 2 & 3.

Logger: custom_components.huawei_solar
Source: helpers/update_coordinator.py:168
Integration: Huawei Solar
First occurred: 9 January 2023 at 09:25:26 (283 occurrences)
Last logged: 16:14:10

Timeout fetching TA2270270016_data_update_coordinator data
Timeout fetching TA2270269658_data_update_coordinator data
Timeout fetching 102180067169_data_update_coordinator data
Error fetching TA2270270016_data_update_coordinator data: Could not update TA2270270016 values: Could not read register value, has another device interrupted the connection?
Error fetching TA2270269658_data_update_coordinator data: Could not update TA2270269658 values: Got error while reading from register 37760 with length 28: Exception Response(131, 3, IllegalAddress)

Note that both slaves are somewhat failing. I think slave 3 was failing more but that was observational and when I took time to look at it all 3 are unavailable

image

Very strange.. Note how the Unavailable events are sometimes staggered too....

My wifi shouldn't be dropping, the other devices running off that wireless point aren't dropping any packets etc. and all have active monitoring.. Possibly the dongle doing something weird with comms to fusion?

bigmoby commented 1 year ago

Hi @JohnMcLear the same issue in my father's HA installation but in the same my own installation it's ok. My and my father's Huawei solar plant are literally the same and the same version of this integration, and the same dongle firmware. What's the different thing between and my father? Probably the fact that I never access to the Solar Fusion app but my father very often! Could it be the cause?! I don't know! When the integration is off I have to reboot the dongle (I've created a rest API calling from HA) and then I have to restart the integration itself.

JohnMcLear commented 1 year ago

When the integration is off I have to reboot the dongle (I've created a rest API calling from HA) and then I have to restart the integration itself.

Can you clarify what you mean here please by "the integration is off", do you mean showing as "unavailable" in Home Assistant?

Also what steps do you take to "reboot the dongle"?

I'm going to uninstall the "FusionSolar" app and I'll see if things improve, I doubt it but I'm open minded :)

bigmoby commented 1 year ago

When the integration is off I have to reboot the dongle (I've created a rest API calling from HA) and then I have to restart the integration itself.

Can you clarify what you mean here please by "the integration is off", do you mean showing as "unavailable" in Home Assistant?

Also what steps do you take to "reboot the dongle"?

I'm going to uninstall the "FusionSolar" app and I'll see if things improve, I doubt it but I'm open minded :)

Hi @JohnMcLear , sure I mean the integration appears to me as unavailable (and all the meters related on that of course).

In order to reboot the dongle please try to call this as a service:

rest_command:
  reset_ew11:
    url: http://[your-dongle-ip]/cmd
    method: POST
    username: !secret ew_11_username
    password: !secret ew_11_password
    payload: 'msg={"CID":20003,"PL":{}}'
    content_type:  'application/json; charset=utf-8'

And after that I have to restart the integration (in Devices menu). I hope it could be useful to you 👍

ikxdf commented 1 year ago

Hi, thanks for your great work. Me, and some other friends, have the same issue with this integration. It works well for 3-4 days and after that the starts to have 5-6 Hours of delay and the inverter result disconnected from cloud. When we notice that stops the integration and all start to work normaly again. we have basically two type of config:

  1. Raspberry as a Wi-Fi bridge
  2. Home assistant directly Connect with wifi

seem like the integration is sendigs a lot of request to the inverter and the inverter slow down.

thanks in advance

JohnMcLear commented 1 year ago

Theory: At some point someone (I forgot who) speculated that if the fusion solar app was uninstalled from a phone it would have an impact on availability.

Conclusion: There is no impact from having the app installed/not installed on Inverter "Availability"

I'm going to attempt the restart script as per above next.

wlcrs commented 1 year ago

seem like the integration is sendigs a lot of request to the inverter and the inverter slow down.

Having multiple slaves will of course add an extra burden on the master to process all the update requests. It is very well possible that it's too much for the system to handle.

Does lowering the polling frequency solve the problem? Either follow the instructions here: https://github.com/wlcrs/huawei_solar#inverter-polling-frequency, or change the relevant constants in const.py

JohnMcLear commented 1 year ago

@wlcrs I'll take a look at that today as well as the restart script. Thanks.

I unchecked "Enable polling for updates"

I created a new automation

alias: Huawei Inverter Update Data
description: ""
trigger:
  - platform: time_pattern
    minutes: "/1"
condition: []
action:
  - service: homeassistant.update_entity
    target:
      entity_id:
        - sensor.inverter_daily_yield_1
        - sensor.inverter_daily_yield_2
        - sensor.inverter_daily_yield_3
    data: {}
mode: single

I tried using the example automation but that didn't work.

Note to self: I made this update 2nd March 10:35 am

ikxdf commented 1 year ago

seem like the integration is sendigs a lot of request to the inverter and the inverter slow down.

Having multiple slaves will of course add an extra burden on the master to process all the update requests. It is very well possible that it's too much for the system to handle.

Does lowering the polling frequency solve the problem? Either follow the instructions here: https://github.com/wlcrs/huawei_solar#inverter-polling-frequency, or change the relevant constants in const.py

I was thinking the same: the system have some problems to handle all this requests.

i have notice that. After a inverter and cloud Connectivity down caused by this integration i have a 4hours of data delay on the cloud. This delay slowly disappear in 3 days with integration powered off. Inverter reboot have no effect. Seems like the inverter have ha cache and with the integration polling this cache become huge and hard to handle for it.

Hope this can help.

wlcrs commented 1 year ago

I tried using the example automation but that didn't work.

Make sure that the target entity_id exists. The naming of entities has changed due to HA policy changes, so it depends on when you first installed the integration. You can use the Developer Tools -> Services to make a valid automation action:

image

You'll need to add an entity from every inverter that you have

After clicking on YAML Mode you will receive the yaml code to use:

image

JohnMcLear commented 1 year ago

Good point, I edited my above comment.

JohnMcLear commented 1 year ago

rest_command: reset_ew11: url: http://[your-dongle-ip]/cmd method: POST username: !secret ew_11_username password: !secret ew_11_password payload: 'msg={"CID":20003,"PL":{}}' content_type: 'application/json; charset=utf-8'

Afaik I think the default username is admin and 00000a here.

rest_command:
  reset_inverter_dongle:
    url: http://SDongleA-HV2170115623.lan/cmd
    method: POST
    username: admin
    password: 00000a
    payload: 'msg={"CID":20003,"PL":{}}'
    content_type:  'application/json; charset=utf-8'

For example would be correct if the default username and pass is still set? cc @bigmoby

 Client error. Url: http://SDongleA-HV2170115623.lan/cmd. Error: Cannot connect to host sdonglea-hv2170115623.lan:80 ssl:default [Connect call failed ('10.0.0.100', 80)] 
jose@ryzin:~$ curl SDongleA-HV2170115623.lan
curl: (7) Failed to connect to SDongleA-HV2170115623.lan port 80 after 6 ms: Connection refused
jose@ryzin:~$ 
bigmoby commented 1 year ago

rest_command: reset_ew11: url: http://[your-dongle-ip]/cmd method: POST username: !secret ew_11_username password: !secret ew_11_password payload: 'msg={"CID":20003,"PL":{}}' content_type: 'application/json; charset=utf-8'

Afaik I think the default username is admin and 00000a here.

Hi @JohnMcLear I remember that the default username and password for the Dongle are: admin/admin.

JohnMcLear commented 1 year ago

note that I'm getting Connection refused, not authentication failed but I'll try admin/admin

JohnMcLear commented 1 year ago

Client error. Url: http://SDongleA-HV2170115623.lan/cmd. Error: Cannot connect to host sdonglea-hv2170115623.lan:80 ssl:default [Connect call failed ('10.0.0.100', 80)]

JohnMcLear commented 1 year ago

@ikxdf @wlcrs An initial update

Theory: Less frequent polling will lead to less incorrect Unavailable values.

Prelim Conclusion: Changing to less frequent polling does not solve the problem or improve the user experience. I only have two days of data but given the patterns of Unavailable look exactly the same I'm going to make the preliminary conclusion that reducing the poll rate to /1 doesn't fix the problem.

image

I'm going to attempt /2 minutes now (4th of March).

JohnMcLear commented 1 year ago

image

/2 didn't work, going to attempt /5

ikxdf commented 1 year ago

image

/2 didn't work, going to attempt /5

I have a friend and he is using sucessfully your integration but his inverter is not connected to the cloud. No delay and no inverter issues. seems like the inverter is unable to stream both

JohnMcLear commented 1 year ago

I can confirm that adjusting the frequency of querying the inverters has no notable impact on the availability of an inverter. I tested at /1, /2 & /5 minutes

image

So this issue is related to something different, any suggestions for alternative approaches @wlcrs ?

wlcrs commented 1 year ago

Thank you for your clear reporting.

Can you enable debug logging for a while on this integration (available in the same menu where you fetched the diagnostics file). Once the problem has presented itself you can disable it again and upload the resulting file.

thbiela commented 1 year ago

I think I have the same error. Sometimes I get timeouts and the entities become unavailable. Otherwise the integration works fine. I have two inverters, a battery and a power meter connected.

Logger: custom_components.huawei_solar
Source: helpers/update_coordinator.py:215
Integration: Huawei Solar
First occurred: 8. März 2023 um 21:33:20 (78 occurrences)
Last logged: 09:10:22

Error fetching HV21B0270250_data_update_coordinator data: Could not update HV21<redacted> values: Got error while reading from register 37760 with length 28: Exception Response(131, 3, SlaveFailure)
Error fetching HV2110009960_data_update_coordinator data: Could not update HV21<redacted>  values: Got error while reading from register 32000 with length 20: Exception Response(131, 3, SlaveFailure)
Timeout fetching HV211<redacted>_data_update_coordinator data
Timeout fetching HV21B<redacted>_configuration_update_coordinator data
Timeout fetching HV21B<redacted>_data_update_coordinator data

I have disabled automatic polling for updates and created an automation script. But I have noticed, that even with disabled polling, the values are still being updated (for example the power meter values). I have 109 entities that are being read by the integration, I think that is too much.

image

This is my automation script:

alias: Huawei Update Trigger
description: ""
trigger:
  - platform: time_pattern
    seconds: /20
condition: []
action:
  - service: homeassistant.update_entity
    data: {}
    target:
      entity_id:
        - sensor.battery_charge_discharge_power_2
        - sensor.inverter_input_power_2
        - sensor.inverter_active_power_1
        - sensor.inverter_active_power_2
        - sensor.inverter_daily_yield_1
        - sensor.battery_day_charge_2
        - sensor.battery_day_discharge_2
        - sensor.battery_state_of_capacity_2
        - switch.battery_charge_from_grid_2
mode: single

Dongle:

SDongleA-05 Version V100R001C00SPC133 Connected to 5KTL Battery

Luna2000 5kWh Version V100R002C00SPC116 Connected to 10KTL 5KTL

SUN2000-5KTL-M1 Version V100R001C00SPC148 Modbus ID address 1 No battery 10KTL

SUN2000-10KTL-M1 Version V100R001C00SPC150 Modbus ID address 2 Battery

config_entry-huawei_solar-8f917a2ab63c2ca9b71f691605f3713d.json.txt home-assistant_huawei_solar_2023-03-09T08-37-14.051Z.log

JohnMcLear commented 1 year ago

I enabled debug logs at 14:18 pm on the 9th of Mar, I'll come back to you once I have something useful @wlcrs - - thanks

wlcrs commented 1 year ago

Thanks @thbiela for your logs. I see some SlaveFailure responses, which are different from SlaveBusy errors that I already handle well. I can/should more aggressively retry the calls to the inverter in case of a SlaveFailure.

Note that this is clearly an inverter-side issue, and that I cannot guarantee any improvement. There is already so much retrying going on at multiple levels in the process...

I'll also wait for John to come back with this logs to verify if we're seeing the same errors appearing in his case.

thbiela commented 1 year ago

Thanks for looking into this. Do you know why disabling polling does not work?

All 109 entities are still being updated even if I disable it here:

image

wlcrs commented 1 year ago

No.

On Thu, Mar 9, 2023, 18:35 thbiela @.***> wrote:

Thanks for looking into this. Do you know why disabling polling does not work?

All 109 entities are still being updated even if I disable it here:

[image: image] https://user-images.githubusercontent.com/33088153/224109138-0b741609-47f9-40c3-9856-b87b970fccaf.png

— Reply to this email directly, view it on GitHub https://github.com/wlcrs/huawei_solar/issues/248#issuecomment-1462477328, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAQM5LATZAOJZJSHGCJNC6DW3IIHRANCNFSM6AAAAAATURBLPQ . You are receiving this because you were mentioned.Message ID: @.***>

thbiela commented 1 year ago

OK, after disabling my automation for polling, the entities stopped refreshing. So it has to do with my automation. Even if I try to refresh only one entity, all entities are being polled from the inverter. Is this behaviour intended? If yes, could you tell me if disabling all entities that I do not need will reduce the amount of data that is being read by the integration? Many thanks.

wlcrs commented 1 year ago

I leverage the DataUpdateCoordinator from Home Assistant to optimize the updating of entities. All registers are updated in a batched fashion, independent of if they are disabled are not. Only if you have multiple inverters it can make sense to disable all entities of one of the inverters to stop it being queried.

thbiela commented 1 year ago

So currently the only solution for me seems to be to clone the huawei-solar repository at gitlab and remove the not needed values from the arrays at the bottom of this file, correct? https://gitlab.com/Emilv2/huawei-solar/-/blob/develop/src/huawei_solar/bridge.py

I think that polling these 109 entites could be too much to handle and that this is the reason for the error.

wlcrs commented 1 year ago

Yes. Feel free to experiment and report back!

On Thu, Mar 9, 2023, 19:37 thbiela @.***> wrote:

So currently the only solution for me seems to be to clone the huawei-solar repository at gitlab and remove the not needed values from the arrays at the bottom of this file, correct? https://gitlab.com/Emilv2/huawei-solar/-/blob/develop/src/huawei_solar/bridge.py

I think that polling these 109 entites could be too much to handle and that this is the reason for the error.

— Reply to this email directly, view it on GitHub https://github.com/wlcrs/huawei_solar/issues/248#issuecomment-1462578020, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAQM5LFRSMARZEPGB3A4CA3W3IPONANCNFSM6AAAAAATURBLPQ . You are receiving this because you were mentioned.Message ID: @.***>

JohnMcLear commented 1 year ago

Contents of

cat home-assistant_huawei_solar_2023-03-10T10-47-19.729Z.log | grep huawei > wlcr.txt wlcr.txt

cat home-assistant_huawei_solar_2023-03-10T10-47-19.729Z.log | grep inverter > inverter.txt inverter.txt

JohnMcLear commented 1 year ago

RE batch collection or # of entities being an issue, one approach to testing this theory could be to stagger data gathering in an automation IE minutes: 1,4,7,10... for inverter 1 minutes: 2,5,8,11... for inverter 2 minutes: 3,6,9,12... for inverter 3

I can run this test next week if needs be, for now it appears I don't get a "busy" error but a "fails" fwiw @wlcrs

ikxdf commented 1 year ago

RE batch collection or # of entities being an issue, one approach to testing this theory could be to stagger data gathering in an automation IE minutes: 1,4,7,10... for inverter 1 minutes: 2,5,8,11... for inverter 2 minutes: 3,6,9,12... for inverter 3

I can run this test next week if needs be, for now it appears I don't get a "busy" error but a "fails" fwiw @wlcrs

@wlcrs The problem is not related at the number of iverter. I have only one inverter and i have the issue. i am in a group and some users, with one inverter, are a le to use the integration for >1 week without delay or issues without cloud sync. Other users, with cloud sync, can use the integration for only 3 or 4 days. After that the cloud result disconnected and when stop the integration the cloud sync restare with 2 Hours of delay of data. This delay on the cloud will be reduced to 0 after 2 days. Stop and start the inverter have no effects to resolve the delay.

wlcrs commented 1 year ago

@JohnMcLear you filtered out the stacktraces with your grep. Can you please provide a sample containing a few full stack traces at least?

JohnMcLear commented 1 year ago

@wlcrs - I cherry picked some out for you, I think 1 and 3 might be duplicates but I left it in anyway.

1

2023-03-09 15:53:21.224 ERROR (MainThread) [custom_components.huawei_solar] Unexpected exception from <bound method DataUpdateCoordinator.async_refresh of <custom_components.huawei_solar.H
uaweiSolarUpdateCoordinator object at 0xffff80614eb0>>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 109, in _handle_timer_finish
    await task
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 215, in async_refresh
    await self._async_refresh(log_failures=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 330, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 135, in async_update_listeners
    update_callback()
  File "/config/custom_components/huawei_solar/sensor.py", line 851, in _handle_coordinator_update
    value = self.coordinator.data[self._register_key].value
KeyError: 'power_meter_active_power'

2

Appears to be mostly cruft due to a template value that adds unavailable values.

2023-03-09 15:56:23.405 ERROR (MainThread) [homeassistant.helpers.event] Error while processing template: Template("{{ (((states('sensor.battery_state_of_capacity_1') | float) + (states('s
ensor.battery_state_of_capacity_2') | float) + (states('sensor.battery_state_of_capacity_3') | float))/3) | round(2)}}")
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1771, in forgiving_float_filter
    return float(value)
ValueError: could not convert string to float: 'unknown'

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 458, in async_render
    render_result = _render_with_context(self.template, compiled, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2007, in _render_with_context
    return template.render(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/jinja2/environment.py", line 1301, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.10/site-packages/jinja2/environment.py", line 936, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 1, in top-level template code
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1774, in forgiving_float_filter
    raise_no_default("float", value)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1472, in raise_no_default
    raise ValueError(
ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ (((states('sensor.battery_state_of_capacity_1') | float) + (states('sensor.battery_state_of_capaci
ty_2') | float) + (states('sensor.battery_state_of_capacity_3') | float))/3) | round(2)}}' but no default was specified

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 576, in async_render_to_info
    render_info._result = self.async_render(variables, strict=strict, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 460, in async_render
    raise TemplateError(err) from err
homeassistant.exceptions.TemplateError: ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ (((states('sensor.battery_state_of_capacity_1') | float) +
 (states('sensor.battery_state_of_capacity_2') | float) + (states('sensor.battery_state_of_capacity_3') | float))/3) | round(2)}}' but no default was specified
2023-03-09 15:56:23.422 ERROR (MainThread) [homeassistant.helpers.template_entity] TemplateError('ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ 
(((states('sensor.battery_state_of_capacity_1') | float) + (states('sensor.battery_state_of_capacity_2') | float) + (states('sensor.battery_state_of_capacity_3') | float))/3) | round(2)}}'
 but no default was specified') while processing template 'Template("{{ (((states('sensor.battery_state_of_capacity_1') | float) + (states('sensor.battery_state_of_capacity_2') | float) + 
(states('sensor.battery_state_of_capacity_3') | float))/3) | round(2)}}")' for attribute '_attr_native_value' in entity 'sensor.solarbattery'
2023-03-09 15:56:23.430 ERROR (MainThread) [homeassistant.helpers.event] Error while processing template: Template("{{ (states('sensor.battery_charge_discharge_power_1') | float) + (states
('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_discharge_power_3') | float)}}")
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1771, in forgiving_float_filter
    return float(value)
ValueError: could not convert string to float: 'unknown'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 458, in async_render
    render_result = _render_with_context(self.template, compiled, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2007, in _render_with_context
    return template.render(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/jinja2/environment.py", line 1301, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.10/site-packages/jinja2/environment.py", line 936, in handle_exception
    raise rewrite_traceback_stack(source=source)
  File "<template>", line 1, in top-level template code
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1774, in forgiving_float_filter
    raise_no_default("float", value)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 1472, in raise_no_default
    raise ValueError(
ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ (states('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_disch
arge_power_1') | float) + (states('sensor.battery_charge_discharge_power_3') | float)}}' but no default was specified

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 576, in async_render_to_info
    render_info._result = self.async_render(variables, strict=strict, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 460, in async_render
    raise TemplateError(err) from err
homeassistant.exceptions.TemplateError: ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ (states('sensor.battery_charge_discharge_power_1') | float
) + (states('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_discharge_power_3') | float)}}' but no default was specified
2023-03-09 15:56:23.431 ERROR (MainThread) [homeassistant.helpers.template_entity] TemplateError('ValueError: Template error: float got invalid input 'unknown' when rendering template '{{ 
(states('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_discharge_power_3') | float)}}' b
ut no default was specified') while processing template 'Template("{{ (states('sensor.battery_charge_discharge_power_1') | float) + (states('sensor.battery_charge_discharge_power_1') | flo
at) + (states('sensor.battery_charge_discharge_power_3') | float)}}")' for attribute '_attr_native_value' in entity 'sensor.solarbatterydischarge'

3

Possibly a duplication of 1 During handling of the above exception, another exception occurred:

2023-03-09 16:00:29.625 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.inverter_daily_yield_2 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 541, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 747, in async_device_update
    await task
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 428, in async_update
    await self.coordinator.async_request_refresh()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 189, in async_request_refresh
    await self._debounced_refresh.async_call()
  File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 82, in async_call
    await task
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 215, in async_refresh
    await self._async_refresh(log_failures=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 330, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 135, in async_update_listeners
    update_callback()
  File "/config/custom_components/huawei_solar/sensor.py", line 851, in _handle_coordinator_update
    value = self.coordinator.data[self._register_key].value
KeyError: 'power_meter_active_power'
2023-03-09 16:00:29.632 DEBUG (MainThread) [huawei_solar.huawei_solar] Reading register 32064
wlcrs commented 1 year ago

Hi all, can you please test again with 1.2.6 beta 1?

JohnMcLear commented 1 year ago

Thanks for the fix man I'll test asap and feedback. ETA 5 days

JohnMcLear commented 1 year ago

Screenshot_20230312-101845

I'll grab logs later

JohnMcLear commented 1 year ago

image

cat home-assistant_huawei_solar_2023-03-13T11-53-27.712Z.log | grep huawei | grep -v register > 1.log

Oh wait I'm an idiot, I had automatic checking on AND my automation was running so probably spamming the inverter hard. I'm going to disable my automation and I'll keep testing over the next few days and report back

JohnMcLear commented 1 year ago

Screenshot_20230314-203303

Minor feedback, still some drops today. Only a few events so I'll provide more feedback on Thurs including logs.

thbiela commented 1 year ago

Some feedback: The 'SlaveFailure' error isn't appearing so often anymore, but now I can see the following 'IllegalAddress' error:

Logger: custom_components.huawei_solar
Source: helpers/update_coordinator.py:215
Integration: Huawei Solar
First occurred: 10. März 2023 um 16:07:00 (922 occurrences)
Last logged: 08:26:01

Error fetching HV2110009960_data_update_coordinator data: Could not update HV2110009xxx values: Got error while reading from register 32000 with length 20: Exception Response(131, 3, IllegalAddress)
Error fetching HV21B0270250_data_update_coordinator data: Could not update HV21B0270xxx values: Got error while reading from register 32064 with length 52: Exception Response(131, 3, IllegalAddress)
Timeout fetching HV21B0270xxx_configuration_update_coordinator data
Timeout fetching HV2110009xxx_data_update_coordinator data
Timeout fetching HV21B0270xxx_data_update_coordinator data

Additional warnings:

Logger: homeassistant.helpers.entity
Source: helpers/entity.py:541
First occurred: 10. März 2023 um 15:53:57 (8042 occurrences)
Last logged: 08:36:10

Update of sensor.inverter_active_power_1 is taking over 10 seconds
Update of switch.battery_charge_from_grid_2 is taking over 10 seconds
Update of sensor.battery_charge_discharge_power_2 is taking over 10 seconds
Update of camera.xiaomi_cloud_map_extractor is taking over 10 seconds
Update of binary_sensor.thomas_pc_ethernet is taking over 10 seconds

home-assistant_huawei_solar_2023-03-16T07-44-23.671Z.log

config_entry-huawei_solar-8f917a2ab63c2ca9b71f691605f3713d.json (1).txt

wlcrs commented 1 year ago

Hi @thbiela , an IllegalAddress modbus error normally signals a permanent failure, as it says as much as "the registers that you are requesting do not exist at all". There is no point in aggressively retrying to read from the inverter at that point. The sensors going to "Unavailable" at that point is correct behavior in my opinion.

Can you please leave the debug logging enabled for a while to capture some more information? Now I see that you enabled it only very shortly, meaning that it didn't capture anything useful.

I see another very worrying warning in your logs:

2023-03-14 08:55:39.481 INFO (MainThread) [backoff] Backing off _do_read(...) for 2.0s (huawei_solar.exceptions.SlaveBusyException: Mismatch between number of requested registers (52) and number of received registers (1))

This means that the integration probably receives answers to modbus read requests it didn't do. Do you have anything else connected to your installation on the RS485 ports for instance?

thbiela commented 1 year ago

Hi, I have enabled debug logging and will disable it in a few hours. I have nothing else connected to the RS485 ports, only the huawei solar integration is accessing the inverter via modbus TCP.

JohnMcLear commented 1 year ago

Bug is confirmed still present

image

RE Modbus, I have the huawei energy sensor thingy.

cat home-assistant_huawei_solar_2023-03-16T12-57-25.244Z.log | grep solar | grep -v Reading | grep 16 > 16.txt [16.txt](https://github.com/wlcrs/huawei_solar/files/10990983/16.txt)

I have "Enable polling for updates" enabled and my automation to get the data disabled.

2023-03-15 06:11:20.472 INFO (MainThread) [backoff] Backing off _do_read(...) for 1.0s (asyncio.exceptions.TimeoutError)
2023-03-15 06:11:20.473 DEBUG (MainThread) [huawei_solar.huawei_solar] Received <class 'asyncio.exceptions.TimeoutError'>: backing off reading for 1.0 seconds after 1 tries
2023-03-15 06:11:27.449 ERROR (MainThread) [custom_components.huawei_solar] Timeout fetching TA2270270016_data_update_coordinator data

This appears to be the main stack trace. Nothing notable after

ikxdf commented 1 year ago

check this: https://github.com/openhab/openhab-core/issues/2926

wlcrs commented 1 year ago

Interesting! Thank you for your input!

Sadly this is something that pyModbus does not support for the moment.

Before I do the effort of creating a PR, can you test the following patch please?

In the init.py file of the integration, can you please paste the following lines just above async def async_setup_entry:

patch_applied = False

def monkey_patch_delay_after_connect():
    """
    Dirty fix to force a delay after each connection
    """

    global patch_applied

    if patch_applied:
        return

    from pymodbus.client.base import ModbusBaseClient
    from time import sleep

    orig_connection_made = ModbusBaseClient.connection_made 

    def patched_connection_made(self, transport):
        orig_connection_made(self, transport)
        sleep(2)

    ModbusBaseClient.connection_made  = patched_connection_made
    patch_applied = True

Restart HA after making the changes. Feel free to play around with the sleep time: `sleep(2) means waiting for 2 seconds, which this OpenHab user suggests as a good value.

ikxdf commented 1 year ago

Interesting! Thank you for your input!

Sadly this is something that pyModbus does not support for the moment.

Before I do the effort of creating a PR, can you test the following patch please?

In the init.py file of the integration, can you please paste the following lines just above async def async_setup_entry:

patch_applied = False

def monkey_patch_delay_after_connect():
    """
    Dirty fix to force a delay after each connection
    """

    global patch_applied

    if patch_applied:
        return

    from pymodbus.client.base import ModbusBaseClient
    from time import sleep

    orig_connection_made = ModbusBaseClient.connection_made 

    def patched_connection_made(self, transport):
        orig_connection_made(self, transport)
        sleep(2)

    ModbusBaseClient.connection_made  = patched_connection_made
    patch_applied = True

Restart HA after making the changes. Feel free to play around with the sleep time: `sleep(2) means waiting for 2 seconds, which this OpenHab user suggests as a good value.

My inverter was unresponsive after 4 or 5 days. I will made the changes this night and report back after 5 days.

thank you

JohnMcLear commented 1 year ago

@ikxdf did this patch resolve the issue for you? I haven't tested it on my setup.

ikxdf commented 1 year ago

@ikxdf did this patch resolve the issue for you? I haven't tested it on my setup.

I am at the 6th day without any issue: no delay and no cloud disconnection. I have update the inverter at latest version before apply the fix…i cant said if the good result is because fix or update.

At latest firmware update There is another problem (i have already open an issue but now is closed…). Now the integration show energy consumption at yield energy sensor. This is the update. D6823218-2EF2-41E4-BA59-B723785E4C2D

JohnMcLear commented 1 year ago

I was on SPC130 afaik for quite a long time.

I prolly need to do some testing here because I'm not sure @ikxdf is collecting the same data / correct data to debug this issue, ugh... I'll try sort it now.