"The weather station is currently offline" error

[DanielF]

You should also look at using ftp rename instead of 'delete before upload'. Assuming your ftp server supports ftp rename...

I'm pretty sure I tried that a week or so back, and the results were worse (more 'station offline' errors). (I have no control over the server FTP service - it belongs to someone else.) But once we get realtime uploading going consistently, I'll have another look at that.

[DanielF]

Steve,

I've set RTdisconnectcount=0, and then I followed your suggestion and re-tried 'rename' rather than 'delete'. The effect was immediate - my gauges stopped responding!

At the same time, I turned on FTP logging again, and sent the resulting log to the guy (Ian) who manages the web pages that host 'Gerroa-Weather'. He asked that I post the following extract from the log, with his comments:

"This is the part to post, it shows two successful transfers and then it keeps aborting .... on the server the file realtimegauges.txttmp exists with zero bytes length. If I manually delete it the updates continue for a while until the same happens again. Im my opinion, there is an issue with the rename code within Cumulus. Thanks."

Code: Select all

20:01:09:567 ! Send first block
20:01:09:567 DataSocketPutDataSent 1362
20:01:09:567 032A7EF0 TriggerDataSent 888
20:01:09:567 DataSocketPutDataSent 0
20:01:09:567 032A7EF0 TCustomWSocket.Shutdown 1 888
20:01:09:786 ! Data Session closed
20:01:09:786 ! Next3PutAsync
20:01:09:786 032A7EF0 TCustomWSocket.Shutdown 1 888
20:01:09:848 >|226 File receive OK.|

20:01:09:848 ! Next3PutAsync
20:01:09:848 ! HighLevelAsync 0
20:01:09:848 ! HighLevelAsync done
20:01:10:052 ! HighLevelAsync 0
20:01:10:052 032A77E0 TriggerDataSent 980
20:01:10:130 >|350 Ready for RNTO.|

20:01:10:130 ! HighLevelAsync 0
20:01:10:130 032A77E0 TriggerDataSent 980
20:01:10:208 >|250 Rename successful.|

20:01:10:208 ! HighLevelAsync 0
20:01:10:208 ! HighLevelAsync done
20:01:17:052 032A77E0 TriggerDataSent 980
20:01:17:130 >|200 Switching to ASCII mode.|

20:01:18:052 ! HighLevelAsync 0
20:01:18:052 032A77E0 TriggerDataSent 980
20:01:18:130 >|227 Entering Passive Mode (203,16,214,120,130,93)|

20:01:18:130 ! HighLevelAsync 0
20:01:18:130 TWSocket will connect to 203.16.214.120:33373
20:01:18:192 ! Data Session opened (Put)
20:01:18:192 032A7EF0 TriggerDataSent 916
20:01:18:192 032A77E0 TriggerDataSent 980
20:01:18:270 >|150 Ok to send data.|

20:01:18:270 ! Send first block
20:01:18:270 DataSocketPutDataSent 1363
20:01:18:270 032A7EF0 TriggerDataSent 916
20:01:18:270 DataSocketPutDataSent 0
20:01:18:270 032A7EF0 TCustomWSocket.Shutdown 1 916
20:01:18:364 ! Data Session closed
20:01:18:364 ! Next3PutAsync
20:01:18:364 032A7EF0 TCustomWSocket.Shutdown 1 916
20:01:18:583 >|226 File receive OK.|

20:01:18:583 ! Next3PutAsync
20:01:18:583 ! HighLevelAsync 0
20:01:18:583 ! HighLevelAsync done
20:01:19:052 ! HighLevelAsync 0
20:01:19:052 032A77E0 TriggerDataSent 980
20:01:19:114 >|350 Ready for RNTO.|

20:01:19:114 ! HighLevelAsync 0
20:01:19:114 032A77E0 TriggerDataSent 980
20:01:19:177 >|250 Rename successful.|

20:01:19:177 ! HighLevelAsync 0
20:01:19:177 ! HighLevelAsync done
20:01:26:052 032A77E0 TriggerDataSent 980
20:01:26:130 >|200 Switching to ASCII mode.|

20:01:27:052 ! HighLevelAsync 0
20:01:27:052 032A77E0 TriggerDataSent 980
20:01:27:130 >|227 Entering Passive Mode (203,16,214,120,130,173)|

20:01:27:130 ! HighLevelAsync 0
20:01:27:130 TWSocket will connect to 203.16.214.120:33453
20:01:27:192 ! Data Session opened (Put)
20:01:27:192 032A7EF0 TriggerDataSent 856
20:01:27:192 032A77E0 TriggerDataSent 980
20:01:27:302 >|150 Ok to send data.|

