Re: [policyd-users] 2.1x Accounting not working

Sat, 24 Nov 2012 17:29:52 -0800 

On 11/24/2012 06:48 PM, Marcin Czupryniak wrote:

Hello after a day pulling my hairs off, I've decided to ask for help...
I'm trying to implement some reporting and accounting on an SMTP relay (authenticated), after trying for a whole day seems that the accounting it's not working at all.
The database table accounting_tracking doesn't get populated with data and thus the defined limits are not enforced.
I've installed the 2.1 RPM under Centos6.3 and just a precaution disabled SeLinux (will be enabled in production) configured everything. The mails are coming to policyd properly yet seems that the accounting module is not counting them... 
Any clues?

Martin



Below is an extract from the debug log:
[2012/11/24-18:23:13 - 12089] [CORE] INFO: 2012/11/24-18:23:13 CONNECT TCP Peer: "127.0.0.1:36008" Local: "127.0.0.1:10031" [2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = { 
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => 383,
          '_timestamp' => 1353777793,
          'helo_name' => 'pcmart.int',
'reverse_client_name' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          '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' => 'smtptest',
          'instance' => '2f42.50b10281.31fd3.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '0',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => '[email protected]',
'client_name' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'client_address' => '95.241.241.163',
          '_protocol_transport' => 'Postfix'
        };
[2012/11/24-18:23:13 - 12104] [CORE] DEBUG: Child Preforked (12104)
[2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = { 
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => 383,
          '_timestamp' => 1353777793,
          'helo_name' => 'pcmart.int',
'reverse_client_name' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          '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' => 'smtptest',
          'instance' => '2f42.50b10281.31fd3.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '0',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => '[email protected]',
'client_name' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'client_address' => '95.241.241.163',
          '_protocol_transport' => 'Postfix'
        };
[2012/11/24-18:23:13 - 12104] [CBPOLICYD] DEBUG: Starting up caching engine [2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy... [2012/11/24-18:23:13 - 12089] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = { 
          'Recipient' => '[email protected]',
          'SASLUsername' => 'smtptest',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '2f42.50b10281.31fd3.0',
          'EncryptionCipher' => '',
          'Size' => '1',
          'EncryptionKeySize' => '0',
          'EncryptionProtocol' => '',
          'Helo' => 'pcmart.int',
          'ClientAddress' => '95.241.241.163',
'ClientName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'Sender' => '[email protected]',
          'SASLSender' => '',
          '_ClientAddress' => bless( {
                                       'raw_ip' => '95.241.241.163',
                                       'ip' => '95.241.241.163',
                                       'ip_version' => 4,
                                       'cidr' => 32
                                     }, 'awitpt::netip' ),
          'Protocol' => 'ESMTP',
'ClientReverseName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'SASLMethod' => 'PLAIN'
        };
[2012/11/24-18:23:13 - 12089] [POLICIES] DEBUG: Found policy member with ID '8' in policy 'SMTPBasic' [2012/11/24-18:23:13 - 12089] [POLICIES] DEBUG: [ID:8/Name:SMTPBasic]: Main policy sources '$smtptest' [2012/11/24-18:23:13 - 12089] [POLICIES] DEBUG: [ID:8/Name:SMTPBasic]: - Resolved source '$smtptest' to a SASL user specification, match = 1 [2012/11/24-18:23:13 - 12089] [POLICIES] INFO: [ID:8/Name:SMTPBasic]: Source matching result: matched=1 [2012/11/24-18:23:13 - 12089] [POLICIES] DEBUG: [ID:8/Name:SMTPBasic]: Main policy destinations '' [2012/11/24-18:23:13 - 12089] [POLICIES] INFO: [ID:8/Name:SMTPBasic]: Destination matching result: matched=0 [2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {}; [2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Request translated into session data: $VAR1 = { 
          'Recipient' => '[email protected]',
          'SASLUsername' => 'smtptest',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '2f42.50b10281.31fd3.0',
          'EncryptionCipher' => '',
          'Size' => '1',
          'EncryptionKeySize' => '0',
          'UnixTimestamp' => 1353777793,
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => '',
          'Helo' => 'pcmart.int',
          'ClientAddress' => '95.241.241.163',
'ClientName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'Sender' => '[email protected]',
          'SASLSender' => '',
          '_ClientAddress' => bless( {
                                       'raw_ip' => '95.241.241.163',
                                       'ip' => '95.241.241.163',
                                       'ip_version' => 4,
                                       'cidr' => 32
                                     }, 'awitpt::netip' ),
          'ProtocolState' => 'RCPT',
          'Policy' => {},
          'Protocol' => 'ESMTP',
'ClientReverseName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'SASLMethod' => 'PLAIN'
        };
[2012/11/24-18:23:13 - 12089] [CBPOLICYD] INFO: Got request #1
[2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Access Control Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Access Control Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'HELO/EHLO Check Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Greylisting Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Quotas Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Quotas Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Accounting Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Accounting Plugin' returned CBP_CONTINUE 
[2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Done with modules
[2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Protocol state is 'END-OF-MESSAGE', decoding policy... 
[2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Decoded into: $VAR1 = {};
[2012/11/24-18:23:13 - 12089] [TRACKING] DEBUG: Request translated into session data: $VAR1 = { 
          'SASLUsername' => 'smtptest',
          'QueueID' => '4CDEC140FAE',
          'RecipientData' => '/<[email protected]>#',
          'EncryptionCipher' => '',
          'Instance' => '2f42.50b10281.31fd3.0',
          'Size' => '1',
          'EncryptionKeySize' => '0',
          'UnixTimestamp' => 1353777793,
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => '',
          'Helo' => 'pcmart.int',
          'ClientAddress' => '95.241.241.163',
'ClientName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'Sender' => '[email protected]',
          'SASLSender' => '',
          '_ClientAddress' => bless( {
                                       'raw_ip' => '95.241.241.163',
                                       'ip' => '95.241.241.163',
                                       'ip_version' => 4,
                                       'cidr' => 32
                                     }, 'awitpt::netip' ),
          'ProtocolState' => 'END-OF-MESSAGE',
          '_Recipient_To_Policy' => {},
          'Protocol' => 'ESMTP',
'ClientReverseName' => 'host163-241-static.241-95-b.business.telecomitalia.it', 
          'SASLMethod' => 'PLAIN'
        };
[2012/11/24-18:23:13 - 12089] [CBPOLICYD] INFO: Got request #2 (pipelined) [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Access Control Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Access Control Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'HELO/EHLO Check Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Greylisting Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Quotas Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Quotas Plugin' returned CBP_SKIP [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Running module: Accounting Plugin [2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Module 'Accounting Plugin' returned CBP_CONTINUE 
[2012/11/24-18:23:13 - 12089] [CBPOLICYD] DEBUG: Done with modules



Configuration file:
#
# Server configuration
#
[server]

# Protocols to load
protocols=<<EOT
Postfix
Bizanga
EOT

# Modules to load
modules=<<EOT
Core
AccessControl
Accounting
Amavis
CheckHelo
CheckSPF
Greylisting
Quotas
EOT

# User to run this daemon as
user=cbpolicyd
group=cbpolicyd

# Filename to store pid of parent process
#pid_file=/var/run/cbpolicyd/cbpolicyd.pid

# Cache file
cache_file=/var/run/cbpolicyd/cache
# Uncommenting the below option will prevent cbpolicyd going into the background 
#background=no

# Preforking configuration
#
# min_server            - Minimum servers to keep around
# min_spare_servers     - Minimum spare servers to keep around ready to
#                         handle requests
# max_spare_servers - Maximum spare servers to have around doing nothing 
# max_servers           - Maximum servers alltogether
# max_requests - Maximum number of requests each child will serve 
#
# One may want to use the following as a rough guideline...
# Small mailserver:  2, 2, 4, 10, 1000
# Medium mailserver: 4, 4, 12, 25, 1000
# Large mailserver: 8, 8, 16, 64, 1000
#
min_servers=4
min_spare_servers=4
max_spare_servers=12
max_servers=25
max_requests=1000



# Log level:
# 0 - Errors only
# 1 - Warnings and errors
# 2 - Notices, warnings, errors
# 3 - Info, notices, warnings, errors
# 4 - Debugging
log_level=4

# File to log to instead of stdout
log_file=/var/log/cbpolicyd/cbpolicyd.log

# Log destination for mail logs...
# main - Default. Log to policyd's main log mechanism, accepts NO args 
# syslog        - log mail via syslog
#                       format: log_mail=facility@method,args
#
# Valid methods for syslog:
# native        - Let Sys::Syslog decide
# unix          - Unix socket
# udp           - UDP socket
# stream        - Stream (for Solaris)
#
# Example: unix native
#log_mail=mail@syslog:native
#
# Example: unix socket
#log_mail=mail@syslog:unix
#
# Example: udp
#log_mail=mail@syslog:udp,127.0.0.1
#
# Example: Solaris
#log_mail=local0@syslog:stream,/dev/log
log_mail=maillog

# Things to log in extreme detail
# modules       - Log detailed module running information
# tracking      - Log detailed tracking information
# policies      - Log policy resolution
# protocols     - Log general protocol info, but detailed
# bizanga       - Log the bizanga protocol
# cache         - Log cache usage on client shutdown
#
# There is no default for this configuration option. Options can be
# separated by commas. ie. protocols,modules
#
log_detail=policies,tracking,modules

# Protocol to use "tcp" or "unix", defaults to "tcp"
#proto=tcp

# IP to listen on, * for all. Blank for unix sockets
host=127.0.0.1

# Port to run on, in the case of a unix socket it would be the path
# eg. 10031
# eg. /var/run/cbpolicyd/policyd.sock
port=10031

# Timeout in communication with clients
# Idle timeout in postfix defaults to 1015s (active connection)
#timeout_idle=1015
# Busy sockets in postfix defaults to 100s
#timeout_busy=115

# cidr_allow/cidr_deny
# Comma, whitespace or semi-colon separated. Contains a CIDR block to
# compare the clients IP to.  If cidr_allow or cidr_deny options are
# given, the incoming client must match a cidr_allow and not match a
# cidr_deny or the client connection will be closed.
#cidr_allow=0.0.0.0/0
#cidr_deny=



[database]
#DSN=DBI:SQLite:dbname=policyd.sqlite
DSN=DBI:mysql:database=policyd;host=localhost
Username=root
Password=Delldell
#

# What do we do when we have a database connection problem
# tempfail      - Return temporary failure
# pass          - Return success
bypass_mode=tempfail

# How many seconds before we retry a DB connection
bypass_timeout=30

# Table prefix to use, be sure to generate the schema with the table
# prefix aswell!
#table_prefix=


# Access Control module
[AccessControl]
enable=0


# Accounting module
[Accounting]
enable=1


# Amavis module
[Amavis]
enable=0 # Disabled by default


# CheckHelo module
[CheckHelo]
enable=0


# CheckSPF module
[CheckSPF]
enable=0


# Greylisting module
[Greylisting]
enable=0
#training_mode=1
#defer_message=Greylisting in effect, please come back later
#blacklist_message=Greylisting in effect, sending server blacklisted


# Quotas module
[Quotas]
enable=0





and relevant from postfix configuration:

smtpd_recipient_restrictions =
        check_policy_service inet:127.0.0.1:10031,
        permit_sasl_authenticated,
        reject
smtpd_end_of_data_restrictions = check_policy_service inet:127.0.0.1:10031 


After another cigarette and caffeine night, I managed to solve the issue...
For future reference for everyone just note that:
1) Policies created in the webui have to be enabled just after the creation, they are created with the disabled flag! 2) When using member matching in a policy make sure that both source and destination are written. Make sure that you don't omit the destination field, just put "any" if you're not going to use it
For my issue it was that i was specifying a source ($sasl_username) but not a destination, i was just leaving the field blank thinking that it should work... Please someone from the dev team: patch the web interface so if anyone leaves the destination field empty just silently write "any" into it, this will avoid that people like me end up with balded head :) 

Anyway thanks for this great piece of software, hear from you soon!

Martin


_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org

Reply via email to