realtime.txt oddity

[Adrian Hudson]

My realtime.txt has stopped FTPing. It has worked for ever until the day before yesterday whereupon it (and just it, all other files are FTPing fine) just stopped. I was nowhere near the PC so it wasn't me who broke it - honest!

An excerpt from the realtimeftplog.txt looks like thus:

07:58:22:356 ========= Start of realtime FTP ==========
07:58:22:356 ===Start of realtime.txt upload
07:58:22:357 05378E90 TriggerDataSent 1176
07:58:22:357 >|200 Type set to A.|

07:58:23:357 Putting file
07:58:23:357 ! HighLevelAsync 0
07:58:23:357 05378E90 TriggerDataSent 1176
07:58:23:358 >|200 PORT command successful.|

07:58:23:358 ! HighLevelAsync 0
07:58:23:359 05379650 TCustomWSocket.Shutdown 1 1188
07:58:24:358 Putting done
07:58:24:358 Renaming file
07:58:24:358 ! HighLevelAsync 0
07:58:24:358 05378E90 TriggerDataSent 1176
07:58:24:358 >|550 |

07:58:25:358 Renaming done
07:58:25:358 ===End of upload of realtime.txt
07:58:25:358 ===Processing CUtags.php
07:58:25:358 ===Processing c:\cumulus\cumuluswebtags.php
07:58:25:358 ===Processing c:\cumulus\myrealtime.txt
07:58:25:359 ===Processing latest.txt
07:58:25:359 ===Processing plaintext.txt
07:58:25:359 ===Processing willand.pdf
07:58:25:359 ===Processing realtimelog.txt
07:58:25:359 ===Processing davcon24.txt
07:58:25:359 ===Processing cumulus.xml
07:58:25:359 05378E90 TriggerDataSent 1176
07:58:25:359 >|200 Type set to A.|

07:58:26:359 Putting file
07:58:26:359 ! HighLevelAsync 0
07:58:26:359 05378E90 TriggerDataSent 1176
07:58:26:360 >|200 PORT command successful.|

07:58:26:360 ! HighLevelAsync 0
07:58:26:360 ! Data Session requested
07:58:26:360 05379650 Socket accepted 864
07:58:26:361 05379650 TCustomWSocket.Shutdown 1 788
07:58:26:361 ! Data Session opened
07:58:26:361 05378E90 TriggerDataSent 1176
07:58:26:361 05379650 TriggerDataSent 864
07:58:26:361 >|125 Data connection already open; Transfer starting.|

07:58:26:362 DataSocketPutDataSent 2467
07:58:26:362 05379650 TriggerDataSent 864
07:58:26:362 DataSocketPutDataSent 0
07:58:26:362 05379650 TCustomWSocket.Shutdown 1 864
07:58:26:370 ! Data Session closed
07:58:26:370 ! Next3PutAsync
07:58:26:370 05379650 TCustomWSocket.Shutdown 1 864
07:58:26:370 >|226 Transfer complete.|
.
.
and so on..
.
.

...so, as you can see, I am receiving an error 550 which means "Requested action not taken. File unavailable (e.g., file not found, no access)."

the other files, again as you can see, are fine.

550 can mean a permissions issue or the file just isn't there. In this case, I have checked permissions and there are no problems - that file (via the folder inheritance permissions) is set to "Everyone - Full control" and also the user the FTP is logging on as, also has Full control. The transfer is currently set to "Use FTP rename" and the 550 occurs during the attempt to rename.

I have tried setting Cumulus to "Use FTP rename" = off, but that makes no difference. This is what the log file looks like with this option set off:

21:15:25:058 ===Start of realtime.txt upload
21:15:25:063 05668E90 TriggerDataSent 1168
21:15:25:063 >|200 Type set to A.|

21:15:26:058 Putting file
21:15:26:058 ! HighLevelAsync 0
21:15:26:059 05668E90 TriggerDataSent 1168
21:15:26:059 >|200 PORT command successful.|

21:15:26:059 ! HighLevelAsync 0
21:15:26:059 05669650 TCustomWSocket.Shutdown 1 1184
21:15:27:058 Putting done

...no indication that there is any problem. The file simply does not get transferred.

The realtime.txt file is being created every 5 seconds as per the settings and if I transfer it to the web server manually using FTP, it goes fine.

All the files named on the Files tab in the Cumulus Internet settings are transferred fine by Cumulus - including a couple a that are marked "Realtime?" ticked - which go every 5 seconds as configured. So, the only file that is not transferring is realtime.txt.

