Re: Postfix Not Sending Emails. Timeout on Cleanup socket error.

From: Gonzo Fernandez <gonzo_at_nospam>
Date: Fri Dec 16 2011 - 01:24:12 GMT
To: Lorens Kockum <postfix-users-4329@tagged.lorens.org>

Lorens,

Thanks for your info about the mailbox size limit. I do have log watch running and have not received any emails. Took care of that by expanding the size limit to 20MB. As for doing a grep search on 884643E30022 (The ID that said stuck in queue for 1 day), here is the output:

# egrep 884643E30022 /var/log/maillog

Dec 12 10:08:50 batch-ca4-02 postfix/pickup[26935]: warning: 884643E30022: message has been queued for 1 days
Dec 12 10:08:50 batch-ca4-02 postfix/pickup[26935]: 884643E30022: uid=500 from=<XXXX@XXXX.com>
Dec 12 10:08:50 batch-ca4-02 postfix/cleanup[26937]: 884643E30022: message-id=<20111212180850.884643E30022@batch-ca4-02>
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_active_feed: incoming/884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_message_alloc: active 884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: 884643E30022: from=<XXXX@XXXX.com>, size=1503, nrcpt=1 (queue active)
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_peer_select: 884643E30022 smtp 192.168.X.X (5 of 10)
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_job_retire: 884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: send attr queue_id = 884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/smtp[26956]: input attribute value: 884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/smtp[26956]: deliver_request_get: file active/884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/smtp[26956]: 884643E30022: to=<XXXX@XXXX.net>, relay=192.168.X.X[192.168.X.X]:25, delay=102997, delays=102997/0/0/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 8DBA6D0016E)
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_active_done: 884643E30022
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: 884643E30022: removed
Dec 12 10:08:50 batch-ca4-02 postfix/qmgr[26936]: qmgr_job_free: 884643E30022 smtp

Here is everything that I could find between the hours where the "read timeout on cleanup socket error" happened.
(Dec 11 05:31:27 batch-ca4-02 postfix/cleanup[31691]: warning: 8A2993E3003B: read timeout on cleanup socket)

Dec 11 04:04:26 batch-ca4-02 postfix/pickup[25527]: 9CC1F3E3003A: uid=0 from=<root>
Dec 11 04:06:17 batch-ca4-02 postfix/smtpd[31631]: dict_eval: const pickup
Dec 11 04:06:17 batch-ca4-02 postfix/smtp[31689]: dict_eval: const pickup
Dec 11 04:09:19 batch-ca4-02 postfix/pickup[25527]: 7905B3E3003A: uid=500 from=<XXXX@XXXX.com>
Dec 11 07:15:59 batch-ca4-02 postfix/smtpd[5663]: dict_eval: const pickup

