diff --git a/ldapserver/server.py b/ldapserver/server.py
index bbe8dbf157057618a523405d77de5813ada217c4..a629a5c5929c990397e1eb65b8d93063b34cd202 100644
--- a/ldapserver/server.py
+++ b/ldapserver/server.py
@@ -2,6 +2,10 @@ import traceback
import ssl
import socketserver
import typing
+import logging
+import time
+import random
+import string
from . import asn1, exceptions, ldap, schema, objects
from .dn import DN
@@ -11,12 +15,22 @@ def reject_critical_controls(controls=None):
if control.criticality:
raise exceptions.LDAPUnavailableCriticalExtension()
+class RequestLogAdapter(logging.LoggerAdapter):
+ def process(self, msg, kwargs):
+ return self.extra['trace_id'] + ': ' + msg, kwargs
+
class BaseLDAPRequestHandler(socketserver.BaseRequestHandler):
+ logger = logging.getLogger('ldapserver.server')
+
def setup(self):
super().setup()
+ self.trace_id = ''.join([random.choice(string.ascii_letters) for _ in range(10)])
+ self.logger = RequestLogAdapter(self.logger, {'trace_id': self.trace_id})
self.keep_running = True
def handle(self):
+ time_connect = time.perf_counter()
+ self.logger.info('Connection from %r', self.client_address)
buf = b''
while self.keep_running:
try:
@@ -31,6 +45,8 @@ class BaseLDAPRequestHandler(socketserver.BaseRequestHandler):
else:
buf += chunk
self.request.close()
+ time_disconnect = time.perf_counter()
+ self.logger.info('Disconnected duration_seconds=%.3f', time_disconnect - time_connect)
def handle_message(self, shallowmsg: ldap.ShallowLDAPMessage) -> typing.Iterable[ldap.LDAPMessage]:
'''Handle an LDAP request foobar
@@ -57,7 +73,7 @@ class BaseLDAPRequestHandler(socketserver.BaseRequestHandler):
try:
msg = shallowmsg.decode()[0]
except ValueError as e:
- self.on_recv_invalid(shallowmsg)
+ self.logger.error('Could not decode message %s, ignoring', shallowmsg)
raise exceptions.LDAPProtocolError() from e
for args in handler(msg.protocolOp, msg.controls):
response, controls = args if isinstance(args, tuple) else (args, None)
@@ -66,54 +82,62 @@ class BaseLDAPRequestHandler(socketserver.BaseRequestHandler):
if response_type is not None:
respmsg = ldap.LDAPMessage(shallowmsg.messageID, response_type(e.code, diagnosticMessage=e.message))
yield respmsg
+ self.logger.info('Operation aborted, responded with result code "%s" msg="%s"', e.code.name, e.message)
except Exception as e: # pylint: disable=broad-except
if response_type is not None:
respmsg = ldap.LDAPMessage(shallowmsg.messageID, response_type(ldap.LDAPResultCode.other))
yield respmsg
- self.on_exception(e)
-
- def on_recv_invalid(self, shallowmsg):
- pass
-
- def on_exception(self, e):
- traceback.print_exc()
+ self.logger.exception('Uncaught exception, responded with result code "other"')
+ else:
+ self.logger.exception('Uncaught exception, ignored request')
def handle_bind(self, op: ldap.BindRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('BIND %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPAuthMethodNotSupported()
def handle_unbind(self, op: ldap.UnbindRequest, controls=None) -> typing.NoReturn:
+ self.logger.info('UNBIND %s', op)
reject_critical_controls(controls)
self.keep_running = False
+ return []
def handle_search(self, op: ldap.SearchRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('SEARCH %s', op)
reject_critical_controls(controls)
yield ldap.SearchResultDone(ldap.LDAPResultCode.success)
def handle_modify(self, op: ldap.ModifyRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('MODIFY %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPInsufficientAccessRights()
def handle_add(self, op: ldap.AddRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('ADD %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPInsufficientAccessRights()
def handle_delete(self, op: ldap.DelRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('DELETE %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPInsufficientAccessRights()
def handle_modifydn(self, op: ldap.ModifyDNRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('MODIFYDN %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPInsufficientAccessRights()
def handle_compare(self, op: ldap.CompareRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('COMPRAE %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPInsufficientAccessRights()
def handle_abandon(self, op: ldap.AbandonRequest, controls=None) -> typing.NoReturn:
+ self.logger.info('ABANDON %s', op)
reject_critical_controls(controls)
def handle_extended(self, op: ldap.ExtendedRequest, controls=None) -> typing.Iterable[ldap.ProtocolOp]:
+ self.logger.info('EXTENDED %s', op)
reject_critical_controls(controls)
raise exceptions.LDAPProtocolError()
@@ -395,11 +419,21 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
raise exceptions.LDAPAuthMethodNotSupported()
def handle_search(self, op, controls=None):
+ self.logger.info('SEARCH request dn=%r dn_scope=%s filter=%r, attributes=%r',
+ op.baseObject, op.scope.name, op.filter.get_filter_string(),
+ ' '.join(op.attributes))
reject_critical_controls(controls)
+ entries = 0
+ time_start = time.perf_counter()
for obj in self.do_search(op.baseObject, op.scope, op.filter):
if obj.match_search(op.baseObject, op.scope, op.filter):
- yield obj.get_search_result_entry(op.attributes, op.typesOnly)
+ entry = obj.get_search_result_entry(op.attributes, op.typesOnly)
+ self.logger.debug('SEARCH entry %r', entry)
+ entries += 1
+ yield entry
yield ldap.SearchResultDone(ldap.LDAPResultCode.success)
+ time_end = time.perf_counter()
+ self.logger.info('SEARCH done entries=%d duration_seconds=%.3f', entries, time_end - time_start)
def do_search(self, baseobj, scope, filterobj):
'''Do LDAP SEARCH operation
@@ -423,12 +457,15 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
yield from self.static_objects
def handle_compare(self, op, controls=None):
+ self.logger.info('COMPRAE request "%s" %s=%s', op.entry, op.ava.attributeDesc, repr(op.ava.assertionValue))
obj = self.do_compare(op.entry, op.ava.attributeDesc, op.ava.assertionValue)
if obj is None:
raise exceptions.LDAPNoSuchObject()
if obj.match_compare(op.ava.attributeDesc, op.ava.assertionValue):
+ self.logger.info('COMPRAE result TRUE')
return [ldap.CompareResponse(ldap.LDAPResultCode.compareTrue)]
else:
+ self.logger.info('COMPRAE result FALSE')
return [ldap.CompareResponse(ldap.LDAPResultCode.compareFalse)]
def do_compare(self, dn, attribute, value):
@@ -455,6 +492,7 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
return None
def handle_unbind(self, op, controls=None):
+ self.logger.info('UNBIND')
reject_critical_controls(controls)
self.keep_running = False
return []
@@ -462,6 +500,7 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
def handle_extended(self, op, controls=None):
reject_critical_controls(controls)
if op.requestName == ldap.EXT_STARTTLS_OID and self.supports_starttls:
+ self.logger.info('EXTENDED STARTTLS')
# StartTLS (RFC 4511)
yield ldap.ExtendedResponse(ldap.LDAPResultCode.success, responseName=ldap.EXT_STARTTLS_OID)
try:
@@ -470,10 +509,12 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
traceback.print_exc()
self.keep_running = False
elif op.requestName == ldap.EXT_WHOAMI_OID and self.supports_whoami:
+ self.logger.info('EXTENDED WHOAMI')
# "Who am I?" Operation (RFC 4532)
identity = (self.do_whoami() or '').encode()
yield ldap.ExtendedResponse(ldap.LDAPResultCode.success, responseValue=identity)
elif op.requestName == ldap.EXT_PASSWORD_MODIFY_OID and self.supports_password_modify:
+ self.logger.info('EXTENDED PASSWORD_MODIFY')
# Password Modify Extended Operation (RFC 3062)
newpw = None
if op.requestValue is None:
@@ -488,6 +529,7 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
encoded = ldap.PasswdModifyResponseValue.to_ber(ldap.PasswdModifyResponseValue(newpw))
yield ldap.ExtendedResponse(ldap.LDAPResultCode.success, responseValue=encoded)
else:
+ self.logger.warning('Unsupported or disabled EXTENDED operation %r', op.requestName)
yield from super().handle_extended(op, controls) # pylint: disable=not-an-iterable
#: :any:`ssl.SSLContext` for StartTLS