Re: [policyd-users] Race condition when auto[white|black]list, [greylisting|quotas]_tracking

[asmodevs]

Thanks for reply.

I tried v2.0.11RC and it seems to work quite better than v2.0.10.

There's only "ONE" failed insert after running for several hours.
====
[2010/10/22-11:43:44 - 30765] [QUOTAS] ERROR: Failed to insert
quota_tracking item: cbp::dblayer::DBDo(125): Error executing command '
%09%09%09%09%09%09INSERT INTO quotas_tracking
%09%09%09%09%09%09%09(QuotasLimitsID,TrackKey,LastUpdate,Counter)
%09%09%09%09%09%09VALUES
%09%09%09%09%09%09%09(
%09%09%09%09%09%09%09%09'7',
%09%09%09%09%09%09%09%09'SenderIP:44.33.22.11/32',
%09%09%09%09%09%09%09%09'1287719024',
%09%09%09%09%09%09%09%09'1'
%09%09%09%09%09%09%09)
%09%09%09%09%09': Duplicate entry '7-SenderIP:44.33.22.11/32' for key 1
====

$$$$
2010-10-22T11:43:44.502960+08:00 penguin cbpolicyd[30754]: module=Quotas,
mode=create, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=945003...@cc.ncu.edu.tw,
reason=quota_create, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
2010-10-22T11:43:44.504104+08:00 penguin cbpolicyd[30769]: module=Quotas,
mode=update, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=944408...@cc.ncu.edu.tw,
reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
*2010-10-22T11:43:44.507701+08:00 penguin postfix/smtpd[30845]: NOQUEUE:
reject: RCPT from smtp107.mail.tp2.yahoo.com[203.188.201.207]: 450 4.7.1 <
945002...@cc.ncu.edu.tw>: Recipient address rejected: Access denied; from=<
cxutfhguqhai...@yahoo.com.sg> to=<945002...@cc.ncu.edu.tw> proto=SMTP helo=<
smtp107.mail.tp2.yahoo.com>*
2010-10-22T11:43:44.516563+08:00 penguin cbpolicyd[30874]: module=Quotas,
mode=update, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=944203...@cc.ncu.edu.tw,
reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
2010-10-22T11:43:44.527249+08:00 penguin cbpolicyd[30854]: module=Quotas,
mode=update, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=944403...@cc.ncu.edu.tw,
reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
2010-10-22T11:43:44.541337+08:00 penguin cbpolicyd[30872]: module=Quotas,
mode=update, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=944403...@cc.ncu.edu.tw,
reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
2010-10-22T11:43:44.541832+08:00 penguin cbpolicyd[30878]: module=Quotas,
mode=update, host=203.188.201.207, helo=smtp107.mail.tp2.yahoo.com, from=
cxutfhguqhai...@yahoo.com.sg, to=944203...@cc.ncu.edu.tw,
reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
203.188.201.207/32, counter=MessageCount, quota=8/2000 (0.4%)
$$$$


I'm quite sure this 'failed insert' is caused by 2.0.11RC.
Because after starting 2.0.11RC,
this error message - "Use of uninitialized value in subtraction (-) at
/usr/local/lib/policyd-2.0/cbp/modules/Quotas.pm line 179, <_READ> line
1111. " continues to show up in log.


Best Regards
Yi-Yen Chuang


On Thu, Oct 21, 2010 at 11:43 PM, Nigel Kukard <nkuk...@lbsd.net> wrote:

>
>
> On 10/21/10 15:22, asmodevs wrote:
>
> We encountered a problem (race condition) when using policyd v2.0.10.
>
>  Database: MySQL 5
> Mail Daemon: Postfix
>
>  Take a look at this.
>
>  (greylisting_autowhitelist), also happened in greylisting_autoblacking
> ====
> 1) [2010/10/21-18:28:21 - 12202] [GREYLISTING] DEBUG: Updated greylisting
> triplet
> ('SenderIP:11.22.33.0/24','a...@aa.aa.aa','x...@xx.xx.xx') @ 1287656901
> 2) [2010/10/21-18:33:21 - 14348] [GREYLISTING] DEBUG: Updated greylisting
> triplet
> ('SenderIP:11.22.33.0/24','a...@aa.aa.aa','x...@xx.xx.xx') @ 1287657200
> 3) [2010/10/21-18:33:21 - 14165] [GREYLISTING] DEBUG: Updated greylisting
> triplet
> ('SenderIP:11.22.33.0/24','a...@aa.aa.aa','x...@xx.xx.xx') @ 1287657200
> 4) %09%09%09%09%09%09%09%09%09%09%09'SenderIP:11.22.33.0/24',
> 5) %09%09%09%09%09%09%09%09': Duplicate entry 'SenderIP:11.22.33.0/24' for
> key 2
> ====
>
>  When SenderIP:11.22.33.0/24 is whitelisted { the line 1) and the line 3)
> },
> the update of greylisting triplet is failed { the line 2), 4), 5) }.
>
>  Then, this failed insert will cause the postfix to reject this email.
> $$$$
> 2010-10-21T18:33:21.121314+08:00 foo postfix/smtpd[2206]: NOQUEUE: reject:
> RCPT from
> smtp.aa.aa.aa[11.22.33.44]: 450 4.7.1 <x...@xx.xx.xx> <x...@xx.xx.xx>:
> Recipient address rejected: Access denied;
> from=<a...@aa.aa.aa to=<x...@xx.xx.xx> <x...@xx.xx.xx> proto=ESMTP
> helo=<smtp.aa.aa.aa>
> $$$$
>
>  The error "Recipient address rejected: Access denied" originally indicate
> that the user doesn't
> exist. But, in here, this account does exists.
>
>  Another example of race condition.
> (greylisting_tracking)
> ====
> [2010/10/18-14:17:03 - 32478] [GREYLISTING] DEBUG: Updated greylisting
> triplet
> ('SenderIP:12.23.34.45/32','b...@bb.bb.bb','x...@xx.xx.xx') @ 1287382622
> [2010/10/18-14:17:03 - 31713] [GREYLISTING] ERROR: Database insert failed:
> cbp::dblayer::DBDo(125):
> Error executing command '
> %09%09%09INSERT INTO greylisting_tracking
> %09%09%09%09(TrackKey,Sender,Recipient,FirstSeen,LastUpdate,Tries,Count)
> %09%09%09VALUES
> %09%09%09%09(
> %09%09%09%09%09'SenderIP:12.23.34.45/32',
> %09%09%09%09%09'b...@bb.bb.bb <09%2509%2509%2509%2509%2...@bb.bb.bb>',
> %09%09%09%09%09'x...@xx.xx.xx',
> %09%09%09%09%09'1287382622',
> %09%09%09%09%09'1287382622',
> %09%09%09%09%091,
> %09%09%09%09%090
> %09%09%09%09)
> %09%09': Duplicate entry 'SenderIP:
> 12.23.34.45/32...@bb.bb.bb-xx12@xx.xx.xx' for key 1
> ====
>
>  Different results.
> $$$$
>  2010-10-18T14:17:03.323086+08:00 foo postfix/smtpd[31119]: NOQUEUE:
> reject: RCPT from
> 12.23.34.45[12.23.34.45]: 451 4.7.1 <x...@xx.xx.xx> <x...@xx.xx.xx>:
> Recipient address rejected: Greylisting in
> effect, please come back later; from=<b...@bb.bb.bb> 
> to=<x...@xx.xx.xx><x...@xx.xx.xx>proto=SMTP
> helo=<12.23.34.45>
> 2010-10-18T14:17:03.324275+08:00 foo postfix/smtpd[5646]: NOQUEUE: reject:
> RCPT from
> 12.23.34.45[12.23.34.45]: 450 4.7.1 <x...@xx.xx.xx> <x...@xx.xx.xx>:
> Recipient address rejected: Access denied;
> from=<b...@bb.bb.bb> to=<x...@xx.xx.xx> <x...@xx.xx.xx> proto=SMTP
> helo=<12.23.34.45>
> $$$$
>
>  And, another.
> (quotas_tracking)
> ====
> [2010/10/19-11:48:28 - 14628] [QUOTAS] ERROR: Failed to insert
> quota_tracking item:
> cbp::dblayer::DBDo(125): Error executing command '
> %09%09%09%09%09%09INSERT INTO quotas_tracking
> %09%09%09%09%09%09%09(QuotasLimitsID,TrackKey,LastUpdate,Counter)
> %09%09%09%09%09%09VALUES
> %09%09%09%09%09%09%09(
> %09%09%09%09%09%09%09%09'8',
> %09%09%09%09%09%09%09%09'Sender:c...@cc.cc.cc<09%2509%2509%2509%2509%2509%2509%2509%27sender%3...@cc.cc.cc>
> ',
> %09%09%09%09%09%09%09%09NULL,
> %09%09%09%09%09%09%09%09'1'
> %09%09%09%09%09%09%09)
> %09%09%09%09%09': Duplicate entry 
> '8-Sender:c...@cc.cc.cc<8-sender%3...@cc.cc.cc>'
> for key 1
> ====
>
>  $$$$
> 2010-10-19T11:48:28.134546+08:00 foo cbpolicyd[14602]: module=Quotas,
> mode=update,
> host=33.44.55.66, helo=66.55.44.33-reverse, from...@cc.cc.cc,
> to...@xx.xx.xx, reason=quota_update,
> policy=8, quota=6, limit=7, track=SenderIP:33.44.55.0/24,
> counter=MessageCount, quota=29/900
> (3.3%)
> 2010-10-19T11:48:28.134594+08:00 foo cbpolicyd[14628]: module=Quotas,
> mode=update,
> host=33.44.55.66, helo=66.55.44.33-reverse, from...@cc.cc.cc,
> to=z...@xx.xx.xx,
> reason=quota_update, policy=8, quota=6, limit=7, track=SenderIP:
> 33.44.55.0/24,
> counter=MessageCount, quota=29/900 (3.3%)
> 2010-10-19T11:48:28.135999+08:00 foo cbpolicyd[14602]: module=Quotas,
> mode=create,
> host=33.44.55.66, helo=66.55.44.33-reverse, from...@cc.cc.cc,
> to...@xx.xx.xx, reason=quota_create,
> policy=8, quota=7, limit=8, track=Sender:c...@cc.cc.cc<sender%3...@cc.cc.cc>,
> counter=MessageCount, quota=1/2000 (0.1%)
> 2010-10-19T11:48:28.137715+08:00 foo cbpolicyd[14602]: module=Quotas,
> mode=update,
> host=33.44.55.66, helo=66.55.44.33-reverse, from...@cc.cc.cc,
> to...@xx.xx.xx, reason=quota_update,
> policy=8, quota=8, limit=9, track=Recipient:z...@xx.xx.xx,
> counter=MessageCount, quota=2/200 (0.9%)
> 2010-10-19T11:48:28.138388+08:00 foo postfix/smtpd[14879]: NOQUEUE: reject:
> RCPT from
> 66.55.44.33-reverse[33.44.55.66]: 450 4.7.1 <z...@xx.xx.xx><z...@xx.xx.xx>:
> Recipient address rejected: Access
> denied; from=<c...@cc.cc.cc> to=<z...@xx.xx.xx> <z...@xx.xx.xx> proto=SMTP
> helo=<66.55.44.33-reverse>
> 2010-10-19T11:48:30.758833+08:00 foo postfix/qmgr[7369]: 22F1719F35F:
> from=<c...@cc.cc.cc>,
> size=757966, nrcpt=1 (queue active)
> $$$$
>
>  There'r two messages from c...@cc.cc.cc at the same time. One insert
> succeed, another failed. So, one
> +message is rejected.
>
>  Is there anyone encountered the same problem? Thanks.
>
>
>
> Could you try v2.0.11RC1?
>
> Regards
> Nigel
>
> _______________________________________________
> Users mailing list
> Users@lists.policyd.org
> http://lists.policyd.org/mailman/listinfo/users
>
>

_______________________________________________
Users mailing list
Users@lists.policyd.org
http://lists.policyd.org/mailman/listinfo/users