Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

USB to RS485 adapter issues? #10

Closed
reedy opened this issue Feb 3, 2022 · 26 comments
Closed

USB to RS485 adapter issues? #10

reedy opened this issue Feb 3, 2022 · 26 comments

Comments

@reedy
Copy link
Contributor

reedy commented Feb 3, 2022 •
edited

Issue related to
[ ] New Sensors / Sensors not working (existing definitions available here)
[x] Sunsynk Home Assistant Add-On
[ ] mbusd Home Assistant Add-On
[ ] Python sunsynk library

Describe the issue/bug
Not so much a bug (necessarily), but I guess a support request.

Recently had a Sunsynk 3.6 kWh inverter installed.

I bought one of https://www.ebay.co.uk/itm/393575748700 "RS485-150U" hoping it would work (being premade), but when starting the addon it seems to timeout.

I don't know if it's due to the wrong pinout on the RJ45 end, but I did try /dev/ttyACM0, /dev/ttyAMA0 and /dev/serial1; all of which failed similarly.

I have plugged it into the BMS485 (top left) port; it seems for a lot of things the 5.5 and 3.6 are similar.

Got a different adapter coming tomorrow from Amazon - https://smile.amazon.co.uk/dp/B06Y1JTGZX which will make it easier to make sure the pinout is right, so this request might be invalid at that point...

Trying to avoid having to shell out for one of https://solar-assistant.io/shop/products/sunsynk_rs485

Happy to try a few other things (and/or doing this outside Home Assistant.. On a vanilla Ubunutu/Raspberry Pi OS/Debian rpi install), such as the library as a standalone if it helps.

Thanks!

Expected behavior
Not crash on startup? :)

Home Assistant version (if applicable)
2022.2.0

Additional context
Add any other context about the problem here.

Logs

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] done.
[services.d] starting services
[services.d] done.
2022-02-03 18:20:43,458 INFO    Loading HASS OS configuration
2022-02-03 18:20:43,460 INFO    Filter *last used for ['total_pv_power', 'total_battery_charge', 'total_battery_discharge', 'total_grid_export', 'total_grid_import']
2022-02-03 18:20:43,460 INFO    Filter *step used for ['battery_soc']
2022-02-03 18:20:43,469 INFO    Protocol made connection.
2022-02-03 18:20:43,470 INFO    Connected to /dev/serial1
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/src/app/./run.py", line 185, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/src/app/./run.py", line 146, in main
    await SUNSYNK.read([ssdefs.serial])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 100, in read
    r_r = await self.client.read_holding_registers(grp[0], glen, unit=self.unit)
  File "/usr/local/lib/python3.9/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
[cmd] ./run.py exited 1
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
@dirkackerman
Copy link
Contributor

dirkackerman commented Feb 3, 2022 •
edited

I had simular output here.

Check your connections and make sure you are using the correct device in linux. I believe USB to serial converters should generally be /dev/ttyUSBx in most distros. Maybe unplug the device and reconnect it and compare the ls /dev output to see the added device's name?

@reedy
Copy link
Contributor Author

reedy commented Feb 3, 2022 •
edited

Thanks for the reply. The dev entry is definitely /dev/ttyACM0 for it.

Screenshot 2022-02-03 at 18 24 42

^ is from Home Assistant. Using a vanilla RasberryPI OS image adding/removing tht USB cable makes /dev/ttyACM0 remove and disappear.

So it's definitely the "correct" logical device, but I'm not sure the USB device is completely correct for this purpose. The fact it's AMA (from a bit of Googling) suggests it might not be a serial console like I'm thinking it is (it was a punt based on availability on ebay) - https://arduino.stackexchange.com/questions/19648/difference-between-dev-ttyacm0-and-dev-ttys0-arduino-ide-ports-under-linux

/dev/ttyACM0 is a USB communication device (CDC) of sub-type "abstract control model" (ACM). That is what the Arduino is.

Which probably means I should stop wasting time on it :). Especially as what should be the right device should be here tomorrow. At what it cost, it's probably not even worth bothering to return with the cost of the return postage...

Will follow up again tomorrow when the delivery person has been!

@reedy
Copy link
Contributor Author

reedy commented Feb 3, 2022

I guess at this point, my only feedback might this part of the code might benefit from a bit better error handling. Trap it and show a better error message, before showing the stack trace anyway

@kellerza
Copy link
Owner

kellerza commented Feb 4, 2022

Will improve that error if it fails on reading the serial number!

@kellerza kellerza closed this as completed Feb 4, 2022
@reedy
Copy link
Contributor Author

reedy commented Feb 4, 2022

Yay, so with https://smile.amazon.co.uk/dp/B06Y1JTGZX and me making up a new (longer) cable.. it works!

