Aug 5, 2024: iRedMail-1.7.1 has been released.

**frank.daeuble** · 2015-03-13 00:51:38

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Topic: Unterstand throttling

==== Required information ====
- iRedMail version: 0.9.0 / Pro 1.9.2
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Linux/BSD distribution name and version: Debian 7.8
- Related log if you're reporting an issue:
====

I have set a global throttling of 15 mail / minute. Now I want to set a higher throttling for one user or domain.

As far as I understood the throttling settings of the domain or even the user have an higher priority. But when I set the throttling of a domain or user at a higher value (for example 50 mails/minute), it won't work.

I can see that both quotas get tracked (in cluebringer DB), but it looks like the lowest limit matches - not matter where defined.

What am I missing?

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

**ZhangHuangbin** · 2015-03-13 08:26:05

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

*) Per-user throttling setting has higher priority than per-domain setting.
*) Please turn on debug mode in Cluebringer and send testing email, paste debug log in Cluebringer log file here so that others can help troubleshoot. Reference: http://www.iredmail.org/docs/debug.cluebringer.html

**frank.daeuble** · 2015-03-13 17:04:21

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

First of all: there is no start/stop scipt cbpolicyd - I changed the settings in /etc/cluebringer/cluebringer.conf and restarted iredapd.

Second: I get hundres of following line in /var/log/cbpolicyd.log:
"Use of uninitialized value $email_domain in lc at /usr/lib/postfix-cluebringer/cbp/policies.pm line 476, <$read> line 207415"

Finding the other relevant lines is very hard.

Besides that I found in syslog, where you can see, that both limits are tracked, but the lower global rule got matched:

Mar 13 09:49:50 host cbpolicyd[22867]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=mick.n@yyyyyy.de, reason=quota_update, policy=2, quota=8, limit=9, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=14/15 (94.5%)
Mar 13 09:49:50 host cbpolicyd[22867]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=mick.n@yyyyyy.de, reason=quota_update, policy=17, quota=15, limit=16, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=14/25 (56.7%)
Mar 13 09:49:51 host cbpolicyd[21335]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=mick.n@wwwww.net, reason=quota_update, policy=2, quota=8, limit=9, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=15/15 (99.6%)
Mar 13 09:49:51 host cbpolicyd[21335]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=mick.n@wwwww.net, reason=quota_update, policy=17, quota=15, limit=16, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=15/25 (59.8%)
Mar 13 09:49:52 host cbpolicyd[1526]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=tobias.k@wwwww.net, reason=quota_update, policy=2, quota=8, limit=9, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=16/15 (104.6%)
Mar 13 09:49:52 host cbpolicyd[1526]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=tobias.k@wwwww.net, reason=quota_update, policy=17, quota=15, limit=16, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=16/25 (62.8%)
Mar 13 09:49:53 host cbpolicyd[22924]: module=Quotas, action=reject, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=andreas.b@wwwww.net, reason=quota_match, policy=2, quota=8, limit=9, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=16/15 (109.6%)
Mar 13 09:49:53 host postfix/smtpd[23627]: 08E116008DE: reject: RCPT from unknown[217.7.160.170]: 554 5.7.1 <andreas.b@wwwww.net>: Recipient address rejected: Quota exceeded (15 messages in 60 seconds); from=<frank@xxxxx.net> to=<andreas.b@wwwww.net> proto=ESMTP helo=<[192.168.1.34]>

**ZhangHuangbin** · 2015-03-13 23:38:46

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

First of all: there is no start/stop scipt cbpolicyd - I changed the settings in /etc/cluebringer/cluebringer.conf and restarted iredapd.

On Debian, it's /etc/init.d/postfix-cluebringer.

frank.daeuble wrote:

Second: I get hundres of following line in /var/log/cbpolicyd.log:
"Use of uninitialized value $email_domain in lc at /usr/lib/postfix-cluebringer/cbp/policies.pm line 476, <$read> line 207415"

Not sure whether this error impacts throttling or not.

frank.daeuble wrote:

Besides that I found in syslog, where you can see, that both limits are tracked, but the lower global rule got matched:

You should paste debug log here so that others can help troubleshoot.

**frank.daeuble** · 2015-03-14 01:15:11

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Ok, now I activated debugging here is the log output ( I have removed our domain-names):