In the end, to keep things going, I have written a little program that FTPs the realtime.txt file that I run alongside Cumulus - and that works fine.

Any help - any ideas - from anyone would be gratefully received since I have run out of ideas!

Thanks!!

[steve]

Cumulus does exactly the same thing for realtime.txt as it does for 'extra' realtime files, so I don't know why there would be a difference. Have you tried restarting Cumulus? Have you tried passive ftp mode (assuming that works with your setup)?

If there are no errors returned when not renaming, it sounds like a problem with the server (despite it working with an ftp client). Or at least something that has changed at the server end.

[Adrian Hudson]

Hello Steve, I hope you are having a great Christmas up there!

Yes, tried restarting Cumulus, rebooting the Cumulus PC and the server too. Tried passive and active FTP. Also tried creating a folder on the server and putting its name into the "directory" setting - the graphs etc went in there but nooooo realtime.txt! Most odd! Both manually FTPing with DOS FTP command and using a program (Autoit) send the file fine.

I think you must be right about it being the server end, but I have no idea why just this one file should not go when all the others do.

The annoying thing is that it just stopped... all on its own! Grrr.

Thanks for the suggestions anyway.

Adrian

[Adrian Hudson]

Interesting...

Looking at the FTP server logs, I can see STOR commands and RNFR (rename from) and RNTO (rename to) commands being processed for the extra realtime files but I can only see a RNFR command for realtime.txt - no STOR or RNFR. Cumulus isn't sending the file before it tries to rename it.

