high load (wait) from cyrus - after restart kolabd it improves for a while

Wed May 21 15:52:14 CEST 2014

Hi all,

so far I figured out that the recipient policy is responsible for the
problem. Like described above, there where masses of error messages for
one recipient in one hosted domain with the particularity that it was an
domain like subdomain.domain.org where another domain "domain.org" also
existed - as a separate domain.

As far I understood the error log from pykolab it tried to enforce the
recipient policy from example.user at subdomain.example.com to
example.user at example.com and collapsed ...

Since I disabled the recipient policy with

  daemon_rcpt_policy = false

in kolab.conf the load of imaps is normal (0.1 to 0.4 max).

Before there where hundreds of connections to cyrus and ldap-queries to
ldap per second which resulted also in a very high load of the ldap-server.

I assume a bug in pykolab which leads to this behaviour.

It seems similar to another problem or bug in kolab-webadmin. As long as
the primary_mail parameter was not set to:

primary_mail = %(givenname)s.%(surname)s at subdomain.example.com

in kolab.conf

also in kolab-webadmin the primary email-address got rewritten to
test.user at example.com.

So the entry in kolab.conf looks now:

[subdomain.example.com]
primary_mail = %(givenname)s.%(surname)s at subdomain.example.com
daemon_rcpt_policy = False

As a workaround it seems ok. But I'm still worried about the problem.
the other error messages in pykolab kolg described below still occur.

Regards
Jan