[2015/03/13-17:27:48 - 25319] [CBPOLICYD] NOTICE: Policyd v2 / Cluebringer - v2.0.11a-debian
[2015/03/13-17:27:48 - 25319] [CBPOLICYD] NOTICE: Initializing system modules.
[2015/03/13-17:27:48 - 25319] [CBPOLICYD] NOTICE: System modules initialized.
[2015/03/13-17:27:48 - 25319] [CBPOLICYD] NOTICE: Module load started...
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => AccessControl: enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => CheckHelo: enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => CheckSPF: enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => Greylisting: enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => Quotas: enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => Protocol(Postfix): enabled
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: => Protocol(Bizanga): enabled
[2015/03/13-17:27:48 - 25319] [CBPOLICYD] NOTICE: Module load done.
[2015/03/13-17:27:48 - 25319] [CBPOLICYD] DEBUG: Opening syslog, destination = 'native', facility = 'mail'.
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: 2015/03/13-17:27:48 cbp (type Net::Server::PreFork) starting! pid(25319)
[2015/03/13-17:27:48 - 25319] [CORE] NOTICE: Binding to TCP port 10031 on host 127.0.0.1 with IPv4
[2015/03/13-17:27:48 - 25319] [CORE] INFO: Setting up serialization via flock
[2015/03/13-17:27:48 - 25319] [CORE] INFO: Beginning prefork (4 processes)
[2015/03/13-17:27:48 - 25319] [CORE] INFO: Starting "4" children
[2015/03/13-17:27:48 - 25332] [CORE] DEBUG: Child Preforked (25332)
[2015/03/13-17:27:48 - 25332] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:27:48 - 25333] [CORE] DEBUG: Child Preforked (25333)
[2015/03/13-17:27:48 - 25333] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:27:48 - 25334] [CORE] DEBUG: Child Preforked (25334)
[2015/03/13-17:27:48 - 25319] [CORE] DEBUG: Parent ready for children.
[2015/03/13-17:27:48 - 25334] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:27:48 - 25335] [CORE] DEBUG: Child Preforked (25335)
[2015/03/13-17:27:48 - 25335] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:27:49 - 25333] [CORE] INFO: 2015/03/13-17:27:49 CONNECT TCP Peer: "[127.0.0.1]:60994" Local: "[127.0.0.1]:10031"
[2015/03/13-17:27:49 - 25319] [CORE] INFO: Starting "1" children
[2015/03/13-17:27:49 - 25333] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
[2015/03/13-17:27:49 - 25340] [CORE] DEBUG: Child Preforked (25340)
[2015/03/13-17:27:49 - 25340] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:27:49 - 25333] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
[2015/03/13-17:27:49 - 25333] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '1' in policy 'Default'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '10' in policy 'no_greylisting'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '11' in policy 'no_greylisting'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '14' in policy 'whitelists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '15' in policy 'blacklists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: Found policy member with ID '20' in policy 'throttle_outbound_b'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:1/Name:Default]: Source not defined or 'any', explicit match: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:1/Name:Default]: Source matching result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:1/Name:Default]: Destination not defined or 'any', explicit match: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:1/Name:Default]: Destination matching result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy destinations '%internal_domains'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 233 destination(s) => @xxx.biz,...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved destination '@xxx.biz' to a email address specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved destination '@xxx.net' to a email address specification, match = 1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Destination group result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Destination matching result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Source matching result: matched=1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy destinations '%no_greylisting_for_internal'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'no_greylisting_for_internal' has 3 destination(s) => ...
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): Destination group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Destination matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) =>
[2015/03/13-17:27:49 - 25333] [POLICIES] WARNING: [ID:11/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:11/Name:no_greylisting]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Main policy sources '%whitelists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Group 'whitelists' has 0 source(s) =>
[2015/03/13-17:27:49 - 25333] [POLICIES] WARNING: [ID:14/Name:whitelists]: No group members for source group 'whitelists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:14/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:14/Name:whitelists]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Main policy sources '%blacklists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Group 'blacklists' has 0 source(s) =>
[2015/03/13-17:27:49 - 25333] [POLICIES] WARNING: [ID:15/Name:blacklists]: No group members for source group 'blacklists'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:15/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:15/Name:blacklists]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy sources 'frank@xxx.net'
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 0
[2015/03/13-17:27:49 - 25333] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Source matching result: matched=0
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/03/13-17:27:49 - 25333] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 3
[2015/03/13-17:27:49 - 25333] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
[2015/03/13-17:27:49 - 25333] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/03/13-17:27:49 - 25333] [CHECKHELO] DEBUG: Updated timestamp for helo 'd12-holbi.co.uk' from address '109.169.50.57'
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/03/13-17:27:49 - 25333] [CBPOLICYD] DEBUG: Done with modules
[2015/03/13-17:28:19 - 25319] [CORE] INFO: Killing "1" children
[2015/03/13-17:28:19 - 25333] [CBPOLICYD] DEBUG: Shutting down caching engine (25333)
[2015/03/13-17:28:21 - 25319] [CORE] INFO: Starting "1" children
[2015/03/13-17:28:21 - 25335] [CORE] INFO: 2015/03/13-17:28:21 CONNECT TCP Peer: "[127.0.0.1]:32780" Local: "[127.0.0.1]:10031"
[2015/03/13-17:28:21 - 25419] [CORE] DEBUG: Child Preforked (25419)
[2015/03/13-17:28:21 - 25419] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '1' in policy 'Default'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '10' in policy 'no_greylisting'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '11' in policy 'no_greylisting'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '14' in policy 'whitelists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '15' in policy 'blacklists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: Found policy member with ID '20' in policy 'throttle_outbound_frank@xxx.net'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:1/Name:Default]: Source not defined or 'any', explicit match: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:1/Name:Default]: Source matching result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:1/Name:Default]: Destination not defined or 'any', explicit match: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:1/Name:Default]: Destination matching result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy destinations '%internal_domains'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 233 destination(s) => @xxx.biz,...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved destination '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Destination group result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Destination matching result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Source matching result: matched=1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy destinations '%no_greylisting_for_internal'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'no_greylisting_for_internal' has 3 destination(s) => ...
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): - Resolved destination ... to a email address specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:no_greylisting_for_internal): Destination group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Destination matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) =>
[2015/03/13-17:28:21 - 25335] [POLICIES] WARNING: [ID:11/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:11/Name:no_greylisting]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Main policy sources '%whitelists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Group 'whitelists' has 0 source(s) =>
[2015/03/13-17:28:21 - 25335] [POLICIES] WARNING: [ID:14/Name:whitelists]: No group members for source group 'whitelists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:14/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:14/Name:whitelists]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Main policy sources '%blacklists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Group 'blacklists' has 0 source(s) =>
[2015/03/13-17:28:21 - 25335] [POLICIES] WARNING: [ID:15/Name:blacklists]: No group members for source group 'blacklists'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:15/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:15/Name:blacklists]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy sources 'frank@xxx.net'
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 0
[2015/03/13-17:28:21 - 25335] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Source matching result: matched=0
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/03/13-17:28:21 - 25335] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 3
[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/03/13-17:28:21 - 25335] [CHECKHELO] DEBUG: Updated timestamp for helo 'pmta40176.emarsys.net' from address '91.211.240.176'
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/03/13-17:28:21 - 25335] [GREYLISTING] DEBUG: Updated greylisting triplet ('SenderIP:91.211.240.0/24',... , ...) @ 1426264101
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/03/13-17:28:21 - 25335] [CBPOLICYD] DEBUG: Done with modules
[2015/03/13-17:28:23 - 25332] [CORE] INFO: 2015/03/13-17:28:23 CONNECT TCP Peer: "[127.0.0.1]:32783" Local: "[127.0.0.1]:10031"
[2015/03/13-17:28:23 - 25332] [TRACKING] DEBUG: Protocol state is 'END-OF-MESSAGE', decoding policy...
[2015/03/13-17:28:23 - 25332] [TRACKING] DEBUG: Decoded into: $VAR1 = {
[2015/03/13-17:28:23 - 25332] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/03/13-17:28:23 - 25332] [CBPOLICYD] DEBUG: Done with modules
[2015/03/13-17:28:53 - 25319] [CORE] INFO: Killing "1" children
[2015/03/13-17:28:53 - 25335] [CBPOLICYD] DEBUG: Shutting down caching engine (25335)
[2015/03/13-17:29:21 - 25340] [CORE] INFO: 2015/03/13-17:29:21 CONNECT TCP Peer: "[127.0.0.1]:32794" Local: "[127.0.0.1]:10031"
[2015/03/13-17:29:21 - 25319] [CORE] INFO: Starting "1" children
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
[2015/03/13-17:29:21 - 25594] [CORE] DEBUG: Child Preforked (25594)

