search

bohdan-s / SunGather

GNU General Public License v3.0
150 stars 63 forks source link

Support for SG8K-D Inverter #8

Closed rianbk closed 2 years ago

rianbk commented 2 years ago

Hey,

Firstly thanks for this, been working on something like this personally but found yours on whirlpool. The script seems to be working in some capacity but I don't think you directly support this model.

Traceback (most recent call last):
File "/usr/local/lib/python3.10/threading.py", line 1009, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.10/threading.py", line 946, in run
self._target(*self._args, **self._kwargs)
File "/usr/src/sungather/exports/mqtt.py", line 38, in publish
self.sensor_topic = self.sensor_topic.replace('{model}', inverter.get('device_type_code', 'unknown').replace('.',''))
AttributeError: 'int' object has no attribute 'replace'
Exception in thread Thread-72 (publish):

I have sent a request to sungrowpower for the modbus register

bohdan-s commented 2 years ago

Turns out python requests does not support threading, which is why there where so many issues. I have removed threading from the whole SunGather, so each cycle may take longer. To make sure it does not impact performance I have added a warning if it takes longer to run than the interval set. This will probably trigger over night, if so i'll add a way to silence it is expected. I have also updated MQTT to use a QOS of 1, now it will check the server has received the publish, and if not queue it. It will also check (and reconnect) every interval so no messages should be lost, and it it should reconnect if MQTT server restarts.

daloser commented 2 years ago

Updated to 0.2.10 - will let you know if I hit any snags. Thanks for your speedy updates and feedback! :-)

dbonnell commented 2 years ago

Yep, I got exactly the same as @daloser overnight. Failed at 19:14:41 for me then nada after that.

Have updated to 0.2.10. Thanks again @bohdan-s for being so responsive!

rianbk commented 2 years ago

Updated, processing for me is under 2 seconds so lots of headroom for the interval.

dbonnell commented 2 years ago

Around 1.6s for me on average, but I have just seen one 8.5s scrape. Not sure why, but it also isn't an issue.

2022-01-20 10:19:21 INFO     Inverter: Successfully scraped in 1.520894 secs
2022-01-20 10:19:21 INFO     PVOutput: Data logged, next upload in 95 secs
2022-01-20 10:19:21 INFO     Next scrape in 28 secs
2022-01-20 10:19:21 INFO     MQTT: Message 86 Published
2022-01-20 10:19:58 INFO     Inverter: Successfully scraped in 8.489367 secs
2022-01-20 10:19:58 INFO     PVOutput: Data logged, next upload in 58 secs
2022-01-20 10:19:58 INFO     Next scrape in 21 secs
rianbk commented 2 years ago

@bohdan-s New pvoutput error overnight. Looks like it happened at midnight for me

2022-01-21 07:16:19 INFO MQTT: Message 2535 Published
2022-01-21 07:16:19 DEBUG Starting new HTTPS connection (1): pvoutput.org:443

2022-01-21 07:16:20 ERROR PVOutput: Upload Failed; 400 Message; b'<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n\n'

2022-01-21 07:16:20 DEBUG Processing Time: 2.82 secs
2022-01-21 07:16:20 INFO Next scrape in 27 secs
daloser commented 2 years ago

after updating to 0.2.10 I had no issues for 2 days; other than a few errors overnight, but restarting SunGather fixed it. However now it no longer updating HA - i have restarted both HA and SunGather but MQTT seems to be recieving nothing. MQTT explorer isn't seeing activity but when i stop HA i get MQTT server connection errors in SunGather, so they are communicating.

The data to the webserver output is correct and updating regulary.

HA - Mosquitto broker log: 1642900482: New connection from 172.30.32.2 on port 1883. 1642900482: Socket error on client , disconnecting. 1642900602: New connection from 172.30.32.2 on port 1883. 1642900602: Socket error on client , disconnecting. 1642900722: New connection from 172.30.32.2 on port 1883. 1642900722: Socket error on client , disconnecting. 1642900842: New connection from 172.30.32.2 on port 1883. 1642900842: Socket error on client , disconnecting. 1642900962: New connection from 172.30.32.2 on port 1883. 1642900962: Socket error on client , disconnecting. 1642901082: New connection from 172.30.32.2 on port 1883. 1642901082: Socket error on client , disconnecting. 1642901202: New connection from 172.30.32.2 on port 1883. 1642901202: Socket error on client , disconnecting. 1642901322: New connection from 172.30.32.2 on port 1883. 1642901322: Socket error on client , disconnecting.

