Merge pull request #1304 from dod-ccpo/170609987-session-logging

Log details about user login and logout.

alembic/versions/5d7198d34b91_remove_users_provisional.py

@@ -0,0 +1,28 @@
+"""remove users.provisional
+
+Revision ID: 5d7198d34b91
+Revises: 02ac8bdcf16f
+Create Date: 2020-01-09 08:42:34.512191
+
+"""
+from alembic import op
+import sqlalchemy as sa
+
+
+# revision identifiers, used by Alembic.
+revision = '5d7198d34b91' # pragma: allowlist secret
+down_revision = '02ac8bdcf16f' # pragma: allowlist secret
+branch_labels = None
+depends_on = None
+
+
+def upgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.drop_column('users', 'provisional')
+    # ### end Alembic commands ###
+
+
+def downgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.add_column('users', sa.Column('provisional', sa.BOOLEAN(), autoincrement=False, nullable=True))
+    # ### end Alembic commands ###

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/domain/users.py

@@ -117,12 +117,3 @@ class Users(object):
         user.last_session_id = session_id
         db.session.add(user)
         db.session.commit()
-
-    @classmethod
-    def finalize(cls, user):
-        user.provisional = False
-
-        db.session.add(user)
-        db.session.commit()
-
-        return user

atst/models/user.py

@@ -1,4 +1,4 @@
-from sqlalchemy import String, ForeignKey, Column, Date, Boolean, Table, TIMESTAMP
+from sqlalchemy import String, ForeignKey, Column, Date, Table, TIMESTAMP
 from sqlalchemy.orm import relationship
 from sqlalchemy.dialects.postgresql import UUID
 from sqlalchemy.event import listen
@@ -67,8 +67,6 @@ class User(
     last_login = Column(TIMESTAMP(timezone=True), nullable=True)
     last_session_id = Column(UUID(as_uuid=True), nullable=True)
 
-    provisional = Column(Boolean)
-
     cloud_id = Column(String)
 
     REQUIRED_FIELDS = [

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,19 +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()
+    try:
-    auth_context.authenticate()
+        auth_context = _make_authentication_context()
-    user = auth_context.get_user()
+        auth_context.authenticate()
 
-    if user.provisional:
+        user = auth_context.get_user()
-        Users.finalize(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:

tests/test_auth.py

@@ -15,7 +15,7 @@ from atst.domain.authnid.crl import CRLCache
 
 from .factories import UserFactory
 from .mocks import DOD_SDN_INFO, DOD_SDN, FIXTURE_EMAIL_ADDRESS
-from .utils import make_crl_list
+from .utils import make_crl_list, FakeLogger
 
 
 MOCK_USER = {"id": "438567dd-25fa-4d83-a8cc-8aa8366cb24a"}
@@ -36,7 +36,7 @@ def _login(client, verify="SUCCESS", sdn=DOD_SDN, cert="", **url_query_args):
     )
 
 
-def test_successful_login_redirect_non_ccpo(client, monkeypatch):
+def test_successful_login_redirect(client, monkeypatch, mock_logger):
     monkeypatch.setattr(
         "atst.domain.authnid.AuthenticationContext.authenticate", lambda *args: True
     )
@@ -51,30 +51,19 @@ def test_successful_login_redirect_non_ccpo(client, monkeypatch):
     assert "home" in resp.headers["Location"]
     assert session["user_id"]
 
-
+    login_msg = mock_logger.messages[-1]
-def test_successful_login_redirect_ccpo(client, monkeypatch):
+    assert "succeeded" in login_msg
-    monkeypatch.setattr(
-        "atst.domain.authnid.AuthenticationContext.authenticate", lambda *args: True
-    )
-    role = PermissionSets.get(PermissionSets.VIEW_AUDIT_LOG)
-    monkeypatch.setattr(
-        "atst.domain.authnid.AuthenticationContext.get_user",
-        lambda *args: UserFactory.create(),
-    )
-
-    resp = _login(client)
-
-    assert resp.status_code == 302
-    assert "home" in resp.headers["Location"]
-    assert session["user_id"]
 
 
-def test_unsuccessful_login_redirect(client, monkeypatch):
+def test_unsuccessful_login_redirect(client, monkeypatch, mock_logger):
     resp = client.get(url_for("atst.login_redirect"))
 
     assert resp.status_code == 401
     assert "user_id" not in session
 
+    login_msg = mock_logger.messages[0]
+    assert "failed" in login_msg
+
 
 # checks that all of the routes in the app are protected by auth
 def is_unprotected(rule):
@@ -221,13 +210,13 @@ def test_creates_new_user_without_email_on_login(
     assert user.email == None
 
 
-def test_logout(app, client, monkeypatch):
+def test_logout(app, client, monkeypatch, mock_logger):
+    user = UserFactory.create()
     monkeypatch.setattr(
         "atst.domain.authnid.AuthenticationContext.authenticate", lambda s: True
     )
     monkeypatch.setattr(
-        "atst.domain.authnid.AuthenticationContext.get_user",
+        "atst.domain.authnid.AuthenticationContext.get_user", lambda s: user,
-        lambda s: UserFactory.create(),
     )
     # create a real session
     resp = _login(client)
@@ -240,6 +229,10 @@ def test_logout(app, client, monkeypatch):
     assert resp_failure.status_code == 302
     destination = urlparse(resp_failure.headers["Location"]).path
     assert destination == url_for("atst.root")
+    # verify that logout is noted in the logs
+    logout_msg = mock_logger.messages[-1]
+    assert user.dod_id in logout_msg
+    assert "logged out" in logout_msg
 
 
 def test_logging_out_creates_a_flash_message(app, client, monkeypatch):

tests/utils/test_logging.py

@@ -72,9 +72,11 @@ def test_request_context_filter(logger, log_stream_content, request_ctx, monkeyp
     user.dod_id = "5678901234"
 
     monkeypatch.setattr("atst.utils.logging.g", Mock(current_user=user))
+    monkeypatch.setattr("atst.utils.logging.session", {"user_id": user_uuid})
     request_ctx.request.environ["HTTP_X_REQUEST_ID"] = request_uuid
     logger.info("this user is doing something")
     log = json.loads(log_stream_content())
     assert log["user_id"] == str(user_uuid)
     assert log["dod_edipi"] == str(user.dod_id)
     assert log["request_id"] == request_uuid
+    assert log["logged_in"] == True