Re: SOLVED: Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Viktor Dukhovni]

On Thu, Mar 03, 2016 at 11:31:50AM +0100, Dietrich Streifert wrote:

> And here is the solution:
> 
> I had to explicitely tell the smtp proxy to NOT use tls by specifying
> 
> -o smtpd_use_tls=no
> -o smtp_use_tls=no
> -o smtpd_tls_security_level=none
> -o smtp_tls_security_level=none

You're much confused about this being a "proxy" issue.  There is
no TLS-client code in the Postfix SMTP server, therefore with
smtpd_proxy_filter TLS is never used.  TLS is used with content_filters,
you must have a content_filter transport that send email through
a transparent proxy.  The place to disable TLS is in the pre-filter
smtp transport and/or the re-inject SMTP server.  You did the
latter, but the reason this solves the problem is unrelated to
smtpd_proxy_filter.

On Thu, Mar 03, 2016 at 09:41:07AM +0100, Dietrich Streifert wrote:

> I'm running a smtp_proxy_filter on localhost:10024 as described in
> http://postfix.cs.utah.edu/SMTPD_PROXY_README.html
> 
> smtp  inet  n   -   n   -   -   smtpd
> -o smtpd_proxy_filter=localhost:10024
> -o smtpd_proxy_options=speed_adjust
> -o smtp_send_xforward_command=yes

This will never use TLS.  You must have a content_filter in place.

> smtp_tls_loglevel = 3
> smtpd_tls_loglevel = 3

This level of logging just obscures what's important with low-level
noise, revert back to "1".

> rewritten as 

Re: SOLVED: Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

Thank you Christian for clarifying this.

It seems that the obsoleted parameters survived somehow several 
migrations since ancient times


Regards
Dietrich

Am 03.03.2016 um 12:01 schrieb Christian Kivalo:

On 2016-03-03 11:31, Dietrich Streifert wrote:

And here is the solution:

I had to explicitely tell the smtp proxy to NOT use tls by specifying

-o smtpd_use_tls=no
-o smtp_use_tls=no
-o smtpd_tls_security_level=none
-o smtp_tls_security_level=none

where it seems that simply setting smtpd_use_tls and smtp_use_tls to
no was not enough! The additional smtp_tls_security_level set to
"none" was also necessary


The options smtpd/smtp_use_tls are obsolete and 
smtpd/smtp_tls_security_level should be used instead. You can remove 
the smtpd/smtp_use_tls option from both main.cf and master.cf and it 
should be good


Take a look at the documentation
From http://www.postfix.org/postconf.5.html#smtp_tls_security_level
- smtp_tls_security_level
The default SMTP TLS security level for the Postfix SMTP client; when 
a non-empty value is specified, this overrides the obsolete parameters 
smtp_use_tls, smtp_enforce_tls, and smtp_tls_enforce_peername.

-

From http://www.postfix.org/postconf.5.html#smtpd_tls_security_level
- smtpd_tls_security_level
The SMTP TLS security level for the Postfix SMTP server; when a 
non-empty value is specified, this overrides the obsolete parameters 
smtpd_use_tls and smtpd_enforce_tls. This parameter is ignored with 
"smtpd_tls_wrappermode = yes".

-


Thank you for your patience and help!

Regards
Dietrich

Re: SOLVED: Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Christian Kivalo]

On 2016-03-03 11:31, Dietrich Streifert wrote:

And here is the solution:

I had to explicitely tell the smtp proxy to NOT use tls by specifying

-o smtpd_use_tls=no
-o smtp_use_tls=no
-o smtpd_tls_security_level=none
-o smtp_tls_security_level=none

where it seems that simply setting smtpd_use_tls and smtp_use_tls to
no was not enough! The additional smtp_tls_security_level set to
"none" was also necessary


The options smtpd/smtp_use_tls are obsolete and 
smtpd/smtp_tls_security_level should be used instead. You can remove the 
smtpd/smtp_use_tls option from both main.cf and master.cf and it should 
be good


Take a look at the documentation
From http://www.postfix.org/postconf.5.html#smtp_tls_security_level
- smtp_tls_security_level
The default SMTP TLS security level for the Postfix SMTP client; when a 
non-empty value is specified, this overrides the obsolete parameters 
smtp_use_tls, smtp_enforce_tls, and smtp_tls_enforce_peername.

-