SunGather Log from last night: 2022-01-22 19:32:05 INFO Starting SunGather 0.2.10 2022-01-22 19:32:05 INFO Loaded config: config.yaml 2022-01-22 19:32:06 INFO Loaded registers: /home/pi/SunGather/SunGather/registers.yaml ^[[C^[[C2022-01-22 23:01:32 WARNING Modbus connection failed: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 8 bytes (0 received) 2022-01-22 23:01:42 WARNING Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response 2022-01-22 23:01:52 WARNING Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response 2022-01-22 23:01:52 WARNING Data collection failed, skipped exporting data. Retying in 30 secs 2022-01-22 23:01:52 WARNING SunGather is taking 30.06 to process, which is longer than interval 30, Please increase scan interval 2022-01-23 00:06:36 WARNING Modbus connection failed: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 8 bytes (0 received) 2022-01-23 00:06:46 WARNING Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response 2022-01-23 00:06:56 WARNING Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response 2022-01-23 00:06:56 WARNING Data collection failed, skipped exporting data. Retying in 30 secs 2022-01-23 00:06:56 WARNING SunGather is taking 30.07 to process, which is longer than interval 30, Please increase scan interval 2022-01-23 03:06:46 WARNING Modbus connection failed: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 8 bytes (0 received) 2022-01-23 03:06:47 ERROR index out of range 2022-01-23 03:06:47 ERROR Modbus Error: [Input/Output] Unable to decode request Traceback (most recent call last): File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/transaction.py", line 210, in execute request.unit_id) File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket self._process(callback, error=True) File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process raise ModbusIOException("Unable to decode request") pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request 2022-01-23 03:06:47 WARNING Modbus connection failed: Modbus Error: [Input/Output] Unable to decode request 2022-01-23 03:06:47 ERROR index out of range 2022-01-23 03:06:47 ERROR Modbus Error: [Input/Output] Unable to decode request Traceback (most recent call last): File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/transaction.py", line 210, in execute request.unit_id) File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket self._process(callback, error=True) File "/home/pi/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process raise ModbusIOException("Unable to decode request") pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request 2022-01-23 03:06:47 WARNING Modbus connection failed: Modbus Error: [Input/Output] Unable to decode request 2022-01-23 03:06:47 WARNING Data collection failed, skipped exporting data. Retying in 30 secs

dbonnell commented 2 years ago

No issues with my HA feed via a standalone Mosquitto broker. I did see that decoding issue twice a day or two ago but nothing since.

dbonnell commented 2 years ago

There does however appear to be an issue with pvoutput export. My yield so far today is 31.4 kWh but pvoutput shows 0.345kWh for the daily total.

image

Drilling into the day in pvoutput is shows more than that, 0.518kWh, for the last 5 minute interval. I'm not sure if this is a pvoutput or SunGather issue.

image

I'm using v1/v4 and have c1 set to 1 (cummulative) but I noticed in the new config-example.yaml that the default is v1/v4 but c1=2. Has that changed?

daloser commented 2 years ago

looks like my issues was the MQTT Integration, removed it and restarted HA, rediscovered the Integration and then restarted SunGather and it was all back up.

dbonnell commented 2 years ago

I re-created config.yaml from config-example.yaml and the only change I made to pvoutput config was the auth and to set c1=1, just as I had before. After restarting, pvoutput seems to be aggregating deltas of the Energy reported for each interval but it is still not showing total energy for the day. Switched it to c1=2 per the new config-examply.yaml and it shows the correct daily total again. Weird.

The pvoutput API docs aren't clear on how c1 applies when only one of v1 or v3 is provided, but logically if only v1 is provided then it shouldn't matter if c1 is 1 or 2 because that should only affect the interpretation of v1, as v3 will be calculated from v4 (by integrating over the 5 min interval). But somehow sending c1=1 screws up pvoutput. IMO that's a pvoutput bug.

Anyway, back in business with pvoutput again.

dbonnell commented 2 years ago

pvoutput failed again. Looks like it never recovered after the last update pushed at 7:15PM 23/1. The log shows the following:


2022-01-25 10:19:08 ERROR    PVOutput: Failed to Upload
2022-01-25 10:19:08 INFO     Next scrape in 21 secs
2022-01-25 10:19:32 INFO     Inverter: Successfully scraped in 2.418299 secs
2022-01-25 10:19:32 INFO     Webserver: Content Updated
2022-01-25 10:19:33 INFO     MQTT: Message 2403 Published
2022-01-25 10:19:39 ERROR    PVOutput: Upload Failed; 400 Message; b'<html><body><h1>400 Bad request</h1>\nYour browser sent an invalid request.\n</body></html>\n\n'```

It is working again after restart.  The above error is from the addbatchstatus POST request.  I've added some extra logging temporarily to the exception handler to see if there was anything weird in the payload of the failed request, but it could be a pvoutput issue.

A quick Google on that pvoutput error didn't turn up anything concrete, however there was a post from 2019 where people noted they suddenly started having that issue.  The cause was pvoutput adding a new load balancer which had strict mode enabled, which required a minimum of HTTP/1.0 and a Host header.

I will let you know if I discover anything further.
bohdan-s commented 2 years ago

@rianbk @dbonnell @daloser Please check v0.3.0 it should resolve all the issues above, PVOutput I made a mistake so after midnight it would never publish until a restart, this is fixed in 0.3.0

dbonnell commented 2 years ago

Updating now. Thank you.

bohdan-s commented 2 years ago

Sorry, don't forget to check the example config again, I moved the c1 flag to a different section of the config to simplify it (was causing an issue).

dbonnell commented 2 years ago

It was working fine for a couple of hours but then failed and never recovered. Last interval in pvoutput is 3:10PM which coincides with the first error below at 15:07:49. Nothing in Grafana from after the same time, so all exports failed. After the initial failure the logs are full of repeated Modbus errors for each scrape attempt. I don't think the inverter wifi dropped out and it was connected when I checked before restarting SunGather, and SunGather connected fine after restarting it.

2022-01-25 14:35:13 INFO     Starting SunGather 0.3.0
...
2022-01-25 15:07:49 WARNING  Modbus connection failed: Modbus Error: [Input/Output] [Errno 104] Connection reset by peer
2022-01-25 15:07:49 ERROR    index out of range
2022-01-25 15:07:49 ERROR    Modbus Error: [Input/Output] Unable to decode request
Traceback (most recent call last):
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/transaction.py", line 208, in execute
    self.client.framer.processIncomingPacket(response,
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
    self._process(callback, error=True)
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2022-01-25 15:07:49 WARNING  Modbus connection failed: Modbus Error: [Input/Output] Unable to decode request
...
2022-01-25 17:28:05 INFO     Connection: ModbusTcpClient(11.11.11.1:502)
2022-01-25 17:28:08 WARNING  Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response
2022-01-25 17:28:08 WARNING  Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response
2022-01-25 17:28:08 WARNING  Modbus connection failed: Modbus Error: [Input/Output] No Response received from the remote unit/Unable to decode response
2022-01-25 17:28:08 WARNING  Data collection failed, skipped exporting data. Retying in 15 secs
2022-01-25 17:28:08 INFO     Next scrape in 11 secs
bohdan-s commented 2 years ago

@dbonnell Pushed 0.3.1 that will force a disconnect, hopefully that will refresh the key and fix the issue :)

rianbk commented 2 years ago

@bohdan-s getting this error, tried new config file

2022-01-25 21:09:59 INFO Starting SunGather 0.3.1
2022-01-25 21:09:59 INFO Loaded config: /config/config.yaml
2022-01-25 21:09:59 INFO Loaded registers: /usr/src/sungather/registers.yaml
2022-01-25 21:09:59 DEBUG Inverter Config Loaded: {'host': '192.168.1.207', 'port': 502, 'timeout': 10, 'retries': 3, 'slave': 1, 'scan_interval': 15, 'connection': 'sungrow', 'model': None, 'smart_meter': True, 'use_local_time': False, 'manual_load': False, 'logging': 10, 'level': 1}
Traceback (most recent call last):
File "/usr/src/sungather/sungather.py", line 524, in <module>
main()
File "/usr/src/sungather/sungather.py", line 470, in main
if not inverter.connect():
File "/usr/src/sungather/sungather.py", line 59, in connect
elif self.config_inverter_configinverter['connection'] == "sungrow":
AttributeError: 'SungrowInverter' object has no attribute 'config_inverter_configinverter'
bohdan-s commented 2 years ago

Easy fix. Sorry I’ll push 0.3.2 with it fixed tomorrow. Might build a few variations of config files for better testing….

dbonnell commented 2 years ago

sungather.py, line#59 should be:

elif self.inverter_config['connection'] == "sungrow":
dbonnell commented 2 years ago

I guess I should have paid attention after I restarted last night. It failed to connect to the inverter (expected .. inverter wifi goes offline when there's no PV output) and never attempted to reconnect. The sum total of log output after I restarted it last night until this morning was this:

2022-01-25 21:51:13 INFO     Starting SunGather 0.3.1
2022-01-25 21:51:13 INFO     Loaded config: config.yaml
2022-01-25 21:51:13 INFO     Loaded registers: /mnt/d/work/sungrow/Sungather/SunGather/registers.yaml
2022-01-25 21:51:13 INFO     Connection: ModbusTcpClient(11.11.11.1:502)
2022-01-25 21:51:23 ERROR    Connection to (11.11.11.1, 502) failed: timed out
2022-01-25 21:51:26 ERROR    Error: Connection to inverter failed: 11.11.11.1:502
Error: Connection to inverter failed: 11.11.11.1:502

It is still not happy:

2022-01-26 10:40:26 INFO     Loading Export: exports\pvoutput
2022-01-26 10:40:36 ERROR    PVOutput: Failed to configure
2022-01-26 10:40:36 WARNING  Modbus connection failed: Modbus Error: [Input/Output] [Errno 104] Connection reset by peer
2022-01-26 10:40:37 ERROR    Unable to decode response Modbus Error: Unknown response 0
2022-01-26 10:40:37 ERROR    Modbus Error: [Input/Output] Unable to decode request
Traceback (most recent call last):
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/transaction.py", line 208, in execute
    self.client.framer.processIncomingPacket(response,
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
    self._process(callback, error=True)
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2022-01-26 10:40:37 WARNING  Modbus connection failed: Modbus Error: [Input/Output] Unable to decode request
2022-01-26 10:40:37 ERROR    Unable to decode response Modbus Error: Unknown response 0
2022-01-26 10:40:37 ERROR    Modbus Error: [Input/Output] Unable to decode request
Traceback (most recent call last):
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/transaction.py", line 208, in execute
    self.client.framer.processIncomingPacket(response,
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
    self._process(callback, error=True)
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2022-01-26 10:40:37 WARNING  Modbus connection failed: Modbus Error: [Input/Output] Unable to decode request
2022-01-26 10:40:37 INFO     Disconnected: ModbusTcpClient(11.11.11.1:502)
2022-01-26 10:40:37 INFO     Disconnected: None
Traceback (most recent call last):
  File "sungather.py", line 524, in <module>
    main()
  File "sungather.py", line 505, in main
    inverter.disconnect()
  File "sungather.py", line 81, in disconnect
    self.client.close()
AttributeError: 'NoneType' object has no attribute 'close'

After enabling DEBUG logging it looks like it is either reconnecting to the inverter very frequently or it is opening multiple connections? 

2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 41055)
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 51763)
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 57751)
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 53325)
2022-01-26 10:44:13 DEBUG    Scraping: read, 5000:100
2022-01-26 10:44:13 DEBUG    load_registers: read, 5000:100
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 54347)
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 52891)
2022-01-26 10:44:13 DEBUG    Current transaction state - TRANSACTION_COMPLETE
2022-01-26 10:44:13 DEBUG    Running transaction 2
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 34399)
2022-01-26 10:44:13 DEBUG    Connection to Modbus server established. Socket ('172.29.113.187', 50727)
2022-01-26 10:44:13 DEBUG    SEND: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x4 0x13 0x88 0x0 0x64
2022-01-26 10:44:13 DEBUG    New Transaction state 'SENDING'
2022-01-26 10:44:13 DEBUG    Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-26 10:44:13 DEBUG    Transaction failed. ([Errno 104] Connection reset by peer)

Looking at SungrowModbusTcpClient, I think it's connect method is responsible for the pairs of Modbus connections. It connects once with ModbusTcpClient to get the encryption key, then closes that connection and connects again with the key.

But the double ups appear to be SunGather connect, which closes the connection it just opened if the inverter client is not http and then the scraping loop connects each time at the top.

If I comment out the close at the end of connect it definitely seems better, but there are still tons of Modbus connection and decode errors. Increasing the sleep in the same spot from 3 to 5 seconds seems to reduce the number of Modbus errors. I'm just taking stabs in the dark here.

I also added checks to the close and disconnect methods that self.client was not None before attempting to call self.client.close()

It is back scraping and exporting again.

dbonnell commented 2 years ago

Reconnected fine this morning and exporting fine, but there were still frequent Modbus connection and decoding errors in the log. I've just upgraded to SungrowModbusWebClient-0.2.7 but that didn't help. Here's an example of the Modbus errors.

2022-01-27 09:59:36 INFO     Starting SunGather 0.3.1
2022-01-27 09:59:36 INFO     Loaded config: config.yaml
2022-01-27 09:59:36 INFO     Loaded registers: /mnt/d/work/sungrow/Sungather/SunGather/registers.yaml
2022-01-27 09:59:36 INFO     Connection: ModbusTcpClient(11.11.11.1:502)
2022-01-27 09:59:42 INFO     Detected Model: SG8K-D
2022-01-27 09:59:42 INFO     Loading Export: exports\webserver
2022-01-27 09:59:42 INFO     Webserver: Configured
2022-01-27 09:59:42 INFO     Loading Export: exports\mqtt
2022-01-27 09:59:42 INFO     MQTT: Connected to localhost:1883
2022-01-27 09:59:42 INFO     Loading Export: exports\pvoutput
2022-01-27 09:59:54 INFO     PVOutput: Configured export to 7 Eastlake Ave every 5 minutes
2022-01-27 09:59:54 WARNING  Modbus connection failed: Modbus Error: [Input/Output] [Errno 104] Connection reset by peer
2022-01-27 09:59:55 ERROR    Unable to decode response Modbus Error: Unknown response 0
2022-01-27 09:59:55 ERROR    Modbus Error: [Input/Output] Unable to decode request
Traceback (most recent call last):
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/transaction.py", line 208, in execute
    self.client.framer.processIncomingPacket(response,
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
    self._process(callback, error=True)
  File "/home/dbonnell/.local/lib/python3.8/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
bohdan-s commented 2 years ago

I don't have a model that supports modbus, but looking at the other projects they constantly connected and disconnected, so I implemented the same thing. I am going to clean it up and just connect, and then reconnect only if there is an issue. I think all the connects / disconnects might be too much for the inverter. My HTTP method was falling over with connect/disconnect thats why i excluded the http connections

dbonnell commented 2 years ago

That's what I've just done to see if it makes a difference. In the scrape() method I wrapped the self.connect() at the top with a check that self.client != None and commented out the self.close() after it has scraped the registers.

If it fails to retrieve all of the registers it is calling self.disconnect() which will close the connection and reset the client to None, so that should take care of connecting again on the next scrape pass.

I tested the reconnect by manually disconnecting then reconnecting the inverter wifi connection. Seems to be working fine but the true test will be if it reconnects tomorrow morning after a prolonged period of disconnection.

Also, just a reminder about the error around line#59 in sungrow.py:

 elif self.config_inverter_configinverter['connection'] == "sungrow":

should be:

 elif self.inverter_config['connection'] == "sungrow":
dbonnell commented 2 years ago

Actually, I think the issue was duplicate connections as I first suspected. Here is a patch of the changes that I made: 0001-Fixed-issues-due-to-multiple-client-connections.txt

At the top of connect() before it calls self.client.connect() to open a new connection I first call self.client.close() to ensure any existing session is closed first.

def connect(self):
        if self.client:
            self.client.close()
            if(self.client.connect()):
                logging.debug("Opened session: " + str(self.client))
                return True
            else:
                self.disconnect()
        ...

I've removed the calls to connect, close and disconnect from scrape. All connection management is now done in the main loop which will either close or disconnect (forces new client to be created) the connection after scraping.

    # Core polling loop
    while True:
        loop_start = datetime.now()

        inverter.connect()

        # Scrape the inverter
        success = inverter.scrape()

        if(success):
            inverter.close()
            for export in exports:
                export.publish(inverter)
        else:
            inverter.disconnect()
            logging.warning(f"Data collection failed, skipped exporting data. Retying in {scan_interval} secs")

I've been running with those changes for a few minutes so far and haven't seen any Modbus errors. I also tested the disconnect/connect cycle by manually dropping the inverter wifi temporarily.

2022-01-27 12:57:35 INFO     MQTT: Message 50 Published
2022-01-27 12:57:50 INFO     Inverter: Successfully scraped in 1.515628 secs
2022-01-27 12:57:50 INFO     PVOutput: Data logged, next upload in 20 secs
2022-01-27 12:57:50 INFO     Next scrape in 13 secs
2022-01-27 12:57:50 INFO     MQTT: Message 51 Published
2022-01-27 12:58:14 ERROR    Connection to (11.11.11.1, 502) failed: timed out
2022-01-27 12:58:14 INFO     Disconnected: ModbusTcpClient(11.11.11.1:502)
2022-01-27 12:58:14 INFO     Connection: ModbusTcpClient(11.11.11.1:502)
2022-01-27 12:58:24 ERROR    Connection to (11.11.11.1, 502) failed: timed out
2022-01-27 12:58:28 INFO     Inverter: Successfully scraped in 1.446501 secs
bohdan-s commented 2 years ago

Thanks, I JUST published 0.3.2 with what i HOPE will fix the issues, I moved the connection checking to its own function, and changed all calls to that function. Connection is not just connection. It also adds a log to file option, so can have screen set to INFO and file set to DEBUG. Check the example config again. I'll review your changes above, since we know they work :) and see if i can merge them into 0.3.3 if 0.3.2 didn't work for you

dbonnell commented 2 years ago

Updated to 0.3.2 but all I get is the following then it just sits there, nothing more:

2022-01-27 13:06:26 INFO     Starting SunGather 0.3.2
2022-01-27 13:06:26 INFO     Loaded config: config.yaml
2022-01-27 13:06:26 INFO     Loaded registers: /mnt/d/work/sungrow/Sungather/SunGather/registers.yaml
2022-01-27 13:06:26 WARNING  Modbus client is not connected, attempting to reconnect
Modbus client is not connected, attempting to reconnect

I've reset to 0.3.1 and re-applied my patch for now.

bohdan-s commented 2 years ago

aahhh ok, I can see you are closing after each loop, but not disconnecting. Let me merge that in and see if it works with the HTTP as well

bohdan-s commented 2 years ago

I found the session left open... I pushed 0.3.2 again, could you test again for me @dbonnell ?

Also can you set the logging to: log_console: 'INFO' # [Optional] Default is WARNING, Options: OFF, DEBUG, INFO, WARNING, ERROR log_file: 'DEBUG' # [Optional] Default is OFF, Options: OFF, DEBUG, INFO, WARNING, ERROR

and upload the log if it fails again?

dbonnell commented 2 years ago

Will do. Where will the log file be?

bohdan-s commented 2 years ago

In the folder you run the script from. I’ll add an option for paths shortly, just need to sort out docker support as well.

dbonnell commented 2 years ago

That seems to have done the trick!

2022-01-27 16:49:22 INFO     Starting SunGather 0.3.2
2022-01-27 16:49:22 INFO     Loaded config: config.yaml
2022-01-27 16:49:22 INFO     Loaded registers: /mnt/d/work/sungrow/Sungather/SunGather/registers.yaml
2022-01-27 16:49:22 INFO     Logging to console set to: INFO
2022-01-27 16:49:22 INFO     Logging to file set to: DEBUG
2022-01-27 16:49:22 INFO     Modbus client is not connected, attempting to reconnect
2022-01-27 16:49:22 INFO     Connection: ModbusTcpClient(11.11.11.1:502)
2022-01-27 16:49:25 INFO     Detected Model: SG8K-D
2022-01-27 16:49:25 INFO     Closing Session: ModbusTcpClient(11.11.11.1:502)
2022-01-27 16:49:25 INFO     Loading Export: exports\webserver
2022-01-27 16:49:25 INFO     Webserver: Configured
2022-01-27 16:49:25 INFO     Loading Export: exports\mqtt
2022-01-27 16:49:25 INFO     MQTT: Connected to localhost:1883
2022-01-27 16:49:25 INFO     Loading Export: exports\pvoutput
2022-01-27 16:49:37 INFO     PVOutput: Configured export to 7 Eastlake Ave every 5 minutes
2022-01-27 16:49:37 INFO     Modbus, Connecting new session
2022-01-27 16:49:39 INFO     Inverter: Successfully scraped in 1.480265 secs
2022-01-27 16:49:39 INFO     MQTT: Published
2022-01-27 16:49:39 INFO     MQTT: Published Home Assistant Discovery messages
2022-01-27 16:49:40 INFO     PVOutput: Data uploaded
2022-01-27 16:49:40 INFO     Closing Session: ModbusTcpClient(11.11.11.1:502)
2022-01-27 16:49:40 INFO     Next scrape in 27 secs
dbonnell commented 2 years ago

I've noticed this occasionally:

2022-01-27 16:52:26 INFO     Loading Export: exports\pvoutput
2022-01-27 16:52:36 ERROR    PVOutput: Failed to configure
PVOutput: Failed to configure

Might be a timeout? It fails to upload to PVOutput after that but the next pass says the upload worked, so I think it recovers.

dbonnell commented 2 years ago

I only just noticed that the daily values in Grafana are not correct. Looks like the problem started on 25/1. image

Looks like you added a 0.1 scaling to a few of the daily registers in 0.3.0 so I can remove that scaling from the Grafana queries now.

image

I'll provide the updated dashboard once I've fixed all the queries.

dbonnell commented 2 years ago

Fixed. I deleted all of the data before 26/1 otherwise some of the data was scaled and some wasn't. In hindsight I could have just updated to apply the 0.1 scaling.

image

Here's the updated Grafana dashboard:

Solar System.zip

dbonnell commented 2 years ago

No issues reconnecting this morning. Seems to be stable again, thank you @bohdan-s

rianbk commented 2 years ago

So mine is still failing once a day overnight. Only a restart fixes it

2022-02-03 15:33:57 WARNING Modbus connection failed

Modbus connection failed

2022-02-03 15:33:58 ERROR index out of range

index out of range
2022-02-03 15:33:58 ERROR Modbus Error: [Input/Output] Unable to decode request

Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/pymodbus/transaction.py", line 208, in execute
self.client.framer.processIncomingPacket(response,
File "/usr/local/lib/python3.10/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
self._process(callback, error=True)

File "/usr/local/lib/python3.10/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request

Modbus Error: [Input/Output] Unable to decode request

Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/pymodbus/transaction.py", line 208, in execute
self.client.framer.processIncomingPacket(response,
File "/usr/local/lib/python3.10/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
self._process(callback, error=True)

File "/usr/local/lib/python3.10/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request

2022-02-03 15:33:58 WARNING Modbus connection failed

Modbus connection failed

2022-02-03 15:33:58 WARNING Data collection failed, skipped exporting data. Retying in 30 secs

Data collection failed, skipped exporting data. Retying in 30 secs
dbonnell commented 2 years ago

@rianbk I've been running for 8 days on the latest version without any failures. Some of the requirements were updated 8 days ago, including pymodbus>=2.5.3 (8 days ago). Maybe check they're all up to date.

pip install --upgrade -r requirements.txt
bohdan-s commented 2 years ago

@rianbk are you using Docker or Python directly? Can you confirm you have the latest requirements and what version of SunGather? I was REALLY hopping the last version was stable, its why I have help off any updates for the last week, I want to get it as stable as possible before making any changes

rianbk commented 2 years ago

@rianbk are you using Docker or Python directly? Can you confirm you have the latest requirements and what version of SunGather? I was REALLY hopping the last version was stable, its why I have help off any updates for the last week, I want to get it as stable as possible before making any changes

Docker, the container auto updates when there is a new version

image

bohdan-s commented 2 years ago

Interesting, could you provide the console/log at the time it stops, and then around the time you would expect it to start again? It should be doing a fresh connection every time it fails, so I am not sure why its not reconnecting.

dbonnell commented 2 years ago

@rianbk are you use Watchtower to auto update your Docker container?

rianbk commented 2 years ago

@rianbk are you use Watchtower to auto update your Docker container?

I run this on unraid, so it has a auto update feature, but Watchtower should do the trick.

Things seem to be have running stable for a while now. I have noticed this in the logs however.

2022-02-19 00:12:27 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:12:57 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:13:27 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:13:58 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:14:28 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:14:58 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:15:28 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:15:58 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:16:28 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:16:58 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:17:28 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:17:58 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:18:28 ERROR PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

PVOutput: Upload Failed; 400 Message; Bad request 400: Moon Powered

2022-02-19 00:18:57 WARNING PVOutput: Over 30 data points scheduled to upload. max is 30 so removing oldest data point
bohdan-s commented 2 years ago

Ha. That’s cool. Either your Timezone is wrong (do the times look right?) or a small amount of power is being generated by the array from the moon. if the times are right all add some code to drop the data after a moon response so it doesn’t try to keep resubmitting it.

rianbk commented 2 years ago

Ha. That’s cool. Either your Timezone is wrong (do the times look right?) or a small amount of power is being generated by the array from the moon. if the times are right all add some code to drop the data after a moon response so it doesn’t try to keep resubmitting it.

Timeszone is fine, from the logs it seems to be always happening up to 20mins after midnight. Inverter itself isn't registering any power

And if i have a look at the export to HASS, i dont see any power reading either. image

bohdan-s commented 2 years ago

Thanks. I’ll have a look at what’s causing it.

bohdan-s commented 2 years ago

Can you have a look at 0.3.4 it should hopefully resolve the issue, And will output a bit more info if its not resolved

rianbk commented 2 years ago

Can you have a look at 0.3.4 it should hopefully resolve the issue, And will output a bit more info if its not resolved

Latest Logs

2022-03-04 00:01:46 INFO Starting SunGather 0.3.4
2022-03-04 00:01:46 INFO Loaded config: /config/config.yaml
2022-03-04 00:01:46 INFO Loaded registers: /usr/src/sungather/registers.yaml
2022-03-04 00:03:30 WARNING Modbus connection failed

Modbus connection failed

2022-03-04 00:03:40 WARNING Modbus connection failed

Modbus connection failed

2022-03-04 00:03:50 WARNING Modbus connection failed

Modbus connection failed

2022-03-04 00:03:50 WARNING Data collection failed, skipped exporting data. Retying in 30 secs

Data collection failed, skipped exporting data. Retying in 30 secs

2022-03-04 00:03:50 WARNING SunGather is taking 30.08 to process, which is longer than interval 30, Please increase scan interval

SunGather is taking 30.08 to process, which is longer than interval 30, Please increase scan interval
bohdan-s commented 2 years ago

Does it reconnect when the sun comes up? Some models don’t return data when solar isn’t being produced.

rianbk commented 2 years ago

Does it reconnect when the sun comes up? Some models don’t return data when solar isn’t being produced.

My model operates 24/7 (its one of the new models that do to capture night time usage of grid power). It just seems to be something that happens when it flicks over to the new day.

It did recover by it self.