On 11/25/2014 02:35 PM, Sebastian Fohler wrote:
> Ok, something seems to be happening after I realligned the order of
> the recipient_check_restrictions. But still I can't see any amavis
> rules or processings in the debug log. I've even reassigned the amavis
> configuration to another policy just to be sure it's one of them which
> are listed. Can you please check that out?
> Thank you.
>
> This is what I get after that change:
>
>
>
> [2014/11/25-14:50:41 - 1342] [CORE] INFO: Starting "1" children
> [2014/11/25-14:50:41 - 2205] [CORE] DEBUG: Child Preforked (2205)
> [2014/11/25-14:50:41 - 2205] [CBPOLICYD] DEBUG: Starting up
> caching engine
> [2014/11/25-14:50:41 - 1352] [CORE] INFO: 2014/11/25-14:50:41
> CONNECT TCP Peer: "127.0.0.1:47384" Local: "127.0.0.1:10031"
> [2014/11/25-14:50:41 - 1352] [PROTOCOLS/Postfix] DEBUG: Possible
> Postfix protocol
> [2014/11/25-14:50:41 - 1352] [PROTOCOLS/Postfix] INFO: Identified
> Postfix protocol
> [2014/11/25-14:50:42 - 1352] [TRACKING] DEBUG: No session tracking
> data exists for request: $VAR1 = {
> 'ccert_fingerprint' => '',
> 'sasl_method' => '',
> 'sasl_sender' => '',
> 'size' => 0,
> '_timestamp' => 1416923441,
> 'helo_name' => 'duda',
> 'reverse_client_name' => 'unknown',
> 'queue_id' => '',
> 'encryption_cipher' => '',
> 'encryption_protocol' => '',
> 'etrn_domain' => '',
> 'ccert_subject' => '',
> 'request' => 'smtpd_access_policy',
> 'protocol_state' => 'RCPT',
> 'stress' => '',
> '_peer_address' => '127.0.0.1',
> 'recipient' => '[email protected]',
> 'sasl_username' => '',
> 'instance' => '89b.54748930.cd277.0',
> 'protocol_name' => 'ESMTP',
> 'encryption_keysize' => '0',
> 'recipient_count' => '0',
> 'ccert_issuer' => '',
> 'sender' => '[email protected]',
> 'client_name' => 'unknown',
> 'client_address' => '10.32.2.152',
> '_protocol_transport' => 'Postfix'
> };
> [2014/11/25-14:50:42 - 1352] [TRACKING] DEBUG: Added session
> tracking information for: $VAR1 = {
> 'ccert_fingerprint' => '',
> 'sasl_method' => '',
> 'sasl_sender' => '',
> 'size' => 0,
> '_timestamp' => 1416923441,
> 'helo_name' => 'duda',
> 'reverse_client_name' => 'unknown',
> 'queue_id' => '',
> 'encryption_cipher' => '',
> 'encryption_protocol' => '',
> 'etrn_domain' => '',
> 'ccert_subject' => '',
> 'request' => 'smtpd_access_policy',
> 'protocol_state' => 'RCPT',
> 'stress' => '',
> '_peer_address' => '127.0.0.1',
> 'recipient' => '[email protected]',
> 'sasl_username' => '',
> 'instance' => '89b.54748930.cd277.0',
> 'protocol_name' => 'ESMTP',
> 'encryption_keysize' => '0',
> 'recipient_count' => '0',
> 'ccert_issuer' => '',
> 'sender' => '[email protected]',
> 'client_name' => 'unknown',
> 'client_address' => '10.32.2.152',
> '_protocol_transport' => 'Postfix'
> };
> [2014/11/25-14:50:42 - 1352] [TRACKING] DEBUG: Protocol state is
> 'RCPT', resolving policy...
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: Going to resolve
> session data into policy: $VAR1 = {
> 'Recipient' => '[email protected]',
> 'SASLUsername' => '',
> 'QueueID' => '',
> 'RecipientData' => '',
> 'Instance' => '89b.54748930.cd277.0',
> 'EncryptionCipher' => '',
> 'Size' => '0',
> 'EncryptionKeySize' => '0',
> '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' ),
> 'Protocol' => 'ESMTP',
> 'ClientReverseName' => 'unknown',
> 'SASLMethod' => ''
> };
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: Found policy member
> with ID '2' in policy 'Default Outbound'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: Found policy member
> with ID '3' in policy 'Default Inbound'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: Found policy member
> with ID '4' in policy 'Default Internal'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: Found policy member
> with ID '5' in policy 'Test'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]: Main policy sources '%internal_ips,%internal_domains'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a
> IP/CIDR specification, match = 1
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]=>(group:internal_ips): Source group result: matched=1
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]: Group 'internal_domains' has 1 source(s) => @domain.de
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]=>(group:internal_domains): - Resolved source '@domain.de' to
> a email address specification, match = 0
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:2/Name:Default
> Outbound]=>(group:internal_domains): Source group result: matched=0
> * [2014/11/25-14:50:42 - 1352] [POLICIES] INFO: [ID:2/Name:Default
> Outbound]: Source matching result: matched=0 *
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:3/Name:Default
> Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:3/Name:Default
> Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:3/Name:Default
> Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a
> IP/CIDR specification, match = 1
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:3/Name:Default
> Inbound]=>(group:internal_ips): Source group result: matched=1
> * [2014/11/25-14:50:42 - 1352] [POLICIES] INFO: [ID:3/Name:Default
> Inbound]: Source matching result: matched=0 *
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]: Main policy sources '%internal_ips,%internal_domains'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a
> IP/CIDR specification, match = 1
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]=>(group:internal_ips): Source group result: matched=1
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]: Group 'internal_domains' has 1 source(s) => @domain.de
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]=>(group:internal_domains): - Resolved source '@domain.de' to
> a email address specification, match = 0
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:4/Name:Default
> Internal]=>(group:internal_domains): Source group result: matched=0
> * [2014/11/25-14:50:42 - 1352] [POLICIES] INFO: [ID:4/Name:Default
> Internal]: Source matching result: matched=0 *
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:5/Name:Test]:
> Main policy sources '@example.net'
> [2014/11/25-14:50:42 - 1352] [POLICIES] DEBUG: [ID:5/Name:Test]: -
> Resolved source '@example.net' to a email address specification, match
> = 0
> * [2014/11/25-14:50:42 - 1352] [POLICIES] INFO: [ID:5/Name:Test]:
> Source matching result: matched=0 *
> [2014/11/25-14:50:42 - 1352] [TRACKING] DEBUG: Policy resolved
> into: $VAR1 = {};
> [2014/11/25-14:50:42 - 1352] [TRACKING] DEBUG: Request translated
> into session data: $VAR1 = {
> 'Recipient' => '[email protected]',
> 'SASLUsername' => '',
> 'QueueID' => '',
> 'RecipientData' => '',
> 'Instance' => '89b.54748930.cd277.0',
> 'EncryptionCipher' => '',
> 'Size' => '0',
> 'EncryptionKeySize' => '0',
> 'UnixTimestamp' => 1416923441,
> '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,
> 'ip_bin' =>
> '00001010001000000000001010011000',
> 'cidr' => 32
> }, 'awitpt::netip' ),
> 'ProtocolState' => 'RCPT',
> 'Policy' => {},
> 'Protocol' => 'ESMTP',
> 'ClientReverseName' => 'unknown',
> 'SASLMethod' => ''
> };
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] INFO: Got request #1
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> Access Control Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module 'Access
> Control Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> HELO/EHLO Check Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module 'HELO/EHLO
> Check Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> SPF Check Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module 'SPF Check
> Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> Greylisting Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module
> 'Greylisting Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> Quotas Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module 'Quotas
> Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Running module:
> Accounting Plugin
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Module 'Accounting
> Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:42 - 1352] [CBPOLICYD] DEBUG: Done with modules
> [2014/11/25-14:50:43 - 1352] [PROTOCOLS/Postfix] DEBUG: Possible
> Postfix protocol
> [2014/11/25-14:50:43 - 1352] [PROTOCOLS/Postfix] INFO: Identified
> Postfix protocol
> [2014/11/25-14:50:43 - 1352] [TRACKING] DEBUG: Protocol state is
> 'END-OF-MESSAGE', decoding policy...
> [2014/11/25-14:50:43 - 1352] [TRACKING] DEBUG: Decoded into: $VAR1
> = {};
> [2014/11/25-14:50:43 - 1352] [TRACKING] DEBUG: Request translated
> into session data: $VAR1 = {
> 'SASLUsername' => '',
> 'QueueID' => '4480D20937',
> 'RecipientData' => '/<[email protected]>#',
> 'EncryptionCipher' => '',
> 'Instance' => '89b.54748930.cd277.0',
> 'Size' => '3',
> 'EncryptionKeySize' => '0',
> 'UnixTimestamp' => 1416923443,
> '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',
> '_Recipient_To_Policy' => {},
> 'Protocol' => 'ESMTP',
> 'ClientReverseName' => 'unknown',
> 'SASLMethod' => ''
> };
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] INFO: Got request #2
> (pipelined)
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> Access Control Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module 'Access
> Control Plugin' returned CBP_SKIP
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> HELO/EHLO Check Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module 'HELO/EHLO
> Check Plugin' returned CBP_SKIP
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> SPF Check Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module 'SPF Check
> Plugin' returned CBP_SKIP
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> Greylisting Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module
> 'Greylisting Plugin' returned CBP_SKIP
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> Quotas Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module 'Quotas
> Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Running module:
> Accounting Plugin
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Module 'Accounting
> Plugin' returned CBP_CONTINUE
> [2014/11/25-14:50:43 - 1352] [CBPOLICYD] DEBUG: Done with modules
> [2014/11/25-14:52:25 - 1352] [CBPOLICYD] WARNING: Client closed
> connection => Peer: 127.0.0.1:47384, Local: 127.0.0.1:10031
> [2014/11/25-14:52:25 - 1342] [CORE] INFO: Killing "1" children
> [2014/11/25-14:52:25 - 1355] [CBPOLICYD] DEBUG: Caching engine:
> hits = 8, misses = 0
> [2014/11/25-14:52:25 - 1355] [CBPOLICYD] DEBUG: Shutting down
> caching engine (1355)
>
>
>
> On 20.11.2014 15:10, Nigel Kukard wrote:
>> On 11/20/2014 10:54 AM, Sebastian Fohler wrote:
>>> On 19.11.2014 08:11, Nigel Kukard wrote:
>>>> On 18.11.2014 15:40, Nigel Kukard wrote:
>>>>>> Remove the default policies and add yourself a policy to match the
>>>>>> mail
>>>>>> you wish to adjust the Amavis a parameters on.
>>>>>>
>>>>>> 1. Look that the policy match phase is being logged
>>>>>> 2. Look that the module is being run
>>>>>> 3. Check amavis logs
>>>>>> 4. Check postfix logs
>>>>>> 5...
>>>>>> 6. PROFIT
>>>>>>
>>>>>> :)
>>>> Please do not top post.
>>>>
>>>> Its not possible you don't see policy resolutions if policyd is
>>>> getting
>>>> requests. Best to double check your configuration.
>>>>
>>>> -N
>>>>
>>>>
>>>
>>> Ok, I guess we agree that policyd seems to get requests, the debug log
>>> shows traffic on policyd so that should be the case. Could you take a
>>> look at the cluebringer.conf I've posted before and check if there is
>>> some missconfiguration you might notice?
>>> I couldn't find anything wrong but maybe I don't unterstand some of
>>> those options correctly.
>>
>> Your check policy service is quite far down on the check list, you do
>> know if any item before it passes the mail in postfix, that no policy
>> request will be made in the RCPT stage? For instance nothing in your
>> my_networks is going to hit policyd.
>>
>> The only thing in your logs is the END-OF-MESSAGE stage.
I kindly request again, please do not top post. I do not have time to go
to the bottom of the mail to find out what the flow of discussion is
then back to the top to try find out what is going on now.
As indicated above in bold, none of your policies are matching.
-N
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
