Topic "FTPS connection take a long time on windows 2008 R2"

Author Message
Guest




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...
Advertisements
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24555
Location: Prague, Czechia
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).
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.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24555
Location: Prague, Czechia
Show us FileZilla log. A real log file, not the message log from GUI.
Guest




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
Guest




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?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24555
Location: Prague, Czechia
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
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24555
Location: Prague, Czechia
prikryl 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:
http://winscp.net/tracker/show_bug.cgi?id=1402
Advertisements

You can post new topics in this forum






Search Site

What is WinSCP?

It is award-winning SFTP client, SCP client, FTPS client and FTP client integrated into one software program for file transfer to FTP server or secure SFTP server. [More]

And it's free!

Donate

About donations

$9   $19   $49   $99

About donations

Recommend

WinSCP Privacy Policy

WinSCP License