Skip to content
Snippets Groups Projects
Commit 5ad9b40d authored by Julian Rother's avatar Julian Rother
Browse files

Added rudimentary logging to request handler class

parent bb029c06
No related branches found
No related tags found
No related merge requests found
Pipeline #8046 passed
Stage: test
Stage: deploy
Show whitespace changes
Inline Side-by-side
Showing
with 51 additions and 9 deletions
ldapserver/server.py
+ 51
− 9
View file @ 5ad9b40d
......@@ -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
......
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment

Impressum - Datenschutzerklärung