Randomly stops sending data

bram2202 commented 5 years ago

Logger randomly stops sending data to mqtt and PVoutput. Some days there are no problems at all, and some days its really bad .

mqtt broker gives error: Socket error on client GoodWeLogger-303e, disconnecting.
PVoutput shows dip: LINK

I tried to watch for errors in the debug output from the logger, but due to its randomness i didn't encounter any problems at the time.

The wifi signal strength inst the problem, the logger / inverter has a direct line of sight to the AP 6m away.

jantenhove commented 5 years ago

I also noticed this recently. I added some extra debug info, but I'm still unable to catpure the stops. It's hard to guess when and where it stops without logs.

bram2202 commented 5 years ago

I switched to a other mqtt broker, and I noticed that there are no drops in messaging, but today so far Pvoutput has dropped out 5 times.

https://pvoutput.org/intraday.jsp?id=68792&sid=61781

PeeVv commented 5 years ago

I also seem to have this problem.

At random intervals the logger stops receiving data. The RS485 RX/TX leds don't blink anymore and the orange power led on the GoodWe lights up solid instead of blinking. Resetting the ESP doesn't seem to work, after some time it starts working again.
PV output shows drops, the same as @bram2202
There are no MQTT messages received, this can sometimes be 30+ minutes after which it starts to work again. PVoutput never drops longer than 10 minutes it seems.
On rare occasions the logger stops working completely, and only a hard reset works.

The ESP is connected to a steady high quality power supply and is near an Unifi access point, so Wifi should not be the issue. The broker is Mosquitto installed on Debian.

PeeVv commented 5 years ago

I checked some debug logs, and the probleem seems to be in the communication with the inverter.

The ESP sends the sendRemoveRegistration data to the inverter. Then it starts sending the sendDiscovery data every 10 seconds. It now takes a long time, 10+ minutes, for the inverter to respond. This is the discovery data:

Sending discovery Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 .

During this time the power light on the inverter is solid orange. After 10+ minutes the inverter sends data and it all works perfectly. The power light now flashes orange.

After some time however, the ESP seems to lose the connection/restart, and the discovery process starts again, and again it takes 10+ minutes for the inverter to respond.

I am not sure why the ESP loses the connection, and whether the discovery takes a long time due to the workings of the inverter or due to a bug in the software. Does anyone have an idea?

-edit-

The solid orange color corresponds with "ON = WiFi CONNECTED / ACTIVE" according to the manual, which is strange because the whole wifi module is disconnected. Reconnecting the wifi module, restarting the inverter, resetting wifi, disconnecting the wifi module and restarting the inverter does not change this status. The blinking pattern possibly corresponds to "BLINK = RS485 CONNECTED", but it looks more like the pattern of "BLINK 1 = WiFi SYSTEM RESETTING", which also would be strange.

jantenhove commented 5 years ago

The inverter has a 10 minute timeout for connected RS485 devices. When the ESP 'thinks' it is no longer connected to the inverter it restarts the discovery. When the inverter still thinks it has a connected logger, it will wait for 10 minutes to start responding to the discovery.

There are 2 issues that need to be addressed:

Why does the ESP thinks it is no longer connected? For this we need (debug) logs.
When the ESP goes in a disconnected state, it will clear the 'reservation' from the inverter. This is clearly not working for your inverter. Did the ESP failed to send it, or did the inverter ignore this message?

Do you have the logs prior to Sending discovery Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . ?

The orange led behavior is the same on my inverter.

Did you compile the project with the latest ESP8266 Arduino core: https://github.com/esp8266/Arduino

PeeVv commented 5 years ago

I have an output log with the debug flag of GoodWeCommunicator and PVOutputPublisher set to true.

