Improve logging and exception handling

.gitignore

@@ -1,3 +1,4 @@
+**/.DS_Store
 _build
 .idea
 *.pyc

src/satosa/attribute_mapping.py

@@ -88,15 +88,20 @@ def to_internal(self, attribute_profile, external_dict):
 
         for internal_attribute_name, mapping in self.from_internal_attributes.items():
             if attribute_profile not in mapping:
-                logger.debug("no attribute mapping found for the attribute profile '%s'", attribute_profile)
+                logger.debug("no attribute mapping found for internal attribute '%s' the attribute profile '%s'" % (
+                    internal_attribute_name, attribute_profile))
                 # skip this internal attribute if we have no mapping in the specified profile
                 continue
 
             external_attribute_name = mapping[attribute_profile]
             attribute_values = self._collate_attribute_values_by_priority_order(external_attribute_name,
                                                                                 external_dict)
             if attribute_values:  # Only insert key if it has some values
+                logger.debug("backend attribute '%s' mapped to %s" % (external_attribute_name,
+                                                            internal_attribute_name))
                 internal_dict[internal_attribute_name] = attribute_values
+            else:
+                logger.debug("skipped backend attribute '%s': no value found", external_attribute_name)
 
         internal_dict = self._handle_template_attributes(attribute_profile, internal_dict)
         return internal_dict
@@ -181,12 +186,16 @@ def from_internal(self, attribute_profile, internal_dict):
 
             if attribute_profile not in attribute_mapping:
                 # skip this internal attribute if we have no mapping in the specified profile
-                logger.debug("no attribute mapping found for the attribute profile '%s'", attribute_profile)
+                logger.debug("no mapping found for '%s' in attribute profile '%s'" %
+                             (internal_attribute_name,
+                             attribute_profile))
                 continue
 
             external_attribute_names = self.from_internal_attributes[internal_attribute_name][attribute_profile]
             # select the first attribute name
             external_attribute_name = external_attribute_names[0]
+            logger.debug("frontend attribute %s mapped from %s" % (external_attribute_name,
+                                                                   internal_attribute_name))
 
             if self.separator in external_attribute_name:
                 nested_attribute_names = external_attribute_name.split(self.separator)

src/satosa/backends/saml2.py

@@ -273,7 +273,7 @@ def _translate_response(self, response, state):
         except AttributeError:
             pass
 
-        satosa_logging(logger, logging.DEBUG, "received attributes:\n%s" % json.dumps(response.ava, indent=4), state)
+        satosa_logging(logger, logging.DEBUG, "backend received attributes:\n%s" % json.dumps(response.ava, indent=4), state)
         return internal_resp
 
     def _metadata_endpoint(self, context):

src/satosa/base.py

@@ -17,6 +17,7 @@
 from .plugin_loader import load_request_microservices, load_response_microservices
 from .routing import ModuleRouter, SATOSANoBoundEndpointError
 from .state import cookie_to_state, SATOSAStateError, State, state_to_cookie
+from saml2.s_utils import UnknownSystemEntity
 
 
 logger = logging.getLogger(__name__)
@@ -131,7 +132,7 @@ def _auth_resp_finish(self, context, internal_response):
         if user_id_to_attr:
             internal_response.attributes[user_id_to_attr] = [internal_response.user_id]
 
-        # Hash all attributes specified in INTERNAL_ATTRIBUTES["hash]
+        # Hash all attributes specified in INTERNAL_ATTRIBUTES["hash"]
         hash_attributes = self.config["INTERNAL_ATTRIBUTES"].get("hash", [])
         internal_attributes = internal_response.attributes
         for attribute in hash_attributes:
@@ -259,9 +260,14 @@ def run(self, context):
         except SATOSANoBoundEndpointError:
             raise
         except SATOSAError:
-            satosa_logging(logger, logging.ERROR, "Uncaught SATOSA error", context.state,
+            satosa_logging(logger, logging.ERROR, "Uncaught SATOSA error ", context.state,
                            exc_info=True)
             raise
+        except UnknownSystemEntity as err:
+            satosa_logging(logger, logging.ERROR,
+                           "configuration error: unknown system entity " + str(err),
+                           context.state, exc_info=False)
+            raise
         except Exception as err:
             satosa_logging(logger, logging.ERROR, "Uncaught exception", context.state,
                            exc_info=True)

src/satosa/proxy_server.py

@@ -11,6 +11,7 @@
 from .context import Context
 from .response import ServiceError, NotFound
 from .routing import SATOSANoBoundEndpointError
+from saml2.s_utils import UnknownSystemEntity
 
 logger = logging.getLogger(__name__)
 
@@ -117,7 +118,8 @@ def __call__(self, environ, start_response, debug=False):
             resp = NotFound("Couldn't find the page you asked for!")
             return resp(environ, start_response)
         except Exception as err:
-            logger.exception("%s" % err)
+            if type(err) != UnknownSystemEntity:
+                logger.exception("%s" % err)
             if debug:
                 raise
 
@@ -137,7 +139,12 @@ def make_app(satosa_config):
             root_logger.addHandler(stderr_handler)
             root_logger.setLevel(logging.DEBUG)
 
-        logger.info("Running SATOSA version %s", pkg_resources.get_distribution("SATOSA").version)
+        try:
+            pkg = pkg_resources.get_distribution(module.__name__)
+            logger.info("Running SATOSA version %s",
+                        pkg_resources.get_distribution("SATOSA").version)
+        except (NameError, pkg_resources.DistributionNotFound):
+            pass
         return ToBytesMiddleware(WsgiApplication(satosa_config))
     except Exception:
         logger.exception("Failed to create WSGI app.")