On Wed, Dec 23, 2009 at 09:56:21AM +0100, Helga Mayer wrote:
> On Wed, 23 Dec 2009, Robert Felber wrote:
>
> > On Tue, Dec 22, 2009 at 01:45:56PM +0100, Helga Mayer wrote:
> >> Hello list,
> >>
> >> I have a problem with rejects due to cache entries.
> >> We use policyd-weight-0.1.14-beta-17.
> >>
> >> This is the message found in the logfile:
> >>
> >> Dec 21 16:09:28 smtp2 postfix/smtpd[16364]: connect from
> >> mail-telecontrol.customer.solnet.ch[82.220.17.226]
> >> Dec 21 16:09:29 smtp2 postfix/policyd-weight[30193]: decided action=550
> >> temporarily blocked because of previous errors - retrying too fast.
> >> penalty: 30 seconds x 0 retries.; <client=82.220.17.226>
> >> <helo=smtp.telecontrol.ch> <from=$sen...@telecontrol.ch>
> >> <to=$recipi...@uni-hohenheim.de>; delay: 0s
> >> Dec 21 16:09:29 smtp2 postfix/smtpd[16364]: NOQUEUE: reject: RCPT from
> >> mail-telecontrol.customer.solnet.ch[82.220.17.226]: 550 5.7.1
> >> <$recipi...@uni-hohenheim.de>: Recipient address rejected: temporarily
> >> blocked
> >> because of previous errors - retrying too fast. penalty: 30 seconds x 0
> >> retries.; from=<$sen...@telecontrol.ch> to=<$recipi...@uni-hohenheim.de>
> >> proto=ESMTP helo=<smtp.telecontrol.ch>
> >>
> >>
> >> There are no other log entries for 82.220.17.226 during the last 8 days.
> >> The cache entry is:
> >
> > [bz]grep 82.220.17.226 /var/log/...log...
> >
> > results only in this snippet?
> yes
>
> What I expected was something like
>
> weighted check: NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5
> NOT_IN_BL_NJABL=-1.5 HELO_IP_IN_CL_SUBNET=-1.2 (check from: .hotmail. -
> helo: .some.domain - helo-domain: .domain.)
> FROM/MX_MATCHES_NOT_HELO(DOMAIN)=1 IN_PM_RFCI=3.2 IN_ABUSE_RFCI=3.2;
> <client=xxx.xxx.xxx.xxx> <helo=helo.some.domain>
> <from=sen...@sender.domain> <to=recipi...@uni-hohenheim.de>; rate:
> 1.7
>
> but there's no entry like this for 82.220.17.226
> >
> >
> >> policyd-weight -s|grep 82.220.17.226 >> blocked: 82.220.17.226 1 0
> >> 1261408171
> >> 1261408171 (UNIX) is the date of the first (and only) reject + 2 seconds :
> >> 1261408171 = Mon, 21 Dec 2009 15:09:31 GMT
> >
> > + 2 seconds indeed sounds strange but could be explained if the
> > log is done in GMT (which would make it then a retry after 59:57 minutes).
> I apologize, this was my mistake. I checked the logs on a common loghost.
> The loghost is 2 second back.
Loghost. Hmhm.
> >
> >
> > Is the policy service used by many machines or _only_ by localhost?
> by 2 machines with identical setup. 2 smtp servers with the same priority
> in the MX Record. Each is running policyd-weight locally.
> On the particular host the time of the cache entry is exactly the time
> of the first reject.
In the cache entry for blocked entries is only the timestamp for the last
attempt. This should be improved, yes.
> So the problem remaining is:
> why is there no reason given in the logs for the reject and for rate:1,
> as seen in the cache entry.
One reason could be that the first attempt was longer than 8 days.
The blocked: 82.220.17.226 1 0 1261408171 indicates that it has been seen
before because
policyd-weight decremented the NTTL (config setting, default 1) counter.
It then depends on how large the cache is, or how often it has to throw out
some of the oldest entries.
Another possibility could be, that the log message(s) simply got lost. In case
of UDP-loses no one can tell what happened.
(maybe by some luck there is some evidence in
/tmp/.policyd-weight/polw-emergency.log,
resp. $LOCKPATH/polw-emergency.log. Would only be there if the syslog daemon
was not
available. but not, if the syslog daemon have had problems with logging)
--
Robert Felber (PGP: 896CF30B)
Munich, Germany
____________________________________________________________
Policyd-weight Mailinglist - http://www.policyd-weight.org/