20:01:27:302 ! Send first block
20:01:27:302 DataSocketPutDataSent 1363
20:01:27:302 032A7EF0 TriggerDataSent 856
20:01:27:302 DataSocketPutDataSent 0
20:01:27:302 032A7EF0 TCustomWSocket.Shutdown 1 856
20:01:27:364 ! Data Session closed
20:01:27:364 ! Next3PutAsync
20:01:27:364 032A7EF0 TCustomWSocket.Shutdown 1 856
20:01:27:505 >|226 File receive OK.|

20:01:27:505 ! Next3PutAsync
20:01:27:505 ! HighLevelAsync 0
20:01:27:505 ! HighLevelAsync done
20:01:28:052 ! HighLevelAsync 0
20:01:28:052 032A77E0 TriggerDataSent 980
20:01:28:130 >|350 Ready for RNTO.|

20:01:28:130 ! HighLevelAsync 0
20:01:28:130 032A77E0 TriggerDataSent 980
20:01:28:223 >|250 Rename successful.|

20:01:28:223 ! HighLevelAsync 0
20:01:28:223 ! HighLevelAsync done
20:01:35:052 032A77E0 TriggerDataSent 980
20:01:35:130 >|200 Switching to ASCII mode.|

20:01:36:052 ! HighLevelAsync 0
20:01:36:052 032A77E0 TriggerDataSent 980
20:01:36:130 >|227 Entering Passive Mode (203,16,214,120,130,233)|

20:01:36:130 ! HighLevelAsync 0
20:01:36:130 TWSocket will connect to 203.16.214.120:33513
20:01:36:177 ! Data Session opened (Put)
20:01:36:177 032A7EF0 TriggerDataSent 888
20:01:36:177 032A77E0 TriggerDataSent 980
20:01:36:270 >|150 Ok to send data.|

20:01:36:270 ! Send first block
20:01:36:270 DataSocketPutDataSent 1363
20:01:36:270 032A7EF0 TriggerDataSent 888
20:01:36:270 DataSocketPutDataSent 0
20:01:36:270 032A7EF0 TCustomWSocket.Shutdown 1 888
20:01:52:052 ! Aborting
20:01:52:052 ! HighLevelAsync 0
20:01:52:052 ! Abort detected
20:01:52:052 ! HighLevelAsync done
20:01:52:052 032A7EF0 TCustomWSocket.Shutdown 1 888
20:01:52:052 ! Data Session closed
20:01:52:052 ! Next3PutAsync
20:01:52:052 ! HighLevelAsync 0
20:01:52:052 FTP Error: FTP component not connected
20:01:52:052 Aborting
20:01:52:052 ! Aborting
20:01:53:052 Realtime FTP Connect attempt
20:01:53:052 ! HighLevelAsync 0
20:01:53:130 TWSocket will connect to 203.16.214.120:21
20:01:53:223 032A77E0 TriggerDataSent 896
20:01:53:348 >|220 (19) NOTICE TO USERS: Warning! The use of this system is restricted to authorised users only. All information and communications on this system are subject to security review, monitoring and recording at any time, without notice or permission. Unauthorised access or use shall be subject to prosecution.|

20:01:53:348 ! HighLevelAsync 0
20:01:53:348 032A77E0 TriggerDataSent 896
20:01:53:427 >|331 Please specify the password.|

20:01:53:427 ! HighLevelAsync 0
20:01:53:427 032A77E0 TriggerDataSent 896
20:01:53:598 >|230-|

20:01:53:598 >|230-Last Updated:   Thu Sep  6 01:54:54 2012|

20:01:53:598 >|230-Home Directory: /webspace/users.on.net/data/D8/65/D865572|

20:01:53:598 >|230-Disk Usage:     691588 kbytes|

20:01:53:598 >|230-|

20:01:53:598 >|230 Login successful.|

20:01:53:598 ! HighLevelAsync 0
20:01:53:598 ! HighLevelAsync done
20:01:53:598 Realtime FTP Connected
20:01:53:598 032A77E0 TriggerDataSent 896
20:01:53:677 >|200 Switching to ASCII mode.|

20:01:54:598 ! HighLevelAsync 0
20:01:54:598 032A77E0 TriggerDataSent 896
20:01:54:677 >|227 Entering Passive Mode (203,16,214,120,207,184)|

