File upload under FTPS 5 second delays

It seems that for some reason whenever I upload a file there are three 5 second delays before the file is actually uploaded to the server. Uploading through another client (FileZilla) does not give me any delays. I'm not quite sure what's causing it but it might have something to do with PHPStorm and certificate authenticating. It's SSL/TLS related for sure, since when turning it off it works fine.

My FTP server is ProFTPD 1.3.4a

This is my tls.conf:

 TLSEngine                               on

TLSLog                                  /var/log/proftpd/tls.log

TLSProtocol                             SSLv3 TLSv1

TLSRSACertificateFile                   /etc/ssl/localcerts/certname.crt

TLSRSACertificateKeyFile                /etc/ssl/localcerts/certname.key

TLSCACertificatePath                    /etc/ssl/certs/

TLSOptions                      NoCertRequest EnableDiags NoSessionReuseRequired

#TLSVerifyClient                         on

TLSRequired                             auth 


And my proftpd.conf:
 UseIPv6                         on

ServerName                      "domain.tld"

IdentLookups                    on

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

AuthOrder                       mod_sql.c

Include /etc/proftpd/sql.conf

Include /etc/proftpd/tls.conf 


The SQL auth is working fine, it's not causing the delays. The delays stop when i comment the tls.conf line, so it's a SSL problem for sure, I just don't know what it is.
Could it be that there is a problem with PHPStorm authenticating the server certificate? Root CA certificates have been installed on the server and the server certificate can be verified by openssl.

Lastly, a tls.log snippet which shows the delays:
Aug 29 22:18:46 mod_tls/2.4.3[2438]: TLSOption EnableDiags enabled, setting diagnostics callback
Aug 29 22:18:46 mod_tls/2.4.3[2438]: TLS/TLS-C requested, starting TLS handshake
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: before/accept initialization
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: unknown state
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client hello A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server hello A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write certificate A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server done A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client key exchange A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read finished A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write change cipher spec A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write finished A
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] ok: SSL negotiation finished successfully
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: SSL negotiation finished successfully
Aug 29 22:18:46 mod_tls/2.4.3[2438]: client supports secure renegotiations
Aug 29 22:18:46 mod_tls/2.4.3[2438]: TLSv1/SSLv3 connection accepted, using cipher AES128-SHA (128 bits)
Aug 29 22:18:46 mod_tls/2.4.3[2438]: Protection set to Private
Aug 29 22:18:46 mod_tls/2.4.3[2438]: starting TLS negotiation on data connection
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: before/accept initialization
Aug 29 22:18:46 mod_tls/2.4.3[2438]: [info] accepting: unknown state
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client hello A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server hello A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write certificate A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server done A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client key exchange A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read certificate verify A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read finished A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write change cipher spec A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write finished A
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:51 mod_tls/2.4.3[2438]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] ok: SSL negotiation finished successfully
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: SSL negotiation finished successfully
Aug 29 22:18:51 mod_tls/2.4.3[2438]: TLSv1/SSLv3 data connection accepted, using cipher AES128-SHA (128 bits)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] writing: SSL/TLS alert warning: close notify
Aug 29 22:18:51 mod_tls/2.4.3[2438]: starting TLS negotiation on data connection
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: before/accept initialization
Aug 29 22:18:51 mod_tls/2.4.3[2438]: [info] accepting: unknown state
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client hello A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server hello A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write certificate A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server done A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client key exchange A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read certificate verify A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read finished A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write change cipher spec A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write finished A
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:18:56 mod_tls/2.4.3[2438]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] ok: SSL negotiation finished successfully
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: SSL negotiation finished successfully
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] received TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] reading: SSL/TLS alert warning: close notify
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] writing: SSL/TLS alert warning: close notify
Aug 29 22:18:56 mod_tls/2.4.3[2438]: starting TLS negotiation on data connection
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: before/accept initialization
Aug 29 22:18:56 mod_tls/2.4.3[2438]: [info] accepting: unknown state
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientHello' Handshake message (149 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client hello A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHello' Handshake message (81 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server hello A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Certificate' Handshake message (1299 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write certificate A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'ServerHelloDone' Handshake message (4 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write server done A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client certificate A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] received TLSv1 'ClientKeyExchange' Handshake message (262 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read client key exchange A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read certificate verify A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] received TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] received TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 read finished A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 ChangeCipherSpec message (1 byte)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write change cipher spec A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 'Finished' Handshake message (16 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 write finished A
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSLv3 flush data
Aug 29 22:19:00 mod_tls/2.4.3[2438]: TLSv1/SSLv3 renegotiation accepted, using cipher AES128-SHA (128 bits)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] ok: SSL negotiation finished successfully
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] accepting: SSL negotiation finished successfully
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [msg] sent TLSv1 warning 'close_notify' Alert message (2 bytes)
Aug 29 22:19:00 mod_tls/2.4.3[2438]: [info] writing: SSL/TLS alert warning: close notify

Please sign in to leave a comment.