Page MenuHomePhorge
Create Task
Maniphest T1414

Kolabd not catching changes in LDAP
Closed, ResolvedPublic
Actions

Description

Using pykolab-0.8.3-5.1.el7.kolab_wf.noarch (CentOS 7):

Kolabd is running, but doesn't recognize when something changes in LDAP (f.e. adding a new user, removing a user, ...). When starting kolabd, it seems LDAP is scanned and actions are taken (f.e. creating mailbox, folders, ...) but after this initial sync kolabd just stops doing stuff, but it is running happily in the background.
Sometimes kolabd is spitting out error messages:

2016-08-11 17:15:11,994 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-11 17:15:11,994 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

Details

Ticket Type
Task

Revisions and Commits

rP pykolab
D208rP764103053f06 T1414: Set LDAP TIMEOUT option only on "immediate" connection
D208rP54cb493d655b T1414: Set LDAP TIMEOUT option only on "immediate" connection

Related Objects

Event Timeline

tobru created this task.Aug 11 2016, 5:22 PM
tobru added a project: PyKolab.Aug 11 2016, 5:38 PM

Just debugged the same stuff with pykolab-0.8.3-3.1.el7.kolab_16.noarch, same behaviour.

After some waiting (~5minutes) kolabd awakens again is sometimes ables to connect, but sometimes the same TIMEOUT happens.

Here is some more debugging output:

2016-08-11 17:34:50,568 pykolab.daemon DEBUG [8871]: added domains: [], removed domains: []
2016-08-11 17:34:50,570 pykolab.auth DEBUG [8871]: Connecting to Authentication backend for domain kolabdemo.ch
2016-08-11 17:34:50,570 pykolab.auth DEBUG [8871]: Connecting to LDAP...
2016-08-11 17:34:50,570 pykolab.auth DEBUG [8871]: Attempting to use LDAP URI ldap://localhost:389
2016-08-11 17:34:50,571 pykolab.daemon DEBUG [8871]: Listing domains...
2016-08-11 17:34:50,571 pykolab.auth DEBUG [8871]: Listing domains...
2016-08-11 17:34:50,571 pykolab.auth DEBUG [8871]: Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=kolabdemo,dc=ch and password: *******************
2016-08-11 17:34:50,574 pykolab.auth DEBUG [8871]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=*))'
2016-08-11 17:34:50,576 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,576 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,577 pykolab.auth DEBUG [8871]: Naming contexts found: ['dc=kolabdemo,dc=ch', 'dc=vischn,dc=ch', 'o=netscaperoot']
2016-08-11 17:34:50,578 pykolab.auth DEBUG [8871]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:34:50,578 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,578 pykolab.auth DEBUG [8871]: Finding domain root dn for domain kolabdemo.ch
2016-08-11 17:34:50,578 pykolab.auth DEBUG [8871]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=kolabdemo.ch))'
2016-08-11 17:34:50,579 pykolab.auth DEBUG [8871]: Domains/Root DNs found: {'kolabdemo.ch': 'dc=kolabdemo,dc=ch'}
2016-08-11 17:34:50,579 pykolab.auth DEBUG [8871]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:34:50,579 pykolab.auth DEBUG [8871]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:34:50,580 pykolab.daemon DEBUG [8871]: Domain 'kolabdemo.ch' naming context: 'dc=kolabdemo,dc=ch', root dn: 'dc=kolabdemo,dc=ch'
2016-08-11 17:34:50,580 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,580 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,582 pykolab.auth DEBUG [8871]: Naming contexts found: ['dc=kolabdemo,dc=ch', 'dc=vischn,dc=ch', 'o=netscaperoot']
2016-08-11 17:34:50,582 pykolab.auth DEBUG [8871]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:34:50,582 pykolab.auth DEBUG [8871]: bind() called but already bound
2016-08-11 17:34:50,582 pykolab.auth DEBUG [8871]: Finding domain root dn for domain vischn.ch
2016-08-11 17:34:50,582 pykolab.auth DEBUG [8871]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=vischn.ch))'
2016-08-11 17:34:50,583 pykolab.auth DEBUG [8871]: Domains/Root DNs found: {'kolabdemo.ch': 'dc=kolabdemo,dc=ch', 'vischn.ch': 'dc=vischn,dc=ch'}
2016-08-11 17:34:50,583 pykolab.auth DEBUG [8871]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:34:50,583 pykolab.auth DEBUG [8871]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:34:50,584 pykolab.daemon DEBUG [8871]: Domain 'vischn.ch' naming context: 'dc=vischn,dc=ch', root dn: 'dc=vischn,dc=ch'
2016-08-11 17:34:50,584 pykolab.daemon DEBUG [8871]: Naming contexts to synchronize: ['dc=kolabdemo,dc=ch', 'dc=vischn,dc=ch']
2016-08-11 17:34:50,584 pykolab.daemon DEBUG [8871]: Result set of domains: ['kolabdemo.ch', 'vischn.ch']
2016-08-11 17:34:50,584 pykolab.daemon DEBUG [8871]: Checking for domain kolabdemo.ch
2016-08-11 17:34:50,585 pykolab.daemon DEBUG [8871]: Domain kolabdemo.ch already there and alive.
2016-08-11 17:34:50,585 pykolab.daemon DEBUG [8871]: Checking for domain vischn.ch
2016-08-11 17:34:50,585 pykolab.daemon DEBUG [8871]: Domain vischn.ch already there and alive.
2016-08-11 17:35:31,040 pykolab.auth DEBUG [8873]: Connecting to Authentication backend for domain kolabdemo.ch
2016-08-11 17:35:31,041 pykolab.auth DEBUG [8873]: Connecting to LDAP...
2016-08-11 17:35:31,042 pykolab.auth DEBUG [8873]: Attempting to use LDAP URI ldap://localhost:389
2016-08-11 17:35:31,042 pykolab.auth DEBUG [8873]: Listing domains...
2016-08-11 17:35:31,042 pykolab.auth DEBUG [8873]: Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=kolabdemo,dc=ch and password: *******************
2016-08-11 17:35:31,045 pykolab.auth DEBUG [8873]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=kolabdemo.ch))'
2016-08-11 17:35:31,047 pykolab.auth DEBUG [8873]: Connecting to Authentication backend for domain kolabdemo.ch
2016-08-11 17:35:31,047 pykolab.auth DEBUG [8873]: Connecting to LDAP...
2016-08-11 17:35:31,047 pykolab.auth DEBUG [8873]: Attempting to use LDAP URI ldap://localhost:389
2016-08-11 17:35:31,048 pykolab.auth DEBUG [8873]: Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=kolabdemo,dc=ch and password: *******************
2016-08-11 17:35:31,052 pykolab.auth DEBUG [8873]: Using filter '(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=20160811153517Z))'
2016-08-11 17:35:31,052 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,052 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,052 pykolab.auth DEBUG [8873]: Finding domain root dn for domain kolabdemo.ch
2016-08-11 17:35:31,053 pykolab.auth DEBUG [8873]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=kolabdemo.ch))'
2016-08-11 17:35:31,053 pykolab.auth DEBUG [8873]: Synchronization is searching against base DN: dc=kolabdemo,dc=ch
2016-08-11 17:35:31,056 pykolab.auth DEBUG [8873]: LDAP Search Result Data Entry:
2016-08-11 17:35:31,056 pykolab.auth DEBUG [8873]:     DN: 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,056 pykolab.auth DEBUG [8873]:     Entry: {'displayName': ['Test, Blubber'], 'cn': ['Blubber Test'], 'mailQuota': ['1048576'], 'preferredLanguage': ['en_US'], 'nsuniqueid': ['947a5a81-5fd811e6-9312c5af-b8834389'], 'objectClass': ['top', 'inetorgperson', 'kolabinetorgperson', 'mailrecipient', 'organizationalperson', 'person'], 'alias': ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch'], 'mailHost': ['localhost'], 'sn': ['Test'], 'mail': ['test@kolabdemo.ch'], 'givenName': ['Blubber'], 'modifytimestamp': ['20160811153517Z'], 'uid': ['test']}
2016-08-11 17:35:31,056 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,057 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,057 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,057 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:31,061 pykolab.auth DEBUG [8873]: Entry type: user
2016-08-11 17:35:31,064 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,064 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,065 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,065 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:31,067 pykolab.auth DEBUG [8873]: Applying recipient policy to 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,068 pykolab.auth DEBUG [8873]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:31,068 pykolab.plugins DEBUG [8873]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:31,068 pykolab.utils DEBUG [8873]: Transliterating string 'Test@kolabdemo.ch' with locale 'en_US'
2016-08-11 17:35:31,068 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:31,069 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:31,069 pykolab.utils DEBUG [8873]: Executing 'Test@kolabdemo.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:31,075 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,076 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:31,076 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,076 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,077 pykolab.auth DEBUG [8873]: No results for mail address test@kolabdemo.ch found
2016-08-11 17:35:31,077 pykolab.plugins DEBUG [8873]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:31,078 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:31,078 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:31,078 pykolab.utils DEBUG [8873]: Transliterating string 'Blubber' with locale 'en_US'
2016-08-11 17:35:31,078 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:31,079 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:31,079 pykolab.utils DEBUG [8873]: Executing 'Blubber | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:31,083 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:31,083 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:31,083 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:31,084 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:31,086 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:31,087 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:31,087 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:31,087 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:31,090 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:31,090 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:31,091 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:31,091 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:31,091 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:31,091 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:31,091 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,092 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:31,092 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,093 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,094 pykolab.auth DEBUG [8873]: No results for address test@kolabdemo.ch found
2016-08-11 17:35:31,094 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,094 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=b.test@kolabdemo.ch)(alias=b.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:31,095 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,095 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,095 pykolab.auth DEBUG [8873]: No results for address b.test@kolabdemo.ch found
2016-08-11 17:35:31,095 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,096 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=blubber.test@kolabdemo.ch)(alias=blubber.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:31,096 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:31,096 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:31,097 pykolab.auth DEBUG [8873]: No results for address blubber.test@kolabdemo.ch found
2016-08-11 17:35:31,097 pykolab.auth DEBUG [8873]: Recipient policy composed the following set of secondary email addresses: ['test@kolabdemo.ch', 'b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:31,097 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:31,097 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:31,098 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:31,098 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:31,098 pykolab.auth DEBUG [8873]: Entry modifications list: {}
2016-08-11 17:35:31,098 pykolab.auth DEBUG [8873]: Result from recipient policy: {}
2016-08-11 17:35:31,171 pykolab.imap DEBUG [8873]: Logging on to Cyrus IMAP server localhost
2016-08-11 17:35:31,192 pykolab.imap DEBUG [8873]: Continuing with separator: '/'
2016-08-11 17:35:31,192 pykolab.imap DEBUG [8873]: This system is not part of a murder topology
2016-08-11 17:35:31,193 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:31,195 pykolab.imap DEBUG [8873]: Looking for folder 'user/test@kolabdemo.ch', we found folders: [u'user/test@kolabdemo.ch']
2016-08-11 17:35:31,196 pykolab.imap DEBUG [8873]: Server for mailbox 'user/test@kolabdemo.ch' is 'localhost'
2016-08-11 17:35:31,196 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,196 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:31,198 pykolab.plugins DEBUG [8873]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:32,092 pykolab.auth DEBUG [8874]: Connecting to Authentication backend for domain vischn.ch
2016-08-11 17:35:32,092 pykolab.auth DEBUG [8874]: Connecting to LDAP...
2016-08-11 17:35:32,093 pykolab.auth DEBUG [8874]: Attempting to use LDAP URI ldap://localhost:389
2016-08-11 17:35:32,093 pykolab.auth DEBUG [8874]: Listing domains...
2016-08-11 17:35:32,093 pykolab.auth DEBUG [8874]: Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=kolabdemo,dc=ch and password: *******************
2016-08-11 17:35:32,096 pykolab.auth DEBUG [8874]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=vischn.ch))'
2016-08-11 17:35:32,107 pykolab.auth DEBUG [8874]: Connecting to Authentication backend for domain vischn.ch
2016-08-11 17:35:32,108 pykolab.auth DEBUG [8874]: Connecting to LDAP...
2016-08-11 17:35:32,108 pykolab.auth DEBUG [8874]: Attempting to use LDAP URI ldap://localhost:389
2016-08-11 17:35:32,109 pykolab.auth DEBUG [8874]: Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=kolabdemo,dc=ch and password: *******************
2016-08-11 17:35:32,112 pykolab.auth DEBUG [8874]: Using filter '(&(|(objectclass=kolabinetorgperson)(|(objectclass=kolabgroupofuniquenames)(objectclass=kolabgroupofurls))(|(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(objectclass=kolabsharedfolder))(objectclass=kolabsharedfolder))(modifytimestamp>=20160613150031Z))'
2016-08-11 17:35:32,113 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,113 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,113 pykolab.auth DEBUG [8874]: Finding domain root dn for domain vischn.ch
2016-08-11 17:35:32,113 pykolab.auth DEBUG [8874]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=vischn.ch))'
2016-08-11 17:35:32,114 pykolab.auth DEBUG [8874]: Synchronization is searching against base DN: dc=vischn,dc=ch
2016-08-11 17:35:32,116 pykolab.auth DEBUG [8874]: LDAP Search Result Data Entry:
2016-08-11 17:35:32,116 pykolab.auth DEBUG [8874]:     DN: 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:32,116 pykolab.auth DEBUG [8874]:     Entry: {'displayName': ['User, Master'], 'cn': ['Master User'], 'mailQuota': ['1048576'], 'preferredLanguage': ['en_US'], 'nsuniqueid': ['711d6581-317711e6-9312c5af-b8834389'], 'objectClass': ['top', 'inetorgperson', 'kolabinetorgperson', 'mailrecipient', 'organizationalperson', 'person'], 'alias': ['m.user@vischn.ch', 'master.user@vischn.ch'], 'mailHost': ['localhost'], 'sn': ['User'], 'mail': ['user2@vischn.ch'], 'givenName': ['Master'], 'modifytimestamp': ['20160613150031Z'], 'uid': ['user2']}
2016-08-11 17:35:32,116 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,116 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,117 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,117 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:32,117 pykolab.auth DEBUG [8874]: Entry type: user
2016-08-11 17:35:32,121 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,121 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,121 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,121 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:32,122 pykolab.auth DEBUG [8874]: Applying recipient policy to 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:32,122 pykolab.auth DEBUG [8874]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:32,122 pykolab.plugins DEBUG [8874]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:32,123 pykolab.utils DEBUG [8874]: Transliterating string 'User@vischn.ch' with locale 'en_US'
2016-08-11 17:35:32,123 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:32,123 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:32,123 pykolab.utils DEBUG [8874]: Executing 'User@vischn.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:32,128 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,129 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user@vischn.ch)(alias=user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:32,129 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,129 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,130 pykolab.auth DEBUG [8874]: 1 result for address user@vischn.ch found, verifying
2016-08-11 17:35:32,130 pykolab.auth DEBUG [8874]: Too bad, primary email address user@vischn.ch already in use for uid=user,ou=People,dc=vischn,dc=ch (we are uid=user2,ou=People,dc=vischn,dc=ch)
2016-08-11 17:35:32,130 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,131 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:32,131 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,131 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,132 pykolab.auth DEBUG [8874]: No results for mail address user2@vischn.ch found
2016-08-11 17:35:32,132 pykolab.plugins DEBUG [8874]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:32,133 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:32,133 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:32,133 pykolab.utils DEBUG [8874]: Transliterating string 'Master' with locale 'en_US'
2016-08-11 17:35:32,133 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:32,133 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:32,133 pykolab.utils DEBUG [8874]: Executing 'Master | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:32,138 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:32,139 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:32,139 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:32,139 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:32,143 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:32,144 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:32,144 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:32,144 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:32,148 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:32,148 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:32,149 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:32,149 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:32,149 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:32,149 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:32,149 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,150 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=m.user@vischn.ch)(alias=m.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:32,150 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,150 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,151 pykolab.auth DEBUG [8874]: No results for address m.user@vischn.ch found
2016-08-11 17:35:32,151 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,152 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:32,152 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,152 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,153 pykolab.auth DEBUG [8874]: No results for address user2@vischn.ch found
2016-08-11 17:35:32,153 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,153 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=master.user@vischn.ch)(alias=master.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:32,154 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:32,154 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:32,154 pykolab.auth DEBUG [8874]: No results for address master.user@vischn.ch found
2016-08-11 17:35:32,154 pykolab.auth DEBUG [8874]: Recipient policy composed the following set of secondary email addresses: ['m.user@vischn.ch', 'user2@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: Entry modifications list: {}
2016-08-11 17:35:32,155 pykolab.auth DEBUG [8874]: Result from recipient policy: {}
2016-08-11 17:35:32,224 pykolab.imap DEBUG [8874]: Logging on to Cyrus IMAP server localhost
2016-08-11 17:35:32,243 pykolab.imap DEBUG [8874]: Continuing with separator: '/'
2016-08-11 17:35:32,243 pykolab.imap DEBUG [8874]: This system is not part of a murder topology
2016-08-11 17:35:32,244 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:32,245 pykolab.imap DEBUG [8874]: Looking for folder 'user/user2@vischn.ch', we found folders: [u'user/user2@vischn.ch']
2016-08-11 17:35:32,247 pykolab.imap DEBUG [8874]: Server for mailbox 'user/user2@vischn.ch' is 'localhost'
2016-08-11 17:35:32,247 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,247 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:32,250 pykolab.plugins DEBUG [8874]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:41,204 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-11 17:35:41,205 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-11 17:35:41,208 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,208 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,208 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,208 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:41,210 pykolab.auth DEBUG [8873]: Entry type: user
2016-08-11 17:35:41,213 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,213 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,213 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,213 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:41,215 pykolab.auth DEBUG [8873]: Applying recipient policy to 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,215 pykolab.auth DEBUG [8873]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:41,215 pykolab.plugins DEBUG [8873]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:41,216 pykolab.utils DEBUG [8873]: Transliterating string 'Test@kolabdemo.ch' with locale 'en_US'
2016-08-11 17:35:41,216 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,216 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,216 pykolab.utils DEBUG [8873]: Executing 'Test@kolabdemo.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,221 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,221 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,222 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,222 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,223 pykolab.auth DEBUG [8873]: No results for mail address test@kolabdemo.ch found
2016-08-11 17:35:41,223 pykolab.plugins DEBUG [8873]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:41,223 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:41,223 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:41,223 pykolab.utils DEBUG [8873]: Transliterating string 'Blubber' with locale 'en_US'
2016-08-11 17:35:41,224 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,224 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,224 pykolab.utils DEBUG [8873]: Executing 'Blubber | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,229 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:41,229 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,229 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,229 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,233 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:41,234 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,234 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,234 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,238 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:41,238 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:41,239 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:41,239 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:41,239 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:41,239 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:41,239 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,240 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,240 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,240 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,241 pykolab.auth DEBUG [8873]: No results for address test@kolabdemo.ch found
2016-08-11 17:35:41,241 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,242 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=b.test@kolabdemo.ch)(alias=b.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,242 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,242 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,243 pykolab.auth DEBUG [8873]: No results for address b.test@kolabdemo.ch found
2016-08-11 17:35:41,243 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,243 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=blubber.test@kolabdemo.ch)(alias=blubber.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,244 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,244 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: No results for address blubber.test@kolabdemo.ch found
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: Recipient policy composed the following set of secondary email addresses: ['test@kolabdemo.ch', 'b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,245 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,246 pykolab.auth DEBUG [8873]: Entry modifications list: {}
2016-08-11 17:35:41,246 pykolab.auth DEBUG [8873]: Result from recipient policy: {}
2016-08-11 17:35:41,251 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:41,252 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:41,254 pykolab.imap DEBUG [8873]: Looking for folder 'user/test@kolabdemo.ch', we found folders: [u'user/test@kolabdemo.ch']
2016-08-11 17:35:41,255 pykolab.imap DEBUG [8873]: Server for mailbox 'user/test@kolabdemo.ch' is 'localhost'
2016-08-11 17:35:41,255 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,255 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,257 pykolab.plugins DEBUG [8873]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:41,259 pykolab.auth DEBUG [8873]: LDAP Search Result Data Entry:
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]:     DN: 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]:     Entry: {'displayName': ['Test, Blubber'], 'cn': ['Blubber Test'], 'mailQuota': ['1048576'], 'preferredLanguage': ['en_US'], 'nsuniqueid': ['947a5a81-5fd811e6-9312c5af-b8834389'], 'objectClass': ['top', 'inetorgperson', 'kolabinetorgperson', 'mailrecipient', 'organizationalperson', 'person'], 'alias': ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch'], 'mailHost': ['localhost'], 'sn': ['Test'], 'mail': ['test@kolabdemo.ch'], 'givenName': ['Blubber'], 'modifytimestamp': ['20160811153517Z'], 'uid': ['test']}
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,260 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:41,267 pykolab.auth DEBUG [8873]: Entry type: user
2016-08-11 17:35:41,271 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,271 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,271 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,271 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:41,276 pykolab.auth DEBUG [8873]: Applying recipient policy to 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,276 pykolab.auth DEBUG [8873]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:41,276 pykolab.plugins DEBUG [8873]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:41,276 pykolab.utils DEBUG [8873]: Transliterating string 'Test@kolabdemo.ch' with locale 'en_US'
2016-08-11 17:35:41,277 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,277 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,277 pykolab.utils DEBUG [8873]: Executing 'Test@kolabdemo.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,282 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,283 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,283 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,283 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,284 pykolab.auth DEBUG [8873]: No results for mail address test@kolabdemo.ch found
2016-08-11 17:35:41,284 pykolab.plugins DEBUG [8873]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:41,285 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:41,285 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:41,285 pykolab.utils DEBUG [8873]: Transliterating string 'Blubber' with locale 'en_US'
2016-08-11 17:35:41,285 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,285 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,285 pykolab.utils DEBUG [8873]: Executing 'Blubber | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,290 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:41,290 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,290 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,290 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,294 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:41,294 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:41,294 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:41,295 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:41,298 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:41,298 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:41,299 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:41,299 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:41,299 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:41,299 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:41,299 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,300 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,300 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,300 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,301 pykolab.auth DEBUG [8873]: No results for address test@kolabdemo.ch found
2016-08-11 17:35:41,302 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,302 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=b.test@kolabdemo.ch)(alias=b.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,302 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,303 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,303 pykolab.auth DEBUG [8873]: No results for address b.test@kolabdemo.ch found
2016-08-11 17:35:41,303 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,304 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=blubber.test@kolabdemo.ch)(alias=blubber.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:41,304 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:41,304 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:41,305 pykolab.auth DEBUG [8873]: No results for address blubber.test@kolabdemo.ch found
2016-08-11 17:35:41,305 pykolab.auth DEBUG [8873]: Recipient policy composed the following set of secondary email addresses: ['test@kolabdemo.ch', 'b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,305 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,305 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,306 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,306 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:41,306 pykolab.auth DEBUG [8873]: Entry modifications list: {}
2016-08-11 17:35:41,306 pykolab.auth DEBUG [8873]: Result from recipient policy: {}
2016-08-11 17:35:41,312 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:41,313 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:41,314 pykolab.imap DEBUG [8873]: Looking for folder 'user/test@kolabdemo.ch', we found folders: [u'user/test@kolabdemo.ch']
2016-08-11 17:35:41,316 pykolab.imap DEBUG [8873]: Server for mailbox 'user/test@kolabdemo.ch' is 'localhost'
2016-08-11 17:35:41,316 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,316 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:41,318 pykolab.plugins DEBUG [8873]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:42,252 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-11 17:35:42,253 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-11 17:35:42,321 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,321 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,321 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,322 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:42,322 pykolab.auth DEBUG [8874]: Entry type: user
2016-08-11 17:35:42,325 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,325 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,326 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,326 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:42,327 pykolab.auth DEBUG [8874]: Applying recipient policy to 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:42,327 pykolab.auth DEBUG [8874]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:42,327 pykolab.plugins DEBUG [8874]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:42,327 pykolab.utils DEBUG [8874]: Transliterating string 'User@vischn.ch' with locale 'en_US'
2016-08-11 17:35:42,328 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,328 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,328 pykolab.utils DEBUG [8874]: Executing 'User@vischn.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,332 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,333 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user@vischn.ch)(alias=user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,333 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,334 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,335 pykolab.auth DEBUG [8874]: 1 result for address user@vischn.ch found, verifying
2016-08-11 17:35:42,335 pykolab.auth DEBUG [8874]: Too bad, primary email address user@vischn.ch already in use for uid=user,ou=People,dc=vischn,dc=ch (we are uid=user2,ou=People,dc=vischn,dc=ch)
2016-08-11 17:35:42,335 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,336 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,336 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,336 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,337 pykolab.auth DEBUG [8874]: No results for mail address user2@vischn.ch found
2016-08-11 17:35:42,337 pykolab.plugins DEBUG [8874]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:42,338 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:42,338 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:42,338 pykolab.utils DEBUG [8874]: Transliterating string 'Master' with locale 'en_US'
2016-08-11 17:35:42,338 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,338 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,338 pykolab.utils DEBUG [8874]: Executing 'Master | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,343 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:42,343 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,344 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,344 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,348 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:42,348 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,348 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,348 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,353 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:42,353 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:42,353 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:42,353 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:42,354 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:42,354 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:42,354 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,354 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=m.user@vischn.ch)(alias=m.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,355 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,355 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,356 pykolab.auth DEBUG [8874]: No results for address m.user@vischn.ch found
2016-08-11 17:35:42,356 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,357 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,357 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,357 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,358 pykolab.auth DEBUG [8874]: No results for address user2@vischn.ch found
2016-08-11 17:35:42,358 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,358 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=master.user@vischn.ch)(alias=master.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,358 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,359 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,359 pykolab.auth DEBUG [8874]: No results for address master.user@vischn.ch found
2016-08-11 17:35:42,359 pykolab.auth DEBUG [8874]: Recipient policy composed the following set of secondary email addresses: ['m.user@vischn.ch', 'user2@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,359 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,360 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,360 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,360 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,360 pykolab.auth DEBUG [8874]: Entry modifications list: {}
2016-08-11 17:35:42,360 pykolab.auth DEBUG [8874]: Result from recipient policy: {}
2016-08-11 17:35:42,367 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:42,368 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:42,369 pykolab.imap DEBUG [8874]: Looking for folder 'user/user2@vischn.ch', we found folders: [u'user/user2@vischn.ch']
2016-08-11 17:35:42,370 pykolab.imap DEBUG [8874]: Server for mailbox 'user/user2@vischn.ch' is 'localhost'
2016-08-11 17:35:42,371 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,371 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,373 pykolab.plugins DEBUG [8874]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]: LDAP Search Result Data Entry:
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]:     DN: 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]:     Entry: {'displayName': ['User, Master'], 'cn': ['Master User'], 'mailQuota': ['1048576'], 'preferredLanguage': ['en_US'], 'nsuniqueid': ['711d6581-317711e6-9312c5af-b8834389'], 'objectClass': ['top', 'inetorgperson', 'kolabinetorgperson', 'mailrecipient', 'organizationalperson', 'person'], 'alias': ['m.user@vischn.ch', 'master.user@vischn.ch'], 'mailHost': ['localhost'], 'sn': ['User'], 'mail': ['user2@vischn.ch'], 'givenName': ['Master'], 'modifytimestamp': ['20160613150031Z'], 'uid': ['user2']}
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,375 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,376 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:42,377 pykolab.auth DEBUG [8874]: Entry type: user
2016-08-11 17:35:42,380 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,380 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,380 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,380 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:42,382 pykolab.auth DEBUG [8874]: Applying recipient policy to 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:42,382 pykolab.auth DEBUG [8874]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:42,382 pykolab.plugins DEBUG [8874]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:42,382 pykolab.utils DEBUG [8874]: Transliterating string 'User@vischn.ch' with locale 'en_US'
2016-08-11 17:35:42,383 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,383 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,383 pykolab.utils DEBUG [8874]: Executing 'User@vischn.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,388 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,389 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user@vischn.ch)(alias=user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,389 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,390 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,391 pykolab.auth DEBUG [8874]: 1 result for address user@vischn.ch found, verifying
2016-08-11 17:35:42,391 pykolab.auth DEBUG [8874]: Too bad, primary email address user@vischn.ch already in use for uid=user,ou=People,dc=vischn,dc=ch (we are uid=user2,ou=People,dc=vischn,dc=ch)
2016-08-11 17:35:42,392 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,392 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,393 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,393 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,394 pykolab.auth DEBUG [8874]: No results for mail address user2@vischn.ch found
2016-08-11 17:35:42,394 pykolab.plugins DEBUG [8874]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:42,395 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:42,395 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:42,395 pykolab.utils DEBUG [8874]: Transliterating string 'Master' with locale 'en_US'
2016-08-11 17:35:42,395 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,396 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,396 pykolab.utils DEBUG [8874]: Executing 'Master | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,402 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:42,402 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,403 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,403 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,408 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:42,408 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:42,408 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:42,408 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:42,413 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:42,414 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,414 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=m.user@vischn.ch)(alias=m.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,415 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,415 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,416 pykolab.auth DEBUG [8874]: No results for address m.user@vischn.ch found
2016-08-11 17:35:42,416 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,416 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,416 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,417 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,417 pykolab.auth DEBUG [8874]: No results for address user2@vischn.ch found
2016-08-11 17:35:42,417 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,418 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=master.user@vischn.ch)(alias=master.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:42,418 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:42,418 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: No results for address master.user@vischn.ch found
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: Recipient policy composed the following set of secondary email addresses: ['m.user@vischn.ch', 'user2@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:42,419 pykolab.auth DEBUG [8874]: Entry modifications list: {}
2016-08-11 17:35:42,420 pykolab.auth DEBUG [8874]: Result from recipient policy: {}
2016-08-11 17:35:42,425 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:42,426 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:42,427 pykolab.imap DEBUG [8874]: Looking for folder 'user/user2@vischn.ch', we found folders: [u'user/user2@vischn.ch']
2016-08-11 17:35:42,428 pykolab.imap DEBUG [8874]: Server for mailbox 'user/user2@vischn.ch' is 'localhost'
2016-08-11 17:35:42,428 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,429 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:42,430 pykolab.plugins DEBUG [8874]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:51,329 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-11 17:35:51,329 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-11 17:35:51,332 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,332 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,332 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,332 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:51,334 pykolab.auth DEBUG [8873]: Entry type: user
2016-08-11 17:35:51,337 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,338 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,338 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,338 pykolab.auth DEBUG [8873]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:51,339 pykolab.auth DEBUG [8873]: Applying recipient policy to 'uid=test,ou=People,dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,340 pykolab.auth DEBUG [8873]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:51,340 pykolab.plugins DEBUG [8873]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:51,340 pykolab.utils DEBUG [8873]: Transliterating string 'Test@kolabdemo.ch' with locale 'en_US'
2016-08-11 17:35:51,340 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:51,340 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:51,341 pykolab.utils DEBUG [8873]: Executing 'Test@kolabdemo.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:51,345 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,346 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:51,346 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,346 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,347 pykolab.auth DEBUG [8873]: No results for mail address test@kolabdemo.ch found
2016-08-11 17:35:51,348 pykolab.plugins DEBUG [8873]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:51,348 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:51,348 pykolab.plugins.recipientpolicy DEBUG [8873]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:51,348 pykolab.utils DEBUG [8873]: Transliterating string 'Blubber' with locale 'en_US'
2016-08-11 17:35:51,348 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:51,349 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:51,349 pykolab.utils DEBUG [8873]: Executing 'Blubber | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:51,353 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:51,353 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:51,353 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:51,353 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:51,358 pykolab.utils DEBUG [8873]: Transliterating string 'Test' with locale 'en_US'
2016-08-11 17:35:51,358 pykolab.utils DEBUG [8873]: Attempting to set locale
2016-08-11 17:35:51,358 pykolab.utils DEBUG [8873]: Success setting locale
2016-08-11 17:35:51,358 pykolab.utils DEBUG [8873]: Executing 'Test | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:51,362 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:51,362 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: B.Test@kolabdemo.ch
2016-08-11 17:35:51,363 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:51,363 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: test@kolabdemo.ch
2016-08-11 17:35:51,363 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:51,363 pykolab.plugins.recipientpolicy DEBUG [8873]: Appending additional mail address: Blubber.Test@kolabdemo.ch
2016-08-11 17:35:51,363 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,364 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=test@kolabdemo.ch)(alias=test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:51,364 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,364 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,366 pykolab.auth DEBUG [8873]: No results for address test@kolabdemo.ch found
2016-08-11 17:35:51,366 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,366 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=b.test@kolabdemo.ch)(alias=b.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:51,367 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,367 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,367 pykolab.auth DEBUG [8873]: No results for address b.test@kolabdemo.ch found
2016-08-11 17:35:51,368 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,368 pykolab.auth DEBUG [8873]: Finding recipient with filter '(&(|(mail=blubber.test@kolabdemo.ch)(alias=blubber.test@kolabdemo.ch))(!(nsuniqueid=947a5a81-5fd811e6-9312c5af-b8834389)))'
2016-08-11 17:35:51,368 pykolab.auth DEBUG [8873]: Searching root dn for domain 'kolabdemo.ch'
2016-08-11 17:35:51,368 pykolab.auth DEBUG [8873]: Returning from cache: 'dc=kolabdemo,dc=ch'
2016-08-11 17:35:51,369 pykolab.auth DEBUG [8873]: No results for address blubber.test@kolabdemo.ch found
2016-08-11 17:35:51,369 pykolab.auth DEBUG [8873]: Recipient policy composed the following set of secondary email addresses: ['test@kolabdemo.ch', 'b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:51,369 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:51,369 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:51,370 pykolab.auth DEBUG [8873]: secondary_mail_addresses: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:51,370 pykolab.auth DEBUG [8873]: entry[alias]: ['b.test@kolabdemo.ch', 'blubber.test@kolabdemo.ch']
2016-08-11 17:35:51,370 pykolab.auth DEBUG [8873]: Entry modifications list: {}
2016-08-11 17:35:51,370 pykolab.auth DEBUG [8873]: Result from recipient policy: {}
2016-08-11 17:35:51,376 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:51,377 pykolab.imap DEBUG [8873]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:51,378 pykolab.imap DEBUG [8873]: Looking for folder 'user/test@kolabdemo.ch', we found folders: [u'user/test@kolabdemo.ch']
2016-08-11 17:35:51,380 pykolab.imap DEBUG [8873]: Server for mailbox 'user/test@kolabdemo.ch' is 'localhost'
2016-08-11 17:35:51,380 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,380 pykolab.auth DEBUG [8873]: bind() called but already bound
2016-08-11 17:35:51,382 pykolab.plugins DEBUG [8873]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-11 17:35:52,441 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-11 17:35:52,442 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-11 17:35:52,444 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,445 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,445 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,445 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:52,446 pykolab.auth DEBUG [8874]: Entry type: user
2016-08-11 17:35:52,451 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,451 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,452 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,452 pykolab.auth DEBUG [8874]: Searching with filter '(objectclass=kolabinetorgperson)'
2016-08-11 17:35:52,457 pykolab.auth DEBUG [8874]: Applying recipient policy to 'uid=user2,ou=People,dc=vischn,dc=ch'
2016-08-11 17:35:52,458 pykolab.auth DEBUG [8874]: Using mail attributes: ['mail', 'alias'], with primary 'mail' and secondary 'alias'
2016-08-11 17:35:52,458 pykolab.plugins DEBUG [8874]: Executing hook set_primary_mail for plugin recipientpolicy
2016-08-11 17:35:52,458 pykolab.utils DEBUG [8874]: Transliterating string 'User@vischn.ch' with locale 'en_US'
2016-08-11 17:35:52,458 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:52,458 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:52,458 pykolab.utils DEBUG [8874]: Executing 'User@vischn.ch | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:52,463 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,464 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user@vischn.ch)(alias=user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:52,464 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,464 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,465 pykolab.auth DEBUG [8874]: 1 result for address user@vischn.ch found, verifying
2016-08-11 17:35:52,465 pykolab.auth DEBUG [8874]: Too bad, primary email address user@vischn.ch already in use for uid=user,ou=People,dc=vischn,dc=ch (we are uid=user2,ou=People,dc=vischn,dc=ch)
2016-08-11 17:35:52,465 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,466 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:52,466 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,466 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,467 pykolab.auth DEBUG [8874]: No results for mail address user2@vischn.ch found
2016-08-11 17:35:52,467 pykolab.plugins DEBUG [8874]: Executing hook set_secondary_mail for plugin recipientpolicy
2016-08-11 17:35:52,468 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:52,468 pykolab.plugins.recipientpolicy DEBUG [8874]: Alternative mail routines: {0: {'{0}.{1}@{2}': "format('%(givenname)s'[0:1].capitalize(), '%(surname)s', '%(domain)s')"}, 1: {'{0}@{1}': "format('%(uid)s', '%(domain)s')"}, 2: {'{0}@{1}': "format('%(givenname)s.%(surname)s', '%(domain)s')"}}
2016-08-11 17:35:52,468 pykolab.utils DEBUG [8874]: Transliterating string 'Master' with locale 'en_US'
2016-08-11 17:35:52,468 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:52,469 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:52,469 pykolab.utils DEBUG [8874]: Executing 'Master | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:52,473 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:52,473 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:52,473 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:52,474 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:52,478 pykolab.utils DEBUG [8874]: Transliterating string 'User' with locale 'en_US'
2016-08-11 17:35:52,478 pykolab.utils DEBUG [8874]: Attempting to set locale
2016-08-11 17:35:52,478 pykolab.utils DEBUG [8874]: Success setting locale
2016-08-11 17:35:52,478 pykolab.utils DEBUG [8874]: Executing 'User | /usr/bin/iconv -f UTF-8 -t ASCII//TRANSLIT -s'
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: M.User@vischn.ch
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: user2@vischn.ch
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:52,482 pykolab.plugins.recipientpolicy DEBUG [8874]: Appending additional mail address: Master.User@vischn.ch
2016-08-11 17:35:52,483 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,483 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=m.user@vischn.ch)(alias=m.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:52,483 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,484 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,485 pykolab.auth DEBUG [8874]: No results for address m.user@vischn.ch found
2016-08-11 17:35:52,485 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,486 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=user2@vischn.ch)(alias=user2@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:52,486 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,486 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,486 pykolab.auth DEBUG [8874]: No results for address user2@vischn.ch found
2016-08-11 17:35:52,487 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,487 pykolab.auth DEBUG [8874]: Finding recipient with filter '(&(|(mail=master.user@vischn.ch)(alias=master.user@vischn.ch))(!(nsuniqueid=711d6581-317711e6-9312c5af-b8834389)))'
2016-08-11 17:35:52,487 pykolab.auth DEBUG [8874]: Searching root dn for domain 'vischn.ch'
2016-08-11 17:35:52,487 pykolab.auth DEBUG [8874]: Returning from cache: 'dc=vischn,dc=ch'
2016-08-11 17:35:52,488 pykolab.auth DEBUG [8874]: No results for address master.user@vischn.ch found
2016-08-11 17:35:52,488 pykolab.auth DEBUG [8874]: Recipient policy composed the following set of secondary email addresses: ['m.user@vischn.ch', 'user2@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:52,488 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:52,489 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:52,489 pykolab.auth DEBUG [8874]: secondary_mail_addresses: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:52,489 pykolab.auth DEBUG [8874]: entry[alias]: ['m.user@vischn.ch', 'master.user@vischn.ch']
2016-08-11 17:35:52,489 pykolab.auth DEBUG [8874]: Entry modifications list: {}
2016-08-11 17:35:52,489 pykolab.auth DEBUG [8874]: Result from recipient policy: {}
2016-08-11 17:35:52,494 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:52,495 pykolab.imap DEBUG [8874]: Reusing existing IMAP server connection to localhost
2016-08-11 17:35:52,497 pykolab.imap DEBUG [8874]: Looking for folder 'user/user2@vischn.ch', we found folders: [u'user/user2@vischn.ch']
2016-08-11 17:35:52,498 pykolab.imap DEBUG [8874]: Server for mailbox 'user/user2@vischn.ch' is 'localhost'
2016-08-11 17:35:52,499 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,499 pykolab.auth DEBUG [8874]: bind() called but already bound
2016-08-11 17:35:52,501 pykolab.plugins DEBUG [8874]: Executing hook set_user_folder_quota for plugin dynamicquota
pascal.mages subscribed.Aug 11 2016, 7:43 PM
vendel.colja subscribed.Aug 12 2016, 2:27 PM
vendel.colja mentioned this in T1307: make pykolab synchronize queueing mechanism reliable.Aug 16 2016, 10:57 AM
vendel.colja added a comment.EditedAug 16 2016, 11:09 AM

pykolab.noarch 0.7.28-1.1.el6.kolab_14 kolab-14-updates

With pykolab 0.7.28 we discover the same issue.

Here an assembly of our logs:

Some 400 lines of pykolab.log as an example of what happens between two of those TIMEOUT ERRORs
grep -A 400 '2016-08-16 09:20:26,163' /var/log/kolab/pykolab.log

2016-08-16 09:20:26,163 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:26,177 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:20:26,178 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:20:26,180 pykolab.imap DEBUG [5684]: Looking for folder 'user/migtest95d.kolab@domain.de', we found folders: [u'user/migtest95d.kolab@domain.de']
2016-08-16 09:20:26,181 pykolab.imap DEBUG [5684]: Checking actual backend server for folder user/migtest95d.kolab@domain.de through annotations
2016-08-16 09:20:26,181 pykolab.imap DEBUG [5684]: Possibly reproducing the find mailfolder server answer from previously detected and stored annotation value: 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:20:26,181 pykolab.imap DEBUG [5684]: Server for mailbox 'user/migtest95d.kolab@domain.de' is 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:20:26,182 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:26,183 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:26,183 pykolab.auth DEBUG [5684]: Entry ID: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:20:26,183 pykolab.auth DEBUG [5684]: Entry DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:20:26,183 pykolab.auth DEBUG [5684]: ldap search: ('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
2016-08-16 09:20:26,188 pykolab.auth DEBUG [5684]: About to consider the user quota for 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de' (used: 0, imap: 1048576, ldap: '1048576', default: '1048576'
2016-08-16 09:20:26,188 pykolab.plugins DEBUG [5684]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-16 09:20:36,199 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:20:36,199 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-16 09:20:36,541 pykolab.auth DEBUG [5684]: auth.ldap.LDAP._synchronize_callback(args (), kw {'entry': [('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']})]})
2016-08-16 09:20:36,542 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:36,543 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:20:36,543 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:20:36,543 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:20:36,547 pykolab.auth DEBUG [5684]: Entry type: user
2016-08-16 09:20:36,549 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 ?
2016-08-16 09:20:36,549 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 ?
2016-08-16 09:20:36,549 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,549 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,565 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 ?
2016-08-16 09:20:36,565 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 ?
2016-08-16 09:20:36,565 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,565 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,578 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:36,578 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:20:36,579 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:20:36,579 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:20:36,584 pykolab.auth DEBUG [5684]: Not applying recipient policy for cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste München,c=de (disabled through configuration)
2016-08-16 09:20:36,584 pykolab.auth DEBUG [5684]: Result from recipient policy: {}
2016-08-16 09:20:36,584 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 ?
2016-08-16 09:20:36,584 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 ?
2016-08-16 09:20:36,585 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,585 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,598 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 ?
2016-08-16 09:20:36,598 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 ?
2016-08-16 09:20:36,598 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,598 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:20:36,612 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:20:36,614 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:20:36,616 pykolab.imap DEBUG [5684]: Looking for folder 'user/migtest95d.kolab@domain.de', we found folders: [u'user/migtest95d.kolab@domain.de']
2016-08-16 09:20:36,617 pykolab.imap DEBUG [5684]: Checking actual backend server for folder user/migtest95d.kolab@domain.de through annotations
2016-08-16 09:20:36,617 pykolab.imap DEBUG [5684]: Possibly reproducing the find mailfolder server answer from previously detected and stored annotation value: 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:20:36,618 pykolab.imap DEBUG [5684]: Server for mailbox 'user/migtest95d.kolab@domain.de' is 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:20:36,618 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:36,618 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:20:36,619 pykolab.auth DEBUG [5684]: Entry ID: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:20:36,619 pykolab.auth DEBUG [5684]: Entry DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:20:36,619 pykolab.auth DEBUG [5684]: ldap search: ('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
2016-08-16 09:20:36,623 pykolab.auth DEBUG [5684]: About to consider the user quota for 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de' (used: 0, imap: 1048576, ldap: '1048576', default: '1048576'
2016-08-16 09:20:36,624 pykolab.plugins DEBUG [5684]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-16 09:22:37,341 pykolab.daemon DEBUG [5683]: added domains: [], removed domains: []
2016-08-16 09:22:37,343 pykolab.auth DEBUG [5683]: Called for domain None
2016-08-16 09:22:37,343 pykolab.auth DEBUG [5683]: Using section domain.de and domain domain.de
2016-08-16 09:22:37,343 pykolab.auth DEBUG [5683]: Using section domain.de and domain domain.de
2016-08-16 09:22:37,343 pykolab.auth DEBUG [5683]: Connecting to Authentication backend for domain domain.de
2016-08-16 09:22:37,344 pykolab.auth DEBUG [5683]: Section domain.de has no option 'auth_mechanism'
2016-08-16 09:22:37,344 pykolab.auth DEBUG [5683]: Starting LDAP...
2016-08-16 09:22:37,344 pykolab.auth DEBUG [5683]: Connecting to LDAP...
2016-08-16 09:22:37,345 pykolab.auth DEBUG [5683]: Attempting to use LDAP URI ldap://ldaptest.domain.de:389
2016-08-16 09:22:37,346 pykolab.daemon DEBUG [5683]: Listing domains...
2016-08-16 09:22:37,346 pykolab.auth DEBUG [5683]: Called for domain None
2016-08-16 09:22:37,346 pykolab.auth DEBUG [5683]: Listing domains...
2016-08-16 09:22:37,347 pykolab.auth DEBUG [5683]: Binding with bind_dn: cn=svc pykolab,ou=kolab,o=Application,c=de and password: *****************
2016-08-16 09:22:37,351 pykolab.auth DEBUG [5683]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=*))'
2016-08-16 09:22:37,352 pykolab.auth DEBUG [5683]: bind() called but already bound
2016-08-16 09:22:37,352 pykolab.auth DEBUG [5683]: bind() called but already bound
2016-08-16 09:22:37,352 pykolab.auth DEBUG [5683]: Entry ID: ''
2016-08-16 09:22:37,353 pykolab.auth DEBUG [5683]: Entry DN: ''
2016-08-16 09:22:37,353 pykolab.auth DEBUG [5683]: ldap search: ('', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['namingContexts']
2016-08-16 09:22:37,356 pykolab.auth DEBUG [5683]: Naming contexts found: ['c=de']
2016-08-16 09:22:37,356 pykolab.auth DEBUG [5683]: Searching root dn for domain 'domain.de'
2016-08-16 09:22:37,356 pykolab.auth DEBUG [5683]: bind() called but already bound
2016-08-16 09:22:37,356 pykolab.auth DEBUG [5683]: Finding domain root dn for domain domain.de
2016-08-16 09:22:37,357 pykolab.auth DEBUG [5683]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=domain.de))'
2016-08-16 09:22:37,358 pykolab.auth DEBUG [5683]: Setting domain root dn from LDAP for domain 'domain.de': 'c=de'
2016-08-16 09:22:37,358 pykolab.auth DEBUG [5683]: Domains/Root DNs found: {'domain.de': 'c=de'}
2016-08-16 09:22:37,358 pykolab.daemon DEBUG [5683]: Domain Base DN for domain 'domain.de' is 'c=de'
2016-08-16 09:22:37,358 pykolab.auth DEBUG [5683]: bind() called but already bound
2016-08-16 09:22:37,358 pykolab.auth DEBUG [5683]: Searching root dn for domain 'e'
2016-08-16 09:22:37,359 pykolab.auth DEBUG [5683]: bind() called but already bound
2016-08-16 09:22:37,359 pykolab.auth DEBUG [5683]: Finding domain root dn for domain e
2016-08-16 09:22:37,359 pykolab.auth DEBUG [5683]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=e))'
2016-08-16 09:22:37,360 pykolab.daemon DEBUG [5683]: Naming contexts to synchronize: [None]
2016-08-16 09:22:37,360 pykolab.daemon DEBUG [5683]: All naming contexts: [None]
2016-08-16 09:22:37,360 pykolab.daemon DEBUG [5683]: Checking for domain None
2016-08-16 09:22:37,360 pykolab.daemon DEBUG [5683]: Domain None already there and alive.
2016-08-16 09:25:36,663 pykolab.auth DEBUG [5684]: Called for domain None
2016-08-16 09:25:36,663 pykolab.auth DEBUG [5684]: Using section domain.de and domain domain.de
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Using section domain.de and domain domain.de
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Connecting to Authentication backend for domain domain.de
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Section domain.de has no option 'auth_mechanism'
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Starting LDAP...
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Connecting to LDAP...
2016-08-16 09:25:36,664 pykolab.auth DEBUG [5684]: Attempting to use LDAP URI ldap://ldaptest.domain.de:389
2016-08-16 09:25:36,666 pykolab.auth DEBUG [5684]: Binding with bind_dn: cn=svc pykolab,ou=kolab,o=Application,c=de and password: *****************
2016-08-16 09:25:36,670 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 ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2016-08-16 09:25:36,670 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 ORDER BY entry.last_change DESC
 LIMIT ? OFFSET ?
