Skip to content

Commit 6eb771f

Browse files
Merge pull request #318 from IdentityPython/micro_services.ldap_attribute_store-logger
Improve logging - satosa.micro_services.ldap_attribute_store
2 parents 94f5653 + 9f85123 commit 6eb771f

File tree

1 file changed

+59
-43
lines changed

1 file changed

+59
-43
lines changed

src/satosa/micro_services/ldap_attribute_store.py

Lines changed: 59 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -14,8 +14,8 @@
1414
import ldap3
1515
from ldap3.core.exceptions import LDAPException
1616

17+
import satosa.logging_util as lu
1718
from satosa.exception import SATOSAError
18-
from satosa.logging_util import satosa_logging
1919
from satosa.micro_services.base import ResponseMicroService
2020
from satosa.response import Redirect
2121

@@ -66,15 +66,15 @@ def __init__(self, config, *args, **kwargs):
6666

6767
if "default" in config and "" in config:
6868
msg = """Use either 'default' or "" in config but not both"""
69-
satosa_logging(logger, logging.ERROR, msg, None)
69+
logger.error(msg)
7070
raise LdapAttributeStoreError(msg)
7171

7272
if "" in config:
7373
config["default"] = config.pop("")
7474

7575
if "default" not in config:
7676
msg = "No default configuration is present"
77-
satosa_logging(logger, logging.ERROR, msg, None)
77+
logger.error(msg)
7878
raise LdapAttributeStoreError(msg)
7979

8080
self.config = {}
@@ -88,7 +88,7 @@ def __init__(self, config, *args, **kwargs):
8888
for sp in sp_list:
8989
if not isinstance(config[sp], dict):
9090
msg = "Configuration value for {} must be a dictionary"
91-
satosa_logging(logger, logging.ERROR, msg, None)
91+
logger.error(msg)
9292
raise LdapAttributeStoreError(msg)
9393

9494
# Initialize configuration using module defaults then update
@@ -111,28 +111,28 @@ def __init__(self, config, *args, **kwargs):
111111
if connection_params in connections:
112112
sp_config["connection"] = connections[connection_params]
113113
msg = "Reusing LDAP connection for SP {}".format(sp)
114-
satosa_logging(logger, logging.DEBUG, msg, None)
114+
logger.debug(msg)
115115
else:
116116
try:
117117
connection = self._ldap_connection_factory(sp_config)
118118
connections[connection_params] = connection
119119
sp_config["connection"] = connection
120120
msg = "Created new LDAP connection for SP {}".format(sp)
121-
satosa_logging(logger, logging.DEBUG, msg, None)
121+
logger.debug(msg)
122122
except LdapAttributeStoreError:
123123
# It is acceptable to not have a default LDAP connection
124124
# but all SP overrides must have a connection, either
125125
# inherited from the default or directly configured.
126126
if sp != "default":
127127
msg = "No LDAP connection can be initialized for SP {}"
128128
msg = msg.format(sp)
129-
satosa_logging(logger, logging.ERROR, msg, None)
129+
logger.error(msg)
130130
raise LdapAttributeStoreError(msg)
131131

132132
self.config[sp] = sp_config
133133

134134
msg = "LDAP Attribute Store microservice initialized"
135-
satosa_logging(logger, logging.INFO, msg, None)
135+
logger.info(msg)
136136

