After several days of testing v2.0.11RC,
the results are the same.
I see race conditions when inserting into greylist_tracking and
greylist_autowhitelist.
I think v2.0.11RC doesn't fix these problems as what I had seen in
My environment：
MX_1 w/ policyd w/ mysqld
MX_2 w/ policyd w/ MX_1's mysqld
failed INSERT sum：
23 24 25 26 27
MX_1 1 3 2 1 1
MX_2 8 9 10 3 5
AWL After Count = 1
( Assume AWL After Count = 100. I guess that failed insert will happen when
100th and 101th messages arrive at the same time. )
Hope this could be helpful.
Best Regards
Yi-Yen Chuang
On Fri, Oct 22, 2010 at 3:11 PM, asmodevs <[email protected]> wrote:
> 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=
> [email protected], [email protected],
> 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=
> [email protected], [email protected],
> 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 <
> [email protected]>: Recipient address rejected: Access denied;
> from=<[email protected]> to=<[email protected]>
> 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=
> [email protected], [email protected],
> 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=
> [email protected], [email protected],
> 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=
> [email protected], [email protected],
> 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=
> [email protected], [email protected],
> 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 <[email protected]> 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','[email protected]','[email protected]') @ 1287656901
>> 2) [2010/10/21-18:33:21 - 14348] [GREYLISTING] DEBUG: Updated greylisting
>> triplet
>> ('SenderIP:11.22.33.0/24','[email protected]','[email protected]') @ 1287657200
>> 3) [2010/10/21-18:33:21 - 14165] [GREYLISTING] DEBUG: Updated greylisting
>> triplet
>> ('SenderIP:11.22.33.0/24','[email protected]','[email protected]') @ 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 <[email protected]> <[email protected]>:
>> Recipient address rejected: Access denied;
>> from=<[email protected] to=<[email protected]> <[email protected]> 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','[email protected]','[email protected]') @ 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'[email protected] <09%2509%2509%2509%2509%[email protected]>',
>> %09%09%09%09%09'[email protected]',
>> %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/[email protected]@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 <[email protected]> <[email protected]>:
>> Recipient address rejected: Greylisting in
>> effect, please come back later; from=<[email protected]>
>> to=<[email protected]><[email protected]>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 <[email protected]> <[email protected]>:
>> Recipient address rejected: Access denied;
>> from=<[email protected]> to=<[email protected]> <[email protected]> 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:[email protected]<09%2509%2509%2509%2509%2509%2509%2509%27sender%[email protected]>
>> ',
>> %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:[email protected]<8-sender%[email protected]>'
>> 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, [email protected],
>> [email protected], 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, [email protected],
>> [email protected],
>> 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, [email protected],
>> [email protected], reason=quota_create,
>> policy=8, quota=7, limit=8, track=Sender:[email protected]<sender%[email protected]>,
>> 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, [email protected],
>> [email protected], reason=quota_update,
>> policy=8, quota=8, limit=9, track=Recipient:[email protected],
>> 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 <[email protected]><[email protected]>:
>> Recipient address rejected: Access
>> denied; from=<[email protected]> to=<[email protected]> <[email protected]> proto=SMTP
>> helo=<66.55.44.33-reverse>
>> 2010-10-19T11:48:30.758833+08:00 foo postfix/qmgr[7369]: 22F1719F35F:
>> from=<[email protected]>,
>> size=757966, nrcpt=1 (queue active)
>> $$$$
>>
>> There'r two messages from [email protected] 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
>> [email protected]
>> http://lists.policyd.org/mailman/listinfo/users
>>
>>
>
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users
