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
--
Best Regards,
Masim "Vavai" Sugianto
/************************************************************/
Blog (ID) : http://www.vavai.com
Excellent Infotama Kreasindo : http://www.vavai.biz
Training Zimbra & Admin Linux : http://bit.ly/h53o2Q
/************************************************************/
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users
