More compact INFO-level logging of SEARCH operations

ldapserver/ldap.py

@@ -42,7 +42,7 @@ class Filter(asn1.Choice, ABC):
 	'''Base class for filters in SEARCH operations'''
 
 	@abstractmethod
-	def get_filter_string(self):
+	def __str__(self):
 		raise NotImplementedError()
 
 class FilterAnd(asn1.Wrapper, Filter):
@@ -64,8 +64,8 @@ class FilterAnd(asn1.Wrapper, Filter):
 	def __init__(self, filters=None):
 		super().__init__(filters=filters)
 
-	def get_filter_string(self):
-		return '(&%s)'%(''.join([subfilter.get_filter_string() for subfilter in self.filters]))
+	def __str__(self):
+		return '(&%s)'%(''.join([str(subfilter) for subfilter in self.filters]))
 
 class FilterOr(asn1.Wrapper, Filter):
 	'''OR conjunction of multiple filters ``(|filters...)``
@@ -86,8 +86,8 @@ class FilterOr(asn1.Wrapper, Filter):
 	def __init__(self, filters=None):
 		super().__init__(filters=filters)
 
-	def get_filter_string(self):
-		return '(|%s)'%(''.join([subfilter.get_filter_string() for subfilter in self.filters]))
+	def __str__(self):
+		return '(|%s)'%(''.join([str(subfilter) for subfilter in self.filters]))
 
 class FilterNot(asn1.Sequence, Filter):
 	'''Negation of a filter ``(!filter)``
@@ -107,8 +107,8 @@ class FilterNot(asn1.Sequence, Filter):
 	def __init__(self, filter=None):
 		super().__init__(filter=filter)
 
-	def get_filter_string(self):
-		return '(!%s)'%self.filter.get_filter_string()
+	def __str__(self):
+		return '(!%s)'%str(self.filter)
 
 class FilterEqual(asn1.Sequence, Filter):
 	'''Attribute equal filter ``(attribute=value)``
@@ -130,7 +130,7 @@ class FilterEqual(asn1.Sequence, Filter):
 	def __init__(self, attribute=None, value=None):
 		super().__init__(attribute=attribute, value=value)
 
-	def get_filter_string(self):
+	def __str__(self):
 		return '(%s=%s)'%(self.attribute, escape_filter_assertionvalue(self.value))
 
 class Substring(asn1.Choice, ABC):
@@ -200,7 +200,7 @@ class FilterSubstrings(asn1.Sequence, Filter):
 			return None
 		return results[0]
 
-	def get_filter_string(self):
+	def __str__(self):
 		substrings = [self.initial_substring or b''] + self.any_substrings + [self.final_substring or b'']
 		value = '*'.join(map(escape_filter_assertionvalue, substrings))
 		return f'({self.attribute}={value})'
@@ -218,7 +218,7 @@ class FilterGreaterOrEqual(asn1.Sequence, Filter):
 	def __init__(self, attribute=None, value=None):
 		super().__init__(attribute=attribute, value=value)
 
-	def get_filter_string(self):
+	def __str__(self):
 		return '(%s>=%s)'%(self.attribute, escape_filter_assertionvalue(self.value))
 
 class FilterLessOrEqual(asn1.Sequence, Filter):
@@ -234,7 +234,7 @@ class FilterLessOrEqual(asn1.Sequence, Filter):
 	def __init__(self, attribute=None, value=None):
 		super().__init__(attribute=attribute, value=value)
 
-	def get_filter_string(self):
+	def __str__(self):
 		return '(%s<=%s)'%(self.attribute, escape_filter_assertionvalue(self.value))
 
 class FilterPresent(asn1.Wrapper, Filter):
@@ -253,7 +253,7 @@ class FilterPresent(asn1.Wrapper, Filter):
 	def __init__(self, attribute=None):
 		super().__init__(attribute=attribute)
 
-	def get_filter_string(self):
+	def __str__(self):
 		return '(%s=*)'%(self.attribute)
 
 class FilterApproxMatch(asn1.Sequence, Filter):
@@ -269,7 +269,7 @@ class FilterApproxMatch(asn1.Sequence, Filter):
 	def __init__(self, attribute=None, value=None):
 		super().__init__(attribute=attribute, value=value)
 
-	def get_filter_string(self):
+	def __str__(self):
 		return '(%s~=%s)'%(self.attribute, escape_filter_assertionvalue(self.value))
 
 class FilterExtensibleMatch(asn1.Sequence, Filter):
@@ -286,8 +286,15 @@ class FilterExtensibleMatch(asn1.Sequence, Filter):
 	matchValue: bytes
 	dnAttributes: bool
 
-	def get_filter_string(self):
-		return '(%s:%s:=%s)'%(self.matchingRule, self.type, escape_filter_assertionvalue(self.matchValue))
+	def __str__(self):
+		parts = []
+		if self.type is not None:
+			parts.append(self.type)
+		if self.dnAttributes:
+			parts.append('dn')
+		if self.matchingRule is not None:
+			parts.append(self.matchingRule)
+		return '(%s:=%s)'%(':'.join(parts), escape_filter_assertionvalue(self.matchValue))
 
 class SearchScope(enum.Enum):
 	''':any:`enum.Enum` of `scope` values in SEARCH operations'''

ldapserver/server.py

@@ -459,12 +459,12 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
 			self.__paged_searches[cookie] = iterator, op
 		yield ldap.SearchResultDone(ldap.LDAPResultCode.success), [build_control(cookie=cookie)]
 		time_end = time.perf_counter()
-		self.logger.info('SEARCH done page cookie=%r entries=%d duration_seconds=%.3f', cookie, entries, time_end - time_start)
+		self.logger.info('SEARCH dn=%r dn_scope=%s filter=%s attributes=%r page_cookie=%r entries=%d duration_seconds=%.3f',
+		                 op.baseObject, op.scope.name, op.filter, ' '.join(op.attributes), cookie, entries, time_end - time_start)
 
 	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))
+		self.logger.debug('SEARCH request dn=%r dn_scope=%s filter=%r attributes=%r',
+		                  op.baseObject, op.scope.name, str(op.filter), ' '.join(op.attributes))
 		paged_control = None
 		if self.supports_paged_results:
 			paged_control, controls = pop_control(controls, ldap.PAGED_RESULTS_OID)
@@ -482,7 +482,8 @@ class LDAPRequestHandler(BaseLDAPRequestHandler):
 				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)
+		self.logger.info('SEARCH dn=%r dn_scope=%s filter=\'%s\' attributes=%r entries=%d duration_seconds=%.3f',
+		                 op.baseObject, op.scope.name, op.filter, ' '.join(op.attributes), entries, time_end - time_start)
 
 	def do_search(self, baseobj, scope, filterobj):
 		'''Do LDAP SEARCH operation