Improve logging.

* Add some log statements.
* Make sure to not write any log messages to file (CherryPy access and error log).
* Update log configuration.

env/conf/logging_conf.json

@@ -3,7 +3,7 @@
     "disable_existing_loggers": false,
     "formatters": {
         "message_only": {
-            "format": "%(message)s"
+            "format": "> %(message)s"
         }
     },
     "handlers": {
@@ -17,12 +17,7 @@
     "loggers": {
         "svs": {
             "level": "DEBUG",
-            "handlers": ["console"],
-            "propagate": false
+            "handlers": ["console"]
         }
-    },
-    "root": {
-        "level": "INFO",
-        "handlers": ["console"]
     }
 }

src/svs/inacademia_server.py

@@ -17,7 +17,7 @@
 from svs.saml import InAcademiaSAMLBackend
 from svs.user_interaction import ConsentPage, EndUserErrorResponse
 from svs.i18n_tool import ugettext as _
-from svs.log_utils import log_transaction_start
+from svs.log_utils import log_transaction_start, log_internal
 from svs.utils import deconstruct_state, construct_state
 
 logger = logging.getLogger(__name__)
@@ -92,9 +92,6 @@ def main():
         "tools.I18nTool.default": "en",
         "tools.I18nTool.mo_dir": pkg_resources.resource_filename("svs", "data/i18n/locales"),
         "tools.I18nTool.domain": "messages",
-
-        "log.access_file": "svs_access.log",
-        "log.error_file": "svs_error.log",
     })
 
     cherrypy.config.update({'engine.autoreload.on': False})
@@ -142,7 +139,6 @@ def main():
             })
         }
     })
-    print("SvS core listening on {}:{}".format(args.host, args.port))
 
     cherrypy.engine.signal_handler.set_handler("SIGTERM", cherrypy.engine.signal_handler.bus.exit)
     cherrypy.engine.signal_handler.set_handler("SIGUSR1", client_db.update)
@@ -253,6 +249,8 @@ def consent_allow(self, state=None, released_claims=None):
         state = json.loads(urllib.unquote_plus(state))
         released_claims = json.loads(urllib.unquote_plus(released_claims))
         transaction_session = self._decode_state(state["state"])
+        log_internal(logger, "consented claims: {}".format(json.dumps(released_claims)),
+                     cherrypy.request, state["state"], transaction_session["client_id"])
         return self.op.id_token(released_claims, state["idp_entity_id"], state["state"],
                                 transaction_session)
 
@@ -314,6 +312,8 @@ def _acs(self, SAMLResponse, RelayState, binding):
         released_claims = self.op.get_claims_to_release(user_id, affiliation, identity, auth_time,
                                                         idp_entity_id,
                                                         self.sp.metadata, transaction_session)
+        log_internal(logger, "claims to consent: {}".format(json.dumps(released_claims)),
+                     cherrypy.request, RelayState, transaction_session["client_id"])
 
         client_name = self._get_client_name(transaction_session["client_id"])
         return ConsentPage.render(client_name, idp_entity_id, released_claims, RelayState)
@@ -344,9 +344,9 @@ def _decode_state(self, state):
         except DecryptionFailed as e:
             abort_with_enduser_error(state, "-", cherrypy.request, logger,
                                      _(
-                                         "We could not complete your validation because an error occurred while handling "
-                                         "your request. Please return to the service which initiated the validation "
-                                         "request and try again."),
+                                             "We could not complete your validation because an error occurred while handling "
+                                             "your request. Please return to the service which initiated the validation "
+                                             "request and try again."),
                                      "Transaction state missing or broken in incoming response.")
 
     def _encode_state(self, payload):

src/svs/saml.py

@@ -162,7 +162,8 @@ def disco_query(self, state):
         # append it to the disco server URL
         loc = self.sp.create_discovery_service_request(
             self.disco_srv, eid, **{"return": ret})
-
+        log_internal(logger, "Discovery service URL: {}".format(self.disco_srv), cherrypy.request,
+                     state)
         return loc
 
     def redirect_to_auth(self, metadata, entity_id, relay_state):