Ask a Question

FTPS: How to avoid 'No TLS Session ID' error with Bitvise server?

0 votes
by (170 points)
edited by

Trying to send files to bitvise server over ftps.
First had trouble with the connection itself. With your help it was solved by
ReuseControlConnectionSession = false

But we still couldn't send any data.
It gets until the STORE and trying to initiate a data connection, but then...

Data connection: HandshakeMessage:ClientHello was sent.
...
Rebex.Net.TlsException: Connection was closed by the remote connection end.

at the same time on the server side:

FTP passive data connection failed.
NoTlsSessionId
The client has tried to perform a full TLS handshake for a data connection. The client must resume the TLS session from the control connection by issuing an abbreviated TLS handshake with a correct TLS session ID.

I might misunderstand something, but we just turned out reusing the control connection session because then we cannot connect, and now it complains about not having that session id.
Anyway we tried to find a setting that makes sense but we couldn't. Could you help us out again?

This is the ftp client's settings dumped out

{
    "DoNotSendSignals": false,
    "DoNotSendAbort": false,
    "KeepAliveDuringTransfer": false,
    "ForceSilentCcc": false,
    "ForceActiveCcc": false,
    "SendDataAsynchronously": false,
    "TimeoutAsynchronousMethods": false,
    "DoNotDetectFeatures": false,
    "IgnorePassiveModeAddress": false,
    "EnableMultipleBlockingCalls": false,
    "PauseBeforeUploadClose": false,
    "DisableInvalidPassiveModeAddressWorkaround": false,
    "EnableControlConnectionFlushing": false,
    "ConnectPassiveLater": false,
    "UseLargeBuffers": false,
    "ReuseControlConnectionSession": false,
    "ForceListHiddenFiles": false,
    "DisableProgressPercentage": false,
    "MultiFileLinkMode": "FollowLinks",
    "MultiFileMoveMode": "All",
    "RestoreDateTime": "None",
    "EnableChecksumVerification": false,
    "TimeComparisonGranularity": "Seconds",
    "RecheckItemExistence": false,
    "PreferredChecksumType": "SHA1",
    "KeepAliveDuringTransferInterval": 30,
    "KeepAliveDuringIdleInterval": 0,
    "ForceMdtmForGetFileDateTime": true,
    "UploadCommand": null,
    "UseLegacyPaths": false,
    "ForceSimpleDirectoryExists": false,
    "RaiseEventsFromCurrentThread": false,
    "As400ListingDateFormat": null,
    "DisableImplicitAs400NameFormat": false,
    "SslUpgradeType": "TLS",
    "SslReuseSessions": true,
    "ForceExtendedDataChannelCommand": false,
    "AlwaysResolveServerName": false,
    "EnableFactsNegotiation": null,
    "CompressionLevel": 6,
    "SkipDuplicateItems": true,
    "BackslashIsRemoteDirectorySeparator": true,
    "EnableDummyRenameForFileExists": false,
    "EnableBrokenShutdownWorkaround": null,
    "MdtmSetTimeOffset": null,
    "GetFileOpenRemoteFirst": false,
    "SslAcceptAllCertificates": true,
    "SslAllowedVersions": "Any",
    "SslServerName": null,
    "SslAllowedSuites": "RSA_WITH_3DES_EDE_CBC_SHA, RSA_WITH_AES_128_CBC_SHA, RSA_WITH_AES_256_CBC_SHA, DHE_RSA_WITH_3DES_EDE_CBC_SHA, DHE_RSA_WITH_AES_128_CBC_SHA, DHE_RSA_WITH_AES_256_CBC_SHA, DHE_RSA_WITH_AES_128_CBC_SHA256, DHE_RSA_WITH_AES_256_CBC_SHA256, ECDHE_RSA_WITH_AES_128_CBC_SHA, ECDHE_RSA_WITH_AES_256_CBC_SHA, ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, ECDHE_ECDSA_WITH_AES_128_CBC_SHA, ECDHE_ECDSA_WITH_AES_256_CBC_SHA, ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, DHE_RSA_WITH_AES_128_GCM_SHA256, DHE_RSA_WITH_AES_256_GCM_SHA384, Fast",
    "SslAllowedCurves": "All",
    "SslAllowVulnerableSuites": false,
    "SslDoNotInsertEmptyFragment": false,
    "SslRenegotiationExtensionEnabled": true,
    "SslServerNameIndicationEnabled": true,
    "SslServerCertificateVerifier": {},
    "SslClientCertificateRequestHandler": {},
    "SslMinimumDiffieHellmanKeySize": 1024,
    "SslSession": null,
    "SslServerCertificateValidationOptions": "None",
    "SslStrictKeyUsageValidation": false
}

