[stunnel-users] slow transfer of smtp

[jason kawaja]

greetings.  clients connects normally when not using ssl (stunnel).   
when using ssl the connection on the client end appears to take about  
a minute but does eventually work (mail is sent through encrypted).  
shown below is the log with debug=7 and a space between the area  
where a "pause" seems to be, ideas on what could be occurring during  
this time to induce the "pause"?

client = machine making connection.
server = machine running stunnel accepting the connection.

2007.02.14 12:24:06 LOG7[69377:134631424]: imaps accepted FD=9 from  
client:62847
2007.02.14 12:24:06 LOG7[69377:134633984]: imaps started
2007.02.14 12:24:06 LOG7[69377:134633984]: FD 9 in non-blocking mode
2007.02.14 12:24:06 LOG7[69377:134633984]: TCP_NODELAY option set on  
local socket
2007.02.14 12:24:06 LOG7[69377:134633984]: FD 10 in non-blocking mode
2007.02.14 12:24:06 LOG7[69377:134633984]: FD 11 in non-blocking mode
2007.02.14 12:24:06 LOG7[69377:134633984]: Connection from client: 
62847 permitted by libwrap
2007.02.14 12:24:06 LOG5[69377:134633984]: imaps connected from  
client:62847
2007.02.14 12:24:06 LOG7[69377:134631424]: Cleaning up the signal pipe
2007.02.14 12:24:06 LOG6[69377:134631424]: Child process 69387  
finished with code 0
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): before/ 
accept initialization
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
read client hello A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
write server hello A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
write certificate A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
write server done A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
flush data
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
read client key exchange A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
read finished A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
write change cipher spec A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
write finished A
2007.02.14 12:24:06 LOG7[69377:134633984]: SSL state (accept): SSLv3  
flush data
2007.02.14 12:24:06 LOG7[69377:134633984]:    1 items in the session  
cache
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 client connects  
(SSL_connect())
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 client connects that  
finished
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 client  
renegotiatations requested
2007.02.14 12:24:06 LOG7[69377:134633984]:    1 server connects  
(SSL_accept())
2007.02.14 12:24:06 LOG7[69377:134633984]:    1 server connects that  
finished
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 server  
renegotiatiations requested
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 session cache hits
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 session cache misses
2007.02.14 12:24:06 LOG7[69377:134633984]:    0 session cache timeouts
2007.02.14 12:24:06 LOG6[69377:134633984]: SSL accepted: new session  
negotiated
2007.02.14 12:24:06 LOG6[69377:134633984]: Negotiated ciphers: AES128- 
SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
2007.02.14 12:24:06 LOG7[69377:134633984]: FD 10 in non-blocking mode
2007.02.14 12:24:06 LOG7[69377:134633984]: imaps connecting server:143
2007.02.14 12:24:06 LOG7[69377:134633984]: connect_wait: waiting 10  
seconds
2007.02.14 12:24:06 LOG7[69377:134633984]: connect_wait: connected
2007.02.14 12:24:06 LOG7[69377:134633984]: Remote FD=10 initialized
2007.02.14 12:24:06 LOG7[69377:134633984]: TCP_NODELAY option set on  
remote socket
2007.02.14 12:24:08 LOG7[69377:134631424]: ssmtp accepted FD=11 from  
client:62848
2007.02.14 12:24:08 LOG7[69377:134881280]: ssmtp started
2007.02.14 12:24:08 LOG7[69377:134881280]: FD 11 in non-blocking mode
2007.02.14 12:24:08 LOG7[69377:134881280]: TCP_NODELAY option set on  
local socket
2007.02.14 12:24:08 LOG7[69377:134881280]: FD 12 in non-blocking mode
2007.02.14 12:24:08 LOG7[69377:134881280]: FD 13 in non-blocking mode
2007.02.14 12:24:08 LOG7[69377:134881280]: Connection from client: 
62848 permitted by libwrap
2007.02.14 12:24:08 LOG5[69377:134881280]: ssmtp connected from  
client:62848
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): before/ 
accept initialization
2007.02.14 12:24:08 LOG7[69377:134631424]: Cleaning up the signal pipe
2007.02.14 12:24:08 LOG6[69377:134631424]: Child process 69391  
finished with code 0
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
read client hello A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
write server hello A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
write certificate A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
write server done A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
flush data
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
read client key exchange A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
read finished A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
write change cipher spec A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
write finished A
2007.02.14 12:24:08 LOG7[69377:134881280]: SSL state (accept): SSLv3  
flush data
2007.02.14 12:24:08 LOG7[69377:134881280]:    2 items in the session  
cache
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 client connects  
(SSL_connect())
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 client connects that  
finished
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 client  
renegotiatations requested
2007.02.14 12:24:08 LOG7[69377:134881280]:    2 server connects  
(SSL_accept())
2007.02.14 12:24:08 LOG7[69377:134881280]:    2 server connects that  
finished
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 server  
renegotiatiations requested
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 session cache hits
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 session cache misses
2007.02.14 12:24:08 LOG7[69377:134881280]:    0 session cache timeouts
2007.02.14 12:24:08 LOG6[69377:134881280]: SSL accepted: new session  
negotiated
2007.02.14 12:24:08 LOG6[69377:134881280]: Negotiated ciphers: AES128- 
SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
2007.02.14 12:24:08 LOG7[69377:134881280]: FD 12 in non-blocking mode
2007.02.14 12:24:08 LOG7[69377:134881280]: ssmtp connecting server:25
2007.02.14 12:24:08 LOG7[69377:134881280]: connect_wait: waiting 10  
seconds
2007.02.14 12:24:08 LOG7[69377:134881280]: connect_wait: connected
2007.02.14 12:24:08 LOG7[69377:134881280]: Remote FD=12 initialized
2007.02.14 12:24:08 LOG7[69377:134881280]: TCP_NODELAY option set on  
remote socket

