Discussion:
postscreen contantly deferring mail
(too old to reply)
Ralf Hildebrandt
2016-07-25 09:25:08 UTC
Permalink
From my log:

Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>

Jul 23 07:59:57 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>
Jul 23 07:59:58 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>

Jul 23 12:00:43 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:60516: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>
Jul 23 12:00:44 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:60516: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>

Jul 23 16:02:54 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:55805: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>
Jul 23 16:02:55 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:55805: 450 4.3.2 Service currently
unavailable; from=<***@yahoo.com>, to=<***@charite.de>, proto=ESMTP, helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>

Why would postscreen repeatedly TEMPFAIL these delivery attempts?

They come from the same IP (106.10.151.33), go to the same two
recipients and are sent from the same sender.
--
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Schleißheimer Straße 26/MG, 80333 München

Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer
Aufsichtsratsvorsitzender: Florian Kirstein
Erwan David
2016-07-25 09:49:46 UTC
Permalink
Post by Ralf Hildebrandt
Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
Jul 23 07:59:57 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
Jul 23 07:59:58 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
Jul 23 12:00:43 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:60516: 450 4.3.2 Service currently
Jul 23 12:00:44 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:60516: 450 4.3.2 Service currently
Jul 23 16:02:54 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:55805: 450 4.3.2 Service currently
Jul 23 16:02:55 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:55805: 450 4.3.2 Service currently
Why would postscreen repeatedly TEMPFAIL these delivery attempts?
They come from the same IP (106.10.151.33), go to the same two
recipients and are sent from the same sender.
Maybe the sending server does not wait enough before sending command ?
Wietse Venema
2016-07-25 10:50:50 UTC
Permalink
Post by Ralf Hildebrandt
Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:58305: 450 4.3.2 Service currently
That's multiple RCPT TO commands in the same SMTP session. Doesn't
postscreen log BLACKLISTED, PREGREET, DNSBL, or some other error
for that session?
Post by Ralf Hildebrandt
Jul 23 07:59:57 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
Jul 23 07:59:58 mail-cbf postfix/postscreen[36326]: NOQUEUE: reject: RCPT from [106.10.151.33]:42935: 450 4.3.2 Service currently
Ditto.

