On 01/28/11 06:57, Masim "Vavai" Sugianto wrote: > Hi Nigel, > > On Fri, Jan 28, 2011 at 1:31 PM, Nigel Kukard <[email protected]> wrote: >>> On Fri, Jan 28, 2011 at 12:50 PM, Nigel Kukard <[email protected]> wrote: >>>> Try enabling full debugging, you'll then see what policy checks are >>>> being done and if they matching ... this will more than likely help >>>> pinpoint where the problem lies. > Below is my log, sending internal email from trusted network , please advise : > > tail -f /opt/zimbra/log/cbpolicyd.log > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: Process Backgrounded > [2011/01/28-13:50:01 - 11159] [CBPOLICYD] NOTICE: Policyd v2 / > Cluebringer - v2.0.10 > [2011/01/28-13:50:01 - 11159] [CBPOLICYD] NOTICE: Initializing system modules. > [2011/01/28-13:50:01 - 11159] [CBPOLICYD] NOTICE: System modules initialized. > [2011/01/28-13:50:01 - 11159] [CBPOLICYD] NOTICE: Module load started... > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: => Quotas: enabled > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: => Protocol(Postfix): enabled > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: => Protocol(Bizanga): enabled > [2011/01/28-13:50:01 - 11159] [CBPOLICYD] NOTICE: Module load done. > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: 2011/01/28-13:50:01 cbp > (type Net::Server::PreFork) starting! pid(11159) > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: Using default listen value of 128 > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: Binding to TCP port 10031 > on host 127.0.0.1 > [2011/01/28-13:50:01 - 11159] [CORE] NOTICE: Setting gid to "1000 1000" > [2011/01/28-13:50:01 - 11159] [CORE] INFO: Setting up serialization via flock > [2011/01/28-13:50:01 - 11159] [CORE] INFO: Beginning prefork (4 processes) > [2011/01/28-13:50:01 - 11159] [CORE] INFO: Starting "4" children > [2011/01/28-13:50:01 - 11938] [CORE] DEBUG: Child Preforked (11938) > [2011/01/28-13:50:01 - 11938] [CBPOLICYD] DEBUG: Starting up caching engine > [2011/01/28-13:50:01 - 11939] [CORE] DEBUG: Child Preforked (11939) > [2011/01/28-13:50:01 - 11939] [CBPOLICYD] DEBUG: Starting up caching engine > [2011/01/28-13:50:01 - 11159] [CORE] DEBUG: Parent ready for children. > [2011/01/28-13:50:01 - 11940] [CORE] DEBUG: Child Preforked (11940) > [2011/01/28-13:50:01 - 11941] [CORE] DEBUG: Child Preforked (11941) > [2011/01/28-13:50:01 - 11940] [CBPOLICYD] DEBUG: Starting up caching engine > [2011/01/28-13:50:01 - 11941] [CBPOLICYD] DEBUG: Starting up caching engine > [2011/01/28-13:50:24 - 11159] [CORE] INFO: Starting "1" children > [2011/01/28-13:50:24 - 11941] [CORE] INFO: 2011/01/28-13:50:24 CONNECT > TCP Peer: "127.0.0.1:34144" Local: "127.0.0.1:10031" > [2011/01/28-13:50:24 - 11941] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2011/01/28-13:50:24 - 11941] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2011/01/28-13:50:24 - 13701] [CORE] DEBUG: Child Preforked (13701) > [2011/01/28-13:50:24 - 13701] [CBPOLICYD] DEBUG: Starting up caching engine > [2011/01/28-13:50:24 - 11941] [TRACKING] DEBUG: No session tracking > data exists for request: $VAR1 = { > 'ccert_fingerprint' => '', > 'sasl_method' => '', > 'sasl_sender' => '', > 'size' => '403', > '_timestamp' => 1296197424, > 'helo_name' => 'vavai.vavai.com', > 'reverse_client_name' => > '136.static.111-96-29.astinet.telkom.net.id', > 'queue_id' => 'AEF4BDB0301', > 'encryption_cipher' => '', > 'encryption_protocol' => '', > 'etrn_domain' => '', > 'ccert_subject' => '', > 'request' => 'smtpd_access_policy', > 'protocol_state' => 'END-OF-MESSAGE', > 'stress' => '', > 'recipient' => '[email protected]', > 'sasl_username' => '', > 'instance' => '357d.4d426730.a1056.0', > 'protocol_name' => 'ESMTP', > 'encryption_keysize' => '0', > 'recipient_count' => '1', > 'ccert_issuer' => '', > 'sender' => '[email protected]', > 'client_name' => 'unknown', > 'client_address' => '111.96.29.136', > '_protocol_transport' => 'Postfix' > }; > [2011/01/28-13:50:24 - 11941] [TRACKING] DEBUG: Protocol state is > 'END-OF-MESSAGE', decoding policy... > [2011/01/28-13:50:24 - 11941] [TRACKING] DEBUG: Decoded into: $VAR1 = {}; > [2011/01/28-13:50:24 - 11941] [TRACKING] DEBUG: Request translated > into session data: $VAR1 = { > 'SASLUsername' => '', > 'QueueID' => 'AEF4BDB0301', > 'RecipientData' => '', > 'Instance' => '357d.4d426730.a1056.0', > 'EncryptionCipher' => '', > 'Size' => '403', > 'EncryptionKeySize' => '0', > 'ParsedClientAddress' => { > 'Broadcast_Long' => 1986010504, > 'Network' => '111.96.29.136', > 'IP_Long' => 1986010504, > 'Broadcast' => '111.96.29.136', > 'IP' => '111.96.29.136', > 'Mask_Long' => 4294967295, > 'Network_Long' => 1986010504 > }, > 'ProtocolTransport' => 'Postfix', > 'EncryptionProtocol' => '', > 'Helo' => 'vavai.vavai.com', > 'ClientAddress' => '111.96.29.136', > 'ClientName' => 'unknown', > 'Sender' => '[email protected]', > 'SASLSender' => '', > 'Timestamp' => 1296197424, > 'ProtocolState' => 'END-OF-MESSAGE', > '_Recipient_To_Policy' => {}, > 'Protocol' => 'ESMTP', > 'ClientReverseName' => '136.static.111-96-29.astinet.telkom.net.id', > 'SASLMethod' => '' > }; > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Got request, running > modules... > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Running module: > Access Control Plugin > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Running module: > HELO/EHLO Check Plugin > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Running module: SPF > Check Plugin > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Running module: > Greylisting Plugin > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Running module: Quotas Plugin > [2011/01/28-13:50:24 - 11941] [CBPOLICYD] DEBUG: Done with modules > [2011/01/28-13:50:26 - 11939] [CORE] INFO: 2011/01/28-13:50:26 CONNECT > TCP Peer: "127.0.0.1:34151" Local: "127.0.0.1:10031" > [2011/01/28-13:50:26 - 11939] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2011/01/28-13:50:26 - 11939] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2011/01/28-13:50:26 - 11939] [TRACKING] DEBUG: No session tracking > data exists for request: $VAR1 = { > 'ccert_fingerprint' => '', > 'sasl_method' => '', > 'sasl_sender' => '', > 'size' => '1159', > '_timestamp' => 1296197426, > 'helo_name' => 'localhost', > 'reverse_client_name' => 'localhost', > 'queue_id' => '0B1C0DB0306', > 'encryption_cipher' => '', > 'encryption_protocol' => '', > 'etrn_domain' => '', > 'ccert_subject' => '', > 'request' => 'smtpd_access_policy', > 'protocol_state' => 'END-OF-MESSAGE', > 'stress' => '', > 'recipient' => '[email protected]', > 'sasl_username' => '', > 'instance' => '358a.4d426732.af75.0', > 'protocol_name' => 'ESMTP', > 'encryption_keysize' => '0', > 'recipient_count' => '1', > 'ccert_issuer' => '', > 'sender' => '[email protected]', > 'client_name' => 'localhost', > 'client_address' => '127.0.0.1', > '_protocol_transport' => 'Postfix' > }; > [2011/01/28-13:50:26 - 11939] [TRACKING] DEBUG: Protocol state is > 'END-OF-MESSAGE', decoding policy... > [2011/01/28-13:50:26 - 11939] [TRACKING] DEBUG: Decoded into: $VAR1 = {}; > [2011/01/28-13:50:26 - 11939] [TRACKING] DEBUG: Request translated > into session data: $VAR1 = { > 'SASLUsername' => '', > 'QueueID' => '0B1C0DB0306', > 'RecipientData' => '', > 'Instance' => '358a.4d426732.af75.0', > 'EncryptionCipher' => '', > 'Size' => '1159', > 'EncryptionKeySize' => '0', > 'ParsedClientAddress' => { > 'Broadcast_Long' => 2130706433, > 'Network' => '127.0.0.1', > 'IP_Long' => 2130706433, > 'Broadcast' => '127.0.0.1', > 'IP' => '127.0.0.1', > 'Mask_Long' => 4294967295, > 'Network_Long' => 2130706433 > }, > 'ProtocolTransport' => 'Postfix', > 'EncryptionProtocol' => '', > 'Helo' => 'localhost', > 'ClientAddress' => '127.0.0.1', > 'ClientName' => 'localhost', > 'Sender' => '[email protected]', > 'SASLSender' => '', > 'Timestamp' => 1296197426, > 'ProtocolState' => 'END-OF-MESSAGE', > '_Recipient_To_Policy' => {}, > 'Protocol' => 'ESMTP', > 'ClientReverseName' => 'localhost', > 'SASLMethod' => '' > }; > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Got request, running > modules... > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Running module: > Access Control Plugin > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Running module: > HELO/EHLO Check Plugin > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Running module: SPF > Check Plugin > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Running module: > Greylisting Plugin > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Running module: Quotas Plugin > [2011/01/28-13:50:26 - 11939] [CBPOLICYD] DEBUG: Done with modules > [2011/01/28-13:50:44 - 11941] [CORE] INFO: 2011/01/28-13:50:44 CONNECT > TCP Peer: "127.0.0.1:34164" Local: "127.0.0.1:10031" > [2011/01/28-13:50:44 - 11941] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2011/01/28-13:50:44 - 11941] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2011/01/28-13:50:44 - 11941] [TRACKING] DEBUG: No session tracking > data exists for request: $VAR1 = { > 'ccert_fingerprint' => '', > 'sasl_method' => '', > 'sasl_sender' => '', > 'size' => '403', > '_timestamp' => 1296197444, > 'helo_name' => 'vavai.vavai.com', > 'reverse_client_name' => > '136.static.111-96-29.astinet.telkom.net.id', > 'queue_id' => '44CCADB0301', > 'encryption_cipher' => '', > 'encryption_protocol' => '', > 'etrn_domain' => '', > 'ccert_subject' => '', > 'request' => 'smtpd_access_policy', > 'protocol_state' => 'END-OF-MESSAGE', > 'stress' => '', > 'recipient' => '[email protected]', > 'sasl_username' => '', > 'instance' => '357d.4d426744.39cbe.0', > 'protocol_name' => 'ESMTP', > 'encryption_keysize' => '0', > 'recipient_count' => '1', > 'ccert_issuer' => '', > 'sender' => '[email protected]', > 'client_name' => 'unknown', > 'client_address' => '111.96.29.136', > '_protocol_transport' => 'Postfix' > }; > [2011/01/28-13:50:44 - 11941] [TRACKING] DEBUG: Protocol state is > 'END-OF-MESSAGE', decoding policy... > [2011/01/28-13:50:44 - 11941] [TRACKING] DEBUG: Decoded into: $VAR1 = {}; > [2011/01/28-13:50:44 - 11941] [TRACKING] DEBUG: Request translated > into session data: $VAR1 = { > 'SASLUsername' => '', > 'QueueID' => '44CCADB0301', > 'RecipientData' => '', > 'Instance' => '357d.4d426744.39cbe.0', > 'EncryptionCipher' => '', > 'Size' => '403', > 'EncryptionKeySize' => '0', > 'ParsedClientAddress' => { > 'Broadcast_Long' => 1986010504, > 'Network' => '111.96.29.136', > 'IP_Long' => 1986010504, > 'Broadcast' => '111.96.29.136', > 'IP' => '111.96.29.136', > 'Mask_Long' => 4294967295, > 'Network_Long' => 1986010504 > }, > 'ProtocolTransport' => 'Postfix', > 'EncryptionProtocol' => '', > 'Helo' => 'vavai.vavai.com', > 'ClientAddress' => '111.96.29.136', > 'ClientName' => 'unknown', > 'Sender' => '[email protected]', > 'SASLSender' => '', > 'Timestamp' => 1296197444, > 'ProtocolState' => 'END-OF-MESSAGE', > '_Recipient_To_Policy' => {}, > 'Protocol' => 'ESMTP', > 'ClientReverseName' => '136.static.111-96-29.astinet.telkom.net.id', > 'SASLMethod' => '' > }; > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Got request, running > modules... > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Running module: > Access Control Plugin > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Running module: > HELO/EHLO Check Plugin > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Running module: SPF > Check Plugin > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Running module: > Greylisting Plugin > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Running module: Quotas Plugin > [2011/01/28-13:50:44 - 11941] [CBPOLICYD] DEBUG: Done with modules > [2011/01/28-13:50:45 - 11938] [CORE] INFO: 2011/01/28-13:50:45 CONNECT > TCP Peer: "127.0.0.1:34171" Local: "127.0.0.1:10031" > [2011/01/28-13:50:45 - 11938] [PROTOCOLS/Postfix] DEBUG: Possible > Postfix protocol > [2011/01/28-13:50:45 - 11938] [PROTOCOLS/Postfix] INFO: Identified > Postfix protocol > [2011/01/28-13:50:45 - 11938] [TRACKING] DEBUG: No session tracking > data exists for request: $VAR1 = { > 'ccert_fingerprint' => '', > 'sasl_method' => '', > 'sasl_sender' => '', > 'size' => '1159', > '_timestamp' => 1296197445, > 'helo_name' => 'localhost', > 'reverse_client_name' => 'localhost', > 'queue_id' => '53732DB0306', > 'encryption_cipher' => '', > 'encryption_protocol' => '', > 'etrn_domain' => '', > 'ccert_subject' => '', > 'request' => 'smtpd_access_policy', > 'protocol_state' => 'END-OF-MESSAGE', > 'stress' => '', > 'recipient' => '[email protected]', > 'sasl_username' => '', > 'instance' => '3635.4d426745.53426.0', > 'protocol_name' => 'ESMTP', > 'encryption_keysize' => '0', > 'recipient_count' => '1', > 'ccert_issuer' => '', > 'sender' => '[email protected]', > 'client_name' => 'localhost', > 'client_address' => '127.0.0.1', > '_protocol_transport' => 'Postfix' > }; > [2011/01/28-13:50:45 - 11938] [TRACKING] DEBUG: Protocol state is > 'END-OF-MESSAGE', decoding policy... > [2011/01/28-13:50:45 - 11938] [TRACKING] DEBUG: Decoded into: $VAR1 = {}; > [2011/01/28-13:50:45 - 11938] [TRACKING] DEBUG: Request translated > into session data: $VAR1 = { > 'SASLUsername' => '', > 'QueueID' => '53732DB0306', > 'RecipientData' => '', > 'Instance' => '3635.4d426745.53426.0', > 'EncryptionCipher' => '', > 'Size' => '1159', > 'EncryptionKeySize' => '0', > 'ParsedClientAddress' => { > 'Broadcast_Long' => 2130706433, > 'Network' => '127.0.0.1', > 'IP_Long' => 2130706433, > 'Broadcast' => '127.0.0.1', > 'IP' => '127.0.0.1', > 'Mask_Long' => 4294967295, > 'Network_Long' => 2130706433 > }, > 'ProtocolTransport' => 'Postfix', > 'EncryptionProtocol' => '', > 'Helo' => 'localhost', > 'ClientAddress' => '127.0.0.1', > 'ClientName' => 'localhost', > 'Sender' => '[email protected]', > 'SASLSender' => '', > 'Timestamp' => 1296197445, > 'ProtocolState' => 'END-OF-MESSAGE', > '_Recipient_To_Policy' => {}, > 'Protocol' => 'ESMTP', > 'ClientReverseName' => 'localhost', > 'SASLMethod' => '' > }; > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Got request, running > modules... > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Running module: > Access Control Plugin > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Running module: > HELO/EHLO Check Plugin > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Running module: SPF > Check Plugin > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Running module: > Greylisting Plugin > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Running module: Quotas Plugin > [2011/01/28-13:50:45 - 11938] [CBPOLICYD] DEBUG: Done with modules >
I see no policy requests for RCPT stage. -N
signature.asc
Description: OpenPGP digital signature
_______________________________________________ Users mailing list [email protected] http://lists.policyd.org/mailman/listinfo/users