137137
def _construct_filter_value(
138138
self, candidate, name_id_value, name_id_format, issuer, attributes
@@ -176,7 +176,7 @@ def _construct_filter_value(
176176
for attr_value in [attributes.get(identifier_name)]
177177
]
178178
msg = "Found candidate values {}".format(values)
179-
satosa_logging(logger, logging.DEBUG, msg, None)
179+
logger.debug(msg)
180180

181181
# If one of the configured identifier names is name_id then if there is
182182
# also a configured name_id_format add the value for the NameID of that
@@ -190,7 +190,7 @@ def _construct_filter_value(
190190
and candidate_name_id_format == name_id_format
191191
):
192192
msg = "IdP asserted NameID {}".format(name_id_value)
193-
satosa_logging(logger, logging.DEBUG, msg, None)
193+
logger.debug(msg)
194194
candidate_nameid_value = name_id_value
195195

196196
# Only add the NameID value asserted by the IdP if it is not
@@ -201,18 +201,18 @@ def _construct_filter_value(
201201
if candidate_nameid_value not in values:
202202
msg = "Added NameID {} to candidate values"
203203
msg = msg.format(candidate_nameid_value)
204-
satosa_logging(logger, logging.DEBUG, msg, None)
204+
logger.debug(msg)
205205
values.append(candidate_nameid_value)
206206
else:
207207
msg = "NameID {} value also asserted as attribute value"
208208
msg = msg.format(candidate_nameid_value)
209-
satosa_logging(logger, logging.WARN, msg, None)
209+
logger.warning(msg)
210210

211211
# If no value was asserted by the IdP for one of the configured list of
212212
# identifier names for this candidate then go onto the next candidate.
213213
if None in values:
214214
msg = "Candidate is missing value so skipping"
215-
satosa_logging(logger, logging.DEBUG, msg, None)
215+
logger.debug(msg)
216216
return None
217217

218218
# All values for the configured list of attribute names are present
@@ -225,14 +225,14 @@ def _construct_filter_value(
225225
else candidate["add_scope"]
226226
)
227227
msg = "Added scope {} to values".format(scope)
228-
satosa_logging(logger, logging.DEBUG, msg, None)
228+
logger.debug(msg)
229229
values.append(scope)
230230

231231
# Concatenate all values to create the filter value.
232232
value = "".join(values)
233233

234234
msg = "Constructed filter value {}".format(value)
235-
satosa_logging(logger, logging.DEBUG, msg, None)
235+
logger.debug(msg)
236236

237237
return value
238238

@@ -283,13 +283,13 @@ def _ldap_connection_factory(self, config):
283283
server = ldap3.Server(**args)
284284

285285
msg = "Creating a new LDAP connection"
286-
satosa_logging(logger, logging.DEBUG, msg, None)
286+
logger.debug(msg)
287287

288288
msg = "Using LDAP URL {}".format(ldap_url)
289-
satosa_logging(logger, logging.DEBUG, msg, None)
289+
logger.debug(msg)
290290

291291
msg = "Using bind DN {}".format(bind_dn)
292-
satosa_logging(logger, logging.DEBUG, msg, None)
292+
logger.debug(msg)
293293

294294
auto_bind_string = config["auto_bind"]
295295
auto_bind_map = {
@@ -309,9 +309,9 @@ def _ldap_connection_factory(self, config):
309309

310310
if client_strategy == ldap3.REUSABLE:
311311
msg = "Using pool size {}".format(pool_size)
312-
satosa_logging(logger, logging.DEBUG, msg, None)
312+
logger.debug(msg)
313313
msg = "Using pool keep alive {}".format(pool_keepalive)
314-
satosa_logging(logger, logging.DEBUG, msg, None)
314+
logger.debug(msg)
315315

316316
try:
317317
connection = ldap3.Connection(
@@ -327,16 +327,16 @@ def _ldap_connection_factory(self, config):
327327
pool_keepalive=pool_keepalive,
328328
)
329329
msg = "Successfully connected to LDAP server"
330-
satosa_logging(logger, logging.DEBUG, msg, None)
330+
logger.debug(msg)
331331

332332
except LDAPException as e:
333333
msg = "Caught exception when connecting to LDAP server: {}"
334334
msg = msg.format(e)
335-
satosa_logging(logger, logging.ERROR, msg, None)
335+
logger.error(msg)
336336
raise LdapAttributeStoreError(msg)
337337

338338
msg = "Successfully connected to LDAP server"
339-
satosa_logging(logger, logging.DEBUG, msg, None)
339+
logger.debug(msg)
340340

341341
return connection
342342

@@ -348,7 +348,7 @@ def _populate_attributes(self, config, record):
348348
ldap_attributes = record.get("attributes", None)
349349
if not ldap_attributes:
350350
msg = "No attributes returned with LDAP record"
351-
satosa_logging(logger, logging.DEBUG, msg, None)
351+
logger.debug(msg)
352352
return
353353

354354
ldap_to_internal_map = (
@@ -373,8 +373,8 @@ def _populate_attributes(self, config, record):
373373
else [values]
374374
)
375375
msg = "Recording internal attribute {} with values {}"
376-
msg = msg.format(internal_attr, attributes[internal_attr])
377-
satosa_logging(logger, logging.DEBUG, msg, None)
376+
logline = msg.format(internal_attr, attributes[internal_attr])
377+
logger.debug(logline)
378378

379379
return attributes
380380

@@ -408,12 +408,14 @@ def process(self, context, data):
408408
"issuer": issuer,
409409
"config": self._filter_config(config),
410410
}
411-
satosa_logging(logger, logging.DEBUG, msg, context.state)
411+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
412+
logger.debug(logline)
412413

413414
# Ignore this SP entirely if so configured.
414415
if config["ignore"]:
415416
msg = "Ignoring SP {}".format(requester)
416-
satosa_logging(logger, logging.INFO, msg, context.state)
417+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
418+
logger.info(logline)
417419
return super().process(context, data)
418420

419421
# The list of values for the LDAP search filters that will be tried in
@@ -437,7 +439,8 @@ def process(self, context, data):
437439
if filter_value
438440
]
439441
msg = {"message": "Search filters", "filter_values": filter_values}
440-
satosa_logging(logger, logging.DEBUG, msg, context.state)
442+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
443+
logger.debug(logline)
441444

442445
# Initialize an empty LDAP record. The first LDAP record found using
443446
# the ordered # list of search filter values will be the record used.
@@ -450,7 +453,8 @@ def process(self, context, data):
450453
"message": "LDAP server host",
451454
"server host": connection.server.host,
452455
}
453-
satosa_logging(logger, logging.DEBUG, msg, context.state)
456+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
457+
logger.debug(logline)
454458

