added logging to connection

ldap3/core/connection.py

@@ -172,6 +172,8 @@ def __init__(self,
                 self.authentication = authentication
             else:
                 self.last_error = 'unknown authentication method'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPUnknownAuthenticationMethodError(self.last_error)
             self.version = version
             self.auto_referrals = True if auto_referrals else False
@@ -241,6 +243,8 @@ def __init__(self,
                 self.strategy = MockAsyncStrategy(self)
             else:
                 self.last_error = 'unknown strategy'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPUnknownStrategyError(self.last_error)
 
             # map strategy functions to connection functions
@@ -265,6 +269,8 @@ def __init__(self,
                         self.start_tls(read_server_info=True)
                     if not self.bound:
                         self.last_error = 'automatic bind not successful' + (' - ' + self.last_error if self.last_error else '')
+                        if log_enabled(VERBOSITY_SEVERE):
+                            log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                         raise LDAPBindError(self.last_error)
 
             if log_enabled(VERBOSITY_CHATTY):
@@ -360,6 +366,8 @@ def __exit__(self, exc_type, exc_val, exc_tb):
                 self.open()
 
             if exc_type is not None:
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', exc_type, self)
                 return False  # re-raise LDAPExceptionError
 
     def bind(self,
@@ -399,15 +407,21 @@ def bind(self,
                         response = self.do_sasl_bind(controls)
                     else:
                         self.last_error = 'requested SASL mechanism not supported'
+                        if log_enabled(VERBOSITY_SEVERE):
+                            log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                         raise LDAPSASLMechanismNotSupportedError(self.last_error)
                 elif self.authentication == NTLM:
                     if self.user and self.password:
                         response = self.do_ntlm_bind(controls)
                     else:  # user or password missing
                         self.last_error = 'NTLM needs domain\\username and a password'
+                        if log_enabled(VERBOSITY_SEVERE):
+                            log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                         raise LDAPUnknownAuthenticationMethodError(self.last_error)
                 else:
                     self.last_error = 'unknown authentication method'
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                     raise LDAPUnknownAuthenticationMethodError(self.last_error)
 
                 if not self.strategy.sync and self.authentication not in (SASL, NTLM):  # get response if async except for SASL and NTLM that return the bind result even for async
@@ -420,6 +434,8 @@ def bind(self,
                     result = response
                 else:
                     self.last_error = 'unknown authentication method'
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                     raise LDAPUnknownAuthenticationMethodError(self.last_error)
 
                 if result is None:
@@ -509,6 +525,8 @@ def search(self,
                 attributes += (ALL_OPERATIONAL_ATTRIBUTES, )  # concatenate tuple
 
             if isinstance(paged_size, int):
+                if log_enabled(VERBOSITY_CHATTY):
+                    log(VERBOSITY_CHATTY, 'performing paged search for %d items with cookie %s for %s', paged_size, paged_cookie, self)
                 real_search_control_value = RealSearchControlValue()
                 real_search_control_value['size'] = Size(paged_size)
                 real_search_control_value['cookie'] = Cookie(paged_cookie) if paged_cookie else Cookie('')
@@ -592,8 +610,11 @@ def add(self,
                 object_class_attr_name = 'objectClass'
 
             attributes[object_class_attr_name] = list(set([object_class for object_class in parm_object_class + attr_object_class]))  # remove duplicate ObjectClasses
+
             if not attributes[object_class_attr_name]:
                 self.last_error = 'ObjectClass attribute is mandatory'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPObjectClassError(self.last_error)
 
             request = add_operation(dn, attributes, self.server.schema if self.server else None)
@@ -623,6 +644,8 @@ def delete(self,
             self._fire_deferred()
             if self.read_only:
                 self.last_error = 'connection is read-only'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPConnectionIsReadOnlyError(self.last_error)
 
             request = delete_operation(dn)
@@ -657,22 +680,32 @@ def modify(self,
             self._fire_deferred()
             if self.read_only:
                 self.last_error = 'connection is read-only'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPConnectionIsReadOnlyError(self.last_error)
 
             if not isinstance(changes, dict):
                 self.last_error = 'changes must be a dictionary'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPChangesError(self.last_error)
 
             if not changes:
                 self.last_error = 'no changes in modify request'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPChangesError(self.last_error)
 
             for change in changes:
                 if len(changes[change]) != 2:
                     self.last_error = 'malformed change'
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                     raise LDAPChangesError(self.last_error)
                 elif changes[change][0] not in [MODIFY_ADD, MODIFY_DELETE, MODIFY_REPLACE, MODIFY_INCREMENT, 0, 1, 2, 3]:
                     self.last_error = 'unknown change type'
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                     raise LDAPChangesError(self.last_error)
 
             request = modify_operation(dn, changes, self.server.schema if self.server else None)
@@ -706,10 +739,14 @@ def modify_dn(self,
             self._fire_deferred()
             if self.read_only:
                 self.last_error = 'connection is read-only'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPConnectionIsReadOnlyError(self.last_error)
 
             if new_superior and not dn.startswith(relative_dn):  # as per RFC4511 (4.9)
-                self.last_error = 'DN cannot change while moving'
+                self.last_error = 'DN cannot change while performing moving'
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', self.last_error, self)
                 raise LDAPChangesError(self.last_error)
 
             request = modify_dn_operation(dn, relative_dn, delete_old_dn, new_superior)
@@ -791,6 +828,8 @@ def start_tls(self, read_server_info=True):  # as per RFC4511. Removal of TLS is
                 self._deferred_start_tls = True
                 self.tls_started = True
                 return_value = True
+                if log_enabled(VERBOSITY_CHATTY):
+                    log(VERBOSITY_CHATTY, 'deferring START TLS for %s', self)
             else:
                 self._deferred_start_tls = False
                 if self.server.tls.start_tls(self) and self.strategy.sync:  # for async connections _start_tls is run by the strategy
@@ -884,6 +923,8 @@ def refresh_server_info(self):
         if not self.strategy.pooled:
             with self.lock:
                 if not self.closed:
+                    if log_enabled(VERBOSITY_CHATTY):
+                        log(VERBOSITY_CHATTY, 'refreshing server info for %s', self)
                     previous_response = self.response
                     previous_result = self.result
                     previous_entries = self._entries
@@ -892,6 +933,8 @@ def refresh_server_info(self):
                     self.result = previous_result
                     self._entries = previous_entries
         else:
+            if log_enabled(VERBOSITY_CHATTY):
+                log(VERBOSITY_CHATTY, 'refreshing server info from pool for %s', self)
             self.strategy.pool.get_info_from_server()
 
     def response_to_ldif(self,
@@ -914,6 +957,8 @@ def response_to_ldif(self,
                         header = add_ldif_header(['-'])[0]
                         stream.write(prepare_for_stream(header + line_separator + line_separator))
                     stream.write(prepare_for_stream(ldif_output + line_separator + line_separator))
+                if log_enabled(VERBOSITY_CHATTY):
+                    log(VERBOSITY_CHATTY, 'building LDIF output %s for %s', ldif_output, self)
                 return ldif_output
 
             return None
@@ -947,6 +992,8 @@ def response_to_json(self,
 
                 json_output = json.dumps(json_dict, ensure_ascii=True, sort_keys=sort, indent=indent, check_circular=True, default=format_json, separators=(',', ': '))
 
+                if log_enabled(VERBOSITY_CHATTY):
+                    log(VERBOSITY_CHATTY, 'building JSON output %s for %s', json_output, self)
                 if stream:
                     stream.write(json_output)
 
@@ -962,6 +1009,9 @@ def response_to_file(self,
                 if isinstance(target, STRING_TYPES):
                     target = open(target, 'w+')
 
+                if log_enabled(VERBOSITY_CHATTY):
+                    log(VERBOSITY_CHATTY, 'writing response to file for %s', self)
+
                 target.writelines(self.response_to_json(raw=raw, indent=indent, sort=sort))
                 target.close()
 
@@ -970,6 +1020,8 @@ def _fire_deferred(self):
             if self.lazy and not self._executing_deferred:
                 self._executing_deferred = True
 
+                if log_enabled(VERBOSITY_NORMAL):
+                    log(VERBOSITY_NORMAL, 'executing deferred (open: %s, start_tls: %s, bind: %s) for %s', self._deferred_open, self._deferred_start_tls, self._deferred_bind, self)
                 try:
                     if self._deferred_open:
                         self.open(read_server_info=False)
@@ -978,7 +1030,9 @@ def _fire_deferred(self):
                     if self._deferred_bind:
                         self.bind(read_server_info=False, controls=self._bind_controls)
                     self.refresh_server_info()
-                except LDAPExceptionError:
+                except LDAPExceptionError as e:
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, '%s for %s', e, self)
                     raise  # re-raise LDAPExceptionError
                 finally:
                     self._executing_deferred = False
@@ -1034,6 +1088,8 @@ def _get_entries(self, search_response):
                             entries.append(entry)
                         break
                 else:
+                    if log_enabled(VERBOSITY_SEVERE):
+                        log(VERBOSITY_SEVERE, 'attribute set not found for %s in %s', resp_attr_set, self)
                     raise LDAPObjectError('attribute set not found for ' + str(resp_attr_set))
 
         return entries

ldap3/core/tls.py

@@ -25,11 +25,14 @@
 
 from .exceptions import LDAPSSLNotSupportedError, LDAPSSLConfigurationError, LDAPStartTLSError, LDAPCertificateError, start_tls_exception_factory
 from .. import SEQUENCE_TYPES
+from ..utils.log import log, log_enabled, VERBOSITY_SEVERE, VERBOSITY_SPARSE, VERBOSITY_NORMAL, VERBOSITY_CHATTY
 
 try:
     # noinspection PyUnresolvedReferences
     import ssl
 except ImportError:
+    if log_enabled(VERBOSITY_SEVERE):
+        log(VERBOSITY_SEVERE, 'SSL not supported in this Python interpreter')
     raise LDAPSSLNotSupportedError('SSL not supported in this Python interpreter')
 
 try:
@@ -72,33 +75,45 @@ def __init__(self,
         if validate in [ssl.CERT_NONE, ssl.CERT_OPTIONAL, ssl.CERT_REQUIRED]:
             self.validate = validate
         elif validate:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'invalid validate parameter %s', validate)
             raise LDAPSSLConfigurationError('invalid validate parameter')
         if ca_certs_file and path.exists(ca_certs_file):
             self.ca_certs_file = ca_certs_file
         elif ca_certs_file:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'invalid CA public key file %s', ca_certs_file)
             raise LDAPSSLConfigurationError('invalid CA public key file')
         else:
             self.ca_certs_file = None
 
         if ca_certs_path and use_ssl_context and path.exists(ca_certs_path):
             self.ca_certs_path = ca_certs_path
         elif ca_certs_path and not use_ssl_context:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'cannot use CA public keys path, SSLContext not available')
             raise LDAPSSLNotSupportedError('cannot use CA public keys path, SSLContext not available')
         elif ca_certs_path:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'invalid CA public keys path %s', ca_certs_path)
             raise LDAPSSLConfigurationError('invalid CA public keys path')
         else:
             self.ca_certs_path = None
 
         if ca_certs_data and use_ssl_context:
             self.ca_certs_data = ca_certs_data
         elif ca_certs_data:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'cannot use CA data, SSLContext not available')
             raise LDAPSSLNotSupportedError('cannot use CA data, SSLContext not available')
         else:
             self.ca_certs_data = None
 
         if local_private_key_password and use_ssl_context:
             self.private_key_password = local_private_key_password
         elif local_private_key_password:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'cannot use local private key password, SSLContext not available')
             raise LDAPSSLNotSupportedError('cannot use local private key password, SSLContext is not available')
         else:
             self.private_key_password = None
@@ -188,6 +203,8 @@ def start_tls(self, connection):
             if connection.result['description'] not in ['success']:
                 # startTLS failed
                 connection.last_error = 'startTLS failed - ' + str(connection.result['description'])
+                if log_enabled(VERBOSITY_SEVERE):
+                    log(VERBOSITY_SEVERE, '%s for %s', connection.last_error, connection)
                 raise LDAPStartTLSError(connection.last_error)
             return self._start_tls(connection)
 
@@ -202,6 +219,8 @@ def _start_tls(self, connection):
         connection.starting_tls = False
 
         if exc:
+            if log_enabled(VERBOSITY_SEVERE):
+                log(VERBOSITY_SEVERE, 'error %s wrapping socket for TLS in %s', connection.last_error, connection)
             raise start_tls_exception_factory(LDAPStartTLSError, exc)(connection.last_error)
 
         if connection.usage:
@@ -222,8 +241,13 @@ def check_hostname(sock, server_name, additional_names):
 
         try:
             match_hostname(server_certificate, host_name)  # raise CertificateError if certificate doesn't match server name
+            if log_enabled(VERBOSITY_CHATTY):
+                log(VERBOSITY_CHATTY, "certificate matches host name %s", host_name)
             return
         except CertificateError:
-            pass
+            if log_enabled(VERBOSITY_CHATTY):
+                log(VERBOSITY_CHATTY, "certificate doesn't match host name %s", host_name)
 
+    if log_enabled(VERBOSITY_SEVERE):
+        log(VERBOSITY_SEVERE, "host name doesn't match")
     raise LDAPCertificateError("hostname doesn't match")

ldap3/utils/ntlm.py

@@ -121,8 +121,8 @@
 AV_FLAG_TARGET_SPN_UNTRUSTED = 2
 
 AV_FLAG_TYPES = [AV_FLAG_CONSTRAINED,
-                AV_FLAG_INTEGRITY,
-                AV_FLAG_TARGET_SPN_UNTRUSTED]
+                 AV_FLAG_INTEGRITY,
+                 AV_FLAG_TARGET_SPN_UNTRUSTED]
 
 
 def pack_windows_version(debug=False):

ldap3/utils/tls_backport.py

@@ -23,6 +23,7 @@
 # along with ldap3 in the COPYING and COPYING.LESSER files.
 # If not, see <http://www.gnu.org/licenses/>.
 import re
+from ..utils.log import log, log_enabled, VERBOSITY_SEVERE, VERBOSITY_SPARSE, VERBOSITY_NORMAL, VERBOSITY_CHATTY
 
 
 class CertificateError(ValueError):  # fix for Python 2, code from Python 3.3 standard library
@@ -34,6 +35,8 @@ def _dnsname_match_backport(dn, hostname, max_wildcards=1):
 
     http://tools.ietf.org/html/rfc6125#section-6.4.3
     """
+    if log_enabled(VERBOSITY_CHATTY):
+        log(VERBOSITY_CHATTY, "matching dn %s with hostname %s", dn, hostname)
     pats = []
     if not dn:
         return False