For the last couple of days I'm now experimenting with the
2.7-20091105-nonprod with the new speed_adjust experimental feature
turned on at the MX port, along with the postscreen. Seems to work
as advertised: timing reports by a pre-queue proxy content filter confirm
that the content filter is invoked only after data has been received.
Current mail load on our server is not high, so I haven't yet seen
what happens under high mail rate conditions.
Here is the relevant part of my master.cf:
dnsblog unix - - n - 0 dnsblog
smtp inet n - n - 1 postscreen
smtpd pass - - n - 150 smtpd
-o smtpd_proxy_filter=127.0.0.1:10010
-o smtpd_proxy_options=speed_adjust
-o smtpd_client_connection_count_limit=30
-o smtpd_proxy_timeout=600
Two things are on my mind:
1. I'm dearly missing in the postfix log the SMTP response from a
pre-queue content filter (or better, a response that was sent back to a SMTP
client), at least in case of a 5xx or 4xx response. With a post-queue filter
setup the response is clearly logged, unlike in the pre-queue setup where it
is not. It makes it hard to correlate a spartanic postfix log of a rejected
transaction (due to a proxy filter rejection) with a log from a content
filter. Even if the correlation were somehow available, seeing a confirmation
of what was really sent back to the client in a postfix log would contribute
to the confidence in the correctness of operation.
2. A couple of times per day I see that postfix terminates its smtpd service:
+pid 9297 (smtpd), uid 125: exited on signal 6
+pid 12680 (smtpd), uid 125: exited on signal 6
+pid 9306 (smtpd), uid 125: exited on signal 6
and a corresponding log entry from a smtpd process:
panic: smtpd_proxy_replay_setup:
non-empty before-queue filter speed-adjust log
The log (some other PIDs) can look like (a grep by PID,
showing previous two transaction of the same process):
Nov 13 13:07:07 dorothy postfix/smtpd[82601]:
connect from unknown[74.63.109.233]
Nov 13 13:07:08 dorothy postfix/smtpd[82601]:
NOQUEUE: client=unknown[74.63.109.233]
Nov 13 13:07:12 dorothy postfix/smtpd[82601]:
disconnect from unknown[74.63.109.233]
Nov 13 13:07:29 dorothy postfix/smtpd[82601]:
connect from 201-92-220-64.dsl.telesp.net.br[201.92.220.64]
Nov 13 13:07:30 dorothy postfix/smtpd[82601]:
NOQUEUE: client=201-92-220-64.dsl.telesp.net.br[201.92.220.64]
Nov 13 13:07:36 dorothy postfix/smtpd[82601]:
disconnect from 201-92-220-64.dsl.telesp.net.br[201.92.220.64]
Nov 13 13:07:43 dorothy postfix/smtpd[82601]:
warning: 122.168.228.121: hostname
ABTS-mpdynamic-121.228.168.122.airtelbroadband.in
verification failed: hostname nor servname provided, or not known
Nov 13 13:07:43 dorothy postfix/smtpd[82601]:
connect from unknown[122.168.228.121]
Nov 13 13:08:26 dorothy postfix/smtpd[82601]:
NOQUEUE: client=unknown[122.168.228.121]
Nov 13 13:08:26 dorothy postfix/smtpd[82601]:
lost connection after RCPT from unknown[122.168.228.121]
Nov 13 13:08:26 dorothy postfix/smtpd[82601]:
disconnect from unknown[122.168.228.121]
Nov 13 13:08:32 dorothy postfix/smtpd[82601]:
connect from unknown[121.139.242.179]
Nov 13 13:08:34 dorothy postfix/smtpd[82601]:
panic: smtpd_proxy_replay_setup: non-empty before-queue
filter speed-adjust log
Here is another case:
Nov 13 13:52:43 dorothy postfix/smtpd[4186]:
NOQUEUE: client=200-199-119-208.user.neoline.com.br[200.199.119.208]
Nov 13 13:52:53 dorothy postfix/smtpd[4186]:
disconnect from 200-199-119-208.user.neoline.com.br[200.199.119.208]
Nov 13 13:52:58 dorothy postfix/smtpd[4186]:
connect from unknown[77.29.4.99]
Nov 13 13:53:01 dorothy postfix/smtpd[4186]:
NOQUEUE: client=unknown[77.29.4.99]
Nov 13 13:54:23 dorothy postfix/smtpd[4186]:
lost connection after DATA (1589 bytes) from unknown[77.29.4.99]
Nov 13 13:54:23 dorothy postfix/smtpd[4186]:
disconnect from unknown[77.29.4.99]
Nov 13 13:54:28 dorothy postfix/smtpd[4186]:
connect from unknown[170.51.195.142]
Nov 13 13:54:31 dorothy postfix/smtpd[4186]:
panic: smtpd_proxy_replay_setup: non-empty before-queue
filter speed-adjust log
So what does this mean?
Mark
