From: /dev/rob0 (rob0gmx.co.uk)
Date: Mon May 30 2005 - 16:18:37 CDT

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Wietse Venema wrote:

>/dev/rob0:
>
>
>>[...]
>>May 30 14:41:41 sorry postfix/smtp[2481]: panic: tls_session_stop:
>>stream has no active TLS context
>>May 30 14:41:42 sorry postfix/qmgr[2479]: warning: premature
>>end-of-input on private/smtp socket while reading input attribute name
>>May 30 14:41:42 sorry postfix/qmgr[2479]: warning: private/smtp socket:
>>malformed response
>>May 30 14:41:42 sorry postfix/qmgr[2479]: warning: transport smtp
>>failure -- see a previous warning/fatal/panic logfile record for the
>>problem description
>>May 30 14:41:42 sorry postfix/master[16875]: warning: process
>>/usr/libexec/postfix/smtp pid 2481 killed by signal 6
>>
>>
>
>This is a dangling pointer problem in Postfix 2.2.
>
>Can you try the patch below?
>
>
Applied on both ends (I suppose being in smtp(8) means it was only
needed on the client, the MX), but no luck. Should I "make tidy"? I
didn't because the MX is an old hunk of junk and I was in a hurry, but
I'll try that later if necessary.

[MX client]
May 30 19:40:16 sorry postfix/smtpd[5636]: connect from
pop.gmx.de[213.165.64.20]
May 30 19:40:20 sorry postfix/smtpd[5636]: 84CA619A07:
client=pop.gmx.de[213.165.64.20]
May 30 19:40:20 sorry postfix/cleanup[5638]: 84CA619A07:
message-id=<429B6C19.50907gmx.co.uk>
May 30 19:40:20 sorry postfix/qmgr[5623]: 84CA619A07:
from=<rob0gmx.co.uk>, size=967, nrcpt=1 (queue active)
May 30 19:40:21 sorry postfix/smtpd[5636]: disconnect from
pop.gmx.de[213.165.64.20]
May 30 19:40:21 sorry postfix/smtp[5639]: Server certificate could not
be verified
May 30 19:40:21 sorry postfix/smtp[5639]: 84CA619A07:
to=<usermy.domain>, relay=rob0.dynamic.nodns4.us[68.62.173.11],
delay=4, status=deferred (TLS failure: Cannot verify server certificate)

[home mailbox server]
May 30 14:40:23 whn postfix/smtpd[14188]: connect from
sorry.no-ip-here.net[66.226.201.55]
May 30 14:40:23 whn postfix/smtpd[14188]: setting up TLS connection from
sorry.no-ip-here.net[66.226.201.55]
May 30 14:40:23 whn postfix/smtpd[14188]: TLS connection established
from sorry.no-ip-here.net[66.226.201.55]: TLSv1 with cipher
DHE-RSA-AES256-SHA (256/256 bits)
May 30 14:40:23 whn postfix/smtpd[14188]: lost connection after STARTTLS
from sorry.no-ip-here.net[66.226.201.55]
May 30 14:40:23 whn postfix/smtpd[14188]: disconnect from
sorry.no-ip-here.net[66.226.201.55]

I will try this later with debug_peer set. FWIW after I turned off
debug_peer and changed MUST_NOPEERMATCH to MAY, I couldn't tell from the
logging that no TLS was taking place.

For example here's the patch you sent:

[MX]
May 30 19:13:38 sorry postfix/smtpd[3284]: connect from
english-breakfast.cloud9.net[168.100.1.9]
May 30 19:13:38 sorry postfix/smtpd[3284]: A92F619C0C:
client=english-breakfast.cloud9.net[168.100.1.9]
May 30 19:13:38 sorry postfix/cleanup[3288]: A92F619C0C:
message-id=<20050530191212.17DD6BC165spike.porcupine.org>
May 30 19:13:38 sorry postfix/qmgr[2479]: A92F619C0C:
from=<owner-postfix-userspostfix.org>, size=3535, nrcpt=1 (queue active)
May 30 19:13:38 sorry postfix/smtpd[3284]: disconnect from
english-breakfast.cloud9.net[168.100.1.9]
May 30 19:13:39 sorry postfix/smtp[3289]: Server certificate could not
be verified
May 30 19:13:39 sorry postfix/smtp[3289]: A92F619C0C:
to=<listaliasmy.domain>, relay=rob0.dynamic.nodns4.us[68.62.173.11],
delay=1, status=sent (250 Ok: queued as 3BE64312E0)
May 30 19:13:39 sorry postfix/qmgr[2479]: A92F619C0C: removed

"Server certificate could not be verified" is the only indication, and
since I wasn't requiring verification, I'd think that would mean TLS was
used.

