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? 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. > > 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. But FWIW, in previous instances with respect to this client, the CONNECT and dnsblog share the same timestamp such that there is no 2s delay, e.g.: May 5 15:20:51 mx1 postfix/postscreen[38500]: CONNECT from [88.23.204.109]:38458 to [69.147.83.52]:25 May 5 15:20:51 mx1 postfix/dnsblog[45022]: addr 88.23.204.109 listed by domain bl.spameatingmonkey.net as 127.0.0.3 May 5 15:20:51 mx1 postfix/dnsblog[45025]: addr 88.23.204.109 listed by domain zen.spamhaus.org as 127.0.0.11 May 5 15:20:51 mx1 postfix/dnsblog[45025]: addr 88.23.204.109 listed by domain zen.spamhaus.org as 127.0.0.4 May 5 15:20:57 mx1 postfix/postscreen[38500]: DNSBL rank 5 for [88.23.204.109]:38458 May 5 15:20:57 mx1 postfix/postscreen[38500]: NOQUEUE: reject: RCPT from [88.23.204.109]:38458: 550 5.7.1 Service unavailable; client [88.23.204.109] blocked using bl.spameatingmonkey.net; from=<zo...@mc2school.org>, to=<n...@freebsd.org>, proto=ESMTP, helo=<109.Red-88-23-204.staticIP.rima-tde.net> ... and ... May 5 15:22:22 mx1 postfix/postscreen[38500]: CONNECT from [88.23.204.109]:38943 to [69.147.83.52]:25 May 5 15:22:22 mx1 postfix/dnsblog[45121]: addr 88.23.204.109 listed by domain bl.spameatingmonkey.net as 127.0.0.3 May 5 15:22:22 mx1 postfix/dnsblog[45116]: addr 88.23.204.109 listed by domain zen.spamhaus.org as 127.0.0.4 May 5 15:22:22 mx1 postfix/dnsblog[45116]: addr 88.23.204.109 listed by domain zen.spamhaus.org as 127.0.0.11 May 5 15:22:24 mx1 postfix/postscreen[38500]: DNSBL rank 5 for [88.23.204.109]:38943 May 5 15:22:24 mx1 postfix/postscreen[38500]: NOQUEUE: reject: RCPT from [88.23.204.109]:38943: 550 5.7.1 Service unavailable; client [88.23.204.109] blocked using bl.spameatingmonkey.net; from=<welled...@eoriginal.com>, to=<nj...@freebsd.org>, proto=ESMTP, helo=<109.Red-88-23-204.staticIP.rima-tde.net> > 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. > ... > If this discrepancy is reproducible let me know. Otherwise I > will not lose sleep over this. Fair enough; I will not report back unless I am able to reproduce it. -- Sahil Tandon
