On 11/29/2009 03:27 PM, Wietse Venema wrote:
> Emmett Culley:
>> For some months I've been noticing on multiple servers that mail
>> from a cron job defined in the root's crontab takes 24 hours to
>> get to it's destination. It finally bugged me enough to have me
>> take a look for the reason. This is what I found in the maillog
>> for each day:
>>
>> Nov 29 03:15:58 den1 postfix/pickup[8219]: B0771588D1B: uid=0 from=<root>
>> Nov 29 03:15:58 den1 postfix/cleanup[7689]: B0771588D1B:
>> message-id=<20091129101558.b0771588...@den1.thisserver.net>
>> Nov 29 03:15:58 den1 postfix/qmgr[3361]: B0771588D1B:
>> from=<r...@den1.thisserver.net>, size=819, nrcpt=1 (queue active)
>> Nov 29 03:15:59 den1 postfix/smtp[7691]: B0771588D1B:
>> to=<webmas...@example.com>, relay=example.com[123.45.67.89]:25, delay=86457,
>> delays=86457/0/0.36/0.18, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
>> 3586C400032)
>
> This message is queued on a DIFFERENT mail system
> example.com[123.45.67.89]:25, meaning it was sent via the SMTP port
> (port 25) to a mail system on a named example.com with IP address
> 123.45.67.89.
>
> Is the local machine running MacOS? Apple has made some changes
> such that Postfix is not running all of the time. This is a change
> that is specific to APPLE, and may explain why mail not picked
> up as soon as it is enqueued.
>
> Is the queue on a file server, and are the client and file server
> clocks out of sync?
>
> Looking at the Received: in your message as delivered, the clocks
> on those systems are all out of sync.
>
> Wietse
>
Both machines are running CentOS and Postfix. One is on MST (sender,
thisserver.net) the the other is on PST (receiver, example.com).
The log entries are from thisserver.net. So I think I am seeing the cron
process hitting the local Postfix server 24 hours after cron says it was sent.
After taking a closer look at the email, the first "Received:" header says the
email was received from cron by the sender on 11/29 at 3:15:58, yet cron and
the email content show that it was sent 24 hours earlier.
Email Header:
----- snip -------
Received: from g1.example.com ([127.0.0.1])
by localhost (g1.example.com [127.0.0.1]) (amavisd-new, port 10024)
with ESMTP id dS+5g5AAK5vQ
for <webmaster.example....@example.com>;
Sun, 29 Nov 2009 02:15:59 -0800 (PST)
Received: from den1.thisserver.net (den1.thisserver.net [98.76.54.32])
by g1.example.com (Postfix) with ESMTP id 3586C400032
for <webmas...@example.com>; Sun, 29 Nov 2009 02:15:59 -0800 (PST)
Received: by den1.thisserver.net (Postfix, from userid 0)
id ; Sun, 29 Nov 2009 03:15:58 -0700 (MST)
----- snip ------
Date: Sat, 28 Nov 2009 03:15:01 -0700 (MST)
Email content:
----- snip -------
Sat Nov 28 03:16:05 MST 2009
-------------------------------------
That along with the log showing that Postfix (on the sender) didn't see it from
cron until the next day, like the email headers indicate, tells me it must be
something between cron and Postfix. It was only the "delay=86457" that had me
query the Postfix users mailing list.
Nov 29 03:15:58 den1 postfix/pickup[8219]: B0771588D1B: uid=0 from=<root>
Nov 29 03:15:58 den1 postfix/cleanup[7689]: B0771588D1B:
message-id=<20091129101558.b0771588...@den1.thisserver.net>
Nov 29 03:15:58 den1 postfix/qmgr[3361]: B0771588D1B:
from=<r...@den1.thisserver.net>, size=819, nrcpt=1 (queue active)
Nov 29 03:15:59 den1 postfix/smtp[7691]: B0771588D1B:
to=<webmas...@example.com>, relay=example.com[123.45.67.89]:25, delay=86457,
delays=86457/0/0.36/0.18, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
3586C400032)
Please note, however that the last log line shows that the email was queued as
3586C400032, which is the same ESMTP id as in the next "Received:" header. It
seems like understanding where the "delay=86457" and "delays=86457/0/0.36/0.18"
come from would probably help me to understand the 24 delay.
Emmett