And here is everything before the "read timeout on cleanup socket":

Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: diag_type
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: diag_text
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: diag_text
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: mta_type
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: mta_type
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: mta_mname
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: mta_mname
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: action
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: action
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: reason
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: reason
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: status
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: status
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute value: 0
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: private/smtp socket: wanted attribute: (list terminator)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: input attribute name: (end)
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: qmgr_queue_unthrottle: queue 192.168.X.X
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: qmgr_active_done: 177013E30037
Dec 11 04:07:59 batch-ca4-02 postfix/smtp[31689]: master_notify: status 1
Dec 11 04:07:59 batch-ca4-02 postfix/smtp[31689]: connection closed
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: 177013E30037: removed
Dec 11 04:07:59 batch-ca4-02 postfix/qmgr[28082]: qmgr_job_free: 177013E30037 smtp
Dec 11 04:09:19 batch-ca4-02 postfix/pickup[25527]: 7905B3E3003A: uid=500 from=<XXXX@XXXX.com>
Dec 11 04:09:19 batch-ca4-02 postfix/cleanup[31691]: 7905B3E3003A: message-id=<20111211120919.7905B3E3003A@batch-ca4-02>
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: trigger_server_accept_fifo: trigger arrived
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: master_notify: status 0
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: request: 87 (W)
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: qmgr_scan_start: start incoming queue scan
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: master_notify: status 1
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: qmgr_active_feed: queue incoming
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: qmgr_active_feed: incoming/7905B3E3003A
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: qmgr_message_alloc: active 7905B3E3003A
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: 7905B3E3003A: from=<batches@usaepay.com>, size=1084, nrcpt=1 (queue active)
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: start sorted recipient list
Dec 11 04:09:19 batch-ca4-02 postfix/qmgr[28082]: qmgr_message_sort: X@XXXX.com
Dec 11 04:09:39 batch-ca4-02 postfix/smtpd[31631]: rewrite stream disconnect
Dec 11 04:09:39 batch-ca4-02 postfix/smtp[31689]: idle timeout -- exiting
Dec 11 04:16:47 batch-ca4-02 postfix/smtpd[31631]: idle timeout -- exiting
Dec 11 05:09:19 batch-ca4-02 postfix/cleanup[31691]: warning: timeout on cleanup socket while reading input attribute name
Dec 11 05:30:09 batch-ca4-02 postfix/smtpd[5663]: dict_eval: const mail
Dec 11 05:31:27 batch-ca4-02 postfix/cleanup[31691]: warning: 8A2993E3003B: read timeout on cleanup socket
Dec 11 05:53:51 batch-ca4-02 postfix/smtpd[5663]: dict_eval: const ipv4

I know I originally stated that the email is from the pickup but now I'm not so sure. I'm seeing a lot of postfix/smtp verbose messages.
I hope this helps.

Gonzo Fernandez
Network Engineer

On Dec 15, 2011, at 2:07 PM, Lorens Kockum wrote:

> On Thu, Dec 15, 2011 at 11:49:35AM -0800, Gonzo Fernandez wrote:
>> /var/log/maillog:Dec 14 04:03:07 batch-ca4-02 postfix/sendmail[12280]: fatal: root(0): queue file write error
>> /var/log/maillog:Dec 15 12:03:07 batch-ca4-02 postfix/postdrop[21744]: warning: uid=0: Illegal seek
>
> In addition to what Wietse asked for in another mail just now,
> do look at the output of the commands
>
> mount
>
> dmesg
>
> That should show if there is a hardware problem.
>
> If it is not, then is it not possible that the 8A2993E3003B you
> are worrying about is a locally submitted mail from some system
> daemon (like logwatch) that is too big for your configured
> system limits? The times on the error messages make me suspect
> some kind of cron job.
>
> See:
>
> http://www.electrictoolbox.com/logwatch-postfix-sendmail-errors/
>
> http://www.cyberciti.biz/tips/linux-unix-posttfix-mutt-illegal-seek-error.html
>
> 8A2993E3003B would then be a minor consequence of your main
> problem, which is mail freezing up over weekends.
>
> To diagnose that problem, it would be interesting to grep on a
> queue id that was correctly queued, like (from an earlier mail):
>
> Dec 12 10:08:50 batch-ca4-02 postfix/pickup[26935]: warning: 884643E30022: message has been queued for 1 days
>
> Since mails such as those have been correctly queued, there
> should be a wealth of information about when and how and why
> it's staying in the queue so long.
>
> HTH
>

This message: [ Message body ]
Next message: Wietse Venema: "Re: Postfix Not Sending Emails. Timeout on Cleanup socket error."
Previous message: Wietse Venema: "Re: warning: problem talking to service private/scache: Operation timed out"
In reply to: Lorens Kockum: "Re: Postfix Not Sending Emails. Timeout on Cleanup socket error."
Next in thread: Wietse Venema: "Re: Postfix Not Sending Emails. Timeout on Cleanup socket error."
Reply: Wietse Venema: "Re: Postfix Not Sending Emails. Timeout on Cleanup socket error."

Contemporary messages sorted: [ By Date ] [ By Thread ] [ By Subject ] [ By Author ]