Re: ucspi-tls (attn: Scott Gifford)

On Thu, 02 Jun 2005 12:57:14 -0400
Scott Gifford <[email protected]> wrote:

> I'm not sure; it doesn't look good, but it's not specific enough to
> know exactly what's going on.
> 
> See if you get the error when you test with stunnel; with stunnel 3,
> I use something like:
> 
>     ./stunnel -D debug -n smtp -f -c -r
>     mail.actionwebservices.com:25
> 
> If you don't see the error with that, it's a client-specific
> problem.

Must be a client thing then:

# ./stunnel -D debug -n smtp -f -c -r trutwins.homeip.net:25
2005.06.02 13:25:08 LOG5[10199:1024]: Using 'trutwins.homeip.net.25'
as tcpwrapper service name
2005.06.02 13:25:08 LOG7[10199:1024]: Snagged 64 random bytes from
/root/.rnd
2005.06.02 13:25:08 LOG7[10199:1024]: Wrote 1024 new random bytes to
/root/.rnd
2005.06.02 13:25:08 LOG7[10199:1024]: RAND_status claims sufficient
entropy for the PRNG
2005.06.02 13:25:08 LOG6[10199:1024]: PRNG seeded successfully
2005.06.02 13:25:08 LOG5[10199:1024]: stunnel 3.26 on
i686-pc-linux-gnu PTHREAD+LIBWRAP with OpenSSL 0.9.7g 11 Apr 2005
2005.06.02 13:25:08 LOG7[10199:1024]: trutwins.homeip.net.25 started
2005.06.02 13:25:08 LOG7[10199:1024]: trutwins.homeip.net.25
connecting 24.94.218.197:25
2005.06.02 13:25:08 LOG7[10199:1024]: Remote FD=3 initialized
2005.06.02 13:25:08 LOG7[10199:1024]: Negotiations for smtp(client
side) started
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 220 0 mailfront ESMTP.
220 0 mailfront ESMTP
2005.06.02 13:25:09 LOG7[10199:1024]:  -> 220 0 mailfront ESMTP...
2005.06.02 13:25:09 LOG7[10199:1024]:  -> EHLO localhost..
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250-0.
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250-AUTH LOGIN PLAIN.
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250-STARTTLS.
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250-SIZE 0.
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250-8BITMIME.
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 250 PIPELINING.
2005.06.02 13:25:09 LOG7[10199:1024]:  -> STARTTLS..
2005.06.02 13:25:09 LOG7[10199:1024]:  <- 220 2.0.0 Ready to start
TLS.
2005.06.02 13:25:09 LOG7[10199:1024]: Relying on OpenSSL RSA Blinding.
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect):
before/connect initialization
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 write
client hello A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 read
server hello A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 read
server certificate A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 read
server key exchange A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 read
server done A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 write
client key exchange A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 write
change cipher spec A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 write
finished A
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 flush
data
2005.06.02 13:25:09 LOG7[10199:1024]: SSL state (connect): SSLv3 read
finished A
2005.06.02 13:25:09 LOG7[10199:1024]:    1 items in the session cache
2005.06.02 13:25:09 LOG7[10199:1024]:    1 client connects
(SSL_connect())
2005.06.02 13:25:09 LOG7[10199:1024]:    1 client connects that
finished
2005.06.02 13:25:09 LOG7[10199:1024]:    0 client renegotiatations
requested
2005.06.02 13:25:09 LOG7[10199:1024]:    0 server connects
(SSL_accept())
2005.06.02 13:25:09 LOG7[10199:1024]:    0 server connects that
finished
2005.06.02 13:25:09 LOG7[10199:1024]:    0 server renegotiatiations
requested
2005.06.02 13:25:09 LOG7[10199:1024]:    0 session cache hits
2005.06.02 13:25:09 LOG7[10199:1024]:    0 session cache misses
2005.06.02 13:25:09 LOG7[10199:1024]:    0 session cache timeouts
2005.06.02 13:25:09 LOG6[10199:1024]: Negotiated ciphers:
DHE-RSA-AES256-SHA      SSLv3 Kx=DH       Au=RSA  Enc=AES(256) 
Mac=SHA1
MAIL FROM: [email protected] 
250 Sender accepted.
RCPT TO: [email protected]
250 OK
DATA
354 End your message with a period.
Subject: stunnel test

this is a test!
.
250 Accepted message qp 31746 bytes 154
QUIT
221 Good bye.
2005.06.02 13:25:49 LOG7[10199:1024]: SSL alert (read): warning: close
notify
2005.06.02 13:25:49 LOG7[10199:1024]: SSL closed on SSL_read
2005.06.02 13:25:49 LOG7[10199:1024]: SSL alert (write): warning:
close notify
2005.06.02 13:25:49 LOG7[10199:1024]: SSL write shutdown (output
buffer empty)
2005.06.02 13:25:49 LOG7[10199:1024]: Socket write shutdown (output
buffer empty)
2005.06.02 13:25:49 LOG5[10199:1024]: Connection closed: 112 bytes
sent to SSL, 123 bytes sent to socket
2005.06.02 13:25:49 LOG7[10199:1024]: trutwins.homeip.net.25 finished
(0 left)

And in the qmail logs:

@40000000429f4eaf3aeb753c sslserver: status: 1/31
@40000000429f4eaf3af642dc sslserver: pid 31745 from 209.18.107.89
@40000000429f4eaf3afc9024 sslserver: ok 31745 0:192.168.0.3:25
:209.18.107.89::35084
@40000000429f4eb02c7d2af4 sslserver: ssl 31744 accept 
@40000000429f4eb915a7636c smtpfront-qmail[31745]: MAIL FROM:
[email protected]
@40000000429f4ebf21b46524 smtpfront-qmail[31745]: RCPT TO:
[email protected]
@40000000429f4ed32825d30c smtpfront-qmail[31745]: Accepted message qp
31746 bytes 154
@40000000429f4ed909dfa044 smtpfront-qmail[31745]: bytes in: 138 bytes
out: 261
@40000000429f4ed90d17cc8c sslserver: end 31744 status 0
@40000000429f4ed90d17e3fc sslserver: status: 0/31

My client is Sylpheed 1.0.4 on Winders - I'll try a couple other
clients and see if there are other problems.  Oddly it seems to
deliver the message fine.

Josh