Merge pull request #298 from sebulibah/micro_services.custom_logging-logger

Improve logging - satosa.micro_services.custom_logging

Author: c00kiemon5ter

src/satosa/micro_services/custom_logging.py

@@ -2,16 +2,17 @@
 SATOSA microservice that outputs log in custom format.
 """
 
-from .base import ResponseMicroService
-from satosa.logging_util import satosa_logging
-from base64 import urlsafe_b64encode, urlsafe_b64decode
-
-import json
 import copy
+import json
 import logging
 
+import satosa.logging_util as lu
+from .base import ResponseMicroService
+
+
 logger = logging.getLogger(__name__)
 
+
 class CustomLoggingService(ResponseMicroService):
     """
     Use context and data object to create custom log output
@@ -21,7 +22,7 @@ class CustomLoggingService(ResponseMicroService):
     def __init__(self, config, *args, **kwargs):
         super().__init__(*args, **kwargs)
         self.config = config
-        
+
     def process(self, context, data):
         logprefix = CustomLoggingService.logprefix
 
@@ -30,18 +31,26 @@ def process(self, context, data):
         config = self.config
         configClean = copy.deepcopy(config)
 
-        satosa_logging(logger, logging.DEBUG, "{} Using default configuration {}".format(logprefix, configClean), context.state)
+        msg = "{} Using default configuration {}".format(logprefix, configClean)
+        logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+        logger.debug(logline)
 
         # Find the entityID for the SP that initiated the flow and target IdP
         try:
             spEntityID = context.state.state_dict['SATOSA_BASE']['requester']
             idpEntityID = data.auth_info.issuer
         except KeyError as err:
-            satosa_logging(logger, logging.ERROR, "{} Unable to determine the entityID's for the IdP or SP".format(logprefix), context.state)
+            msg = "{} Unable to determine the entityID's for the IdP or SP".format(logprefix)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.error(logline)
             return super().process(context, data)
 
-        satosa_logging(logger, logging.DEBUG, "{} entityID for the SP requester is {}".format(logprefix, spEntityID), context.state)
-        satosa_logging(logger, logging.ERROR, "{} entityID for the target IdP is {}".format(logprefix, idpEntityID), context.state)
+        msg = "{} entityID for the SP requester is {}".format(logprefix, spEntityID)
+        logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+        logger.debug(logline)
+        msg = "{} entityID for the target IdP is {}".format(logprefix, idpEntityID)
+        logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+        logger.error(logline)
 
         # Obtain configuration details from the per-SP configuration or the default configuration
         try:
@@ -57,17 +66,25 @@ def process(self, context, data):
 
 
         except KeyError as err:
-            satosa_logging(logger, logging.ERROR, "{} Configuration '{}' is missing".format(logprefix, err), context.state)
+            msg = "{} Configuration '{}' is missing".format(logprefix, err)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.error(logline)
             return super().process(context, data)
 
         record = None
 
         try:
-            satosa_logging(logger, logging.DEBUG, "{} Using context {}".format(logprefix, context), context.state)
-            satosa_logging(logger, logging.DEBUG, "{} Using data {}".format(logprefix, data.to_dict()), context.state)
+            msg = "{} Using context {}".format(logprefix, context)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.debug(logline)
+            msg = "{} Using data {}".format(logprefix, data.to_dict())
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.debug(logline)
 
             # Open log_target file
-            satosa_logging(logger, logging.DEBUG, "{} Opening log_target file {}".format(logprefix, log_target), context.state)
+            msg = "{} Opening log_target file {}".format(logprefix, log_target)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.debug(logline)
             loghandle = open(log_target,"a")
 
             # This is where the logging magic happens
@@ -78,15 +95,19 @@ def process(self, context, data):
             log['idp'] = idpEntityID
             log['sp'] = spEntityID
             log['attr'] = { key: data.to_dict()['attr'].get(key) for key in attrs }
-            
+
             print(json.dumps(log), file=loghandle, end="\n")
 
         except Exception as err:
-            satosa_logging(logger, logging.ERROR, "{} Caught exception: {0}".format(logprefix, err), None)
+            msg = "{} Caught exception: {}".format(logprefix, err)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(None), message=msg)
+            logger.error(logline)
             return super().process(context, data)
 
         else:
-            satosa_logging(logger, logging.DEBUG, "{} Closing log_target file".format(logprefix), context.state)
+            msg = "{} Closing log_target file".format(logprefix)
+            logline = lu.LOG_FMT.format(id=lu.get_session_id(context.state), message=msg)
+            logger.debug(logline)
 
             # Close log_target file
             loghandle.close()