Page MenuHomePhorge
Create Task
Maniphest T2166

wallace fails to read resource calendar
Open, NormalPublic
Actions

Description

The problem is that wallace fails to accept or decline resource booking requests.
If /etc/sysconfig/wallace is set to use -l debug -d 8 then:

2017-01-02 11:15:35,274 pykolab.imap DEBUG [6639]: Logging on to Cyrus IMAP server localhost
2017-01-02 11:15:35,311 pykolab.imap DEBUG [6639]: Continuing with separator: '/'
2017-01-02 11:15:35,311 pykolab.imap DEBUG [6639]: This system is not part of a murder topology
2017-01-02 11:15:35,344 pykolab.wallace DEBUG [6639]: Fetching message UID '1' from folder 'shared/Resources/Aquarium@domain.io'
2017-01-02 11:15:35,394 pykolab.wallace DEBUG [6639]: Fetching message UID '2' from folder 'shared/Resources/Aquarium@domain.io'
2017-01-02 11:15:35,397 pykolab.wallace DEBUG [6639]: Fetching message UID '3' from folder 'shared/Resources/Aquarium@domain.io'
2017-01-02 11:15:35,440 pykolab.wallace DEBUG [6639]: Fetching message UID '4' from folder 'shared/Resources/Aquarium@domain.io'
2017-01-02 11:15:35,483 pykolab.wallace DEBUG [6639]: Attempt to move forward kolab event recurrence from 2016-12-08 15:00:00+01:00 closer to 2017-01-03 20:30:00+02:00
2017-01-02 11:15:35,502 pykolab.wallace DEBUG [6639]: Attempt to move forward kolab event recurrence from 2016-12-15 15:00:00+01:00 closer to 2017-01-03 20:30:00+02:00
2017-01-02 11:15:35,503 pykolab.wallace DEBUG [6639]: Attempt to move forward kolab event recurrence from 2016-12-22 15:00:00+01:00 closer to 2017-01-03 20:30:00+02:00
2017-01-02 11:15:35,503 pykolab.wallace DEBUG [6639]: Attempt to move forward kolab event recurrence from 2016-12-29 15:00:00+01:00 closer to 2017-01-03 20:30:00+02:00
2017-01-02 11:15:35,504 pykolab.wallace DEBUG [6639]: * Comparing itip at 2017-01-03 20:30:00+02:00/2017-01-03 21:00:00+02:00 with kolab at 2017-01-05 13:30:00+01:00/2017-01-05 15:00:00+01:00: False (1)
2017-01-02 11:15:35,504 pykolab.wallace DEBUG [6639]: Fetching message UID '5' from folder 'shared/Resources/Aquarium@domain.io'
2017-01-02 11:15:35,504 pykolab.wallace ERROR Failed to read resource calendar for 'cn=Aquarium,ou=Resources,dc=domain,dc=io': abort('socket error: [Errno 32] Broken pipe',)
2017-01-02 11:15:35,505 pykolab.auth DEBUG [6639]: bind() called but already bound
2017-01-02 11:15:35,505 pykolab.auth DEBUG [6639]: Searching root dn for domain 'domain.io'
2017-01-02 11:15:35,505 pykolab.auth DEBUG [6639]: Returning from cache: 'dc=domain,dc=io'
2017-01-02 11:15:35,505 pykolab.auth DEBUG [6639]: Searching with filter '(uniquemember=cn=Aquarium,ou=Resources,dc=domain,dc=io)'
2017-01-02 11:15:35,508 pykolab.wallace DEBUG [6639]: Accept invitation for individual resource 'cn=Aquarium,ou=Resources,dc=domain,dc=io' / 'resource-confroom-aquarium@domain.io'
2017-01-02 11:15:35,508 pykolab.auth DEBUG [6639]: bind() called but already bound
2017-01-02 11:15:35,508 pykolab.auth DEBUG [6639]: Searching root dn for domain 'domain.io'
2017-01-02 11:15:35,508 pykolab.auth DEBUG [6639]: Returning from cache: 'dc=domain,dc=io'
2017-01-02 11:15:35,508 pykolab.auth DEBUG [6639]: Searching with filter '(uniquemember=cn=Aquarium,ou=Resources,dc=domain,dc=io)'
2017-01-02 11:15:35,509 pykolab.imap ERROR Could not set ACL for cyrus-admin on folder "shared/Resources/Aquarium@domain.io": CYRUSError(99, 'SETACL', '[Errno 32] Broken pipe')
2017-01-02 11:15:35,512 pykolab.wallace ERROR Failed to save event to resource calendar at 'shared/Resources/Aquarium@domain.io': abort('socket error: [Errno 32] Broken pipe',)
2017-01-02 11:15:35,512 pykolab.wallace DEBUG [6639]: Adding event to 'shared/Resources/Aquarium@domain.io': False