The log on our side

2022-06-20 09:39:20.354 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "<<< ": 227 Entering Passive Mode (51,124,201,77,160,40)
    2022-06-20 09:39:20.358 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" ">>> ": STOR testupload.txt
    2022-06-20 09:39:20.360 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp": Establishing data connection to 51.124.201.77:41000.
    2022-06-20 09:39:20.362 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "Proxy": Connecting to 11.11.11.11:41000 (no proxy).
    2022-06-20 09:39:20.370 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "Proxy": Connection established.
    2022-06-20 09:39:20.372 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp": Established data connection from 22.22.22.22:59970.
    2022-06-20 09:39:20.374 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "<<< ": 150 Opening data connection
    2022-06-20 09:39:20.377 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp": Upgrading data connection to TLS.
    2022-06-20 09:39:20.380 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Using classic TLS core.
    2022-06-20 09:39:20.382 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Enabled cipher suites: 0x000F3DF7EBE00640.
    2022-06-20 09:39:20.383 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Applicable cipher suites: 0x000F3DF7EBE00640.
    2022-06-20 09:39:20.385 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ClientHello was sent.
    2022-06-20 09:39:20.407 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: TLS socket was closed, 0 bytes of data were received.
    2022-06-20 09:39:20.410 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: TLS socket closed while negotiation was in progress.
    2022-06-20 09:39:20.414 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Closing TLS socket.
    2022-06-20 09:39:20.436 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp": Error while starting data transfer: Rebex.Net.FtpException: The server has closed the connection. ---> Rebex.Net.TlsException: Connection was closed by the remote connection end.
       at iizsj.dgpfm.fosdf()
       at iizsj.eefpa.gnzor()
       at Rebex.Net.TlsSocket.yciew()
       at Rebex.Net.TlsSocket.Negotiate()
       at iizsj.vkvpq.xtjgq(TlsParameters p0, TlsSession p1, FtpTransferState p2, Boolean p3)
       at iizsj.lqpyn.xtjgq(TlsParameters p0, TlsSession p1, FtpTransferState p2, Boolean p3)
       at Rebex.Net.Ftp.wvoov(String p0, Boolean p1, vkvpq p2, ziqoa p3, Int64 p4, FtpTransferState p5)
       --- End of inner exception stack trace ---
       at Rebex.Net.Ftp.wvoov(String p0, Boolean p1, vkvpq p2, ziqoa p3, Int64 p4, FtpTransferState p5)

The log on the sever side

<event seq="7631" time="2022-06-17 12:03:45.525513 +0200" app="BvSshServer 8.49" name="I_FTP_PASV_DISPATCHER_DATA_FAILED" desc="FTP passive data connection failed.">
    <parameters 
        remoteAddress="22.22.22.22:2112" 
        loc="NL/EU" listenAddress="0.0.0.0:41000" 
        failureReason="NoTlsSessionId"/>
    <help message="The client has tried to perform a full TLS handshake for a data connection. The client must resume the TLS session from the control connection by issuing an abbreviated TLS handshake with a correct TLS session ID."/>
</event>
Applies to: Rebex FTP/SSL

1 Answer

0 votes
by (147k points)
edited by

Update: To resolve this issue, upgrade to Rebex FTP R6.5 (or higher) and make sure to set ReuseControlConnectionSession to true.

Hello

I am somewhat puzzled by the following statement:

First had trouble with the connection itself. With your help it was solved by
ReuseControlConnectionSession = false

This seems somewhat strange. ReuseControlConnectionSession has not effect on the initial connection (the control connection), which means that setting it to true (which is also the default value) should have no ill effects. If this is not the case, would it be possible to provide two logs for comparison, one with ReuseControlConnectionSession set to true and the other with false?

Additionally, Bitvise FTPS server apparently insists that the FTP client must reuse the control connection session for the data connection. Therefore, setting ReuseControlConnectionSession to false is not going to work, because that setting instructs the FTP not to reuse the control connection session.

by (170 points)
I have to admit I only know the very basics about this protocol. So I might misuesd some words. But I try to summarize:

Our first issue was a connection error. For which we exchanged emails. The log extract is

