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]>: Recipient address
rejected: Access denied;
from=<[email protected] to=<[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]>: Recipient address
rejected: Greylisting in
effect, please come back later; from=<[email protected]> to=<[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]>: Recipient address
rejected: Access denied;
from=<[email protected]> to=<[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]>: Recipient
address rejected: Access
denied; from=<[email protected]> to=<[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.
Sincerely,
Yi-Yen Chuang
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users
