One of my users has observed that mail addressed to him late at night seems to
frequently get delayed. for very long periods of time.
He sent me headers which look like this:
Return-Path: <[EMAIL PROTECTED]>
Delivered-To: [EMAIL PROTECTED]
Received: (qmail 19114 invoked from network); 9 Mar 2001 11:20:54 -0000
Received: from hydepark-jump.vircio.com (qmailr@[10.1.1.1]) (envelope-sender
<[EMAIL PROTECTED]>) by hackberry.vircio.com (qmail-ldap-1.03) with SMTP for
<[EMAIL PROTECTED]>; 9 Mar 2001 11:20:54 -0000
Received: (qmail 32510 invoked by uid 84); 9 Mar 2001 02:59:42 -0000
Received: from [EMAIL PROTECTED] by hydepark-jump.vircio.com with
qmail-scanner-0.90 (uvscan: v4.0.50/v4115. . Clean. Processed in 0.328525 secs);
08/03/2001 20:59:42
Received: from mailgate.1starnet.com (HELO mail.1starnet.com) ([207.243.104.248])
(envelope-sender <[EMAIL PROTECTED]>)by cust-46-98.customer.jump.net
(qmail-ldap-1.03) with SMTPfor <[EMAIL PROTECTED]>; 9 Mar 2001 02:59:41 -0000
Received: from sweep2 [207.243.105.243] by mail.1starnet.com (SMTPD32-6.05) id
A71C11570140; Thu, 08 Mar 2001 20:59:40 -0600
Received: (from default [12.41.197.55]) by sweep2 (NAVIEG 2.1 bld 63) with SMTP id
M2001030820593623359for <[EMAIL PROTECTED]>; Thu, 08 Mar 2001 20:59:37 -0600
From: "Joan Heuston" <[EMAIL PROTECTED]>
To: "David" <[EMAIL PROTECTED]>
Subject: Trip
Date: Thu, 8 Mar 2001 21:08:39 -0600
Message-ID: <01c0a846$3d8e7fe0$37c5290c@default>
MIME-Version: 1.0
Content-Type: multipart/alternative;
boundary="----=_NextPart_000_0004_01C0A813.F2F40FE0"
X-Priority: 3
X-MSMail-Priority: Normal
X-Mailer: Microsoft Outlook Express 4.71.1712.3
X-MimeOLE: Produced By Microsoft MimeOLE V4.71.1712.3
X-UID: 14
I ran them through a slightly modified version of the mailroute.pl script to
see this:
Thu Mar 8 2001 20:59:37 (from default [12.41.197.55])
by sweep2 (NAVIEG 2.1 bld 63)
with SMTP id M2001030820593623359
for <[EMAIL PROTECTED]>
20:59:40 from sweep2 [207.243.105.243]
by mail.1starnet.com (SMTPD32-6.05) id A71C11570140
20:59:41 from mailgate.1starnet.com (HELO mail.1starnet.com)
([207.243.104.248]) (envelope-sender <[EMAIL PROTECTED]>)
by cust-46-98.customer.jump.net (qmail-ldap-1.03)
with SMTP
for <[EMAIL PROTECTED]>
20:59:42 from [EMAIL PROTECTED]
by hydepark-jump.vircio.com
with qmail-scanner-0.90 (uvscan: v4.0.50/v4115. . Clean.
Processed in 0.328525 secs)
20:59:42 (qmail 32510 invoked by uid 84)
Fri 9 05:20:54 from hydepark-jump.vircio.com (qmailr@[10.1.1.1])
(envelope-sender <[EMAIL PROTECTED]>)
by hackberry.vircio.com (qmail-ldap-1.03)
with SMTP
for <[EMAIL PROTECTED]>
05:20:54 (qmail 19114 invoked from network)
2001-03-09 05:18:35.339952500 HydePark-Jump.virCIO.Com: new msg 50506
2001-03-09 05:18:35.475620500 HydePark-Jump.virCIO.Com: info msg 50506: bytes 4620
from <[EMAIL PROTECTED]> qp 32510 uid 84
2001-03-09 05:18:54.574282500 HydePark-Jump.virCIO.Com: starting delivery 542: msg
50506 to local [EMAIL PROTECTED]
2001-03-09 05:18:54.685686500 HydePark-Jump.virCIO.Com: delivery 542: success:
did_0+0+0/
2001-03-09 05:20:53.589986500 HydePark-Jump.virCIO.Com: starting delivery 895: msg
50506 to remote [EMAIL PROTECTED]
2001-03-09 05:20:54.606229500 HydePark-Jump.virCIO.Com: delivery 895: success:
10.1.1.5_accepted_message./Remote_host_said:_250_ok_984136854_qp_19114/
2001-03-09 05:20:54.608846500 HydePark-Jump.virCIO.Com: end msg 50506
2001-03-09 05:20:59.447298500 Hackberry.virCIO.Com: new msg 22132
2001-03-09 05:20:59.447644500 Hackberry.virCIO.Com: info msg 22132: bytes 4911 from
<[EMAIL PROTECTED]> qp 19114 uid 101
2001-03-09 05:21:02.173139500 Hackberry.virCIO.Com: starting delivery 644: msg 22132
to local [EMAIL PROTECTED]
2001-03-09 05:21:02.210565500 Hackberry.virCIO.Com: starting delivery 645: msg 22132
to local [EMAIL PROTECTED]
2001-03-09 05:21:03.041980500 Hackberry.virCIO.Com: delivery 644: success: did_0+0+0/
2001-03-09 05:21:03.098023500 Hackberry.virCIO.Com: delivery 645: success: did_1+0+0/
2001-03-09 05:21:03.437875500 Hackberry.virCIO.Com: end msg 22132
This afternoon's hackery was to extract my hostname from the headers and grovel
through the logs to find the info you see at the bottom.
Anyway, as you can see, qmail-scanner appears to have handed the message off
to qmail-queue at Thu Mar 8 2001 20:59:42 according to the headers, but it
doesn't show up in the logs until 2001-03-09 05:18:35.339952500.
I'm very confused here. It is true that qmail-queue adds the
(qmail 32510 invoked by uid 84) line, right? How can it possibly not log it
until so many hours later?
I have a job that kicks all sorts of things in the wee hours, so I suspect
that it's probably what allows things to finally flow, but what might be
hanging things for that long? Would this be a symptom of qmail simply not
running even though qmail-smtpd is?
Chris
--
Chris Garrigues http://www.DeepEddy.Com/~cwg/
virCIO http://www.virCIO.Com
4314 Avenue C
Austin, TX 78751-3709 +1 512 374 0500
My email address is an experiment in SPAM elimination. For an
explanation of what we're doing, see http://www.DeepEddy.Com/tms.html
Nobody ever got fired for buying Microsoft,
but they could get fired for relying on Microsoft.
PGP signature
