maximal_backoff_time not properly applied on a multi instance server

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

maximal_backoff_time not properly applied on a multi instance server

Brice Lopez
Hello,

I'm dealing with a strange issue on a postfix server running multiple instances. I've set a maximal_backoff_time of 8 hours in the instance's main.cf. I can check it was actually applied with postconf:

  $ sudo postmulti -i postfix-p26-o151 -x postconf | grep -E 'queue_lifetime|backoff_time'
  bounce_queue_lifetime = 5d
  maximal_backoff_time = 8h
  maximal_queue_lifetime = 3d
  minimal_backoff_time = 10m

However, when I check the logs for this instance, I can find multiple occurences of deferred emails moved back to the active queue with the default maximal_backoff_time of 4000s. I've double checked the postfix docu
mentation, the main.cf file should be private for each instance. Is this a bug, or did I forget a parameter?

2018-12-12T01:06:34.384322+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T01:07:40.017722+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[6667]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=386893, delays=386828/65/0.37/0.1, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T02:16:35.950068+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T02:17:37.859783+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[1443]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=391091, delays=391029/61/0.37/0.1, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T03:26:35.447677+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T03:27:34.835921+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[31192]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=395288, delays=395229/59/0.37/0.11, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T04:36:30.932122+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T04:37:41.922446+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[28194]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=399495, delays=399424/71/0.37/0.11, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T05:46:31.881443+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T05:47:46.309076+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[25988]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=403700, delays=403625/74/0.37/0.11, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T06:56:33.072730+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T06:57:54.902251+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[26065]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=407908, delays=407826/81/0.37/0.11, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T08:06:34.682500+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781, nrcpt=1 (queue active)
2018-12-12T08:08:00.726228+00:00 pr-li-smtp00-0047 info postfix-p26-o151/smtp[28467]: C0E76483ECE: to=<[hidden email]>, relay=mx.AAAA.AAA[DDD.DD.DD.DD]:25, delay=412114, delays=412028/86/0.37/0.11, dsn=4.7.1, status=deferred (host mx.AAAA.AAA[DDD.DD.DD.DD] said: 450 4.7.1 Your email server DDD.DDD.DDD.DDD was temporarily blocked due to spam - contact us and report a problem (in reply to RCPT TO command))
2018-12-12T09:16:37.731205+00:00 pr-li-smtp00-0047 info postfix-p26-o151/qmgr[31295]: C0E76483ECE: from=<[hidden email]>, size=28781,

Regards,

Brice Lopez
Reply | Threaded
Open this post in threaded view
|

Re: maximal_backoff_time not properly applied on a multi instance server

Viktor Dukhovni


> On Dec 12, 2018, at 7:24 AM, Brice Lopez <[hidden email]> wrote:
>
> I'm dealing with a strange issue on a postfix server running multiple instances. I've set a maximal_backoff_time of 8 hours in the instance's main.cf. I can check it was actually applied with postconf:
>
>  $ sudo postmulti -i postfix-p26-o151 -x postconf | grep -E 'queue_lifetime|backoff_time'
>  bounce_queue_lifetime = 5d
>  maximal_backoff_time = 8h
>  maximal_queue_lifetime = 3d
>  minimal_backoff_time = 10m

$ date
$ ls -l /etc/postfix-p26-o151/main.cf

As root:

# qdir=$(postmulti -i postfix-p26-o151 -x postconf -hx queue_directory)
# ps -o pid,etime,args -p $(pgrep -P $(cat $qdir/pid/master.pid) -x qmgr)

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: maximal_backoff_time not properly applied on a multi instance server

Brice Lopez
On Wed, Dec 12, 2018 at 08:45:14AM -0500, Viktor Dukhovni wrote:

> $ date
> $ ls -l /etc/postfix-p26-o151/main.cf
>
> As root:
>
> # qdir=$(postmulti -i postfix-p26-o151 -x postconf -hx queue_directory)
> # ps -o pid,etime,args -p $(pgrep -P $(cat $qdir/pid/master.pid) -x qmgr)