2016-08-16 09:25:36,671 sqlalchemy.engine.base.Engine INFO (1, 0)
2016-08-16 09:25:36,671 sqlalchemy.engine.base.Engine INFO (1, 0)
2016-08-16 09:25:36,727 pykolab.auth DEBUG [5684]: Using timestamp '20160812133016Z'
2016-08-16 09:25:36,727 pykolab.auth DEBUG [5684]: Using filter '(&(|(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))(&(objectclass=lhmDistributionList)(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(!(objectclass=nstombstone)))(&(objectclass=kolabresource)(|(&(objectclass=kolabsharedfolder)(kolabfoldertype=event)(mail=NOCHNICHTAKTIV))(objectclass=groupofuniquenames)(objectclass=groupofurls))(!(objectclass=nstombstone)))(&(objectclass=kolabsharedfolder)(!(&(objectclass=lhmDistributionList)(|(objectclass=groupofuniquenames)(objectclass=groupofurls))(!(objectclass=nstombstone))))(!(objectclass=nstombstone))))(modifytimestamp>=20160812133016Z))'
2016-08-16 09:25:36,727 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:36,727 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:36,727 pykolab.auth DEBUG [5684]: Finding domain root dn for domain domain.de
2016-08-16 09:25:36,728 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=domainrelatedobject)(associatedDomain=domain.de))'
2016-08-16 09:25:36,730 pykolab.auth DEBUG [5684]: Setting domain root dn from LDAP for domain 'domain.de': 'c=de'
2016-08-16 09:25:36,730 pykolab.auth DEBUG [5684]: Synchronization is searching against base DN: c=de
2016-08-16 09:25:37,027 pykolab.auth DEBUG [5684]: LDAP Search Result Data Entry:
2016-08-16 09:25:37,028 pykolab.auth DEBUG [5684]:     DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:37,028 pykolab.auth DEBUG [5684]:     Entry: {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']}
2016-08-16 09:25:37,028 pykolab.auth DEBUG [5684]: auth.ldap.LDAP._synchronize_callback(args (), kw {'dn': 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 'change_type': None, 'primary_domain': None, 'secondary_domains': [], 'entry': {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']}, 'previous_dn': None, 'change_number': None})
2016-08-16 09:25:37,029 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:37,030 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:37,030 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:37,030 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:37,036 pykolab.auth DEBUG [5684]: Entry type: user
2016-08-16 09:25:37,037 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 ?
2016-08-16 09:25:37,037 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 ?
2016-08-16 09:25:37,037 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,037 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,051 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 ?
2016-08-16 09:25:37,051 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 ?
2016-08-16 09:25:37,051 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,051 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,064 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:37,064 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:37,064 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:37,065 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:37,068 pykolab.auth DEBUG [5684]: Not applying recipient policy for cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste München,c=de (disabled through configuration)
2016-08-16 09:25:37,068 pykolab.auth DEBUG [5684]: Result from recipient policy: {}
2016-08-16 09:25:37,069 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 ?
2016-08-16 09:25:37,069 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 ?
2016-08-16 09:25:37,069 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,069 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,082 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 ?
2016-08-16 09:25:37,082 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 ?
2016-08-16 09:25:37,082 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,082 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:37,115 pykolab.imap DEBUG [5684]: Logging on to Cyrus IMAP server imap-test.domain.de
2016-08-16 09:25:37,149 pykolab.imap DEBUG [5684]: Continuing with separator: '/'
2016-08-16 09:25:37,149 pykolab.imap DEBUG [5684]: Detected we are running in a Murder topology
2016-08-16 09:25:37,151 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:25:37,154 pykolab.imap DEBUG [5684]: Looking for folder 'user/migtest95d.kolab@domain.de', we found folders: [u'user/migtest95d.kolab@domain.de']
2016-08-16 09:25:37,155 pykolab.imap DEBUG [5684]: Checking actual backend server for folder user/migtest95d.kolab@domain.de through annotations
2016-08-16 09:25:37,157 pykolab.imap DEBUG [5684]: Server for INBOX folder user/migtest95d.kolab@domain.de is kolabbek001.srv.ha3.dir.domain.de
2016-08-16 09:25:37,157 pykolab.imap DEBUG [5684]: Server for mailbox 'user/migtest95d.kolab@domain.de' is 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:25:37,158 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:37,158 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:37,158 pykolab.auth DEBUG [5684]: Entry ID: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:37,158 pykolab.auth DEBUG [5684]: Entry DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:37,158 pykolab.auth DEBUG [5684]: ldap search: ('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
2016-08-16 09:25:37,190 pykolab.auth DEBUG [5684]: About to consider the user quota for 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de' (used: 0, imap: 1048576, ldap: '1048576', default: '1048576'
2016-08-16 09:25:37,190 pykolab.plugins DEBUG [5684]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-16 09:25:47,201 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:25:47,202 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-16 09:25:47,539 pykolab.auth DEBUG [5684]: auth.ldap.LDAP._synchronize_callback(args (), kw {'entry': [('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']})]})
2016-08-16 09:25:47,540 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,540 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:47,540 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:47,541 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:47,545 pykolab.auth DEBUG [5684]: Entry type: user
2016-08-16 09:25:47,547 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 ?
2016-08-16 09:25:47,547 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 ?
2016-08-16 09:25:47,547 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,547 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,561 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 ?
2016-08-16 09:25:47,561 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 ?
2016-08-16 09:25:47,561 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,561 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,573 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,574 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:47,574 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:47,574 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:47,577 pykolab.auth DEBUG [5684]: Not applying recipient policy for cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste München,c=de (disabled through configuration)
2016-08-16 09:25:47,577 pykolab.auth DEBUG [5684]: Result from recipient policy: {}
2016-08-16 09:25:47,578 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 ?
2016-08-16 09:25:47,578 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 ?
2016-08-16 09:25:47,578 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,578 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,591 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 ?
2016-08-16 09:25:47,591 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 ?
2016-08-16 09:25:47,592 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,592 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,605 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:25:47,606 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:25:47,608 pykolab.imap DEBUG [5684]: Looking for folder 'user/migtest95d.kolab@domain.de', we found folders: [u'user/migtest95d.kolab@domain.de']
2016-08-16 09:25:47,609 pykolab.imap DEBUG [5684]: Checking actual backend server for folder user/migtest95d.kolab@domain.de through annotations
2016-08-16 09:25:47,609 pykolab.imap DEBUG [5684]: Possibly reproducing the find mailfolder server answer from previously detected and stored annotation value: 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:25:47,609 pykolab.imap DEBUG [5684]: Server for mailbox 'user/migtest95d.kolab@domain.de' is 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:25:47,609 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,609 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,609 pykolab.auth DEBUG [5684]: Entry ID: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:47,610 pykolab.auth DEBUG [5684]: Entry DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:47,610 pykolab.auth DEBUG [5684]: ldap search: ('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
2016-08-16 09:25:47,614 pykolab.auth DEBUG [5684]: About to consider the user quota for 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de' (used: 0, imap: 1048576, ldap: '1048576', default: '1048576'
2016-08-16 09:25:47,614 pykolab.plugins DEBUG [5684]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-16 09:25:47,894 pykolab.auth DEBUG [5684]: LDAP Search Result Data Entry:
2016-08-16 09:25:47,894 pykolab.auth DEBUG [5684]:     DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:47,894 pykolab.auth DEBUG [5684]:     Entry: {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']}
2016-08-16 09:25:47,894 pykolab.auth DEBUG [5684]: auth.ldap.LDAP._synchronize_callback(args (), kw {'dn': 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 'change_type': None, 'primary_domain': None, 'secondary_domains': [], 'entry': {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']}, 'previous_dn': None, 'change_number': None})
2016-08-16 09:25:47,895 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,895 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:47,896 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:47,896 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:47,900 pykolab.auth DEBUG [5684]: Entry type: user
2016-08-16 09:25:47,902 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 ?
2016-08-16 09:25:47,902 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 ?
2016-08-16 09:25:47,902 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,902 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,916 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 ?
2016-08-16 09:25:47,916 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 ?
2016-08-16 09:25:47,916 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,916 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,928 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,929 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:47,929 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:47,929 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:47,934 pykolab.auth DEBUG [5684]: Not applying recipient policy for cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste München,c=de (disabled through configuration)
2016-08-16 09:25:47,934 pykolab.auth DEBUG [5684]: Result from recipient policy: {}
2016-08-16 09:25:47,935 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 ?
2016-08-16 09:25:47,935 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 ?
2016-08-16 09:25:47,935 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,935 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,948 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 ?
2016-08-16 09:25:47,948 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 ?
2016-08-16 09:25:47,948 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,948 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:47,959 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:25:47,960 pykolab.imap DEBUG [5684]: Reusing existing IMAP server connection to imap-test.domain.de
2016-08-16 09:25:47,962 pykolab.imap DEBUG [5684]: Looking for folder 'user/migtest95d.kolab@domain.de', we found folders: [u'user/migtest95d.kolab@domain.de']
2016-08-16 09:25:47,963 pykolab.imap DEBUG [5684]: Checking actual backend server for folder user/migtest95d.kolab@domain.de through annotations
2016-08-16 09:25:47,963 pykolab.imap DEBUG [5684]: Possibly reproducing the find mailfolder server answer from previously detected and stored annotation value: 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:25:47,963 pykolab.imap DEBUG [5684]: Server for mailbox 'user/migtest95d.kolab@domain.de' is 'kolabbek001.srv.ha3.dir.domain.de'
2016-08-16 09:25:47,964 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,964 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:47,964 pykolab.auth DEBUG [5684]: Entry ID: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:47,964 pykolab.auth DEBUG [5684]: Entry DN: 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de'
2016-08-16 09:25:47,964 pykolab.auth DEBUG [5684]: ldap search: ('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['mailquota']
2016-08-16 09:25:47,968 pykolab.auth DEBUG [5684]: About to consider the user quota for 'cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de' (used: 0, imap: 1048576, ldap: '1048576', default: '1048576'
2016-08-16 09:25:47,969 pykolab.plugins DEBUG [5684]: Executing hook set_user_folder_quota for plugin dynamicquota
2016-08-16 09:25:57,979 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:25:57,980 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 3059, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.6/site-packages/pykolab/auth/ldap/__init__.py", line 2738, in _persistent_search
    resp_ctrl_classes={ecnc.controlType:ecnc}
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 476, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
    result = func(*args,**kwargs)
TIMEOUT

2016-08-16 09:25:58,316 pykolab.auth DEBUG [5684]: auth.ldap.LDAP._synchronize_callback(args (), kw {'entry': [('cn=MigTest95d Kolab,ou=Testuser Migration,ou=KOLAB-Testuser,ou=1. Testou-xxx,o=Grundfeste Wustermoringen,c=de', {'lhmTitle': ['Frau'], 'uid': ['migtest95d.kolab'], 'lhmPopImap': ['IMAP'], 'objectClass': ['inetOrgPerson', 'kolabInetOrgPerson', 'lhmObject', 'lhmPerson', 'lhmTempKolab', 'mailRecipient', 'organizationalPerson', 'person', 'posixAccount', 'top'], 'uidNumber': ['16100101'], 'street': ['Teststr. 1'], 'lhmCalUser': ['Nein'], 'lhmMailboxServer': ['head'], 'cn': ['MigTest95d Kolab'], 'preferredLanguage': ['de_DE'], 'lhmTempKolabEnabled': ['FALSE'], 'lhmObjectID': ['911188532'], 'lhmDisplayPrintTelIndex': ['TRUE'], 'postalCode': ['80331'], 'mail': ['migtest95d.kolab@domain.de'], 'lhmListMemberAuto': ['TRUE'], 'lhmHideMobile': ['FALSE'], 'lhmDisplayPrintTel': ['TRUE'], 'description': ['ImportTimestamp:20160519060847'], 'lhmOfficePostalCode': ['80331'], 'loginShell': ['/bin/bash'], 'lhmOfficeLocalityName': ['Wustermoringen'], 'nsuniqueid': ['0187c295-534211e6-801caa55-5371e77f'], 'lhmOfficeStreetAddress': ['Teststr. 1'], 'lhmFaxUser': ['Nein'], 'gidNumber': ['513'], 'lhmRasLevel': ['none'], 'lhmJumperAdmin': ['FALSE'], 'displayName': ['MigTest95d Kolab'], 'mailQuota': ['1048576'], 'lhmSAPrequired': ['FALSE'], 'l': ['Wustermoringen'], 'mailHost': ['kolabbek001.srv.ha3.dir.domain.de'], 'gecos': ['MigTest95d Kolab'], 'sn': ['Kolab'], 'lhmRasUser': ['FALSE'], 'homeDirectory': ['/home/migtest95d.kolab'], 'ou': ['MIGTESTKOLAB'], 'givenName': ['MigTest95d'], 'modifytimestamp': ['20160812133016Z']})]})
2016-08-16 09:25:58,317 pykolab.auth DEBUG [5684]: bind() called but already bound
2016-08-16 09:25:58,318 pykolab.auth DEBUG [5684]: Searching root dn for domain 'domain.de'
2016-08-16 09:25:58,318 pykolab.auth DEBUG [5684]: Returning from cache: 'c=de'
2016-08-16 09:25:58,318 pykolab.auth DEBUG [5684]: Searching with filter '(&(objectclass=kolabinetorgperson)(objectclass=mailrecipient)(mail=*))'
2016-08-16 09:25:58,322 pykolab.auth DEBUG [5684]: Entry type: user
2016-08-16 09:25:58,324 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 ?
2016-08-16 09:25:58,324 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 ?
2016-08-16 09:25:58,324 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:58,324 sqlalchemy.engine.base.Engine INFO ('0187c295-534211e6-801caa55-5371e77f', 1, 0)
2016-08-16 09:25:58,339 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 = ?

This to give an overview how regularly the TIMEOUT ERROR occures,
grep 'ERROR An error occured using _persistent_search: TIMEOUT' /var/log/kolab/pykolab.lo

2016-08-16 07:59:52,575 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:00:03,466 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:05:18,884 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:05:29,687 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:10:40,771 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:10:51,817 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:16:02,903 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:16:13,711 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:21:24,785 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:21:35,581 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:26:46,685 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:26:57,423 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:32:08,451 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:32:19,272 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:37:30,526 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:37:41,389 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:42:52,496 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:43:03,278 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:48:14,330 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:48:25,089 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:53:36,153 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:53:46,991 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:58:57,996 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 08:59:08,814 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:04:19,794 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:04:30,549 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:09:41,523 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:09:52,402 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:15:03,517 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:15:14,345 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:20:25,421 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:20:36,199 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:25:47,201 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:25:57,979 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:31:09,055 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:31:19,897 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:36:31,104 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:36:41,863 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:41:52,903 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:42:03,682 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:47:14,728 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:47:25,485 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:52:36,499 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:52:47,322 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:57:58,387 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 09:58:09,146 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:03:20,241 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:03:31,007 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:08:42,041 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:08:52,853 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:14:03,865 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:14:14,653 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:19:25,699 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:19:36,517 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:24:47,595 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:24:58,433 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:30:09,637 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:30:20,570 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:35:31,859 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:35:42,894 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:40:53,932 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:41:04,798 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:46:15,998 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:46:26,792 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:51:40,083 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:51:50,974 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:57:04,777 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 10:57:15,859 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
2016-08-16 11:02:30,425 pykolab.auth ERROR An error occured using _persistent_search: TIMEOUT()
Florian_Eder added subscribers: Florian_Eder, Robert_Selk.Aug 17 2016, 2:11 PM
machniak assigned this task to vanmeeuwen.Aug 17 2016, 4:17 PM
machniak subscribed.

In rPd71e26c1a we added 10 second timeout (OPT_TIMEOUT option). I'm curious if we shouldn't use OPT_NETWORK_TIMEOUT and/or greater OPT_TIMEOUT value. Jeroen, what was your intention?

vanmeeuwen added a comment.Aug 18 2016, 11:21 AM

Line 444 should be claused similarly to line 431 (by line 430)

machniak added a comment.Aug 18 2016, 11:27 AM

Ehh. So, different value for immediate? What values?

vanmeeuwen added a comment.Aug 18 2016, 1:36 PM

rather than setting the timeout unconditionally, it should set the timeout only for if immediate:

machniak added a revision: D208: T1414: Set LDAP TIMEOUT option only on "immediate" connection.Aug 18 2016, 2:18 PM
tobru added a comment.Aug 18 2016, 2:31 PM

Thanks for your effort. As soon as the changes are available in Winterfell, I'll be happy to test it.

vendel.colja added a comment.Aug 18 2016, 3:04 PM

We'll test it in Kolab Enterprise 14 repos if available.

machniak added a comment.Sep 8 2016, 11:33 AM

I applied the fix into Kolab Winterfell installation, and I still see "infinite" processing loop with the same traceback. I restarted wallace and kolabd.

machniak added a comment.Sep 9 2016, 2:25 PM

I finally found the culprit. Differential updated.

vanmeeuwen closed this task as Resolved by committing rP54cb493d655b: T1414: Set LDAP TIMEOUT option only on "immediate" connection.Oct 6 2016, 11:38 AM
vanmeeuwen added a commit: rP54cb493d655b: T1414: Set LDAP TIMEOUT option only on "immediate" connection.
vanmeeuwen added a commit: rP764103053f06: T1414: Set LDAP TIMEOUT option only on "immediate" connection.