The relevant (I think) part shows the inverter stops responding to the data:

Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD .
Parsing incoming data with length: 0x43 . 0xAA 0x55 0x1 0xAB 0x1 0x81 0x3C 0x9 0x41 0x9 0x63 0x0 0x3C 0x0 0x42 0x9 0x61 0x0 0x78 0x13 0x88 0xB 0xA0 0x0 0x1 0x1 0x7E 0x0 0x0 0x0 0x0 0x0 0x0 0x11 0x95 0x0 0x0 0x2 0x2D 0x3 0xF2 0x0 0x0 0x0 0xC8 0x1 0x60 0xE 0x2E 0x0 0x14 0x0 0x5C 0x13 0x8 0xB 0xF 0x15 0x12 0x0 0x0 0x0 0x0 0x0 0x8 0x0 0x0 0xA 0x48 .
CRC received: 0xA 0x48 , calculated CRC: 0xA 0x48 .
CRC match.
Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD .
Sending discovery
Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 .
Sending discovery
Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 .

This is the whole data log: out.txt

I stopped it when the inverter stopped responding, but this continued until the timeout of the inverter.

Are there any other debug settings I must use?

jantenhove commented 5 years ago

Thanks for the debug log. You stopped logging too soon however :) The inverter did not respond on the request for information. When this happens the inverter will be marked offline by the ESP after 30 seconds. The discovery is sent every 10 seconds, so we need an extra 10 seconds of logging to see if the ESP marks the inverter offline (and removes the registration).

djares01 commented 4 years ago

I have a similar problem, I started your logger for first time 3 days ago, the first 2 days I used the code with the softserial problem, but yesterday I used the new code, but still same problem.

After a random time, some hours, inverter stops responding to commands and I have to fisically shutdown inverter from grid and PV to restore connectivity (this morning I tried to reboot through internal webpage but not resolved). Today I put the log on, so I will write you the logs if I have the same behaviour, I have changed poll time to 5 seconds, maybe 1seconds was to much.

My goodwe is a GW3648EM

djares01 commented 4 years ago

This night again, this is when happened:

