1 Topic by Dominique (edited by Dominique 2015-05-19 01:11:05)

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Topic: Cluebringer not tracking

==== Required information ====
- iRedMail version: 0.9.1
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MariaDB
- Web server (Apache or Nginx): Nginx
- Linux/BSD distribution name and version: CentOS 7
- Related log if you're reporting an issue:
====

I set global throttling using iRedAdmin-Pro 2.0 to max 5 emails per day and then tried sending more than 5 emails with a single account, which worked.  Cluebringer didn't stop me and when I check the database it seems like Cluebringer is not even tracking the outgoing emails:

MariaDB [cluebringer]> select * from quotas;
+----+----------+------------------+--------------------+--------+---------+----------------------------------------------+---------+----------+
| ID | PolicyID | Name             | Track              | Period | Verdict | Data                                         | Comment | Disabled |
+----+----------+------------------+--------------------+--------+---------+----------------------------------------------+---------+----------+
|  1 |        2 | default_outbound | Sender:user@domain |  86400 | reject  | Quota exceeded (5 messages in 86400 seconds) | NULL    |        0 |
+----+----------+------------------+--------------------+--------+---------+----------------------------------------------+---------+----------+
1 row in set (0.00 sec)

MariaDB [cluebringer]> select * from quotas_limits;
+----+----------+--------------+--------------+---------+----------+
| ID | QuotasID | Type         | CounterLimit | Comment | Disabled |
+----+----------+--------------+--------------+---------+----------+
|  1 |        1 | MessageCount |            5 | NULL    |        0 |
+----+----------+--------------+--------------+---------+----------+
1 row in set (0.00 sec)

MariaDB [cluebringer]> select * from quotas_tracking;
Empty set (0.00 sec)


I got this to work on a previous installation but I had to manually configure it using the cluebringer UI.. which I don't have now, as I'm using Nginx and I won't install Apache just for this.  It was the only solution on the old version as RedAdmin-Pro didn't support global throttling yet.

----

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

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,094

Re: Cluebringer not tracking

Records in `quotas` and `quotas_limits` looks fine. Could you please help gather below info to help troubleshoot?

*) turn on debug mode in Cluebringer. Document: http://www.iredmail.org/docs/debug.cluebringer.html
*) send one more testing email.
*) Check cluebringer log file (/var/log/cbpolicyd.log), and paste all log content related to this testing email.

3 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

The log file:

