Sahil Tandon:
> On Sat, 2012-05-05 at 19:49:18 -0400, Wietse Venema wrote:
>
> > Sahil Tandon:
> > > May 5 15:24:07 mx1 postfix/postscreen[38500]: CONNECT from
> > > [88.23.204.109]:40294 to [69.147.83.52]:25
> > > May 5 15:24:07 mx1 postfix/dnsblog[45237]: addr 88.23.204.109 listed by
> > > domain bl.spameatingmonkey.net as 127.0.0.3
> > > May 5 15:24:07 mx1 postfix/dnsblog[45234]: addr 88.23.204.109 listed by
> > > domain zen.spamhaus.org as 127.0.0.11
> > > May 5 15:24:07 mx1 postfix/dnsblog[45234]: addr 88.23.204.109 listed by
> > > domain zen.spamhaus.org as 127.0.0.4
> > > May 5 15:24:09 mx1 postfix/postscreen[38500]: DNSBL rank 5 for
> > > [88.23.204.109]:40294
> > > May 5 15:24:09 mx1 postfix/postscreen[38500]: HANGUP after 0.24 from
> > > [88.23.204.109]:40294 in tests after SMTP handshake
> > > May 5 15:24:09 mx1 postfix/postscreen[38500]: DISCONNECT
> > > [88.23.204.109]:40294
> > >
> > > In this second instance, is it correct to infer that Postfix was under
> > > stress given the 2s (rather than 6s) that elapses between the last
> > > dnsblog(8) entry and when the DNSBL rank is logged by postscreen(8)?
> >
> > No. What your see is this: there are no more before-220 tests when
> > the DNBLS lookups complete, therefore postscreen makes its decision
> > immediately.
>
> Hmm, OK.
>
> > Either you have pregreet tests turned off, or this this client has
> > already passed the pregreet test recently, and that result was
> > cached in the temporary whitelist database.
>
> Gotcha, and because PREGREET tests are enabled, it must be the cache as
> you note.
>
> > By the way, what is going on with your DNS? Why do both DNSBL replies
> > arrive (almost) simultaneously after two seconds?
My bad. postscreen reports 'DNSBL rank' after two seconds.
> In the log excerpt quoted above, CONNECT and dnsblog entries share the
> same timestamp of '15:24:07', so - just so I understand your question -
> do you mean why the 'DNSBL rank' is logged two seconds after CONNECT? I
> assumed that was because Postfix waits for postscreen_greet_wait to
> elapse before logging 'DNSBL rank' when the score matches or exceeds the
> threshold.
postscreen will report DNSBL results when *ALL* lookups
complete or when the postscreen_greet_wait timer expires.
> > > May 5 15:25:08 mx1 postfix/postscreen[38500]: CONNECT from
> > > [88.23.204.109]:41253 to [69.147.83.52]:25
> > > May 5 15:25:10 mx1 postfix/dnsblog[45304]: addr 88.23.204.109 listed by
> > > domain zen.spamhaus.org as 127.0.0.4
> > > May 5 15:25:10 mx1 postfix/dnsblog[45304]: addr 88.23.204.109 listed by
> > > domain zen.spamhaus.org as 127.0.0.11
> > > May 5 15:25:10 mx1 postfix/dnsblog[45300]: addr 88.23.204.109 listed by
> > > domain bl.spameatingmonkey.net as 127.0.0.3
> > > May 5 15:25:10 mx1 postfix/postscreen[38500]: NOQUEUE: reject: RCPT
> > > from [88.23.204.109]:41253: 450 4.3.2 Service currently unavailable;
> > > from=<unlacesj...@clickz.com>, to=<freebsd-...@freebsd.org>,
> > > proto=ESMTP, helo=<109.Red-88-23-204.staticIP.rima-tde.net>
> > > May 5 15:25:11 mx1 postfix/postscreen[38500]: HANGUP after 1.1 from
> > > [88.23.204.109]:41253 in tests after SMTP handshake
> > > May 5 15:25:11 mx1 postfix/postscreen[38500]: PASS NEW
> > > [88.23.204.109]:41253
> > > May 5 15:25:11 mx1 postfix/postscreen[38500]: DISCONNECT
> > > [88.23.204.109]:41253
> >
> > postscreen sends out DNSBL lookup requests because the client is
> > not yet whitelisted for this test.
> >
> > Notice that again, both DNSBL replies arrive two seconds later.
>
> In this case I think I see what you mean: the dnsblog logging appears 2s
> after the CONNECT.
...
> > Apparently this time the DNSBL score did not reach your '5' threshold,
> > so the client is not blocked. Perhaps some bit got flipped as the
> > dnsblog reported its results to the postscreen daemon; postscreen
> > '-v' logging will show how it maintains DNSBL scores.
>
> Ah, this is what confuses me: the exact same DNSBL hits resulted in a
> rank of 5 so many times earlier, and the underlying configuration (i.e.
> the weights per DNSBL) have not changed in quite some time, so I
> expected to see a 5 rank here again.
I repeat, perhaps some bit got flipped as the dnsblog daemon reported
its results to the postscreen daemon; postscreen '-v' logging will
show how it maintains DNSBL scores.
Wietse
