Re: Need help debugging a possible content filter problem

3 msg	Re: Virtual domain aliases
4 msg	address verify vs. virtual_alias_maps
20 msg	Postfix/ClamAV Config Error
4 msg	smtp /dev/poll problem
6 msg	Addresses filtering for only one supported domain
14 msg	Greylist question
1 msg	One transport with AUTH and other transport wit...
7 msg	Is this expected reject behavior for foreign IP...
3 msg	relay_domains and virtual_mailbox_domains not w...

Need help debugging a possible content filter p...
\ Rob Tanner (28 Nov 2007)
. \ Victor Duchovni (28 Nov 2007)

11 msg	spam emails with \| in front of the email addresses
9 msg	unexpected domain rewrite (by postfix?)
5 msg	Error receiving email
20 msg	Postfix 2.5-20071111, smtp.gmail.com, bouncing ...
1 msg	Bounce notification configure
45 msg	Re: Recipient validation
2 msg	Use of MySQL for lookups
8 msg	proposal: change behavior with respect to recip...
11 msg	OT: Any bad DKIM experiences?
8 msg	hashed spool directories

Subject:	Re: Need help debugging a possible content filter problem
Group:	Postfix-users
From:	Victor Duchovni
Date:	28 Nov 2007

On Tue, Nov 27, 2007 at 08:26:16PM -0800, Rob Tanner wrote:

> relay=localhost.linfield.edu[127.0.0.1], delay=1780, status=sent (250
> OK, sent 474CE652_12080_9_2 )
>
> My question is what exactly is the delay value? What is it measuring?
> When everything is running nicely, the delay value seldom even gets as
> high as 10 but in the above example, it's 1780. Wjat exactly is it?

The Postfix 2.3 RELEASE_NOTES file says in part:

- Better insight into the nature of performance bottle necks, with
detailed logging of delays in various stages of message delivery.
Postfix logs additional delay information as "delays=a/b/c/d"
where a=time before queue manager, including message transmission;
b=time in queue manager; c=connection setup time including DNS,
HELO and TLS; d=message transmission time.

- Logging of the connection reuse count when SMTP connections are
used for more than one message delivery. This information is
needed because Postfix can now reuse connections hundreds of times
or more. Logging of the connection reuse count can help to diagnose
inter-operability problems with servers that suffer from memory
leaks or other resource leaks.

At this point the Postfix logging for a recipient looks like this:

Nov 3 16:04:31 myname postfix/smtp[30840]: 19B6B2900FE:
to=<wietse>, orig_to=<wietse@test>,
relay=mail.example.com[1.2.3.4], conn_use=2, delay=0,
delays=0/0.01/0.05/0.1, dsn=2.0.0, status=sent (250 2.0.0 Ok)

The following two logfile fields may or may not be present:

orig_to This is omitted when the address did not change.
conn_use This is omitted when a connection is used once.

The old-style (Postfix 2.2 and earlier) "delay" is a+b+c+d where:

a=time before queue manager, including message transmission
b=time in queue manager
c=connection setup time including DNS, HELO and TLS
d=message transmission time

The "a" and "b" values are delay before the current delivery attempt, while
the "c" and "d" values are delay during the current delivery attempt.

For me, just this more detailed latency breakdown justifies upgrading
to Postfix 2.3 (at this point really 2.4)

--
Viktor.

Disclaimer: off-list followups get on-list replies or get ignored.
Please do not ignore the "Reply-To" header.

To unsubscribe from the postfix-users list, visit
http://www.postfix.org/lists.html or click the link below:
<mailto:majordomo?body=unsubscribe%20postfix-users>

If my response solves your problem, the best way to thank me is to not
send an "it worked, thanks" follow-up. If you must respond, please put
"It worked, thanks" in the "Subject" so I can delete these quickly.