From http://www.postfix.org/postconf.5.html#smtpd_tls_security_level
- smtpd_tls_security_level
The SMTP TLS security level for the Postfix SMTP server; when a 
non-empty value is specified, this overrides the obsolete parameters 
smtpd_use_tls and smtpd_enforce_tls. This parameter is ignored with 
"smtpd_tls_wrappermode = yes".

-


Thank you for your patience and help!

Regards
Dietrich


--
 Christian Kivalo

SOLVED: Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

And here is the solution:

I had to explicitely tell the smtp proxy to NOT use tls by specifying

-o smtpd_use_tls=no
-o smtp_use_tls=no
-o smtpd_tls_security_level=none
-o smtp_tls_security_level=none

where it seems that simply setting smtpd_use_tls and smtp_use_tls to no 
was not enough! The additional smtp_tls_security_level set to "none" was 
also necessary


Thank you for your patience and help!

Regards
Dietrich

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

Hi Viktor,

thank you for the script I will run it asap on the server.

Meanwhile I think the problem is the following:

I'm running a smtp_proxy_filter on localhost:10024 as described in 
http://postfix.cs.utah.edu/SMTPD_PROXY_README.html


smtp  inet  n   -   n   -   -   smtpd
-o smtpd_proxy_filter=localhost:10024
-o smtpd_proxy_options=speed_adjust
-o smtp_send_xforward_command=yes

and it seems that smtp is trying to initiate a tls handshake with this 
proxy which does not support tls, leading to the timeout of 300s. Is 
there an option to prevent the attempt to initiate a tls


I've set in main.cf:

smtp_use_tls = yes
smtpd_use_tls = yes
smtpd_tls_security_level = may
smtp_tls_security_level = may
smtp_tls_loglevel = 3
smtpd_tls_loglevel = 3

and here is the log:

mail() on [/data/development/phpmail/mail.php:9]: To: 
dietrich.streif...@googlemail.com -- Headers: From: nore...@.de  
Reply-To: s...@.de  X-Mailer: PHP/5.4.16

Mar  3 09:26:47 node1 postfix/pickup[20765]: 5392C35E3D9: uid=0 from=
Mar  3 09:26:47 node1 postsrsd[29345]: srs_forward:  
rewritten as 

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Viktor Dukhovni]

On Wed, Mar 02, 2016 at 10:01:35PM +0100, Dietrich Streifert wrote:

> Ah OK! This log entries may be helpfull:
> 
> 135125:Mar  2 18:32:55 node1 postfix/smtp[9047]: 5B0A235E18A: Cannot start
> TLS: handshake failure
> 135131:Mar  2 18:32:55 node1 postfix/cleanup[22956]: 7D9B335E185:
> message-id=<20160302172755.5b0a235e...@..de>
> 135133:Mar  2 18:32:55 node1 postfix/smtp[9047]: 5B0A235E18A:
> to=, relay=localhost[127.0.0.1]:10024,
> delay=300, delays=0.06/0.01/300/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok:
> queued as 7D9B335E185)
> 135135:Mar  2 18:32:55 node1 postfix/qmgr[8697]: 5B0A235E18A: removed
> 
> Is this all due to some stage trying to talk to smtp via TLS but fails?

Yes, the message is deferred when the TLS handshake fails.  Later
it is retried and either TLS succeeds, or fallback to cleartext
happens.  THere are probably more messages in the log about the
TLS failures.  Perhaps your firewall is blocking TLS, but there no
information to work with in what you've posted so far.

Try ("collate" script attached):

# logfile=/var/log/mail.log # or whatever
# perl collate "${logfile}" |
perl -ne 'BEGIN {$/="\n\n"} print if m{5B0A235E18A}'

-- 
Viktor.
#! /usr/bin/perl

use strict;
use warnings;

# Postfix delivery agents
my @agents = qw(discard error lmtp local pipe smtp virtual);

my $instre = qr{(?x)
\A  # Absolute line start
(?:\S+ \s+){3}  # Timestamp, adjust for other time formats
\S+ \s+ # Hostname
(postfix(?:-\S+)?)/ # postfix instance
};

my $cmdpidre = qr{(?x)
\G  # Continue from previous match
(\S+)\[(\d+)\]:\s+  # command[pid]:
};

my %smtpd;
my %smtp;
my %transaction;
my $i = 0;
my %seqno;

my %isagent = map { ($_, 1) } @agents;

