On Jul 26, 2012, at 3:11 AM, Robert Anderson wrote:
> On 25/07/2012 10:16, CSS wrote:
>> I've run into a small issue with my very basic "match all sasl-authenticated
>> users" policy (ID 6 below in both the policies and policy_members tables).
>>
>> sqlite> select * from policies;
>> 1|Default|0|Default System Policy|0
>> 6|outbound mail|10|put sasl-auth and any other outbound groups here|0
>> 7|outbound-test|20|testing|1
>>
>> sqlite> select * from policy_members;
>> 1|1||||0
>> 6|6|$*|any|match sasl-auth users|0
>> 7|7|[email protected]|any|testing|0
>>
>> I see normal users that are connecting with a mail client being tracked, and
>> I think I'm grabbing all of them. However I just enabled smtp-auth in
>> roundcube so I can also track my webmail users. According to Postfix, this
>> is working:
>>
>> Jul 25 03:58:31 hc1 postfix/smtpd[25015]: connect from hc2.foo.com[x.x.x.x]
>> Jul 25 03:58:32 hc1 postfix/smtpd[25015]: F40808FD9D:
>> client=hc2.foo.com[x.x.x.x], sasl_method=PLAIN,
>> [email protected]
>>
>> And compared to another message I sent as another user via a normal MUA:
>>
>> Jul 25 03:49:50 hc1 postfix/smtpd[23814]: connect from y.y.y.y[y.y.y.y]
>> Jul 25 03:49:51 hc1 cbpolicyd[23779]: module=Quotas, mode=update,
>> host=y.y.y.y, helo=frankentosh.foo.com, [email protected], [email protected],
>> reason=quota_update, policy=6, quota=3, limit=4,
>> track=SASLUsername:[email protected], counter=MessageCount, quota=1.00/100 (1.0%)
>> Jul 25 03:49:51 hc1 postfix/smtpd[23814]: 218D178B5D:
>> client=y.y.y.y[y.y.y.66], sasl_method=PLAIN, [email protected]
>>
>> What might account for the difference?
>>
>> The only thing of note here is that the IP that the mail server, smtpd and
>> roundcube are using are all the same IP. Could this be triggering some type
>> of ignore?
>>
>> With the log level set to 3, I'm not seeing anything in the cbpolicyd.log on
>> these connections.
>
> Would you mind posting the output of postconf?
Sure, see below. Sorry for the delay, I wanted to check if swapping around
policyd's listening IP to be different from the local ssmtp submission IP would
have any effect - no change. Increasing the log_level on policyd doesn't seem
to generate much more info, but it's set to "4" below. Just for comparison
purposes, I'm showing both a local ssmtp smtp-auth session (postfix logs
confirm sasl auth happening) and a remote so you can see the difference in the
two sessions. policyd is totally silent on the local smtp-auth connection...
> Also, just for reference,
> policyd's logging and configuration + postfix log.
Also below, do let me know if you want to see anything else...
Thanks,
Charles
postconf -n:
alias_maps = hash:/etc/aliases, hash:/usr/local/var/dtc/etc/postfix_aliases
anvil_rate_time_unit = 30s
body_checks = regexp:/usr/local/etc/postfix/maps/body_checks
bounce_queue_lifetime = 3d
broken_sasl_auth_clients = yes
command_directory = /usr/local/sbin
config_directory = /usr/local/etc/postfix
content_filter = smtp-amavis:[x.x.x.216]:10024
daemon_directory = /usr/local/libexec/postfix
data_directory = /var/db/postfix
debug_peer_level = 2
disable_vrfy_command = yes
header_checks = regexp:/usr/local/etc/postfix/maps/header_checks
html_directory = /usr/local/share/doc/postfix
inet_interfaces = all
mail_owner = postfix
mailbox_size_limit = 0
mailq_path = /usr/local/bin/mailq
manpage_directory = /usr/local/man
maximal_queue_lifetime = 3d
message_size_limit = 30720000
mime_header_checks = regexp:/usr/local/etc/postfix/maps/mime_header_checks
myhostname = hc1.example.com (altered)
mynetworks_style = host
newaliases_path = /usr/local/bin/newaliases
parent_domain_matches_subdomains =
queue_directory = /var/spool/postfix
readme_directory = /usr/local/share/doc/postfix
recipient_bcc_maps = hash:/usr/local/etc/postfix/recipient_bcc
recipient_delimiter = -
relay_domains = /usr/local/var/dtc/etc/postfix_relay_domains
relay_recipient_maps = hash:/usr/local/var/dtc/etc/postfix_relay_recipients
sample_directory = /usr/local/etc/postfix
sender_bcc_maps = hash:/usr/local/etc/postfix/sender_bcc
sendmail_path = /usr/local/sbin/sendmail
setgid_group = maildrop
smtp_bind_address = x.x.x.216
smtp_tls_note_starttls_offer = yes
smtp_tls_security_level = may
smtp_use_tls = yes
smtpd_client_connection_rate_limit = 20
smtpd_client_recipient_rate_limit = 200
smtpd_client_restrictions = permit_mynetworks, permit_sasl_authenticated,
check_client_access regexp:/usr/local/etc/postfix/maps/relaying_stoplist,
permit
smtpd_delay_reject = yes
smtpd_end_of_data_restrictions = check_policy_service inet:x.x.x.216:10031
smtpd_helo_required = yes
smtpd_recipient_restrictions = permit_mynetworks,
check_policy_service inet:x.x.x.216:10031,
permit_sasl_authenticated, check_client_access
regexp:/usr/local/etc/postfix/maps/relaying_stoplist,
reject_invalid_hostname, reject_non_fqdn_sender,
reject_non_fqdn_recipient,
reject_unknown_sender_domain,
reject_unknown_recipient_domain,
reject_unauth_destination, permit
smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_sasl_path = private/auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_tls_auth_only = no
smtpd_tls_cert_file = /usr/local/etc/ssl/postfix.pem
smtpd_tls_key_file = /usr/local/etc/ssl/private/postfix.pem
smtpd_tls_received_header = yes
smtpd_use_tls = yes
transport_maps = hash:/usr/local/etc/postfix/transport
unknown_local_recipient_reject_code = 550
virtual_alias_maps = hash:/usr/local/var/dtc/etc/postfix_virtual
virtual_gid_maps = static:1001
virtual_mailbox_base = /
virtual_mailbox_domains =
hash:/usr/local/var/dtc/etc/postfix_virtual_mailbox_domains
virtual_mailbox_maps = hash:/usr/local/var/dtc/etc/postfix_vmailbox
virtual_minimum_uid = 98
virtual_transport = maildrop
virtual_uid_maps = hash:/usr/local/var/dtc/etc/postfix_virtual_uid_mapping
cluebringer.conf:
#
# Server configuration
#
[server]
# Protocols to load
protocols=<<EOT
Postfix
EOT
# Modules to load
modules=<<EOT
Core
Quotas
EOT
# User to run this daemon as
user=vscan
group=vscan
# Filename to store pid of parent process
pid_file=/var/run/policyd/cbpolicyd.pid
#
min_servers=4
min_spare_servers=4
max_spare_servers=12
max_servers=25
max_requests=1000
# Log level:
log_level=2
# File to log to instead of stdout
log_file=/var/log/policyd/cbpolicyd.log
# Example: unix native
log_mail=mail@syslog:native
# IP to listen on, * for all
#host=*
host=x.x.x.216
[database]
DSN=DBI:SQLite:dbname=/usr/local/etc/policyd-sqlite/policyd.sqlite
bypass_mode=tempfail
# How many seconds before we retry a DB connection
bypass_timeout=30
# Access Control module
[AccessControl]
enable=0
# Greylisting module
[Greylisting]
enable=0
# CheckHelo module
[CheckHelo]
enable=0
# CheckSPF module
[CheckSPF]
enable=0
# Quotas module
[Quotas]
enable=1
Logging during an ssmtp delivery where ssmtp is using smtp-auth.
cbpolicyd.log (log_level4):
[2012/08/05-17:05:13 - 24193] [CORE] INFO: Starting "4" children
[2012/08/05-17:05:13 - 24194] [CORE] DEBUG: Child Preforked (24194)
[2012/08/05-17:05:13 - 24195] [CORE] DEBUG: Child Preforked (24195)
[2012/08/05-17:05:13 - 24193] [CORE] DEBUG: Parent ready for children.
[2012/08/05-17:05:13 - 24196] [CORE] DEBUG: Child Preforked (24196)
[2012/08/05-17:05:13 - 24195] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:05:13 - 24196] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:05:13 - 24197] [CORE] DEBUG: Child Preforked (24197)
[2012/08/05-17:05:13 - 24197] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:05:13 - 24194] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:05:20 - 24193] [CORE] INFO: Starting "1" children
[2012/08/05-17:05:20 - 24196] [CORE] INFO: 2012/08/05-17:05:20 CONNECT TCP
Peer: "x.x.x.215:54843" Local: "x.x.x.216:10031"
[2012/08/05-17:05:20 - 24205] [CORE] DEBUG: Child Preforked (24205)
[2012/08/05-17:05:20 - 24205] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:05:21 - 24195] [CORE] INFO: 2012/08/05-17:05:21 CONNECT TCP
Peer: "x.x.x.215:32964" Local: "x.x.x.216:10031"
[2012/08/05-17:05:51 - 24193] [CORE] INFO: Killing "1" children
[2012/08/05-17:05:51 - 24194] [CBPOLICYD] DEBUG: Shutting down caching engine
(24194)
postfix log:
Aug 5 17:05:19 hc1 postfix/smtpd[24202]: connect from
hc2.example.com[x.x.x.215]
Aug 5 17:05:19 hc1 postfix/smtpd[24202]: BEED1E149B:
client=hc2.example.com[x.x.x.215], sasl_method=LOGIN,
[email protected]
Aug 5 17:05:20 hc1 postfix/cleanup[24204]: BEED1E149B:
message-id=<[email protected]>
Aug 5 17:05:20 hc1 postfix/smtpd[24202]: disconnect from
hc2.example.com[x.x.x.215]
Aug 5 17:05:20 hc1 postfix/qmgr[22741]: BEED1E149B:
from=<[email protected]>, size=682, nrcpt=1 (queue active)
Aug 5 17:05:20 hc1 sSMTP[24201]: Sent mail for [email protected] (221
2.0.0 Bye) uid=1001 username=spork outbytes=537
Aug 5 17:05:21 hc1 postfix/smtpd[24208]: connect from
hc2.example.com[x.x.x.215]
Aug 5 17:05:21 hc1 postfix/smtpd[24208]: 3C600E14A4:
client=hc2.example.com[x.x.x.215]
Aug 5 17:05:21 hc1 postfix/cleanup[24204]: 3C600E14A4:
message-id=<[email protected]>
Aug 5 17:05:21 hc1 postfix/smtpd[24208]: disconnect from
hc2.example.com[x.x.x.215]
Aug 5 17:05:21 hc1 postfix/qmgr[22741]: 3C600E14A4:
from=<[email protected]>, size=1177, nrcpt=1 (queue active)
Aug 5 17:05:21 hc1 postfix/smtp[24206]: BEED1E149B: to=<[email protected]>,
relay=x.x.x.216[x.x.x.216]:10024, delay=1.5, delays=1.1/0.03/0/0.43, dsn=2.0.0,
status=sent (250 2.0.0 from MTA(smtp:[x.x.x.216]:10025): 250 2.0.0 Ok: queued
as 3C600E14A4)
Aug 5 17:05:21 hc1 postfix/qmgr[22741]: BEED1E149B: removed
Aug 5 17:05:21 hc1 postfix/smtp[24209]: 3C600E14A4: to=<[email protected]>,
relay=mail.morefoo.com[x.x.x.222]:25, delay=0.11, delays=0.02/0.03/0.06/0.01,
dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 56F472D4806)
Aug 5 17:05:21 hc1 postfix/qmgr[22741]: 3C600E14A4: removed
And the same thing with a "remote" smtp-auth user.
cbpolicyd.log:
[2012/08/05-17:10:21 - 24193] [CORE] INFO: Starting "1" children
[2012/08/05-17:10:21 - 24195] [CORE] INFO: 2012/08/05-17:10:21 CONNECT TCP
Peer: "x.x.x.215:35473" Local: "x.x.x.216:10031"
[2012/08/05-17:10:21 - 24701] [CORE] DEBUG: Child Preforked (24701)
[2012/08/05-17:10:21 - 24701] [CBPOLICYD] DEBUG: Starting up caching engine
[2012/08/05-17:10:22 - 24288] [CORE] INFO: 2012/08/05-17:10:22 CONNECT TCP
Peer: "x.x.x.215:28149" Local: "x.x.x.216:10031"
[2012/08/05-17:10:23 - 24196] [CORE] INFO: 2012/08/05-17:10:23 CONNECT TCP
Peer: "x.x.x.215:17469" Local: "x.x.x.216:10031"
[2012/08/05-17:10:53 - 24193] [CORE] INFO: Killing "1" children
[2012/08/05-17:10:53 - 24701] [CBPOLICYD] DEBUG: Shutting down caching engine
(24701)
postfix log:
Aug 5 17:10:21 hc1 postfix/smtpd[24697]: connect from
foon.example2.com[y.y.y.66]
Aug 5 17:10:21 hc1 cbpolicyd[24195]: module=Quotas, mode=update,
host=y.y.y.66, helo=frankentosh.sporklab.com, [email protected],
[email protected], reason=quota_update, policy=6, quota=3, limit=4,
track=SASLUsername:[email protected], counter=MessageCount, quota=1.00/1000
(0.1%)
Aug 5 17:10:21 hc1 cbpolicyd[24195]: module=Quotas, mode=update,
host=y.y.y.66, helo=frankentosh.sporklab.com, [email protected],
[email protected], reason=quota_update, policy=8, quota=4, limit=5,
track=SASLUsername:[email protected], counter=MessageCount, quota=1.00/5000
(0.0%)
Aug 5 17:10:21 hc1 postfix/smtpd[24697]: AA6A7E14D4:
client=foon.example2.com[y.y.y.66], sasl_method=PLAIN,
[email protected]
Aug 5 17:10:22 hc1 postfix/cleanup[24702]: AA6A7E14D4:
message-id=<[email protected]>
Aug 5 17:10:22 hc1 postfix/qmgr[22741]: AA6A7E14D4: from=<[email protected]>,
size=727, nrcpt=1 (queue active)
Aug 5 17:10:23 hc1 postfix/smtpd[24705]: connect from
hc2.example.com[x.x.x.215]
Aug 5 17:10:23 hc1 postfix/smtpd[24705]: 25164E14E6:
client=hc2.example.com[x.x.x.215]
Aug 5 17:10:23 hc1 postfix/cleanup[24702]: 25164E14E6:
message-id=<[email protected]>
Aug 5 17:10:23 hc1 postfix/smtpd[24705]: disconnect from
hc2.example.com[x.x.x.215]
Aug 5 17:10:23 hc1 postfix/qmgr[22741]: 25164E14E6: from=<[email protected]>,
size=1222, nrcpt=1 (queue active)
Aug 5 17:10:23 hc1 postfix/smtp[24703]: AA6A7E14D4: to=<[email protected]>,
relay=x.x.x.216[x.x.x.216]:10024, delay=1.7, delays=1.3/0.03/0/0.37, dsn=2.0.0,
status=sent (250 2.0.0 from MTA(smtp:[x.x.x.216]:10025): 250 2.0.0 Ok: queued
as 25164E14E6)
Aug 5 17:10:23 hc1 postfix/qmgr[22741]: AA6A7E14D4: removed
Aug 5 17:10:23 hc1 postfix/smtp[24706]: 25164E14E6: to=<[email protected]>,
relay=mail.morefoo.com[x.x.x.222]:25, delay=0.24, delays=0.02/0.03/0.06/0.13,
dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5F37C2D4806)
Aug 5 17:10:23 hc1 postfix/qmgr[22741]: 25164E14E6: removedexample.com
> _______________________________________________
> Users mailing list
> [email protected]
> http://lists.policyd.org/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.policyd.org/mailman/listinfo/users_lists.policyd.org