**ZhangHuangbin** · 2015-03-14 10:08:51

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

You omitted too many log in last post, for example:

[2015/03/13-17:28:21 - 25335] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {

What's the content inside the {} block?

**frank.daeuble** · 2015-03-16 18:27:12

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Ok, then here comes the following lines, I only removed the list of domains - there is no closing bracket in the logs:

[2015/03/13-17:29:21 - 25594] [CORE] DEBUG: Child Preforked (25594)
[2015/03/13-17:29:21 - 25594] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '1' in policy 'Default'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '10' in policy 'no_greylisting'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '11' in policy 'no_greylisting'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '14' in policy 'whitelists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '15' in policy 'blacklists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: Found policy member with ID '20' in policy 'throttle_outbound_frank@xxx.net'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:1/Name:Default]: Source not defined or 'any', explicit match: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:1/Name:Default]: Source matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:1/Name:Default]: Destination not defined or 'any', explicit match: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:1/Name:Default]: Destination matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy destinations '!%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 233 destination(s) => @xxx.biz,...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved destination '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Destination group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Destination matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 233 source(s) => @xxx.biz,@xxx.net,...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_domains' has 233 source(s) => @xxx.biz,@xxx.net,...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.biz' to a email address specification, match = 0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) =>
[2015/03/13-17:29:21 - 25340] [POLICIES] WARNING: [ID:11/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:11/Name:no_greylisting]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Main policy sources '%whitelists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Group 'whitelists' has 0 source(s) =>
[2015/03/13-17:29:21 - 25340] [POLICIES] WARNING: [ID:14/Name:whitelists]: No group members for source group 'whitelists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:14/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:14/Name:whitelists]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Main policy sources '%blacklists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Group 'blacklists' has 0 source(s) =>
[2015/03/13-17:29:21 - 25340] [POLICIES] WARNING: [ID:15/Name:blacklists]: No group members for source group 'blacklists'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:15/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:15/Name:blacklists]: Source matching result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy sources 'frank@xxx.net'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 1
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Source matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy destinations '!%internal_ips,!%internal_domains'
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_ips' has 1 destination(s) => 10.0.0.0/8
[2015/03/13-17:29:21 - 25340] [POLICIES] WARNING: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): - Destination '10.0.0.0/8' is not a valid specification
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): Destination group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_domains' has 233 destination(s) => @xxx.biz,...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): - Resolved destination '@xxx.biz' to a email address specification, match = 0
...
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): Destination group result: matched=0
[2015/03/13-17:29:21 - 25340] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Destination matching result: matched=1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 2
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=30 => policy ids: 17
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/03/13-17:29:21 - 25340] [CBPOLICYD] DEBUG: Running module: Quotas Plugin

**frank.daeuble** · 2015-03-23 16:15:34

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Did I miss something?

I know this is not urgent, but I would really appreciate any help to get this working.