[home]
May 30 14:13:41 whn postfix/smtpd[9886]: TLS connection established from
sorry.no-ip-here.net[66.226.201.55]: TLSv1 with cipher
DHE-RSA-AES256-SHA (256/256 bits)
May 30 14:13:41 whn postfix/smtpd[9886]: 3BE64312E0:
client=sorry.no-ip-here.net[66.226.201.55]
May 30 14:13:41 whn postfix/cleanup[9890]: 3BE64312E0:
message-id=<20050530191212.17DD6BC165spike.porcupine.org>
May 30 14:13:41 whn postfix/qmgr[8982]: 3BE64312E0:
from=<owner-postfix-userspostfix.org>, size=3845, nrcpt=1 (queue active)
May 30 14:13:41 whn postfix/smtpd[9886]: disconnect from
sorry.no-ip-here.net[66.226.201.55]
May 30 14:13:41 whn postfix/local[9891]: 3BE64312E0: to=<memy.domain>,
orig_to=<listaliasmy.domain>, relay=local, delay=0, status=sent
(delivered to maildir)
May 30 14:13:41 whn postfix/qmgr[8982]: 3BE64312E0: removed

And here there is no indication that TLS failed. On the contrary, it
says, "TLS connection established ..."

So is that the workaround for now, to use "MAY" rather than
"MUST_NOPEERMATCH" in smtp_tls_per_site maps? I just tried that again,
and now it's succeeding according to logs and Received: headers.

>*** ./smtp_proto.c- Sat Apr 2 16:22:50 2005
>--- ./smtp_proto.c Mon May 30 15:05:19 2005
>***************
>*** 631,636 ****
>--- 631,637 ----
> tls_client_stop(smtp_tls_ctx, session->stream,
> var_smtp_starttls_tmout, 1,
> &(session->tls_info));
>+ session->tls_context = 0;
> return (smtp_site_fail(state, 450,
> "TLS failure: Cannot verify server certificate"));
> }
>***************
>*** 650,655 ****
>--- 651,657 ----
> tls_client_stop(smtp_tls_ctx, session->stream,
> var_smtp_starttls_tmout, 1,
> &(session->tls_info));
>+ session->tls_context = 0;
> return (smtp_site_fail(state, 450,
> "TLS failure: Cannot verify server hostname"));
> }
>
I apologise to Viktor and to all for the stupid question in the OP; as
an excuse I can say I have been under stress as maximal_queue_lifetime
approached. (I got the mail flushed with a few hours to spare.) I should
also point out that Viktor's clairvoyance (MUST_NOPEERMATCH vs. MUST) is
better than he admits. :)

Victor Duchovni:

>> May 30 14:41:41 sorry postfix/smtp[2481]: B3D961F180:
>> to=<usermy.domain>, relay=rob0.dynamic.nodns4.us[68.62.173.11],
>> delay=3, status=deferred (TLS failure: Cannot verify server certificate)
>>
>> Does that mean it's still trying to insist on verification of the remote
>> server certificate? This was after a postmap(1) of the smtp_tls_per_site
>> map file and a "postfix reload" to be sure.
>
>Yes, failure to verify is only fatal with "MUST". You also have set
>enforce_tls... Good questions include all required contextual information.
>
>

... but not this time ...
# postconf | grep enforce_tls
smtp_enforce_tls = no
smtpd_enforce_tls = no

Basically I copied and pasted the main.cf from the TLS_README (as
provided with 2.2.3.) FYI here's the whole section, and both
configurations look the same except for the filenames:

### 2005/05/29 - TLS
smtp_tls_CAfile = /etc/postfix/tls/cacert.pem
smtp_tls_cert_file = /etc/postfix/tls/sorry-cert.pem
smtp_tls_key_file = /etc/postfix/tls/sorry-key.pem
smtp_tls_loglevel = 1 # oops, just added this
smtp_tls_per_site = hash:/etc/postfix/tls/site_maps
smtp_tls_session_cache_database =
   btree:/var/run/smtp_tls_session_cache
smtp_use_tls = yes
smtpd_tls_CAfile = /etc/postfix/tls/cacert.pem
smtpd_tls_cert_file = /etc/postfix/tls/sorry-cert.pem
smtpd_tls_key_file = /etc/postfix/tls/sorry-key.pem
smtpd_tls_loglevel = 1
smtpd_tls_received_header = yes
smtpd_tls_session_cache_database =
   btree:/var/run/smtpd_tls_session_cache
smtpd_use_tls = yes
tls_random_source = dev:/dev/urandom
### /TLS

(While writing this I added the smtp_tls_loglevel. The only ones not in
the "quick-and-dirty" are the loglevels, per_site map, and the
received_header.)

>> [...]
>> May 30 14:41:41 sorry postfix/smtp[2481]: panic: tls_session_stop:
>> stream has no active TLS context
>
>This is much more interesting, can you reproduce it with verbose logging
>enabled? The TLS verification code is substantially reworked in 2.3
>snapshots, can you try 2.3-20050510?
>

I did (between the first post and a few hours ago) get some debug_peer
output. Unfortunately I can't work on it any more right now. The 2.3
snapshot didn't work in this deployment because of the Dovecot AUTH
patch, otherwise I would have been using it. If Timo starts maintaining
a 2.3 patch I will switch.

I do appreciate the assistance from both Wietse and Viktor. I'll get
back to this, with verbose log output, either later today or tomorrow.
--
    mail to this address is discarded unless "/dev/rob0"
    or "not-spam" is in Subject: header

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]