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)
Nov 29 03:15:59 den1 postfix/qmgr[3361]: B0771588D1B: removed
Nov 29 04:05:59 den1 postfix/pickup[8219]: 8F5C358913E: uid=0 from=<root>
Nov 29 04:05:59 den1 postfix/cleanup[10278]: 8F5C358913E:
message-id=<20091129110559.8f5c3589...@den1.thisserver.net>
Nov 29 04:05:59 den1 postfix/qmgr[3361]: 8F5C358913E:
from=<r...@den1.thisserver.net>, size=2488, nrcpt=1 (queue active)
Nov 29 04:05:59 den1 postfix/cleanup[10278]: A6027589038:
message-id=<20091129110559.8f5c3589...@den1.thisserver.net>
Nov 29 04:05:59 den1 postfix/qmgr[3361]: A6027589038:
from=<r...@den1.thisserver.net>, size=2626, nrcpt=1 (queue active)
Nov 29 04:05:59 den1 postfix/local[10280]: 8F5C358913E:
to=<r...@den1.thisserver.net>, orig_to=<root>, relay=local, delay=7.5,
delays=7.4/0.03/0/0.05, dsn=2.0.0, status=sent (forwarded as A6027589038)
Nov 29 04:05:59 den1 postfix/qmgr[3361]: 8F5C358913E: removed
Nov 29 04:06:00 den1 postfix/smtp[10286]: A6027589038:
to=<webmas...@example.com>, orig_to=<root>, relay=example.com[123.45.67.89]:25,
delay=0.41, delays=0.04/0.01/0.21/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok:
queued as F0C77400032)
Nov 29 04:06:00 den1 postfix/qmgr[3361]: A6027589038: removed
The first object (B0771588D1B) is the mail generated by root's crontab job (see
below). The first thing I noticed is that the "delay=86417" is within a few
seconds of 24 hours. There is also a "status=sent" and that it is queued. So
I am assuming that it gets queued somewhere.
However, running postqueue -p shows that nothing is queued. Still, that email
must be stored somewhere on this server because it always get received at it's
original destination 24 hour later.
Note the second email that is received by Postfix, at 4:05. It also originates
from cron, although it is from logwatch and not from the root's crontab.
I am certain this isn't a Postfix issue. It almost certainly has to do with
cron, but I can find no references to cron job mail delays when searching the
web.
Can someone tell me how the "delay=" value gets set? And possibly where such a
delayed email might be stored while waiting for the delay time to elapse?
--------------- email B0771588D1B --------------
>From - Sun Nov 29 02:16:04 2009
X-Mozilla-Status: 0001
X-Mozilla-Status2: 00000000
Return-Path: <r...@den1.thisserver.net>
Received: from murder ([unix socket])
by g1.example.com (Cyrus v2.3.7-Invoca-RPM-2.3.7-7.el5_4.3) with LMTPA;
Sun, 29 Nov 2009 02:16:04 -0800
X-Sieve: CMU Sieve 2.3
Received: from localhost (localhost.localdomain [127.0.0.1])
by g1.example.com (Postfix) with ESMTP id 049AD40003C
for <webmaster.example....@example.com>; Sun, 29 Nov 2009 02:16:04
-0800 (PST)
X-Virus-Scanned: amavisd-new at example.com
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 [198.202.202.21])
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)
From: r...@den1.thisserver.net (Cron Daemon)
To: webmas...@example.com
Subject: Cron <r...@den1> /usr/lib/freefi/freefirstcron
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated
X-Cron-Env: <mailto=webmas...@example.com>
X-Cron-Env: <SHELL=/bin/sh>
X-Cron-Env: <HOME=/root>
X-Cron-Env: <PATH=/usr/bin:/bin>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <USER=root>
Message-Id: <20091129101558.b0771588...@den1.thisserver.net>
Date: Sat, 28 Nov 2009 03:15:01 -0700 (MST)
Stopping httpd: [ OK ]
Starting httpd: [ OK ]
Stopping squid: ................[ OK ]
Starting squid: .[ OK ]
Reseting FreeFi gateway daemon: [ OK ][ OK ]
Sat Nov 28 03:16:05 MST 2009
-----------------------------------------------------------
Note the second "Received" (bottom up) is seen by our mail server 24 hours
after Postfix received it from cron.
Emmett