**ZhangHuangbin** · 2015-03-23 16:46:53

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
[2015/03/13-17:29:21 - 25340] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {

Dear Frank,

Still missing debug message inside '$VAR1 = {}' block. Please try again and attach it.
We need this block to understand which policy (ordered by priority) will be applied to this outgoing email.

**frank.daeuble** · 2015-03-24 02:09:21

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Thanks for your answer and your patience!

I used grep to filter the logs, that removed the lines without timestamp. My Fault, sorry for that. Now I made a new testmail and found the lines:

[2015/03/23-18:54:46 - 25843] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
'0' => [
'1'
],
'30' => [
'17'
],
'10' => [
'2'
]
};
[2015/03/23-18:54:46 - 25843] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
'Recipient' => 'frank.daeuble@zzz.de',
'SASLUsername' => 'frank@xxx.net',
'QueueID' => '',
'RecipientData' => '',
'Instance' => '63ef.55105366.7410.0',
'EncryptionCipher' => 'ECDHE-RSA-AES128-SHA',
'Size' => '1403',
'EncryptionKeySize' => '128',
'ParsedClientAddress' => {
'Broadcast_Long' => 3641155754,
'Network' => 'xxxx',
'IP_Long' => 3641155754,
'Broadcast' => 'xxxx',
'IP' => 'xxxx',
'Mask_Long' => 4294967295,
'Network_Long' => 3641155754
},
'ProtocolTransport' => 'Postfix',
'EncryptionProtocol' => 'TLSv1',
'Helo' => '[192.168.1.34]',
'ClientAddress' => 'xxxx',
'ClientName' => 'unknown',
'Sender' => 'frank@xxx.net',
'SASLSender' => '',
'Timestamp' => 1427133286,
'ProtocolState' => 'RCPT',
'Policy' => {
'0' => [
'1'
],
'30' => [
'17'
],
'10' => [
'2'
]
},
'Protocol' => 'ESMTP',
'ClientReverseName' => 'unknown',
'SASLMethod' => 'PLAIN'
};

**ZhangHuangbin** · 2015-03-24 08:15:22

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 2
[2015/03/13-17:29:21 - 25340] [POLICIES] DEBUG: END RESULT: prio=30 => policy ids: 17

According to the debug message, Cluebringer find it matches 3 policies: policy id 1, 2, 17.
Policy id 1 is not set by iRedMail by default, policy id 2 is 'Default Outbound', but there's no policy id 17 in debug message.

Could you please try to empty throttling for this user, then re-enable it for this user? This step will make sure it has all required SQL records in Cluebringer database.

Next time, please paste FULL log related to testing email, do NOT use 'grep'.

**frank.daeuble** · 2015-03-24 23:42:58

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Yes, here are the three policies from the database:

ID Name Priority Description Disabled
1 Default 0 Default System Policy 0
2 Default Outbound 10 Default Outbound System Policy 0
17 throttle_outbound_frank@xxx.net 30 outbound_frank@xxx.net 0

So there you can see, 17 is the throtteling for the user with a hiher priority, but the policy 2 (throtteling for all) seems to match first.

I will try to make a new test, but I have to find a moment where there is not so much traffic on the mailserver...

**ZhangHuangbin** · 2015-03-25 07:29:35

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

According to Policyd document: http://wiki.policyd.org/policies#priorities

Priorities are processed in an ascending fashion, this means that 0 will be processed before 1, 10 before 20 etc.

But we still need the FULL debug log to see how Cluebringer processes this smtp session.

**frank.daeuble** · 2015-04-23 16:06:42

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Sorry for the late response - now I was able to make some more test and researches.

Your last post about processing the Priorities was very helpful. That is the reason why the Default_Outboud Policy match before the user-based one. But why does a user-based (also a domain) policy gets a higher Priority value (always 30) ? Because of that the user-based will never match before the default.

By the way: You said Policy 1 was not set by iRedMail, but I haven't set it either?

And here is a full debug log:

[2015/04/22-23:08:33 - 12277] [CORE] NOTICE: Process Backgrounded
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] NOTICE: Policyd v2 / Cluebringer - v2.0.11a-debian
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] NOTICE: Initializing system modules.
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] NOTICE: System modules initialized.
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] NOTICE: Module load started...
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => AccessControl: enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => CheckHelo: enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => CheckSPF: enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => Greylisting: enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => Quotas: enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => Protocol(Postfix): enabled
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE:   => Protocol(Bizanga): enabled
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] NOTICE: Module load done.
[2015/04/22-23:08:33 - 12277] [CBPOLICYD] DEBUG: Opening syslog, destination = 'native', facility = 'mail'.
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE: 2015/04/22-23:08:33 cbp (type Net::Server::PreFork) starting! pid(12277)
[2015/04/22-23:08:33 - 12277] [CORE] NOTICE: Binding to TCP port 10031 on host 127.0.0.1 with IPv4
[2015/04/22-23:08:33 - 12277] [CORE] INFO: Setting up serialization via flock
[2015/04/22-23:08:33 - 12277] [CORE] INFO: Beginning prefork (4 processes)
[2015/04/22-23:08:33 - 12277] [CORE] INFO: Starting "4" children
[2015/04/22-23:08:33 - 12290] [CORE] DEBUG: Child Preforked (12290)
[2015/04/22-23:08:33 - 12290] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/04/22-23:08:33 - 12291] [CORE] DEBUG: Child Preforked (12291)
[2015/04/22-23:08:33 - 12291] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/04/22-23:08:33 - 12292] [CORE] DEBUG: Child Preforked (12292)
[2015/04/22-23:08:33 - 12277] [CORE] DEBUG: Parent ready for children.
[2015/04/22-23:08:33 - 12292] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/04/22-23:08:33 - 12293] [CORE] DEBUG: Child Preforked (12293)
[2015/04/22-23:08:33 - 12293] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/04/22-23:08:36 - 12277] [CORE] INFO: Starting "1" children
[2015/04/22-23:08:36 - 12290] [CORE] INFO: 2015/04/22-23:08:36 CONNECT TCP Peer: "[127.0.0.1]:40702" Local: "[127.0.0.1]:10031"
[2015/04/22-23:08:36 - 12329] [CORE] DEBUG: Child Preforked (12329)
[2015/04/22-23:08:36 - 12329] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/04/22-23:08:36 - 12290] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => '456',
          '_timestamp' => 1429736916,
          'helo_name' => '[192.168.1.34]',
          'reverse_client_name' => 'unknown',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES128-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'frank@xxx.net',
          'recipient' => 'xxx@gmx.de',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '3022.55380dd4.aa81d.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '128',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'frank@xxx.net',
          'client_name' => 'unknown',
          'client_address' => 'x.x.x.x',
          '_protocol_transport' => 'Postfix'
        };