Am 16.05.2014 12:56, schrieb Jan Kowalsky:
> 
> Am 14.05.2014 12:44, schrieb Jan Kowalsky:
>> Hi all,
>>
>> we have a continually high load on our kolab-mailserver. There are two
>> "imapd -s" processes which produces high disk i/o and results in a load
>> from 2.5 to 3 and more.
>>
>> The server should be sufficiant for our ~ 300 users. We've had an kolab
>> 2.3 installation running with no problems.
>>
>> After restarting kolabd the load decreases to 0.15 to 0.5  and the high
>> io of cyrus is gone (without restarting cyrus). After a while -
>> sometimes halve an our sometimes a couple of ours the load increases again.
> 
> I figured out so far, that pykolab is responsible for the load. It
> seems that it tries to sync one or more entries multiple times without
> success or with errors.
> 
> Maybe someone can give some hints where to look further?
> 
> pykolab 0.6.12-0~kolab8 on debian wheezy with kolab 3.2
> 
> There are a couple of mail-addresses which leads to debug-errors
> poykolab.log. (look at the end.)
> 
> But these errors don't lead to the high load.
> 
> What leads to high load seems to be exactly one entry, which appears in
> the log more than 100000 times a day. But the error starts to occur only
> after a while, a couple of hours, when kolab-server was started.
> 
> What is irritating me:
> 
>   * the domain is: orga.example.org
>   * the primary mailadress is orga.info at orga.example.org
> 
> But nevertheless there are entries with
> 
>   * orga.info at example.org (without subdomain) in the logs:
> 
> ~~~~~~~
> 2014-05-15 14:50:19,907 pykolab.auth DEBUG [8384]: Searching with filter
> '(objectclass=kolabinetorgperson)'
> 2014-05-15 14:50:19,908 pykolab.auth DEBUG [8384]: Applying recipient
> policy to 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 14:50:19,909 pykolab.auth DEBUG [8384]: Using mail
> attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
> 2014-05-15 14:50:19,909 pykolab.plugins DEBUG [8384]: Executing hook
> set_primary_mail for plugin recipientpolicy
> 2014-05-15 14:50:19,910 pykolab.utils DEBUG [8384]: Transliterating
> string 'orga.info at orga.example.org' with locale 'de_DE'
> 2014-05-15 14:50:19,910 pykolab.utils DEBUG [8384]: Attempting to set locale
> 2014-05-15 14:50:19,911 pykolab.utils DEBUG [8384]: Failure to set locale
> 2014-05-15 14:50:19,911 pykolab.utils DEBUG [8384]: Executing
> 'orga.info at orga.example.org | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
> 2014-05-15 14:50:19,921 pykolab.auth DEBUG [8384]: Finding recipient
> with filter
> '(&(|(mail=orga.info at orga.example.org)(alias=orga.info at orga.example.org))(!(nsuniqueid=b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2)))'
> 2014-05-15 14:50:19,922 pykolab.auth DEBUG [8384]: No results for mail
> address orga.info at orga.example.org found
> 2014-05-15 14:50:19,923 pykolab.auth DEBUG [8384]: Setting entry
> attribute 'mail' to 'orga.info at orga.example.org' for {'dn':
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org', 'domain':
> 'example.org', 'displayname': 'info, orga', 'cn': 'orga info',
> 'mailquota': '512000', 'alias': 'orga at orga.example.org',
> 'preferredlanguage': 'de_DE', 'userpassword':
> '{SSHA}cN4fDJDjk3L2FqacQZi3jAVMJKQhI6sM', 'nsuniqueid':
> 'b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 'id':
> 'b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 'objectclass': ['top',
> 'inetorgperson', 'kolabinetorgperson', 'mailrecipient',
> 'organizationalperson', 'person'], 'mailhost': 'localhost', 'sn':
> 'info', 'mail': 'orga.info at example.org', 'surname': 'info', 'givenname':
> 'orga', 'type': 'user', 'modifytimestamp': '20140515124830Z', 'uid':
> 'oinfo'}
> ~~~~~~~
> 
> Is there a bug for domains with more than two components? But the
> orga.info at orga.example.org is the only address out of a couple of
> addressess of the same domain where the error occurs.
> 
> I deleted the databases in /var/lib/kolab with no effect. Is there any
> other location where datas are stored exept cyrus, ldap and the
> kolab-cache in /var/lib/kolab ?
> 
> A larger log entry for the questionable problem:
> 
> ~~~~~~~~~~
> 2014-05-15 12:01:35,022 pykolab.auth DEBUG [28984]: Searching with
> filter '(objectclass=kolabinetorgperson)'
> 2014-05-15 12:01:35,024 pykolab.auth DEBUG [28984]: Applying recipient
> policy to 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,024 pykolab.auth DEBUG [28984]: Using mail
> attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
> 2014-05-15 12:01:35,024 pykolab.plugins DEBUG [28984]: Executing hook
> set_primary_mail for plugin recipientpolicy
> 2014-05-15 12:01:35,025 pykolab.utils DEBUG [28984]: Transliterating
> string 'orga.info at orga.example.org' with locale 'de_DE'
> 2014-05-15 12:01:35,025 pykolab.utils DEBUG [28984]: Attempting to set
> locale
> 2014-05-15 12:01:35,025 pykolab.utils DEBUG [28984]: Failure to set locale
> 2014-05-15 12:01:35,025 pykolab.utils DEBUG [28984]: Executing
> 'orga.info at orga.example.org | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
> 2014-05-15 12:01:35,026 sqlalchemy.engine.base.Engine INFO SELECT
> entry.id AS entry_id, entry.uniqueid AS entry_uniqueid,
> entry.result_attribute AS entry_result_attribute, entry.last_change AS
> entry_last_change
> FROM entry
> WHERE entry.uniqueid = ?
>  LIMIT ? OFFSET ?
> 2014-05-15 12:01:35,026 sqlalchemy.engine.base.Engine INFO SELECT
> entry.id AS entry_id, entry.uniqueid AS entry_uniqueid,
> entry.result_attribute AS entry_result_attribute, entry.last_change AS
> entry_last_change
> FROM entry
> WHERE entry.uniqueid = ?
>  LIMIT ? OFFSET ?
> 2014-05-15 12:01:35,027 sqlalchemy.engine.base.Engine INFO
> ('b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 1, 0)
> 2014-05-15 12:01:35,027 sqlalchemy.engine.base.Engine INFO
> ('b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 1, 0)
> 2014-05-15 12:01:35,028 pykolab.auth DEBUG [28998]: Searching with
> filter '(objectclass=kolabinetorgperson)'
> 2014-05-15 12:01:35,030 pykolab.auth DEBUG [28998]: Applying recipient
> policy to 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,030 pykolab.auth DEBUG [28998]: Using mail
> attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
> 2014-05-15 12:01:35,030 pykolab.plugins DEBUG [28998]: Executing hook
> set_primary_mail for plugin recipientpolicy
> 2014-05-15 12:01:35,031 pykolab.utils DEBUG [28998]: Transliterating
> string 'orga.info at example.org' with locale 'de_DE'
> 2014-05-15 12:01:35,031 pykolab.utils DEBUG [28998]: Attempting to set
> locale
> 2014-05-15 12:01:35,031 pykolab.utils DEBUG [28998]: Failure to set locale
> 2014-05-15 12:01:35,032 pykolab.utils DEBUG [28998]: Executing
> 'orga.info at example.org | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
> 2014-05-15 12:01:35,078 pykolab.auth DEBUG [28998]: Finding recipient
> with filter
> '(&(|(mail=orga.info at example.org)(alias=orga.info at example.org))(!(nsuniqueid=b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2)))'
> 2014-05-15 12:01:35,078 pykolab.auth DEBUG [28984]: Finding recipient
> with filter
> '(&(|(mail=orga.info at orga.example.org)(alias=orga.info at orga.example.org))(!(nsuniqueid=b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2)))'
> 2014-05-15 12:01:35,079 pykolab.auth DEBUG [28984]: No results for mail
> address orga.info at orga.example.org found
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28984]: Entry modifications
> list: {}
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28998]: No results for mail
> address orga.info at example.org found
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28984]: Result from
> recipient policy: {}
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28998]: Setting entry
> attribute 'mail' to 'orga.info at example.org' for {'dn':
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org', 'domain':
> 'orga.example.org', 'displayname': 'info, orga', 'cn': 'orga info',
> 'mailquota': '512000', 'alias': 'orga at orga.example.org',
> 'preferredlanguage': 'de_DE', 'userpassword':
> '{SSHA}cN4fDJDjk3L2FqacQZi3jAVMJKQhI6sM', 'nsuniqueid':
> 'b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 'id':
> 'b5bf8a81-c05c11e3-89c8ad4c-cdc1d3d2', 'objectclass': ['top',
> 'inetorgperson', 'kolabinetorgperson', 'mailrecipient',
> 'organizationalperson', 'person'], 'mailhost': 'localhost', 'sn':
> 'info', 'mail': 'orga.info at orga.example.org', 'surname': 'info',
> 'givenname': 'orga', 'type': 'user', 'modifytimestamp':
> '20140514203047Z', 'uid': 'oinfo'}
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28984]: Entry ID:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,080 pykolab.auth DEBUG [28998]: Entry ID:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,081 pykolab.auth DEBUG [28984]: Entry DN:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,081 pykolab.auth DEBUG [28984]: ldap search:
> ('uid=oinfo,ou=People,dc=orga,dc=example,dc=org', 0,
> filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
> 2014-05-15 12:01:35,081 pykolab.auth DEBUG [28998]: Entry DN:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,081 pykolab.auth DEBUG [28998]: ldap search:
> ('uid=oinfo,ou=People,dc=orga,dc=example,dc=org', 0,
> filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['*']
> 2014-05-15 12:01:35,084 pykolab.auth DEBUG [28984]: About to consider
> the user quota for 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> (used: None, imap: None, ldap: '512000', default: 0
> 2014-05-15 12:01:35,084 pykolab.plugins DEBUG [28984]: Executing hook
> set_user_folder_quota for plugin dynamicquota
> 2014-05-15 12:01:35,085 pykolab.imap DEBUG [28984]: Verbinde nochmal zum
> IMAP Server localhost
> 2014-05-15 12:01:35,130 pykolab.imap DEBUG [28984]: Logging on to Cyrus
> IMAP server localhost
> 2014-05-15 12:01:35,179 pykolab.auth DEBUG [28998]: Entry modifications
> list: {'mail': 'orga.info at example.org'}
> 2014-05-15 12:01:35,179 pykolab.auth DEBUG [28998]: Result from
> recipient policy: {'mail': 'orga.info at example.org'}
> 2014-05-15 12:01:35,180 pykolab.auth DEBUG [28998]: Entry ID:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,180 pykolab.auth DEBUG [28998]: Entry DN:
> 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> 2014-05-15 12:01:35,180 pykolab.auth DEBUG [28998]: ldap search:
> ('uid=oinfo,ou=People,dc=orga,dc=example,dc=org', 0,
> filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
> 2014-05-15 12:01:35,181 pykolab.conf WARNING Option imap/virtual_domains
> does not exist in config file /etc/kolab/kolab.conf, pulling from defaults
> 2014-05-15 12:01:35,219 pykolab.auth DEBUG [28998]: About to consider
> the user quota for 'uid=oinfo,ou=People,dc=orga,dc=example,dc=org'
> (used: None, imap: None, ldap: '512000', default: 0
> 2014-05-15 12:01:35,219 pykolab.plugins DEBUG [28998]: Executing hook
> set_user_folder_quota for plugin dynamicquota
> 2014-05-15 12:01:35,220 pykolab.imap DEBUG [28998]: Verbinde nochmal zum
> IMAP Server localhost
> 2014-05-15 12:01:35,266 pykolab.imap DEBUG [28998]: Logging on to Cyrus
> IMAP server localhost
> 2014-05-15 12:01:35,304 pykolab.conf WARNING Option imap/virtual_domains
> does not exist in config file /etc/kolab/kolab.conf, pulling from defaults
> 2014-05-15 12:01:35,577 pykolab.imap DEBUG [28984]: Continuing with
> separator: '/'
> ~~~~~~~~~~~~
> 
> For some other addresses there are errors like:
> 
> ~~~~~~~~~~~~~~~~~
> 2014-05-14 23:45:48,876 pykolab.auth DEBUG [28947]: Searching with
> filter '(objectclass=kolabinetorgperson)'
> 2014-05-14 23:45:48,877 pykolab.auth DEBUG [28947]: Applying recipient
> policy to 'uid=user,ou=People,dc=datenkollektiv,dc=net'
> 2014-05-14 23:45:48,877 pykolab.auth DEBUG [28947]: Using mail
> attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
> 2014-05-14 23:45:48,878 pykolab.auth DEBUG [28947]: key 'alias' not in entry
> 2014-05-14 23:45:48,878 pykolab.auth DEBUG [28947]: key 'alias' is the
> sec. mail attr.
> 2014-05-14 23:45:48,878 pykolab.plugins DEBUG [28947]: Executing hook
> set_primary_mail for plugin recipientpolicy
> 2014-05-14 23:45:48,880 pykolab.utils DEBUG [28947]: Transliterating
> string 'test.user at datenkollektiv.net' with locale 'de_DE'
> 2014-05-14 23:45:48,880 pykolab.utils DEBUG [28947]: Attempting to set
> locale
> 2014-05-14 23:45:48,881 pykolab.utils DEBUG [28947]: Failure to set locale
> 2014-05-14 23:45:48,881 pykolab.utils DEBUG [28947]: Executing
> 'test.user at datenkollektiv.net | /usr/bin/iconv -f UTF-8 -t
> ASCII//TRANSLIT -s'
> 2014-05-14 23:45:48,892 pykolab.auth DEBUG [28947]: Finding recipient
> with filter
> '(&(|(mail=test.user at datenkollektiv.net)(alias=test.user at datenkollektiv.net))(!(nsuniqueid=15857181-d6ad11e3-8698ad4c-cdc1d3d2)))'
> 2014-05-14 23:45:48,895 pykolab.auth DEBUG [28947]: No results for mail
> address test.user at datenkollektiv.net found
> 2014-05-14 23:45:48,895 pykolab.auth DEBUG [28947]: Entry modifications
> list: {}
> 2014-05-14 23:45:48,896 pykolab.auth DEBUG [28947]: Result from
> recipient policy: {}
> 2014-05-14 23:45:48,898 sqlalchemy.engine.base.Engine INFO SELECT
> entry.id AS entry_id, entry.uniqueid AS entry_uniqueid,
> entry.result_attribute AS entry_result_attribute, entry.last_change AS
> entry_last_change
> FROM entry
> WHERE entry.uniqueid = ?
> ~~~~~~~~~~~~~~~~~~~
> 
> What I'm confuses about is the "No results for mail address
> test.user at datenkollektiv.net  found" but the address exists.
> 
> The second strange behaviour is, that there are only about 10 adresses
> which are tried to sync again and again - but only every 15 minutes or
> halve an hour. Not like the one address which is synced thousands of times.
> 
> Any idea?
> 
> Jan
> _______________________________________________
> users mailing list
> users at lists.kolab.org
> https://lists.kolab.org/mailman/listinfo/users
> 