ftp uploads failing

[billy]

Over the past 10 days or so some of my ftp uploads fail. Sometimes CMX's recovery system works as planned and on the next cycle or two the upload resumes. However, for some the failure remains on all subsequent cycles and only a restart of CMX can restore the upload. Typically, this seems to become the case for about 3 files each day. The files that fail in this way vary - sometimes it is a standard file (eg realtime.txt), sometimes an extra web file (I have 8 of these at various intervals), and sometimes a MySQL upload. And yes I realize the number of different files being uploaded is profligate!

These uploads have been working for a long time - ie several years - albeit in various forms - but no recent changes

I think the failing files are usually being uploaded at the realtime interval (12 seconds) although the MySQL file that failed on a couple of occasions is at 1 minute intervals. The realtime uploads are finished within 3 seconds - when working correctly

I'm using plain simple ftp, and have tried two different, and completely independent, commercial web servers. The failures have occurred across both recent releases b3190 and b3184.

Attached is a recent diagnostic file where four files became "stuck" and CMX was never was able to restart them - until I restarted CMX.

I'd be grateful if those who are able to read these "tea leaves" can give me an insight into what the cause may be or better still what the fix is!

Some key time-points in the file:

FIRST
2022-07-03 16:55:09.336 ProcessTemplateFile: Error writing to file 'web_cmxui/realtimetagsT.phptmp'
Successful recovery from this error after a couple more attempts

SECOND
2022-07-04 00:06:45.279 Error encountered during Realtime file update.
2022-07-04 00:06:45.279 Sharing violation on path /home/linc/CumulusMX/realtime.txt
Remains in error until CMX restarted

THIRD
2022-07-04 00:20:09.455 ProcessTemplateFile: Error writing to file 'web_cmxui/realtimetagsT.phptmp'
Remains in error until CMX restarted

FOURTH
2022-07-04 01:29:09.386 ProcessTemplateFile: Error writing to file 'web/cumuluswebtags.txttmp'
Remains in error until CMX restarted


FIFTH
2022-07-04 02:14:09.509 ProcessTemplateFile: Error writing to file 'web_cmxui/realtime-xT.txttmp'
Remains in error until CMX restarted

[mcrossley]

Please see if you still have this issue with the latest version - v3.19.0 - just released.

[billy]

Thanks for the quick reply Mark. I have installed v3.19.0 and will report back in the morning (perth time, which is UTC +08) by which time I would expect the errors to have appeared if they are going to occur.

[billy]

The problem continues after the upgrade. Two uploads at the realtime interval failed ... the first from 00:19 hours and the second from 00:25. Also the MySQL at 1 minute intervals failed after success at 01:10 and never resumed although the log file suggests it did - the entry "Upload of failed MySQL commands complete." is not supported by the table itself, which has no rows added after 01:10.

[billy]

OK, after some further investigation ... ie reading the diags file carefully

The upload of a file fails permanently (ie until a restart) when it fails once AND then the second attempt to upload also fails.

All the failures seem to occur because other processes delay the ftp uploads - in my case it seems to be managing the Davis loop data. I don't know why dealing with the Davis data takes so long.

What follows is a more more verbose explanation. Or just take a look at the realtime cycles [195] - [197] compared to [218] - [219] in the zip. They are around 08:47 - 08:51 this morning.

Be aware that on my system it typically takes a little less than 3" to complete a realtime ftp upload sequence, well within the 12" realtime interval. e.g. a nice ftp cycle is like this:
2022-07-06 08:46:48.510 Realtime[195]: Start cycle
... it's all over in less than 3"
2022-07-06 08:46:51.171 Realtime[195]: End cycle

