MichaluxPL / Sofar_LSW3

Get MODBUS data from Sofar (K-TLX) inverter through LSW-3 or LSE module
GNU General Public License v3.0
94 stars 45 forks source link

No access to PV logger every morning #46

Closed ilexpl01 closed 9 months ago

ilexpl01 commented 1 year ago

Cześć Michale,

I've setup your script and get all the data from logger - that looks fine :)

Unfortunatelly almost every morning the script is kind of stuck. It does not collect any data untill I login to logger website and reset it:

image

Device information Device serial number1774324xxx Firmware versionLSW3_15_FFFF_1.0.57

The script is started by Synology NAS every minute. I does check if PV logger is pingable:

!/bin/bash

Settings

PV_IP="hidden" # PV IP Address

Check if PV Logger is contactable

PINGTIME=ping -c 1 -q $PV_IP | awk -F"/" '{print $5}' | xargs

echo $PINGTIME if expr "$PINGTIME" '>' 0 then echo "rozpoczynam odczyt danych ..." python3 /volume1/docker/domoticz/scripts/sofar/InverterData.py else echo "brak komunikacji !!!" fi

Any advice ?

Maybe some kind of timeout flag within python script would do the trick ?

Pozdrawiam Mikołaj

MichaluxPL commented 1 year ago

Hi, Have exactly the same problem - surprisingly it started to occur some time ago (didn't see it at first). It's obviously some kind of a logger's bug. Unfortunately no timeout will do the trick :( I've prepared an automated approach to restart logger just after it comes to life every morning (run from crontab). It starts before sunrise and waits for the logger to start responding. Then restarts it. Here is the code of python script to do it - feel free to adapt/use it:

#!/usr/bin/python3

import urllib3
import subprocess
from selenium import webdriver
from selenium.webdriver.common.keys import Keys
from selenium.webdriver.common.by import By
from selenium.webdriver.chrome.options import Options
from selenium.webdriver.support.ui import WebDriverWait
from time import sleep
from datetime import datetime

# Ping to check logger's availability
param = "-c"
host = "LOGGER's IP HERE in x.x.x.x format"
command = ["ping", param, "1", host]
while subprocess.call(command) != 0:
 sleep(60)
print("Logger ON ! ", str(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))

# When logger is up, wait 15min, then restart
sleep(900)
print("Restarting loggeer at ",str(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))
username="admin"
password="LOGGER's password here"
chromedriver = '/usr/bin/chromedriver'
option = webdriver.ChromeOptions();
option.add_argument('headless');
browser = webdriver.Chrome(chromedriver,options=option)
try:
  browser.get('http://admin:LOGGER's password here@LOGGER's IP here/restart.html')
except:
  browser.quit()

try:
  browser.find_element_by_id("btn1").submit()
  print("Logger restarted")
except:
  print("Error restarting logger")
  browser.quit()
browser.quit()
ilexpl01 commented 1 year ago

Thank You for a fast reply. I have spent some time to get chrom runing within docker container + chromedriver installation.

If I run my test script I get an error:

root@domoticz:/opt/domoticz/userdata/scripts/sofar# python3 /opt/domoticz/userdata/scripts/sofar/PVloggerRestart.py PING 192.168.100.241 (192.168.100.241) 56(84) bytes of data. 64 bytes from 192.168.100.241: icmp_seq=1 ttl=254 time=2.96 ms

--- 192.168.100.241 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.964/2.964/2.964/0.000 ms Logger ON ! 2022-09-16 12:14:29 Restarting loggeer at 2022-09-16 12:14:34 <<changed to 5 seconds /opt/domoticz/userdata/scripts/sofar/PVloggerRestart.py:29: DeprecationWarning: executable_path has been deprecated, please pass in a Service object browser = webdriver.Chrome(chromedriver,options=option) Traceback (most recent call last): File "/opt/domoticz/userdata/scripts/sofar/PVloggerRestart.py", line 29, in browser = webdriver.Chrome(chromedriver,options=option) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/chrome/webdriver.py", line 72, in init service_log_path, service, keep_alive) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/chromium/webdriver.py", line 97, in init options=options) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/remote/webdriver.py", line 270, in init self.start_session(capabilities, browser_profile) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/remote/webdriver.py", line 363, in start_session response = self.execute(Command.NEW_SESSION, parameters) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/remote/webdriver.py", line 428, in execute self.error_handler.check_response(response) File "/usr/local/lib/python3.7/dist-packages/selenium/webdriver/remote/errorhandler.py", line 243, in check_response raise exception_class(message, screen, stacktrace) selenium.common.exceptions.WebDriverException: Message: unknown error: Chrome failed to start: exited abnormally. (unknown error: DevToolsActivePort file doesn't exist) (The process started from chrome location /usr/bin/chromium is no longer running, so ChromeDriver is assuming that Chrome has crashed.) Stacktrace:

0 0x563826122e89

But if I run a test script:

!/usr/bin/python3

from selenium import webdriver

options = webdriver.ChromeOptions() options.add_argument('--headless')

options.add_argument('window-size=1200x600')

options.add_argument('--no-sandbox') options.add_argument('--disable-dev-shm-usage')

browser = webdriver.Chrome(chrome_options=options)

If the chromedriver is not set in the PATH environment variable, specify the chromedriver location with the executable_path option.

browser = webdriver.Chrome(chrome_options=options, executable_path="/usr/local/bin/chromedriver")

url = "http://192.168.100.241/index_cn.html"

browser.get(url) browser.save_screenshot("Website.png") browser.quit()

I do get the website screenshot

image

Any advice ?

Additional question:

Why in Your script You want to define username and password and later same data has to be filled in code:

browser.get('http://admin:LOGGER's password here@LOGGER's IP here/restart.html')

ilexpl01 commented 1 year ago

after couple of hours :) ......

Got the python script running.

!/usr/bin/python3

import urllib3 import subprocess from selenium import webdriver from selenium.webdriver.common.keys import Keys from selenium.webdriver.common.by import By from selenium.webdriver.chrome.options import Options from selenium.webdriver.support.ui import WebDriverWait from time import sleep from datetime import datetime

options = webdriver.ChromeOptions() options.add_argument('--headless') options.add_argument('--no-sandbox')

host = "192.168.100.241" #LOGGER's IP HERE in x.x.x.x format" username = "master" #LOGGER's username password = "sonoff" #LOGGER's password next_ping = 60 restart_delay = 900 param = "-c" count = "1" command = ["ping", param, count, host]

Ping to check logger's availability

while subprocess.call(command) != 0: sleep(next_ping) print("Logger ON ! ", str(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))

When logger is up, wait 15min, then restart

sleep(restart_delay) print("Restarting loggeer at ",str(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))

browser = webdriver.Chrome(options=options)

url = "http://"+username+":"+password+"@"+host+"/restart.html"

try: browser.get(url) except: browser.quit()

try: browser.find_element(By.ID,'btn1').submit() print("Logger restarted") except: print("Error restarting logger") browser.quit() browser.quit()

but .............................

With the help from Sofar Poland I got my logger upgraded to newest version:

image

Maybe that would solve my problem. Will keep the topic updated

ilexpl01 commented 1 year ago

Upgrade of the logger to 1.0.84 version was not muche helpfull :/

MichaluxPL commented 1 year ago

That's a pity - I hoped it would fix it ... BTW - could You share logger's upgrade file ? Can You see any noticeable changes in logger's GUI after the upgrade ?

ilexpl01 commented 1 year ago

Hi

The upgrade was performed remotely by Sofar Poland. Just give them a call (waited over 90 minutes in a queue for the operator) and have the SN of your inverter by hand.

I do not see ANY noticeable changes. I still have a hiccups with logger communication. I run Domoticz. Created a script that runs every minute from sunrise till sunset and check if there was a positive data transfer from logger. If not the logger is restarted. Will tune my script to see how many restarts I have daily.

On the other hand I am thinking to replace LSW-3 logger to LSE-3 version (runs over ethernet cable). Have You got any opinion regarding LSE-3 model ?

MichaluxPL commented 1 year ago

I only have to restart LSW-3 at the beginning of each day. Then it works correctly. Strangely it started to have problems after a few months of using. No LSW-3's firmware of inverter's firmware was changed. Regarding LSE-3 - don't have any experience with it. I guess it only differs by the connection type.

ilexpl01 commented 1 year ago

Hi

Have replaced LSW-3 with LSE-3, changed inverter_sn in config.cfg.

Here is the output:

root@domoticz:/opt/domoticz/userdata/scripts/sofar# python3 InverterHWData.py
Modbus request: 0104 2000 000e 7a0e
Hex string to send: A5 1700 1045 0000 7c5b657d 020000000000000000000000000000 01042000000e7a0e 00 15
Data sent: bytearray(b'\xa5\x17\x00\x10E\x00\x00|[e}\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x04 \x00\x00\x0ez\x0e\x00\x15')
Data received: b'\xa5\x17\x00\x10E\x03\x00\xfc\x02'
Hex string received: A5 17 00 10 45 03 00 FC 02
Traceback (most recent call last):
File "InverterHWData.py", line 121, in
val1=chr(int(str(responsereg[0:2]),16))
ValueError: invalid literal for int() with base 16: ''

root@domoticz:/opt/domoticz/userdata/scripts/sofar# python3 InverterData.py
Connecting to logger... connected successfully !
*** Chunk no: 0
Sent data: bytearray(b'\xa5\x17\x00\x10E\x00\x00|[e}\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x03\x00\x00\x00(E\xd4\x00\x15')
Received data: b'\xa5\x17\x00\x10E\x03\x00\xfc\x02'
No value in response for register 0x0000
Check register start/end values in config.cfg

Any advice ?

MichaluxPL commented 1 year ago

Looks like LSE protocol specs differ form LSW-3 (Your LSE-3 in particular, because I've seen some confirmations before it was working with my script). I think I've seen a time ago some info about new devices protocol changes on elektroda.pl. Unfortunately I can't help with that. You'd need exact protocol specs and change the script accordingly.

ilexpl01 commented 1 year ago

Update:

Moved from LSW-3 to LSE3. Factory firmware of LSE-3 was ME_0A_2701_5.02. Upgraded to version: ME_08_2708_2.06 and .......... it looks fine (30 minutes test period) :)

So far with LSW-3 my logger was restarted round about 10 times a day :/

I'll watch the situation with new logger & firmware in the next days.

rimelis commented 1 year ago

@ilexpl01 Could I kindly ask you where you get the newer firmware for your stick?

lszeremeta commented 1 year ago

@ilexpl01 Could I kindly ask you where you get the newer firmware for your stick?

You can ask support to update firmware remotely if you use Solarman Smart or Solarman Business.

ilexpl01 commented 1 year ago

IMHO I know when the script does not get the data from logger but I do not know how to solve it.

EVERY morning my Domoticz does restart the logger (every 4 minutes) couple of times untill there is a value in Current power field.

While there is no value (example below):

image

the script fails to retreive data.

I GUESS :)

rimelis commented 1 year ago

The webpage of logger doesn't parse data of newer inverters well. I have 11KTLX G3 connected and do not see any values in status page except some crazy number in Total yield. However it doesn't mean that logger is not communicating with inverter as https://home.solarmanpv.com/ shows everything correctly.

ilexpl01 commented 1 year ago

@ilexpl01 Could I kindly ask you where you get the newer firmware for your stick?

Here You are. ME_08_2701_2.06U.bin.zip

ilexpl01 commented 1 year ago

@ilexpl01 Could I kindly ask you where you get the newer firmware for your stick?

Here You are. ME_08_2701_2.06U.bin.zip

maxxximatoze commented 1 year ago

@ilexpl01 Could I kindly ask you where you get the newer firmware for your stick?

Here You are. ME_08_2701_2.06U.bin.zip

Hello, can you please tell me if your LSE3 logger is the USB or RS232 version ? because I have an USB version plugged into a HYD6000-EP with firmware ME_0D_270A_1.08U.bin (also tried ME_0D_270A_1.09U.bin) and it does not works, but works greats with LSW3 USB logger. I would like to know if I can flash it with ME_08_2701_2.06U.bin which seems to be the version that works ? Thanks in advance.

Best regards.

miikaforma commented 9 months ago