[2015/04/22-23:08:36 - 12290] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => '456',
          '_timestamp' => 1429736916,
          'helo_name' => '[192.168.1.34]',
          'reverse_client_name' => 'unknown',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES128-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'frank@xxx.net',
          'recipient' => 'xxx@gmx.de',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '3022.55380dd4.aa81d.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '128',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'frank@xxx.net',
          'client_name' => 'unknown',
          'client_address' => 'x.x.x.x',
          '_protocol_transport' => 'Postfix'
        };
[2015/04/22-23:08:36 - 12290] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
          'Recipient' => 'xxx@gmx.de',
          'SASLUsername' => 'frank@xxx.net',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '3022.55380dd4.aa81d.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES128-SHA',
          'Size' => '456',
          'EncryptionKeySize' => '128',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '[192.168.1.34]',
          'ClientAddress' => 'x.x.x.x',
          'ClientName' => 'unknown',
          'Sender' => 'frank@xxx.net',
          'SASLSender' => '',
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'unknown',
          'SASLMethod' => 'PLAIN'
        };
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '1' in policy 'Default'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '10' in policy 'no_greylisting'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '11' in policy 'no_greylisting'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '14' in policy 'whitelists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '15' in policy 'blacklists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: Found policy member with ID '20' in policy 'throttle_outbound_frank@xxx.net'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:1/Name:Default]: Source not defined or 'any', explicit match: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:1/Name:Default]: Source matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:1/Name:Default]: Destination not defined or 'any', explicit match: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:1/Name:Default]: Destination matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 239 source(s) => @xxx.net, ...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@yyy.biz' to a email address specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy destinations '!%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 239 destination(s) => @xxx.net, ...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved destination '@yyy.biz' to a email address specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved destination '@xxx.net' to a email address specification, match = 0
...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Destination group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Destination matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 239 source(s) => @xxx.net, ...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@yyy.biz' to a email address specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_domains' has 239 source(s) => @xxx.net, ...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@yyy.biz' to a email address specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) => 
[2015/04/22-23:08:36 - 12290] [POLICIES] WARNING: [ID:11/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:11/Name:no_greylisting]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Main policy sources '%whitelists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Group 'whitelists' has 0 source(s) => 
[2015/04/22-23:08:36 - 12290] [POLICIES] WARNING: [ID:14/Name:whitelists]: No group members for source group 'whitelists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:14/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:14/Name:whitelists]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Main policy sources '%blacklists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Group 'blacklists' has 0 source(s) => 
[2015/04/22-23:08:36 - 12290] [POLICIES] WARNING: [ID:15/Name:blacklists]: No group members for source group 'blacklists'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:15/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:15/Name:blacklists]: Source matching result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy sources 'frank@xxx.net'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 1
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Source matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy destinations '!%internal_ips,!%internal_domains'
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_ips' has 1 destination(s) => 10.0.0.0/8
[2015/04/22-23:08:36 - 12290] [POLICIES] WARNING: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): - Destination '10.0.0.0/8' is not a valid specification
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): Destination group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_domains' has 239 destination(s) => @xxx.net, ...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): - Resolved destination '@yyy.biz' to a email address specification, match = 0
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): - Resolved destination '@xxx.net' to a email address specification, match = 0
...
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): Destination group result: matched=0
[2015/04/22-23:08:36 - 12290] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Destination matching result: matched=1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 2
[2015/04/22-23:08:36 - 12290] [POLICIES] DEBUG: END RESULT: prio=30 => policy ids: 17
[2015/04/22-23:08:36 - 12290] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
          '0' => [
                   '1'
                 ],
          '30' => [
                    '17'
                  ],
          '10' => [
                    '2'
                  ]
        };
[2015/04/22-23:08:36 - 12290] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'Recipient' => 'xxx@gmx.de',
          'SASLUsername' => 'frank@xxx.net',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '3022.55380dd4.aa81d.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES128-SHA',
          'Size' => '456',
          'EncryptionKeySize' => '128',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 3641155754,
                                     'Network' => 'x.x.x.x',
                                     'IP_Long' => 3641155754,
                                     'Broadcast' => 'x.x.x.x',
                                     'IP' => 'x.x.x.x',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 3641155754
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '[192.168.1.34]',
          'ClientAddress' => 'x.x.x.x',
          'ClientName' => 'unknown',
          'Sender' => 'frank@xxx.net',
          'SASLSender' => '',
          'Timestamp' => 1429736916,
          'ProtocolState' => 'RCPT',
          'Policy' => {
                        '0' => [
                                 '1'
                               ],
                        '30' => [
                                  '17'
                                ],
                        '10' => [
                                  '2'
                                ]
                      },
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'unknown',
          'SASLMethod' => 'PLAIN'
        };
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/04/22-23:08:36 - 12290] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/04/22-23:08:37 - 12290] [CBPOLICYD] DEBUG: Done with modules
[2015/04/22-23:08:38 - 12292] [CORE] INFO: 2015/04/22-23:08:38 CONNECT TCP Peer: "[127.0.0.1]:40704" Local: "[127.0.0.1]:10031"
[2015/04/22-23:08:38 - 12292] [TRACKING] DEBUG: Protocol state is 'END-OF-MESSAGE', decoding policy...
[2015/04/22-23:08:38 - 12292] [TRACKING] DEBUG: Decoded into: $VAR1 = {
          'xxx@gmx.de' => {
                                '0' => [
                                         '1'
                                       ],
                                '30' => [
                                          '17'
                                        ],
                                '10' => [
                                          '2'
                                        ]
                              }
        };