455459
for filter_val in filter_values:
456460
ldap_ident_attr = config["ldap_identifier_attribute"]
@@ -459,7 +463,8 @@ def process(self, context, data):
459463
"message": "LDAP query with constructed search filter",
460464
"search filter": search_filter,
461465
}
462-
satosa_logging(logger, logging.DEBUG, msg, context.state)
466+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
467+
logger.debug(logline)
463468

464469
attributes = (
465470
config["query_return_attributes"]
@@ -480,13 +485,15 @@ def process(self, context, data):
480485
exp_msg = "Caught unhandled exception: {}".format(err)
481486

482487
if exp_msg:
483-
satosa_logging(logger, logging.ERROR, exp_msg, context.state)
488+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=exp_msg)
489+
logger.error(logline)
484490
return super().process(context, data)
485491

486492
if not results:
487493
msg = "Querying LDAP server: No results for {}."
488494
msg = msg.format(filter_val)
489-
satosa_logging(logger, logging.DEBUG, msg, context.state)
495+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
496+
logger.debug(logline)
490497
continue
491498

492499
if isinstance(results, bool):
@@ -495,17 +502,20 @@ def process(self, context, data):
495502
responses = connection.get_response(results)[0]
496503

497504
msg = "Done querying LDAP server"
498-
satosa_logging(logger, logging.DEBUG, msg, context.state)
505+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
506+
logger.debug(logline)
499507
msg = "LDAP server returned {} records".format(len(responses))
500-
satosa_logging(logger, logging.INFO, msg, context.state)
508+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
509+
logger.info(logline)
501510

502511
# For now consider only the first record found (if any).
503512
if len(responses) > 0:
504513
if len(responses) > 1:
505514
msg = "LDAP server returned {} records using search filter"
506515
msg = msg + " value {}"
507516
msg = msg.format(len(responses), filter_val)
508-
satosa_logging(logger, logging.WARN, msg, context.state)
517+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
518+
logger.warning(logline)
509519
record = responses[0]
510520
break
511521

@@ -514,7 +524,8 @@ def process(self, context, data):
514524
if config["clear_input_attributes"]:
515525
msg = "Clearing values for these input attributes: {}"
516526
msg = msg.format(data.attributes)
517-
satosa_logging(logger, logging.DEBUG, msg, context.state)
527+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
528+
logger.debug(logline)
518529
data.attributes = {}
519530

520531
# This adapts records with different search and connection strategy
@@ -538,7 +549,8 @@ def process(self, context, data):
538549
"DN": record["dn"],
539550
"attributes": record["attributes"],
540551
}
541-
satosa_logging(logger, logging.DEBUG, msg, context.state)
552+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
553+
logger.debug(logline)
542554

543555
# Populate attributes as configured.
544556
new_attrs = self._populate_attributes(config, record)
@@ -555,16 +567,18 @@ def process(self, context, data):
555567
if user_ids:
556568
data.subject_id = "".join(user_ids)
557569
msg = "NameID value is {}".format(data.subject_id)
558-
satosa_logging(logger, logging.DEBUG, msg, None)
570+
logger.debug(msg)
559571

560572
# Add the record to the context so that later microservices
561573
# may use it if required.
562574
context.decorate(KEY_FOUND_LDAP_RECORD, record)
563575
msg = "Added record {} to context".format(record)
564-
satosa_logging(logger, logging.DEBUG, msg, context.state)
576+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
577+
logger.debug(logline)
565578
else:
566579
msg = "No record found in LDAP so no attributes will be added"
567-
satosa_logging(logger, logging.WARN, msg, context.state)
580+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
581+
logger.warning(logline)
568582
on_ldap_search_result_empty = config["on_ldap_search_result_empty"]
569583
if on_ldap_search_result_empty:
570584
# Redirect to the configured URL with
@@ -578,9 +592,11 @@ def process(self, context, data):
578592
encoded_idp_entity_id,
579593
)
580594
msg = "Redirecting to {}".format(url)
581-
satosa_logging(logger, logging.INFO, msg, context.state)
595+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
596+
logger.info(logline)
582597
return Redirect(url)
583598

584599
msg = "Returning data.attributes {}".format(data.attributes)
585-
satosa_logging(logger, logging.DEBUG, msg, context.state)
600+
logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
601+
logger.debug(logline)
586602
return super().process(context, data)

0 commit comments

Comments
 (0)