02:47:16.484 -> Sending discovery 02:47:16.484 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:47:16.718 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:17.171 -> Parsing incoming data with length: 0x89 . 0xAA 0x55 0x1 0xAB 0x1 0x81 0x82 0x0 0x0 0x0 0x0 0x0 0x1 0x0 0x0 0x9 0x40 0x0 0x0 0x13 0x87 0xFF 0x7B 0x0 0x0 0x0 0xB3 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0x64 0x0 0x0 0x2 0xD4 0x29 0x9 0x0 0x0 0xB 0x77 0x3 0x0 0x0 0x0 0x0 0x3 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0xF9 0x1 0x0 0x0 0x85 0x0 0x3 0x0 0x0 0x17 0xFC 0x0 0x0 0x9 0x40 0x0 0x2 0x0 0x2 0x1 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xFF 0x7B 0x0 0x2 0x14 0x4 0x4 0x2 0x30 0xC 0x3 0xE8 0x0 0x0 0x0 0x1 0x0 0x1 0x0 0x0 0x0 0x1 0x0 0x0 0x0 0x20 0x0 0x2 0x0 0x1 0x0 0x0 0x0 0x0 0x10 0x8 0x40 0x44 0x0 0x0 0x0 0x8 0xE 0x54 . 02:47:17.218 -> CRC received: 0xE 0x54 , calculated CRC: 0xE 0x54 . 02:47:17.218 -> CRC match. 02:47:21.765 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:22.375 -> Parsing incoming data with length: 0x89 . 0xAA 0x55 0x1 0xAB 0x1 0x81 0x82 0x0 0x0 0x0 0x0 0x0 0x1 0x0 0x0 0x9 0x40 0x0 0x0 0x13 0x86 0xFF 0x7E 0x0 0x0 0x0 0xB3 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0x64 0x0 0x0 0x2 0xD4 0x29 0x9 0x0 0x0 0xB 0x75 0x3 0x0 0x0 0x0 0x0 0x3 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0xF9 0x1 0x0 0x0 0x82 0x0 0x3 0x0 0x0 0x17 0xFC 0x0 0x0 0x9 0x40 0x0 0x2 0x0 0x2 0x1 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xFF 0x7E 0x0 0x3 0x14 0x4 0x4 0x2 0x30 0x12 0x3 0xE8 0x0 0x0 0x0 0x1 0x0 0x1 0x0 0x0 0x0 0x1 0x0 0x0 0x0 0x20 0x0 0x2 0x0 0x1 0x0 0x0 0x0 0x0 0x10 0x8 0x40 0x44 0x0 0x0 0x0 0x8 0xE 0x5B . 02:47:22.421 -> CRC received: 0xE 0x5B , calculated CRC: 0xE 0x5B . 02:47:22.421 -> CRC match. 02:47:26.468 -> Sending discovery 02:47:26.468 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:47:26.750 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:27.375 -> Parsing incoming data with length: 0x89 . 0xAA 0x55 0x1 0xAB 0x1 0x81 0x82 0x0 0x0 0x0 0x0 0x0 0x1 0x0 0x0 0x9 0x3F 0x0 0x0 0x13 0x87 0xFF 0x80 0x0 0x0 0x0 0xB3 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0x64 0x0 0x0 0x2 0xD4 0x29 0x9 0x0 0x0 0xB 0x74 0x3 0x0 0x0 0x0 0x0 0x3 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x19 0xF9 0x1 0x0 0x0 0x80 0x0 0x3 0x0 0x0 0x17 0xFC 0x0 0x0 0x9 0x3F 0x0 0x2 0x0 0x2 0x1 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xFF 0x80 0x0 0x3 0x14 0x4 0x4 0x2 0x30 0x17 0x3 0xE8 0x0 0x0 0x0 0x1 0x0 0x1 0x0 0x0 0x0 0x1 0x0 0x0 0x0 0x20 0x0 0x2 0x0 0x1 0x0 0x0 0x0 0x0 0x10 0x8 0x40 0x44 0x0 0x0 0x0 0x8 0xE 0x60 . 02:47:27.421 -> CRC received: 0xE 0x60 , calculated CRC: 0xE 0x60 . 02:47:27.421 -> CRC match. 02:47:31.750 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:41.500 -> Sending discovery 02:47:41.500 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:47:41.500 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:46.500 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:51.531 -> Sending discovery 02:47:51.531 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:47:51.531 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:56.562 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x1 0x1 0x0 CRC high/low: 0x1 0xAD . 02:47:57.406 -> Marking inverter @ address: 1offline. 02:47:57.406 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x1 0x0 0x2 0x0 CRC high/low: 0x1 0xAD . 02:48:01.531 -> Sending discovery 02:48:01.531 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:48:01.531 -> Not asking inverter with address: 1 for information. Addressconfirmed: 0, isOnline: 0. 02:48:06.546 -> Not asking inverter with address: 1 for information. Addressconfirmed: 0, isOnline: 0. 02:48:11.515 -> Sending discovery 02:48:11.515 -> Sending data to inverter(s): 0xAA 0x55 0xAB 0x7F 0x0 0x0 0x0 CRC high/low: 0x2 0x29 . 02:48:11.562 -> Not asking inverter with address: 1 for information. Addressconfirmed: 0, isOnline: 0. 02:48:16.562 -> Not asking inverter with address: 1 for information. Addressconfirmed: 0, isOnline: 0.

And now is always with the same message in bucle after 7h

jantenhove commented 4 years ago

I also have this issue., after 2 years of flawless functioning. So far I have tested the following

Changed interval to 10 seconds, detection interval if one inverter is found to 30 minutes -> no effect
Used latest SoftwareSerial (from GitHub) -> no effect
Used an older version of SoftwareSerial -> no effect
More logging to check if it's a firmware problem -> no effect
Used S/W counting instead of interrupts for the SoftwareSerial -> no effect
Tried with slightly higher/lower baudreates -> no effect.

I have also implemented remote logging (using telnet) so I can also test the hardware serial and see if the problem still occurs.

It seems like invalid data is sent to the inverter after which the inverter stops responding for a long time (10+ hours). Resetting the ESP does not have any effect.

djares01 commented 4 years ago

Have you tried to contact goodwe? Maybe is and error in their firmware.

djares01 commented 4 years ago

@jantenhove I see you've added a remote logging and some changes, but I can't compile, it gives a lots of erros (I've included this library https://github.com/JoaoLopesF/RemoteDebug )

The biggest error is this: 'class RemoteDebug' has no member named 'isRunning'

It's seems isRunning is not and instruction that RemoteDebug accepts.

jantenhove / GoodWeLogger

Randomly stops sending data #16