[2015/05/18-13:38:04 - 1132] [CORE] NOTICE: Process Backgrounded
[2015/05/18-13:38:04 - 1132] [CBPOLICYD] NOTICE: Policyd v2 / Cluebringer - v2.0.14-1
[2015/05/18-13:38:04 - 1132] [CBPOLICYD] NOTICE: Initializing system modules.
[2015/05/18-13:38:04 - 1132] [CBPOLICYD] NOTICE: System modules initialized.
[2015/05/18-13:38:04 - 1132] [CBPOLICYD] NOTICE: Module load started...
[2015/05/18-13:38:04 - 1132] [CORE] NOTICE:   => AccessControl: enabled
[2015/05/18-13:38:05 - 1132] [CORE] NOTICE:   => CheckHelo: enabled
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE:   => CheckSPF: enabled
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE:   => Greylisting: enabled
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE:   => Quotas: enabled
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE:   => Protocol(Postfix): enabled
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE:   => Protocol(Bizanga): enabled
[2015/05/18-13:38:06 - 1132] [CBPOLICYD] NOTICE: Module load done.
[2015/05/18-13:38:06 - 1132] [CBPOLICYD] DEBUG: Opening syslog, destination = 'native', facility = 'mail'.
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE: 2015/05/18-13:38:06 cbp (type Net::Server::PreFork) starting! pid(1132)
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE: Binding to TCP port 10031 on host 127.0.0.1 with IPv4
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE: Setting gid to "2003 2003"
[2015/05/18-13:38:06 - 1132] [CORE] NOTICE: Setting uid to "2003"
[2015/05/18-13:38:06 - 1132] [CORE] INFO: Setting up serialization via flock
[2015/05/18-13:38:06 - 1132] [CORE] INFO: Beginning prefork (4 processes)
[2015/05/18-13:38:06 - 1132] [CORE] INFO: Starting "4" children
[2015/05/18-13:38:06 - 1132] [CORE] DEBUG: Parent ready for children.
[2015/05/18-13:38:06 - 1287] [CORE] DEBUG: Child Preforked (1287)
[2015/05/18-13:38:06 - 1287] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-13:38:07 - 1297] [CORE] DEBUG: Child Preforked (1297)
[2015/05/18-13:38:07 - 1297] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-13:38:07 - 1295] [CORE] DEBUG: Child Preforked (1295)
[2015/05/18-13:38:07 - 1295] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-13:38:07 - 1296] [CORE] DEBUG: Child Preforked (1296)
[2015/05/18-13:38:07 - 1296] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-13:38:07 - 1287] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to MySQL server on '127.0.0.1' (111) (1287)
[2015/05/18-13:38:07 - 1297] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to MySQL server on '127.0.0.1' (111) (1297)
[2015/05/18-13:38:07 - 1295] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to MySQL server on '127.0.0.1' (111) (1295)
[2015/05/18-13:38:07 - 1296] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to MySQL server on '127.0.0.1' (111) (1296)
[2015/05/18-13:39:23 - 1287] [CORE] INFO: 2015/05/18-13:39:23 CONNECT TCP Peer: "[127.0.0.1]:58184" Local: "[127.0.0.1]:10031"
[2015/05/18-13:39:23 - 1287] [CBPOLICYD] WARNING: Client in BYPASS mode due to DB connection failure!
[2015/05/18-13:39:23 - 1287] [CBPOLICYD] NOTICE: Client BYPASS timeout exceeded, reconnecting...
[2015/05/18-13:39:23 - 1132] [CORE] INFO: Starting "1" children
[2015/05/18-13:39:23 - 2626] [CORE] DEBUG: Child Preforked (2626)
[2015/05/18-13:39:23 - 2626] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-13:39:24 - 1297] [CORE] INFO: 2015/05/18-13:39:24 CONNECT TCP Peer: "[127.0.0.1]:58190" Local: "[127.0.0.1]:10031"
[2015/05/18-13:39:24 - 1297] [CBPOLICYD] WARNING: Client in BYPASS mode due to DB connection failure!
[2015/05/18-13:39:24 - 1297] [CBPOLICYD] NOTICE: Client BYPASS timeout exceeded, reconnecting...
[2015/05/18-13:39:24 - 1132] [CORE] INFO: Starting "1" children
[2015/05/18-13:39:24 - 2634] [CORE] DEBUG: Child Preforked (2634)
[2015/05/18-13:39:24 - 2634] [CBPOLICYD] DEBUG: Starting up caching engine

Seems like there's a database connection problem. It's a fresh install and I didn't change anything related.

Cheers

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,094

Re: Cluebringer not tracking

Dominique wrote:

[2015/05/18-13:38:07 - 1287] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to MySQL server on '127.0.0.1' (111) (1287)

Please start MySQL service first.

Did you reboot server after iRedMail installation?

5 Reply by Dominique (edited by Dominique 2015-05-18 21:16:51)

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

The server was restarted multiple times already... and MariaDB is always running... as you can see in the query results I showed in my original post and the fact that I managed to use iRedAdmin-Pro

I just tried again sending an email after 100% assuring that MariaDB is running and this was the result in the log file:

[2015/05/18-14:12:18 - 1295] [CORE] INFO: 2015/05/18-14:12:18 CONNECT TCP Peer: "[127.0.0.1]:58312" Local: "[127.0.0.1]:10031"
[2015/05/18-14:12:18 - 1295] [CBPOLICYD] WARNING: Client in BYPASS mode due to DB connection failure!
[2015/05/18-14:12:18 - 1132] [CORE] INFO: Starting "1" children
[2015/05/18-14:12:18 - 2821] [CORE] DEBUG: Child Preforked (2821)
[2015/05/18-14:12:18 - 2821] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-14:12:18 - 1295] [CBPOLICYD] NOTICE: Client BYPASS timeout exceeded, reconnecting...
[2015/05/18-14:12:19 - 1296] [CORE] INFO: 2015/05/18-14:12:19 CONNECT TCP Peer: "[127.0.0.1]:58318" Local: "[127.0.0.1]:10031"
[2015/05/18-14:12:19 - 1296] [CBPOLICYD] WARNING: Client in BYPASS mode due to DB connection failure!
[2015/05/18-14:12:19 - 1296] [CBPOLICYD] NOTICE: Client BYPASS timeout exceeded, reconnecting...
[2015/05/18-14:12:19 - 1132] [CORE] INFO: Starting "1" children
[2015/05/18-14:12:19 - 2829] [CORE] DEBUG: Child Preforked (2829)
[2015/05/18-14:12:19 - 2829] [CBPOLICYD] DEBUG: Starting up caching engine

6 Reply by mir

  • mir
  • Member
  • Offline
  • Registered: 2014-05-30
  • Posts: 170

Re: Cluebringer not tracking

Dominique wrote:

[2015/05/18-14:12:19 - 1296] [CBPOLICYD] WARNING: Client in BYPASS mode due to DB connection failure!

It might be true that MariaDB is always running but cluebringer is not able to connect to the database which means every connection is passed through (Client in BYPASS mode).

7 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

I than tried changing the cluebringer config to connect to localhost instead of 127.0.0.1, giving me the following error:

[2015/05/18-14:58:59 - 1211] [CBPOLICYD] WARNING: Failed to connect to database: Error connecting to database: Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (2) (1211)

so I checked for all sockets using  "find / -type s", which returns this:
/var/lib/mysql/mysql.sock

so the socket does exist

@mir  That is the problem, yes.. but I'm looking for a solution

8 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

Now Cluebringer seems to be able to connect to the database... but it's still not tracking the quota.

Could it have anything to do with the fact that the rules were added after the vmail database was imported?  When I check the rest of the tables I can't find any reference to the domains configured... while on the previous server there were records per domain.  All tables with groups and members in the names are empty... maybe because the users were imported instead of added.

The log file:
[2015/05/18-15:19:53 - 2630] [CORE] INFO: 2015/05/18-15:19:53 CONNECT TCP Peer: "[127.0.0.1]:47841" Local: "[127.0.0.1]:10031"
[2015/05/18-15:19:53 - 1121] [CORE] INFO: Starting "1" children
[2015/05/18-15:19:53 - 2735] [CORE] DEBUG: Child Preforked (2735)
[2015/05/18-15:19:53 - 2735] [CBPOLICYD] DEBUG: Starting up caching engine
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: No session tracking data exists for request: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'LOGIN',
          'sasl_sender' => '',
          'size' => 0,
          '_timestamp' => 1431958793,
          'helo_name' => '_',
          'reverse_client_name' => 'email',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES256-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'xxxxxx@xxxxxx.es',
          'recipient' => 'xxxxxx@xxxxxx.be',
          'ccert_pubkey_fingerprint' => '',
          'instance' => 'aaa.5559f509.4a694.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '256',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'xxxxxx@xxxxxx.es',
          'client_name' => 'email',
          'client_address' => '127.0.0.1',
          '_protocol_transport' => 'Postfix'
        };
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Added session tracking information for: $VAR1 = {
          'ccert_fingerprint' => '',
          'sasl_method' => 'LOGIN',
          'sasl_sender' => '',
          'size' => 0,
          '_timestamp' => 1431958793,
          'helo_name' => '_',
          'reverse_client_name' => 'email',
          'queue_id' => '',
          'encryption_cipher' => 'ECDHE-RSA-AES256-SHA',
          'encryption_protocol' => 'TLSv1',
          'etrn_domain' => '',
          'ccert_subject' => '',
          'request' => 'smtpd_access_policy',
          'protocol_state' => 'RCPT',
          'stress' => '',
          'sasl_username' => 'xxxxxx@xxxxxx.es',
          'recipient' => 'xxxxxx@xxxxxx.be',
          'ccert_pubkey_fingerprint' => '',
          'instance' => 'aaa.5559f509.4a694.0',
          'protocol_name' => 'ESMTP',
          'encryption_keysize' => '256',
          'recipient_count' => '0',
          'ccert_issuer' => '',
          'sender' => 'xxxxxx@xxxxxx.es',
          'client_name' => 'email',
          'client_address' => '127.0.0.1',
          '_protocol_transport' => 'Postfix'
        };
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Protocol state is 'RCPT', resolving policy...
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Going to resolve session data into policy: $VAR1 = {
          'Recipient' => 'xxxxxx@xxxxxx.be',
          'SASLUsername' => 'xxxxxx@xxxxxx.es',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => 'aaa.5559f509.4a694.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES256-SHA',
          'Size' => '0',
          'EncryptionKeySize' => '256',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '_',
          'ClientAddress' => '127.0.0.1',
          'ClientName' => 'email',
          'Sender' => 'xxxxxx@xxxxxx.es',
          'SASLSender' => '',
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'email',
          'SASLMethod' => 'LOGIN'
        };
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '2' in policy 'Default Outbound'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '3' in policy 'Default Inbound'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '4' in policy 'Default Internal'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '6' in policy 'whitelists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '7' in policy 'blacklists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '8' in policy 'no_greylisting'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: Found policy member with ID '9' in policy 'no_greylisting'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Main policy sources '%internal_domains'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]: Group 'internal_domains' has 1 source(s) => @yyyyyyyyy.com
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): - Resolved source '@yyyyyyyyy.com' to a email address specification, match = 0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:2/Name:Default Outbound]=>(group:internal_domains): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:2/Name:Default Outbound]: Source matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/05/18-15:19:53 - 2630] [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/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_ips): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 1 source(s) => @yyyyyyyyy.com
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved source '@yyyyyyyyy.com' to a email address specification, match = 0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Source matching result: matched=1
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Main policy destinations '%internal_domains'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]: Group 'internal_domains' has 1 destination(s) => @yyyyyyyyy.com
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): - Resolved destination '@yyyyyyyyy.com' to a email address specification, match = 0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:3/Name:Default Inbound]=>(group:internal_domains): Destination group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:3/Name:Default Inbound]: Destination matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Main policy sources '%internal_ips,%internal_domains'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:4/Name:Default Internal]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/05/18-15:19:53 - 2630] [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/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:4/Name:Default Internal]=>(group:internal_ips): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:4/Name:Default Internal]: Source matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:6/Name:whitelists]: Main policy sources '%whitelists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:6/Name:whitelists]: Group 'whitelists' has 0 source(s) =>
[2015/05/18-15:19:53 - 2630] [POLICIES] WARNING: [ID:6/Name:whitelists]: No group members for source group 'whitelists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:6/Name:whitelists]=>(group:whitelists): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:6/Name:whitelists]: Source matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:7/Name:blacklists]: Main policy sources '%blacklists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:7/Name:blacklists]: Group 'blacklists' has 0 source(s) =>
[2015/05/18-15:19:53 - 2630] [POLICIES] WARNING: [ID:7/Name:blacklists]: No group members for source group 'blacklists'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:7/Name:blacklists]=>(group:blacklists): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:7/Name:blacklists]: Source matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Main policy sources '!%internal_ips,!%internal_domains'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'internal_ips' has 1 source(s) => 10.0.0.0/8
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_ips): - Resolved source '10.0.0.0/8' to a IP/CIDR specification, match = 0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_ips): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'internal_domains' has 1 source(s) => @yyyyyyyyy.com
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_domains): - Resolved source '@yyyyyyyyy.com' to a email address specification, match = 0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:internal_domains): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:8/Name:no_greylisting]: Source matching result: matched=1
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Main policy destinations '%no_greylisting_for_internal'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]: Group 'no_greylisting_for_internal' has 0 destination(s) =>
[2015/05/18-15:19:53 - 2630] [POLICIES] WARNING: [ID:8/Name:no_greylisting]: No group members for destination group 'no_greylisting_for_internal'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:8/Name:no_greylisting]=>(group:no_greylisting_for_internal): Destination group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:8/Name:no_greylisting]: Destination matching result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]: Main policy sources '%no_greylisting_for_external'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]: Group 'no_greylisting_for_external' has 0 source(s) =>
[2015/05/18-15:19:53 - 2630] [POLICIES] WARNING: [ID:9/Name:no_greylisting]: No group members for source group 'no_greylisting_for_external'
[2015/05/18-15:19:53 - 2630] [POLICIES] DEBUG: [ID:9/Name:no_greylisting]=>(group:no_greylisting_for_external): Source group result: matched=0
[2015/05/18-15:19:53 - 2630] [POLICIES] INFO: [ID:9/Name:no_greylisting]: Source matching result: matched=0
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Policy resolved into: $VAR1 = {};
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'Recipient' => 'xxxxxx@xxxxxx.be',
          'SASLUsername' => 'xxxxxx@xxxxxx.es',
          'QueueID' => '',
          'RecipientData' => '',
          'Instance' => 'aaa.5559f509.4a694.0',
          'EncryptionCipher' => 'ECDHE-RSA-AES256-SHA',
          'Size' => '0',
          'EncryptionKeySize' => '256',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 2130706433,
                                     'Network' => '127.0.0.1',
                                     'IP_Long' => 2130706433,
                                     'Broadcast' => '127.0.0.1',
                                     'IP' => '127.0.0.1',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 2130706433
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '_',
          'ClientAddress' => '127.0.0.1',
          'ClientName' => 'email',
          'Sender' => 'xxxxxx@xxxxxx.es',
          'SASLSender' => '',
          'Timestamp' => 1431958793,
          'ProtocolState' => 'RCPT',
          'Policy' => {},
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'email',
          'SASLMethod' => 'LOGIN'
        };
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] INFO: Got request #1
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Access Control Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'HELO/EHLO Check Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'SPF Check Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Greylisting Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Quotas Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Done with modules
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Protocol state is 'END-OF-MESSAGE', decoding policy...
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Decoded into: $VAR1 = {};
[2015/05/18-15:19:53 - 2630] [TRACKING] DEBUG: Request translated into session data: $VAR1 = {
          'SASLUsername' => 'xxxxxx@xxxxxx.es',
          'QueueID' => '6181D3FDF9',
          'RecipientData' => '/<xxxxxx@xxxxxx.be>#',
          'EncryptionCipher' => 'ECDHE-RSA-AES256-SHA',
          'Instance' => 'aaa.5559f509.4a694.0',
          'Size' => '1',
          'EncryptionKeySize' => '256',
          'ParsedClientAddress' => {
                                     'Broadcast_Long' => 2130706433,
                                     'Network' => '127.0.0.1',
                                     'IP_Long' => 2130706433,
                                     'Broadcast' => '127.0.0.1',
                                     'IP' => '127.0.0.1',
                                     'Mask_Long' => 4294967295,
                                     'Network_Long' => 2130706433
                                   },
          'ProtocolTransport' => 'Postfix',
          'EncryptionProtocol' => 'TLSv1',
          'Helo' => '_',
          'ClientAddress' => '127.0.0.1',
          'ClientName' => 'email',
          'Sender' => 'xxxxxx@xxxxxx.es',
          'SASLSender' => '',
          'Timestamp' => 1431958793,
          'ProtocolState' => 'END-OF-MESSAGE',
          '_Recipient_To_Policy' => {},
          'Protocol' => 'ESMTP',
          'ClientReverseName' => 'email',
          'SASLMethod' => 'LOGIN'
        };
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Got request, running modules...
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] INFO: Got request #2 (pipelined)
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Access Control Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Access Control Plugin' returned CBP_SKIP
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: HELO/EHLO Check Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'HELO/EHLO Check Plugin' returned CBP_SKIP
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: SPF Check Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'SPF Check Plugin' returned CBP_SKIP
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Greylisting Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Greylisting Plugin' returned CBP_SKIP
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Running module: Quotas Plugin
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Module 'Quotas Plugin' returned CBP_CONTINUE
[2015/05/18-15:19:53 - 2630] [CBPOLICYD] DEBUG: Done with modules
[2015/05/18-15:21:33 - 2630] [CBPOLICYD] WARNING: Client closed connection => Peer: 127.0.0.1:47841, Local: 127.0.0.1:10031
[2015/05/18-15:21:33 - 1121] [CORE] INFO: Killing "1" children
[2015/05/18-15:21:33 - 2630] [CBPOLICYD] DEBUG: Shutting down caching engine (2630)

