3

We use postfix on a CentOS server to accept incoming mail, then do some filtering, then send the message on to our real mail server where we will pickup the mail. The postfix server sometimes has long delays when it tries to send to our real mail server. We will see delivery logs like this:

Sep 01 10:09:52 <hostname> postfix/pickup[18057]: 4mGC2s3EdYa3LNN4: uid=12345 from=<sender-email> orig_id=4oGC2h1ZU4a3LNLd
Sep 01 10:09:52 <hostname> postfix/cleanup[28788]: 4mGC2s3EdYa3LNN4: message-id=<id>
Sep 01 10:09:53 <hostname> postfix/qmgr[28730]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:12:44 <hostname> postfix/qmgr[24361]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:15:49 <hostname> postfix/qmgr[20098]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:17:50 <hostname> postfix/qmgr[29129]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:20:09 <hostname> postfix/qmgr[30381]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:22:05 <hostname> postfix/qmgr[15028]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:25:11 <hostname> postfix/qmgr[12533]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:28:33 <hostname> postfix/qmgr[30857]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:30:16 <hostname> postfix/qmgr[21858]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)
Sep 01 10:32:41 <hostname> postfix/smtp[26435]: 4mGC2s3EdYa3LNN4: to=<user@example.com>, relay=server.example.com[x.x.x.x]:25, delay=1379, delays=1234/132/3.5/9.6, dsn=2.0.0, status=sent (250 OK)
Sep 01 10:32:41 <hostname> postfix/qmgr[12857]: 4mGC2s3EdYa3LNN4: from=<sender-email>, size=8874, nrcpt=1 (queue active)

We haven't been able to discover at this point what the "(queue active)" message means in this situation. What is the cause of the "(queue active)" message, and why does that cause delays in the message over 1000 seconds?

Extra Sauce
  • 71
  • 1
  • 1
  • 6

2 Answers2

8

We haven't been able to discover at this point what the "(queue active)"

Postfix maintains queues for the pending mails, "queue active" indicates there are mails in the queue.

To see queued mails issue:

sudo mailq

or

sudo postqueue -p

What is the cause of the "(queue active)" message.

Messages are queued due to delivery errors. Such errors can be: DNS error, a full mailbox or nonexistent mail recipient.

why does that cause delays in the message over 1000 seconds

Queue times are configured in main.cf file. According to postfix documentation

The minimal time between attempts to deliver a deferred message; prior to Postfix 2.4 the default value was 1000s.

If 1000sec is too long for you, you can change the timer. I advise you to read the entire postfix tuning-guide before making any changes.

Finally you can Flush the queue(force postfix to immediately process the queue) by using

sudo postqueue -f

or

sudo postfix flush
pmarkoulidakis
  • 431
  • 3
  • 6
  • When the message keeps saying "(queue active)", and it's because of one of the errors you named, "DNS error, a full mailbox or nonexistent mail recipient," Is the only way to find out the specific error by manually troubleshooting? What about increasing the verbosity of the logs? – Extra Sauce Sep 16 '15 at 17:12
  • 2
    You don't need to increase the verbosity. Default settings are good to troubleshoot those errors. What's in the log file? – pmarkoulidakis Sep 18 '15 at 18:26
  • Well, nothing more than what I posted shows up in the log file. That's the problem, is that Postfix is not revealing why the message isn't just being sent. – Extra Sauce Sep 24 '19 at 20:30
0

I came across this site with some interesting information:

http://en.redinskala.com/postfix-maillog-interpretation/

A couple things I found:

1) They gave an example log line:

Jan 2 20:31:17 tmcent01 postfix/qmgr[26454]: B58C4330038: from=, size=711, nrcpt=1 (queue active)

With this explanation, my emphasis added:

Line 4 indicates that syntax corrections are finished and now the mail is RFC 822 compliant, from this moment the mail falls into the hands of the “qmgr” daemon. This daemon is responsible for moving the mails left by qmgr to the appropriate queue. Qmgr is constantly reviewing which mails in the incoming queue have “700” permissions, and it sees a file like this it automatically sends it to the “active” queue. This is because any mail left by cleanup with “700” permissions is assumed to be ready for delivery to its final destination whether it is a local or external mail. In this line we can see the sender’s mailbox, the number of recipients, the total size of the mail (up to this moment, because the final size may change when it is received in the recipient’s mailbox) and the queue it is being moved to.

So it seems that "queue active" may mean that the message is being moved to the active queue.

2) The "delays" are reported to be in this order:

smtpd, cleanup, qmgr and local, in such cases where the mail is not internal, you will see the last time is that of the “smtp” daemon instead of “local”

Which may be different from the order listed here:

Understanding a Postfix log file entry

So I am thinking that if I am seeing multiple "(queue active)" entries, it may be due to a postfix reload or something, just at the right time, so as to cause the qmgr to re-queue a message into the "active" queue. That's my guess currently, based on this:

http://postfix.1071664.n5.nabble.com/Understanding-delays-td10263.html

Who killed your queue manager and restarted Postfix? Now the message had to re-enter the active queue. Don't "reload" frequenty from cron, ...

Extra Sauce
  • 71
  • 1
  • 1
  • 6