On Thu, Dec 10, 2009 at 11:12:36AM -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?
>
> 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.
It comes from the message sitting in the maildrop queue for 24 hours,
or from a 24 hour delay between the invocation of sendmail(1) and EOF on
the message body. If, for example, the process that has the write-side of
the pipe to sendmail(1) keeps it open for 24 hours, the message will be
delayed by 24 hours.
> 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.
It is of course related, but does not answer your underlying question.
> Where does the delay=86457 come from? Who sets it? What does it
> represent? Where is the messages stored for the missing 24 hours?
The pre-active delay is measured from the time message is created until
it enters the active queue (in this case for the first time). So the
message was either:
- Not yet fully formed (delayed EOF in the
mail(1)->sendmail(1)->postdrop(1)) process chain)
- Fully formed, but unprocessed in the maildrop queue for 24 hours.
- Fully formed, but unprocessed in the incoming queue for 24 hours.
The last can be ruled out, because the pickup(8) and cleanup(8)
log entries do not predate the qmgr(8) log entries by 24 hours.
So, it is one of the first two. None of this requires in-depth
understanding of the "delay" or "delays" fields, because the same evidence
is clear from the logs and headers. The "delays=1day" value just corroborates
the fact that the message went nowhere for 24 hours.
Do try to rule out the possibility that the code creating the message
is directly or via a child-process keeping the write-side pipe open
for 24 hours or so.
If this happens every day, just list the maildrop queue a few hours
before the expected departure time of the message:
# ls -l /var/spool/postfix/maildrop
and report your findings. If you find any files there with a timestamp
nearly a day old, also run:
# fuser /var/spool/postfix/maildrop/<filename>
and report the "ps -p <pid>" output for that process id (any parent
processes also if relevant).
--
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:majord...@postfix.org?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.
