Issue switching from SFTP to FTPS

[broadstairs]

Now I have seen this a couple of times when I tested SFTP and then switched back to FTPS when CMX gives an error and does not connect. I have found that if I then switch to FTP it connects fine. The username and passwords are the same for both FTPS and FTP but not for SFTP. I have extracted the relevant part of the log gile which shows the last SFTP and the failed switch to FTPS.

Code: Select all

2022-06-16 09:08:04.469 SFTP[Int]: Uploading daily graph data files
2022-06-16 09:08:04.469 SFTP[Int]: Done uploading 0 daily graph data files
2022-06-16 09:08:04.469 SFTP[Int]: Connection process complete
2022-06-16 09:08:06.497 Reading live data
2022-06-16 09:08:06.528 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:06.528 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C5-07-4A-0A-00-5B-0B-00-09-0C-00-0D-15-00-08-87-7F-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-61
2022-06-16 09:08:06.528 LiveData: Wind Decode >> Last=2.0, LastDir=91, Gust=2.9, (MXAvg=3.0)
2022-06-16 09:08:09.071 Updating internet settings
2022-06-16 09:08:09.071 Writing Cumulus.ini file
2022-06-16 09:08:09.086 Completed writing Cumulus.ini file
2022-06-16 09:08:10.537 Reading live data
2022-06-16 09:08:10.568 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:10.568 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-4A-0A-00-54-0B-00-09-0C-00-14-15-00-08-8C-C5-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-AD
2022-06-16 09:08:10.568 LiveData: Wind Decode >> Last=2.0, LastDir=84, Gust=4.5, (MXAvg=3.0)
2022-06-16 09:08:14.577 Reading live data
2022-06-16 09:08:14.609 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:14.609 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-49-0A-00-4B-0B-00-10-0C-00-14-15-00-08-89-8C-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-6E
2022-06-16 09:08:14.609 LiveData: Wind Decode >> Last=3.6, LastDir=75, Gust=4.5, (MXAvg=3.0)
2022-06-16 09:08:18.618 Reading live data
2022-06-16 09:08:18.648 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:18.648 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-49-0A-00-4D-0B-00-10-0C-00-15-15-00-08-8D-10-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-F9
2022-06-16 09:08:18.648 LiveData: Wind Decode >> Last=3.6, LastDir=77, Gust=4.7, (MXAvg=3.0)
2022-06-16 09:08:22.657 Reading live data
2022-06-16 09:08:22.688 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:22.688 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-49-0A-00-4F-0B-00-12-0C-00-1A-15-00-08-91-75-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-6B
2022-06-16 09:08:22.688 LiveData: Wind Decode >> Last=4.0, LastDir=79, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:26.697 Reading live data
2022-06-16 09:08:26.729 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:26.729 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-49-0A-00-4F-0B-00-12-0C-00-1A-15-00-08-91-75-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-6B
2022-06-16 09:08:26.729 LiveData: Wind Decode >> Last=4.0, LastDir=79, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:26.900 Realtime[197]: Start cycle
2022-06-16 09:08:26.900 Realtime[197]: Creating realtime.txt
2022-06-16 09:08:26.900 Realtime[197]: Processing realtime file - realtimegauges.txt
2022-06-16 09:08:26.916 Realtime[197]: End cycle
2022-06-16 09:08:26.916 RealtimeReconnect: Realtime ftp attempting disconnect
2022-06-16 09:08:26.963 RealtimeReconnect: Realtime ftp disconnected
2022-06-16 09:08:26.963 RealtimeReconnect: Realtime ftp attempting to reconnect
2022-06-16 09:08:26.978 RealtimeReconnect: Error reconnecting ftp server - No host has been specified
2022-06-16 09:08:26.978 RealtimeReconnect: Realtime ftp attempting to reinitialise the connection
2022-06-16 09:08:26.994 RealtimeFTPLogin: Using FTPS protocol
2022-06-16 09:08:26.994 RealtimeFTPLogin: Attempting realtime FTP connect to host ftp.stella-maris.org.uk on port 990
2022-06-16 09:08:30.738 Reading live data
2022-06-16 09:08:30.769 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:30.769 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-49-0A-00-4E-0B-00-0E-0C-00-1A-15-00-08-94-F9-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-ED
2022-06-16 09:08:30.769 LiveData: Wind Decode >> Last=3.1, LastDir=78, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:34.782 Reading live data
2022-06-16 09:08:34.813 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:34.813 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-4A-0A-00-43-0B-00-0B-0C-00-1A-15-00-08-91-75-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-59
2022-06-16 09:08:34.813 LiveData: Wind Decode >> Last=2.5, LastDir=67, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:38.822 Reading live data
2022-06-16 09:08:38.853 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:38.853 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-4A-0A-00-22-0B-00-0D-0C-00-1A-15-00-08-8F-68-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-2B
2022-06-16 09:08:38.853 LiveData: Wind Decode >> Last=2.9, LastDir=34, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:42.020 RealtimeFTPLogin: Error connecting ftp - Timed out trying to connect!
2022-06-16 09:08:42.863 Reading live data
2022-06-16 09:08:42.894 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:42.894 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C6-07-4A-0A-00-1A-0B-00-0D-0C-00-1A-15-00-08-8B-4E-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-05
2022-06-16 09:08:42.894 LiveData: Wind Decode >> Last=2.9, LastDir=26, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:46.903 Reading live data
2022-06-16 09:08:46.934 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:46.934 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C5-07-4B-0A-00-2B-0B-00-0A-0C-00-1A-15-00-08-87-34-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-F5
2022-06-16 09:08:46.934 LiveData: Wind Decode >> Last=2.2, LastDir=43, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:50.943 Reading live data
2022-06-16 09:08:50.975 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:50.975 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C5-07-4B-0A-00-2B-0B-00-0A-0C-00-1A-15-00-08-87-34-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-F5
2022-06-16 09:08:50.975 LiveData: Wind Decode >> Last=2.2, LastDir=43, Gust=5.8, (MXAvg=3.1)
2022-06-16 09:08:54.984 Reading live data
2022-06-16 09:08:55.015 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:55.015 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C4-07-4A-0A-00-4D-0B-00-10-0C-00-12-15-00-08-87-CA-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-A9
2022-06-16 09:08:55.015 LiveData: Wind Decode >> Last=3.6, LastDir=77, Gust=4.0, (MXAvg=3.1)
2022-06-16 09:08:56.918 Realtime[198]: Start cycle
2022-06-16 09:08:56.918 Realtime[198]: Creating realtime.txt
2022-06-16 09:08:56.918 Realtime[198]: Processing realtime file - realtimegauges.txt
2022-06-16 09:08:56.918 Realtime[198]: End cycle
2022-06-16 09:08:59.024 Reading live data
2022-06-16 09:08:59.055 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:08:59.055 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C4-07-4A-0A-00-57-0B-00-12-0C-00-14-15-00-08-84-46-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-30
2022-06-16 09:08:59.055 LiveData: Wind Decode >> Last=4.0, LastDir=87, Gust=4.5, (MXAvg=3.2)
2022-06-16 09:09:00.522 DoLogFile: Writing log entry for 16/06/2022 09:09:00
2022-06-16 09:09:00.522 DoLogFile: max gust: 6
2022-06-16 09:09:00.522 DoLogFile: log entry for 16/06/2022 09:09:00 written
2022-06-16 09:09:00.522 Writing today.ini, LastUpdateTime = 16/06/2022 09:09:00 raindaystart = 152.4 rain counter = 152.4
2022-06-16 09:09:00.522 DoExtraLogFile: Writing log entry for 16/06/2022 09:09:00
2022-06-16 09:09:00.522 DoExtraLogFile: Log entry for 16/06/2022 09:09:00 written
2022-06-16 09:09:00.522 Creating standard web files
2022-06-16 09:09:00.537 Done creating standard Data file
2022-06-16 09:09:00.537 Creating graph data files
2022-06-16 09:09:02.035 RealtimeReconnect: Realtime ftp attempting disconnect
2022-06-16 09:09:02.035 RealtimeReconnect: Realtime ftp disconnected
2022-06-16 09:09:02.035 RealtimeReconnect: Realtime ftp attempting to reconnect
2022-06-16 09:09:02.846 Done creating graph data files
2022-06-16 09:09:02.846 Interval: Processing extra file[0] - D:\CumulusMX\webfiles\CU-tags.txt
2022-06-16 09:09:02.909 FTP[Int]: CumulusMX Connecting to ftp.stella-maris.org.uk
2022-06-16 09:09:03.065 Reading live data
2022-06-16 09:09:03.096 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:09:03.096 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C9-09-27-F6-02-00-C4-07-4A-0A-00-58-0B-00-12-0C-00-14-15-00-08-89-41-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-31
2022-06-16 09:09:03.096 LiveData: Wind Decode >> Last=4.0, LastDir=88, Gust=4.5, (MXAvg=3.2)
2022-06-16 09:09:07.105 Reading live data
2022-06-16 09:09:07.136 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:09:07.136 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C8-09-27-F5-02-00-C3-07-4A-0A-00-4C-0B-00-08-0C-00-14-15-00-08-8A-B8-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-90
2022-06-16 09:09:07.136 LiveData: Wind Decode >> Last=1.8, LastDir=76, Gust=4.5, (MXAvg=3.2)
2022-06-16 09:09:11.140 Reading live data
2022-06-16 09:09:11.171 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:09:11.171 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C8-09-27-F5-02-00-C3-07-4A-0A-00-47-0B-00-08-0C-00-14-15-00-08-8C-7A-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-4F
2022-06-16 09:09:11.171 LiveData: Wind Decode >> Last=1.8, LastDir=71, Gust=4.5, (MXAvg=3.2)
2022-06-16 09:09:15.181 Reading live data
2022-06-16 09:09:15.212 DoCommand(CMD_GW1000_LIVEDATA): Valid response
2022-06-16 09:09:15.212 Received: FF-FF-27-00-5C-01-00-EC-06-38-08-27-C8-09-27-F5-02-00-C2-07-4A-0A-00-42-0B-00-18-0C-00-18-15-00-08-8F-68-16-03-E8-17-03-2A-00-C8-4D-00-74-1A-00-E0-22-39-1B-00-E2-23-3A-62-00-00-00-00-61-62-A3-2D-B1-60-0C-19-00-1D-0E-00-00-10-00-00-11-00-00-12-00-00-00-A9-13-00-00-05-F4-0D-00-00-4E
2022-06-16 09:09:15.212 LiveData: Wind Decode >> Last=5.4, LastDir=66, Gust=5.4, (MXAvg=3.2)
2022-06-16 09:09:17.037 RealtimeReconnect: Error reconnecting ftp server - Timed out trying to connect!
2022-06-16 09:09:17.037 RealtimeReconnect: Realtime ftp attempting to reinitialise the connection
2022-06-16 09:09:17.037 RealtimeFTPLogin: Using FTPS protocol
2022-06-16 09:09:17.037 RealtimeFTPLogin: Attempting realtime FTP connect to host ftp.stella-maris.org.uk on port 990
2022-06-16 09:09:17.926 FTP[Int]: Error connecting ftp - Timed out trying to connect!

