search

kellerza / sunsynk

Deye/Sunsynk Inverter Python library and Home Assistant OS Addon
https://kellerza.github.io/sunsynk/
MIT License
218 stars 91 forks source link

Unable to get data from inverter with modbus gateway #56

Closed wax911 closed 2 years ago

wax911 commented 2 years ago

Issue related to

Sunsynk / mbusd Home Assistant Add-On

Describe the issue/bug

I followed the wiring instructions with the correct ethernet cable type plugged into RS485 port on the 485-to-usb adpter (see image below), coupled with using pymodbus and mbusd for handling sending and recieving of data.

image

Expected behavior Seeing how commands are recieved on the modbus gateway, I'm not entirely sure what I could be missing. I've double checked the wiring, tried different connection RS485 adapters and all behave the same

Your environment

Logs

From the addon

[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-08-28 12:38:55,112 INFO    Loading HASS OS configuration
2022-08-28 12:38:55,288 DEBUG   last unit:kWh, id:total_pv_power
2022-08-28 12:38:55,289 DEBUG   last unit:kWh, id:total_battery_charge
2022-08-28 12:38:55,290 DEBUG   last unit:kWh, id:total_battery_discharge
2022-08-28 12:38:55,290 DEBUG   last unit:kWh, id:total_grid_export
2022-08-28 12:38:55,291 DEBUG   last unit:kWh, id:total_grid_import
2022-08-28 12:38:55,292 DEBUG   last unit:%, id:battery_soc
2022-08-28 12:38:55,293 DEBUG   step unit:W, id:grid_power
2022-08-28 12:38:55,294 DEBUG   avg unit:V, id:grid_voltage
2022-08-28 12:38:55,294 DEBUG   step unit:W, id:load_power
2022-08-28 12:38:55,295 DEBUG   step unit:W, id:essential_power
2022-08-28 12:38:55,296 DEBUG   step unit:W, id:non_essential_power
2022-08-28 12:38:55,296 DEBUG   step unit:W, id:pv1_power
2022-08-28 12:38:55,297 DEBUG   step unit:W, id:pv2_power
2022-08-28 12:38:55,298 DEBUG   step unit:W, id:battery_power
2022-08-28 12:38:55,298 DEBUG   step unit:A, id:battery_current
2022-08-28 12:38:55,299 DEBUG   avg unit:V, id:battery_voltage
2022-08-28 12:38:55,300 DEBUG   last unit:kWh, id:day_grid_import
2022-08-28 12:38:55,301 DEBUG   last unit:kWh, id:day_grid_export
2022-08-28 12:38:55,302 DEBUG   last unit:kWh, id:day_pv_energy
2022-08-28 12:38:55,303 DEBUG   last unit:kWh, id:day_battery_charge
2022-08-28 12:38:55,303 DEBUG   last unit:kWh, id:day_battery_discharge
2022-08-28 12:38:55,304 INFO    Filter *last used for battery_soc, day_battery_charge, day_battery_discharge, day_grid_export, day_grid_import, day_pv_energy, total_battery_charge, total_battery_discharge, total_grid_export, total_grid_import, total_pv_power
2022-08-28 12:38:55,304 INFO    Filter *step used for battery_current, battery_power, essential_power, grid_power, load_power, non_essential_power, pv1_power, pv2_power
2022-08-28 12:38:55,305 INFO    Filter *avg used for battery_voltage, grid_voltage
2022-08-28 12:38:55,306 DEBUG   Using selector: EpollSelector
2022-08-28 12:38:55,309 DEBUG   Connecting.
2022-08-28 12:38:55,321 DEBUG   Get address info pop-os.lan:502, type=<SocketKind.SOCK_STREAM: 1>
2022-08-28 12:38:55,371 DEBUG   Getting address info pop-os.lan:502, type=<SocketKind.SOCK_STREAM: 1> took 48.700ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, 'pop-os.lan', ('192.168.8.184', 502))]
2022-08-28 12:38:55,404 DEBUG   Client connected to modbus server
2022-08-28 12:38:55,405 INFO    Protocol made connection.
2022-08-28 12:38:55,407 DEBUG   <asyncio.TransportSocket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('172.30.33.3', 39100), raddr=('192.168.8.184', 502)> connected to pop-os.lan:502: (<_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>, <pymodbus.client.asynchronous.async_io.ModbusClientProtocol object at 0x7f931efb50>)
2022-08-28 12:38:55,409 INFO    Connected to pop-os.lan:502.
2022-08-28 12:38:55,421 DEBUG   send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 12:38:55,429 DEBUG   Adding transaction 1
2022-08-28 12:38:57,543 DEBUG   recv: 0x0 0x1 0x0 0x0 0x0 0x3 0x1 0x83 0xb
2022-08-28 12:38:57,544 DEBUG   Processing: 0x0 0x1 0x0 0x0 0x0 0x3 0x1 0x83 0xb
2022-08-28 12:38:57,546 DEBUG   Factory Response[131]
2022-08-28 12:38:57,547 DEBUG   Getting transaction 1
2022-08-28 12:38:57,555 ERROR   Read Error: (1,3,5) failed to read
2022-08-28 12:38:57,555 INFO    ############################################################
2022-08-28 12:38:57,556 INFO    No response on the Modbus interface, try checking the wiring to the Inverter, the USB-to-RS485 converter, etc
2022-08-28 12:38:57,557 INFO    ############################################################
2022-08-28 12:38:57,557 CRITICAL This Add-On will terminate in 30 seconds, use the Supervisor Watchdog to restart automatically.