A little information I gathered from this issue. I dockerized this 2 days ago (https://hub.docker.com/r/miikaforma/sofar-lsw3-logger). After the first night, I noticed it didn't log any entries in the morning. Solarman smart app showed the inverter as offline while it said the logger is online. Running this script locally at the time would sometimes give data and sometimes an error. After I turned off the docker container, the inverter popped online and running the script locally would always give data without errors. I then restarted the docker container and it started logging normally as well. This lead me to believe that the script is either keeping some connection open or spamming requests in a loop and never finishes (the spamming kind of would make more sense in regards that running it locally would sometimes work).

Anyways, I changed the command I had from this:

command: ['/bin/bash', '-c', 'while true; do python3 /app/InverterData.py; sleep 60; done']

to this

command: ['/bin/bash', '-c', 'while true; do timeout 30s python3 /app/InverterData.py; if [ $$? -eq 124 ]; then echo "The command exceeded the 30 second timeout."; fi; sleep 60; done']

And tomorrow morning everything was working fine. I then checked the logs and it shows that the 30 second timeout had happened 6 times after which the script has been logging normally.

docker service logs sofar_logger.1.wx65hark5qqaq3onwomu2vb9x --timestamps --details &> sofar_logs.txt

2023-09-18T04:00:27.199805128Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Could not open socket - inverter/logger turned off
2023-09-18T04:01:37.413437656Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Could not open socket - inverter/logger turned off
2023-09-18T04:02:47.666154682Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Could not open socket - inverter/logger turned off
2023-09-18T04:04:17.677417781Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:05:47.684637193Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:07:17.691211300Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:08:47.697526487Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:10:17.740519184Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:11:47.747357854Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  Terminated
2023-09-18T04:12:48.511617111Z sofar_logger.1.wx65hark5qqa@instance-20220403-1746    |  *** JSON output:

So yeah, all this leads me to believe there's something in the script that could be changed to fix it. But finding out where exactly the issues is, is another thing. I'm not too familiar with Python to know what all the code does. Though I guess adding more print commands in the loops and before/after the commands that request data from the logger would likely show which part is the culprit. Just too bad it seems to require always waiting for the next day to actually get the issue to show up 😅

miikaforma commented 9 months ago

Ok, think I figured it out. I added some debug prints of my own (https://github.com/miikaforma/Sofar_LSW3/commit/d522871a0fc0e6bcd00e5cdb51aa7e03dca7ed47) and today got the results.

2023-09-19T04:12:01.261920060Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Connecting to logger... Could not open socket - inverter/logger turned off
2023-09-19T04:13:11.469887479Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Connecting to logger... Could not open socket - inverter/logger turned off
2023-09-19T04:14:11.728353245Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Connecting to logger... connected successfully !
2023-09-19T04:14:11.728521205Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:11.728710205Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:11.728716565Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:12.195699042Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:12.195731242Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Entering while a<=i
2023-09-19T04:14:12.224245404Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Exited while a<=i
2023-09-19T04:14:12.224257484Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:12.224408844Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:12.224415244Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:12.523381428Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:12.523411828Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:12.523415028Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:12.523417548Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:12.711579563Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:12.711726643Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:12.711863443Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:12.711870763Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:12.903286698Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:12.903320898Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:12.903606138Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:12.903624818Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:13.101132913Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:13.101161473Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:13.101721754Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:13.101736154Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:13.285477128Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
2023-09-19T04:14:13.285508448Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sending data with clientSocket.sendall
2023-09-19T04:14:13.285688288Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Sent data successfully with clientSocket.sendall
2023-09-19T04:14:13.285695408Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Receiving data with clientSocket.recv(1024)
2023-09-19T04:14:13.485232504Z sofar_logger.1.mh8wvwjewl83@instance-20220403-1746    |  Received data with clientSocket.recv(1024)
... same looping over and over

So, I'm guessing the invstatus gets set to 0 here: https://github.com/MichaluxPL/Sofar_LSW3/blob/main/InverterData.py#L210C25-L210C36

And after that it's in a forever loop because the invstatus will always be 0 and never again goes inside this block: https://github.com/MichaluxPL/Sofar_LSW3/blob/main/InverterData.py#L175

After that it hangs the inverter/logger with too many requests. But when you restart the logger, it probably hits the sys.exit(1) or something and that's why it starts working again.

Btw, I think this will be problematic as well? https://github.com/MichaluxPL/Sofar_LSW3/blob/main/InverterData.py#L173C9-L173C21

MichaluxPL commented 9 months ago

I've made a small fix for this loop condition - please check it out. Please let me know about the results :)

miikaforma commented 9 months ago

It seems to be working at least for me now 👍 . It prints inverter status as "Stand-by" for a few times and then it becomes "Normal" (which it didn't do before).

MichaluxPL commented 9 months ago

I've made some additional fixes for this one. Now script shouldn't even try to send/receive more data to/from the logger, when it reports inverter's status <> 0 (Normal). I've also added log file config options together with some debug info. Tested it locally and looks like the logger does not hang anymore :) @miikaforma thanks for nailing it down :+1:

ilexpl01 commented 9 months ago

It seems to be working at least for me 2 now :). Good job !

ciao87 commented 1 month ago

M

Has got someone the firmware file ME_0D_270A_1.08U.bin and ME_0D_270A_1.09U.bin ?