high load (wait) from cyrus - after restart kolabd it improves for a while
Jan Kowalsky
jankow at datenkollektiv.net
Fri May 16 12:56:55 CEST 2014
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
More information about the users
mailing list