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...

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).

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.

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

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

I seems solve the issue followed by the link https://www.rootusers.com/problems-with-winscp-verifying-ssl-certificates/ to copy file cacert.pem in the same location of winscp.exe.

I don't know why this is only happen on windows 2008, can you explain it?

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.

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