2022-06-20 14:20:04.204 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Trying to resume session.
2022-06-20 14:20:04.204 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ClientHello was sent.
2022-06-20 14:20:04.222 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ServerHello was received.
2022-06-20 14:20:04.222 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Negotiating TLS 1.2, RSA with ephemeral ECDH, AES with 256-bit key in GCM mode, AEAD.
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: The server supports secure renegotiation.
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:Certificate was received.
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ServerKeyExchange was received.
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ServerHelloDone was received.
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Verifying server certificate ('CN=*.xxxxxxxx.net').
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Certificate verification result: Accept
2022-06-20 14:20:04.223 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Verifying server key exchange signature.
2022-06-20 14:20:04.224 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Using ephemeral ECDH public key exchange with NIST P-384 curve.
2022-06-20 14:20:04.228 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ClientKeyExchange was sent.
2022-06-20 14:20:04.228 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: CipherSpec:ChangeCipherSpec was sent.
2022-06-20 14:20:04.229 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:Finished was sent.
2022-06-20 14:20:04.235 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: TLS socket was closed, 0 bytes of data were received.
2022-06-20 14:20:04.239 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: TLS socket closed while negotiation was in progress.
2022-06-20 14:20:04.240 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Closing TLS socket.
2022-06-20 14:20:04.241 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "<<< ": 450 TLS session for the data connection was not resumed from the control connection.
2022-06-20 14:20:04.254 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp": Error while starting data transfer: Rebex.Net.FtpException: TLS session for the data connection was not resumed from the control connection (450).
   at Rebex.Net.Ftp.wvoov(String p0, Boolean p1, vkvpq p2, ziqoa p3, Int64 p4, FtpTransferState p5)


You explained it and pointed out the ReuseControlConnectionSession setting

According to the log, the client did actually attempt to establish data connection by resuming the TLS session from the control. This is indicated by the following log entry:
2022-06-02 11:39:28.234 [ 25] [Information] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: Trying to resume session.
2022-06-02 11:39:28.235 [ 25] [Debug] Tie.MessagePortal.Communication.AddIns.Ftp.FtpAddIn, "Rebex.Net.Ftp" "TLS": Data connection: HandshakeMessage:ClientHello was sent.
(This behavior is controlled using Ftp.Settings.ReuseControlConnectionSession setting, but it’s enabled by default because many FTP server enforce it.)


So the first try we did was to flip that Ftp.Settings.ReuseControlConnectionSession boolean. And then it went further successfully until the first upload attempt. The settings and the relevant part of the log are above in the original question.

I tried to put the full log there but it exceeds the allowed length of the message.
by (147k points)
Sorry for the confusion. I did not mean to suggest disabling ReuseControlConnectionSession, I just wanted to point out that reusing control connection session is enabled by default. Also, apparently, even the very first log from June 2nd (which did not touch ReuseControlConnectionSession) failed with "450 TLS session for the data connection was not resumed from the control connection" error in response to "STOR testupload.txt" command.

In the two latest logs, ReuseControlConnectionSession with both true and false resulted in a successful connection, and in both cases, the error only occurred while attempting the upload - which show that ReuseControlConnectionSession has indeed no effect on the control connection. So in both cases, the communication wents successfully until the first upload attempt. However, the actual error is different in those two cases:

1) With "reuse=true", the server lets the client negotiate a TLS session for the data connection, but then responds with the "450" error, complaining that the client did not resume the TLS session from the control connection (which is strange - the client did attempt exactly that, but the server did not comply).

2) With "reuse=false", the server does not even let the client negotiate a TLS session for the data connection - upon receiving the ClientHello message, the server immediatelly closes the data connection.

So ReuseControlConnectionSession=true actually seems to get you a slightly bit further than ReuseControlConnectionSession=false. That makes sense, because the server clearly states that it expects the client to resume the TLS session from the control connection. But why is it refusing that as well? That's what we don't know - the server maintainer or vendor should be able to answer that question.

Are you able to connect to the same FTP server and account using any third-party FTP client such as WinSCP (in FTP over TLS mode) or FileZilla? If you are, would it be possible to share a log with us for comparison?

Also, would it be possible to check the server log to see why it rejected the FTP client's attempt to resume the TLS session from the control connection, and proceeded to perform a full TLS negotiation instead?
by (170 points)
I sent a WinSCP log in e-mail.
Connecting and successfully uploading a file to BitVise through FTPs
by (147k points)
Thanks! We have been able to reproduce a similar issue with current version of Bitvise, and it looks like that lack of support for some TLS extension might be causing the problem. We are investigating this and let you know what we find soon.
by (170 points)
We finally had a chance to test again with the binaries you sent. It is working now. Thank You!
by (147k points)
Thanks! We'll publish these enhancements with a new version of Rebex FTP soon!
by (147k points)
Thanks once again! These enhancements were published with Rebex FTP / Rebex File Transfer Pack / Rebex Total Pack R6.5: https://www.rebex.net/file-transfer-pack/history.aspx#R6.5
...