[python-ldap] syncrepl_poll timeout causing extra IndexError exception

[Karl Kornel]

Hello!

	I would like to report a syncrepl-related issue with python-ldap 2.4.38, running in Python 2.7.13, on Mac OS X.  The OpenLDAP library is 2.4.44.  It seems like the `timeout` parameter in syncrepl_poll() is causing an unexpected exception (that is, not a timeout).

	Here is the situation:  I am doing syncrepl in “refreshAndPersist” mode.  My code is subclassing the SyncreplConsumer and SimpleLDAPObject classes.  The code is successfully able to go through the refresh phase, and syncrepl_refreshdone() is called.

	The exception occurs when I make the first call to syncrepl_poll() in the refresh phase.  Here is the exception and traceback:

Traceback (most recent call last):
  File "demo.py", line 62, in <module>
    loop_result = client.poll()
  File "/Users/akkornel/git/syncrepl/syncrepl_client/__init__.py", line 400, in poll
    all=1, timeout=3)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/syncrepl.py", line 352, in syncrepl_poll
    add_intermediates=1, add_ctrls=1, all = 0
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 523, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 115, in _ldap_call
    if not e.args[0].has_key('info') and e.args[0].has_key('errno'):
IndexError: tuple index out of range


I turned up trace_level to 9, deleted all temporary files (to ensure a full sync) and then ran again.  Here is the last portion of the output:

===== OUTPUT START =====
=> result:
(121,
 [('1.3.6.1.4.1.4203.1.9.1.4',
   '\xa16\x044rid=000,csn=20170529043510.977702Z#000000#000#000000',
   [])],
 5,
 [])
REFRESH COMPLETE!
*** <Syncrepl(Thread-1, initial)> ldap://directory-master.stanford.edu/cn%3Dpeople%2Cdc%3Dstanford%2Cdc%3Dedu??one?%28suPrivilegeGroup%3Dresearch-computing%3A%2A%29?bindname=GSSAPI - Syncrepl.result4
((5, 0, 3, 1, 1, 0), {})
  File "demo.py", line 62, in <module>
    loop_result = client.poll()
  File "/Users/akkornel/git/syncrepl/syncrepl_client/__init__.py", line 400, in poll
    all=1, timeout=3)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/syncrepl.py", line 352, in syncrepl_poll
    add_intermediates=1, add_ctrls=1, all = 0
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 523, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 104, in _ldap_call
    traceback.print_stack(limit=self._trace_stack_limit,file=self._trace_file)
Traceback (most recent call last):
  File "demo.py", line 62, in <module>
    loop_result = client.poll()
  File "/Users/akkornel/git/syncrepl/syncrepl_client/__init__.py", line 400, in poll
    all=1, timeout=3)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/syncrepl.py", line 352, in syncrepl_poll
    add_intermediates=1, add_ctrls=1, all = 0
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 523, in result4
    ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 115, in _ldap_call
    if not e.args[0].has_key('info') and e.args[0].has_key('errno'):
IndexError: tuple index out of range
*** <Syncrepl(Thread-1, initial)> ldap://directory-master.stanford.edu/cn%3Dpeople%2Cdc%3Dstanford%2Cdc%3Dedu??one?%28suPrivilegeGroup%3Dresearch-computing%3A%2A%29?bindname=GSSAPI - Syncrepl.unbind_ext
((None, None), {})
  File "/Users/akkornel/git/syncrepl/syncrepl_client/__init__.py", line 326, in __del__
    return self.unbind()
  File "/Users/akkornel/git/syncrepl/syncrepl_client/__init__.py", line 320, in unbind
    return SimpleLDAPObject.unbind(self)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 649, in unbind
    return self.unbind_ext(None,None)
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 628, in unbind_ext
    res = self._ldap_call(self._l.unbind_ext,RequestControlTuples(serverctrls),RequestControlTuples(clientctrls))
  File "/Users/akkornel/Library/Python/2.7/lib/python/site-packages/ldap/ldapobject.py", line 104, in _ldap_call
    traceback.print_stack(limit=self._trace_stack_limit,file=self._trace_file)
=> result:
None
===== OUTPUT END =====

The “REFRESH COMPLETE!” message is my code inside of syncrepl_refreshdone().

I am calling syncrepl_poll() with `all=1` and `timeout=3`.   If I remove the `timeout` parameter, the crash does not happen.  Of course, syncrepl_poll() hangs, but I expect that here.

So, next I removed the `all` parameter, and put `timeout` back in.  In other words, I am calling syncrepl_poll() with just `timeout=3`.  That gives me the same exception as before. 

Finally, I removed the `timeout` parameter again, so now I am calling syncrepl_poll() without any extra parameters (the only parameter is `msgid`).  This time, syncrepl_poll() again works, but it regularly hangs when there are no changes.

So, it seems to me that there is a problem when using timeout: The LDAP operations is allowed to time out, but the timeout is not identified as a timeout.

If you have any questions for me, please let me know!

--
A. Karl Kornel | System Administrator
Research Computing | Stanford University
+1 (650) 736-9327