Helio Coelho Junior wrote: > Hi Nigel: > > Thanks for answering. > It was already in full debug mode. Here we go, from the moment the > cbpolicyd process starts: > > [2009/08/21-15:21:43 - 15659] [CORE] NOTICE: Process Backgrounded > [2009/08/21-15:21:43 - 15659] [CBPOLICYD] NOTICE: Policyd v2 / > Cluebringer - v2.1.0a > [2009/08/21-15:21:43 - 15659] [CBPOLICYD] NOTICE: Initializing system modules. > [2009/08/21-15:21:43 - 15659] [CBPOLICYD] NOTICE: System modules initialized. > [2009/08/21-15:21:43 - 15659] [CBPOLICYD] NOTICE: Module load started... > [2009/08/21-15:21:43 - 15659] [CORE] NOTICE: => AccessControl: enabled > [2009/08/21-15:21:43 - 15659] [CORE] NOTICE: => CheckHelo: enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => CheckSPF: enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => Greylisting: enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => Quotas: enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => Accounting: enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => Protocol(Postfix): enabled > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: => Protocol(Bizanga): enabled > [2009/08/21-15:21:44 - 15659] [CBPOLICYD] NOTICE: Module load done. > [2009/08/21-15:21:44 - 15659] [CBPOLICYD] NOTICE: Session tracking is ENABLED. > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: 2009/08/21-15:21:44 cbp > (type Net::Server::PreFork) starting! pid(15659) > [2009/08/21-15:21:44 - 15659] [CORE] NOTICE: Binding to TCP port 10031 > on host 127.0.0.1 > [2009/08/21-15:21:44 - 15659] [CORE] WARNING: Group Not Defined. > Defaulting to EGID '0 5 0 0' > [2009/08/21-15:21:44 - 15659] [CORE] WARNING: User Not Defined. > Defaulting to EUID '0' > [2009/08/21-15:21:44 - 15659] [CORE] INFO: Setting up serialization via flock > [2009/08/21-15:21:44 - 15659] [CORE] INFO: Beginning prefork (4 processes) > [2009/08/21-15:21:44 - 15659] [CORE] INFO: Starting "4" children > [2009/08/21-15:21:44 - 15679] [CORE] DEBUG: Child Preforked (15679) > [2009/08/21-15:21:44 - 15679] [CBPOLICYD] DEBUG: Starting up caching engine > [2009/08/21-15:21:44 - 15680] [CORE] DEBUG: Child Preforked (15680) > [2009/08/21-15:21:44 - 15680] [CBPOLICYD] DEBUG: Starting up caching engine > [2009/08/21-15:21:44 - 15681] [CORE] DEBUG: Child Preforked (15681) > [2009/08/21-15:21:44 - 15681] [CBPOLICYD] DEBUG: Starting up caching engine > [2009/08/21-15:21:44 - 15682] [CORE] DEBUG: Child Preforked (15682) > [2009/08/21-15:21:44 - 15659] [CORE] DEBUG: Parent ready for children. > [2009/08/21-15:21:44 - 15682] [CBPOLICYD] DEBUG: Starting up caching engine > [2009/08/21-15:22:07 - 15659] [CORE] INFO: Starting "1" children > [2009/08/21-15:22:07 - 15679] [CORE] INFO: 2009/08/21-15:22:07 CONNECT > TCP Peer: "127.0.0.1:58217" Local: "127.0.0.1:10031" > [2009/08/21-15:22:07 - 15679] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2009/08/21-15:22:07 - 15679] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2009/08/21-15:22:07 - 16125] [CORE] DEBUG: Child Preforked (16125) > [2009/08/21-15:22:07 - 16125] [CBPOLICYD] DEBUG: Starting up caching engine > [2009/08/21-15:22:07 - 15679] [TRACKING] ERROR: Failed to select > session tracking info: awitpt::db::dblayer::DBSelect(127): Error > executing select: You have an error in your SQL syntax; check the > manual that corresponds to your MySQL server version for the right > syntax to use near '""session_tracking > %09%09%09%09WHERE > %09%09%09%09%09Instance = '3ee9.4a8ee5ce.0'' at line 13 > [2009/08/21-15:22:07 - 15679] [CBPOLICYD:15679] DEBUG: Error getting > session data > [2009/08/21-15:22:07 - 15680] [CORE] INFO: 2009/08/21-15:22:07 CONNECT > TCP Peer: "127.0.0.1:55046" Local: "127.0.0.1:10031" > [2009/08/21-15:22:07 - 15680] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2009/08/21-15:22:07 - 15680] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2009/08/21-15:22:07 - 15680] [TRACKING] ERROR: Failed to select > session tracking info: awitpt::db::dblayer::DBSelect(127): Error > executing select: You have an error in your SQL syntax; check the > manual that corresponds to your MySQL server version for the right > syntax to use near '""session_tracking > %09%09%09%09WHERE > %09%09%09%09%09Instance = '3ef6.4a8ee5cf.0'' at line 13 > [2009/08/21-15:22:07 - 15680] [CBPOLICYD:15680] DEBUG: Error getting > session data > [2009/08/21-15:22:08 - 15681] [CORE] INFO: 2009/08/21-15:22:08 CONNECT > TCP Peer: "127.0.0.1:60636" Local: "127.0.0.1:10031" > [2009/08/21-15:22:08 - 15681] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2009/08/21-15:22:08 - 15681] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2009/08/21-15:22:08 - 15681] [TRACKING] ERROR: Failed to select > session tracking info: awitpt::db::dblayer::DBSelect(127): Error > executing select: You have an error in your SQL syntax; check the > manual that corresponds to your MySQL server version for the right > syntax to use near '""session_tracking > %09%09%09%09WHERE > %09%09%09%09%09Instance = '3ee9.4a8ee5ce.0'' at line 13 > [2009/08/21-15:22:08 - 15681] [CBPOLICYD:15681] DEBUG: Error getting > session data > [2009/08/21-15:22:08 - 15682] [CORE] INFO: 2009/08/21-15:22:08 CONNECT > TCP Peer: "127.0.0.1:60638" Local: "127.0.0.1:10031" > [2009/08/21-15:22:08 - 15682] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2009/08/21-15:22:08 - 15682] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2009/08/21-15:22:08 - 15682] [TRACKING] ERROR: Failed to select > session tracking info: awitpt::db::dblayer::DBSelect(127): Error > executing select: You have an error in your SQL syntax; check the > manual that corresponds to your MySQL server version for the right > syntax to use near '""session_tracking > %09%09%09%09WHERE > %09%09%09%09%09Instance = '3f17.4a8ee5d0.0'' at line 13 > [2009/08/21-15:22:08 - 15682] [CBPOLICYD:15682] DEBUG: Error getting > session data > [2009/08/21-15:22:08 - 15679] [CORE] INFO: 2009/08/21-15:22:08 CONNECT > TCP Peer: "127.0.0.1:60639" Local: "127.0.0.1:10031" > [2009/08/21-15:22:08 - 15679] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2009/08/21-15:22:08 - 15679] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2009/08/21-15:22:08 - 15679] [TRACKING] ERROR: Failed to select > session tracking info: awitpt::db::dblayer::DBSelect(127): Error > executing select: You have an error in your SQL syntax; check the > manual that corresponds to your MySQL server version for the right > syntax to use near '""session_tracking > > > []'s > Helio > > > Pablo Picasso - "Computers are useless. They can only give you > answers." - http://www.brainyquote.com/quotes/authors/p/pablo_picasso.html > > > >> Can you run policyd in full debug mode? >> log_detail=modules,tracking,policies,protocols >> >> That will output what its getting from postfix. Make very very sure you >> do not mix trunk files from both versions. >> This is the debug I get when enabling the above in a clean checkout... % ./cbpolicyd -c cluebringer.conf.devel --fg --debug [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: Policyd v2 / Cluebringer - v2.1.0a [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: Initializing system modules. [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: System modules initialized. [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: Module load started... [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Amavis: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => AccessControl: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => CheckHelo: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => CheckSPF: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Greylisting: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Quotas: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Accounting: enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Protocol(Postfix): enabled [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: => Protocol(Milter): enabled [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: Module load done. [2009/08/22-06:45:35 - 19744] [CBPOLICYD] NOTICE: Session tracking is ENABLED. [2009/08/22-06:45:35 - 19744] [CBPOLICYD] DEBUG: Opening syslog, destination = 'unix', facility = 'mail'. [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: 2009/08/22-06:45:35 cbp (type Net::Server::PreFork) starting! pid(19744) [2009/08/22-06:45:35 - 19744] [CORE] NOTICE: Binding to TCP port 10031 on host 127.0.0.1 [2009/08/22-06:45:35 - 19744] [CORE] WARNING: Group Not Defined. Defaulting to EGID '0 11 10 6 4 3 2 1 0' [2009/08/22-06:45:35 - 19744] [CORE] WARNING: User Not Defined. Defaulting to EUID '0' [2009/08/22-06:45:35 - 19744] [CORE] INFO: Setting up serialization via flock [2009/08/22-06:45:35 - 19744] [CORE] INFO: Beginning prefork (4 processes) [2009/08/22-06:45:35 - 19744] [CORE] INFO: Starting "4" children [2009/08/22-06:45:35 - 19746] [CORE] DEBUG: Child Preforked (19746) [2009/08/22-06:45:35 - 19746] [CBPOLICYD] DEBUG: Starting up caching engine [2009/08/22-06:45:35 - 19747] [CORE] DEBUG: Child Preforked (19747) [2009/08/22-06:45:35 - 19747] [CBPOLICYD] DEBUG: Starting up caching engine [2009/08/22-06:45:35 - 19748] [CORE] DEBUG: Child Preforked (19748) [2009/08/22-06:45:35 - 19748] [CBPOLICYD] DEBUG: Starting up caching engine [2009/08/22-06:45:35 - 19744] [CORE] DEBUG: Parent ready for children. [2009/08/22-06:45:35 - 19749] [CORE] DEBUG: Child Preforked (19749) [2009/08/22-06:45:35 - 19749] [CBPOLICYD] DEBUG: Starting up caching engine [2009/08/22-06:45:44 - 19747] [CORE] INFO: 2009/08/22-06:45:44 CONNECT TCP Peer: "10.254.254.17:37858" Local: "127.0.0.1:1003 1" [2009/08/22-06:45:44 - 19747] [PROTOCOLS/Postfix] DEBUG: Possible Postfix protocol [2009/08/22-06:45:44 - 19747] [PROTOCOLS/Postfix] INFO: Identified Postfix protocol [2009/08/22-06:45:44 - 19744] [CORE] INFO: Starting "1" children [2009/08/22-06:45:44 - 19755] [CORE] DEBUG: Child Preforked (19755) [2009/08/22-06:45:44 - 19747] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = { 'ccert_fingerprint' => '', 'sasl_method' => '', 'sasl_sender' => '', 'size' => '0', '_timestamp' => 1250923544, 'helo_name' => 'its.me', 'reverse_client_name' => 'policyd-devel', 'queue_id' => '', 'encryption_cipher' => '', 'encryption_protocol' => '', 'etrn_domain' => '', 'ccert_subject' => '', 'request' => 'smtpd_access_policy', 'protocol_state' => 'RCPT', 'stress' => '', '_peer_address' => '10.254.254.17', 'recipient' => '[email protected]', 'sasl_username' => '', 'instance' => '4d0a.4a8f9416.44039.0', 'protocol_name' => 'SMTP', 'encryption_keysize' => '0', 'recipient_count' => '0', 'ccert_issuer' => '', 'sender' => '[email protected]', 'client_name' => 'policyd-devel', 'client_address' => '10.254.254.17', '_protocol_transport' => 'Postfix' }; [2009/08/22-06:45:44 - 19755] [CBPOLICYD] DEBUG: Starting up caching engine [2009/08/22-06:45:44 - 19747] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = { 'ccert_fingerprint' => '', 'sasl_method' => '', 'sasl_sender' => '', 'size' => '0', '_timestamp' => 1250923544, 'helo_name' => 'its.me', 'reverse_client_name' => 'policyd-devel', 'queue_id' => '', 'encryption_cipher' => '', 'encryption_protocol' => '', 'etrn_domain' => '', 'ccert_subject' => '', 'request' => 'smtpd_access_policy', 'protocol_state' => 'RCPT', 'stress' => '', '_peer_address' => '10.254.254.17', 'recipient' => '[email protected]', 'sasl_username' => '', 'instance' => '4d0a.4a8f9416.44039.0', 'protocol_name' => 'SMTP', 'encryption_keysize' => '0', 'recipient_count' => '0', 'ccert_issuer' => '', 'sender' => '[email protected]', 'client_name' => 'policyd-devel', 'client_address' => '10.254.254.17', '_protocol_transport' => 'Postfix' }; [2009/08/22-06:45:44 - 19747] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy... [2009/08/22-06:45:44 - 19747] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = { 'Recipient' => '[email protected]', 'SASLUsername' => '', 'QueueID' => '', 'RecipientData' => '', 'Instance' => '4d0a.4a8f9416.44039.0', 'EncryptionCipher' => '', 'Size' => '0', 'EncryptionKeySize' => '0', 'PeerAddress' => '10.254.254.17', 'EncryptionProtocol' => '', 'Helo' => 'its.me', 'ClientAddress' => '10.254.254.17', 'ClientName' => 'policyd-devel', 'Sender' => '[email protected]', 'SASLSender' => '', 'Protocol' => 'SMTP', 'ClientReverseName' => 'policyd-devel', 'SASLMethod' => '' }; [2009/08/22-06:45:44 - 19747] [POLICIES] DEBUG: Found policy member with ID '5' in policy 'Test' [2009/08/22-06:45:44 - 19747] [POLICIES] DEBUG: [ID:5/Name:Test]: Source not defined or 'any', explicit match: matched=1 [2009/08/22-06:45:44 - 19747] [POLICIES] INFO: [ID:5/Name:Test]: Source matching result: matched=1 [2009/08/22-06:45:44 - 19747] [POLICIES] DEBUG: [ID:5/Name:Test]: Destination not defined or 'any', explicit match: matched=1 [2009/08/22-06:45:44 - 19747] [POLICIES] INFO: [ID:5/Name:Test]: Destination matching result: matched=1 [2009/08/22-06:45:44 - 19747] [POLICIES] DEBUG: END RESULT: prio=50 => policy ids: 5 [2009/08/22-06:45:44 - 19747] [TRACKING] DEBUG: Policy resolved into: $VAR1 = { '50' => [ '5' ] }; [2009/08/22-06:45:44 - 19747] [TRACKING] DEBUG: Request translated into session data: $VAR1 = { 'Recipient' => '[email protected]', 'SASLUsername' => '', 'QueueID' => '', 'RecipientData' => '', 'Instance' => '4d0a.4a8f9416.44039.0', 'EncryptionCipher' => '', 'Size' => '0', 'EncryptionKeySize' => '0', 'UnixTimestamp' => 1250923544, 'ParsedClientAddress' => { 'Broadcast_Long' => 184483345, 'Network' => '10.254.254.17', 'IP_Long' => 184483345, 'Broadcast' => '10.254.254.17', 'IP' => '10.254.254.17', 'Mask_Long' => 4294967295, 'Network_Long' => 184483345 }, 'ProtocolTransport' => 'Postfix', 'PeerAddress' => '10.254.254.17', 'EncryptionProtocol' => '', 'Helo' => 'its.me', 'ClientAddress' => '10.254.254.17', 'ClientName' => 'policyd-devel', 'Sender' => '[email protected]', 'SASLSender' => '', 'ProtocolState' => 'RCPT', 'Policy' => { '50' => [ '5' ] }, 'Protocol' => 'SMTP', 'ClientReverseName' => 'policyd-devel', 'SASLMethod' => '' }; [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Got request, running modules... [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: Access Control Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: Quotas Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Running module: Accounting Plugin [2009/08/22-06:45:44 - 19747] [CBPOLICYD] DEBUG: Done with modules [2009/08/22-06:45:51 - 19746] [CORE] INFO: 2009/08/22-06:45:51 CONNECT TCP Peer: "10.254.254.17:37859" Local: "127.0.0.1:1003 1" [2009/08/22-06:45:51 - 19746] [PROTOCOLS/Postfix] DEBUG: Possible Postfix protocol [2009/08/22-06:45:51 - 19746] [PROTOCOLS/Postfix] INFO: Identified Postfix protocol [2009/08/22-06:45:51 - 19746] [TRACKING] DEBUG: Protocol state is 'END-OF-MESSAGE', decoding policy... [2009/08/22-06:45:51 - 19746] [TRACKING] DEBUG: Decoded into: $VAR1 = { '[email protected]' => { '50' => [ '5' ] } }; [2009/08/22-06:45:51 - 19746] [TRACKING] DEBUG: Request translated into session data: $VAR1 = { 'SASLUsername' => '', 'QueueID' => '08CAD2010118', 'RecipientData' => '/<[email protected]>#50=5;', 'EncryptionCipher' => '', 'Instance' => '4d0a.4a8f9416.44039.0', 'Size' => '7', 'EncryptionKeySize' => '0', 'UnixTimestamp' => 1250923551, 'ParsedClientAddress' => { 'Broadcast_Long' => 184483345, 'Network' => '10.254.254.17', 'IP_Long' => 184483345, 'Broadcast' => '10.254.254.17', 'IP' => '10.254.254.17', 'Mask_Long' => 4294967295, 'Network_Long' => 184483345 }, 'ProtocolTransport' => 'Postfix', 'PeerAddress' => '10.254.254.17', 'EncryptionProtocol' => '', 'Helo' => 'its.me', 'ClientAddress' => '10.254.254.17', 'ClientName' => 'policyd-devel', 'Sender' => '[email protected]', 'SASLSender' => '', 'ProtocolState' => 'END-OF-MESSAGE', '_Recipient_To_Policy' => { '[email protected]' => { '50' => [ '5' ] } }, 'Protocol' => 'SMTP', 'ClientReverseName' => 'policyd-devel', 'SASLMethod' => '' }; [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Got request, running modules... [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: Access Control Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: Quotas Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Running module: Accounting Plugin [2009/08/22-06:45:51 - 19746] [CBPOLICYD] DEBUG: Done with modules
Here is the mail I sent and how... % telnet localhost 25 Trying 10.254.254.17... Connected to localhost. Escape character is '^]'. 220 localhost.localdomain ESMTP helo its.me 250 localhost.localdomain mail from: <[email protected]> 250 2.1.0 Ok rcpt to: <[email protected]> 250 2.1.5 Ok data 354 End data with <CR><LF>.<CR><LF> test1 . 250 2.0.0 Ok: queued as 08CAD2010118 quit 221 2.0.0 Bye Connection closed by foreign host. Can you try a clean installation? -N _______________________________________________ Users mailing list [email protected] http://lists.policyd.org/mailman/listinfo/users
