Log details about user login and logout.

To satisfy security requirements, we need to explicitly track:

- when a user attempts to log in, successful or not
- when a user logs out
- whether or not the user associated with a request is logged in

The first two are satisfied by extra log statements and the last is a
new boolean field on the JSON logs.

atst/domain/auth.py

@@ -1,4 +1,4 @@
-from flask import g, redirect, url_for, session, request
+from flask import g, redirect, url_for, session, request, current_app as app
 
 from atst.domain.users import Users
 
@@ -59,8 +59,10 @@ def get_last_login():
 
 def logout():
     if session.get("user_id"):  # pragma: no branch
+        dod_id = g.current_user.dod_id
         del session["user_id"]
         del session["last_login"]
+        app.logger.info(f"user with EDIPI {dod_id} has logged out")
 
 
 def _unprotected_route(request):

atst/routes/__init__.py

@@ -19,6 +19,7 @@ from werkzeug.exceptions import NotFound
 from atst.domain.users import Users
 from atst.domain.authnid import AuthenticationContext
 from atst.domain.auth import logout as _logout
+from atst.domain.exceptions import UnauthenticatedError
 from atst.utils.flash import formatted_flash as flash
 
 
@@ -64,11 +65,15 @@ def catch_all(path):
         raise NotFound()
 
 
+def _client_s_dn():
+    return request.environ.get("HTTP_X_SSL_CLIENT_S_DN")
+
+
 def _make_authentication_context():
     return AuthenticationContext(
         crl_cache=app.crl_cache,
         auth_status=request.environ.get("HTTP_X_SSL_CLIENT_VERIFY"),
-        sdn=request.environ.get("HTTP_X_SSL_CLIENT_S_DN"),
+        sdn=_client_s_dn(),
         cert=request.environ.get("HTTP_X_SSL_CLIENT_CERT"),
     )
 
@@ -89,16 +94,24 @@ def current_user_setup(user):
     session["user_id"] = user.id
     session["last_login"] = user.last_login
     app.session_limiter.on_login(user)
+    app.logger.info(f"authentication succeeded for user with EDIPI {user.dod_id}")
     Users.update_last_login(user)
 
 
 @bp.route("/login-redirect")
 def login_redirect():
-    auth_context = _make_authentication_context()
-    auth_context.authenticate()
-    user = auth_context.get_user()
+    try:
+        auth_context = _make_authentication_context()
+        auth_context.authenticate()
+
+        user = auth_context.get_user()
+        current_user_setup(user)
+    except UnauthenticatedError as err:
+        app.logger.info(
+            f"authentication failed for subject distinguished name {_client_s_dn()}"
+        )
+        raise err
 
-    current_user_setup(user)
     return redirect(redirect_after_login_url())
 
 

atst/utils/logging.py

@@ -2,16 +2,22 @@ import datetime
 import json
 import logging
 
-from flask import g, request, has_request_context
+from flask import g, request, has_request_context, session
 
 
 class RequestContextFilter(logging.Filter):
     def filter(self, record):
         if has_request_context():
             if getattr(g, "current_user", None):
-                record.user_id = str(g.current_user.id)
                 record.dod_edipi = g.current_user.dod_id
 
+            user_id = session.get("user_id")
+            if user_id:
+                record.user_id = str(user_id)
+                record.logged_in = True
+            else:
+                record.logged_in = False
+
             if request.environ.get("HTTP_X_REQUEST_ID"):
                 record.request_id = request.environ.get("HTTP_X_REQUEST_ID")
 
@@ -30,6 +36,7 @@ class JsonFormatter(logging.Formatter):
         ("request_id", lambda r: r.__dict__.get("request_id")),
         ("user_id", lambda r: r.__dict__.get("user_id")),
         ("dod_edipi", lambda r: r.__dict__.get("dod_edipi")),
+        ("logged_in", lambda r: r.__dict__.get("logged_in")),
         ("severity", lambda r: r.levelname),
         ("tags", lambda r: r.__dict__.get("tags")),
         ("audit_event", lambda r: r.__dict__.get("audit_event")),
@@ -44,7 +51,7 @@ class JsonFormatter(logging.Formatter):
 
         for field, func in self._DEFAULT_RECORD_FIELDS:
             result = func(record)
-            if result:
+            if result is not None:
                 message_dict[field] = result
 
         if record.args: