Re: Mail from cron delay
On 12/10/2009 11:37 AM, Victor Duchovni wrote: 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 -ppid output for that process id (any parent processes also if relevant). Thanks to the hints above I looked into the code that I was calling from the cron job. I found that one of the scripts that was being called never returned until the next night when it was executed again. Hence the 24 hour delay. I fixed that script and now the email from cron arrives when it should. Thanks for your comments.
Re: Mail from cron delay
On Sat, Jan 16, 2010 at 06:14:45PM -0800, Emmett Culley wrote: 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) Thanks to the hints above I looked into the code that I was calling from the cron job. I found that one of the scripts that was being called never returned until the next night when it was executed again. Hence the 24 hour delay. Nice to know that deductive reasoning works not just in Sir Arthur Conan Doyle novels. -- 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.
Re: Mail from cron delay
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
Re: Mail from cron delay
Emmett Culley: 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 Postfix adds the Message-Id: *AND* the Date: header when it moves the submission from the maildrop queue to the incoming queue. - The Date: header contains the time that the message was submitted to the maildrop queue (28 Nov 2009 03:15:01 -0700). - The Message-Id: header contains the time that the message was moved from maildrop queue to incoming queue. This is the same time as the Received: by den1.thisserver.net header (29 Nov 2009 03:15:58 -0700 which is MST, is identical to 20091129101558 which is in UTC). Please review my questions in my earlier follow-up response. I wrote most of Postfix, so I might have a clue. Is the mail queue on a file server, and is the clock drifted? Is the machine running MacOS? They have modified the way that Postfix picks up local submissions. Wietse
Re: Mail from cron delay
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.
Re: Mail from cron delay
On Sun, Nov 29, 2009 at 02:42:14PM -0800, Emmett Culley wrote: 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 Any warnings in your logs matching either of the below regexps? egrep 'message dated [0-9]* seconds into the future' /some/log/file egrep 'message has been queued for [0-9]* days' /some/log/file -- 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.
Re: Mail from cron delay
Victor Duchovni: On Sun, Nov 29, 2009 at 02:42:14PM -0800, Emmett Culley wrote: 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 Any warnings in your logs matching either of the below regexps? egrep 'message dated [0-9]* seconds into the future' /some/log/file egrep 'message has been queued for [0-9]* days' /some/log/file Some unhelpful systems log warning messages separate from normal activity, so he may have to look in different files. Wietse
Re: Mail from cron delay
On 11/29/2009 03:27 PM, Wietse Venema wrote: Emmett Culley: 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) This message is queued on a DIFFERENT mail system example.com[123.45.67.89]:25, meaning it was sent via the SMTP port (port 25) to a mail system on a named example.com with IP address 123.45.67.89. Is the local machine running MacOS? Apple has made some changes such that Postfix is not running all of the time. This is a change that is specific to APPLE, and may explain why mail not picked up as soon as it is enqueued. Is the queue on a file server, and are the client and file server clocks out of sync? Looking at the Received: in your message as delivered, the clocks on those systems are all out of sync. Wietse Both machines are running CentOS and Postfix. One is on MST (sender, thisserver.net) the the other is on PST (receiver, example.com). The log entries are from thisserver.net. So I think I am seeing the cron process hitting the local Postfix server 24 hours after cron says it was sent. After taking a closer look at the email, the first Received: header says the email was received from cron by the sender on 11/29 at 3:15:58, yet cron and the email content show that it was sent 24 hours earlier. Email Header: - snip --- 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 [98.76.54.32]) 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) - snip -- Date: Sat, 28 Nov 2009 03:15:01 -0700 (MST) Email content: - snip --- Sat Nov 28 03:16:05 MST 2009 - That along with the log showing that Postfix (on the sender) didn't see it from cron until the next day, like the email headers indicate, tells me it must be something between cron and Postfix. It was only the delay=86457 that had me query the Postfix users mailing list. 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) Please note, however that the last log line shows that the email was queued as 3586C400032, which is the same ESMTP id as in the next Received: header. 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. Emmett
Re: Mail from cron delay
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. -- 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.
Mail from cron delay
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: 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
Re: Mail from cron delay
Emmett Culley: 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) This message is queued on a DIFFERENT mail system example.com[123.45.67.89]:25, meaning it was sent via the SMTP port (port 25) to a mail system on a named example.com with IP address 123.45.67.89. Is the local machine running MacOS? Apple has made some changes such that Postfix is not running all of the time. This is a change that is specific to APPLE, and may explain why mail not picked up as soon as it is enqueued. Is the queue on a file server, and are the client and file server clocks out of sync? Looking at the Received: in your message as delivered, the clocks on those systems are all out of sync. Wietse
