OK, I turned off the Postfix debuging mode. I tried to send a mail with my server and there is the log file :
[mail.log] Aug 23 16:13:11 testing-puppet postfix/smtpd[13548]: connect from unknown[192.168.170.85] Aug 23 16:13:12 testing-puppet postfix/smtpd[13548]: NOQUEUE: reject: RCPT from unknown[192.168.170.85]: 450 4.7.1 <[email protected]>: Sender address rejected: Access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<[192.168.170.85]> Aug 23 16:13:16 testing-puppet postfix/smtpd[13548]: disconnect from unknown[192.168.170.85] [cbpolicyd.log] [2011/08/23-16:13:11 - 11072] [CORE] INFO: Starting "1" children [2011/08/23-16:13:11 - 12506] [CORE] INFO: 2011/08/23-16:13:11 CONNECT TCP Peer: "192.168.254.242:36410" Local: "192.168.254.242:10031" [2011/08/23-16:13:11 - 12506] [TRACKING] ERROR: Failed to select session tracking info: cbp::dblayer::DBSelect(107): Error executing select: Unknown column 'Timestamp' in 'field list' [2011/08/23-16:13:11 - 12506] [CBPOLICYD:12506] DEBUG: Error getting session data [2011/08/23-16:13:12 - 13552] [CORE] DEBUG: Child Preforked (13552) [2011/08/23-16:13:12 - 13552] [CBPOLICYD] DEBUG: Starting up caching engine 2011/8/23 Simon Hobson <[email protected]>: > At 15:17 +0200 23/8/11, Roland Vogt wrote: > > OK, so you know what to look for in the future, this is the section > that starts processing a call to the policy server (this is the > smtpd_recipient_restrictions section) : > >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: >>> START Sender >>address RESTRICTIONS <<< >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: generic_checks: >>name=check_policy_service >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: trying... >>[192.168.254.242] >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: auto_clnt_open: >>connected to 192.168.254.242:10031 > > Hmm 192.168.254.242, that's not the address given before (127.0.0.1) ! > > Now we see Postfix sending information to the policy server - one > attribute at a time : > >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr request >>= smtpd_access_policy >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>protocol_state = RCPT >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>protocol_name = ESMTP >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>client_address = 192.168.170.85 >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>client_name = unknown >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>reverse_client_name = unknown >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>helo_name = [192.168.170.85] >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr sender >>= [email protected] >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>recipient = [email protected] >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>recipient_count = 0 >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr queue_id = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>instance = 314e.4e53a7f3.4169a.0 >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr size = 363 >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr etrn_domain = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr stress = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr sasl_method = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr sasl_username = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr sasl_sender = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr ccert_subject = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr ccert_issuer = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>ccert_fingerprint = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>encryption_protocol = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>encryption_cipher = >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: send attr >>encryption_keysize = 0 > > Now Postfix has sent all the information, it asks the policy server > for an answer : > >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: >>192.168.254.242:10031: wanted attribute: action >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: input attribute >>name: action > > And gets the answer "DEFER" > >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: input attribute >>value: DEFER >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: >>192.168.254.242:10031: wanted attribute: (list terminator) >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: input attribute >>name: (end) > > > So having got the answer DEFER, it rejects the message and informs the client > : > >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: >>check_table_result: inet:192.168.254.242:10031 DEFER policy query >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: NOQUEUE: reject: >>RCPT from unknown[192.168.170.85]: 450 4.7.1 <[email protected]>: >>Sender address rejected: Access denied; from=<[email protected]> >>to=<[email protected]> proto=ESMTP helo=<[192.168.170.85]> >>Aug 23 15:15:31 testing-puppet postfix/smtpd[12622]: generic_checks: >>name=check_policy_service status=2 > > > So, now we've shown that Postfix is actually querying the policy > server. You can turn off the Postfix debugging and we need to go back > to the CLuebringer logs. The logs you posted earlier didn't show any > connections from Postfix - which would be the case given the > incorrect (and invalid) port number. > > -- > Simon Hobson > > Visit http://www.magpiesnestpublishing.co.uk/ for books by acclaimed > author Gladys Hobson. Novels - poetry - short stories - ideal as > Christmas stocking fillers. Some available as e-books. > _______________________________________________ > Users mailing list > [email protected] > http://lists.policyd.org/mailman/listinfo/users > _______________________________________________ Users mailing list [email protected] http://lists.policyd.org/mailman/listinfo/users
