solaredge-modbus-multi icon indicating copy to clipboard operation
solaredge-modbus-multi copied to clipboard

Published 20 hours ago • verified publisher icon WillCodeForCats

Diagnosing pymodbus connection issues

Open thargy opened this issue 1 year ago • 50 comments

Describe the feature Allow easy access to pymodbus debug logs in HAOS. The documentation notes a 'download diagnostics' option that no longer appears.

Home Assistant (please complete the following information):

  • Home Assistant Core Version: 2024.1.5
  • solaredge-modbus-multi Version: v2.4.9-pre.3

Additional context I am talking to SolarEdge to diagnose issues with multi-inverter site's new home backup functionality - which isn't currently working or supported. (Apparently it's setting parameter 1404 which can be changed from 1 to 2 to indicate Multi-Inverter Backup Mode).

However, when they made that change on my system this TCP modbus integration failed. Here is the current logging with debug enabled:

2024-01-23 16:44:19.606 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] solaredge_modbus_multi configuration: number_of_inverters=2, start_device_id=1, detect_meters=True, detect_batteries=True, detect_extras=True, keep_modbus_open=False, adv_storage_control=True, adv_site_limit_control=True, allow_battery_energy_reset=False, sleep_after_write=3, battery_rating_adjust=0, 
2024-01-23 16:44:19.606 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] coordinator timeout is 31.2
2024-01-23 16:44:19.610 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 16:44:19.610 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 16:44:31.617 ERROR (MainThread) [custom_components.solaredge_modbus_multi] Unexpected error fetching SolarEdge Coordinator data: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 194, in _async_update_data
    return await self._refresh_modbus_data_with_retry(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 232, in _refresh_modbus_data_with_retry
    raise ex
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 229, in _refresh_modbus_data_with_retry
    return await self._hub.async_refresh_modbus_data()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 319, in async_refresh_modbus_data
    await self._async_init_solaredge()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 209, in _async_init_solaredge
    await new_inverter.init_device()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 671, in init_device
    inverter_data = await self.hub.modbus_read_holding_registers(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 414, in modbus_read_holding_registers
    result = await self._client.read_holding_registers(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pymodbus/client/base.py", line 207, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-01-23 16:44:31.622 DEBUG (MainThread) [custom_components.solaredge_modbus_multi] Finished fetching SolarEdge Coordinator data in 12.016 seconds (success: False)

I would like an easy way to enable debug logging on pymodbus and download logs so that I can see what communications are occurring to hopefully help SolarEdge diagnose the issue. Obviously they don't officially support Pymodbus or this integration so I would like to provide as much useful information to them to hopefully get this working again.

I looked up pymodbus and the debug logs show raw frame data which I feel could be invaluable - i.e. it would be great to show SolarEdge what data is sent on the modbus and to see if there's some kind of unexpected response. Obviously, I'd share the logs here too.

Appreciate your help.

thargy avatar Jan 23 '24 16:01 thargy

configuration.yaml

logger:
    logs:
        pymodbus: debug

WillCodeForCats avatar Jan 23 '24 17:01 WillCodeForCats

Firstly, I apologise for being so lazy. I thought that might work, but I'm so stressed talking to SolarEdge and trying to resolve things I panicked.

As promised, I got the following logs:

2024-01-23 17:37:14.112 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 17:37:14.112 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 17:37:14.130 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 17:37:14.130 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 17:37:14.147 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 17:37:14.147 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 17:37:14.147 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:14.147 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:17.161 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:17.161 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:20.162 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:20.163 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:23.166 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:23.167 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:26.170 ERROR (MainThread) [custom_components.solaredge_modbus_multi] Unexpected error fetching SolarEdge Coordinator data: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 194, in _async_update_data
    return await self._refresh_modbus_data_with_retry(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 232, in _refresh_modbus_data_with_retry
    raise ex
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 229, in _refresh_modbus_data_with_retry
    return await self._hub.async_refresh_modbus_data()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 319, in async_refresh_modbus_data
    await self._async_init_solaredge()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 209, in _async_init_solaredge
    await new_inverter.init_device()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 671, in init_device
    inverter_data = await self.hub.modbus_read_holding_registers(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 414, in modbus_read_holding_registers
    result = await self._client.read_holding_registers(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pymodbus/client/base.py", line 207, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-01-23 17:37:26.777 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 17:37:26.777 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 17:37:26.844 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 17:37:26.844 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 17:37:26.856 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 17:37:26.856 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 17:37:26.856 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:26.856 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:28.170 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to [Errno 104] Connection reset by peer
2024-01-23 17:37:28.170 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-23 17:37:38.617 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 17:37:38.617 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 17:37:38.619 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 17:37:38.619 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 17:37:38.619 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 17:37:38.619 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 17:37:38.619 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:38.620 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:41.621 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:41.623 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:44.624 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:44.625 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:47.627 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:37:47.627 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:37:50.628 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-01-23 17:37:50.629 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-23 17:37:50.629 ERROR (MainThread) [custom_components.solaredge_modbus_multi] Unexpected error fetching SolarEdge Coordinator data: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 194, in _async_update_data
    return await self._refresh_modbus_data_with_retry(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 232, in _refresh_modbus_data_with_retry
    raise ex
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 229, in _refresh_modbus_data_with_retry
    return await self._hub.async_refresh_modbus_data()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 319, in async_refresh_modbus_data
    await self._async_init_solaredge()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 209, in _async_init_solaredge
    await new_inverter.init_device()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 671, in init_device
    inverter_data = await self.hub.modbus_read_holding_registers(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 414, in modbus_read_holding_registers
    result = await self._client.read_holding_registers(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pymodbus/client/base.py", line 207, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-01-23 17:38:10.831 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 17:38:10.831 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 17:38:10.833 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 17:38:10.834 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 17:38:10.834 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 17:38:10.834 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 17:38:10.834 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:38:10.835 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:38:13.837 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:38:13.837 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:38:16.839 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:38:16.839 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:38:19.841 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:38:19.841 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:38:22.842 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-01-23 17:38:22.843 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-23 17:38:22.843 ERROR (MainThread) [custom_components.solaredge_modbus_multi] Unexpected error fetching SolarEdge Coordinator data: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 194, in _async_update_data
    return await self._refresh_modbus_data_with_retry(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 232, in _refresh_modbus_data_with_retry
    raise ex
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 229, in _refresh_modbus_data_with_retry
    return await self._hub.async_refresh_modbus_data()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 319, in async_refresh_modbus_data
    await self._async_init_solaredge()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 209, in _async_init_solaredge
    await new_inverter.init_device()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 671, in init_device
    inverter_data = await self.hub.modbus_read_holding_registers(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 414, in modbus_read_holding_registers
    result = await self._client.read_holding_registers(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pymodbus/client/base.py", line 207, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-01-23 17:39:03.004 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 17:39:03.004 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 17:39:03.007 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 17:39:03.007 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 17:39:03.007 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 17:39:03.008 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 17:39:03.008 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:39:03.008 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:39:06.010 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:39:06.011 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:39:09.013 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:39:09.014 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:39:12.015 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 17:39:12.015 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 17:39:15.017 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-01-23 17:39:15.017 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-23 17:39:15.017 ERROR (MainThread) [custom_components.solaredge_modbus_multi] Unexpected error fetching SolarEdge Coordinator data: Modbus Error: [Input/Output] ERROR: No response received after 3 retries
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 194, in _async_update_data
    return await self._refresh_modbus_data_with_retry(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 232, in _refresh_modbus_data_with_retry
    raise ex
  File "/config/custom_components/solaredge_modbus_multi/__init__.py", line 229, in _refresh_modbus_data_with_retry
    return await self._hub.async_refresh_modbus_data()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 319, in async_refresh_modbus_data
    await self._async_init_solaredge()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 209, in _async_init_solaredge
    await new_inverter.init_device()
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 671, in init_device
    inverter_data = await self.hub.modbus_read_holding_registers(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solaredge_modbus_multi/hub.py", line 414, in modbus_read_holding_registers
    result = await self._client.read_holding_registers(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pymodbus/client/base.py", line 207, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries

Which are illuminating. They confirm my telnet test that the port is open but there's nothing coming back.

I found this line interesting:

2024-01-23 17:37:28.170 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to [Errno 104] Connection reset by peer

But it only occurred once.

Is there any other illumination you can provide before I pass on my interpretation to SolarEdge. Again, I'm conscious this is not formally supported by them so the more insight I can pass on to them the more likely there are to be able to help rectify the issue.

To be clear, the communications were working fine until SolarEdge made some parameter changes to my inverters, so I strongly suspect the issue is at their end (particular as the time the communication stopped coincides with the time they made the changes).

thargy avatar Jan 23 '24 17:01 thargy

I would try giving the inverter a cold boot if you haven't already done that. Turn the red switch to 0, wait for it to shut down, then open the DC disconnect, then open the AC disconnect. The three light tower should turn off. Wait 30 seconds then turn it back on starting with the AC disconnect.

WillCodeForCats avatar Jan 23 '24 17:01 WillCodeForCats

Yeah, we tried resetting the new mode flag followed by a comms board reboot; and I previously tried a cold boot whilst in the new mode. I've suggested the next step is to try changing the new mode back and doing a cold boot - but they have to make the change first and will want to watch what happens. I'll bounce the log back to them now.

thargy avatar Jan 23 '24 17:01 thargy

This might also be a connection race from an uncaught exception during setup; I've corrected that in PR #515 and I'll push a pre release shortly for you to try.

WillCodeForCats avatar Jan 23 '24 17:01 WillCodeForCats

Release v2.4.9-pre.4 contains the change.

WillCodeForCats avatar Jan 23 '24 18:01 WillCodeForCats

OK, I'll hold on to try that first. I don't want it to be our issue as I've got a really good line to their engineers right now, and they're interested in helping resolve issues, so I don't want to lose that goodwill. I'll keep you informed of any info I get as I'm quite a complex site for them, and they're interested in debugging some of their new functionality that is currently being extended to multi-inverter sites. That includes proper HomeBackup support for multi-inverter multi-battery sites, that I tested today and allowed both my inverters to power the home in a full backup scenario (grid off), I was running ~9kW of load with no grid connection.

thargy avatar Jan 23 '24 18:01 thargy

Basically what wasn't happening is when an IO error occurred during setup it wasn't calling disconnect. It would then loop back around holding onto a possibly dead connection. What's supposed to happen if we get an IO error is force a disconnect and open a new connection on the next retry.

Of course the inverter could still not be responding, but at least I can say for sure it's not because an old connection is being held onto.

If they happen to tell you about any modbus registers that aren't documented, let me know and I can add them to the integration.

WillCodeForCats avatar Jan 23 '24 18:01 WillCodeForCats

OK, I ran using that and I didn't see any ModbusIOException in the output.

2024-01-23 18:09:33.247 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-23 18:09:33.247 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-23 18:09:33.279 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-23 18:09:33.279 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-23 18:09:33.287 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Storage Control is enabled. Use at your own risk!
2024-01-23 18:09:33.288 WARNING (MainThread) [custom_components.solaredge_modbus_multi.hub] Power Control Options: Site Limit Control is enabled. Use at your own risk!
2024-01-23 18:09:33.288 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 18:09:33.288 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 18:09:36.290 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 18:09:36.291 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 18:09:39.297 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 18:09:39.297 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 18:09:42.298 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x45
2024-01-23 18:09:42.299 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-23 18:09:45.300 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-01-23 18:09:45.301 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-23 18:09:55.620 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
...

As you can see, you are now correctly catching the error and reconnecting. I recommend you dump the error to the log as an error as well as raising the HubInitFailed exception as that doesn't appear in the logs and is easy to miss (I only see it when I hover over the hover failure message in the hub).

However, I'm still not getting a response.

The only new register may be the Multi-Inverter Backup Mode which I think I heard 1404 for, with 1 indicating existing functionality (off/disabled maybe?) and 2 enabling the mode (on/enbaled?). I can't be 100% sure though. If you want to add it as a beta, I can try and spot if it changes when they make changes? If it reports as 2 right now then I guess that's a pretty good bet.

thargy avatar Jan 23 '24 18:01 thargy

During setup when the configuration is first loaded (or reloaded), Home Assistant will turn all errors into ConfigEntryNotReady which signals HA that setup failed for that integration and to try again later.

Older versions of Home Assistant would show this error more prominently in the integration panel, but at some point it was decided to hide it the hover tooltip. I don't remember if it would also log or not, but it was a decision from the HA core team to make setup errors more hidden.

WillCodeForCats avatar Jan 23 '24 18:01 WillCodeForCats

I checked the core code, they are disabling failure logging at that stage:

https://github.com/home-assistant/core/blob/dev/homeassistant/helpers/update_coordinator.py#L279

WillCodeForCats avatar Jan 23 '24 18:01 WillCodeForCats

Yeah, it doesn't also log it. I appreciate that is the HA Devs choice. Is it considered anti-pattern to also put the error in the log? Personally, I'd put the full error in the log and put a friendly error in the Hub like 'A modbus communication error occurred'. However it's whatever you prefer.

If you want to put a feature branch with an option for the new mode, rather than a beta that would affect everyone, I can patch my code locally?

thargy avatar Jan 23 '24 18:01 thargy

I would need to know the modbus register address, size, and type. 1404 is way outside the holding register range that starts at 40000.

WillCodeForCats avatar Jan 23 '24 21:01 WillCodeForCats

Yeah I’m just starting to read up on the Sun Spec. I’ll see if I can get more info, but I’m not hugely optimistic. Ofc I’ll share it if I do.

thargy avatar Jan 23 '24 21:01 thargy

The plot thickens, I sent raw data to the port and could see that it responded with zero-length data. I changed the unit identifier to '02' and voila, I got data back. Checking the SetApp, sure enough their engineers have changed the device ID from 1 to 2.

However, I can't find how to easily change the Device ID/IP Address/Port of the existing hub? I've seen a repair ticket appear after many hours which allows you do that, but there's nowhere I can find to do it now.

The configuration menu does not expose those settings, and I can't temporarily disable the existing hub and add a new one to test. I have a large system and am loathe to delete the existing hub and have to go through and ensure all the entity ids are correct later if I can just change the Device ID somewhere.

Possibly I'm being blind, but if you can point me in the right direction that would be great.

thargy avatar Jan 24 '24 09:01 thargy

OK, I just deleted the hub and added a new one with Device ID 2. The setup still fails, but I'm getting a lot more logs now:

2024-01-24 09:40:19.205 DEBUG (MainThread) [pymodbus.logging] Connecting to 192.168.89.177:1502.
2024-01-24 09:40:19.205 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-01-24 09:40:19.208 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-01-24 09:40:19.208 DEBUG (MainThread) [pymodbus.logging] callback_connected called
2024-01-24 09:40:19.208 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x1 0x0 0x0 0x0 0x6 0x2 0x3 0x9c 0x40 0x0 0x45
2024-01-24 09:40:19.209 DEBUG (MainThread) [pymodbus.logging] Adding transaction 1
2024-01-24 09:40:19.238 DEBUG (MainThread) [pymodbus.logging] recv: 0x0 0x1 0x0 0x0 0x0 0x8d 0x2 0x3 0x8a 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41 0x53 0x6f 0x6c 0x61 0x72 0x45 0x64 0x67 0x65 0x20 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x53 0x45 0x35 0x30 0x30 0x30 0x48 0x2d 0x52 0x57 0x42 0x4d 0x4e 0x42 0x46 0x35 0x34 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x30 0x30 0x30 0x34 0x2e 0x30 0x30 0x31 0x39 0x2e 0x30 0x30 0x33 0x39 0x0 0x0 0x37 0x35 0x30 0x32 0x42 0x32 0x46 0x41 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 old_data:  addr=None
2024-01-24 09:40:19.239 DEBUG (MainThread) [pymodbus.logging] Processing: 0x0 0x1 0x0 0x0 0x0 0x8d 0x2 0x3 0x8a 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41 0x53 0x6f 0x6c 0x61 0x72 0x45 0x64 0x67 0x65 0x20 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x53 0x45 0x35 0x30 0x30 0x30 0x48 0x2d 0x52 0x57 0x42 0x4d 0x4e 0x42 0x46 0x35 0x34 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x30 0x30 0x30 0x34 0x2e 0x30 0x30 0x31 0x39 0x2e 0x30 0x30 0x33 0x39 0x0 0x0 0x37 0x35 0x30 0x32 0x42 0x32 0x46 0x41 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2
2024-01-24 09:40:19.239 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-24 09:40:19.239 DEBUG (MainThread) [pymodbus.logging] Getting transaction 1
2024-01-24 09:40:19.239 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Registers received requested : 69 69
2024-01-24 09:40:19.239 DEBUG (MainThread) [pymodbus.logging] [21365, 28243, 1, 65, 21359, 27745, 29253, 25703, 25888, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 21317, 13616, 12336, 18477, 21079, 16973, 20034, 17973, 13312, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 12336, 12340, 11824, 12337, 14638, 12336, 13113, 0, 14133, 12338, 16946, 17985, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2]
2024-01-24 09:40:19.240 DEBUG (MainThread) [pymodbus.logging] handle: [b'Su', b'nS']
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_SunSpec_ID 0x53756e53<class 'int'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_SunSpec_DID 0x1<class 'int'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_SunSpec_Length 0x41<class 'int'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_Manufacturer SolarEdge<class 'str'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_Model SE5000H-RWBMNBF54<class 'str'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_Option <class 'str'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_Version 0004.0019.0039<class 'str'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_SerialNumber 7502B2FA<class 'str'>
2024-01-24 09:40:19.240 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2: C_Device_address 0x2<class 'int'>
2024-01-24 09:40:19.241 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x2 0x0 0x0 0x0 0x6 0x2 0x3 0x9c 0xb9 0x0 0x9
2024-01-24 09:40:19.241 DEBUG (MainThread) [pymodbus.logging] Adding transaction 2
2024-01-24 09:40:19.289 DEBUG (MainThread) [pymodbus.logging] recv: 0x0 0x2 0x0 0x0 0x0 0x15 0x2 0x3 0x12 0x0 0x1 0x0 0x41 0x57 0x61 0x74 0x74 0x4e 0x6f 0x64 0x65 0x0 0x0 0x0 0x0 0x0 0x0 old_data:  addr=None
2024-01-24 09:40:19.290 DEBUG (MainThread) [pymodbus.logging] Processing: 0x0 0x2 0x0 0x0 0x0 0x15 0x2 0x3 0x12 0x0 0x1 0x0 0x41 0x57 0x61 0x74 0x74 0x4e 0x6f 0x64 0x65 0x0 0x0 0x0 0x0 0x0 0x0
2024-01-24 09:40:19.290 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-24 09:40:19.290 DEBUG (MainThread) [pymodbus.logging] Getting transaction 2
2024-01-24 09:40:19.290 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Registers received requested : 9 9
2024-01-24 09:40:19.290 DEBUG (MainThread) [pymodbus.logging] [1, 65, 22369, 29812, 20079, 25701, 0, 0, 0]
2024-01-24 09:40:19.290 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2 MMPPT: mmppt_DID 0x1 <class 'int'>
2024-01-24 09:40:19.290 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2 MMPPT: mmppt_Length 0x41 <class 'int'>
2024-01-24 09:40:19.291 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2 MMPPT: mmppt_Units 0x0 <class 'int'>
2024-01-24 09:40:19.291 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2 is NOT Multiple MPPT
2024-01-24 09:40:19.291 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x3 0x0 0x0 0x0 0x6 0x2 0x3 0x9c 0xb9 0x0 0x43
2024-01-24 09:40:19.291 DEBUG (MainThread) [pymodbus.logging] Adding transaction 3
2024-01-24 09:40:19.352 DEBUG (MainThread) [pymodbus.logging] recv: 0x0 0x3 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0x0 0x1 0x0 0x41 0x57 0x61 0x74 0x74 0x4e 0x6f 0x64 0x65 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x57 0x4e 0x44 0x2d 0x33 0x59 0x2d 0x34 0x30 0x30 0x2d 0x4d 0x42 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x45 0x78 0x70 0x6f 0x72 0x74 0x2b 0x49 0x6d 0x70 0x6f 0x72 0x74 0x0 0x0 0x0 0x33 0x31 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x35 0x30 0x39 0x31 0x39 0x39 0x36 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x3 old_data:  addr=None
2024-01-24 09:40:19.352 DEBUG (MainThread) [pymodbus.logging] Processing: 0x0 0x3 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0x0 0x1 0x0 0x41 0x57 0x61 0x74 0x74 0x4e 0x6f 0x64 0x65 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x57 0x4e 0x44 0x2d 0x33 0x59 0x2d 0x34 0x30 0x30 0x2d 0x4d 0x42 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x45 0x78 0x70 0x6f 0x72 0x74 0x2b 0x49 0x6d 0x70 0x6f 0x72 0x74 0x0 0x0 0x0 0x33 0x31 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x35 0x30 0x39 0x31 0x39 0x39 0x36 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x3
2024-01-24 09:40:19.352 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-24 09:40:19.352 DEBUG (MainThread) [pymodbus.logging] Getting transaction 3
2024-01-24 09:40:19.352 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Registers received requested : 67 67
2024-01-24 09:40:19.353 DEBUG (MainThread) [pymodbus.logging] [1, 65, 22369, 29812, 20079, 25701, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 22350, 17453, 13145, 11572, 12336, 11597, 16896, 0, 0, 0, 0, 0, 0, 0, 0, 0, 17784, 28783, 29300, 11081, 28016, 28530, 29696, 0, 13105, 0, 0, 0, 0, 0, 0, 0, 13616, 14641, 14649, 13824, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 3]
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_SunSpec_DID 0x1 <class 'int'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_SunSpec_Length 0x41 <class 'int'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_Manufacturer WattNode <class 'str'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_Model WND-3Y-400-MB <class 'str'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_Option Export+Import <class 'str'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_Version 31 <class 'str'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_SerialNumber 5091996 <class 'str'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M1: C_Device_address 0x3 <class 'int'>
2024-01-24 09:40:19.353 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Found I2M1
2024-01-24 09:40:19.354 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x4 0x0 0x0 0x0 0x6 0x2 0x3 0x9d 0x67 0x0 0x43
2024-01-24 09:40:19.355 DEBUG (MainThread) [pymodbus.logging] Adding transaction 4
2024-01-24 09:40:19.600 DEBUG (MainThread) [pymodbus.logging] recv: 0x0 0x4 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0x2 0xbd 0x0 0x99 0x0 0x0 0x0 0x1 0xff 0xff 0x0 0x1 0x0 0x0 0x0 0x0 0xff 0xff 0xff 0xff 0x0 0x21 0x0 0x22 0x0 0x7 0x0 0x61 0x80 0x0 0x9 0x61 0x4 0xb0 0x0 0x0 0xc3 0x81 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0xff 0xff 0xff 0xff 0xff 0xff 0x9 0x61 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x80 0x0 0x80 0x0 0x80 0x0 old_data:  addr=None
2024-01-24 09:40:19.600 DEBUG (MainThread) [pymodbus.logging] Processing: 0x0 0x4 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0x2 0xbd 0x0 0x99 0x0 0x0 0x0 0x1 0xff 0xff 0x0 0x1 0x0 0x0 0x0 0x0 0xff 0xff 0xff 0xff 0x0 0x21 0x0 0x22 0x0 0x7 0x0 0x61 0x80 0x0 0x9 0x61 0x4 0xb0 0x0 0x0 0xc3 0x81 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0x80 0x0 0xff 0xff 0xff 0xff 0xff 0xff 0x9 0x61 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x80 0x0 0x80 0x0 0x80 0x0
2024-01-24 09:40:19.600 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-24 09:40:19.601 DEBUG (MainThread) [pymodbus.logging] Getting transaction 4
2024-01-24 09:40:19.601 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Registers received requested : 67 67
2024-01-24 09:40:19.601 DEBUG (MainThread) [pymodbus.logging] [701, 153, 0, 1, 65535, 1, 0, 0, 65535, 65535, 33, 34, 7, 97, 32768, 2401, 1200, 0, 50049, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 32768, 32768, 32768, 32768, 32768, 32768, 32768, 32768, 32768, 65535, 65535, 65535, 2401, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 32768, 32768, 32768]
2024-01-24 09:40:19.601 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_SunSpec_DID 0x2bd <class 'int'>
2024-01-24 09:40:19.601 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_SunSpec_Length 0x99 <class 'int'>
2024-01-24 09:40:19.601 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_Manufacturer !"a	a <class 'str'>
2024-01-24 09:40:19.601 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_Model Á <class 'str'>
2024-01-24 09:40:19.602 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_Option  <class 'str'>
2024-01-24 09:40:19.602 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_Version 	a <class 'str'>
2024-01-24 09:40:19.602 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_SerialNumber  <class 'str'>
2024-01-24 09:40:19.602 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: C_Device_address 0x8000 <class 'int'>
2024-01-24 09:40:19.602 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M2: Meter 2 ident incorrect or not installed.
2024-01-24 09:40:19.602 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x5 0x0 0x0 0x0 0x6 0x2 0x3 0x9e 0x15 0x0 0x43
2024-01-24 09:40:19.603 DEBUG (MainThread) [pymodbus.logging] Adding transaction 5
2024-01-24 09:40:19.639 DEBUG (MainThread) [pymodbus.logging] recv: 0x0 0x5 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0xff 0xff 0x0 0x0 0x0 0x1 0x0 0x2 0xff 0xff 0xf7 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x0 0x0 0xff 0xfe 0x0 0x0 0x0 0x0 0xff 0xff 0x0 0x0 0x0 0x0 0x2 0xbf 0x0 0x11 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xfe 0xff 0xfd 0x2 0xc0 0x0 0x41 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff old_data:  addr=None
2024-01-24 09:40:19.639 DEBUG (MainThread) [pymodbus.logging] Processing: 0x0 0x5 0x0 0x0 0x0 0x89 0x2 0x3 0x86 0xff 0xff 0x0 0x0 0x0 0x1 0x0 0x2 0xff 0xff 0xf7 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0x0 0x0 0xff 0xfe 0x0 0x0 0x0 0x0 0xff 0xff 0x0 0x0 0x0 0x0 0x2 0xbf 0x0 0x11 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xfe 0xff 0xfd 0x2 0xc0 0x0 0x41 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff
2024-01-24 09:40:19.639 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-24 09:40:19.639 DEBUG (MainThread) [pymodbus.logging] Getting transaction 5
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] Registers received requested : 67 67
2024-01-24 09:40:19.640 DEBUG (MainThread) [pymodbus.logging] [65535, 0, 1, 2, 65535, 63487, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 0, 65534, 0, 0, 65535, 0, 0, 703, 17, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65534, 65533, 704, 65, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535, 65535]
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_SunSpec_DID 0xffff <class 'int'>
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_SunSpec_Length 0x0 <class 'int'>
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_Manufacturer  <class 'str'>
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_Model  <class 'str'>
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_Option  <class 'str'>
2024-01-24 09:40:19.640 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_Version  <class 'str'>
2024-01-24 09:40:19.641 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_SerialNumber A <class 'str'>
2024-01-24 09:40:19.641 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: C_Device_address 0xffff <class 'int'>
2024-01-24 09:40:19.641 DEBUG (MainThread) [custom_components.solaredge_modbus_multi.hub] I2M3: Meter 3 ident incorrect or not installed.
2024-01-24 09:40:19.641 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x6 0x0 0x0 0x0 0x6 0x3 0x3 0x9c 0x40 0x0 0x45
2024-01-24 09:40:19.641 DEBUG (MainThread) [pymodbus.logging] Adding transaction 6
2024-01-24 09:40:22.642 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x6 0x0 0x0 0x0 0x6 0x3 0x3 0x9c 0x40 0x0 0x45
2024-01-24 09:40:22.643 DEBUG (MainThread) [pymodbus.logging] Adding transaction 6
2024-01-24 09:40:25.644 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x6 0x0 0x0 0x0 0x6 0x3 0x3 0x9c 0x40 0x0 0x45
2024-01-24 09:40:25.645 DEBUG (MainThread) [pymodbus.logging] Adding transaction 6
2024-01-24 09:40:28.647 DEBUG (MainThread) [pymodbus.logging] send: 0x0 0x6 0x0 0x0 0x0 0x6 0x3 0x3 0x9c 0x40 0x0 0x45
2024-01-24 09:40:28.648 DEBUG (MainThread) [pymodbus.logging] Adding transaction 6
2024-01-24 09:40:31.649 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-01-24 09:40:31.650 DEBUG (MainThread) [pymodbus.logging] Getting transaction 6
2024-01-24 09:40:31.650 DEBUG (MainThread) [custom_components.solaredge_modbus_multi] Finished fetching SolarEdge Coordinator data in 12.446 seconds (success: False)

I can see it interrogates the primary inverter and then tries to talk to Device ID 3 but gets no response. This reminds me of the previous issues relating to non-consecutive modbus device IDs...

Sadly, everytime SEDG muck around with my system they force these IDs back to defaults which may not be non-consecutive. (see #368).

It might be worth changing the hub failure error to suggest checking the DeviceID when it gets no response from an open connection?

Also, I'm wondering if it would be possible to auto scan the device IDs, given that sending the wrong ID results in an immediate empty response?

thargy avatar Jan 24 '24 09:01 thargy

Great news! It turns out that they set the Device ID for both the master and slave inverters to '2'!!! I've queried why they did that - I hope it was just engineers messing around with things they didn't understand. Setting the master back to 1 has allowed me to re-add the hub.

I had previously renamed all the second solaredge_b1_...._2 entities, for the first battery on the second inverter to solaredge_b2_.... I wonder if it might be better to default to something like, solaredge_i1_b1_... and solaredge_i2_b1_..., that is specify the inverter and battery numbers in the entity name for clarity/disambiguation?

In the meantime, I've changed all my references to use the default naming so it isn't so difficult to remove and re-add a hub. This has been a very informative issue, as it's forced me to finally dig into the Modbus specs and understand them better. When I finish all my renovations and get my head above water, I'll try to contribute more time to helping with this fantastic project.

Thank you for your help.

thargy avatar Jan 24 '24 12:01 thargy

I did try naming like that, but reverted it for reasons I can't remember now. It might be in the history.

The repair isn't raised during setup, but its easy to change that.

WillCodeForCats avatar Jan 24 '24 14:01 WillCodeForCats

Scanning all possible modbus addresses isn't really practical. With minimum timeouts would take at least 12 minutes, and nobody is going to wait that long for HA to finish startup or add an entry and not think something is broken (if HA would even allow that before forcing a timeout).

Modbus protocol doesn't provide a way to detect duplicate ID. You can't assume that no response means duplicate ID, it can just mean no response too. I monitor my inverters and occasionally they will do the same non-response thing for a cycle.

WillCodeForCats avatar Jan 24 '24 14:01 WillCodeForCats

For what it's worth when my system was installed the installers left unit ID settings set to '1', so it's possible that in general it's not well understood why that setting would need to be unique per inverter. Duplicate unit ID does not appear to affect Solaredge's proprietary leader/follower protocol or their monitoring platform.

WillCodeForCats avatar Jan 24 '24 14:01 WillCodeForCats

Scanning all possible modbus addresses isn't really practical. With minimum timeouts would take at least 12 minutes, and nobody is going to wait that long for HA to finish startup or add an entry and not think something is broken (if HA would even allow that before forcing a timeout).

It is true there are 247 possible device IDs (1->247) and at 3s timeout that would be just over 12 minutes in the worst case. However, SolarEdge runs on RS485 which I believe has a limit of 32 connected devices - though there's no guarantee that those IDs are consecutive, they are almost always clumped in the first 32 id spaces. Further, in my testing, when I pinged a missing device ID, I got an instant zero-length response - sensing this would allow immediate moving on to the next ID in a 'Fast Scan'. A timeout would usually indicate a comms failure and the scan could optionally abort immediately.

As it is unlikely that most devices would have an ID set above > 32, and, most of the time, and unassigned IP will immediately respond with an empty packet we can do an initial fast scan extremely quickly for the vast majority of scenarios. If the scan reports progress as it goes, the user can click stop when all the devices are found. Alternatively, they can enter the target device count before commencing a scan.

It's also not a requirement that people use the 'fast scan' if we provide a UI for manually entering Device IDs (which the fast scan populates automatically), they can have a Scan button to optionally perform a scan. We can also have a slower scan that rigorously checks from 1->247 with full timeouts if necessary, and that would take 12mins.

The point is that such a function would probably work very quickly for the vast majority of installs. SolarEdge has told me that the vast majority of sites are one inverter and one battery max, and the Device ID is likely to be < 4. Scanning automatically for device IDs and supporting non-consecutive IDs will make it much easier for less technical users.

Anyway, this is a suggestion, and I may be able to have a crack at implementing and testing it in the future if you're interested. If you think it's worth it I can write up a clean feature request for garnering interest?

Modbus protocol doesn't provide a way to detect duplicate ID. You can't assume that no response means duplicate ID, it can just mean no response too. I monitor my inverters and occasionally they will do the same non-response thing for a cycle.

Yes, in fact the primary inverter was responding fine on the ID, and the follower was hidden, there was no way to see there was actually a duplicate ID. A duplicate ID did not cause a non-response; the empty response was on ID '1', which was empty (as it had been moved to collide on '2'). As you can see from the logs, the primary inverter is the one responding on '2' whilst the duplication was in effect.

A scan whilst a duplicate ID is set would result in only the master inverter being found, and the follower being unavailable - in such a scenario the UI could suggest using the SetApp to check that there are different Device IDs and provide a link to the wiki.

It is my suspicion that distinguishing between an empty response and a lack of response will prove very fruitful in detecting an empty device ID. I suspect that when you fail to get a response on occasion on a valid ID, it is a non-response not an empty response, but that's harder to confirm as the current pymodbus doesn't log an empty response and waits for the timeout instead. A brief scan of pymodbus docs seems to indicate it can detect an empty response though, but I would need to investigate further.

thargy avatar Jan 24 '24 15:01 thargy

There are commercial size installations using this integration, so we can't make any assumptions about small sites.

WillCodeForCats avatar Jan 24 '24 15:01 WillCodeForCats

It is my suspicion that distinguishing between an empty response and a lack of response will prove very fruitful in detecting an empty device ID.

My inverters don't have that behavior, so that's probably dependent on the firmware version if yours do that and mine don't.

WillCodeForCats avatar Jan 24 '24 15:01 WillCodeForCats

There are commercial-size installations using this integration, so we can't make any assumptions about small sites.

Agreed, but I'm not. As stated above, the 32-device limit is the same on large installations, so they must use separate mod busses to exceed that. Even if that limit isn't there, the Modbus spec uses one byte and only supports 247 values. My proposal has the following non-breaking mitigations for your scenario:

  1. Using the scan is optional, the user can add IDs manually (as now, except with the ability to add multiple IDs rather than just a 'starting' ID).
  2. I believe we can detect an empty ID very quickly (ms) not (s), however, even if you require a 3s timeout each time it only takes up to 12 minutes maximum, even on very large installations, it will usually find all devices before that, as it will only take 12 minutes if the last device is on Device ID 247 and we require 3s to detect an empty ID.

As such the proposal only adds a convenience feature, it doesn't create a breaking change. If users on large sites don't want to perform a scan, or wait up to 12 minutes, they are free to not do so. I suspect for the vast majority of users a scan will be quicker, more robust and more convenient. However, this is just a proposal for discussion.

My inverters don't have that behavior, so that's probably dependent on the firmware version if yours do that and mine don't.

Just to confirm, the pymodbus logs do not show any empty response. I only saw that by using Packet Sender and manually sending the binary data to the TCP port. I could not see a near instant empty response come back, whereas pymodbus reported nothing and waited for the full 3s timeout. I need to check the pymodbus code to see how it handles a truly zero length packet to see if we can detect it. Have you tried hitting the TCP Modbus directly rather than through pymodbus?

thargy avatar Jan 24 '24 15:01 thargy

I've already been working on stuff in regards to invalid IDs from #460 and the wish list has non-consecutive IDs on it, but I've not uploaded anything yet since it's not a high priority.

Modbus at its heart is broadcast-response and I have seen data from inverters where their "normal" is 1-2 seconds to respond, so 3 seconds is necessary (already on the edge of being too short). I've also seen inverters with an escalating response delay. I can't tell you the exact issue/pr but if you look through all of the closed ones it's in there somewhere. There's not much difference between Modbus TCP and RTU: you still broadcast and either you get a response or you don't. I also calculate timeouts based on number of requests and device types based on past observations, which you can see the total calculated timeout if you turn on debugging.

There are four possibilities when sending a modbus request:

  • A normal response with a data packet.
  • No response: comm error, malformed data on the bus, collision, other I/O reasons. In any case it's a timeout.
  • We get a response but there's a parity, LRC, or CRC error. This is also ultimately a timeout.
  • We get a response but it's one of the exception codes rather than a data packet.

So for the case of auto detecting IDs for setup, scanning the first 32 addresses with a 3 second delay and 3 retry attempts would be up to about 5 minutes. In reality it would probably be faster but it's not guaranteed.

I work with modbus outside of this (power meters, generators, transfer switches, pumps, air handlers, etc.), but I use libmodbus in C. I have modbus simulators that I've built up over time to work with this integration especially for devices I don't have like batteries. Other connection methods are academic at best, since HA is using Python and the Pymodbus library. About the only thing external tools are useful for in my experience are scanning registers looking for undocumented stuff. Even my simulators aren't ideal because they don't have the weird problems SE stuff can randomly have.

It's also on my wish list to support a serial option, so anything that's done ideally should consider the possibility for modbus RTU (the original form). It's at the bottom of the priority list though.

WillCodeForCats avatar Jan 24 '24 17:01 WillCodeForCats

I should add that I don't really care if some auto-detect takes 5 minutes to run, but I don't know how HA reacts to long running setups and end users generally want things to be instant or they complain.

WillCodeForCats avatar Jan 24 '24 17:01 WillCodeForCats

PR #518 will raise the repair issue if setup fails, previously it would just raise on connection issues post-setup.

WillCodeForCats avatar Jan 24 '24 17:01 WillCodeForCats

Thanks for the great detail! Looking through your 4 responses you don’t list an empty response though - have you not seen an empty packet in your testing. Like I said, my system gave back a near instant empty packet for unassigned IDs, which is not the same as no response.

In terms of malformed responses it always a choice whether to retry (until a count or timeout) or log and move on. I can see the argument for the former - there being a bad response is a hint there is at least a device at that id so worth a retry.

I appreciate that an empty response is a TCP thing though, and wouldn’t work with RTU.

The 5-12 minute thing may cause a HA setup fail, that would need investigating. If they do timeout for setup there’s a strong case for a keep-alive feature request, but I acknowledge your concern. I have seen other setups that warn that it can take several minutes though, so I suspect it’s doable. It’s easy to find out with a nice long sleep anyway!

As for user experience that’s pretty resolvable with good UI. I think scan functionality should be an opt in, rather than requirement, e.g. a button you press when setting a list of device IDs that warns before starting. If you know your IDs you can just enter them manually. It’s highly likely most scans would complete fairly quickly after scanning 2-5 IDs, and if the user is warned that a scan may take up to 12 minutes they’ll accept that. They can always be passed to a wiki explaining why it takes so long.

I saw the PR and think that’s a great addition.

Ultimately this is a great tool, and has allowed me to do some really cool smart home stuff, so thanks for all the hard work and effort. I will obviously update you if I manage to get the register number out of SEDG. I currently have some really good access so it is possible. I’ve made a strong argument for getting it, though they’re understandably going to be reluctant given the beta nature of the mode.

thargy avatar Jan 24 '24 17:01 thargy

A modbus frame always has its headers, id, function code, and data bytes. TCP only differs from RTU in that modbus TCP doesn't include a checksum after the data bytes because it's relying on the lower levels of TCP/IP to handle that aspect.

If something send an "empty" response that would just be an I/O error as far as I understand the modbus protocol, maybe some attempts to resend the request, ultimately timing out due to no response.

WillCodeForCats avatar Jan 24 '24 23:01 WillCodeForCats

A modbus frame always has its headers, id, function code, and data bytes. TCP only differs from RTU in that modbus TCP doesn't include a checksum after the data bytes because it's relying on the lower levels of TCP/IP to handle that aspect.

Yes.

If something send an "empty" response that would just be an I/O error as far as I understand the modbus protocol, maybe some attempts to resend the request, ultimately timing out due to no response.

What I saw was an empty TCP packet, (basically just a 64 byte header) which is a totally valid TCP packet - but as you say not a valid Modbus frame. It is quite distinct from no response at all, but I believe is treated like no response by pymodbus - as there is no data to decode.

I didn't see it treated as an error by pymodbus, which is not surprising as it's not really part of the modbus design itself as the idea of zero length only becomes possible when the modbus protocol is embedded in a different transport protocol as with Modbus TCP. The distinction between no response and empty occurs at the TCP layer not the Modbus protocol layer. Hence I acknowledged it wouldn't help when using Modbus RTU.

Technically, it is possible to distinguish such an empty TCP packet from no response, but I'm not sure if pymodbus supports that natively or just swallows the empty packet entirely (quite possible). In my testing that empty packet comes back instantly and may be a reliable indicator that the device id is unassigned, as opposed to a communication error or unresponsive slave. However, that would need careful testing and investigation. I am encouraged that the receipt of a tcp packet, albeit empty, requires the modbus server/slave to process the request and respond - unlike when it's just busy. It is not unlikely that the empty response is a result of SEDG's implementation recognising there is no device at that ID, and so having nothing to include in a response payload. An empty response would be equivalent to 'we know nothing came back' as opposed to no response being 'we're still waiting for a response'.

thargy avatar Jan 24 '24 23:01 thargy