while (<>) {
next unless m{$instre}ogc; my $inst = $1;
next unless m{$cmdpidre}ogc; my $command = $1; my $pid = $2;

if ($command eq "smtpd") {
if (m{\Gconnect from }gc) {
# Start new log
$smtpd{$pid}->{"log"} = $_; next;
}

$smtpd{$pid}->{"log"} .= $_;

if (m{\G(\w+): client=}gc) {
# Fresh transaction 
my $qid = "$inst/$1";
$smtpd{$pid}->{"qid"} = $qid;
$transaction{$qid} = $smtpd{$pid}->{"log"};
$seqno{$qid} = ++$i;
next;
}

my $qid = $smtpd{$pid}->{"qid"};
$transaction{$qid} .= $_
if (defined($qid) && exists $transaction{$qid});
delete $smtpd{$pid} if (m{\Gdisconnect from}gc);
next;
}

if ($command eq "pickup") {
if (m{\G(\w+): uid=}gc) {
my $qid = "$inst/$1";
$transaction{$qid} = $_;
$seqno{$qid} = ++$i;
}
next;
}

# bounce(8) logs transaction start after cleanup(8) already logged
# the message-id, so the cleanup log entry may be first
#
if ($command eq "cleanup") {
next unless (m{\G(\w+): }gc);
my $qid = "$inst/$1";
$transaction{$qid} .= $_;
$seqno{$qid} = ++$i if (! exists $seqno{$qid});
next;
}

if ($command eq "qmgr") {
next unless (m{\G(\w+): }gc);
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
if (m{\Gremoved$}gc) {
print delete $transaction{$qid}, "\n";
}
}
next;
}

# Save pre-delivery messages for smtp(8) and lmtp(8)
#
if ($command eq "smtp" || $command eq "lmtp") {
$smtp{$pid} .= $_;

if (m{\G(\w+): to=}gc) {
my $qid = "$inst/$1";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $smtp{$pid};
}
delete $smtp{$pid};
}
next;
}

if ($command eq "bounce") {
if (m{\G(\w+): .*? notification: (\w+)$}gc) {
my $qid = "$inst/$1";
my $newid = "$inst/$2";
if (defined($transaction{$qid})) {
$transaction{$qid} .= $_;
}
$transaction{$newid} =
$_ . $transaction{$newid};
$seqno{$newid} = ++$i if (! exists $seqno{$newid});
}
 

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

Ah OK! This log entries may be helpfull:

135125:Mar  2 18:32:55 node1 postfix/smtp[9047]: 5B0A235E18A: Cannot 
start TLS: handshake failure
135131:Mar  2 18:32:55 node1 postfix/cleanup[22956]: 7D9B335E185: 
message-id=<20160302172755.5b0a235e...@..de>
135133:Mar  2 18:32:55 node1 postfix/smtp[9047]: 5B0A235E18A: 
to=, 
relay=localhost[127.0.0.1]:10024, delay=300, delays=0.06/0.01/300/0.08, 
dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 7D9B335E185)

135135:Mar  2 18:32:55 node1 postfix/qmgr[8697]: 5B0A235E18A: removed

Is this all due to some stage trying to talk to smtp via TLS but fails?


Am 02.03.2016 um 20:14 schrieb Viktor Dukhovni:

On Wed, Mar 02, 2016 at 06:09:54PM +0100, Dietrich Streifert wrote:


I'm using php mail to send mails which uses  /usr/sbin/sendmail -t -i to
send the mail.

On my previous server centos 6 using postfix 2.6.6 the mail was delivered
nearly instant to the recipient, whereas on centos 7 with postfix 2.10.1 the
mail gets enqueued for ca. 5 minutes and is then successfully delivered to
the recipient.

At what stage is the delay?  Post at least one log entry that shows
delivery completion with the "delay=nnn, delays=a/b/c/d" information.

Also post the output of:

$ ls -ld /var/spool/postfix/public
$ ls -ld /var/spool/postfix/public/pickup
$ ls -lL $(postconf -h command_directory)/postdrop

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Viktor Dukhovni]

On Wed, Mar 02, 2016 at 06:09:54PM +0100, Dietrich Streifert wrote:

> I'm using php mail to send mails which uses  /usr/sbin/sendmail -t -i to
> send the mail.
> 
> On my previous server centos 6 using postfix 2.6.6 the mail was delivered
> nearly instant to the recipient, whereas on centos 7 with postfix 2.10.1 the
> mail gets enqueued for ca. 5 minutes and is then successfully delivered to
> the recipient.