Just need to try and work out the dashboards/sensors now (I'm new to HA too)...

@reedy
Copy link
Contributor Author

reedy commented Feb 4, 2022

Seem to be having similar issues to #13 even only with 1 or 2 sensors

PORT: /dev/ttyUSB0
PORT_ADDRESS: ''
SUNSYNK_ID: '210615XXXX'
SENSORS:
  - battery_voltage
  - battery_soc
SENSOR_PREFIX: Sunsynk
TIMEOUT: 10
MQTT_HOST: core-mosquitto
MQTT_PORT: 1883
MQTT_USERNAME: mqtt
MQTT_PASSWORD: redacted
DEBUG: 0

And then the logs...

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] done.
[services.d] starting services
[services.d] done.
2022-02-04 17:28:56,880 INFO    Loading HASS OS configuration
2022-02-04 17:28:56,881 INFO    Filter *step used for ['battery_voltage', 'battery_soc']
2022-02-04 17:28:56,896 INFO    Protocol made connection.
2022-02-04 17:28:56,899 INFO    Connected to /dev/ttyUSB0
2022-02-04 17:28:56,955 INFO    ############################################################
2022-02-04 17:28:56,956 INFO                   SMA serial number '210615XXXX'
2022-02-04 17:28:56,957 INFO    ############################################################
2022-02-04 17:28:56,975 INFO    MQTT: Connection successful
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/src/app/./run.py", line 185, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/src/app/./run.py", line 156, in main
    await SUNSYNK.read([f.sensor for f in SENSORS])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 100, in read
    r_r = await self.client.read_holding_registers(grp[0], glen, unit=self.unit)
  File "/usr/local/lib/python3.9/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
[cmd] ./run.py exited 1
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.

@reedy reedy mentioned this issue Feb 5, 2022
Merged
@reedy
Copy link
Contributor Author

reedy commented Feb 6, 2022

Same on 2022.02.05-0.1.0...

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] done.
[services.d] starting services
[services.d] done.
2022-02-06 13:29:37,754 INFO    Loading HASS OS configuration
2022-02-06 13:29:37,756 INFO    Filter *step used for ['battery_voltage']
2022-02-06 13:29:37,756 INFO    Filter *last used for ['battery_soc']
2022-02-06 13:29:37,764 INFO    Protocol made connection.
2022-02-06 13:29:37,764 INFO    Connected to /dev/ttyUSB0
2022-02-06 13:29:37,817 INFO    ############################################################
2022-02-06 13:29:37,818 INFO                Inverter serial number '210615XXXX'
2022-02-06 13:29:37,818 INFO    ############################################################
2022-02-06 13:29:37,856 INFO    MQTT: Connection successful
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/src/app/./run.py", line 204, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/src/app/./run.py", line 170, in main
    await SUNSYNK.read([f.sensor for f in SENSORS])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 100, in read
    r_r = await self.client.read_holding_registers(
  File "/usr/local/lib/python3.9/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
[cmd] ./run.py exited 1
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

And after dea9864

2022-02-08 01:26:05,458 INFO    MQTT: Connection successful
2022-02-08 01:26:26,475 ERROR   Timeout on initial read. Sensors: ['Battery voltage:step:mean', 'Battery SOC:last']
2022-02-08 01:26:46,551 ERROR   Timeout reading single sensor: Battery SOC:last
2022-02-08 01:27:08,586 ERROR   TimeOut 
2022-02-08 01:27:29,611 ERROR   TimeOut 
2022-02-08 01:27:56,654 ERROR   TimeOut 
2022-02-08 01:28:17,679 ERROR   TimeOut

Think I need to turn up the debug settings

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

With DEBUG: 2

During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 659, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 363, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 178, in main
    await SUNSYNK.read([fil.sensor])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Battery SOC', 46, 0, None, '%')
2022-02-08 01:31:33,290 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/battery_voltage, 52.08
2022-02-08 01:31:33,295 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/battery_soc, 46
2022-02-08 01:31:33,300 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x2 0x74 0x2d
2022-02-08 01:31:33,301 DEBUG   Adding transaction 1
2022-02-08 01:31:33,348 DEBUG   recv: 0x1 0x3 0x4 0x14 0x58 0x0 0x2e 0xfe 0xc
2022-02-08 01:31:33,348 DEBUG   Getting Frame - 0x3 0x4 0x14 0x58 0x0 0x2e
2022-02-08 01:31:33,349 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:31:33,349 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:31:33,349 DEBUG   Getting transaction 1
2022-02-08 01:31:33,351 DEBUG   Request registers: [183, 184] glen=2. Response [5208, 46] len=2. regs={183: 5208, 184: 46}
2022-02-08 01:31:33,351 DEBUG   Battery voltage low=5208 high=0 value=52V
2022-02-08 01:31:33,352 DEBUG   Battery SOC low=46 high=0 value=46%
2022-02-08 01:31:33,352 DEBUG   Battery SOC:last over 1 samples = 46
2022-02-08 01:31:33,352 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/battery_soc, 46
2022-02-08 01:31:34,307 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:31:34,310 DEBUG   Adding transaction 1
2022-02-08 01:31:34,356 DEBUG   recv: 0x40 0x20 0x20 0x11 0x65 0xf3 0xff
2022-02-08 01:31:34,357 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:31:34,358 DEBUG   Resetting frame - Current Frame in buffer - 0x40 0x20 0x20 0x11 0x65 0xf3 0xff
2022-02-08 01:31:54,335 ERROR   TimeOut 
2022-02-08 01:31:54,339 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:31:54,341 DEBUG   Adding transaction 1
2022-02-08 01:31:54,384 DEBUG   recv: 0x1 0x3 0x2 0x14 0x59 0x77 0x7e
2022-02-08 01:31:54,385 DEBUG   Getting Frame - 0x3 0x2 0x14 0x59
2022-02-08 01:31:54,385 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:31:54,387 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:31:54,387 DEBUG   Getting transaction 1
2022-02-08 01:31:54,390 DEBUG   Request registers: [183] glen=1. Response [5209] len=1. regs={183: 5209}
2022-02-08 01:31:54,390 DEBUG   Battery voltage low=5209 high=0 value=52V
2022-02-08 01:31:55,345 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:31:55,347 DEBUG   Adding transaction 1
2022-02-08 01:31:55,394 DEBUG   recv: 0x1 0x3 0x2 0x14 0x59 0x77 0x7e
2022-02-08 01:31:55,395 DEBUG   Getting Frame - 0x3 0x2 0x14 0x59
2022-02-08 01:31:55,396 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:31:55,396 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:31:55,397 DEBUG   Getting transaction 1
2022-02-08 01:31:55,399 DEBUG   Request registers: [183] glen=1. Response [5209] len=1. regs={183: 5209}
2022-02-08 01:31:55,400 DEBUG   Battery voltage low=5209 high=0 value=52V
2022-02-08 01:31:56,351 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:31:56,353 DEBUG   Adding transaction 1
2022-02-08 01:31:56,405 DEBUG   recv: 0x40 0x20 0x20 0x11 0x65 0xf3 0xff
2022-02-08 01:31:56,406 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:31:56,406 DEBUG   Resetting frame - Current Frame in buffer - 0x40 0x20 0x20 0x11 0x65 0xf3 0xff
2022-02-08 01:32:16,378 ERROR   TimeOut 
2022-02-08 01:32:16,382 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:32:16,385 DEBUG   Adding transaction 1
2022-02-08 01:32:16,433 DEBUG   recv: 0x1 0x3 0x2 0x14 0x59 0x77 0x7e
2022-02-08 01:32:16,434 DEBUG   Getting Frame - 0x3 0x2 0x14 0x59
2022-02-08 01:32:16,434 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:32:16,435 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:32:16,436 DEBUG   Getting transaction 1
2022-02-08 01:32:16,438 DEBUG   Request registers: [183] glen=1. Response [5209] len=1. regs={183: 5209}
2022-02-08 01:32:16,439 DEBUG   Battery voltage low=5209 high=0 value=52V
2022-02-08 01:32:17,386 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:32:17,388 DEBUG   Adding transaction 1
2022-02-08 01:32:17,433 DEBUG   recv: 0x1 0x3 0x2 0x14 0x59 0x77 0x7e
2022-02-08 01:32:17,434 DEBUG   Getting Frame - 0x3 0x2 0x14 0x59
2022-02-08 01:32:17,434 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:32:17,435 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:32:17,435 DEBUG   Getting transaction 1
2022-02-08 01:32:17,438 DEBUG   Request registers: [183] glen=1. Response [5209] len=1. regs={183: 5209}
2022-02-08 01:32:17,438 DEBUG   Battery voltage low=5209 high=0 value=52V
2022-02-08 01:32:18,392 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:32:18,394 DEBUG   Adding transaction 1
2022-02-08 01:32:18,444 DEBUG   recv: 0x20 0x20 0x20 0x51 0x75 0xf9 0xff
2022-02-08 01:32:18,445 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:32:18,445 DEBUG   Resetting frame - Current Frame in buffer - 0x20 0x20 0x20 0x51 0x75 0xf9 0xff

Ok... So with DEBUG enabled, things work?

This is obviously good, but a bit strange... Some race type conditions, and debug mode helps there?

Screenshot 2022-02-08 at 01 34 33

Any ideas @kellerza? :)

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Logs get truncated quite quickly..