20:01:54:677 ! HighLevelAsync 0
20:01:54:677 TWSocket will connect to 203.16.214.120:53176
20:01:54:739 ! Data Session opened (Put)
20:01:54:739 032A7EF0 TriggerDataSent 980
20:01:54:739 032A77E0 TriggerDataSent 896
20:02:10:598 ! Aborting
20:02:10:598 ! HighLevelAsync 0
20:02:10:598 ! Abort detected
20:02:10:598 ! HighLevelAsync done
20:02:10:598 032A7EF0 TCustomWSocket.Shutdown 1 980
20:02:10:598 ! Data Session closed
20:02:10:598 ! Next3PutAsync
20:02:10:598 ! HighLevelAsync 0
20:02:10:598 FTP Error: FTP component not connected
20:02:10:598 Aborting
20:02:10:598 ! Aborting
20:02:11:598 Realtime FTP Connect attempt
20:02:11:598 ! HighLevelAsync 0
20:02:11:598 TWSocket will connect to 203.16.214.120:21
20:02:11:677 032A77E0 TriggerDataSent 888
20:02:11:755 >|220 (19) NOTICE TO USERS: Warning! The use of this system is restricted to authorised users only. All information and communications on this system are subject to security review, monitoring and recording at any time, without notice or permission. Unauthorised access or use shall be subject to prosecution.|

20:02:11:755 ! HighLevelAsync 0
20:02:11:755 032A77E0 TriggerDataSent 888
20:02:11:833 >|331 Please specify the password.

[steve]

There's no issue with the FTP rename code in Cumulus. There actually isn't any FTP rename code in Cumulus. All of the FTP is handled by a third-party component which is in use by thousands of people in all kinds of different software with all kinds of different FTP servers. The 'abort' is nothing to do with the rename. The abort occurs because of a timeout of 15 seconds when attempting to transfer the data. You were getting the same timeouts before you turned rename on!

[vk2him]

Hi Steve,

Daniel uploads his files onto my ISP's webspace as his ISP doesn't provide any. We have been experimenting with different settings within Cumulus to try to remedy the situation of frequent and regular aborts as captured in the logfile extracts posted above.

With FTP rename option enabled, the uploads start OK but will shortly lockup and never recover unless a) Cumulus is restarted or b) the temporary file is manually deleted from the ftp target directory.

With the option Delete before upload enabled , the same aborts within the logfile occur, however it doesn't lockup and will eventually succeed.

We were hoping the last logfile extract may give some clues as to why the ftp process is never able to get over the 15 second abort? It looks like the process reconnects, logs back in and sends the password, then starts the upload but aborts. Is there a list of what the different triggerdatasent mean?

My assumption that the rename within Cumulus had a problem was based on my experience that if the temporary file was manually deleted then the upload immediately continued for a short while ... I thought (wrongly now it seems) that if the code was under your control it may be possible to add some code to manually try to delete the temporary file when it detected the abort. No disrespect was intended by my comment that "there is an issue with rename code within Cumulus", it just seemed a logical conclusion.

Regards
Ian

[mcrossley]

Sounds like it fails after the upload of the temp file and before the rename is actioned. From then on the upload of the temp file fails as it is already there and cannot be overwritten for some reason. But the session aborts and Cumulus logs back in again so what is different from that and restarting Cumulus? Is some state being cached somewhere?

[steve]

My assumption that the rename within Cumulus had a problem was based on my experience that if the temporary file was manually deleted then the upload immediately continued for a short while ... I thought (wrongly now it seems) that if the code was under your control it may be possible to add some code to manually try to delete the temporary file when it detected the abort.

The fact that deleting the file on the server gets it going again suggests to me that it's a problem at the server. The client end doesn't know or care whether the file already exists, it just says to the server "create me this file, and here's the data for it". Presumably this is why Daniel had the 'delete before upload' setting selected in the first place, to try to get around this issue. Deleting the file before uploading a new copy is the worst possible setting for a 'realtime' upload as it increases the amount of time that there is no file on the server. This is where the 'rename' option comes in; it minimises the time where the file isn't available.

Having said all that, before I mentioned the rename setting, Daniel was getting timeouts anyway, with the 'delete' setting and without the 'rename' setting, so it's clear that neither of these have anything to do with the problem.

[DanielF]

I've changed the ISP where my weather page is hosted, and it now seems to be working with 'rename' instead of 'delete'. But the FTP log still reports lots of aborts and errors...

I found out only recently that my own ISP provides me with free web space (I'd always thought he didn't!), so I've now moved my weather page to:
http://www.shoalhaven.net.au/~daniel_fo ... a-Weather/
instead of at my friend Ian's ISP.

This has allowed me to turn off FTP 'delete' and turn on 'rename', and the gauges display OK most of the time, though I don't know how reliably the realtime file is being uploaded. I ran FTP logging overnight, and found that there were numerous aborts and many FTP errors. Not being familiar with FTP I'm not sure exactly what they mean, but I'm hoping someone here can point me in the right direction.

It seems strange that I have upload problems with two entirely different ISPs; the only common element is Cumulus!

At least now I'm using my own ISP I can possibly talk to him about the problems. So what should I be asking him, or what tests should I be running?

The attached file is just a very small extract from the 11.5MByte full log, but it shows the pattern of aborts & errors that occur throughout the logging period.