From Modbus TCP to RTU/serial gateway

28 Aug 2022 12:37:44 mbusd-0.5.1 started...
28 Aug 2022 12:37:44 tty: trying to open /dev/ttyUSB0 (speed 9600 mode 8N1)
28 Aug 2022 12:37:44 tty: state now is TTY_PAUSE
28 Aug 2022 12:37:44 conn_loop(): select(): max_sd = 4, t_out = 000000:100000 
28 Aug 2022 12:37:45 conn_loop(): select() returns 0 
28 Aug 2022 12:37:45 tty: state now is TTY_READY
28 Aug 2022 12:37:45 conn_loop(): select(): max_sd = 4, t_out = 000060:000000 
28 Aug 2022 12:38:45 conn_loop(): select() returns 0 
28 Aug 2022 12:38:45 conn_loop(): select(): max_sd = 4, t_out = 000060:000000 
28 Aug 2022 12:38:55 conn_loop(): select() returns 1 
28 Aug 2022 12:38:55 conn_open(): accepting connection from 192.168.8.148
28 Aug 2022 12:38:55 queue_new_elem(): length now is 1
28 Aug 2022 12:38:55 conn[192.168.8.148]: state now is CONN_HEADER
28 Aug 2022 12:38:55 conn_loop(): select(): max_sd = 5, t_out = 000060:000000 
28 Aug 2022 12:38:55 conn_loop(): select() returns 1 
28 Aug 2022 12:38:55 conn[192.168.8.148]: state now is CONN_RQST_FUNC
28 Aug 2022 12:38:55 conn_loop(): select(): max_sd = 5, t_out = 000060:000000 
28 Aug 2022 12:38:55 conn_loop(): select() returns 1 
28 Aug 2022 12:38:55 conn[192.168.8.148]: read request fc 3
28 Aug 2022 12:38:55 conn[192.168.8.148]: state now is CONN_RQST_TAIL
28 Aug 2022 12:38:55 conn[192.168.8.148]: request: [01][03][00][03][00][05]
28 Aug 2022 12:38:55 conn[192.168.8.148]: state now is CONN_TTY
28 Aug 2022 12:38:55 tty: state now is TTY_RQST
28 Aug 2022 12:38:55 conn_loop(): select(): max_sd = 4, t_out = 000060:000000 
28 Aug 2022 12:38:55 conn_loop(): select() returns 1 
28 Aug 2022 12:38:55 tty: written 8 bytes
28 Aug 2022 12:38:55 tty: request written (total 8 bytes)
28 Aug 2022 12:38:55 tty: state now is TTY_RESP
28 Aug 2022 12:38:55 tty: estimated 15 bytes, waiting 523958 usec
28 Aug 2022 12:38:55 conn_loop(): select(): max_sd = 4, t_out = 000000:523958 
28 Aug 2022 12:38:55 conn_loop(): select() returns 0 
28 Aug 2022 12:38:55 tty: response timeout
kellerza commented 2 years ago

