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