[2015/04/22-23:08:38 - 12292] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'SASLUsername' => 'frank@xxx.net',
          'QueueID' => '19FE660070E',
          'RecipientData' => '/<xxx@gmx.de>#0=1;30=17;10=2;',
          'EncryptionCipher' => 'ECDHE-RSA-AES128-SHA',
          'Instance' => '3022.55380dd4.aa81d.0',
          'Size' => '456',
          'EncryptionKeySize' => '128',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 3641155754,
                                     'Network' => 'x.x.x.x',
                                     'IP_Long' => 3641155754,
                                     'Broadcast' => 'x.x.x.x',
                                     'IP' => 'x.x.x.x',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 3641155754
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '[192.168.1.34]',
          'ClientAddress' => 'x.x.x.x',
          'ClientName' => 'unknown',
          'Sender' => 'frank@xxx.net',
          'SASLSender' => '',
          'Timestamp' => 1429736918,
          'ProtocolState' => 'END-OF-MESSAGE',
          '_Recipient_To_Policy' => {
                                      'xxx@gmx.de' => {
                                                            '0' => [
                                                                     '1'
                                                                   ],
                                                            '30' => [
                                                                      '17'
                                                                    ],
                                                            '10' => [
                                                                      '2'
                                                                    ]
                                                          }
                                    },
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'unknown',
          'SASLMethod' => 'PLAIN'
        };
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/04/22-23:08:38 - 12292] [CBPOLICYD] DEBUG: Done with modules

**ZhangHuangbin** · 2015-04-23 19:57:36

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

Mar 13 09:49:52 host cbpolicyd[1526]: module=Quotas, mode=update, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=tobias.k@wwwww.net, reason=quota_update, policy=17, quota=15, limit=16, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=16/25 (62.8%)
Mar 13 09:49:53 host cbpolicyd[22924]: module=Quotas, action=reject, host=217.7.160.170, helo=[192.168.1.34], from=frank@xxxxx.net, to=andreas.b@wwwww.net, reason=quota_match, policy=2, quota=8, limit=9, track=Sender:frank@xxxxx.net, counter=MessageCount, quota=16/15 (109.6%)

I can see you have per-user throttling to 16 messages, default outbound throttling to 9 messages.

I will try to reproduce this issue and come back later.

**ZhangHuangbin** · 2015-04-24 11:47:11

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

I have set a global throttling of 15 mail / minute. Now I want to set a higher throttling for one user or domain.

Throttling works for me here. Priority: per-user > per-domain > global setting.

I tested with a per-domain setting (4 mails max per hour), and a per-user setting (15 mails max per hour), Cluebringer uses only per-user setting.

No idea why it doesn't work for you, i suggest you delete related log in SQL table `cluebringer.quotas_tracking`, and try again.
Also, could you please show us output of below commands?

# postconf smtpd_recipient_restrictions
# postconf smtpd_end_of_data_restrictions

**frank.daeuble** · 2015-04-24 15:45:07

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

Thanks for your Testing and strange, it is working for you but not for us?

Can I delete all records in cluebringer.quotas_tracking?

smtpd_recipient_restrictions = reject_unknown_sender_domain, reject_unknown_recipient_domain, reject_non_fqdn_sender, reject_non_fqdn_recipient, reject_unlisted_recipient, check_policy_service inet:127.0.0.1:7777, check_policy_service inet:127.0.0.1:10031, permit_mynetworks, permit_sasl_authenticated, reject_rbl_client b.barracudacentral.org, reject_unauth_destination

smtpd_end_of_data_restrictions = check_policy_service inet:127.0.0.1:10031

**ZhangHuangbin** · 2015-04-24 16:11:14

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

Can I delete all records in cluebringer.quotas_tracking?

Yes.

Your Postfix setting is fine.

**frank.daeuble** · 2015-08-28 22:28:42

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

While being busy in the meantime, I now updated to iredmail 0.9.2 and to iRedAdminPro SQL 2.1.3

I now also deleted all records in cluebringer.quotas_tracking, but again both poicies are matched and the Default Outbound is used before the per-user one.

So sadly the same issue still exist. Any further ideas?

**ZhangHuangbin** · 2015-08-29 10:19:42

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Unterstand throttling

frank.daeuble wrote:

I now also deleted all records in cluebringer.quotas_tracking, but again both poicies are matched and the Default Outbound is used before the per-user one.

per-user throttling has higher priority, why 'Default Outbound' is used before per-user throttling? Could you please show us related debug log?

**frank.daeuble** · 2015-09-02 01:58:33

frank.daeuble
Member
Offline

Registered: 2013-10-14
Posts: 37

