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

[Jan Kowalsky]

Hi,

I think I solved the Problem substantially.

Am 21.05.2014 15:52, schrieb Jan Kowalsky:
> 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.

yes and no ...

Responsible was probably an error in the ldap-entry - occurred during
migration. The email-Address of one entry was in fact wrong: it was
test.user at example.com instead of test.user at subdomain.example.com.

I thought I checked it twice. But ...

There are still entries which are handled continually by pykolab (others
not) - but everything is working fine so far and the load is reasonable.


> 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

Regars
Jan