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.
-N
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
