On 11/14/2014 09:40 PM, Sebastian Fohler wrote:
> Thank you for your answer.
>
> How do I raise the debug level to full?
>
> On 14.11.2014 12:30, Nigel Kukard wrote:
>> On 11/14/2014 11:13 AM, Sebastian Fohler wrote:
>>> Can someone help me to get amavisd working with my cbpolicyd?
>>>
>>> Versions:
>>> Amavis: amavisd-new-2.9.1-2.el6.noarch.rpm CentOS / EPEL repository
>>> CBPolicyD: cluebringer-v2.1.x-201310261831.noarch.rpm
>>> Postfix: postfix-2.6.6-6.el6_5.x86_64.rpm
>>>
>>> Amavis bin patched with amavisd-2.8.1_policyd_201308131703.patch
>>>
>>>
>>>
>>> This is the debug log while starting the cbpolicyd, which shows that
>>> the amavis module is active and enabled:
>>>
>>> ################################################################################################
>>>
>>>
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: Policyd v2 /
>>> Cluebringer - v2.1.x-201310261831
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: Initializing system
>>> modules.
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: System modules
>>> initialized.
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: Module load
>>> started...
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => AccessControl:
>>> enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => Amavis: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => Accounting: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => CheckHelo: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => CheckSPF: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => Greylisting: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => Quotas: enabled
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: => Protocol(Postfix):
>>> enabled
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: Module load done.
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] NOTICE: Session tracking is
>>> ENABLED.
>>> [2014/11/14-11:26:02 - 13472] [CBPOLICYD] DEBUG: Opening syslog,
>>> destination = 'native', facility = 'mail'.
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: 2014/11/14-11:26:02 cbp
>>> (type Net::Server::PreFork) starting! pid(13472)
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: Using default listen
>>> value of 128
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: Binding to TCP port 10031
>>> on host *
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: Setting gid to "506 506"
>>> [2014/11/14-11:26:02 - 13472] [CORE] NOTICE: Setting uid to "505"
>>> [2014/11/14-11:26:02 - 13472] [CORE] INFO: Setting up serialization
>>> via flock
>>> [2014/11/14-11:26:02 - 13472] [CORE] INFO: Beginning prefork (4
>>> processes)
>>> [2014/11/14-11:26:02 - 13472] [CORE] INFO: Starting "4" children
>>> [2014/11/14-11:26:02 - 13474] [CORE] DEBUG: Child Preforked (13474)
>>> [2014/11/14-11:26:02 - 13474] [CBPOLICYD] DEBUG: Starting up caching
>>> engine
>>> [2014/11/14-11:26:02 - 13472] [CORE] DEBUG: Parent ready for children.
>>> [2014/11/14-11:26:02 - 13476] [CORE] DEBUG: Child Preforked (13476)
>>> [2014/11/14-11:26:02 - 13476] [CBPOLICYD] DEBUG: Starting up caching
>>> engine
>>> [2014/11/14-11:26:02 - 13477] [CORE] DEBUG: Child Preforked (13477)
>>> [2014/11/14-11:26:02 - 13477] [CBPOLICYD] DEBUG: Starting up caching
>>> engine
>>> [2014/11/14-11:26:02 - 13475] [CORE] DEBUG: Child Preforked (13475)
>>> [2014/11/14-11:26:02 - 13475] [CBPOLICYD] DEBUG: Starting up caching
>>> engine
>>> ##############################################################################################
>>>
>>>
>>>
>>>
>>> And this is the debug log while processing emails:
>>>
>>> ##############################################################################################
>>>
>>>
>>> [2014/11/13-13:56:52 - 18992] [PROTOCOLS/Postfix] DEBUG: Possible
>>> Postfix protocol
>>> [2014/11/13-13:56:52 - 18992] [PROTOCOLS/Postfix] INFO: Identified
>>> Postfix protocol
>>> [2014/11/13-13:56:52 - 18992] [TRACKING] DEBUG: No session tracking
>>> data exists for request: $VAR1 = {
>>> 'ccert_fingerprint' => '',
>>> 'sasl_method' => '',
>>> 'sasl_sender' => '',
>>> 'size' => 3375,
>>> '_timestamp' => 1415883412,
>>> 'helo_name' => 'duda',
>>> 'reverse_client_name' => 'unknown',
>>> 'queue_id' => '399CA208A3',
>>> 'encryption_cipher' => '',
>>> 'encryption_protocol' => '',
>>> 'etrn_domain' => '',
>>> 'ccert_subject' => '',
>>> 'request' => 'smtpd_access_policy',
>>> 'protocol_state' => 'END-OF-MESSAGE',
>>> 'stress' => '',
>>> '_peer_address' => '127.0.0.1',
>>> 'recipient' => '[email protected]',
>>> 'sasl_username' => '',
>>> 'instance' => '1bb7.5464aa91.39579.0',
>>> 'protocol_name' => 'ESMTP',
>>> 'encryption_keysize' => '0',
>>> 'recipient_count' => '1',
>>> 'ccert_issuer' => '',
>>> 'sender' => '[email protected]',
>>> 'client_name' => 'unknown',
>>> 'client_address' => '10.32.2.152',
>>> '_protocol_transport' => 'Postfix'
>>> };
>>> [2014/11/13-13:56:52 - 18992] [TRACKING] DEBUG: Protocol state is
>>> 'END-OF-MESSAGE', decoding policy...
>>> [2014/11/13-13:56:52 - 18992] [TRACKING] DEBUG: Decoded into: $VAR1 =
>>> undef;
>>> [2014/11/13-13:56:52 - 18992] [TRACKING] DEBUG: Request translated
>>> into session data: $VAR1 = {
>>> 'SASLUsername' => '',
>>> 'QueueID' => '399CA208A3',
>>> 'RecipientData' => '',
>>> 'Instance' => '1bb7.5464aa91.39579.0',
>>> 'EncryptionCipher' => '',
>>> 'Size' => '4',
>>> 'EncryptionKeySize' => '0',
>>> 'UnixTimestamp' => 1415883412,
>>> 'ProtocolTransport' => 'Postfix',
>>> 'EncryptionProtocol' => '',
>>> 'Helo' => 'duda',
>>> 'ClientAddress' => '10.32.2.152',
>>> 'ClientName' => 'unknown',
>>> 'Sender' => '[email protected]',
>>> 'SASLSender' => '',
>>> '_ClientAddress' => bless( {
>>> 'raw_ip' => '10.32.2.152',
>>> 'ip' => '10.32.2.152',
>>> 'ip_version' => 4,
>>> 'cidr' => 32
>>> }, 'awitpt::netip' ),
>>> 'ProtocolState' => 'END-OF-MESSAGE',
>>> 'Protocol' => 'ESMTP',
>>> 'ClientReverseName' => 'unknown',
>>> 'SASLMethod' => ''
>>> };
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] INFO: Got request #11
>>> (pipelined)
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module:
>>> Access Control Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'Access
>>> Control Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module:
>>> HELO/EHLO Check Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'HELO/EHLO
>>> Check Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module: SPF
>>> Check Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'SPF Check
>>> Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module:
>>> Greylisting Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'Greylisting
>>> Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module:
>>> Quotas Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'Quotas
>>> Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Running module:
>>> Accounting Plugin
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Module 'Accounting
>>> Plugin' returned CBP_SKIP
>>> [2014/11/13-13:56:52 - 18992] [CBPOLICYD] DEBUG: Done with modules
>>> [2014/11/13-13:58:34 - 18992] [CBPOLICYD] WARNING: Client closed
>>> connection => Peer: 127.0.0.1:49353, Local: 127.0.0.1:10031
>>> [2014/11/13-13:58:34 - 18699] [CORE] INFO: Killing "1" children
>>> [2014/11/13-13:58:34 - 7099] [CBPOLICYD] DEBUG: Caching engine: hits =
>>> 0, misses = 0
>>> [2014/11/13-13:58:34 - 7099] [CBPOLICYD] DEBUG: Shutting down caching
>>> engine (7099)
>>> ###############################################################################################
>>>
>>>
>>> --snip--
>> First off, I see no policy matches. Enable full debugging.
>>
>> I'd also suggest using the latest git version, just to rule out any
>> *possible* changes since the snapshot.
Check your config file for logging options, enable all of them.
-N
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
