Hi,
Thx for helping out.
For case nr 1:
[2008/07/26-22:28:21 - 22234] [CORE] INFO: 2008/07/26-22:28:21 CONNECT TCP
Peer: "127.0.0.1:45400" Local: "127.0.0.1:10031"
[2008/07/26-22:28:21 - 22234] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:28:21 - 22234] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:28:21 - 22233] [CORE] INFO: Starting "1" children
[2008/07/26-22:28:21 - 22234] [TRACKING] DEBUG: No session tracking data exists
for request: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '10971',
'_timestamp' => 1217104101,
'helo_name' => 'mail.smartnet.no',
'reverse_client_name' => 'mail.smartnet.no',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '56dd.488b88e5.c6635.0',
'protocol_name' => 'ESMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[EMAIL PROTECTED]',
'client_name' => 'mail.smartnet.no',
'client_address' => '195.18.134.10',
'_protocol_transport' => 'Postfix'
};
[2008/07/26-22:28:21 - 22242] [CORE] DEBUG: Child Preforked (22242)
[2008/07/26-22:28:21 - 22242] [CBPOLICYD] DEBUG: Starting up caching engine
[2008/07/26-22:28:21 - 22234] [TRACKING] DEBUG: Added session tracking
information for: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '10971',
'_timestamp' => 1217104101,
'helo_name' => 'mail.smartnet.no',
'reverse_client_name' => 'mail.smartnet.no',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '56dd.488b88e5.c6635.0',
'protocol_name' => 'ESMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[EMAIL PROTECTED]',
'client_name' => 'mail.smartnet.no',
'client_address' => '195.18.134.10',
'_protocol_transport' => 'Postfix'
};
[2008/07/26-22:28:21 - 22234] [TRACKING] DEBUG: Protocol state is 'RCPT',
resolving policy...
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Found policy member with ID '1'
in policy 'Default'
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Found policy member with ID '7'
in policy 'Default Inbound'
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Resolved sources '[EMAIL
PROTECTED]' from policy member ID '7'
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Resolved policy 'Default
Inbound' source '[EMAIL PROTECTED]' is an email address specification, match = 1
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Resolved destinations
'@waastad.org' from policy member ID '7'
[2008/07/26-22:28:21 - 22234] [POLICIES] DEBUG: Resolved policy 'Default
Inbound' destination '@waastad.org' is an email address specification, match = 1
[2008/07/26-22:28:21 - 22234] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
'0' => [
'1'
],
'10' => [
'3'
]
};
[2008/07/26-22:28:21 - 22234] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'Recipient' => '[EMAIL PROTECTED]',
'SASLUsername' => '',
'QueueID' => '',
'RecipientData' => '',
'Instance' => '56dd.488b88e5.c6635.0',
'EncryptionCipher' => '',
'Size' => '10971',
'EncryptionKeySize' => '0',
'ParsedClientAddress' => {
'Broadcast_Long' => 3272771082,
'Network' => '195.18.134.10',
'IP_Long' => 3272771082,
'Broadcast' => '195.18.134.10',
'IP' => '195.18.134.10',
'Mask_Long' => 4294967295,
'Network_Long' => 3272771082
},
'ProtocolTransport' => 'Postfix',
'EncryptionProtocol' => '',
'Helo' => 'mail.smartnet.no',
'ClientAddress' => '195.18.134.10',
'ClientName' => 'mail.smartnet.no',
'Sender' => '[EMAIL PROTECTED]',
'SASLSender' => '',
'Timestamp' => 1217104101,
'ProtocolState' => 'RCPT',
'Policy' => {
'0' => [
'1'
],
'10' => [
'3'
]
},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'mail.smartnet.no',
'SASLMethod' => ''
};
[2008/07/26-22:28:21 - 22234] [CHECKHELO] DEBUG: Updated timestamp for helo
'mail.smartnet.no' from address '195.18.134.10'
[2008/07/26-22:28:21 - 22234] [CHECKSPF] DEBUG: SPF result: datametrix.no: No
applicable sender policy available
[2008/07/26-22:28:21 - 22234] [CORE] INFO: module=CheckSPF, action=add_header,
host=195.18.134.10, helo=mail.smartnet.no, [EMAIL PROTECTED], [EMAIL
PROTECTED], reason=no_spf_record
[2008/07/26-22:28:22 - 22234] [GREYLISTING] DEBUG: Updated greylisting triplet
('SenderIP:195.18.134.0/24','[EMAIL PROTECTED]','[EMAIL PROTECTED]') @
1217104101
[2008/07/26-22:28:22 - 22234] [CORE] INFO: module=Greylisting, action=pass,
host=195.18.134.10, helo=mail.smartnet.no, [EMAIL PROTECTED], [EMAIL
PROTECTED], reason=authenticated
[2008/07/26-22:28:22 - 22234] [CORE] INFO: module=Quotas, action=none,
host=195.18.134.10, helo=mail.smartnet.no, [EMAIL PROTECTED], [EMAIL
PROTECTED], reason=no_quota
[2008/07/26-22:28:23 - 22235] [CORE] INFO: 2008/07/26-22:28:23 CONNECT TCP
Peer: "127.0.0.1:45401" Local: "127.0.0.1:10031"
[2008/07/26-22:28:23 - 22235] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:28:23 - 22235] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:28:23 - 22235] [TRACKING] DEBUG: Protocol state is
'END-OF-MESSAGE', decoding policy...
[2008/07/26-22:28:23 - 22235] [TRACKING] DEBUG: Decoded into: $VAR1 = {
'[EMAIL PROTECTED]' => {
'0' => [
'1'
],
'10' => [
'3'
]
}
};
[2008/07/26-22:28:23 - 22235] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'SASLUsername' => '',
'QueueID' => '19CFB5C232',
'RecipientData' => '/<[EMAIL PROTECTED]>#0=1;10=3;',
'EncryptionCipher' => '',
'Instance' => '56dd.488b88e5.c6635.0',
'Size' => '10971',
'EncryptionKeySize' => '0',
'ParsedClientAddress' => {
'Broadcast_Long' => 3272771082,
'Network' => '195.18.134.10',
'IP_Long' => 3272771082,
'Broadcast' => '195.18.134.10',
'IP' => '195.18.134.10',
'Mask_Long' => 4294967295,
'Network_Long' => 3272771082
},
'ProtocolTransport' => 'Postfix',
'EncryptionProtocol' => '',
'Helo' => 'mail.smartnet.no',
'ClientAddress' => '195.18.134.10',
'ClientName' => 'mail.smartnet.no',
'Sender' => '[EMAIL PROTECTED]',
'SASLSender' => '',
'Timestamp' => 1217104103,
'ProtocolState' => 'END-OF-MESSAGE',
'_Recipient_To_Policy' => {
'[EMAIL PROTECTED]' => {
'0' => [
'1'
],
'10' => [
'3'
]
}
},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'mail.smartnet.no',
'SASLMethod' => ''
};
[2008/07/26-22:28:39 - 22242] [CORE] INFO: 2008/07/26-22:28:39 CONNECT TCP
Peer: "127.0.0.1:55137" Local: "127.0.0.1:10031"
[2008/07/26-22:28:39 - 22242] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:28:39 - 22242] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:28:39 - 22233] [CORE] INFO: Starting "1" children
[2008/07/26-22:28:39 - 22255] [CORE] DEBUG: Child Preforked (22255)
[2008/07/26-22:28:39 - 22255] [CBPOLICYD] DEBUG: Starting up caching engine
[2008/07/26-22:28:39 - 22242] [TRACKING] DEBUG: No session tracking data exists
for request: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '11678',
'_timestamp' => 1217104119,
'helo_name' => 'localhost',
'reverse_client_name' => 'localhost',
'queue_id' => '744735C2F2',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'END-OF-MESSAGE',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '56eb.488b88f7.72b2d.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'
};
[2008/07/26-22:28:39 - 22242] [TRACKING] DEBUG: Protocol state is
'END-OF-MESSAGE', decoding policy...
[2008/07/26-22:28:39 - 22242] [TRACKING] DEBUG: Decoded into: $VAR1 = {};
[2008/07/26-22:28:39 - 22242] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'SASLUsername' => '',
'QueueID' => '744735C2F2',
'RecipientData' => '',
'Instance' => '56eb.488b88f7.72b2d.0',
'EncryptionCipher' => '',
'Size' => '11678',
'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' => 1217104119,
'ProtocolState' => 'END-OF-MESSAGE',
'_Recipient_To_Policy' => {},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'localhost',
'SASLMethod' => ''
};
And for case 2:
[2008/07/26-22:31:42 - 22235] [CORE] INFO: 2008/07/26-22:31:42 CONNECT TCP
Peer: "127.0.0.1:55145" Local: "127.0.0.1:10031"
[2008/07/26-22:31:42 - 22235] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:31:42 - 22235] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:31:42 - 22233] [CORE] INFO: Starting "1" children
[2008/07/26-22:31:42 - 22235] [TRACKING] DEBUG: No session tracking data exists
for request: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '10971',
'_timestamp' => 1217104302,
'helo_name' => 'mail.smartnet.no',
'reverse_client_name' => 'mail.smartnet.no',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '56fa.488b89ae.d8d6a.0',
'protocol_name' => 'ESMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[EMAIL PROTECTED]',
'client_name' => 'mail.smartnet.no',
'client_address' => '195.18.134.10',
'_protocol_transport' => 'Postfix'
};
[2008/07/26-22:31:42 - 22270] [CORE] DEBUG: Child Preforked (22270)
[2008/07/26-22:31:42 - 22270] [CBPOLICYD] DEBUG: Starting up caching engine
[2008/07/26-22:31:42 - 22235] [TRACKING] DEBUG: Added session tracking
information for: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '10971',
'_timestamp' => 1217104302,
'helo_name' => 'mail.smartnet.no',
'reverse_client_name' => 'mail.smartnet.no',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '56fa.488b89ae.d8d6a.0',
'protocol_name' => 'ESMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[EMAIL PROTECTED]',
'client_name' => 'mail.smartnet.no',
'client_address' => '195.18.134.10',
'_protocol_transport' => 'Postfix'
};
[2008/07/26-22:31:42 - 22235] [TRACKING] DEBUG: Protocol state is 'RCPT',
resolving policy...
[2008/07/26-22:31:42 - 22235] [POLICIES] DEBUG: Found policy member with ID '1'
in policy 'Default'
[2008/07/26-22:31:42 - 22235] [POLICIES] DEBUG: Found policy member with ID '3'
in policy 'Default Inbound'
[2008/07/26-22:31:42 - 22235] [POLICIES] DEBUG: Resolved sources '@waastad.org'
from policy member ID '3'
[2008/07/26-22:31:42 - 22235] [POLICIES] DEBUG: Resolved policy 'Default
Inbound' source '@waastad.org' is an email address specification, match = 0
[2008/07/26-22:31:42 - 22235] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
'0' => [
'1'
]
};
[2008/07/26-22:31:42 - 22235] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'Recipient' => '[EMAIL PROTECTED]',
'SASLUsername' => '',
'QueueID' => '',
'RecipientData' => '',
'Instance' => '56fa.488b89ae.d8d6a.0',
'EncryptionCipher' => '',
'Size' => '10971',
'EncryptionKeySize' => '0',
'ParsedClientAddress' => {
'Broadcast_Long' => 3272771082,
'Network' => '195.18.134.10',
'IP_Long' => 3272771082,
'Broadcast' => '195.18.134.10',
'IP' => '195.18.134.10',
'Mask_Long' => 4294967295,
'Network_Long' => 3272771082
},
'ProtocolTransport' => 'Postfix',
'EncryptionProtocol' => '',
'Helo' => 'mail.smartnet.no',
'ClientAddress' => '195.18.134.10',
'ClientName' => 'mail.smartnet.no',
'Sender' => '[EMAIL PROTECTED]',
'SASLSender' => '',
'Timestamp' => 1217104302,
'ProtocolState' => 'RCPT',
'Policy' => {
'0' => [
'1'
]
},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'mail.smartnet.no',
'SASLMethod' => ''
};
[2008/07/26-22:31:43 - 22235] [CORE] INFO: module=Quotas, action=none,
host=195.18.134.10, helo=mail.smartnet.no, [EMAIL PROTECTED], [EMAIL
PROTECTED], reason=no_quota
[2008/07/26-22:31:44 - 22242] [CORE] INFO: 2008/07/26-22:31:44 CONNECT TCP
Peer: "127.0.0.1:55146" Local: "127.0.0.1:10031"
[2008/07/26-22:31:44 - 22242] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:31:44 - 22242] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:31:44 - 22242] [TRACKING] DEBUG: Protocol state is
'END-OF-MESSAGE', decoding policy...
[2008/07/26-22:31:44 - 22242] [TRACKING] DEBUG: Decoded into: $VAR1 = {
'[EMAIL PROTECTED]' => {
'0' => [
'1'
]
}
};
[2008/07/26-22:31:44 - 22242] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'SASLUsername' => '',
'QueueID' => '1166E5C232',
'RecipientData' => '/<[EMAIL PROTECTED]>#0=1;',
'EncryptionCipher' => '',
'Instance' => '56fa.488b89ae.d8d6a.0',
'Size' => '10971',
'EncryptionKeySize' => '0',
'ParsedClientAddress' => {
'Broadcast_Long' => 3272771082,
'Network' => '195.18.134.10',
'IP_Long' => 3272771082,
'Broadcast' => '195.18.134.10',
'IP' => '195.18.134.10',
'Mask_Long' => 4294967295,
'Network_Long' => 3272771082
},
'ProtocolTransport' => 'Postfix',
'EncryptionProtocol' => '',
'Helo' => 'mail.smartnet.no',
'ClientAddress' => '195.18.134.10',
'ClientName' => 'mail.smartnet.no',
'Sender' => '[EMAIL PROTECTED]',
'SASLSender' => '',
'Timestamp' => 1217104304,
'ProtocolState' => 'END-OF-MESSAGE',
'_Recipient_To_Policy' => {
'[EMAIL PROTECTED]' => {
'0' => [
'1'
]
}
},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'mail.smartnet.no',
'SASLMethod' => ''
};
[2008/07/26-22:31:52 - 22235] [CORE] INFO: 2008/07/26-22:31:52 CONNECT TCP
Peer: "127.0.0.1:55154" Local: "127.0.0.1:10031"
[2008/07/26-22:31:52 - 22235] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2008/07/26-22:31:52 - 22235] [PROTOCOLS/Postfix] INFO: Identified Postfix
protocol
[2008/07/26-22:31:52 - 22235] [TRACKING] DEBUG: No session tracking data exists
for request: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => '11672',
'_timestamp' => 1217104312,
'helo_name' => 'localhost',
'reverse_client_name' => 'localhost',
'queue_id' => '45ED65C2F2',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'END-OF-MESSAGE',
'stress' => '',
'recipient' => '[EMAIL PROTECTED]',
'sasl_username' => '',
'instance' => '5707.488b89b8.4474c.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'
};
[2008/07/26-22:31:52 - 22235] [TRACKING] DEBUG: Protocol state is
'END-OF-MESSAGE', decoding policy...
[2008/07/26-22:31:52 - 22235] [TRACKING] DEBUG: Decoded into: $VAR1 = {};
[2008/07/26-22:31:52 - 22235] [TRACKING] DEBUG: Request translated into session
data: $VAR1 = {
'SASLUsername' => '',
'QueueID' => '45ED65C2F2',
'RecipientData' => '',
'Instance' => '5707.488b89b8.4474c.0',
'EncryptionCipher' => '',
'Size' => '11672',
'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' => 1217104312,
'ProtocolState' => 'END-OF-MESSAGE',
'_Recipient_To_Policy' => {},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'localhost',
'SASLMethod' => ''
};
[2008/07/26-22:32:32 - 22233] [CORE] INFO: Killing "1" children
[2008/07/26-22:32:32 - 22270] [CBPOLICYD] DEBUG: Shutting down caching engine
(22270)
Best regards,
hw
-----Original Message-----
From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Nigel Kukard
Sent: 25. juli 2008 22:14
To: [email protected]
Subject: Re: [policyd-users] v2.0.2 debug analysis
> Yes, It seems so,
> But I do not see why this should happen:
>
> 1. Not using policy groups:
> [EMAIL PROTECTED], [EMAIL PROTECTED] => is working fine
>
> 2. Using policy groups:
> SOURCE=!%internal_domains, DESTINATION= %internal_domains, and
> internal_domains has one member: @waastad.org => does NOT work!
Can you provide debug info again?
-N
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users
