TechQA.

FTPS 2-5 second delays

716 views Asked by At

For developing in PHP I use the PHPStorm IDE which has an embedded FTP client. Whenever I upload a file to the FTP Server, I get 2-5 second delays, which causes the file upload to take ~10-15 seconds. It has to be related to SSL, either the netotiation or the verification of the server certificate by the FTP client. Whenever I switch to FTP, the upload is lightning fast. I should also add that when I connect with a different client (FileZilla) uploading and downloading works perfectly fine. I have ruled out the UseIPv6 and IdentLookups options, turning them off has no effect. I connect in PASSIVE mode so that's not causing any problems either.

I'm out of ideas and could really use some help! Thanks.

The FTP server is proftpd 1.3.4a on a Debian Wheezy machine.

proftpd.conf:

Include /etc/proftpd/modules.conf
UseIPv6                         on
IdentLookups                    on
ServerName                      "domain.tld"
ServerType                      standalone
DeferWelcome                    on
MultilineRFC2228                on
DefaultServer                   on
ShowSymlinks                    on
TimeoutNoTransfer               600
TimeoutStalled                  600
TimeoutIdle                     1200
DisplayLogin                    welcome.msg
DisplayChdir                    .message true
ListOptions                     "-l"
DenyFilter                      \*.*/
DefaultRoot                     ~
RequireValidShell               on
Port                            21
PassivePorts                  49152 65534
MaxInstances                    30
Umask                           027  027
AllowOverwrite                  on
AuthOrder                       mod_sql.c
# UseSendFile                   off
<IfModule mod_quotatab.c>
    QuotaEngine off
</IfModule>

<IfModule mod_ratio.c>
    Ratios off
</IfModule>

<IfModule mod_delay.c>
    DelayEngine off
</IfModule>

#
# Alternative authentication frameworks
#
#Include /etc/proftpd/ldap.conf
Include /etc/proftpd/sql.conf

#
# This is used for FTPS connections
#
Include /etc/proftpd/tls.conf

tls.conf:

<IfModule mod_tls.c>
    TLSEngine                               on
    TLSLog                                  /var/log/proftpd/tls.log
    TLSProtocol                             SSLv3 TLSv1

    TLSRSACertificateFile                   /etc/ssl/localcerts/domain_tld.crt
    TLSRSACertificateKeyFile                /etc/ssl/localcerts/domain_tld.key
    TLSCACertificatePath                    /etc/ssl/certs/

    TLSOptions                      NoCertRequest EnableDiags NoSessionReuseRequired
    #TLSVerifyClient                         on
    TLSRequired                             auth

    #TLSRenegotiate                          required off
</IfModule>

And lastly, the tls.log from uploading a file through the PHPStorm IDE:

Aug 30 08:56:46 mod_tls/2.4.3[8365]: TLSOption EnableDiags enabled, setting diagnostics callback
Aug 30 08:56:46 mod_tls/2.4.3[8365]: TLS/TLS-C requested, starting TLS handshake
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: before/accept initialization
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: unknown state
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client hello A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server hello A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write certificate A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server done A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client key exchange A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read finished A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write change cipher spec A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write finished A
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] ok: SSL negotiation finished successfully
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: SSL negotiation finished successfully
Aug 30 08:56:46 mod_tls/2.4.3[8365]: client supports secure renegotiations
Aug 30 08:56:46 mod_tls/2.4.3[8365]: TLSv1/SSLv3 connection accepted, using cipher AES128-SHA (128 bits)
Aug 30 08:56:46 mod_tls/2.4.3[8365]: Protection set to Private
Aug 30 08:56:46 mod_tls/2.4.3[8365]: starting TLS negotiation on data connection
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: before/accept initialization
Aug 30 08:56:46 mod_tls/2.4.3[8365]: [info] accepting: unknown state
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client hello A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server hello A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write certificate A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server done A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client key exchange A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read certificate verify A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read finished A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write change cipher spec A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write finished A
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:50 mod_tls/2.4.3[8365]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] ok: SSL negotiation finished successfully
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: SSL negotiation finished successfully
Aug 30 08:56:50 mod_tls/2.4.3[8365]: TLSv1/SSLv3 data connection accepted, using cipher AES128-SHA (128 bits)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] writing: SSL/TLS alert warning: close notify
Aug 30 08:56:50 mod_tls/2.4.3[8365]: starting TLS negotiation on data connection
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: before/accept initialization
Aug 30 08:56:50 mod_tls/2.4.3[8365]: [info] accepting: unknown state
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client hello A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server hello A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write certificate A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server done A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client key exchange A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read certificate verify A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read finished A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write change cipher spec A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write finished A
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:52 mod_tls/2.4.3[8365]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] ok: SSL negotiation finished successfully
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: SSL negotiation finished successfully
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] received TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] reading: SSL/TLS alert warning: close notify
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] writing: SSL/TLS alert warning: close notify
Aug 30 08:56:52 mod_tls/2.4.3[8365]: starting TLS negotiation on data connection
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: before/accept initialization
Aug 30 08:56:52 mod_tls/2.4.3[8365]: [info] accepting: unknown state
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client hello A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server hello A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write certificate A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write server done A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client certificate A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read client key exchange A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read certificate verify A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 read finished A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write change cipher spec A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 write finished A
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSLv3 flush data
Aug 30 08:56:54 mod_tls/2.4.3[8365]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] ok: SSL negotiation finished successfully
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] accepting: SSL negotiation finished successfully
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 30 08:56:54 mod_tls/2.4.3[8365]: [info] writing: SSL/TLS alert warning: close notify
ssl ftp phpstorm ftps proftpd
Original Q&A
2

There are 2 answers

0
Castaglia On BEST ANSWER

The root cause for this has been found; the ProFTPD Bugzilla has a report and a fix for this:

http://bugs.proftpd.org/show_bug.cgi?id=4108

0
sroes On

Try changing the TLSProtocol configuration to TLSv1:

TLSProtocol TLSv1

Related Questions in SSL

Related Questions in FTP

Related Questions in PHPSTORM

Related Questions in FTPS

Related Questions in PROFTPD

Popular Questions

Popular Tags

javascript python java c# php android html jquery c++ css ios sql mysql r reactjs node.js arrays c asp.net json python-3.x ruby-on-rails .net sql-server swift django angular objective-c pandas excel

Trending Questions