2007.02.14 12:25:06 LOG7[69377:134631424]: imaps accepted FD=13 from  
client:62850
2007.02.14 12:25:06 LOG7[69377:134882816]: imaps started
2007.02.14 12:25:06 LOG7[69377:134882816]: FD 13 in non-blocking mode
2007.02.14 12:25:06 LOG7[69377:134882816]: TCP_NODELAY option set on  
local socket
2007.02.14 12:25:06 LOG7[69377:134882816]: FD 14 in non-blocking mode
2007.02.14 12:25:06 LOG7[69377:134882816]: FD 15 in non-blocking mode
2007.02.14 12:25:06 LOG7[69377:134882816]: Connection from client: 
62850 permitted by libwrap
2007.02.14 12:25:06 LOG5[69377:134882816]: imaps connected from  
client:62850
2007.02.14 12:25:06 LOG7[69377:134631424]: Cleaning up the signal pipe
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): before/ 
accept initialization
2007.02.14 12:25:06 LOG6[69377:134631424]: Child process 69478  
finished with code 0
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
read client hello A
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
write server hello A
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
write change cipher spec A
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
write finished A
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
flush data
2007.02.14 12:25:06 LOG7[69377:134882816]: SSL state (accept): SSLv3  
read finished A
2007.02.14 12:25:06 LOG7[69377:134882816]:    2 items in the session  
cache
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 client connects  
(SSL_connect())
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 client connects that  
finished
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 client  
renegotiatations requested
2007.02.14 12:25:06 LOG7[69377:134882816]:    3 server connects  
(SSL_accept())
2007.02.14 12:25:06 LOG7[69377:134882816]:    3 server connects that  
finished
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 server  
renegotiatiations requested
2007.02.14 12:25:06 LOG7[69377:134882816]:    1 session cache hits
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 session cache misses
2007.02.14 12:25:06 LOG7[69377:134882816]:    0 session cache timeouts
2007.02.14 12:25:06 LOG6[69377:134882816]: SSL accepted: previous  
session reused
2007.02.14 12:25:06 LOG7[69377:134882816]: FD 14 in non-blocking mode
2007.02.14 12:25:06 LOG7[69377:134882816]: imaps connecting server:143
2007.02.14 12:25:06 LOG7[69377:134882816]: connect_wait: waiting 10  
seconds
2007.02.14 12:25:06 LOG7[69377:134882816]: connect_wait: connected
2007.02.14 12:25:06 LOG7[69377:134882816]: Remote FD=14 initialized
2007.02.14 12:25:06 LOG7[69377:134882816]: TCP_NODELAY option set on  
remote socket


--
Jason Kawaja, 2-4568
IT Expert, UF Dept of ECE