Viktor Dukhovni wrote:
>
> On Thu, Apr 19, 2012 at 10:41:11AM +0000, Viktor Dukhovni wrote:
>
>> > Please see log output below.
>
> The client HELO in the log decodes as:
>
> Version 3.1
> cipher suites
> TLS_DHE_RSA_WITH_AES_256_CBC_SHA
> TLS_DHE_DSS_WITH_AES_256_CBC_SHA
> TLS_DHE_RSA_WITH_CAMELLIA_256_CBC_SHA
> TLS_DHE_DSS_WITH_CAMELLIA_256_CBC_SHA
> TLS_DH_anon_WITH_AES_256_CBC_SHA
> TLS_DH_anon_WITH_CAMELLIA_256_CBC_SHA
> TLS_RSA_WITH_AES_256_CBC_SHA
> TLS_RSA_WITH_CAMELLIA_256_CBC_SHA
> TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA
> TLS_DHE_DSS_WITH_3DES_EDE_CBC_SHA
> TLS_DH_anon_WITH_3DES_EDE_CBC_SHA
> TLS_RSA_WITH_3DES_EDE_CBC_SHA
> TLS_DHE_RSA_WITH_AES_128_CBC_SHA
> TLS_DHE_DSS_WITH_AES_128_CBC_SHA
> TLS_DHE_RSA_WITH_SEED_CBC_SHA
> TLS_DHE_DSS_WITH_SEED_CBC_SHA
> TLS_DHE_RSA_WITH_CAMELLIA_128_CBC_SHA
> TLS_DHE_DSS_WITH_CAMELLIA_128_CBC_SHA
> TLS_DH_anon_WITH_AES_128_CBC_SHA
> TLS_DH_anon_WITH_SEED_CBC_SHA
> TLS_DH_anon_WITH_CAMELLIA_128_CBC_SHA
> TLS_RSA_WITH_AES_128_CBC_SHA
> TLS_RSA_WITH_SEED_CBC_SHA
> TLS_RSA_WITH_CAMELLIA_128_CBC_SHA
> TLS_DH_anon_WITH_RC4_128_MD5
> TLS_RSA_WITH_RC4_128_SHA
> TLS_RSA_WITH_RC4_128_MD5
> TLS_EMPTY_RENEGOTIATION_INFO_SCSV
> compression methods
> deflate
> NULL
>
> Perhaps renegotiation support in the server is an issue, but first
> rule out out-of-sync LMTP, by looking at the protocol plain-text
> exchange that precedes the SSL handshake. Postfix will not proceed
> to the SSL stage unless it receives "2XX" in response to STARTTLS.
> After that point the server may not send plaintext messages.
>
> --
> Viktor.
>
>
Viktor:
Thank you for your response. I have included the debug file as best that I
know how below.
In regards to renegotiation, I am not sure which command field would allow
this option to be set.
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: initializing the client-side
TLS engine
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: smtp_stream_setup: maxtime=300
enable_deadline=0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24: 220
mail.test.com server ready
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: > 127.0.0.1[127.0.0.1]:24: LHLO
mail.test.com
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-mail.test.com
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-8BITMIME
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-ENHANCEDSTATUSCODES
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-PIPELINING
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-SIZE
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24:
250-STARTTLS
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24: 250
IGNOREQUOTA
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: server features: 0x101f size 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: Using LMTP PIPELINING, TCP send
buffer size is 50604, PIPELINING buffer size is 4096
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: smtp_stream_setup: maxtime=300
enable_deadline=0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: > 127.0.0.1[127.0.0.1]:24:
STARTTLS
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: < 127.0.0.1[127.0.0.1]:24: 220
Begin TLS negotiation now
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: setting up TLS connection to
127.0.0.1[127.0.0.1]:24
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 127.0.0.1[127.0.0.1]:24: TLS
cipher list "ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL"
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: looking for session
lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
in lmtp cache
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr request = lookup
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr cache_type = lmtp
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr cache_id =
lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
Apr 19 08:47:07 HP_ML110 postfix/tlsmgr[1628]: lookup lmtp session
id=lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value:
4294967295
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: session
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: session
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value: (end)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: (list terminator)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: (end)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr request = seed
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr size = 32
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value: 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: seed
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: seed
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value:
iKWs1K4bQO4xh2yEttAVfmTqf6tXuTio+sqp4quKbPg=
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: (list terminator)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: (end)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: SSL_connect:before/connect
initialization
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: write to 080B5008 [080CD920]
(111 bytes => 111 (0x6F))
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0000 16 03 01 00 6a 01 00 00|66
03 01 4f 90 17 5b 35 ....j... f..O..[5
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0010 da d1 fb 12 e0 4e 23 54|6b
35 6e 6d bf c8 cb ff .....N#T k5nm....
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0020 82 50 e6 25 fc 93 93 6e|63
88 df 00 00 38 00 39 .P.%...n c....8.9
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0030 00 38 00 88 00 87 00 3a|00
89 00 35 00 84 00 16 .8.....: ...5....
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0040 00 13 00 1b 00 0a 00 33|00
32 00 9a 00 99 00 45 .......3 .2.....E
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0050 00 44 00 34 00 9b 00 46|00
2f 00 96 00 41 00 18 .D.4...F ./...A..
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0060 00 05 00 04 00 ff 02 01|00
00 04 00 23 ........ ....#
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 006d - <SPACES/NULLS>
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: SSL_connect:SSLv2/v3 write
client hello A
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: read from 080B5008 [080D2E80]
(7 bytes => -1 (0xFFFFFFFF))
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: read from 080B5008 [080D2E80]
(7 bytes => 7 (0x7))
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 0000 34 35 34 20 34 2e 33
454 4.3
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: SSL_connect:error in SSLv2/v3
read server hello A
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: SSL_connect error to
127.0.0.1[127.0.0.1]:24: -1
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: warning: TLS library problem:
1638:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown
protocol:s23_clnt.c:699:
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: remove session
lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
from client cache
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr request = delete
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr cache_type = lmtp
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr cache_id =
lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
Apr 19 08:47:07 HP_ML110 postfix/tlsmgr[1628]: delete lmtp session
id=lmtp:127.0.0.1:24:mail.test.com&p=1&c=ALL:!EXPORT:!LOW:+RC4:@STRENGTH:!eNULL
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value:
4294967295
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/tlsmgr: wanted
attribute: (list terminator)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: (end)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: connect to subsystem
private/defer
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr nrequest = 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr flags = 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr queue_id = 2387380178
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr original_recipient =
postmas...@test.com
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr recipient =
postmas...@mail.test.com
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr offset = 4294967295
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr dsn_orig_rcpt =
rfc822;postmas...@test.com
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr notify_flags = 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr status = 4.7.5
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr diag_type =
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr diag_text =
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr mta_type =
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr mta_mname =
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr action = delayed
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: send attr reason = Cannot start
TLS: handshake failure
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/defer socket: wanted
attribute: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: status
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute value: 0
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: private/defer socket: wanted
attribute: (list terminator)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: input attribute name: (end)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: 2387380178:
to=<postmas...@mail.test.com>, orig_to=<postmas...@test.com>,
relay=127.0.0.1[127.0.0.1]:24, delay=0.56, delays=0.29/0.01/0.26/0,
dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: flush_add: site mail.test.com
id 2387380178
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: match_list_match:
mail.test.com: no match
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: flush_add: site mail.test.com
id 2387380178 status 4
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: name_mask: resource
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: name_mask: software
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: name_mask: delay
Apr 19 08:47:07 HP_ML110 postfix/lmtp[1638]: name_mask: bounce
Apr 19 08:47:40 HP_ML110 postfix/postsuper[1642]: Deleted: 1 message
--
View this message in context:
http://old.nabble.com/postfix-lmtp-ssl-failure-tp33705787p33714500.html
Sent from the Postfix mailing list archive at Nabble.com.
