FluentFTP
FluentFTP copied to clipboard
robinrodricks
FileZilla FTPS - TLS fails on data upload.
FTP OS: Windows
FTP Server: FileZilla (latest (1.0.1)
Computer OS: Windows
FluentFTP Version: 35.0.5
Attempting to upload a file to FileZilla from C# (.net 3.1) using explicit TLS fails to perform TLS handshake (note "Connect" is successful)
This can be replicated every time (I've done it on 3 machines) by debugging the following code after installing FileZilla on a windows machine.
FileZilla settings - Under FTP Server
- Protocol: "Require explicit FTP over TLS"
I have also tried downloading the certificates via openssl and added them in to the code below, but with the same results.
using var client = new FtpClient("127.0.0.1", 21, "orderease", "xxx")
{
SocketKeepAlive = true,
ValidateAnyCertificate = true,
SslProtocols = SslProtocols.Tls12,
EncryptionMode = FtpEncryptionMode.Explicit,
DataConnectionType = FtpDataConnectionType.PASV,
};
var ftpLog = new StringBuilder();
client.OnLogEvent = (level, s) => { ftpLog.AppendLine(level + " - " + s); };
client.Connect();
client.SetWorkingDirectory("/GMS-EDI/GMS_Order");
var response = client.Upload(Encoding.ASCII.GetBytes(content), $"{fileName}.txt");
if (response == FtpStatus.Failed)
{
log.LogError("Failed to upload ");
log.LogError(ftpLog.ToString());
}
client.Disconnect();
Logs : Filezilla Logs
2021-10-28T18:08:42.299Z >> [FTP Session 26 127.0.0.1 orderease] SYST
2021-10-28T18:08:42.299Z << [FTP Session 26 127.0.0.1 orderease] 215 UNIX emulated by FileZilla.
2021-10-28T18:08:49.043Z >> [FTP Session 26 127.0.0.1 orderease] CWD /GMS-EDI/GMS_Order
2021-10-28T18:08:49.043Z << [FTP Session 26 127.0.0.1 orderease] 250 CWD command successful
2021-10-28T18:08:52.655Z >> [FTP Session 26 127.0.0.1 orderease] PWD
2021-10-28T18:08:52.655Z << [FTP Session 26 127.0.0.1 orderease] 257 "/GMS-EDI/GMS_Order" is current directory.
2021-10-28T18:08:52.655Z >> [FTP Session 26 127.0.0.1 orderease] SIZE /GMS-EDI/GMS_Order/SPISO-20211028124510-N.txt
2021-10-28T18:08:52.655Z << [FTP Session 26 127.0.0.1 orderease] 213 892
2021-10-28T18:08:52.656Z >> [FTP Session 26 127.0.0.1 orderease] DELE SPISO-20211028124510-N.txt
2021-10-28T18:08:52.656Z << [FTP Session 26 127.0.0.1 orderease] 250 File deleted successfully.
2021-10-28T18:08:52.657Z >> [FTP Session 26 127.0.0.1 orderease] TYPE I
2021-10-28T18:08:52.657Z << [FTP Session 26 127.0.0.1 orderease] 200 Type set to I
2021-10-28T18:08:52.660Z >> [FTP Session 26 127.0.0.1 orderease] PASV
2021-10-28T18:08:52.660Z VV [FTP Session 26 127.0.0.1 orderease] Trying: data_listen_socket_->listen(1, 0)
2021-10-28T18:08:52.660Z << [FTP Session 26 127.0.0.1 orderease] 227 Entering Passive Mode (127,0,0,1,204,126)
2021-10-28T18:08:52.661Z VV [FTP Session 26 127.0.0.1 orderease] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
2021-10-28T18:08:52.662Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::server_handshake()
2021-10-28T18:08:52.662Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::continue_handshake()
2021-10-28T18:08:52.662Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::continue_handshake()
2021-10-28T18:08:52.662Z >> [FTP Session 26 127.0.0.1 orderease] STOR SPISO-20211028124510-N.txt
2021-10-28T18:08:52.662Z << [FTP Session 26 127.0.0.1 orderease] 150 Starting data transfer.
2021-10-28T18:08:52.663Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::continue_handshake()
2021-10-28T18:08:52.666Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::continue_handshake()
2021-10-28T18:08:52.666Z II [FTP Session 26 127.0.0.1 orderease] TLS Handshake successful
2021-10-28T18:08:52.666Z II [FTP Session 26 127.0.0.1 orderease] TLS Session resumed
2021-10-28T18:08:52.666Z II [FTP Session 26 127.0.0.1 orderease] Protocol: TLS1.2, Key exchange: ECDHE-X25519, Cipher: AES-256-GCM, MAC: AEAD
2021-10-28T18:08:52.666Z VV [FTP Session 26 127.0.0.1 orderease] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
2021-10-28T18:08:52.667Z !! [FTP Session 26 127.0.0.1 orderease] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
2021-10-28T18:08:52.667Z == [FTP Session 26 127.0.0.1 orderease] Client did not properly shut down TLS connection
2021-10-28T18:08:52.667Z VV [FTP Session 26 127.0.0.1 orderease] tls_layer_impl::shutdown()
2021-10-28T18:08:52.667Z VV [FTP Session 26 127.0.0.1 orderease] data_socket_->shutdown() = 126
2021-10-28T18:08:52.667Z << [FTP Session 26 127.0.0.1 orderease] 425 Error while transfering data: ECONNABORTED - Connection aborted
2021-10-28T18:08:52.667Z VV [FTP Session 26 127.0.0.1 orderease] session::close_data_connection() = 1
2021-10-28T18:08:57.659Z !! [FTP Session 26 127.0.0.1 orderease] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
2021-10-28T18:08:57.659Z !! [FTP Server] Session ended with error from source 0. Reason: ECONNABORTED - Connection aborted.
FluentFTP logs
[2021-10-28T18:18:49.266Z] Failed to upload
[2021-10-28T18:18:49.903Z] Verbose - > Connect()
[2021-10-28T18:18:49.904Z] Info - Status: Connecting to 127.0.0.1:21
[2021-10-28T18:18:49.905Z] Verbose - Response: 220-FileZilla Server 1.0.1
[2021-10-28T18:18:49.905Z] Info - Response: 220 Please visit https://filezilla-project.org/
[2021-10-28T18:18:49.906Z] Info - Status: Detected FTP server: FileZilla
[2021-10-28T18:18:49.907Z] Info - Command: AUTH TLS
[2021-10-28T18:18:49.908Z] Info - Response: 234 Using authentication type TLS.
[2021-10-28T18:18:49.909Z] Info - Status: FTPS Authentication Successful
[2021-10-28T18:18:49.910Z] Verbose - Status: Time to activate encryption: 0h 0m 0s. Total Seconds: 0.0273426.
[2021-10-28T18:18:49.911Z] Info - Command: USER orderease
[2021-10-28T18:18:49.912Z] Info - Response: 331 Please, specify the password.
[2021-10-28T18:18:49.913Z] Info - Command: PASS ***
[2021-10-28T18:18:49.914Z] Info - Response: 230 Login successful.
[2021-10-28T18:18:49.915Z] Info - Command: PBSZ 0
[2021-10-28T18:18:49.916Z] Info - Response: 200 PBSZ=0
[2021-10-28T18:18:49.917Z] Info - Command: PROT P
[2021-10-28T18:18:49.918Z] Info - Response: 200 Protection level set to P
[2021-10-28T18:18:49.919Z] Info - Command: FEAT
[2021-10-28T18:18:49.920Z] Verbose - Response: 211-Features:
Response: MDTM
Response: REST STREAM
Response: SIZE
Response: MLST type*;size*;modify*;perm*;
Response: MLSD
Response: AUTH SSL
Response: AUTH TLS
Response: PROT
Response: PBSZ
Response: UTF8
Response: TVFS
Response: EPSV
Response: EPRT
Response: MFMT
[2021-10-28T18:18:49.923Z] Info - Response: 211 End
[2021-10-28T18:18:49.924Z] Info - Status: Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
[2021-10-28T18:18:49.925Z] Info - Command: OPTS UTF8 ON
[2021-10-28T18:18:49.926Z] Info - Response: 202 UTF8 mode is always enabled. No need to send this command
[2021-10-28T18:18:49.927Z] Info - Command: SYST
[2021-10-28T18:18:49.928Z] Info - Response: 215 UNIX emulated by FileZilla.
[2021-10-28T18:18:49.930Z] Verbose - > SetWorkingDirectory("/GMS-EDI/GMS_Order")
[2021-10-28T18:18:49.931Z] Info - Command: CWD /GMS-EDI/GMS_Order
[2021-10-28T18:18:49.932Z] Info - Response: 250 CWD command successful
[2021-10-28T18:18:49.933Z] Verbose - > Upload("SPISO-20211028124510-N.txt", Overwrite, False)
[2021-10-28T18:18:49.934Z] Verbose - > FileExists("SPISO-20211028124510-N.txt")
[2021-10-28T18:18:49.935Z] Verbose - Status: Testing connectivity using Socket.Poll()...
[2021-10-28T18:18:49.936Z] Info - Command: PWD
[2021-10-28T18:18:49.939Z] Info - Response: 257 "/GMS-EDI/GMS_Order" is current directory.
[2021-10-28T18:18:49.940Z] Info - Command: SIZE /GMS-EDI/GMS_Order/SPISO-20211028124510-N.txt
[2021-10-28T18:18:49.941Z] Info - Response: 213 892
[2021-10-28T18:18:49.942Z] Verbose - > DeleteFile("SPISO-20211028124510-N.txt")
[2021-10-28T18:18:49.943Z] Info - Command: DELE SPISO-20211028124510-N.txt
[2021-10-28T18:18:49.944Z] Info - Response: 250 File deleted successfully.
[2021-10-28T18:18:49.946Z] Verbose - > OpenWrite("SPISO-20211028124510-N.txt", Binary)
[2021-10-28T18:18:49.948Z] Info - Command: TYPE I
[2021-10-28T18:18:49.950Z] Info - Response: 200 Type set to I
[2021-10-28T18:18:49.951Z] Verbose - > OpenPassiveDataStream(PASV, "STOR SPISO-20211028124510-N.txt", 0)
[2021-10-28T18:18:49.954Z] Info - Command: PASV
[2021-10-28T18:18:49.955Z] Info - Response: 227 Entering Passive Mode (127,0,0,1,244,130)
[2021-10-28T18:18:49.956Z] Info - Status: Connecting to 127.0.0.1:62594
[2021-10-28T18:18:49.957Z] Info - Command: STOR SPISO-20211028124510-N.txt
[2021-10-28T18:18:49.958Z] Info - Response: 150 Starting data transfer.
[2021-10-28T18:18:49.959Z] Info - Status: FTPS Authentication Successful
[2021-10-28T18:18:49.961Z] Verbose - Status: Time to activate encryption: 0h 0m 0s. Total Seconds: 0.0057162.
[2021-10-28T18:18:49.962Z] Verbose - Status: Disposing FtpSocketStream...
[2021-10-28T18:18:49.963Z] Info - Response: 425 Error while transfering data: ECONNABORTED - Connection aborted
I have the same issue with FileZilla Server
2021-11-16 15:50:07.6618|Info|Level Info -> Status: Connecting to ***.***.***.***:21 |
2021-11-16 15:50:07.7417|Info|Level Verbose -> Response: 220-FileZilla Server 1.0.1 |
2021-11-16 15:50:07.7417|Info|Level Info -> Response: 220 Please visit https://filezilla-project.org/ |
2021-11-16 15:50:07.7417|Info|Level Info -> Status: Detected FTP server: FileZilla |
2021-11-16 15:50:07.7417|Info|Level Info -> Command: AUTH TLS |
2021-11-16 15:50:07.7823|Info|Level Info -> Response: 234 Using authentication type TLS. |
2021-11-16 15:50:07.8648|Info|Level Info -> Status: FTPS Authentication Successful |
2021-11-16 15:50:07.8648|Info|Level Verbose -> Status: Time to activate encryption: 0h 0m 0s. Total Seconds: 0,0823393. |
2021-11-16 15:50:07.8648|Info|Level Info -> Command: USER ********* |
2021-11-16 15:50:07.9031|Info|Level Info -> Response: 331 Please, specify the password. |
2021-11-16 15:50:07.9031|Info|Level Info -> Command: PASS *** |
2021-11-16 15:50:08.0238|Info|Level Info -> Response: 230 Login successful. |
2021-11-16 15:50:08.0238|Info|Level Info -> Command: PBSZ 0 |
2021-11-16 15:50:08.0702|Info|Level Info -> Response: 200 PBSZ=0 |
2021-11-16 15:50:08.0702|Info|Level Info -> Command: PROT P |
2021-11-16 15:50:08.1110|Info|Level Info -> Response: 200 Protection level set to P |
2021-11-16 15:50:08.1110|Info|Level Info -> Command: FEAT |
2021-11-16 15:50:08.1530|Info|Level Verbose -> Response: 211-Features:
Response: MDTM
Response: REST STREAM
Response: SIZE
Response: MLST type*;size*;modify*;perm*;
Response: MLSD
Response: AUTH SSL
Response: AUTH TLS
Response: PROT
Response: PBSZ
Response: UTF8
Response: TVFS
Response: EPSV
Response: EPRT
Response: MFMT |
2021-11-16 15:50:08.1530|Info|Level Info -> Response: 211 End |
2021-11-16 15:50:08.1530|Info|Level Info -> Status: Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed |
2021-11-16 15:50:08.1530|Info|Level Info -> Command: OPTS UTF8 ON |
2021-11-16 15:50:08.1919|Info|Level Info -> Response: 202 UTF8 mode is always enabled. No need to send this command |
2021-11-16 15:50:08.1919|Info|Level Info -> Command: SYST |
2021-11-16 15:50:08.2296|Info|Level Info -> Response: 215 UNIX emulated by FileZilla. |
2021-11-16 15:50:08.2296|Info|Level Verbose -> Status: Listing parser set to: Machine |
2021-11-16 15:50:08.2296|Info|Level Verbose -> > Upload("./raw/RAW_2.csv", Overwrite, False) |
2021-11-16 15:50:08.2296|Info|Level Verbose -> > FileExists("./raw/RAW_2.csv") |
2021-11-16 15:50:08.2296|Info|Level Info -> Command: PWD |
2021-11-16 15:50:08.2708|Info|Level Info -> Response: 257 "/" is current directory. |
2021-11-16 15:50:08.2708|Info|Level Info -> Command: SIZE /raw/RAW_2.csv |
2021-11-16 15:50:08.3176|Info|Level Info -> Response: 550 No such file |
2021-11-16 15:50:08.3176|Info|Level Verbose -> > OpenWrite("./raw/RAW_2.csv", Binary) |
2021-11-16 15:50:08.3176|Info|Level Info -> Command: TYPE I |
2021-11-16 15:50:08.3562|Info|Level Info -> Response: 200 Type set to I |
2021-11-16 15:50:08.3562|Info|Level Verbose -> > OpenPassiveDataStream(PASV, "STOR ./raw/RAW_2.csv", 0) |
2021-11-16 15:50:08.3562|Info|Level Info -> Command: PASV |
2021-11-16 15:50:08.3975|Info|Level Info -> Response: 227 Entering Passive Mode (10,255,254,19,97,170) |
2021-11-16 15:50:08.3975|Info|Level Info -> Status: Connecting to ***.***.***.***:25002 |
2021-11-16 15:50:08.4304|Info|Level Info -> Command: STOR ./raw/RAW_2.csv |
2021-11-16 15:50:08.4934|Info|Level Info -> Response: 150 Starting data transfer. |
2021-11-16 15:50:08.5348|Info|Level Info -> Status: FTPS Authentication Successful |
2021-11-16 15:50:08.5348|Info|Level Verbose -> Status: Time to activate encryption: 0h 0m 0s. Total Seconds: 0,0411848. |
2021-11-16 15:50:08.5348|Info|Level Verbose -> Status: Disposing FtpSocketStream... |
2021-11-16 15:50:08.5658|Info|Level Info -> Response: 425 Error while transfering data: ECONNABORTED - Connection aborted |
2021-11-16 15:50:08.5658|Info|Level Verbose -> > ConnectAsync() |
2021-11-16 15:50:08.5658|Info|Level Info -> Command: QUIT |
2021-11-16 15:50:08.6104|Info|Level Info -> Response: 200 Goodbye. |
2021-11-16 15:50:08.6104|Info|Level Verbose -> Status: Disposing FtpSocketStream... |
Same problem. Had to disable TSL to upload successfully a file. This is the log for UploadFileAsync with FtpRemoteExists.Overwrite and FtpVerify.Retry options.
2021-12-02T10:53:38.826Z >> [FTP Session 49 127.0.0.1 admin] TYPE I
2021-12-02T10:53:38.826Z << [FTP Session 49 127.0.0.1 admin] 200 Type set to I
2021-12-02T10:53:38.836Z >> [FTP Session 49 127.0.0.1 admin] PASV
2021-12-02T10:53:38.836Z << [FTP Session 49 127.0.0.1 admin] 227 Entering Passive Mode (127,0,0,1,235,25)
2021-12-02T10:53:38.844Z >> [FTP Session 49 127.0.0.1 admin] RETR /data/file.csv
2021-12-02T10:53:38.845Z << [FTP Session 49 127.0.0.1 admin] 150 Starting data transfer.
2021-12-02T10:53:38.848Z << [FTP Session 49 127.0.0.1 admin] 226 Operation successful
2021-12-02T10:53:38.897Z >> [FTP Session 49 127.0.0.1 admin] SIZE /data/file.csv
2021-12-02T10:53:38.897Z << [FTP Session 49 127.0.0.1 admin] 213 695
2021-12-02T10:53:38.909Z >> [FTP Session 49 127.0.0.1 admin] DELE /data/file.csv
2021-12-02T10:53:38.909Z << [FTP Session 49 127.0.0.1 admin] 250 File deleted successfully.
2021-12-02T10:53:38.918Z >> [FTP Session 49 127.0.0.1 admin] PASV
2021-12-02T10:53:38.918Z << [FTP Session 49 127.0.0.1 admin] 227 Entering Passive Mode (127,0,0,1,235,27)
2021-12-02T10:53:38.928Z >> [FTP Session 49 127.0.0.1 admin] STOR /data/file.csv
2021-12-02T10:53:38.929Z << [FTP Session 49 127.0.0.1 admin] 150 Starting data transfer.
2021-12-02T10:53:38.941Z !! [FTP Session 49 127.0.0.1 admin] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
2021-12-02T10:53:38.941Z == [FTP Session 49 127.0.0.1 admin] Client did not properly shut down TLS connection
2021-12-02T10:53:38.941Z << [FTP Session 49 127.0.0.1 admin] 425 Error while transfering data: ECONNABORTED - Connection aborted
2021-12-02T10:53:38.959Z >> [FTP Session 49 127.0.0.1 admin] QUIT
Had this same issues as well. One thing I did notice is that if I roll back to v 34.0.2 it seems to work, the non-properly terminated logging messages on the server side don't show up and all of my files are successfully uploaded. The instant I move the NuGet package to 35.0.0 the problem shows up and stays all the way through 35.2.1.
@Jlarson06 good work debugging this, did you find out the part of the code that caused this issue in newer versions?
I've also been encountering this issue. I stumbled across it when the FTP was returning a transient failure response instead of a successful write.
FTP OS: Windows FTP Server: FileZilla (latest (1.2.0) Computer OS: Windows FluentFTP Version: 35.2.3
I am beginning to suspect FileZilla Server.
A Windows FTPS configuration using IIS works fine with the same commands, whereas with FileZilla server, whether I use Microsoft's FtpWebRequest or FluentFTP the Filezilla logs show the same error below for a data upload.
Even if I use the site ftptest.net to test the server, the same error as above appears in the logs:
GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
For now I'm going to use the Windows FTP instead. I am curious if this behavior is the same across multiple versions of FileZilla Server. @TrevorLinkgreen, were you able to use previous versions of FileZilla server, or is this the first time you set the server up with Fluent as a client?
Had this same issues as well. One thing I did notice is that if I roll back to v 34.0.2 it seems to work, the non-properly terminated logging messages on the server side don't show up and all of my files are successfully uploaded. The instant I move the NuGet package to 35.0.0 the problem shows up and stays all the way through 35.2.1.
Had same issue here downgraded to V34 for now and messages disappeared.
Filezilla server 1.0.1 both Fluentftp 36.1.0 and 34.0.2 is returning FTPStatus.Failed, during upload at file. Actually the file is uploaded to server but UploadFile is returning FTPStatus.Failed
FtpStatus res = client.UploadFile(fileLocation, ftp.ftpEmployeeFileLocation, FtpRemoteExists.Overwrite, false, FtpVerify.Retry);
I see same error log at FileZilla ftpserver
GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated. Client did not properly shut down TLS connection 425 Error while transferring data: ECONNABORTED - Connection aborted
I'm having the exact same issue.
- OS is Windows 10 (10.0.19044 Build 19044)
- FileZilla Server is version 1.2.0
- Tried FluentFTP 36.1.0 and 34.0.2
- .NET Core 3.1 (upgrade to .NET 6.0 didn't help)
- TLS 1.2 (can't even connect when choosing TLS 1.3, even when running .NET 6)
All uploads are "Failed", and the FileZilla log shows the "TLS connection was non-properly terminated" error. Doesn't matter if I set explicit FTP over SSL as required or not. But the files actually exist on the server.
This was partly fixed with V37.0.4 on March 9, 2022
Then a further fix was applied:
Nearly a month ago PR https://github.com/robinrodricks/FluentFTP/pull/944 addressed exactly this problem. Merged into master on September 10.
It came into Nuget Release V41.0.0 on October 2.
https://github.com/robinrodricks/FluentFTP/pull/944 explicitely mentions the wrong order of ssl stream shutdown, as seen from a vsftp server. This happened on any server type - and each server type reacts differently to this. Some more lenient and some less so.
If you read https://github.com/robinrodricks/FluentFTP/pull/944 and also read the article mentioned therein (this, you will agree it is the same problem as yours.
Ergo - I advise updating to FluentFTP V41.