Re: Unterstand throttling

The log output has not changed, here is a new one with the same result:

let me know if I can do anything further

[2015/09/01-19:18:35 - 13499] [CORE] NOTICE: Process Backgrounded
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] NOTICE: Policyd v2 / Cluebringer - v2.0.11a-debian
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] NOTICE: Initializing system modules.
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] NOTICE: System modules initialized.
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] NOTICE: Module load started...
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => AccessControl: enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => CheckHelo: enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => CheckSPF: enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => Greylisting: enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => Quotas: enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => Protocol(Postfix): enabled
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE:   => Protocol(Bizanga): enabled
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] NOTICE: Module load done.
[2015/09/01-19:18:35 - 13499] [CBPOLICYD] DEBUG: Opening syslog, destination = 'native', facility = 'mail'.
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE: 2015/09/01-19:18:35 cbp (type Net::Server::PreFork) starting! pid(13499)
[2015/09/01-19:18:35 - 13499] [CORE] NOTICE: Binding to TCP port 10031 on host 127.0.0.1 with IPv4
[2015/09/01-19:18:35 - 13499] [CORE] INFO: Setting up serialization via flock
[2015/09/01-19:18:35 - 13499] [CORE] INFO: Beginning prefork (4 processes)
[2015/09/01-19:18:35 - 13499] [CORE] INFO: Starting "4" children
[2015/09/01-19:18:35 - 13513] [CORE] DEBUG: Child Preforked (13513)
[2015/09/01-19:18:35 - 13513] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/09/01-19:18:35 - 13514] [CORE] DEBUG: Child Preforked (13514)
[2015/09/01-19:18:35 - 13514] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/09/01-19:18:35 - 13515] [CORE] DEBUG: Child Preforked (13515)
[2015/09/01-19:18:35 - 13515] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/09/01-19:18:35 - 13499] [CORE] DEBUG: Parent ready for children.
[2015/09/01-19:18:35 - 13516] [CORE] DEBUG: Child Preforked (13516)
[2015/09/01-19:18:35 - 13516] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/09/01-19:19:16 - 13499] [CORE] INFO: Starting "1" children
[2015/09/01-19:19:16 - 13514] [CORE] INFO: 2015/09/01-19:19:16 CONNECT TCP Peer: "[127.0.0.1]:34407" Local: "[127.0.0.1]:10031"
[2015/09/01-19:19:16 - 13664] [CORE] DEBUG: Child Preforked (13664)
[2015/09/01-19:19:16 - 13664] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/09/01-19:19:16 - 13514] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => '1330',
          '_timestamp' => 1441127956,
          'helo_name' => '[192.168.1.34]',
          'reverse_client_name' => 'unknown',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES128-GCM-SHA256',
          'encryption_protocol' => 'TLSv1.2',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'frank@xxx.net',
          'recipient' => 'nadine@zzz.net',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '355f.55e5de14.d17ee.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '128',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'frank@xxx.net',
          'client_name' => 'unknown',
          'client_address' => 'x.x.x.170',
          '_protocol_transport' => 'Postfix'
        };
[2015/09/01-19:19:16 - 13514] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'PLAIN',
          'sasl_sender' => '',
          'size' => '1330',
          '_timestamp' => 1441127956,
          'helo_name' => '[192.168.1.34]',
          'reverse_client_name' => 'unknown',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES128-GCM-SHA256',
          'encryption_protocol' => 'TLSv1.2',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'frank@xxx.net',
          'recipient' => 'nadine@zzz.net',
          'ccert_pubkey_fingerprint' => '',
          'instance' => '355f.55e5de14.d17ee.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '128',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'frank@xxx.net',
          'client_name' => 'unknown',
          'client_address' => 'x.x.x.170',
          '_protocol_transport' => 'Postfix'
        };