You should use the BMS485 port on a 5kW, guess its the same on the 8kW

refer to the homepage for other connectivity tips

wax911 commented 2 years ago

Thanks @kellerza I wasn't aware of that, I'm a little lost here, do you perhaps have an image of the BMS485 port you're referring to?

I can only see the RS485, CAN and DRMs

kellerza commented 2 years ago

Ok, 8kW seems to be RS485

Have you gone through these steps? https://github.com/kellerza/sunsynk#fault-finding

wax911 commented 2 years ago

Going through the fault finding section now 🤔 I'll report back shortly with results

wax911 commented 2 years ago

So after some tinkering and playing around with the modbus S/N I managed to get a different response along with a different adapter all together:

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-08-28 17:46:09,408 INFO    Loading HASS OS configuration
2022-08-28 17:46:09,569 DEBUG   last unit:kWh, id:total_pv_power
2022-08-28 17:46:09,570 DEBUG   last unit:kWh, id:total_battery_charge
2022-08-28 17:46:09,570 DEBUG   last unit:kWh, id:total_battery_discharge
2022-08-28 17:46:09,571 DEBUG   last unit:kWh, id:total_grid_export
2022-08-28 17:46:09,572 DEBUG   last unit:kWh, id:total_grid_import
2022-08-28 17:46:09,573 DEBUG   last unit:%, id:battery_soc
2022-08-28 17:46:09,574 DEBUG   step unit:W, id:grid_power
2022-08-28 17:46:09,575 DEBUG   avg unit:V, id:grid_voltage
2022-08-28 17:46:09,576 DEBUG   step unit:W, id:load_power
2022-08-28 17:46:09,577 DEBUG   step unit:W, id:essential_power
2022-08-28 17:46:09,578 DEBUG   step unit:W, id:non_essential_power
2022-08-28 17:46:09,579 DEBUG   step unit:W, id:pv1_power
2022-08-28 17:46:09,580 DEBUG   step unit:W, id:pv2_power
2022-08-28 17:46:09,581 DEBUG   step unit:W, id:battery_power
2022-08-28 17:46:09,582 DEBUG   step unit:A, id:battery_current
2022-08-28 17:46:09,582 DEBUG   avg unit:V, id:battery_voltage
2022-08-28 17:46:09,583 DEBUG   last unit:kWh, id:day_grid_import
2022-08-28 17:46:09,584 DEBUG   last unit:kWh, id:day_grid_export
2022-08-28 17:46:09,585 DEBUG   last unit:kWh, id:day_pv_energy
2022-08-28 17:46:09,586 DEBUG   last unit:kWh, id:day_battery_charge
2022-08-28 17:46:09,587 DEBUG   last unit:kWh, id:day_battery_discharge
2022-08-28 17:46:09,588 INFO    Filter *last used for battery_soc, day_battery_charge, day_battery_discharge, day_grid_export, day_grid_import, day_pv_energy, total_battery_charge, total_battery_discharge, total_grid_export, total_grid_import, total_pv_power
2022-08-28 17:46:09,588 INFO    Filter *step used for battery_current, battery_power, essential_power, grid_power, load_power, non_essential_power, pv1_power, pv2_power
2022-08-28 17:46:09,589 INFO    Filter *avg used for battery_voltage, grid_voltage
2022-08-28 17:46:09,591 DEBUG   Using selector: EpollSelector
2022-08-28 17:46:09,594 DEBUG   Connecting.
2022-08-28 17:46:09,604 DEBUG   Get address info pop-os.lan:502, type=<SocketKind.SOCK_STREAM: 1>
2022-08-28 17:46:09,640 DEBUG   Getting address info pop-os.lan:502, type=<SocketKind.SOCK_STREAM: 1> took 33.963ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, 'pop-os.lan', ('192.168.8.184', 502))]
2022-08-28 17:46:09,656 DEBUG   Client connected to modbus server
2022-08-28 17:46:09,657 INFO    Protocol made connection.
2022-08-28 17:46:09,660 DEBUG   <asyncio.TransportSocket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('172.30.33.3', 44406), raddr=('192.168.8.184', 502)> connected to pop-os.lan:502: (<_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>, <pymodbus.client.asynchronous.async_io.ModbusClientProtocol object at 0x7f87a8bc40>)
2022-08-28 17:46:09,661 INFO    Connected to pop-os.lan:502.
2022-08-28 17:46:09,668 DEBUG   send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:09,673 DEBUG   Adding transaction 1
2022-08-28 17:46:10,202 DEBUG   recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:10,203 DEBUG   Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:10,204 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-08-28 17:46:10,205 DEBUG   Getting transaction 1
2022-08-28 17:46:10,209 WARNING Did not complete read, only read 0/5
2022-08-28 17:46:10,210 DEBUG   Request registers: [3, 4, 5, 6, 7] glen=5. Response [] len=0. regs={}
2022-08-28 17:46:10,213 INFO    ############################################################
2022-08-28 17:46:10,214 INFO                   Inverter serial number 'None'
2022-08-28 17:46:10,215 INFO    ############################################################
2022-08-28 17:46:10,215 INFO    ############################################################
2022-08-28 17:46:10,216 INFO    SUNSYNK_ID should be set to the serial number of your Inverter!
2022-08-28 17:46:10,217 INFO    ############################################################
2022-08-28 17:46:10,220 DEBUG   Close <_UnixSelectorEventLoop running=False closed=False debug=True>
[cmd] ./run.py exited 0
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
28 Aug 2022 17:55:21 mbusd-0.5.1 started...
28 Aug 2022 17:55:21 tty: trying to open /dev/ttyUSB1 (speed 9600 mode 8N1)
28 Aug 2022 17:55:21 tty: state now is TTY_PAUSE
28 Aug 2022 17:55:21 conn_loop(): select(): max_sd = 4, t_out = 000000:100000 
28 Aug 2022 17:55:21 conn_loop(): select() returns 0 
28 Aug 2022 17:55:21 tty: state now is TTY_READY
28 Aug 2022 17:55:21 conn_loop(): select(): max_sd = 4, t_out = 000060:000000 
28 Aug 2022 17:55:33 conn_loop(): select() returns 1 
28 Aug 2022 17:55:33 conn_open(): accepting connection from 192.168.8.148
28 Aug 2022 17:55:33 queue_new_elem(): length now is 1
28 Aug 2022 17:55:33 conn[192.168.8.148]: state now is CONN_HEADER
28 Aug 2022 17:55:33 conn_loop(): select(): max_sd = 5, t_out = 000060:000000 
28 Aug 2022 17:55:33 conn_loop(): select() returns 1 
28 Aug 2022 17:55:33 conn[192.168.8.148]: state now is CONN_RQST_FUNC
28 Aug 2022 17:55:33 conn_loop(): select(): max_sd = 5, t_out = 000060:000000 
28 Aug 2022 17:55:33 conn_loop(): select() returns 1 
28 Aug 2022 17:55:33 conn[192.168.8.148]: read request fc 3
28 Aug 2022 17:55:33 conn[192.168.8.148]: state now is CONN_RQST_TAIL
28 Aug 2022 17:55:33 conn[192.168.8.148]: request: [01][03][00][03][00][05]
28 Aug 2022 17:55:33 conn[192.168.8.148]: state now is CONN_TTY
28 Aug 2022 17:55:33 tty: state now is TTY_RQST
28 Aug 2022 17:55:33 conn_loop(): select(): max_sd = 4, t_out = 000060:000000 
28 Aug 2022 17:55:33 conn_loop(): select() returns 1 
28 Aug 2022 17:55:33 tty: written 8 bytes
28 Aug 2022 17:55:33 tty: request written (total 8 bytes)
28 Aug 2022 17:55:33 tty: state now is TTY_RESP
28 Aug 2022 17:55:33 tty: estimated 15 bytes, waiting 523958 usec
28 Aug 2022 17:55:33 conn_loop(): select(): max_sd = 4, t_out = 000000:523958 
28 Aug 2022 17:55:33 conn_loop(): select() returns 1 
28 Aug 2022 17:55:33 tty: read 8 bytes
28 Aug 2022 17:55:33 tty: rx offset is 0
28 Aug 2022 17:55:33 tty: rx len changed from 15 to 5
28 Aug 2022 17:55:33 tty: read 8 bytes of 5, offset 0
28 Aug 2022 17:55:33 conn_loop(): select(): max_sd = 4, t_out = 000000:510791 
28 Aug 2022 17:55:34 conn_loop(): select() returns 0 
28 Aug 2022 17:55:34 tty: response read (total 8 bytes, offset 0 bytes)
28 Aug 2022 17:55:34 tty: response is correct
28 Aug 2022 17:55:34 tty: response: [01][03][00][03][00][05][75][c9]
28 Aug 2022 17:55:34 conn[192.168.8.148]: state now is CONN_RESP
28 Aug 2022 17:55:34 tty: state now is TTY_PAUSE
28 Aug 2022 17:55:34 conn_loop(): select(): max_sd = 5, t_out = 000000:100000 
28 Aug 2022 17:55:34 conn_loop(): select() returns 1 
28 Aug 2022 17:55:34 conn[192.168.8.148]: state now is CONN_HEADER
28 Aug 2022 17:55:34 conn_loop(): select(): max_sd = 5, t_out = 000000:099849 
28 Aug 2022 17:55:34 conn_loop(): select() returns 0 
28 Aug 2022 17:55:34 tty: state now is TTY_READY
28 Aug 2022 17:55:34 conn_loop(): select(): max_sd = 5, t_out = 000060:000000 
28 Aug 2022 17:55:34 conn_loop(): select() returns 1 
28 Aug 2022 17:55:34 conn_close(): closing connection from 192.168.8.148
28 Aug 2022 17:55:34 queue_delete_elem(): length now is 0
28 Aug 2022 17:55:34 conn_loop(): select(): max_sd = 4, t_out = 000060:000000

