We are running 2.1-snapshot-201104210611 with Postfix 2.8.3 It appears that Postfix tries to re-use the same socket for the smtpd_recipient_restrictions and smtpd_end_of_data_restrictions. However it appears cbpolicyd closes this socket after the first check or has some error. As a result we notice that there is about a 1-2 second delay after the result of the DATA command while Postfix times out and reconnects to cbpolicyd. We have confirmed this by turning on Postfix debugging - the relevant parts are shown below:
Jul 4 14:23:12 omr postfix/smtpd[82707]: smtpd_check_addr: [email protected] Jul 4 14:23:12 omr postfix/smtpd[82707]: ctable_locate: move existing entry key [email protected] Jul 4 14:23:12 omr postfix/smtpd[82707]: extract_addr: in: <[email protected]>, result: [email protected] Jul 4 14:23:12 omr postfix/smtpd[82707]: >>> START Recipient address RESTRICTIONS <<< Jul 4 14:23:12 omr postfix/smtpd[82707]: generic_checks: name=check_policy_service Jul 4 14:23:12 omr postfix/smtpd[82707]: trying... [127.0.0.1] Jul 4 14:23:12 omr postfix/smtpd[82707]: auto_clnt_open: connected to 127.0.0.1:10031 .. Jul 4 14:23:12 omr cbpolicyd[82710]: module=Accounting, mode=update, host=192.168.10.99, helo=localhost, [email protected], [email protected], reason=accounting_update, policy=1, accounting=1, track=SASLUsername:[email protected], period=2011-07-04, count=23/500 (4.6%), size=21/1048576 (0.0%) .. Jul 4 14:23:12 omr postfix/smtpd[82707]: > unknown[192.168.10.99]: 250 2.1.5 Ok Jul 4 14:23:12 omr postfix/smtpd[82707]: watchdog_pat: 0x80120a710 Jul 4 14:23:12 omr postfix/smtpd[82707]: < unknown[192.168.10.99]: DATA Jul 4 14:23:12 omr postfix/smtpd[82707]: > unknown[192.168.10.99]: 354 End data with <CR><LF>.<CR><LF> Jul 4 14:23:12 omr postfix/smtpd[82707]: >>> START End-of-data RESTRICTIONS <<< Jul 4 14:23:12 omr postfix/smtpd[82707]: generic_checks: name=check_policy_service Jul 4 14:23:12 omr postfix/smtpd[82707]: warning: problem talking to server 127.0.0.1:10031: Unknown error: 0 Jul 4 14:23:13 omr postfix/smtpd[82707]: auto_clnt_close: disconnect 127.0.0.1:10031 stream Jul 4 14:23:13 omr postfix/smtpd[82707]: trying... [127.0.0.1] Jul 4 14:23:13 omr postfix/smtpd[82707]: auto_clnt_open: connected to 127.0.0.1:10031 .. Jul 4 14:23:13 omr cbpolicyd[82705]: module=Accounting, mode=update, host=192.168.10.99, helo=localhost, [email protected], [email protected], reason=accounting_update, policy=1, accounting=1, track=SASLUsername:[email protected], period=2011-07-04, count=23/500 (4.6%), size=21/1048576 (0.0%) We found that if we use the public IP address of the machine for smtpd_end_of_data_restrictions policy check and the loopback address for the smtpd_recipient_restrictions policy checks the delay is eliminated, as they appear as two distinct policy servers to Postfix, so attempted connection reuse doesn't occur. smtpd_recipient_restrictions = check_policy_service inet:127.0.0.1:10031, smtpd_end_of_data_restrictions = check_policy_service inet:192.168.2.40:10031 We are wondering if this is the intended behavior of cbpolicyd or could this be a possible issue? Sincerely, Nikolai Schupbach _______________________________________________ Users mailing list [email protected] http://lists.policyd.org/mailman/listinfo/users