[2015/09/01-19:19:17 - 13514] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
          'Recipient' => 'nadine@zzz.net',
          'SASLUsername' => 'frank@xxx.net',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '355f.55e5de14.d17ee.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES128-GCM-SHA256',
          'Size' => '1330',
          'EncryptionKeySize' => '128',
          'EncryptionProtocol' => 'TLSv1.2',
          'Helo' => '[192.168.1.34]',
          'ClientAddress' => 'x.x.x.170',
          'ClientName' => 'unknown',
          'Sender' => 'frank@xxx.net',
          'SASLSender' => '',
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'unknown',
          'SASLMethod' => 'PLAIN'
        };
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '1' in policy 'Default'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '10' in policy 'no_greylisting'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '11' in policy 'no_greylisting'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '14' in policy 'whitelists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '15' in policy 'blacklists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '20' in policy 'throttle_outbound_frank@xxx.net'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: Found policy member with ID '21' in policy 'throttle_outbound_xxx.net'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:1/Name:Default]: Source not defined or 'any', explicit match: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:1/Name:Default]: Source matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:1/Name:Default]: Destination not defined or 'any', explicit match: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:1/Name:Default]: Destination matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 255 source(s) => ...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy destinations '!%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 255 destination(s) => ...
...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Destination group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Destination matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 255 source(s) => ...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]: Group 'internal_domains' has 255 source(s) => ...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:10/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:10/Name:no_greylisting]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) => 
[2015/09/01-19:19:17 - 13514] [POLICIES] WARNING: [ID:11/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:11/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:11/Name:no_greylisting]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Main policy sources '%whitelists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:14/Name:whitelists]: Group 'whitelists' has 0 source(s) => 
[2015/09/01-19:19:17 - 13514] [POLICIES] WARNING: [ID:14/Name:whitelists]: No group members for source group 'whitelists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:14/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:14/Name:whitelists]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Main policy sources '%blacklists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:15/Name:blacklists]: Group 'blacklists' has 0 source(s) => 
[2015/09/01-19:19:17 - 13514] [POLICIES] WARNING: [ID:15/Name:blacklists]: No group members for source group 'blacklists'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:15/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:15/Name:blacklists]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy sources 'frank@xxx.net'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Source matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Main policy destinations '!%internal_ips,!%internal_domains'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_ips' has 1 destination(s) => 10.0.0.0/8
[2015/09/01-19:19:17 - 13514] [POLICIES] WARNING: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): - Destination '10.0.0.0/8' is not a valid specification
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_ips): Destination group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]: Group 'internal_domains' has 255 destination(s) => ...
...
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:20/Name:throttle_outbound_frank@xxx.net]=>(group:internal_domains): Destination group result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:20/Name:throttle_outbound_frank@xxx.net]: Destination matching result: matched=1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:21/Name:throttle_outbound_xxx.net]: Main policy sources '@xxx.net,!frank@xxx.net'
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:21/Name:throttle_outbound_xxx.net]: - Resolved source '@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: [ID:21/Name:throttle_outbound_xxx.net]: - Resolved source 'frank@xxx.net' to a email address specification, match = 1
[2015/09/01-19:19:17 - 13514] [POLICIES] INFO: [ID:21/Name:throttle_outbound_xxx.net]: Source matching result: matched=0
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: END RESULT: prio=0 => policy ids: 1
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: END RESULT: prio=10 => policy ids: 2
[2015/09/01-19:19:17 - 13514] [POLICIES] DEBUG: END RESULT: prio=30 => policy ids: 17
[2015/09/01-19:19:17 - 13514] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {
          '0' => [
                   '1'
                 ],
          '30' => [
                    '17'
                  ],
          '10' => [
                    '2'
                  ]
        };
[2015/09/01-19:19:17 - 13514] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'Recipient' => 'nadine@zzz.net',
          'SASLUsername' => 'frank@xxx.net',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => '355f.55e5de14.d17ee.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES128-GCM-SHA256',
          'Size' => '1330',
          'EncryptionKeySize' => '128',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 3641155754,
                                     'Network' => 'x.x.x.170',
                                     'IP_Long' => 3641155754,
                                     'Broadcast' => 'x.x.x.170',
                                     'IP' => 'x.x.x.170',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 3641155754
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1.2',
          'Helo' => '[192.168.1.34]',
          'ClientAddress' => 'x.x.x.170',
          'ClientName' => 'unknown',
          'Sender' => 'frank@xxx.net',
          'SASLSender' => '',
          'Timestamp' => 1441127956,
          'ProtocolState' => 'RCPT',
          'Policy' => {
                        '0' => [
                                 '1'
                               ],
                        '30' => [
                                  '17'
                                ],
                        '10' => [
                                  '2'
                                ]
                      },
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'unknown',
          'SASLMethod' => 'PLAIN'
        };
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/09/01-19:19:17 - 13514] [CBPOLICYD] DEBUG: Done with modules

Aug 5, 2024: iRedMail-1.7.1 has been released.

Unterstand throttling

Posts: 21

1 Topic by frank.daeuble 2015-03-13 00:51:38

Topic: Unterstand throttling

2 Reply by ZhangHuangbin 2015-03-13 08:26:05

Re: Unterstand throttling

3 Reply by frank.daeuble 2015-03-13 17:04:21 (edited by frank.daeuble 2015-03-13 21:01:29)

Re: Unterstand throttling

4 Reply by ZhangHuangbin 2015-03-13 23:38:46

Re: Unterstand throttling

5 Reply by frank.daeuble 2015-03-14 01:15:11

Re: Unterstand throttling

6 Reply by ZhangHuangbin 2015-03-14 10:08:51

Re: Unterstand throttling

7 Reply by frank.daeuble 2015-03-16 18:27:12

Re: Unterstand throttling

8 Reply by frank.daeuble 2015-03-23 16:15:34

Re: Unterstand throttling

9 Reply by ZhangHuangbin 2015-03-23 16:46:53

Re: Unterstand throttling

10 Reply by frank.daeuble 2015-03-24 02:09:21

Re: Unterstand throttling

11 Reply by ZhangHuangbin 2015-03-24 08:15:22

Re: Unterstand throttling

12 Reply by frank.daeuble 2015-03-24 23:42:58

Re: Unterstand throttling

13 Reply by ZhangHuangbin 2015-03-25 07:29:35

Re: Unterstand throttling

14 Reply by frank.daeuble 2015-04-23 16:06:42

Re: Unterstand throttling

15 Reply by ZhangHuangbin 2015-04-23 19:57:36

Re: Unterstand throttling

16 Reply by ZhangHuangbin 2015-04-24 11:47:11

Re: Unterstand throttling

17 Reply by frank.daeuble 2015-04-24 15:45:07

Re: Unterstand throttling

18 Reply by ZhangHuangbin 2015-04-24 16:11:14

Re: Unterstand throttling

19 Reply by frank.daeuble 2015-08-28 22:28:42

Re: Unterstand throttling

20 Reply by ZhangHuangbin 2015-08-29 10:19:42

Re: Unterstand throttling

21 Reply by frank.daeuble 2015-09-02 01:58:33

Re: Unterstand throttling

Posts: 21