2022-02-08 01:37:35,692 DEBUG   send: 0x1 0x3 0x0 0x3 0x0 0x5 0x75 0xc9
2022-02-08 01:37:35,694 DEBUG   Adding transaction 1
2022-02-08 01:37:35,746 DEBUG   recv: 0x1 0x3 0xa 0x32 0x31 0x30 0x36 0x31 0x35 0x34 0x32 0x37 0x37 0xf9 0x39 0xff
2022-02-08 01:37:35,748 DEBUG   Getting Frame - 0x3 0xa 0x32 0x31 0x30 0x36 0x31 0x35 0x34 0x32 0x37 0x37
2022-02-08 01:37:35,749 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:37:35,750 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:37:35,751 DEBUG   Getting transaction 1
2022-02-08 01:37:35,754 DEBUG   Request registers: [3, 4, 5, 6, 7] glen=5. Response [12849, 12342, 12597, 13362, 14135] len=5. regs={3: 12849, 4: 12342, 5: 12597, 6: 13362, 7: 14135}
2022-02-08 01:37:35,755 INFO    ############################################################
2022-02-08 01:37:35,755 INFO                Inverter serial number '210615XXXX'
2022-02-08 01:37:35,756 INFO    ############################################################
2022-02-08 01:37:35,789 INFO    MQTT: Connection successful
2022-02-08 01:37:36,264 DEBUG   PUBLISH 1R SUNSYNK/status/210615XXXX/availability, online
2022-02-08 01:37:36,276 DEBUG   publish homeassistant/sensor/210615XXXX/total_pv_power/config
2022-02-08 01:37:36,277 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/total_pv_power/config, {"unique_id": "210615XXXX_total_pv_power", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/total_pv_power", "name": "Sunsynk Total PV Power", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "energy", "unit_of_measurement": "kWh", "state_class": "total_increasing"}
2022-02-08 01:37:36,283 DEBUG   publish homeassistant/sensor/210615XXXX/total_battery_charge/config
2022-02-08 01:37:36,284 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/total_battery_charge/config, {"unique_id": "210615XXXX_total_battery_charge", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/total_battery_charge", "name": "Sunsynk Total Battery Charge", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "energy", "unit_of_measurement": "kWh", "state_class": "total_increasing"}
2022-02-08 01:37:36,288 DEBUG   publish homeassistant/sensor/210615XXXX/total_battery_discharge/config
2022-02-08 01:37:36,289 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/total_battery_discharge/config, {"unique_id": "210615XXXX_total_battery_discharge", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/total_battery_discharge", "name": "Sunsynk Total Battery Discharge", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "energy", "unit_of_measurement": "kWh", "state_class": "total_increasing"}
2022-02-08 01:37:36,293 DEBUG   Rx retained msg: topic=homeassistant/sensor/210615XXXX/battery_soc/config -- device=210615XXXX
2022-02-08 01:37:36,293 DEBUG   Rx retained msg: topic=homeassistant/sensor/210615XXXX/battery_voltage/config -- device=210615XXXX
2022-02-08 01:37:36,294 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/battery_voltage/config
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/threading.py", line 954, in _bootstrap_inner
2022-02-08 01:37:36,308 DEBUG   publish homeassistant/sensor/210615XXXX/total_grid_export/config
2022-02-08 01:37:36,309 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/total_grid_export/config, {"unique_id": "210615XXXX_total_grid_export", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/total_grid_export", "name": "Sunsynk Total Grid Export", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "energy", "unit_of_measurement": "kWh", "state_class": "total_increasing"}
    self.run()
  File "/usr/local/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3452, in _thread_main
2022-02-08 01:37:36,318 DEBUG   publish homeassistant/sensor/210615XXXX/total_grid_import/config
2022-02-08 01:37:36,319 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/total_grid_import/config, {"unique_id": "210615XXXX_total_grid_import", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/total_grid_import", "name": "Sunsynk Total Grid Import", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "energy", "unit_of_measurement": "kWh", "state_class": "total_increasing"}
    self.loop_forever(retry_first_connection=True)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1779, in loop_forever
    rc = self.loop(timeout, max_packets)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1181, in loop
2022-02-08 01:37:36,329 DEBUG   publish homeassistant/sensor/210615XXXX/battery_soc/config
2022-02-08 01:37:36,330 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/battery_soc/config, {"unique_id": "210615XXXX_battery_soc", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/battery_soc", "name": "Sunsynk Battery SOC", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "battery", "unit_of_measurement": "%"}
    rc = self.loop_read(max_packets)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1572, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2310, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2936, in _packet_handle
    return self._handle_publish()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3216, in _handle_publish
2022-02-08 01:37:36,342 DEBUG   publish homeassistant/select/210615XXXX/system_mode/config
2022-02-08 01:37:36,344 DEBUG   PUBLISH 1R homeassistant/select/210615XXXX/system_mode/config, {"unique_id": "210615XXXX_system_mode", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/system_mode", "name": "Sunsynk System Mode", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "command_topic": "SUNSYNK/status/210615XXXX/system_mode_set", "options": ["UPDATE"]}
2022-02-08 01:37:36,351 DEBUG   publish homeassistant/select/210615XXXX/system_mode_voltages/config
    self._handle_on_message(message)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3444, in _handle_on_message
2022-02-08 01:37:36,353 DEBUG   PUBLISH 1R homeassistant/select/210615XXXX/system_mode_voltages/config, {"unique_id": "210615XXXX_system_mode_voltages", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/system_mode_voltages", "name": "Sunsynk System Mode Voltages", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "command_topic": "SUNSYNK/status/210615XXXX/system_mode_voltages_set", "options": ["UPDATE"]}
    self.on_message(self, self._userdata, message)
  File "/usr/src/app/mqtt.py", line 246, in __on_message
    _loop.create_task(self.publish(topic, None, retain=True))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 433, in create_task
    task = tasks.Task(coro, loop=self, name=name)
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 748, in call_soon
    self._check_thread()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 785, in _check_thread
    raise RuntimeError(
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one
2022-02-08 01:37:36,364 ERROR   Task was destroyed but it is pending!
source_traceback: Object created at (most recent call last):
  File "/usr/local/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3452, in _thread_main
    self.loop_forever(retry_first_connection=True)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1779, in loop_forever
    rc = self.loop(timeout, max_packets)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1181, in loop
    rc = self.loop_read(max_packets)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 1572, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2310, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 2936, in _packet_handle
    return self._handle_publish()
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3216, in _handle_publish
    self._handle_on_message(message)
  File "/usr/local/lib/python3.9/site-packages/paho/mqtt/client.py", line 3444, in _handle_on_message
    self.on_message(self, self._userdata, message)
  File "/usr/src/app/mqtt.py", line 246, in __on_message
    _loop.create_task(self.publish(topic, None, retain=True))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 433, in create_task
    task = tasks.Task(coro, loop=self, name=name)
task: <Task pending name='Task-3' coro=<MQTTClient.publish() running at /usr/src/app/mqtt.py:186> created at /usr/local/lib/python3.9/asyncio/base_events.py:433>
/usr/local/lib/python3.9/threading.py:956: RuntimeWarning: coroutine 'MQTTClient.publish' was never awaited
  self._invoke_excepthook(self)
RuntimeWarning: Enable tracemalloc to get the object allocation traceback
2022-02-08 01:37:36,796 DEBUG   send: 0x1 0x3 0x0 0x48 0x0 0xb 0x84 0x1b
2022-02-08 01:37:36,799 DEBUG   Adding transaction 1
2022-02-08 01:37:36,869 DEBUG   recv: 0x1 0x3 0x16 0x3 0x4b 0x0 0x0 0x2 0xab 0x0 0x0 0x0 0x0 0x0 0x0 0x3 0x4 0x13 0x8b 0x0 0x0 0x0 0x6a 0x0 0x0 0x11 0xa3 0xff
2022-02-08 01:37:36,869 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:37:36,870 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x16 0x3 0x4b 0x0 0x0 0x2 0xab 0x0 0x0 0x0 0x0 0x0 0x0 0x3 0x4 0x13 0x8b 0x0 0x0 0x0 0x6a 0x0 0x0 0x11 0xa3 0xff

But...

    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 178, in main
    await SUNSYNK.read([fil.sensor])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Total Grid Export', 106, 0, None, 'kWh')
2022-02-08 01:38:17,090 DEBUG   send: 0x1 0x3 0x0 0x4e 0x0 0x3 0x65 0xdc
2022-02-08 01:38:17,091 DEBUG   Adding transaction 1
2022-02-08 01:38:17,140 DEBUG   recv: 0x1 0x3 0x6 0x3 0x4 0x13 0x88 0x0 0x0 0x54 0x28
2022-02-08 01:38:17,140 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:38:17,142 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x6 0x3 0x4 0x13 0x88 0x0 0x0 0x54 0x28
2022-02-08 01:38:37,116 ERROR   Timeout reading single sensor: Total Grid Import:last
2022-02-08 01:38:37,129 DEBUG   send: 0x1 0x3 0x0 0xb8 0x0 0x1 0x4 0x2f
2022-02-08 01:38:37,130 DEBUG   Adding transaction 1
2022-02-08 01:38:37,175 DEBUG   recv: 0x1 0x3 0x2 0x0 0x2d 0x78 0x59 0xff
2022-02-08 01:38:37,175 DEBUG   Getting Frame - 0x3 0x2 0x0 0x2d
2022-02-08 01:38:37,176 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:38:37,176 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:38:37,177 DEBUG   Getting transaction 1
2022-02-08 01:38:37,179 DEBUG   Request registers: [184] glen=1. Response [45] len=1. regs={184: 45}
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/src/app/./run.py", line 172, in main
    await SUNSYNK.read([f.sensor for f in SENSORS])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 100, in read
    r_r = await self.client.read_holding_registers(
  File "/usr/local/lib/python3.9/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 659, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 363, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 178, in main
    await SUNSYNK.read([fil.sensor])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Battery SOC', 45, 0, None, '%')
2022-02-08 01:38:37,184 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/total_pv_power, 156.2
2022-02-08 01:38:37,188 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/total_battery_charge, 84.3
2022-02-08 01:38:37,191 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/total_battery_discharge, None
2022-02-08 01:38:37,194 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/total_grid_export, 10.6
2022-02-08 01:38:37,197 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/total_grid_import, None
2022-02-08 01:38:37,199 DEBUG   PUBLISH 0 SUNSYNK/status/2106154277/battery_soc, 45
2022-02-08 01:38:37,203 DEBUG   send: 0x1 0x3 0x0 0x48 0x0 0xb 0x84 0x1b
2022-02-08 01:38:37,204 DEBUG   Adding transaction 1
2022-02-08 01:38:37,276 DEBUG   recv: 0x1 0x3 0x16 0x3 0x4b 0x0 0x0 0x2 0xab 0x0 0x0 0x0 0x0 0x0 0x0 0x3 0x4 0x13 0x89 0x0 0x0 0x0 0x6a 0x0 0x0 0x32 0x63 0xff
2022-02-08 01:38:37,276 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:38:37,277 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x16 0x3 0x4b 0x0 0x0 0x2 0xab 0x0 0x0 0x0 0x0 0x0 0x0 0x3 0x4 0x13 0x89 0x0 0x0 0x0 0x6a 0x0 0x0 0x32 0x63 0xff

And more...

2022-02-08 01:39:56,589 DEBUG   Total Battery Charge low=843 high=0 value=84kWh
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 659, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 363, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 192, in poll_sensors
    await SUNSYNK.read([f.sensor for f in fsensors])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Total Battery Discharge', 683, 0, None, 'kWh')
2022-02-08 01:39:56,595 DEBUG   Total Grid Export low=106 high=0 value=10kWh
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 659, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 363, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 192, in poll_sensors
    await SUNSYNK.read([f.sensor for f in fsensors])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Total Grid Import', 772, 0, None, 'kWh')
2022-02-08 01:39:56,598 DEBUG   send: 0x1 0x3 0x0 0x60 0x0 0x2 0xc4 0x15
2022-02-08 01:39:56,600 DEBUG   Adding transaction 1
2022-02-08 01:39:56,653 DEBUG   recv: 0x1 0x3 0x4 0x6 0x1a 0x0 0x0 0xdb 0x7c
2022-02-08 01:39:56,654 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:39:56,655 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x4 0x6 0x1a 0x0 0x0 0xdb 0x7c
2022-02-08 01:40:16,626 ERROR   TimeOut

@kellerza
Copy link
Owner

kellerza commented Feb 8, 2022

What happens with only battery_voltage as a start. Frist try without debug and then enable it later

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

As per #10 (comment)

  - battery_voltage
  - battery_soc

These without debug mode didn't work. See #10 (comment) and then with DEBUG set we got #10 (comment)

I'll try just battery_voltage and no debug...

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022 •
edited

Just battery_voltage and no debug:

2022-02-08 01:54:45,332 INFO    MQTT: Connection successful
2022-02-08 01:54:45,832 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/total_pv_power/config
2022-02-08 01:54:45,833 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/total_battery_charge/config
2022-02-08 01:54:45,835 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/total_battery_discharge/config
2022-02-08 01:54:45,836 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/total_grid_export/config
2022-02-08 01:54:45,837 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/total_grid_import/config
2022-02-08 01:54:45,838 WARNING Removing HASS MQTT discovery info homeassistant/sensor/210615XXXX/battery_soc/config
2022-02-08 01:55:06,353 ERROR   Timeout on initial read. Sensors: ['Battery voltage:step:mean']
2022-02-08 01:55:26,431 ERROR   TimeOut 
2022-02-08 01:55:47,456 ERROR   TimeOut

etc etc.

Adding back DEBUG: 2, we start getting the voltage being reported...

Screenshot 2022-02-08 at 02 01 28

2022-02-08 01:58:55,969 INFO    MQTT: Connection successful
2022-02-08 01:58:56,461 DEBUG   PUBLISH 1R SUNSYNK/status/210615XXXX/availability, online
2022-02-08 01:58:56,485 DEBUG   publish homeassistant/sensor/210615XXXX/battery_voltage/config
2022-02-08 01:58:56,486 DEBUG   PUBLISH 1R homeassistant/sensor/210615XXXX/battery_voltage/config, {"unique_id": "210615XXXX_battery_voltage", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/battery_voltage", "name": "Sunsynk Battery voltage", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "device_class": "voltage", "unit_of_measurement": "V"}
2022-02-08 01:58:56,492 DEBUG   publish homeassistant/select/210615XXXX/system_mode/config
2022-02-08 01:58:56,493 DEBUG   PUBLISH 1R homeassistant/select/210615XXXX/system_mode/config, {"unique_id": "210615XXXX_system_mode", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/system_mode", "name": "Sunsynk System Mode", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "command_topic": "SUNSYNK/status/210615XXXX/system_mode_set", "options": ["UPDATE"]}
2022-02-08 01:58:56,498 DEBUG   publish homeassistant/select/210615XXXX/system_mode_voltages/config
2022-02-08 01:58:56,499 DEBUG   PUBLISH 1R homeassistant/select/210615XXXX/system_mode_voltages/config, {"unique_id": "210615XXXX_system_mode_voltages", "device": {"identifiers": ["210615XXXX"], "manufacturer": "Sunsynk", "model": "Inverter 210615XXXX", "name": "Sunsynk Inverter 210615XXXX"}, "state_topic": "SUNSYNK/status/210615XXXX/system_mode_voltages", "name": "Sunsynk System Mode Voltages", "availability": [{"topic": "SUNSYNK/status/210615XXXX/availability"}], "command_topic": "SUNSYNK/status/210615XXXX/system_mode_voltages_set", "options": ["UPDATE"]}
2022-02-08 01:58:56,503 DEBUG   Rx retained msg: topic=homeassistant/sensor/210615XXXX/battery_voltage/config -- device=210615XXXX
2022-02-08 01:58:56,504 DEBUG   Rx retained msg: topic=homeassistant/select/210615XXXX/system_mode/config -- device=210615XXXX
2022-02-08 01:58:56,505 DEBUG   Rx retained msg: topic=homeassistant/select/210615XXXX/system_mode_voltages/config -- device=210615XXXX
2022-02-08 01:58:57,007 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:58:57,009 DEBUG   Adding transaction 1
2022-02-08 01:58:57,055 DEBUG   recv: 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:58:57,056 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:58:57,056 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:17,034 ERROR   Timeout on initial read. Sensors: ['Battery voltage:step:mean']
2022-02-08 01:59:17,048 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:59:17,049 DEBUG   Adding transaction 1
2022-02-08 01:59:17,094 DEBUG   recv: 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:17,095 DEBUG   Getting Frame - 0x3 0x2 0x14 0x64
2022-02-08 01:59:17,095 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:59:17,096 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:59:17,096 DEBUG   Getting transaction 1
2022-02-08 01:59:17,099 DEBUG   Request registers: [183] glen=1. Response [5220] len=1. regs={183: 5220}
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/src/app/./run.py", line 172, in main
    await SUNSYNK.read([f.sensor for f in SENSORS])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 100, in read
    r_r = await self.client.read_holding_registers(
  File "/usr/local/lib/python3.9/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.9/logging/__init__.py", line 659, in format
    record.message = record.getMessage()
  File "/usr/local/lib/python3.9/logging/__init__.py", line 363, in getMessage
    msg = msg % self.args
TypeError: %d format: a number is required, not NoneType
Call stack:
  File "/usr/src/app/./run.py", line 214, in <module>
    LOOP.run_until_complete(main(LOOP))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1882, in _run_once
    handle._run()
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/src/app/./run.py", line 178, in main
    await SUNSYNK.read([fil.sensor])
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sunsynk.py", line 116, in read
    update_sensors(sensors, regs)
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 124, in update_sensors
    sen.update_value()
  File "/usr/local/lib/python3.9/site-packages/sunsynk/sensor.py", line 60, in update_value
    _LOGGER.debug(
Message: '%s low=%d high=%d value=%d%s'
Arguments: ('Battery voltage', 5220, 0, None, 'V')
2022-02-08 01:59:17,108 DEBUG   PUBLISH 0 SUNSYNK/status/210615XXXX/battery_voltage, 52.2
2022-02-08 01:59:17,113 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:59:17,114 DEBUG   Adding transaction 1
2022-02-08 01:59:17,164 DEBUG   recv: 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:17,165 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:59:17,165 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:37,140 ERROR   TimeOut 
2022-02-08 01:59:37,146 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:59:37,147 DEBUG   Adding transaction 1
2022-02-08 01:59:37,193 DEBUG   recv: 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:37,194 DEBUG   Getting Frame - 0x3 0x2 0x14 0x64
2022-02-08 01:59:37,194 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-02-08 01:59:37,195 DEBUG   Frame advanced, resetting header!!
2022-02-08 01:59:37,195 DEBUG   Getting transaction 1
2022-02-08 01:59:37,198 DEBUG   Request registers: [183] glen=1. Response [5220] len=1. regs={183: 5220}
2022-02-08 01:59:37,199 DEBUG   Battery voltage low=5220 high=0 value=52V
2022-02-08 01:59:38,151 DEBUG   send: 0x1 0x3 0x0 0xb7 0x0 0x1 0x34 0x2c
2022-02-08 01:59:38,154 DEBUG   Adding transaction 1
2022-02-08 01:59:38,203 DEBUG   recv: 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff
2022-02-08 01:59:38,204 DEBUG   Frame check failed, ignoring!!
2022-02-08 01:59:38,204 DEBUG   Resetting frame - Current Frame in buffer - 0xff 0x1 0x3 0x2 0x14 0x64 0xb6 0xaf 0xff

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Screenshot 2022-02-08 at 02 06 23

Will see what it reports over the next few hours

@kellerza
Copy link
Owner

kellerza commented Feb 8, 2022

Ok, try to update in 5 min when the CI/CD job is finished and then at least debugging should work better

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Screenshot 2022-02-08 at 12 33 02

Looks like it was fairly consistenly getting values overnight.

Just updated to 2022.02.08-0.1.1

Without debug enabled, it's still regularly timing out it seems

2022-02-08 12:28:46,245 INFO    MQTT: Connection successful
2022-02-08 12:29:07,255 ERROR   Read error: Timeout
2022-02-08 12:29:07,256 INFO    Retrying individual sensors: ['Battery voltage:step:mean']
2022-02-08 12:29:32,363 ERROR   Read error: Timeout
2022-02-08 12:29:53,389 ERROR   Read error: Timeout
2022-02-08 12:30:14,397 ERROR   Read error: Timeout
2022-02-08 12:30:35,422 ERROR   Read error: Timeout
2022-02-08 12:30:56,447 ERROR   Read error: Timeout
2022-02-08 12:31:17,472 ERROR   Read error: Timeout
2022-02-08 12:31:38,492 ERROR   Read error: Timeout
2022-02-08 12:31:59,517 ERROR   Read error: Timeout
2022-02-08 12:32:20,542 ERROR   Read error: Timeout
2022-02-08 12:32:43,558 ERROR   Read error: Timeout
2022-02-08 12:33:13,609 ERROR   Read error: Timeout
2022-02-08 12:33:34,621 ERROR   Read error: Timeout

Lets turn debug back on now...

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Screenshot 2022-02-08 at 13 42 23

It looks like the various improvements you've made are definitely helping! 👍

@kellerza
Copy link
Owner

kellerza commented Feb 8, 2022

I still don't like your Timeouts, it seems to occur way too often! I probably get <5 a day...

Can you try do this through the mbusd bridge addon?

Things to check on your cable:

  • Do you run this next wire next to any AC or to a lesser extend DC cables? (Maybe remove this completely from other cable trunking to be sure)
  • Make sure you use a twisted pair (gr-gr-white)
  • Make sure the crimp is good
  • Do you use a good quality CAT5e/CAT6?
  • Shielded might be an option (ground on the one side only)

Another thing might be to try another RS485 converter, like this with pin 3 to ground

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022 •
edited

I can try to get the mbusd addon up and running.

Do you run this next wire next to any AC or to a lesser extend DC cables? (Maybe remove this completely from other cable trunking to be sure)

Nope. Experience has told me not to bother doing stuff like that until you know it's all working. The cable currently goes out the front of the inverter (the removeable panel is off), into the USB adapter plugged into the RPI sat on top of a grounded metal cabinet, so nowhere near any DC or AC cables.

Cable is definitely twisted pair (see photos in #14 same for cable out of inverter setup)

Crimp seems to be fine, has continuity.

I'm not sure if it is good quality cable. It's CAT5e, and the tail end of the box I've been using on and off for a while. I do have some (much newer) external grade CAT5e I can try making a cable up from instead. Electricians used cable from the same reel to do the inverter <-> battery communication cable.

The plugs I know are of decent quality.

Haven't got any shielded cable (currently).

Happy to try another converter if I can find somewhere to source one... That one ordered from ZA isn't that bad price wise, just shy of 245 ZAR shipped to the UK (though, I'm not sure it's actually delivery to the UK - National Delivery - Flat Rate - R98.00), but not sure how quick it might be. No useful google-able part number to try and find one at another supplier, unfortunately.

That or finding a similar FTDI one (ie "known good brand") somewhere....

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Looks like the mbusd version just works a lot better...

Immediately showing extra data

Screenshot 2022-02-08 at 14 42 37

@kellerza
Copy link
Owner

kellerza commented Feb 8, 2022

That seems to be better! It just uses a C implementation to do the RS485 comms, the external pymodbus might be 100% python

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Logs are generally quieter too..

[14:39:12] INFO: Starting mbusd -d -L - -v 2 -p /dev/ttyUSB0 -s 9600 -m 8N1 -P 502
08 Feb 2022 14:39:12 mbusd-0.5.1 started...
08 Feb 2022 14:39:12 tty: trying to open /dev/ttyUSB0 (speed 9600 mode 8N1)
08 Feb 2022 14:40:53 conn_open(): accepting connection from 172.30.33.1

2022-02-08 14:40:53,209 INFO    MQTT: Connection successful
2022-02-08 14:47:00,150 ERROR   Read Error: failed to read
2022-02-08 15:00:23,106 ERROR   Read Error: failed to read

@reedy
Copy link
Contributor Author

reedy commented Feb 8, 2022

Modbus is still identical

2022-02-08 14:40:53,209 INFO    MQTT: Connection successful
2022-02-08 14:47:00,150 ERROR   Read Error: failed to read
2022-02-08 15:00:23,106 ERROR   Read Error: failed to read
2022-02-08 15:21:31,376 ERROR   Read Error: failed to read
2022-02-08 16:13:04,565 ERROR   Read Error: failed to read
2022-02-08 16:25:44,407 ERROR   Read Error: failed to read
2022-02-08 16:28:53,181 ERROR   Read Error: failed to read
2022-02-08 16:31:23,685 ERROR   Read Error: failed to read
2022-02-08 16:44:26,874 ERROR   Read Error: failed to read
2022-02-08 16:49:28,650 ERROR   Read Error: failed to read
2022-02-08 17:02:24,722 ERROR   Read Error: failed to read
2022-02-08 17:13:18,058 ERROR   Read Error: failed to read
2022-02-08 17:20:13,180 ERROR   Read Error: failed to read
2022-02-08 17:36:38,801 ERROR   Read Error: failed to read
2022-02-08 17:54:21,920 ERROR   Read Error: failed to read
2022-02-08 18:01:20,268 ERROR   Read Error: failed to read
2022-02-08 18:08:50,095 ERROR   Read Error: failed to read
2022-02-08 18:09:46,323 ERROR   Read Error: failed to read
2022-02-08 18:27:31,178 ERROR   Read Error: failed to read
2022-02-08 18:29:42,796 ERROR   Read Error: failed to read
2022-02-08 18:44:00,296 ERROR   Read Error: failed to read
2022-02-08 19:16:09,142 ERROR   Read Error: failed to read
2022-02-08 19:20:17,497 ERROR   Read Error: failed to read
2022-02-08 19:31:28,224 ERROR   Read Error: failed to read

@kellerza
Copy link
Owner

kellerza commented Feb 9, 2022

Maybe this converter?

Can you try measure if there is voltage difference between the inverter ground (pin 3 on the rj-45 likely orange-white?) and the USB ground (maybe you can try measure to the metal shield)

The only other option I can think of is to increase the retry timer on mbusd (but its not configurable today)

@reedy
Copy link
Contributor Author

reedy commented Feb 9, 2022

Maybe this converter?

Thanks for digging it up. Ordered, should be here in a month...

@kellerza
Copy link
Owner

@reedy you should also try the (dev) version of the addon for improved read&reconnects

@reedy reedy mentioned this issue Mar 20, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@reedy @kellerza @dirkackerman