FTPS connection take a long time on windows 2008 R2

Advertisement

Guest

FTPS connection take a long time on windows 2008 R2

We have FTPS need to run on windows 2008 R2 server. I am using explicit FTP over SSL/TLS protocol. I was using port 21 with version 4.3.5 to connect, everything looks fine. Later, we were asked to switch a new SSL certificate and the port number change to 20021. Version 4.3.5 does not support the new certificate so I have to upgrade to version 5.7.6. I can connect to port 20021, however, the connection take a long time. I tried run the same version on windows 7 and it's normal. Does version 5.7.6 not support windows 2008? I post my log below:

FROM Windows 2008
. 2016-01-20 12:22:34.123 Connecting to *******com:20021 ...
. 2016-01-20 12:22:34.123 TLS layer changed state from unconnected to connecting
. 2016-01-20 12:22:34.123 TLS layer changed state from connecting to connected
. 2016-01-20 12:22:34.123 Connected with *********com:20021, negotiating TLS connection...
< 2016-01-20 12:22:34.295 220 **** FTPS (Version Wed Jan 20 12:22:33 2016) server ready.
> 2016-01-20 12:22:34.295 AUTH TLS
< 2016-01-20 12:22:34.342 234 Enabling TLS, awaiting negotiations.
. 2016-01-20 12:22:34.950 TLS connect: SSLv3 read server hello A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 read server certificate A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 read server key exchange A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 read server done A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 write client key exchange A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 write change cipher spec A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 write finished A
. 2016-01-20 12:22:35.543 TLS connect: SSLv3 flush data
. 2016-01-20 12:22:35.855 TLS connect: SSLv3 read finished A
. 2016-01-20 12:22:35.855 Verifying certificate for "*********" with fingerprint xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx and 20 failures
. 2016-01-20 12:23:20.894 Certificate common name "*********com" matches hostname
. 2016-01-20 12:23:20.894 Certificate for "*********" matches cached fingerprint and failures
. 2016-01-20 12:23:20.894 Using TLSv1.1, cipher TLSv1/SSLv3: DHE-RSA-AES256-SHA, 2048 bit RSA
. 2016-01-20 12:23:20.910 TLS connection established. Waiting for welcome message...


FROM WINDOWS 7
. 2016-01-20 23:17:52.426 Connecting to *********com:20021 ...
. 2016-01-20 23:17:52.426 TLS layer changed state from unconnected to connecting
. 2016-01-20 23:17:52.426 TLS layer changed state from connecting to connected
. 2016-01-20 23:17:52.426 Connected with *********com:20021, negotiating TLS connection...
< 2016-01-20 23:17:52.568 220 **** FTPS (Version Wed Jan 20 23:17:52 2016) server ready.
> 2016-01-20 23:17:52.568 AUTH TLS
< 2016-01-20 23:17:52.594 234 Enabling TLS, awaiting negotiations.
. 2016-01-20 23:17:53.808 TLS connect: SSLv3 read server hello A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 read server certificate A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 read server key exchange A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 read server done A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 write client key exchange A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 write change cipher spec A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 write finished A
. 2016-01-20 23:17:54.519 TLS connect: SSLv3 flush data
. 2016-01-20 23:17:54.857 TLS connect: SSLv3 read finished A
. 2016-01-20 23:17:54.857 Verifying certificate for "*********" with fingerprint xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx and 20 failures
. 2016-01-20 23:17:54.913 Certificate verified against Windows certificate store
. 2016-01-20 23:17:54.914 Certificate common name "*********com" matches hostname
. 2016-01-20 23:17:54.914 Using TLSv1.1, cipher TLSv1/SSLv3: DHE-RSA-AES256-SHA, 2048 bit RSA
. 2016-01-20 23:17:54.954 TLS connection established. Waiting for welcome message...

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
28,802
Location:
Prague, Czechia

Re: FTPS connection take a long time on windows 2008 R2

In that delay between "Verifying certificate for..." and "Certificate common name ...", WinSCP is asking Windows certificate store to verify the server's certificate. I do not know why it takes so long. Maybe you have too many root certificates in the store? (that's just a wild guess).

Reply with quote

Guest

We have about 13 root certificate on server 2008. I don't think it's relate to that because I have no problem using filezilla to connect. I am wondering what does winscp doing while searching windows certificate store.

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
28,802
Location:
Prague, Czechia

Show us FileZilla log. A real log file, not the message log from GUI.

Reply with quote

Guest

filezilla log file