Wietse
Ralf Hildebrandt
2016-07-25 11:05:00 UTC
Permalink
Jul 23 03:58:49 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:58305 to [193.175.73.208]:25
Jul 23 03:58:50 mail-cbf postfix/tlsproxy[56082]: CONNECT from [106.10.151.33]:58305
Jul 23 03:58:51 mail-cbf postfix/tlsproxy[56082]: Anonymous TLS connection established from [106.10.151.33]:58305: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:47500 to [193.175.73.208]:25
Jul 23 03:58:53 mail-cbf postfix/tlsproxy[56082]: CONNECT from [106.10.151.33]:47500
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:58305
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:58305
Jul 23 03:58:53 mail-cbf postfix/tlsproxy[56082]: DISCONNECT [106.10.151.33]:58305
Jul 23 03:58:54 mail-cbf postfix/tlsproxy[56082]: Anonymous TLS connection established from [106.10.151.33]:47500: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 03:58:54 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:47500
Jul 23 03:58:54 mail-cbf postfix/tlsproxy[56082]: DISCONNECT [106.10.151.33]:47500
Jul 23 07:59:55 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:42935 to [193.175.73.208]:25
Jul 23 07:59:55 mail-cbf postfix/tlsproxy[30940]: CONNECT from [106.10.151.33]:42935
Jul 23 07:59:56 mail-cbf postfix/tlsproxy[30940]: Anonymous TLS connection established from [106.10.151.33]:42935: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 07:59:57 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:58359 to [193.175.73.208]:25
Jul 23 07:59:58 mail-cbf postfix/tlsproxy[30940]: CONNECT from [106.10.151.33]:58359
Jul 23 07:59:59 mail-cbf postfix/tlsproxy[30940]: Anonymous TLS connection established from [106.10.151.33]:58359: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 07:59:59 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:42935
Jul 23 07:59:59 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:42935
Jul 23 07:59:59 mail-cbf postfix/tlsproxy[30940]: DISCONNECT [106.10.151.33]:42935
Jul 23 08:00:00 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:58359
Jul 23 08:00:00 mail-cbf postfix/tlsproxy[30940]: DISCONNECT [106.10.151.33]:58359
Jul 23 12:00:41 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:60516 to [193.175.73.208]:25
Jul 23 12:00:42 mail-cbf postfix/tlsproxy[11310]: CONNECT from [106.10.151.33]:60516
Jul 23 12:00:43 mail-cbf postfix/tlsproxy[11310]: Anonymous TLS connection established from [106.10.151.33]:60516: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 12:00:43 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:58359 to [193.175.73.208]:25
Jul 23 12:00:44 mail-cbf postfix/tlsproxy[11310]: CONNECT from [106.10.151.33]:58359
Jul 23 12:00:45 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:60516
Jul 23 12:00:45 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:60516
Jul 23 12:00:45 mail-cbf postfix/tlsproxy[11310]: DISCONNECT [106.10.151.33]:60516
Jul 23 12:00:45 mail-cbf postfix/tlsproxy[11310]: Anonymous TLS connection established from [106.10.151.33]:58359: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 12:00:46 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:58359
Jul 23 12:00:46 mail-cbf postfix/tlsproxy[11310]: DISCONNECT [106.10.151.33]:58359
Jul 23 16:02:51 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:55805 to [193.175.73.208]:25
Jul 23 16:02:52 mail-cbf postfix/tlsproxy[63799]: CONNECT from [106.10.151.33]:55805
Jul 23 16:02:53 mail-cbf postfix/tlsproxy[63799]: Anonymous TLS connection established from [106.10.151.33]:55805: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 16:02:54 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:33462 to [193.175.73.208]:25
Jul 23 16:02:55 mail-cbf postfix/tlsproxy[63799]: CONNECT from [106.10.151.33]:33462
Jul 23 16:02:55 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:55805
Jul 23 16:02:55 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:55805
Jul 23 16:02:55 mail-cbf postfix/tlsproxy[63799]: DISCONNECT [106.10.151.33]:55805
Jul 23 16:02:56 mail-cbf postfix/tlsproxy[63799]: Anonymous TLS connection established from [106.10.151.33]:33462: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 16:02:56 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:33462
Jul 23 16:02:56 mail-cbf postfix/tlsproxy[63799]: DISCONNECT [106.10.151.33]:33462
Jul 23 20:04:31 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:34620 to [193.175.73.208]:25
Jul 23 20:04:37 mail-cbf postfix/tlsproxy[8546]: CONNECT from [106.10.151.33]:34620
Jul 23 20:04:38 mail-cbf postfix/tlsproxy[8546]: Anonymous TLS connection established from [106.10.151.33]:34620: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 20:04:39 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:53975 to [193.175.73.208]:25
Jul 23 20:04:45 mail-cbf postfix/tlsproxy[8546]: CONNECT from [106.10.151.33]:53975
Jul 23 20:04:46 mail-cbf postfix/tlsproxy[8546]: Anonymous TLS connection established from [106.10.151.33]:53975: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul 23 20:04:47 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:53975
Jul 23 20:04:47 mail-cbf postfix/tlsproxy[8546]: DISCONNECT [106.10.151.33]:53975
Jul 23 20:09:39 mail-cbf postfix/postscreen[36326]: COMMAND TIME LIMIT from [106.10.151.33]:34620 after EHLO
Jul 23 20:09:39 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:34620
Jul 23 20:09:39 mail-cbf postfix/tlsproxy[8546]: DISCONNECT [106.10.151.33]:34620
--
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Schleißheimer Straße 26/MG, 80333 München

Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer
Aufsichtsratsvorsitzender: Florian Kirstein
Viktor Dukhovni
2016-07-25 11:31:46 UTC
Permalink
RCPT from [106.10.151.33]:55805: 450 4.3.2 Service currently unavailable;
helo=<nm21-vm2.bullet.mail.sg3.yahoo.com>
Why would postscreen repeatedly TEMPFAIL these delivery attempts?
They come from the same IP (106.10.151.33), go to the same two
recipients and are sent from the same sender.
You should know this by now:

http://www.postfix.org/DEBUG_README.html#mail

You should also check and report any relevant content from the
postscreen cache.
--
Viktor.
Viktor Dukhovni
2016-07-25 11:44:37 UTC
Permalink
Jul 23 03:58:49 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:58305 to [193.175.73.208]:25
Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:47500 to [193.175.73.208]:25
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:58305
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:58305
Jul 23 03:58:54 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:47500
What's odd here, is that the host always makes two parallel TLS
connections (you must have some "late" tests enabled to get all
the way to STARTTLS), with the first connection logging tempfailed
recipients and logging "PASS NEW", and soon after the second seems
to just disconnect without logging either. Don't know what if
anything that second connection does to the cached state.
--
Viktor.
Wietse Venema
2016-07-25 20:47:31 UTC
Permalink
Post by Viktor Dukhovni
Jul 23 03:58:49 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:58305 to [193.175.73.208]:25
Jul 23 03:58:52 mail-cbf postfix/postscreen[36326]: CONNECT from [106.10.151.33]:47500 to [193.175.73.208]:25
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: PASS NEW [106.10.151.33]:58305
Jul 23 03:58:53 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:58305
Jul 23 03:58:54 mail-cbf postfix/postscreen[36326]: DISCONNECT [106.10.151.33]:47500
What's odd here, is that the host always makes two parallel TLS
connections (you must have some "late" tests enabled to get all
the way to STARTTLS), with the first connection logging tempfailed
recipients and logging "PASS NEW", and soon after the second seems
to just disconnect without logging either. Don't know what if
anything that second connection does to the cached state.
First the client passes all tests in the session from
[106.10.151.33]:58305, and postscreen caches that result.

