Build 3088 - SFTP issues

[Vegit8]

MX b3088
running on W10 laptop
I have just updated this instance from 3072 - which was running fairly reliably.
I have been updating another installation of a friends laptop running ubuntu/Mono and a WLL. After a lot of help from Mark this is now running fine for days on end.

Yesterday I updated my install and have started to get FTP issues - similar to those experienced on the Ubuntu version.

Code: Select all

2020-07-15 08:44:14.656 Realtime[50]: Start cycle
2020-07-15 08:44:14.656 Realtime[50]: Creating realtime.txt
2020-07-15 08:44:14.674 Realtime[50]: Processing extra file[0] - C:\CumulusMX\web\realtimegauges.txt
2020-07-15 08:44:14.680 Realtime[50]: Uploading - realtime.txt
2020-07-15 08:44:14.680 SFTP[50]: Starting Upload of realtime.txt to weather/realtime.txt

Loop data removed for brevity

2020-07-15 08:44:33.818 SFTP[50]: Error uploading realtime.txt to weather/realtime.txt : An established connection was aborted by the server.
2020-07-15 08:44:33.848 Realtime[50]: Uploading - realtimegauges.txt
2020-07-15 08:44:33.848 SFTP[50]: Starting Upload of web\realtimegauges.txt to weather/realtimegauges.txt
2020-07-15 08:44:33.849 SFTP[50]: Error uploading web\realtimegauges.txt to weather/realtimegauges.txt : Client not connected.
2020-07-15 08:44:33.849 Realtime[50]: Uploading extra web file[0] C:\CumulusMX\web\realtimegauges.txttmp to weather/realtimegauges.txt
2020-07-15 08:44:33.849 SFTP[50]: Starting Upload of C:\CumulusMX\web\realtimegauges.txttmp to weather/realtimegauges.txt
2020-07-15 08:44:33.850 SFTP[50]: Error uploading C:\CumulusMX\web\realtimegauges.txttmp to weather/realtimegauges.txt : Client not connected.
2020-07-15 08:44:33.850 Realtime[50]: End cycle

Looking at the logs over a period, my FTP cycles normally complete in about .5 of a second

Code: Select all

2020-07-15 08:43:34.654 Realtime[48]: Start cycle
2020-07-15 08:43:35.172 Realtime[48]: End cycle

Obviously there was some kind of issue on the server that caused the FTP to fail in cycle [50]

From that point onwards successive attempts continued to fail

Code: Select all

2020-07-15 08:44:34.669 Realtime[51]: Start cycle
2020-07-15 08:44:34.669 Realtime[51]: Creating realtime.txt
2020-07-15 08:44:34.686 Realtime[51]: Processing extra file[0] - C:\CumulusMX\web\realtimegauges.txt
2020-07-15 08:44:34.696 Realtime[51]: Realtime ftp attempting disconnect
2020-07-15 08:44:34.696 Realtime[51]: Realtime ftp disconnected OK
2020-07-15 08:44:34.696 Realtime[51]: Realtime ftp attempting to reconnect
Loop data
2020-07-15 08:44:49.697 Realtime[51]: Error reconnecting ftp server - Connection failed to establish within 15000 milliseconds.
2020-07-15 08:44:49.697 Realtime[51]: Realtime ftp attempting to reinitialise the connection
2020-07-15 08:44:49.698 SFTP[51]: Attempting realtime SFTP connect to host 94.136.40.104 on port 22

At this point [51] stops and [52] starts a new cycle

Code: Select all

2020-07-15 08:44:54.670 Realtime[52]: Start cycle
2020-07-15 08:44:54.670 Realtime[52]: Creating realtime.txt
2020-07-15 08:44:54.691 Realtime[52]: Processing extra file[0] - C:\CumulusMX\web\realtimegauges.txt
2020-07-15 08:44:54.698 Realtime[52]: Warning, a previous cycle is still trying to connect to FTP server, skip count = 1
2020-07-15 08:44:54.698 Realtime[52]: No FTP attempted this cycle
2020-07-15 08:44:54.698 Realtime[52]: End cycle

FTPlog.txt just has repeated instances of...
# Dispose()
Status: Disposing FtpClient object...

Diags file attached

[mcrossley]

Thanks. So close!

It is doing what I expected now, on failure it tried to disconnect (failed), tried a reconnect (failed), established a new connection (worked).

But it had fallen through to some exception catch code at that point, and that does not clear the FTP in progress flag, so subsequent real time FTP cycles failed. I need to add clearing the in progress flag to the catch code and it *should* work as intended. That will be in the next full release.

[Vegit8]

Hi Mark
Excellent, thanks
as a side note, I checked the connectivity of my FTP server whilst MX was having issues, and got in fine.

Cheers

[mcrossley]

MX Started at 08:27
Connection first failed at 08:44 - successfully reconnected.
Disconnected again at 09:10 - successfully reconnected.
Disconnected again at 09:27 - successfully reconnected.
Disconnected again at 09:30 - successfully reconnected.
Disconnected again at 09:33 - successfully reconnected.
Disconnected again at 09:54 - reconnected, but hit the bug in MX.

So it doesn't look like the SFTP connection to your host is terribly reliable.

Also noted in that log file that there is problem with your dayfile at line 2117 that needs fixing.

[Vegit8]

Hi Mark
The error that I could find in the diags referred to line 2117 in Jul20log.txt

I have looked at the relevant row, and compared it to others and I cant see any problem with it.
Could you have a look for me please...

[mcrossley]

Sorry, yep, wrong file name - and nope I cannot see anything wrong with the file either!

I also tried the file in my dev install and it read it without error.

[mcrossley]

The other thing is that you are forcing the console to send the entire logger contents on start-up because the console log interval is set to 30 minutes, and MX is using 5 minutes.

[Vegit8]

The other thing is that you are forcing the console to send the entire logger contents on start-up because the console log interval is set to 30 minutes, and MX is using 5 minutes.

Hmm, I didnt know I was doing that. Secondly I cant even find a setting where I can change that. It was not a conscious decision.

[mcrossley]

You have to change the console logger interval from the WeatherLink software, or fire up a terminal emulator and send it the command...
SETPER 5

Where 5 is the interval in mutes.

Doing this will clear all your logger history.

[Vegit8]

Hah
Thanks for that, would never have guessed to look there!