On 11/04/2015 03:45 PM, [email protected] wrote:
As of today, I've installed v2.1.x-201205100639.
We're now seeing these errors reported by cbpolicyd:
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 256.
I've installed the latest git version on a vanilla CentOS 7 AWS-EC2
instance. Also installed the latest git version of awit-perl-toolkit.
Cache::FastMmap version 1.43 is installed from CPAN.
Backend database is Postgres 9.4.5
Cluebringer config:
#
# Server configuration
#
[server]
# Protocols to load
protocols=<<EOT
Postfix
EOT
# Modules to load
modules=<<EOT
Core
AccessControl
Accounting
CheckHelo
CheckSPF
Greylisting
Quotas
EOT
# User to run this daemon as
user=root
group=root
# Filename to store pid of parent process
pid_file=/var/run/cbpolicyd.pid
# Cache file
cache_file=/var/run/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=8
min_spare_servers=8
max_spare_servers=16
max_servers=64
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=modules,tracking,policies,protocols,cache
# Protocol to use "tcp" or "unix", defaults to "tcp"
proto=tcp
# IP to listen on, * for all. Blank for unix sockets
host=*
# 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=10.1.0.0/16 10.2.0.0/16 127.0.0.0/8
#cidr_deny=
[database]
#DSN=DBI:SQLite:dbname=policyd.sqlite
DSN=DBI:Pg:database=policyd;host=host.example.com
Username=dbuser
Password=dbpassword
#
# 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=1
# Accounting module
[Accounting]
enable=1
# Amavis module
[Amavis]
enable=0 # Disabled by default
# CheckHelo module
[CheckHelo]
enable=1
# CheckSPF module
[CheckSPF]
enable=1
# Greylisting module
[Greylisting]
enable=1
#training_mode=1
defer_message=Greylisting in effect, please come back later
blacklist_message=Greylisting in effect, sending server blacklisted
# Quotas module
[Quotas]
enable=1
Here's the debug log showing the error:
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: PolicyD v2 /
Cluebringer - v2.1.x-201205100639
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: Initializing system
modules.
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: System modules initialized.
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: Module load started...
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => AccessControl: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => Accounting: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => CheckHelo: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => CheckSPF: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => Greylisting: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => Quotas: enabled
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: => Protocol(Postfix): enabled
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: Module load done.
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] NOTICE: Session tracking is
ENABLED.
[2015/11/05-16:58:14 - 2066] [CBPOLICYD] DEBUG: Opening syslog,
destination = 'native', facility = 'mail'.
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: 2015/11/05-16:58:14 cbp
(type Net::Server::PreFork) starting! pid(2066)
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: Resolved [*]:10031 to
[0.0.0.0]:10031, IPv4
[2015/11/05-16:58:14 - 2066] [CORE] NOTICE: Binding to TCP port 10031 on
host 0.0.0.0 with IPv4
[2015/11/05-16:58:14 - 2066] [CORE] INFO: Setting up serialization via flock
[2015/11/05-16:58:14 - 2066] [CORE] INFO: Beginning prefork (4 processes)
[2015/11/05-16:58:14 - 2066] [CORE] INFO: Starting "4" children
[2015/11/05-16:58:14 - 2066] [CORE] DEBUG: Parent ready for children.
[2015/11/05-16:58:14 - 2068] [CORE] DEBUG: Child Preforked (2068)
[2015/11/05-16:58:14 - 2068] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:14 - 2069] [CORE] DEBUG: Child Preforked (2069)
[2015/11/05-16:58:14 - 2069] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:14 - 2067] [CORE] DEBUG: Child Preforked (2067)
[2015/11/05-16:58:14 - 2067] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:14 - 2070] [CORE] DEBUG: Child Preforked (2070)
[2015/11/05-16:58:14 - 2070] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:23 - 2068] [CORE] INFO: 2015/11/05-16:58:23 CONNECT
TCP Peer: "[127.0.0.1]:56795" Local: "[127.0.0.1]:10031"
[2015/11/05-16:58:23 - 2068] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2015/11/05-16:58:23 - 2068] [PROTOCOLS/Postfix] INFO: Identified
Postfix protocol
[2015/11/05-16:58:23 - 2066] [CORE] INFO: Starting "1" children
[2015/11/05-16:58:23 - 2074] [CORE] DEBUG: Child Preforked (2074)
[2015/11/05-16:58:23 - 2074] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:23 - 2068] [TRACKING] DEBUG: No session tracking data
exists for request: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => 0,
'_timestamp' => 1446742703,
'helo_name' => 'host.example.com',
'reverse_client_name' => 'ip-10-1-1-50.ec2.internal',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'_peer_address' => '127.0.0.1',
'sasl_username' => '',
'recipient' => '[email protected]',
'ccert_pubkey_fingerprint' => '',
'instance' => '817.563b8aaf.106fe.0',
'protocol_name' => 'SMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[email protected]',
'client_name' => 'ip-10-1-1-50.ec2.internal',
'client_address' => '10.1.1.50',
'_protocol_transport' => 'Postfix'
};
[2015/11/05-16:58:23 - 2068] [TRACKING] DEBUG: Added session tracking
information for: $VAR1 = {
'ccert_fingerprint' => '',
'sasl_method' => '',
'sasl_sender' => '',
'size' => 0,
'_timestamp' => 1446742703,
'helo_name' => 'host.example.com',
'reverse_client_name' => 'ip-10-1-1-50.ec2.internal',
'queue_id' => '',
'encryption_cipher' => '',
'encryption_protocol' => '',
'etrn_domain' => '',
'ccert_subject' => '',
'request' => 'smtpd_access_policy',
'protocol_state' => 'RCPT',
'stress' => '',
'_peer_address' => '127.0.0.1',
'sasl_username' => '',
'recipient' => '[email protected]',
'ccert_pubkey_fingerprint' => '',
'instance' => '817.563b8aaf.106fe.0',
'protocol_name' => 'SMTP',
'encryption_keysize' => '0',
'recipient_count' => '0',
'ccert_issuer' => '',
'sender' => '[email protected]',
'client_name' => 'ip-10-1-1-50.ec2.internal',
'client_address' => '10.1.1.50',
'_protocol_transport' => 'Postfix'
};
[2015/11/05-16:58:23 - 2068] [TRACKING] DEBUG: Protocol state is 'RCPT',
resolving policy...
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Going to resolve session
data into policy: $VAR1 = {
'Recipient' => '[email protected]',
'SASLUsername' => '',
'QueueID' => '',
'RecipientData' => '',
'Instance' => '817.563b8aaf.106fe.0',
'EncryptionCipher' => '',
'Size' => '0',
'EncryptionKeySize' => '0',
'EncryptionProtocol' => '',
'Helo' => 'host.example.com',
'ClientAddress' => '10.1.1.50',
'ClientName' => 'ip-10-1-1-50.ec2.internal',
'Sender' => '[email protected]',
'SASLSender' => '',
'_ClientAddress' => bless( {
'raw_ip' => '10.1.1.50',
'ip' => '10.1.1.50',
'ip_version' => 4,
'cidr' => 32
}, 'awitpt::netip' ),
'Protocol' => 'SMTP',
'ClientReverseName' => 'ip-10-1-1-50.ec2.internal',
'SASLMethod' => ''
};
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Found policy member with
ID '1' in policy 'Default'
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Found policy member with
ID '2' in policy 'Default Outbound'
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Found policy member with
ID '3' in policy 'Default Inbound'
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Found policy member with
ID '4' in policy 'Default Internal'
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: Found policy member with
ID '5' in policy 'Test'
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: [ID:1/Name:Default]:
Source not defined or 'any', explicit match: matched=1
[2015/11/05-16:58:23 - 2068] [POLICIES] INFO: [ID:1/Name:Default]:
Source matching result: matched=1
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: [ID:1/Name:Default]:
Destination not defined or 'any', explicit match: matched=1
[2015/11/05-16:58:23 - 2068] [POLICIES] INFO: [ID:1/Name:Default]:
Destination matching result: matched=1
[2015/11/05-16:58:23 - 2068] [POLICIES] DEBUG: [ID:2/Name:Default
Outbound]: Main policy sources '%internal_ips,%internal_domains'
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 256.
[2015/11/05-16:58:24 - 2067] [CORE] INFO: 2015/11/05-16:58:24 CONNECT
TCP Peer: "[127.0.0.1]:56797" Local: "[127.0.0.1]:10031"
[2015/11/05-16:58:24 - 2067] [PROTOCOLS/Postfix] DEBUG: Possible Postfix
protocol
[2015/11/05-16:58:24 - 2067] [PROTOCOLS/Postfix] INFO: Identified
Postfix protocol
[2015/11/05-16:58:24 - 2066] [CORE] INFO: Starting "1" children
[2015/11/05-16:58:24 - 2075] [CORE] DEBUG: Child Preforked (2075)
[2015/11/05-16:58:24 - 2075] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/11/05-16:58:24 - 2067] [TRACKING] DEBUG: Protocol state is 'RCPT',
resolving policy...
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Going to resolve session
data into policy: $VAR1 = {
'Recipient' => '[email protected]',
'SASLUsername' => '',
'QueueID' => '',
'RecipientData' => undef,
'EncryptionCipher' => '',
'Instance' => '817.563b8aaf.106fe.0',
'Size' => '0',
'EncryptionKeySize' => '0',
'UnixTimestamp' => '1446742703',
'EncryptionProtocol' => '',
'Helo' => 'host.example.com',
'ClientAddress' => '10.1.1.50',
'ClientName' => 'ip-10-1-1-50.ec2.internal',
'Sender' => '[email protected]',
'SASLSender' => '',
'_ClientAddress' => bless( {
'raw_ip' => '10.1.1.50',
'ip' => '10.1.1.50',
'ip_version' => 4,
'cidr' => 32
}, 'awitpt::netip' ),
'Protocol' => 'SMTP',
'ClientReverseName' => 'ip-10-1-1-50.ec2.internal',
'SASLMethod' => ''
};
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Found policy member with
ID '1' in policy 'Default'
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Found policy member with
ID '2' in policy 'Default Outbound'
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Found policy member with
ID '3' in policy 'Default Inbound'
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Found policy member with
ID '4' in policy 'Default Internal'
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: Found policy member with
ID '5' in policy 'Test'
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: [ID:1/Name:Default]:
Source not defined or 'any', explicit match: matched=1
[2015/11/05-16:58:24 - 2067] [POLICIES] INFO: [ID:1/Name:Default]:
Source matching result: matched=1
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: [ID:1/Name:Default]:
Destination not defined or 'any', explicit match: matched=1
[2015/11/05-16:58:24 - 2067] [POLICIES] INFO: [ID:1/Name:Default]:
Destination matching result: matched=1
[2015/11/05-16:58:24 - 2067] [POLICIES] DEBUG: [ID:2/Name:Default
Outbound]: Main policy sources '%internal_ips,%internal_domains'
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 256.
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 321, <$read> line 3.
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 321, <$read> line 1.
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 321.
Can't call method "get" on an undefined value at
/usr/local/lib/cbpolicyd-2.1/awitpt/cache.pm line 321.
[2015/11/05-16:58:26 - 2066] [CORE] NOTICE: 2015/11/05-16:58:26 Server
closing!
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Kill TERM pid 2074
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Kill TERM pid 2075
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Kill TERM pid 2070
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Kill TERM pid 2069
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Destroying system modules.
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: System modules destroyed.
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Closing syslog.
[2015/11/05-16:58:26 - 2066] [CORE] DEBUG: Syslog closed.
I see messages on the mailing list going back several years with this
same issue but no resolutions.
Several mentions are made as to old/outdated versions of Cache::FastMmap
being the culprit. I installed the latest from CPAN to rule that out.
Anyone have any other suggestions?
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
