On 12/12/2014 11:43 AM, Sebastian Fohler wrote:
> On 26.11.2014 17:55, Nigel Kukard via Users wrote:
>> 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
>>
>
> Is there some howto or documentation, explaining how to define those
> policies. It seems I can't get them to match at all.
>
> Any help would be great.
http://wiki.policyd.org
-N
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