Now I have no idea why this happens but it has happened before when switching. Normally having switched to FTP I can then switch to FTPS just fine.

Any ideas please?

Stuart

[water01]

Looks to me like you are not switching the port from 900 which is OK for SFTP to whatever port FSTP needs which is usually a standard port i.e. 20.

You hosting provider can give you this info.

[broadstairs]

OK I think I have got to the bottom of it. Yes I was using the wrong port for FTPS but and it's a big BUT.... CMX is NOT showing FTPS as a protocol to use now I have specified port 21 as the correct port it is still using plain old FTP, at least that is what the logs are showing. So settings is set for FTPS and port 21 but it looks very much like CMX is ignoring the FTPS protocol because I am using port 21.

Mark can you take a look at the code please and see if I am correct?

Stuart

[mcrossley]

The protocol type and port number are independent of each other.

[broadstairs]

Well all I can say it that when I used the FTPS with the wrong port I saw FTPS as the protocol in the log file but now using port21 I cannot see any FTPS in the log file. I'll attach the log file and a copy of the .ini file with the pw removed.

Stuart

[mcrossley]

I used your ini file in my test system and it uses FTPS OK....

Code: Select all

2022-06-16 16:31:53.472 Starting 1-minute timer
2022-06-16 16:31:53.473 Data logging interval = 0 (1 mins)
2022-06-16 16:32:06.646 RealtimeFTPLogin: Using FTPS protocol
2022-06-16 16:32:11.260 RealtimeFTPLogin: Attempting realtime FTP connect to host ftp.stella-maris.org.uk on port 21