Config:

PORT: pop-os.lan:502
DRIVER: pymodbus
SUNSYNK_ID: "21070XXXXX"
SENSOR_PREFIX: sunsynk
SENSORS:
  - total_pv_power
  - total_battery_charge
  - total_battery_discharge
  - total_grid_export
  - total_grid_import
  - battery_soc
  - grid_power
  - grid_voltage
  - load_power
  - essential_power
  - non_essential_power
  - pv1_power
  - pv2_power
  - battery_power
  - battery_current
  - battery_voltage
  - day_grid_import
  - day_grid_export
  - day_pv_energy
  - day_battery_charge
  - day_battery_discharge
PROFILES: []
MODBUS_SERVER_ID: 1
MQTT_HOST: core-mosquitto
MQTT_PORT: ######
MQTT_USERNAME: ######
MQTT_PASSWORD: ######
DEBUG: 2
TIME_OUT: 25
kellerza commented 2 years ago

Hi @wax911

You are not getting a (proper) response from the inverter...

Looking at this transaction

2022-08-28 17:46:09,661 INFO    Connected to pop-os.lan:502.
2022-08-28 17:46:09,668 DEBUG   send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:09,673 DEBUG   Adding transaction 1
2022-08-28 17:46:10,202 DEBUG   recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:10,203 DEBUG   Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
2022-08-28 17:46:10,204 DEBUG   Factory Response[ReadHoldingRegistersResponse: 3]
2022-08-28 17:46:10,205 DEBUG   Getting transaction 1
2022-08-28 17:46:10,209 WARNING Did not complete read, only read 0/5
2022-08-28 17:46:10,210 DEBUG   Request registers: [3, 4, 5, 6, 7] glen=5. Response [] len=0. regs={}
2022-08-28 17:46:10,213 INFO    ############################################################
2022-08-28 17:46:10,214 INFO                   Inverter serial number 'None'

For some reason you read exactly what you send!

...
2022-08-28 17:46:09,668 DEBUG   send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
...
2022-08-28 17:46:10,202 DEBUG   recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x3 0x0 0x5
...

So are you sure you wired it up correctly?

kellerza commented 2 years ago

btw, what do you wire up? GND, A & B?

wax911 commented 2 years ago

No idea why that happening to be honest, I've checked my connection multiple times and it's the same. I originally had only A & B tried with GND as well but to no success

I have resorted to using a WiFi data logger in conjunction with the home assistant solarman integration 😅 thanks for the support thus far, really appreciate it!

kellerza commented 2 years ago

You could maybe try swapping A&B. Really strange to get an echo... it almost seems like you have A&B bridged!

If you ever decide to try it again feel free to reach out.