At what stage is the delay?  Post at least one log entry that shows
delivery completion with the "delay=nnn, delays=a/b/c/d" information.

Also post the output of:

   $ ls -ld /var/spool/postfix/public
   $ ls -ld /var/spool/postfix/public/pickup
   $ ls -lL $(postconf -h command_directory)/postdrop

-- 
Viktor.

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[John Stoffel]

> "Dietrich" == Dietrich Streifert  
> writes:

Dietrich> I'm running centos 7.2 with postfix 2.10.1, installed from the 
standard 
Dietrich> centos 7 repo which corresponds to rhel 7.

Dietrich> I'm using php mail to send mails which uses  /usr/sbin/sendmail -t -i 
to 
Dietrich> send the mail.

Dietrich> On my previous server centos 6 using postfix 2.6.6 the mail was 
Dietrich> delivered nearly instant to the recipient, whereas on centos 7 with 
Dietrich> postfix 2.10.1 the mail gets enqueued for ca. 5 minutes and is then 
Dietrich> successfully delivered to the recipient.

Dietrich> I could not find any switch or configuration option within main.cf or 
Dietrich> master.cf which made an difference regarding the mail sending delay.

I wonder if sendmail is only delivering the outgoing queue once every
five minutes by default?  Looking in the log file to see when the mail
gets submitted and delivered might give a hint.

John

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Mauricio Tavares]

On Wed, Mar 2, 2016 at 12:37 PM, Dietrich Streifert
 wrote:
> Hi Mauricio,
>
> no, there is nothing in the log file. Here is the output for one sending
> attempt:
>
> mail() on [/data/development/phpmail/mail.php:9]: To:
> dietrich.streif...@googlemail.com -- Headers: From: nore...@.de
> Reply-To: s...@.de  X-Mailer: PHP/5.4.16
> Mar  2 18:27:55 node1 postfix/pickup[8696]: 5B0A235E18A: uid=0 from=
> Mar  2 18:27:55 node1 postsrsd[9043]: srs_forward: 
> rewritten as 

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

Hi Mauricio,

no, there is nothing in the log file. Here is the output for one sending 
attempt:


mail() on [/data/development/phpmail/mail.php:9]: To: 
dietrich.streif...@googlemail.com -- Headers: From: nore...@.de  
Reply-To: s...@.de  X-Mailer: PHP/5.4.16

Mar  2 18:27:55 node1 postfix/pickup[8696]: 5B0A235E18A: uid=0 from=
Mar  2 18:27:55 node1 postsrsd[9043]: srs_forward:  
rewritten as 

Re: mail sent via sendmail is queued and delayed for approx. 300 seconds

[Mauricio Tavares]

On Wed, Mar 2, 2016 at 12:09 PM, Dietrich Streifert
 wrote:
> Hi all,
>
> I'm running centos 7.2 with postfix 2.10.1, installed from the standard
> centos 7 repo which corresponds to rhel 7.
>
> I'm using php mail to send mails which uses  /usr/sbin/sendmail -t -i to
> send the mail.
>
> On my previous server centos 6 using postfix 2.6.6 the mail was delivered
> nearly instant to the recipient, whereas on centos 7 with postfix 2.10.1 the
> mail gets enqueued for ca. 5 minutes and is then successfully delivered to
> the recipient.
>
> I could not find any switch or configuration option within main.cf or
> master.cf which made an difference regarding the mail sending delay.
>
> It would be great if someone has a hint or a solution which re-enables the
> instant delivery again.
> Thank you for your help.
>
  Did the log file give you any clue of which step is taking too
long to complete?

> Regards
> Dietrich
>

mail sent via sendmail is queued and delayed for approx. 300 seconds

[Dietrich Streifert]

Hi all,

I'm running centos 7.2 with postfix 2.10.1, installed from the standard 
centos 7 repo which corresponds to rhel 7.


I'm using php mail to send mails which uses  /usr/sbin/sendmail -t -i to 
send the mail.


On my previous server centos 6 using postfix 2.6.6 the mail was 
delivered nearly instant to the recipient, whereas on centos 7 with 
postfix 2.10.1 the mail gets enqueued for ca. 5 minutes and is then 
successfully delivered to the recipient.


I could not find any switch or configuration option within main.cf or 
master.cf which made an difference regarding the mail sending delay.


It would be great if someone has a hint or a solution which re-enables 
the instant delivery again.

Thank you for your help.

Regards
Dietrich