Double checked and there is no interaction between port and protocol in CMX.

[broadstairs]

I'll try again but it all works but no mention of FTPS in log file which is what I don't understand.

Stuart

[broadstairs]

I now have managed to get FTPS working again on port 21 but there is something flaky about this when switching between protocols. I just cannot put my finger on it right now. That logfile I uploaded shows SFTP being used and during the life of that file I switched to protocols but nothing showed up as that happening.

I'll fire up my test system and do some controlled tests with and without restarting CMX and see what happens being careful to keep a note of what I do when! I guess it's not a huge issue as most people once settled on an FTP protocol will stick with it.

Stuart

[mcrossley]

Changing protocols on the fly isn't really recommended. CMX uses a single persistent FTP session for the real-time transfers.

I haven't checked but you may be able to... step 1, disable FTP, then step 2, change the protocol and re-enable FTP

[broadstairs]

Mark that could explain it potentially. I will try that first and see what happens.

Stuart

[broadstairs]

In fact and not surprisingly ( ) Mark does seem to be correct. Changing FTP protocols is NOT guaranteed to work unless CMX is shutdown and restarted once the change has been made. I have tested various combinations and although some work some of the time therefore do not rely on it working as you expect.

Safest way is to stop FTP and restart CMX then set up FTP again using the protocol you need to use.

Stuart