However, the other session ends without passing deep protocol
tests, and when that session ends, postscreen caches only the tests
that were passed in that session, i.e. no deep protocol tests.

I'll see if it is possible to handle this without keeping too much
state in postscreen for too much time.

Wietse
Ralf Hildebrandt
2016-07-26 12:24:10 UTC
Permalink
Post by Wietse Venema
Post by Viktor Dukhovni
What's odd here, is that the host always makes two parallel TLS
connections (you must have some "late" tests enabled to get all
the way to STARTTLS), with the first connection logging tempfailed
recipients and logging "PASS NEW", and soon after the second seems
to just disconnect without logging either. Don't know what if
anything that second connection does to the cached state.
First the client passes all tests in the session from
[106.10.151.33]:58305, and postscreen caches that result.
However, the other session ends without passing deep protocol
tests, and when that session ends, postscreen caches only the tests
that were passed in that session, i.e. no deep protocol tests.
I'll see if it is possible to handle this without keeping too much
state in postscreen for too much time.
Thanks
--
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Schleißheimer Straße 26/MG, 80333 München

Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer
Aufsichtsratsvorsitzender: Florian Kirstein
Wietse Venema
2016-07-26 13:19:41 UTC
Permalink
Post by Ralf Hildebrandt
Post by Wietse Venema
Post by Viktor Dukhovni
What's odd here, is that the host always makes two parallel TLS
connections (you must have some "late" tests enabled to get all
the way to STARTTLS), with the first connection logging tempfailed
recipients and logging "PASS NEW", and soon after the second seems
to just disconnect without logging either. Don't know what if
anything that second connection does to the cached state.
First the client passes all tests in the session from
[106.10.151.33]:58305, and postscreen caches that result.
However, the other session ends without passing deep protocol
tests, and when that session ends, postscreen caches only the tests
that were passed in that session, i.e. no deep protocol tests.
I'll see if it is possible to handle this without keeping too much
state in postscreen for too much time.
Thanks
Short answer: disable the after-220 tests:

postscreen_bare_newline_enable = no
postscreen_non_smtp_command_enable = no
postscreen_pipelining_enable = no

Long answer: fixing this requires changing the book-keeping of
passed tests, from per-session state into shared per-client state.

With my current availability, that is likely to take longer than
most clients are willing to retry. Hence the "short answer" suggestion.

Wietse
Peter
2016-07-26 21:12:10 UTC
Permalink
Post by Wietse Venema
postscreen_bare_newline_enable = no
postscreen_non_smtp_command_enable = no
postscreen_pipelining_enable = no
Long answer: fixing this requires changing the book-keeping of
passed tests, from per-session state into shared per-client state.
With my current availability, that is likely to take longer than
most clients are willing to retry. Hence the "short answer" suggestion.
Would doing another cache read right before the update be an easy fix
for this? I do realize this would add additional latency to postscreen,
hopefully not too much.


Peter
Viktor Dukhovni
2016-07-26 21:51:56 UTC
Permalink
Post by Peter
Would doing another cache read right before the update be an easy fix
for this? I do realize this would add additional latency to postscreen,
hopefully not too much.
This still leaves a race condition in place, though it would be for a shorter
time.
--
Viktor.
Peter
2016-07-26 23:00:24 UTC
Permalink
Post by Viktor Dukhovni
Post by Peter
Would doing another cache read right before the update be an easy fix
for this? I do realize this would add additional latency to postscreen,
hopefully not too much.
This still leaves a race condition in place, though it would be for a shorter
time.
The shorter time should be good enough, but I would think you could lock
the db for the operation to prevent the race.


Peter
Wietse Venema
2016-07-26 23:37:30 UTC
Permalink
Post by Viktor Dukhovni
Post by Peter
Would doing another cache read right before the update be an easy fix
for this? I do realize this would add additional latency to postscreen,
hopefully not too much.
This still leaves a race condition in place, though it would be for a shorter
time.
Yes, I would not want to double the number of database accesses.

It was easy enough to share one in-memory copy of postscreen cache
data among multiple SMTP sessions, by introducing one more level
of indirection.

Now it is a matter of carefully reading and updating that shared
state, and avoiding unnecessary postscreen cache lookups and updates
when SMTP sessions from the same client overlap in time.

Wietse
Wietse Venema
2016-07-26 23:40:57 UTC
Permalink
Post by Peter
Post by Viktor Dukhovni
Post by Peter
Would doing another cache read right before the update be an easy fix
for this? I do realize this would add additional latency to postscreen,
hopefully not too much.
This still leaves a race condition in place, though it would be for a shorter
time.
The shorter time should be good enough, but I would think you could lock
the db for the operation to prevent the race.
That would not help. postscreen is normally the only reader/writer.
Only LMDB maps support write/read and write/write sharing, and that
only with the locking scheme described lmdb_table(5).

A better solution is to eliminate the redundant cache access and
update when sessions from the same client overlap in time.

Wietse

Loading...