$ grep multi_instance_directories /etc/postfix/main.cf
multi_instance_directories = /etc/postfix/pools/p25/o8 /etc/postfix/pools/p25/o19 /etc/postfix/pools/p25/o30 /etc/postfix/pools/p25/o41 /etc/postfix/pools/p25/o52 /etc/postfix/pools/p25/o63 /etc/postfix/pools/p25/o74 /etc/postfix/pools/p25/o85 /etc/postfix/pools/p25/o96 /etc/postfix/pools/p25/o107 /etc/postfix/pools/p25/o118 /etc/postfix/pools/p25/o129 /etc/postfix/pools/p25/o140 /etc/postfix/pools/p25/o151 /etc/postfix/pools/p25/o162 /etc/postfix/pools/p25/o173 /etc/postfix/pools/p26/o8 /etc/postfix/pools/p26/o19 /etc/postfix/pools/p26/o30 /etc/postfix/pools/p26/o41 /etc/postfix/pools/p26/o52 /etc/postfix/pools/p26/o63 /etc/postfix/pools/p26/o74 /etc/postfix/pools/p26/o85 /etc/postfix/pools/p26/o96 /etc/postfix/pools/p26/o107 /etc/postfix/pools/p26/o118 /etc/postfix/pools/p26/o129 /etc/postfix/pools/p26/o140 /etc/postfix/pools/p26/o151 /etc/postfix/pools/p26/o162 /etc/postfix/pools/p26/o173

blopez@pr-li-smtp00-0047:/var/log/custom/p26/backup$ grep -r postfix-p26-o151 /etc/postfix/
/etc/postfix/pools/p26/o151/main.cf:multi_instance_name = postfix-p26-o151

$ date
Wed Dec 12 14:05:22 UTC 2018

$ ls -l /etc/postfix/pools/p26/o151/main.cf
-rw-r--r-- 1 root root 2842 Dec 10 10:58 /etc/postfix/pools/p26/o151/main.cf

$ qdir=$(sudo postmulti -i postfix-p26-o151 -x postconf -hx queue_directory)
$(pgrep -P $(sudo cat $qdir/pid/master.pid) -x qmgr)
  PID     ELAPSED COMMAND
31295 120-17:05:56 qmgr -l -t fifo -u

The instance was reloaded a few times since it's running, and on the 10th of september after the configuation modification. I just restarted it just in case.

Regards,

> --
> Viktor.
>

--
Brice Lopez
Reply | Threaded
Open this post in threaded view
|

Re: maximal_backoff_time not properly applied on a multi instance server

Viktor Dukhovni
> On Dec 12, 2018, at 9:15 AM, Brice Lopez <[hidden email]> wrote:
>
> $ date
> Wed Dec 12 14:05:22 UTC 2018
>
> $ ls -l /etc/postfix/pools/p26/o151/main.cf
> -rw-r--r-- 1 root root 2842 Dec 10 10:58 /etc/postfix/pools/p26/o151/main.cf

Your main.cf file last changed 2 days ago.

> $ qdir=$(sudo postmulti -i postfix-p26-o151 -x postconf -hx queue_directory)
> $(pgrep -P $(sudo cat $qdir/pid/master.pid) -x qmgr)
>  PID     ELAPSED COMMAND
> 31295 120-17:05:56 qmgr -l -t fifo -u

Your queue manager has been running for 120 days, without a "postfix reload".

> The instance was reloaded a few times since it's running,

But not more recently than 120 days ago.

> and on the 10th of September after the configuration modification.

Apparently not, as "postfix reload" does restart the queue manager,
so your attempts to "reload" have not been effective.

> I just restarted it just in case.

That should cause the new settings to take effect.

--
--
        Viktor.

P.S. Please don't send unsolicited email to outlook.com or any
     other email mailboxes.
Reply | Threaded
Open this post in threaded view
|

Re: maximal_backoff_time not properly applied on a multi instance server

Brice Lopez
On Wed, Dec 12, 2018 at 12:47:07PM -0500, Viktor Dukhovni wrote:
>
> Apparently not, as "postfix reload" does restart the queue manager,
> so your attempts to "reload" have not been effective.
>
> > I just restarted it just in case.
>
> That should cause the new settings to take effect.

Indeed, it worked. It was a bug in the ansible playbook, it was confirmed by digging in the logs. Thank you for the quick troubleshooting.

Regards,

--
Brice Lopez