Any help much appreciated!

[steve]

It seems strange that I have upload problems with two entirely different ISPs; the only common element is Cumulus!

Apart from your PC, your router, your internet connection... etc.

The attached file is just a very small extract from the 11.5MByte full log, but it shows the pattern of aborts & errors that occur throughout the logging period.

The file only shows one abort, so it's hard to get a picture of how big an issue it is. How often do they occur?

[DanielF]

Apart from your PC, your router, your internet connection... etc.

The file only shows one abort, so it's hard to get a picture of how big an issue it is. How often do they occur?

Yes, sorry, I forgot about the PC, router etc! Incidentally, my ISP suggested I try a smaller MTU (<=1472) in the router, so I did that (in Windows2k also) with no improvement.

I've attached the full overnight file for your interest. I'm away for 5 days from early tomorrow morning, so may not be able to respond or run more tests till Tuesday night, though I'll have my smartphone with me, and could if I get the time!

[steve]

(in Windows2k also)

Ah yes, I'd forgotten you were running an obsolete operating system

I've attached the full overnight file for your interest.

You're getting timeouts every few minutes. I turned on my ftp logging, and it's been running for over four hours, uploading every 10 seconds, without a single timeout.

[DanielF]

You're getting timeouts every few minutes.

Can you please explain to an FTP dummy exactly what that means? Does it mean that Cumulus is sending an FTP command via the control channel and the FTP server is not responding within some specified time? If so, what is that time, and who specifies it?

[steve]

You're assuming that I know any more about how this works than you do. The part of the process which is timing out is when Cumulus does this:

Code: Select all

RealtimeFTP.Put;

This results in the following in the ftp log:

21:06:09:342 ! HighLevelAsync 0
21:06:09:342 032A77E0 TriggerDataSent 936
21:06:09:389 >|227 Entering Passive Mode (203,17,235,1,77,176).|

21:06:09:389 ! HighLevelAsync 0
21:06:09:389 TWSocket will connect to 203.17.235.1:19888
21:06:09:421 ! Data Session opened (Put)
21:06:09:421 032A7EF0 TriggerDataSent 1004
21:06:09:421 032A77E0 TriggerDataSent 936
21:06:09:452 >|150 Opening ASCII mode data connection for WWW/Gerroa-Weather/realtimegauges.txttmp|

21:06:09:452 ! Send first block
21:06:09:452 DataSocketPutDataSent 1340
21:06:09:452 032A7EF0 TriggerDataSent 1004
21:06:09:452 DataSocketPutDataSent 0
21:06:09:452 032A7EF0 TCustomWSocket.Shutdown 1 1004
21:06:09:499 ! Data Session closed
21:06:09:499 ! Next3PutAsync
21:06:09:499 032A7EF0 TCustomWSocket.Shutdown 1 1004
21:06:09:499 >|226 Transfer complete|

21:06:09:499 ! Next3PutAsync
21:06:09:499 ! HighLevelAsync 0
21:06:09:499 ! HighLevelAsync done

Cumulus sets a 15 second timeout on this operation. A timeout will occur if no response is received from the server for any of the various protocol exchanges that are required to perform the 'put'. Your timeouts occur after the server has returned the FTP response "226 Transfer Complete", but clearly there are still one or more steps required to complete the process, as what you get is this:

21:08:42:514 >|226 Transfer complete|

21:08:42:514 ! Next3PutAsync
21:08:58:327 ! Aborting

I have no idea what it is exactly that is being timed out. I tried to install Wireshark to monitor the TCP/IP packets, but I can't install it as it complains I already have WinPcap installed (I don't). I tried to ask on the mailing list for the FTP component, but the mail server won't talk to me.

Are there any timeouts in the ftplog.txt file for the 'normal' uploads?

[DanielF]

I tried to install Wireshark to monitor the TCP/IP packets, but I can't install it as it complains I already have WinPcap installed (I don't).

Are there any timeouts in the ftplog.txt file for the 'normal' uploads?

Yes, the normal uploads all seem to end with aborts (sample attached).

Ah yes, Wireshark. You've reminded me that I have that, and have used it before. Better than that, my cousin is one of (if not the) top networking consultant in Australia (MeasureIT). So I should run a Wireshark session and ask him to have a look at it. Might be some days before I have time, but I'll get back to you.

[steve]

I got a reply from the mailing list for the ftp component that I use: "The server does not seem to close the data connection after the client
did send Shutdown(1) hence the timeout, that is a server bug IMO."

[DanielF]

Thanks Steve. That's interesting. Seems to be a common server problem if that's the case, given that both ISPs I've tried suffer from it.

I'll wait till my cousin has had a chance to offer an opinion before I approach my ISP about a fix.