9 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

Now the tracking is working as expected... I had to add every domain to the policy_group_members table, which is probably what you do when we add a domain using iRedAdmin-Pro.  It still looks like there is a database connection problem tough... but maybe it's because Cluebringer tries to connect before MariaDB is fully started.

It goes into bypass mode and then after the "bypass time-out" time it can connect and it starts working.  Not a major issue but still not really ideal.  I will reduce the bypass timeout to the minimum to prevent quotes not being tracked right after a server reboot.

Do you have any other suggestions that might make this setup ideally track quotas right away?

Cheers

10 Reply by mir

  • mir
  • Member
  • Offline
  • Registered: 2014-05-30
  • Posts: 170

Re: Cluebringer not tracking

Dominique wrote:

Do you have any other suggestions that might make this setup ideally track quotas right away?

Maybe cluebringer should be configured to have a dependency to Mysql/MariaDB which should mean that systemd will first start cluebringer after Mysql/MariaDB has been started?

11 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

mir wrote:
Dominique wrote:

Do you have any other suggestions that might make this setup ideally track quotas right away?

Maybe cluebringer should be configured to have a dependency to Mysql/MariaDB which should mean that systemd will first start cluebringer after Mysql/MariaDB has been started?

That could be a solution... even seems like it was a fluke when cluebringer started working earlier... now I keep getting the database connection errors... even after the server has been running for an hour.

12 Reply by Dominique

  • Dominique
  • Member
  • Offline
  • Registered: 2014-01-09
  • Posts: 98

Re: Cluebringer not tracking

After a few more tests I can only conclude that Cluebringer is trying to connect to mysql before it's running and therefore fails to function properly, going into bypass mode.  Also, Cluebring does not attempt to connect to the database later on so it stays in bypass mode forever, rendering it useless.  Restarting the service manually solves the problem but that's not really a solution.  I don't know how to configure dependencies... been reading about it for about 2 hours now and it's still a puzzle to me.

This was a fresh install of iRedMail 0.9.1 on a vanilla CentOS 7 and Cluebringer won't run properly because of this... so I hope someone can solve this by putting dependencies on the service during installation, so I can just go ahead and reinstall from scratch.

Thank you in advance!