NOTE Fetching message UID messages was added by me. There are about 50 messages to parse for wallace in this resource.
Running wallace with debug level 9 fails to connect to IMAP (which is actually Guam)

2017-01-02 11:46:36,335 pykolab.auth DEBUG [10700]: ldap search: ('cn=Aquarium,ou=Resources,dc=domain,dc=io', 0, filterstr='(objectclass=*)', attrlist=[ 'dn' ] + ['*']
2017-01-02 11:46:36,336 pykolab.wallace DEBUG [10700]: Resources: ['cn=Aquarium,ou=Resources,dc=domain,dc=io']; {'cn=Aquarium,ou=Resources,dc=domain,dc=io': {'dn': 'cn=Aquarium,ou=Resources,dc=domain,dc=io', 'domain': 'domain.io', 'cn': 'Aquarium', 'objectclass': ['top', 'kolabsharedfolder', 'kolabresource', 'mailrecipient'], 'kolabfoldertype': 'event', 'acl': ['anyone, read-only', 'sebastian.giss@domain.io, read-write'], 'kolabtargetfolder': 'shared/Resources/Aquarium@domain.io', 'mail': 'resource-confroom-aquarium@domain.io'}}
2017-01-02 11:46:36,411 pykolab.imap DEBUG [10700]: Logging on to Cyrus IMAP server localhost
^C

If I set wallace to connect directly to Cyrus in /etc/kolab/kolab.conf, then I get CYRUSError: (10, 'LOGIN', SSLError(1, u'[SSL: TLSV1_ALERT_PROTOCOL_VERSION] tlsv1 alert protocol version (_ssl.c:1750)')) error:

2017-01-02 11:51:51,057 pykolab.wallace DEBUG [10915]: Resources: ['cn=Aquarium,ou=Resources,dc=domain,dc=io']; {'cn=Aquarium,ou=Resources,dc=domain,dc=io': {'dn': 'cn=Aquarium,ou=Resources,dc=domain,dc=io', 'domain': 'domain.io', 'cn': 'Aquarium', 'objectclass': ['top', 'kolabsharedfolder', 'kolabresource', 'mailrecipient'], 'kolabfoldertype': 'event', 'acl': ['anyone, read-only', 'sebastian.giss@domain.io, read-write'], 'kolabtargetfolder': 'shared/Resources/Aquarium@domain.io', 'mail': 'resource-confroom-aquarium@domain.io'}}
2017-01-02 11:51:51,114 pykolab.imap DEBUG [10915]: Logging on to Cyrus IMAP server localhost
2017-01-02 11:51:51,115 pykolab.wallace ERROR Unknown error occurred; CYRUSError(10, 'LOGIN', '1750)')
2017-01-02 11:51:51,116 pykolab.wallace ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/wallace/modules.py", line 118, in execute
    return modules[name]['function'](*args, **kw)
  File "/usr/lib/python2.7/site-packages/wallace/module_resources.py", line 260, in execute
    imap.connect()
  File "/usr/lib/python2.7/site-packages/pykolab/imap/__init__.py", line 170, in connect
    self._imap[hostname].login(admin_login, admin_password)
  File "/usr/lib/python2.7/site-packages/pykolab/imap/cyrus.py", line 142, in login
    cyruslib.CYRUS.login(self, *args, **kw)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 419, in login
    self.__doexception("LOGIN", error)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 359, in __doexception
    self.__doraise( function.upper(), msg )
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 368, in __doraise
    raise CYRUSError( idError[0], mode, msg )
CYRUSError: (10, 'LOGIN', '1750)')

I know that this is TLS version allert error when I modify /usr/lib/python2.7/site-packages/cyruslib.py to give full error message.
Running wallace from command line works fine and wallace accepts the invitation and sends the response back with IMAP being Guam or Cyrus.
OTRS: 1100153

Details

Ticket Type
Task

Related Objects

Event Timeline

adomaitis created this task.Jan 2 2017, 11:58 AM
adomaitis added a project: PyKolab.Jan 2 2017, 1:04 PM
petersen subscribed.Jan 5 2017, 2:36 PM
petersen added a subscriber: machniak.Jan 5 2017, 2:48 PM
adomaitis added a comment.Jan 5 2017, 4:29 PM

I was able to bypass the issue in debug mode 8, by setting self.LOGFD = open('/var/log/kolab/cyruslib.log', 'a') around line 319 in cyruslib/py library. Now wallace successfully parse the message and resource calendar and accepts the invitation.
The same trick gives different results in debug level 9:

2017-01-05 16:23:43,776 pykolab.wallace ERROR Module resources.heartbeat() failed with error: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/wallace/__init__.py", line 89, in modules_heartbeat
    modules.heartbeat(module, lastrun)
  File "/usr/lib/python2.7/site-packages/wallace/modules.py", line 128, in heartbeat
    return modules[name]['heartbeat'](*args, **kw)
  File "/usr/lib/python2.7/site-packages/wallace/module_resources.py", line 442, in heartbeat
    imap.connect()
  File "/usr/lib/python2.7/site-packages/pykolab/imap/__init__.py", line 170, in connect
    self._imap[hostname].login(admin_login, admin_password)
  File "/usr/lib/python2.7/site-packages/pykolab/imap/cyrus.py", line 142, in login
    cyruslib.CYRUS.login(self, *args, **kw)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 419, in login
    self.__doexception("LOGIN", error)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 359, in __doexception
    self.__doraise( function.upper(), msg )
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 368, in __doraise
    raise CYRUSError( idError[0], mode, msg )
CYRUSError: (10, 'LOGIN', '[Errno 9] Bad file descriptor')

and

2017-01-05 16:25:10,389 pykolab.imap DEBUG [13257]: Logging on to Cyrus IMAP server localhost
2017-01-05 16:25:10,422 pykolab.wallace ERROR Unknown error occurred; CYRUSError(10, 'LOGIN', '[Errno 32] Broken pipe')
2017-01-05 16:25:10,423 pykolab.wallace ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/wallace/modules.py", line 118, in execute
    return modules[name]['function'](*args, **kw)
  File "/usr/lib/python2.7/site-packages/wallace/module_invitationpolicy.py", line 363, in execute
    imap.connect()
  File "/usr/lib/python2.7/site-packages/pykolab/imap/__init__.py", line 170, in connect
    self._imap[hostname].login(admin_login, admin_password)
  File "/usr/lib/python2.7/site-packages/pykolab/imap/cyrus.py", line 142, in login
    cyruslib.CYRUS.login(self, *args, **kw)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 419, in login
    self.__doexception("LOGIN", error)
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 359, in __doexception
    self.__doraise( function.upper(), msg )
  File "/usr/lib/python2.7/site-packages/cyruslib.py", line 368, in __doraise
    raise CYRUSError( idError[0], mode, msg )
CYRUSError: (10, 'LOGIN', '[Errno 32] Broken pipe')

and

2017-01-05 16:25:00,082 pykolab.auth ERROR LDAP server unavailable: SERVER_DOWN({'desc': "Can't contact LDAP server"},)
2017-01-05 16:25:00,084 pykolab.auth ERROR Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 3065, in _search
    secondary_domains
  File "<string>", line 10, in <module>
  File "/usr/lib/python2.7/site-packages/pykolab/auth/ldap/__init__.py", line 2963, in _regular_search
    (_result_type, _result) = self.ldap.result(_search, False, 0)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 458, in result
    resp_type, resp_data, resp_msgid = self.result2(msgid,all,timeout)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 462, in result2
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all,timeout)
  File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 469, in result3
    resp_ctrl_classes=resp_ctrl_classes
  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)
SERVER_DOWN: {'desc': "Can't contact LDAP server"}

Although there is still a progress, because looks like the invitation is parsed, just these tracebacks are thrown later.

adomaitis mentioned this in T2163: wallace fails to connect to ldap then running in debug 9 mode.Jan 5 2017, 4:30 PM
adomaitis mentioned this in T2169: wallace module_resource heartbeat fails with trace back.
adomaitis added a comment.Jan 5 2017, 5:01 PM

Moved with investigation even further, leaving /usr/lib/python2.7/site-packages/cyruslib.py modified, I also modified:

  • wallace/modules.py commenting lines 135-136, to make sure smtp.set_debuglevel(True) is not set. in debug level 9
  • pykolab/auth/ldap/__init__.py commenting lines 427-428, to make sure trace_level = 1 is not set in debug level 9
  • pykolab/imap/cyrus.py commenting lines 90-92, to make sure self.VERBOSE = True and self.m.debug = 5 is not set in debug level 9

Now I can get wallace working correctly even in debug level 9.

pasik subscribed.Nov 25 2017, 2:33 PM
vanmeeuwen lowered the priority of this task from 60 to Normal.Mar 28 2019, 8:12 AM