(or, if it is sending it, it isn't getting as far as the server - not even a failing attempt to store it.

[beteljuice]

Has your host done something 'silly' like not accepting .txt extensions ?

[steve]

I think that after this response from the server:

07:58:23:358 >|200 PORT command successful.|

the server should open the connection for the transfer of the data (in active mode), and it appears that it is not doing that. Or perhaps it is supposed to do that in response to the STOR command, which it isn't seeing? It's hard to see what's going on because the logging isn't very good. If the FTP component isn't issuing the STOR command for some reason, I don't know why that would be. If it was having trouble accessing the realtime.txt file, for example, I would expect it to throw an exception, and it isn't doing that. Are you doing anything else with the realtime.txt file other than having Cumulus FTP it?

[steve]

I've realised that some time ago, I worked out how to get the ftp logging to be a bit more useful by actually showing the commands it was sending. But I only changed the 'normal' ftp and not the realtime ftp; I've now done that. If you unzip the attached file into your Cumulus installation to replace the cumulus.exe file, it might get us a bit further. Or not...

[Adrian Hudson]

Steve, thank you very much for the version with better logging. See below.

It looks like it isn't attempting the STOR command to me but see what you think.

Without changing anything, if I run my own little program that FTP's the file, using the same credentials etc, the file FTPs fine - still.

To answer some of the questions posed above. No, the receiving server is not set to reject .txt files and no, I'm not doing anything else with realtime.txt.

Does Cumulus use the same form of authentication for the realtime transfer as for the other files sent by FTP?

Its interesting that a couple of other files that I send using the Files tab in Internet settings with the Realtime box ticked, transmit fine. What would happen if I added realtime.txt as an extra file on the Files tab? Would it get its knickers in a twist?

12:26:45:885 ========= Start of realtime FTP ==========
12:26:45:885 ===Start of realtime.txt upload
12:26:45:885 TYPE A
12:26:45:891 05648E90 TriggerDataSent 1112
12:26:45:891 >|200 Type set to A.|

12:26:46:886 Putting file
12:26:46:886 ! HighLevelAsync 0
12:26:46:886 PASV
12:26:46:886 05648E90 TriggerDataSent 1112
12:26:46:887 >|227 Entering Passive Mode (192,168,0,3,236,142).|

12:26:46:887 ! HighLevelAsync 0
12:26:47:886 Putting done
12:26:47:886 Renaming file
12:26:47:886 ! HighLevelAsync 0
12:26:47:886 RNFR realtime.txttmp
12:26:47:886 05648E90 TriggerDataSent 1112
12:26:47:887 >|550 |

12:26:48:886 Renaming done
12:26:48:886 ===End of upload of realtime.txt
12:26:48:886 ===Processing cumulus.xml
12:26:48:886 TYPE A
12:26:48:886 05648E90 TriggerDataSent 1112
12:26:48:887 >|200 Type set to A.|

12:26:49:886 Putting file
12:26:49:886 ! HighLevelAsync 0
12:26:49:886 PASV
12:26:49:886 05648E90 TriggerDataSent 1112
12:26:49:887 >|227 Entering Passive Mode (192,168,0,3,236,143).|

12:26:49:887 ! HighLevelAsync 0
12:26:49:887 05649650 Socket handle created 1156
12:26:49:887 TWSocket will connect to 192.168.0.3:60559
12:26:49:888 ! Data Session opened (Put)
12:26:49:888 STOR cumulus.xmltmp
12:26:49:888 05649650 TriggerDataSent 1156
12:26:49:888 05648E90 TriggerDataSent 1112
12:26:49:889 >|125 Data connection already open; Transfer starting.|

12:26:49:889 ! Send first block
12:26:49:889 DataSocketPutDataSent 2461
12:26:49:889 05649650 TriggerDataSent 1156
12:26:49:889 DataSocketPutDataSent 0
12:26:49:889 05649650 TCustomWSocket.Shutdown 1 1156
12:26:49:898 ! Data Session closed
12:26:49:898 ! Next3PutAsync
12:26:49:898 05649650 TCustomWSocket.Shutdown 1 1156
12:26:49:898 >|226 Transfer complete.|

12:26:49:898 ! Next3PutAsync
12:26:49:898 ! HighLevelAsync 0
12:26:49:898 ! HighLevelAsync done
12:26:50:886 Putting done
12:26:50:886 Renaming file
12:26:50:886 ! HighLevelAsync 0
12:26:50:886 RNFR cumulus.xmltmp
12:26:50:886 05648E90 TriggerDataSent 1112
12:26:50:887 >|350 Requested file action pending further information.|

12:26:50:887 ! HighLevelAsync 0
12:26:50:887 RNTO cumulus.xml
12:26:50:887 05648E90 TriggerDataSent 1112
12:26:50:891 >|250 RNTO command successful.|

12:26:50:891 ! HighLevelAsync 0
12:26:50:891 ! HighLevelAsync done
12:26:51:886 Renaming done
12:26:51:886 ===Processing cumulusajax.xml
12:26:51:886 TYPE A
12:26:51:893 05648E90 TriggerDataSent 1112
12:26:51:893 >|200 Type set to A.|

12:26:52:886 Putting file
12:26:52:886 ! HighLevelAsync 0
12:26:52:886 PASV
12:26:52:892 05648E90 TriggerDataSent 1112
12:26:52:892 >|227 Entering Passive Mode (192,168,0,3,236,144).|

12:26:52:892 ! HighLevelAsync 0
12:26:52:892 05649650 Socket handle created 1172
12:26:52:892 TWSocket will connect to 192.168.0.3:60560
12:26:52:893 ! Data Session opened (Put)
12:26:52:893 STOR cumulusajax.xmltmp
12:26:52:893 05649650 TriggerDataSent 1172
12:26:52:893 05648E90 TriggerDataSent 1112
12:26:52:894 >|125 Data connection already open; Transfer starting.|

12:26:52:894 ! Send first block
12:26:52:894 DataSocketPutDataSent 32768
12:26:52:896 05649650 TriggerDataSent 1172
12:26:52:896 DataSocketPutDataSent 32768
12:26:52:897 05649650 TriggerDataSent 1172
12:26:52:897 DataSocketPutDataSent 21137
12:26:52:898 05649650 TriggerDataSent 1172
12:26:52:898 DataSocketPutDataSent 0
12:26:52:898 05649650 TCustomWSocket.Shutdown 1 1172
12:26:52:915 ! Data Session closed
12:26:52:915 ! Next3PutAsync
12:26:52:915 05649650 TCustomWSocket.Shutdown 1 1172
12:26:52:915 >|226 Transfer complete.|

12:26:52:915 ! Next3PutAsync
12:26:52:915 ! HighLevelAsync 0
12:26:52:915 ! HighLevelAsync done
12:26:53:886 Putting done
12:26:53:886 Renaming file
12:26:53:886 ! HighLevelAsync 0
12:26:53:886 RNFR cumulusajax.xmltmp
12:26:53:886 05648E90 TriggerDataSent 1112
12:26:53:889 >|350 Requested file action pending further information.|

12:26:53:889 ! HighLevelAsync 0
12:26:53:889 RNTO cumulusajax.xml
12:26:53:889 05648E90 TriggerDataSent 1112
12:26:53:892 >|250 RNTO command successful.|

12:26:53:892 ! HighLevelAsync 0
12:26:53:892 ! HighLevelAsync done
12:26:54:886 Renaming done
12:26:54:886 ========= End of realtime FTP ==========

[steve]

The realtime FTP code is basically the same as the normal FTP code. The main differences are that the realtime ftp stays connected (unless you tell it not to) and the realtime ftp doesn't do a CWD on the server, it uses the full remote file path. The difference between the realtime.txt upload and other file uploads is that it determines the full local path of the realtime.txt file by prepending the directory that the Cumulus executable is in, and it creates the full remote path by prepending the ftp directory as configured in the internet settings (and a 'slash', unless the ftp directory is null) whereas for 'extra' files you have to specify the full paths for both the local and remote files.

So a reasonable guess would be that it's the creation of the local or remote path that is causing the problem (i.e. the result is something invalid) but for some reason no error is thrown.

You can add realtime.txt as an extra file without it causing any problems. If that makes it work, then that would seem to confirm that the above guess is correct. How that could have started happening without anything changing is a mystery.

[Adrian Hudson]

It gets stranger and stranger. I did that. I put realtime.txt in as an additional FTP file with realtime ticked. It doesn't send it that way either.

Below, you can see it sending the previous file (cumulusajax.xml) followed by realtime.txt. It just doesn't attempt the STOR.

Permissions on the sending realtime.txt are fine and it is not locked (I can delete it and cumulus just makes a new one within a second or two). Permissions look fine on the folder (and if it is there, the realtime.txt) at the other end and the FTP logs show no attempt to store it.

snip ---

13:46:28:878 ===Processing cumulusajax.xml
13:46:28:878 TYPE A
13:46:28:878 055E8E90 TriggerDataSent 1108
13:46:28:878 >|200 Type set to A.|

13:46:29:878 Putting file
13:46:29:878 ! HighLevelAsync 0
13:46:29:878 PASV
13:46:29:878 055E8E90 TriggerDataSent 1108
13:46:29:879 >|227 Entering Passive Mode (192,168,0,3,223,221).|

13:46:29:879 ! HighLevelAsync 0
13:46:29:879 055E9650 Socket handle created 1172
13:46:29:879 TWSocket will connect to 192.168.0.3:57309
13:46:29:879 ! Data Session opened (Put)
13:46:29:879 STOR cumulusajax.xml
13:46:29:880 055E9650 TriggerDataSent 1172
13:46:29:880 055E8E90 TriggerDataSent 1108
13:46:29:881 >|125 Data connection already open; Transfer starting.|

13:46:29:881 ! Send first block
13:46:29:881 DataSocketPutDataSent 32768
13:46:29:883 055E9650 TriggerDataSent 1172
13:46:29:883 DataSocketPutDataSent 32768
13:46:29:884 055E9650 TriggerDataSent 1172
13:46:29:884 DataSocketPutDataSent 21245
13:46:29:885 055E9650 TriggerDataSent 1172
13:46:29:885 DataSocketPutDataSent 0
13:46:29:885 055E9650 TCustomWSocket.Shutdown 1 1172
13:46:29:899 ! Data Session closed
13:46:29:899 ! Next3PutAsync
13:46:29:900 055E9650 TCustomWSocket.Shutdown 1 1172
13:46:29:900 >|226 Transfer complete.|

13:46:29:900 ! Next3PutAsync
13:46:29:900 ! HighLevelAsync 0
13:46:29:900 ! HighLevelAsync done
13:46:30:878 Putting done
13:46:30:878 ===Processing realtime.txt
13:46:30:878 TYPE A
13:46:30:878 055E8E90 TriggerDataSent 1108
13:46:30:879 >|200 Type set to A.|

13:46:31:878 Putting file
13:46:31:878 ! HighLevelAsync 0
13:46:31:878 PASV
13:46:31:878 055E8E90 TriggerDataSent 1108
13:46:31:879 >|227 Entering Passive Mode (192,168,0,3,223,222).|

13:46:31:879 ! HighLevelAsync 0
13:46:32:878 Putting done
13:46:32:878 ========= End of realtime FTP ==========

snip ---

[Adrian Hudson]

!!!!!!!!!!!!!!!!!!!!!!!

While I was typing that last post, it started transmitting. I touched nothing (I was typing the post!). It is sending it twice now! Once the normal way and once as an extra FTP file! I am loathe to touch it to take the extra file out!! I think I will leave it well alone a day or two and then take out the extra FTP file and see what happens.

How weird is that??!!??

Edit: It survived me ending and restarting Cumulus to stop the ftp logging

[steve]

That is very weird. I can't begin to imagine what might be going on.

[Adrian Hudson]

That is very weird. I can't begin to imagine what might be going on.

Me neither and managing IT is my job!

p.s. Just seen the Cumulus MX - Nice one. Have applied to beta test it. Might side-step this issue!