On 11/30/2009 10:48 AM, Victor Duchovni wrote:
> On Mon, Nov 30, 2009 at 10:35:02AM -0800, Emmett Culley wrote:
>
>> 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.
>
> Not really. The message took 1 day to enter the active queue, not
> surprising, since pickup seems to have it a day late. Did your system
> clock get changed (by a day or so) while Postfix was running?
>
> The pickup(8) daemon scans the maildrop queue every 60 seconds by default,
> and on-demand when postdrop(1) sends a "wakeup trigger" after creating
> a new message.
>
> If you have SE-Linux, AppArmor, ... they could block postdrop from
> accessing the pickup service socket. Also file/directory permissions
> could be wrong, or your clock erratic.
>
So, where does the delay=86457 come from? It is clear to me that the cron
job's email is getting stuck on the originating machine for 24 hours.
---- snip email header ----
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/myco/rstcron
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)
---- snip ----
Something (is assume cron) is putting the original sent date (last line) into
the header, then from the first "Received:" header item I assume that postfix
didn't get it until 24 hours later. That is if I am correct that postfix
places that "Received" item into the message.
This happens every day on four systems.
I cannot let go of the fact that the log shows a delay=86457 (which is a few
second more that 24 hours) isn't related to the late delivery. Where does the
delay=86457 come from? Who sets it? What does it represent? Where is the
messages stored for the missing 24 hours?
What document can I read that will answer these questions?
Emmett
