[exim] spurious delay warning message?

Top Page
Delete this message
Reply to this message
Author: Mrten
Date:  
To: exim-users
Subject: [exim] spurious delay warning message?
Hi,

I'm getting a warning message for a cronjob for a few days now:


This message was created automatically by mail delivery software.
A message that you sent has not yet been delivered to one or more of its
recipients after more than 4 hours on the queue on kimiko.ii.nl.

The message identifier is:     1UgMol-0004Xa-Lb
The date of the message is:    Sun, 26 May 2013 05:12:01 +0200
The subject of the message is: Cron <scripts@kimiko>
$HOME/mysql/backup/sql2sshfs.sh



The weird part is that all the headers indicate that the message was
actually sent on 05:12:19 so was only on the queue for a few seconds:


Received: from kimiko.ii.nl ([82.94.191.102]:59351)
    by mail1.ii.nl with esmtps (TLS1.0:RSA_AES_256_CBC_SHA1:32)
    (Exim 4.76)
    id 1UgRNa-0001S8-Qo
    for scripts@???; Sun, 26 May 2013 05:12:19 +0200
Received: from Debian-exim by kimiko.ii.nl with local (Exim 4.71)
    id 1UgRNJ-0005We-4H
    for scripts@???; Sun, 26 May 2013 05:12:01 +0200
Date: Sun, 26 May 2013 05:12:01 +0200


(I removed a DKIM header, it was long and did not seem important)


The logfiles seem to corroborate this:


root@kimiko:/home/mrten# exigrep 1UgMol-0004Xa-Lb /var/log/exim4/mainlog.1
2013-05-26 05:12:01 [17458] 1UgMol-0004Xa-Lb <= scripts@??? U=scripts
P=local S=4151
2013-05-26 05:12:01 [21242] 1UgMol-0004Xa-Lb == scripts@???
R=dnslookup T=remote_smtp_dkim defer (-1): domain matches
queue_smtp_domains, or -odqs set
2013-05-26 05:12:18 [21249] 1UgMol-0004Xa-Lb => scripts@???
R=dnslookup T=remote_smtp_dkim S=4241 H=mail1.ii.nl [82.94.191.120]
X=TLS1.0:RSA_AES_256_CBC_SHA1:32
DN="2.5.4.13=#131065416d575a4872333637414c73385a46,C=NL,ST=Zuid-Holland,L=Delft,O=ii.nl
(Chefren Hagens),CN=mail1.ii.nl,EMAIL=webmaster@???" C="250 OK
id=1UgRNa-0001S8-AF" QT=4h52m15s DT=1s
2013-05-26 05:12:18 [21249] 1UgMol-0004Xa-Lb Completed QT=4h52m15s

2013-05-26 05:12:01 [21244] 1UgRNJ-0005We-4H <= <> R=1UgMol-0004Xa-Lb
U=Debian-exim P=local S=1180
2013-05-26 05:12:01 [21245] 1UgRNJ-0005We-4H == scripts@???
R=dnslookup T=remote_smtp_dkim defer (-1): domain matches
queue_smtp_domains, or -odqs set
2013-05-26 05:12:19 [21252] 1UgRNJ-0005We-4H => scripts@???
R=dnslookup T=remote_smtp_dkim S=1210 H=mail1.ii.nl [82.94.191.120]*
X=TLS1.0:RSA_AES_256_CBC_SHA1:32
DN="2.5.4.13=#131065416d575a4872333637414c73385a46,C=NL,ST=Zuid-Holland,L=Delft,O=ii.nl
(Chefren Hagens),CN=mail1.ii.nl,EMAIL=webmaster@???" C="250 OK
id=1UgRNa-0001S8-Qo" QT=18s DT=1s
2013-05-26 05:12:19 [21252] 1UgRNJ-0005We-4H Completed QT=18s


The only thing that shows otherwise is that the 'QT=' for the
cronmessage does seem to indicate the mail was on the queue for more
than four hours. But that's not visible from the timestamps from the
logmessages, nor can I find any logmessages indicating when the message
was 'started'.

This particular cronjob runs at 00:20, so the times do add up.

I looked at the docs for delay_warning (set to 4h:8h:24h:10000h), but
they did not give any hints for this.


Is this expected behaviour?

thanks,
Maarten.