search

davidrapan / ha-solarman

⚡ Solarman Stick Logger integration for 🏠 Home Assistant
MIT License
41 stars 13 forks source link

Could we silence errors when inverter is offline? #17

Closed Floppe closed 2 weeks ago

Floppe commented 1 month ago

My inverter gets power from the sun, so at nights the inverter is offline and stick logger is unreachable.

I've lost the logs now when I've restarted several times, but the logs are quite noisy at nights. Perhaps enough with a warning message or remove stack trace and only show unreachable.

PV-Joe commented 1 month ago

What inverter are we talking about?

Floppe commented 1 month ago

It's a Sofar KTLX-G3

davidrapan commented 1 month ago

Hi there, It's made for continuous connection.. So it goes crazy when it can't reach the inverter.

I will think about a way how it could be done without affecting current working state. But can't make any promises as I'm really busy lately.

I wish I could help you more.

Floppe commented 1 month ago

Hi. I understand that. Here are some log snippets incase you do find some time.

2024-07-12 04:26:06.656 ERROR (MainThread) [custom_components.solarman.api] OSError: [Errno 113] Connect call failed ('192.168.10.159', 8899)
Traceback (most recent call last):
  File "/config/custom_components/solarman/api.py", line 47, in reconnect
    self.reader, self.writer = await asyncio.open_connection(self.address, self.port)
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 48, in open_connection
    transport, _ = await loop.create_connection(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1120, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1102, in create_connection
    sock = await self._connect_sock(
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1005, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 641, in sock_connect
    return await fut
           ^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 681, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('192.168.10.159', 8899)
2024-07-12 04:26:06.658 WARNING (MainThread) [asyncio] socket.send() raised exception.
2024-07-12 04:26:06.658 ERROR (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
Traceback (most recent call last):
  File "/config/custom_components/solarman/api.py", line 69, in _send_receive_v5_frame
    await self.writer.drain()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain
    raise exc
  File "/config/custom_components/solarman/api.py", line 199, in async_get
    await self.async_read(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 133, in async_read
    await self._read_registers(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 125, in _read_registers
    response = await self.read_holding_registers(register_addr = start, quantity = length)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 283, in read_holding_registers
    modbus_values = await self._get_modbus_response(mb_request_frame)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 246, in _get_modbus_response
    mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 233, in _send_receive_modbus_frame
    v5_response_frame = await self._send_receive_v5_frame(v5_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 69, in _send_receive_v5_frame
    await self.writer.drain()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain
    raise exc
  File "/config/custom_components/solarman/api.py", line 199, in async_get
    await self.async_read(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 133, in async_read
    await self._read_registers(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 125, in _read_registers
    response = await self.read_holding_registers(register_addr = start, quantity = length)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 283, in read_holding_registers
    modbus_values = await self._get_modbus_response(mb_request_frame)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 246, in _get_modbus_response
    mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 233, in _send_receive_modbus_frame
    v5_response_frame = await self._send_receive_v5_frame(v5_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 69, in _send_receive_v5_frame
    await self.writer.drain()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain
    raise exc
  File "/config/custom_components/solarman/api.py", line 199, in async_get
    await self.async_read(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 133, in async_read
    await self._read_registers(code, params, start, end)
  File "/config/custom_components/solarman/api.py", line 125, in _read_registers
    response = await self.read_holding_registers(register_addr = start, quantity = length)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 283, in read_holding_registers
    modbus_values = await self._get_modbus_response(mb_request_frame)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 246, in _get_modbus_response
    mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 233, in _send_receive_modbus_frame
    v5_response_frame = await self._send_receive_v5_frame(v5_request_frame)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 69, in _send_receive_v5_frame
    await self.writer.drain()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain
    raise exc
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 312, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/coordinator.py", line 33, in _async_update_data
    return await self.inverter.async_get(self._accounting())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 225, in async_get
    await self.async_get_failed(f"Querying {self.serial} at {self.address}:{self.port} failed during connection start. [{format_exception(e)}]")
  File "/config/custom_components/solarman/api.py", line 173, in async_get_failed
    await self.async_disconnect()
  File "/config/custom_components/solarman/api.py", line 113, in async_disconnect
    await self.writer.wait_closed()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 364, in wait_closed
    await self._protocol._get_close_waiter(self)
OSError: [Errno 113] Host is unreachable
2024-07-12 04:26:06.662 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #0 [OSError: [Errno 113] Host is unreachable]
2024-07-12 04:26:10.663 ERROR (MainThread) [custom_components.solarman.coordinator] Unexpected error fetching Solarman data
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 312, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/coordinator.py", line 33, in _async_update_data
    return await self.inverter.async_get(self._accounting())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 225, in async_get
    await self.async_get_failed(f"Querying {self.serial} at {self.address}:{self.port} failed during connection start. [{format_exception(e)}]")
  File "/config/custom_components/solarman/api.py", line 173, in async_get_failed
    await self.async_disconnect()
  File "/config/custom_components/solarman/api.py", line 113, in async_disconnect
    await self.writer.wait_closed()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 364, in wait_closed
    await self._protocol._get_close_waiter(self)
OSError: [Errno 113] Host is unreachable
....
....snip....
....
2024-07-12 04:26:18.614 ERROR (MainThread) [custom_components.solarman.api] OSError: [Errno 113] Connect call failed ('192.168.10.159', 8899)
davidrapan commented 1 month ago

Hi there, I added in the fix: Try for extended handling for EHOSTUNREACH some extended error handling to try to debug our way into some solution. Could you please try it? Enable debug logging and post the logs here?

You will have to manually overwrite the code from the repo in your HA as this is not as part of latest release.

Thanks and have fun!

Floppe commented 1 month ago

I cloned the repo manually and enabled extensive debug logging. Lets wait and see.

Floppe commented 1 month ago

Here is a snippet from when the inverter did go offline. Hope it's enough.


2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.parser] Default update_interval: 60, min_span: 25, digits: 6
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #-5
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) ...
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1d 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 37 15
2024-07-17 23:20:51.981 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 4
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1e 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 38 15
2024-07-17 23:21:07.980 DEBUG (MainThread) [custom_components.solarman.coordinator] Finished fetching Solarman data in 30.000 seconds (success: False)
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.parser] Default update_interval: 60, min_span: 25, digits: 6
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #-5
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) ...
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1f 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 39 15
2024-07-17 23:21:26.971 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:29.971 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 4
2024-07-17 23:21:29.971 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 20 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3a 15
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:29.972 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 3
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 21 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3b 15
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:32.973 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 2
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 22 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3c 15
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:35.974 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 1
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 23 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3d 15
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:38.975 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 0, aborting.
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] Request failed. [Previous Status: Connected]

```2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.parser] Default update_interval: 60, min_span: 25, digits: 6
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #-5
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) ...
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:20:37.980 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1d 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 37 15
2024-07-17 23:20:51.981 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 4
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:20:54.983 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1e 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 38 15
2024-07-17 23:21:07.980 DEBUG (MainThread) [custom_components.solarman.coordinator] Finished fetching Solarman data in 30.000 seconds (success: False)
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.parser] Default update_interval: 60, min_span: 25, digits: 6
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #-5
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) ...
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-17 23:21:12.968 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 1f 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 39 15
2024-07-17 23:21:26.971 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:29.971 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 4
2024-07-17 23:21:29.971 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 20 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3a 15
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:29.972 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:29.972 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 3
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 21 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3b 15
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:32.973 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:32.973 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 2
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 22 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3c 15
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:35.974 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:35.974 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 1
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] SENT: a5 17 00 10 45 23 00 3f af 92 8c 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 04 04 00 2
b 45 24 3d 15
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] EHOSTUNREACH error: [Errno 113] Host is unreachable
2024-07-17 23:21:38.975 DEBUG (MainThread) [custom_components.solarman.api] [2358423359] Send/Receive error: [Errno 113] Host is unreachable
2024-07-17 23:21:38.975 WARNING (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) failed. #-5 [TimeoutError]
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 0, aborting.
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] Request failed. [Previous Status: Connected]
2024-07-17 23:21:41.977 INFO (MainThread) [custom_components.solarman.api] Disconnecting from 192.168.10.159:8899
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] [Errno 113] Host is unreachable can be during closing ignored.
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] Request failed. [Previous Status: Connected]
2024-07-17 23:21:41.977 INFO (MainThread) [custom_components.solarman.api] Disconnecting from 192.168.10.159:8899
2024-07-17 23:21:41.977 DEBUG (MainThread) [custom_components.solarman.api] [Errno 113] Host is unreachable can be during closing ignored.
2024-07-17 23:21:41.977 ERROR (MainThread) [custom_components.solarman.coordinator] Unexpected error fetching Solarman data
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 312, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/coordinator.py", line 30, in _async_update_data
    return await self.inverter.async_get(self._accounting())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/solarman/api.py", line 216, in async_get
    await self.async_get_failed(f"Querying {self.serial} at {self.address}:{self.port} failed. [{format_exception(e)}]")
  File "/config/custom_components/solarman/api.py", line 164, in async_get_failed
    await self.async_disconnect()
  File "/config/custom_components/solarman/api.py", line 114, in async_disconnect
    await self.writer.wait_closed()
  File "/usr/local/lib/python3.12/asyncio/streams.py", line 364, in wait_closed
    await self._protocol._get_close_waiter(self)
OSError: [Errno 113] Host is unreachable
2024-07-17 23:21:42.075 DEBUG (MainThread) [custom_components.solarman.coordinator] Finished fetching Solarman data in 29.107 seconds (success: False)
2024-07-17 23:21:46.857 DEBUG (MainThread) [custom_components.solarman.parser] Default update_interval: 60, min_span: 25, digits: 6
2024-07-17 23:21:46.857 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #-5
2024-07-17 23:21:46.857 DEBUG (MainThread) [custom_components.solarman.api] Querying (1028 - 1070) ...
2024-07-17 23:21:46.857 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: True, cancelled: False.
davidrapan commented 1 month ago

Great! So it looks like I was able to successfully catch and filter out the Errno 113.

So I guess we could make them completely silent...

Thanks for your help and I let you know when it will be ready. ;)

davidrapan commented 1 month ago

Hi @Floppe so I just committed prob final changes regarding "our issue" so could you maybe update the integration and go through the debug logging with me once more again so I can check the flow?

This latest version should quiet the logging! (With debug disabled of course)

If there won't be any other issues consider this matter as done!

Have fun!

gedger commented 1 month ago

I have been watching this issue with interest as I have the same problem with a Solis Inverter. My current solution is to stop the integration polling and instead do it from an automation that starts after sunrise and stops at sunset. Would an improved solution be to have an option in the configuration to "only poll during daylight"? As far as I'm aware all solar inverters shut down at night unless they are a hybrid version with an attached battery.

Floppe commented 1 month ago

Tested and it does not log, so that's good. But it did not connect after sunrise. Could it be because I restarted after sunset. 🤔

All sensors are now unavailable.

davidrapan commented 1 month ago

I have been watching this issue with interest as I have the same problem with a Solis Inverter. My current solution is to stop the integration polling and instead do it from an automation that starts after sunrise and stops at sunset. Would an improved solution be to have an option in the configuration to "only poll during daylight"? As far as I'm aware all solar inverters shut down at night unless they are a hybrid version with an attached battery.

That is really good idea! I look into it!

davidrapan commented 1 month ago

Tested and it does not log, so that's good. But it did not connect after sunrise. Could it be because I restarted after sunset. 🤔

All sensors are now unavailable.

And what if you enable debug log? And let it run "over night" how does the log look like in the morning?

szyx22 commented 1 month ago

There is a big problem with this addon, my HA cpu usage normaly is under 1%, cpu usage growing up to 10% from sunset to midnight, central europe (21:00 to 00:00 3 hours). Sofar Solar with LSW3. Debug log size about 490 MB and a milions of lines...

solar
davidrapan commented 1 month ago

Okay but what it logs though? What does the log look like? There is a possibility that it does not behave correctly when is the inverter offline. Are you turning off the inverter?

Floppe commented 1 month ago

Tested and it does not log, so that's good. But it did not connect after sunrise. Could it be because I restarted after sunset. 🤔

All sensors are now unavailable.

And what if you enable debug log? And let it run "over night" how does the log look like in the morning?

Enabled debug and let it run over night. This time it worked/started after the inverter came online. The only difference now is that debugging is enabled and I restarted while the inverter was online.

szyx22 commented 1 month ago

No I am not turning off my inverter, it do automaticly turn off after sunset like a lot of other inverter models. I think addon should be prepared for that situation. "Turn off addon after sunset" it is not resolving issue. Maybe ping command to check inverter availability? . Error logs are the same as up

davidrapan commented 1 month ago

Tested and it does not log, so that's good. But it did not connect after sunrise. Could it be because I restarted after sunset. 🤔 All sensors are now unavailable.

And what if you enable debug log? And let it run "over night" how does the log look like in the morning?

Enabled debug and let it run over night. This time it worked/started after the inverter came online. The only difference now is that debugging is enabled and I restarted while the inverter was online.

Try it one more time then. But without touching the inverter if possible...

Debug enabled/disable should really don't have any impact on the inner workings it just simply show some more massages in the flow along the way I don't do there any flow changes based on debugging...

davidrapan commented 1 month ago

No I am not turning off my inverter, it do automaticly turn off after sunset like a lot of other inverter models. I think addon should be prepared for that situation. "Turn off addon after sunset" it is not resolving issue. Maybe ping command to check inverter availability? . Error logs are the same as up

I was asking in general if you inverter runs over night or not.

So it does not okay.

My inverter never goes offline, cause I'm charging batteries in off-peak hours and so. So this integration is mainly written to work in that scenario.

You said that your log increased in size during night and now are you saying that it has the same messages as during the day? I don't follow...

If you want to resolve any issues you have to be more specific (provide logs, or better provide debug logs). Just by simply stating: "It does not work, fix it." Does not help at all and my hands are tied.

Adapting flow based on ping would be really bad Idea cause some are connecting to the inverters trough the WAN and there is not guaranteed that ping would be allowed.

Btw I don't think the increased CPU load is caused by this integration. When i turn off the inverter. It does not happen. But I can be mistaken. That's why is crucial that you provide more info. :-)

Cheers!

Floppe commented 1 month ago

Tested and it does not log, so that's good. But it did not connect after sunrise. Could it be because I restarted after sunset. 🤔 All sensors are now unavailable.

And what if you enable debug log? And let it run "over night" how does the log look like in the morning?

Enabled debug and let it run over night. This time it worked/started after the inverter came online. The only difference now is that debugging is enabled and I restarted while the inverter was online.

Try it one more time then. But without touching the inverter if possible...

Debug enabled/disable should really don't have any impact on the inner workings it just simply show some more massages in the flow along the way I don't do there any flow changes based on debugging...

If I recall correctly this happened once before also with the original version. So I guess it's not related to this issue that silences the logging.

davidrapan commented 1 month ago

Yeah sure I was just wondering if this changes did not somehow broke the "coming up" after night off. Cause what could happen is that logging of the messages can slow down that reconnecting intervals and thus without logging them the integration could just do it more frequently. But that's just shooting in the dark again.

I'll try playing with turning off the inverter tonight and I'll see what comes from it.

szyx22 commented 1 month ago

Yes good. So installed this addon again. First night was everything good with cpu usage. Second night, today, cpu again growing up, few minutes log is huge. Graph cpu usage with this addon and next few minutes with uninstaled addon.

cpu2

File "/config/custom_components/solarman/api.py", line 64, in _send_receive_v5_frame await self.writer.drain() File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain raise exc File "/config/custom_components/solarman/api.py", line 181, in async_get await self.async_read(params, code, start, end) File "/config/custom_components/solarman/api.py", line 116, in async_read response = await self.read_holding_registers(register_addr = start, quantity = length) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 283, in read_holding_registers modbus_values = await self._get_modbus_response(mb_request_frame) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 246, in _get_modbus_response mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/pysolarmanv5/pysolarmanv5_async.py", line 233, in _send_receive_modbus_frame v5_response_frame = await self._send_receive_v5_frame(v5_request_frame) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solarman/api.py", line 64, in _send_receive_v5_frame await self.writer.drain() File "/usr/local/lib/python3.12/asyncio/streams.py", line 380, in drain raise exc File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 312, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solarman/coordinator.py", line 33, in _async_update_data return await self.inverter.async_get(self._accounting()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solarman/api.py", line 207, in async_get await self.async_get_failed(f"Querying {self.serial} at {self.address}:{self.port} failed. [{format_exception(e)}]") File "/config/custom_components/solarman/api.py", line 155, in async_get_failed await self.async_disconnect() File "/config/custom_components/solarman/api.py", line 107, in async_disconnect await self.writer.wait_closed() File "/usr/local/lib/python3.12/asyncio/streams.py", line 364, in wait_closed await self._protocol._get_close_waiter(self) OSError: [Errno 113] Host is unreachable 2024-07-22 22:15:03.766 WARNING (MainThread) [custom_components.solarman.api] Querying (0 - 39) failed. #0 [OSError: [Errno 113] Host is unreachable]

davidrapan commented 1 month ago

I will really need whole log with debug enabled (It can even be just enabled when this happens for few minutes not whole time) cause I'm really not able to replicate it in my setup.

Don't forget to obfuscate serial number.

Edit: Did you installed it manually or through HACS?

Cheers!

Floppe commented 1 month ago

For my part it has worked really great now. It has connected again two mornings in a row. So I still have no debug logs when it fails in the morning.

gedger commented 1 month ago

The more I think about this the more I believe this is not the way to go. Suppressing warnings/errors is never a good idea as when an inverter is off-line with a genuine problem then it will be masked. There is no way of knowing whether an inverter is down because of a fault or because it's turned off. Either way a fault log should be raised.

Can I suggest a much easier and cleaner way to achieve this and that is to provide a control input to the integration. This is a simple run/stop control that can then be used by a HA automation to stop the inverter at sunset and then start at sunrise. An automation to trigger at sunrise and sunset is extremely simple to do.

davidrapan commented 1 month ago

The more I think about this the more I believe this is not the way to go. Suppressing warnings/errors is never a good idea as when an inverter is off-line with a genuine problem then it will be masked. There is no way of knowing whether an inverter is down because of a fault or because it's turned off. Either way a fault log should be raised.

Can I suggest a much easier and cleaner way to achieve this and that is to provide a control input to the integration. This is a simple run/stop control that can then be used by a HA automation to stop the inverter at sunset and then start at sunrise. An automation to trigger at sunrise and sunset is extremely simple to do.

Yeah the thing is I don't know about simple way how to accomplish this.. Even HA itself does not have feature like this. You just simply can't turn integration on/off on demand...

davidrapan commented 1 month ago

And I'm not really hiding it. I'm just masking it as a TimeoutError which should in theory raise but not so much.

davidrapan commented 1 month ago

For my part it has worked really great now. It has connected again two mornings in a row. So I still have no debug logs when it fails in the morning.

No worries, just post it here when it happens. ;)

gedger commented 1 month ago

Yeah the thing is I don't know about simple way how to accomplish this.. Even HA itself does not have feature like this. You just simply can't turn integration on/off on demand...

Fair do's. The Home Assistant recorder allows you enable disable recording via a service call. I also have an integration that allows you to change the polling interval from a service call, but have no idea how. If I find anything that looks useful I'll share the code.

I could also go back to my previous way of working with Stephans integration, we'll see how it goes.

https://www.home-assistant.io/common-tasks/general/

section: Defining a custom polling interval

davidrapan commented 1 month ago

Yeah the thing is I don't know about simple way how to accomplish this.. Even HA itself does not have feature like this. You just simply can't turn integration on/off on demand...

Fair do's. The Home Assistant recorder allows you enable disable recording via a service call. I also have an integration that allows you to change the polling interval from a service call, but have no idea how. If I find anything that looks useful I'll share the code.

I could also go back to my previous way of working with Stephans integration, we'll see how it goes.

https://www.home-assistant.io/common-tasks/general/

section: Defining a custom polling interval

Yes I know about this one but if I understand it correctly this just tweaks it from HA side into DataUpdateCoordinator.data which is filled by polling interval defined in the integration.

So in short It doesn't change how often it tries to connect to the inverter.

But maybe I'm wrong...

I could try to add some conditional polling mechanism but I'm just worried that it would just overcomplicate things and only bring more issues...

Edit: lol so maybe it does turn off the polling completely, hah. I just tried it and was able to turn off the integration by that toggle. But I would promise that it did not work like that before, huh. So if is possible to toggle that polling from an automation it should be theoretically possible to turn the integration "off" like that.

Floppe commented 1 month ago

For my part it has worked really great now. It has connected again two mornings in a row. So I still have no debug logs when it fails in the morning.

No worries, just post it here when it happens. ;)

One thing though. The "Connection status" sensor says it is connected 3 days now, which is not true!

And all other sensors freezes, but should really be unavailable.

davidrapan commented 1 month ago

For my part it has worked really great now. It has connected again two mornings in a row. So I still have no debug logs when it fails in the morning.

No worries, just post it here when it happens. ;)

One thing though. The "Connection status" sensor says it is connected 3 days now, which is not true!

And all other sensors freezes, but should really be unavailable.

Hmm that's bad! Could you maybe post log from a time when inverter goes offline? (a debug one)

A fifth TimeoutError should switch the integration into disconnected state. If that does not happen that's a bug then.

It would be really awesome if I could just try this whole flow with my installation but it just behaves for some reason so differently!

Don't forget to obfuscate!

gedger commented 1 month ago

When the inverter is offline my logs are filled continuously with warning messages.

Edit from @davidrapan: Removed the log cause of an exposed serial. :P

davidrapan commented 1 month ago

And what about connection state?

Edit: Also how does the log look like without debug enabled?

gedger commented 1 month ago

I'll grab a log when it goes offline tonight.

gedger commented 1 month ago

Here we go, rather a lot of logging....

home-assistant_2024-07-24T21-03-15.464Z.log

davidrapan commented 1 month ago

Mh, I'm really not sure what can be done with this one as it originates from [asyncio] 😞

gedger commented 1 month ago

It also failed to make the connection when the inverter came back on line. I had to reload the config to get it to connect. Overnight there were quite a few logs.....

This error originated from a custom integration. Logger: asyncio Source: custom_components/solarman/api.py:63 integration: Solarman (documentation, issues) First occurred: 24 July 2024 at 21:34:30 (4911 occurrences) Last logged: 07:07:20 socket.send() raised exception.

gedger commented 1 month ago

A possible temporary work around for this is to install the Frenck integration Spook. This provides several useful advanced service calls including the ability to enable/disable the polling for an integration. I'm testing this and will report back. I'll also try and increase my knowledge of the HA integrations to see if/how this functionality could be built into the integration.

Note: the config_entry_id for Solarman is found for your system when you build the automation using the GUI so don't copy this code verbatim.

alias: PV - Control Polling
description: Enables inverter polling after sunrise
trigger:
  - platform: sun
    event: sunrise
  - platform: sun
    event: sunset
  - platform: homeassistant
    event: start
condition: []
action:
  - if:
      - condition: sun
        after: sunset
        after_offset: "-00:01:00"
    then:
      - service: homeassistant.disable_polling
        data:
          config_entry_id: 8e29598c8e01390f2cf499a1eca7443a
    else:
      - service: homeassistant.enable_polling
        data:
          config_entry_id: 8e29598c8e01390f2cf499a1eca7443a
mode: single
davidrapan commented 1 month ago

It just baffles me how on four installations it behaves in four different ways...

And the important part is Logger: asyncio, that mens it logs directly into log outside of my reach. The only way how to prevent it is to not trigger that exception I think...

I was some time ago making some PR into pysolarmanv5 lib we are using here so I can get rid of the changes I do in this integration. So will see when they release new version and I will be able to remove those forced changes!

gedger commented 1 month ago

I can only assume that each inverter goes offline in a different way? I know my Solis keeps working for a good while once generation has stopped by using grid power before it finally decides to go to sleep. It may be that in that state you can make a connection but it doesn’t respond to modbus/solarman?

gedger commented 1 month ago

Not sure if this is worth a look? https://github.com/StephanJoubert/home_assistant_solarman/pull/535

davidrapan commented 1 month ago

That's basically what I did. Logging suppression. But Stephan is using synchronous flow so very different approach and sadly it won't help in any way in our asynchronous implementation. As the "socket.send() raised exception" exception comes from asyncio library which is not present in Stephans integration.

davidrapan commented 1 month ago

It also failed to make the connection when the inverter came back on line. I had to reload the config to get it to connect. Overnight there were quite a few logs.....

This error originated from a custom integration. Logger: asyncio Source: custom_components/solarman/api.py:63 integration: Solarman (documentation, issues) First occurred: 24 July 2024 at 21:34:30 (4911 occurrences) Last logged: 07:07:20 socket.send() raised exception.

Does it also stop writing into logs then? Cause it would not make any sense otherwise...

gedger commented 1 month ago

No, still writing into the logs but didn't pick up that the inverter was on-line 😕

To be honest there's been several changes to my system over the last few days so I need to let it run for a few days and get a true picture of what's happening. The inverter going off-line also generates a problem if HA is restarted when it's dark as the integration can't initialise and fails, no idea whether it will recover from this when the inverter comes back on-line? It's hard to test when you only have one shutdown event per day...

davidrapan commented 1 month ago

No, still writing into the logs but didn't pick up that the inverter was on-line 😕

That is really strange... cause according to the logs it follows the proper flow of disconnecting and reconnecting... It's not like it's stuck or something... can you maybe try to also look at what wireshark shows during that time? If it sends packets?

It's hard to test when you only have one shutdown event per day...

Yeah exactly. It's the same with trying to guess how to mitigate this by shooting in the dark as I really don't know how to test this scenarios... My inverter runs 24/7 and every try to turn it off or even just interfere with the connection behaves very differently than what you guys describing :(

One of my latest attempts to help you guys out was to add clearing of the variables handling the reading and writing into the socket cause I thought that maybe because they are still holding an instances after disconnect flow and consecutive try to connect fails then maybe the socket.send() exception was cause of that... But it is yet another shot in the dark...

gedger commented 1 month ago

My automation failed to work. It successfully turned off polling and no errors reported however, when polling was enabled in the morning it failed to get a data although did seem to start trying to reconnect. Reloading the integration immediately connected and restored the data flow...

Polling was enabled at 5:07 and debug turned on for a bit from 7.29....

home-assistant_solarman_2024-07-27T06-30-42.075Z.log

PS. I'm also debugging another integration so ignore the other errors...

davidrapan commented 1 month ago

Okay now there is obvious it's not trying to connect back again after disconnect and sure it can't work like that...

Edit2: No that was wrong, there is just simply not enough of the log cause you have longer interval...

BTW nice pic

Edit: Also can you check for me if new diag sensor Update Interval shows you the true and correct interval?

Edit3: Can you update to yesterday pre-release version? There are some changes in the flow which could result at least in better understanding of the matter....

Cheers!

gedger commented 1 month ago

I have updated to latest version and the Update_Interval is now correct at around 30 secs before it recording 5-6 secs. I'll capture more log tomorrow morning if it has the same issue as I won't be dashing out....Will report back.

gedger commented 1 month ago

Whoops seems to be a coding issue. You can replicate by going to system options and disable polling. Needed a reboot to recover.

home-assistant_solarman_2024-07-28T06-00-49.451Z.log