2016-01-31 22:11:52 6236 3 Status: Resolving address of **********.com
2016-01-31 22:11:52 6236 3 Status: Connecting to xxx.xxx.xxx.xxx:20021...
2016-01-31 22:11:52 6236 3 Status: Connection established, waiting for welcome message...
2016-01-31 22:11:52 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:52 6236 3 Response: 220 *****FTPS (Version Sun Jan 31 22:11:52 2016) server ready.
2016-01-31 22:11:52 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:52 6236 3 Command: AUTH TLS
2016-01-31 22:11:52 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:52 6236 3 Response: 234 Enabling TLS, awaiting negotiations.
2016-01-31 22:11:52 6236 3 Status: Initializing TLS...
2016-01-31 22:11:52 6236 3 Trace: CTlsSocket::Handshake()
2016-01-31 22:11:52 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:52 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:53 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:53 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:54 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:54 6236 3 Trace: TLS Handshake successful
2016-01-31 22:11:54 6236 3 Trace: Cipher: AES-128-CBC, MAC: SHA1
2016-01-31 22:11:54 6236 3 Status: Verifying certificate...
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: USER NT1XSH4M
2016-01-31 22:11:56 6236 3 Status: TLS/SSL connection established.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 331 Password required for NT1XSH4M.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: PASS ********
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 230 User *****logged in.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: SYST
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 215 UNIX
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: FEAT
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 211- Extensions supported:
2016-01-31 22:11:56 6236 3 Response: PASV
2016-01-31 22:11:56 6236 3 Response: AUTH TLS
2016-01-31 22:11:56 6236 3 Response: PBSZ
2016-01-31 22:11:56 6236 3 Response: PROT
2016-01-31 22:11:56 6236 3 Response: CCC
2016-01-31 22:11:56 6236 3 Response: 211 End
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: PBSZ 0
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 200 PBSZ Command successful.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Command: PROT P
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 200 PROT Command successful.
2016-01-31 22:11:56 6236 3 Status: Connected
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::ResetOperation(0)
2016-01-31 22:11:56 6236 3 Trace: CControlSocket::ResetOperation(0)
2016-01-31 22:11:56 6236 3 Status: Retrieving directory listing...
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::ChangeDirSend()
2016-01-31 22:11:56 6236 3 Command: PWD
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 257 "********" is current directory.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::ResetOperation(0)
2016-01-31 22:11:56 6236 3 Trace: CControlSocket::ResetOperation(0)
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::ParseSubcommandResult(0)
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::ListSubcommandResult()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferSend()
2016-01-31 22:11:56 6236 3 Command: TYPE I
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 200 Type set to I
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferParseResponse()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferSend()
2016-01-31 22:11:56 6236 3 Command: PASV
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 227 Entering Passive Mode (142,245,8,80,101,244)
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferParseResponse()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferSend()
2016-01-31 22:11:56 6236 3 Command: LIST
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:56 6236 3 Response: 150 Opening data connection for '/bin/ls'.
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferParseResponse()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::SendNextCommand()
2016-01-31 22:11:56 6236 3 Trace: CFtpControlSocket::TransferSend()
2016-01-31 22:11:56 6236 3 Trace: CTransferSocket::OnConnect
2016-01-31 22:11:56 6236 3 Trace: CTlsSocket::Handshake()
2016-01-31 22:11:56 6236 3 Trace: Trying to resume existing TLS session.
2016-01-31 22:11:56 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:56 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:57 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:57 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:58 6236 3 Trace: CTlsSocket::ContinueHandshake()
2016-01-31 22:11:58 6236 3 Trace: TLS Handshake successful
2016-01-31 22:11:58 6236 3 Trace: Cipher: AES-128-CBC, MAC: SHA1
2016-01-31 22:11:58 6236 3 Trace: CTransferSocket::OnConnect
2016-01-31 22:11:58 6236 3 Trace: CTlsSocket::OnSocketEvent(): pending data, postponing close event
2016-01-31 22:11:58 6236 3 Trace: CTransferSocket::TransferEnd(1)
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::TransferEnd()
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::OnReceive()
2016-01-31 22:11:58 6236 3 Response: 226 Transfer complete.
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::TransferParseResponse()
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::ResetOperation(0)
2016-01-31 22:11:58 6236 3 Trace: CControlSocket::ResetOperation(0)
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::ParseSubcommandResult(0)
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::ListSubcommandResult()
2016-01-31 22:11:58 6236 3 Trace: CFtpControlSocket::ResetOperation(0)
2016-01-31 22:11:58 6236 3 Trace: CControlSocket::ResetOperation(0)
2016-01-31 22:11:58 6236 3 Status: Directory listing successful

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
28,802
Location:
Prague, Czechia

Re: filezilla log file

Actually I realized that FileZilla never tries to verify the certificate against Windows certificate store. It will always ask you to verify the certificate personally. So it's irrelevant that there's no delay in FileZilla.

Also I've noticed that the certificate is actually not trusted by the Windows 2008 certificate store anyway (maybe that's the reason it takes longer?).

You had have verified the certificate personally in some previous session.

So I can maybe revert the test. First check if the certificate was verified personally previously. And only if it was not, revert to the certificate store.

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
28,802
Location:
Prague, Czechia

Re: filezilla log file

martin wrote:

So I can maybe revert the test. First check if the certificate was verified personally previously. And only if it was not, revert to the certificate store.
This issue has been added to the tracker:
https://winscp.net/tracker/1402

Reply with quote

Advertisement

You can post new topics in this forum