But the next cycle [196] gets interrupted for about 9" by reading Davis station data and doesn't complete before the next cycle [197] starts.
2022-07-06 08:47:00.510 Realtime[196]: Start cycle
... ftp uploads start and are then paused while Davis data are dealt with
2022-07-06 08:47:01.178 LOOP: 43 - Data packet is good
2022-07-06 08:47:03.172 LOOP: 44 - Data packet is good
2022-07-06 08:47:05.172 LOOP: 45 - Data packet is good
2022-07-06 08:47:07.177 LOOP: 46 - Data packet is good
2022-07-06 08:47:09.170 LOOP: 47 - Data packet is good
... ftp uploads resume but are not completed because time runs out and the next cycle starts
2022-07-06 08:47:12.213 Realtime[196]: Uploading extra web file[0] web/cumuluswebtags.txttmp to /public_html/vp2waw/utils/webtagData.php
2022-07-06 08:47:12.214 FTP[196]: Uploading web/cumuluswebtags.txttmp to /public_html/vp2waw/utils/webtagData.phptmp
2022-07-06 08:47:12.510 Realtime[197]: Start cycle
... this cycle is abandoned because when it tries to ftp the file at the interruption point of [196] ... extra web file [0] ... it can't access the file I suspect:
2022-07-06 08:47:12.645 Realtime[197]: No FTP attempted this cycle
2022-07-06 08:47:12.645 Realtime[197]: End cycle
2022-07-06 08:47:12.668 FTP[196]: Renaming /public_html/vp2waw/utils/webtagData.phptmp to /public_html/vp2waw/utils/webtagData.php
... returns to complete the previous cycle [196]
2022-07-06 08:47:13.828 Realtime[196]: End cycle

So the moral of the story so far is CMX has a neat elegant way of dealing with such happenings.

But just a few minutes later this system fails because the recovery system is itself interrupted while cmx deals with some more Davis data:
first the intial interruption:
2022-07-06 08:51:24.511 Realtime[218]: Start cycle
... starts uploading, pauses for davis data, resumes, then the next cycle starts before [218] is complete.
2022-07-06 08:51:36.432 Realtime[218]: Uploading extra web file[1] web_cmxui/realtime-xT.txttmp to /public_html/vp2cmxui/realtime-x.txt
2022-07-06 08:51:36.433 FTP[218]: Uploading web_cmxui/realtime-xT.txttmp to /public_html/vp2cmxui/realtime-x.txttmp
2022-07-06 08:51:36.511 Realtime[219]: Start cycle
... starts uploads, chokes at the file which was at the interruption point during the last cycle so
2022-07-06 08:51:36.565 Realtime[219]: No FTP attempted this cycle
2022-07-06 08:51:36.565 Realtime[219]: End cycle
... then would expect it to go back to deal with remnants of the previous cycle [218] but reading Davis data gobbles up all the time before the next cycle [220] starts
2022-07-06 08:51:37.184 LOOP: 34 - Data packet is good
2022-07-06 08:51:39.182 LOOP: 35 - Data packet is good
2022-07-06 08:51:41.432 LOOP: 36 - Data packet is good
2022-07-06 08:51:43.177 LOOP: 37 - Data packet is good
2022-07-06 08:51:45.185 LOOP: 38 - Data packet is good
2022-07-06 08:51:47.179 LOOP: 39 - Data packet is good
2022-07-06 08:51:48.511 Realtime[220]: Start cycle

From this point on, the file that has failed twice to upload continues to fail until a cmx restart.

[mcrossley]

OK, I will give a fuller analysis later, but the processing of the data from the station and the FTP are on different threads and independent from each other.

When you say that FTP is "interrupted" for 9 seconds by reading station data, what is actually happening is that the reading of station data is continuing whilst the FTP process is stalled awaiting a response from the server.

This is a recurring pattern. I've started with your first log file and when that fails the same thing happens.

A file rename takes 9.5 seconds to be processed by the server, and the next FTP upload never gets a response from the server, nor does it timeout which is the bigger problem - I'm investigating if a setting has changed on newer versions of the FTP client...

[mcrossley]

Do you have the FTP log file for when one of these errors occurs?

[billy]

Thank goodness you can sensibly interpret the diags logs - clearly I can easily jump to incorrect conclusions! I had assumed the ftp log was incorporated into the diags file, and have just discovered the (very large) ftplog.txt. I will trim it a little and pm it to you. And try and reduce my public faux pas count

[mcrossley]

It does seem to be a bug in the FTP client.

When asked to transfer a file and the server does not respond, the FTP client eventually sends a Socket Poll on the command connection, when it fails to get a response from that it aborts the upload and disposes of the socket stream. However it does not appear to free the file hande to the local file.

The client then reconnects and things carry on, but from that point onwards processing of the initial file that failed to FTP fails with a sharing violation as the client is still holding it open

What I can do is try a brute force approach, so that if a reconnect is required, I completely destroy the previous FTP client and create a new one. That *should* release any resources the old client was holding open.

This is impossible for me to test as I cannot simulate the "hung" connection, if I stop my FTP server or disconnect it from the network I just get a timeout and everything carries on as normal when it can reconnect.

[billy]

Mark, many thanks - I've been running your latest release 3.19.1 b3194 for almost two days without any FTP (or MySQL) errors. Your efforts are much appreciated