Improve auditing of token auth failures

src/middlewared/middlewared/alert/source/auth.py

@@ -1,6 +1,6 @@
 from middlewared.alert.base import Alert, AlertCategory, AlertClass, AlertLevel, AlertSource
 from middlewared.alert.schedule import CrontabSchedule
-from middlewared.utils.audit import UNAUTHENTICATED
+from middlewared.utils.audit import TOKEN_EXPIRED
 from time import time
 
 
@@ -78,12 +78,18 @@ class APIFailedLoginAlertSource(AlertSource):
 
     async def check(self):
         now = int(time())
+
+        # NOTE about filter:
+        # we are intentionally excluding audit entries due to expired tokens
+        # because they are generally benign and we don't want users in habit
+        # of just ignoring or turning off this alert. Alert will still be
+        # raised if someone tries to use non-existent token.
         auth_failures = await self.middleware.call('audit.query', {
             'services': ['MIDDLEWARE'],
             'query-filters': [
                 ['message_timestamp', '>', now - 86400],
                 ['event', '=', 'AUTHENTICATION'],
-                ['username', '!=', UNAUTHENTICATED],
+                ['username', '!=', TOKEN_EXPIRED],
                 ['success', '=', False]
             ],
             'query-options': {

src/middlewared/middlewared/main.py

@@ -1551,7 +1551,12 @@ async def log_audit_message_for_method(self, method, methodobj, params, app, aut
                     'authorized': authorized,
                 }, success)
 
-    async def log_audit_message(self, app, event, event_data, success):
+    async def log_audit_message(self, app, event, event_data, success, user=None):
+        # NOTE: we allow overriding `user` specifically for handling case where
+        # the entry is being generated due to an expired authentication token so
+        # that we can set the value to .TOKEN_EXPIRED rather than .UNAUTHENTICATED
+        # which is more informative to end-users. Generally we should not override
+        # user without very good reason, and it should be properly documented.
         message = "@cee:" + json.dumps({
             "TNAUDIT": {
                 "aid": str(uuid.uuid4()),
@@ -1560,7 +1565,7 @@ async def log_audit_message(self, app, event, event_data, success):
                     "minor": 1
                 },
                 "addr": app.origin.repr() if isinstance(app.origin, TCPIPOrigin) else "127.0.0.1",
-                "user": audit_username_from_session(app.authenticated_credentials),
+                "user": user or audit_username_from_session(app.authenticated_credentials),
                 "sess": app.session_id,
                 "time": utc_now().strftime('%Y-%m-%d %H:%M:%S.%f'),
                 "svc": "MIDDLEWARE",
@@ -1874,15 +1879,13 @@ async def ws_handler(self, request):
                     )
                     break
 
-                datalen = len(msg.data)
-
                 try:
                     message = parse_message(connection.authenticated, msg.data)
                 except MsgSizeError as err:
                     if err.limit is not MsgSizeLimit.UNAUTHENTICATED:
                         origin = connection.origin.repr() if connection.origin else None
                         if connection.authenticated_credentials:
-                            creds =  connection.authenticated_credentials.dump()
+                            creds = connection.authenticated_credentials.dump()
                         else:
                             creds = None
 

src/middlewared/middlewared/plugins/auth.py

@@ -17,11 +17,28 @@
 )
 from middlewared.service_exception import MatchNotFound
 import middlewared.sqlalchemy as sa
+from middlewared.utils.audit import TOKEN_EXPIRED
 from middlewared.utils.origin import UnixSocketOrigin
 from middlewared.utils.crypto import generate_token
 from middlewared.utils.time_utils import utc_now
 
 
+class TokenError(Exception):
+    pass
+
+
+class TokenDoesNotExist(TokenError):
+    errmsg = 'Token does not exist'
+
+
+class TokenExpired(TokenError):
+    errmsg = 'Token is expired'
+
+
+class TokenOriginDoesNotMatch(TokenError):
+    errmsg = 'Token origin does not match'
+
+
 class TokenManager:
     def __init__(self):
         self.tokens = {}
@@ -36,19 +53,30 @@ def create(self, ttl, attributes, match_origin, parent_credentials, session_id):
         self.tokens[token] = Token(self, token, ttl, attributes, match_origin, credentials, session_id)
         return self.tokens[token]
 
-    def get(self, token, origin):
+    def get(self, token, origin, raise_error=False):
         token = self.tokens.get(token)
         if token is None:
+            if raise_error:
+                raise TokenDoesNotExist
+
             return None
 
         if not token.is_valid():
             self.tokens.pop(token.token)
+            if raise_error:
+                raise TokenExpired
+
             return None
 
         if token.match_origin:
             if not isinstance(origin, type(token.match_origin)):
+                if raise_error:
+                    raise TokenOriginDoesNotMatch
                 return None
             if not token.match_origin.match(origin):
+                if raise_error:
+                    raise TokenOriginDoesNotMatch
+
                 return None
 
         return token
@@ -465,16 +493,27 @@ async def login_with_token(self, app, token_str):
         """
         Authenticate session using token generated with `auth.generate_token`.
         """
-        token = self.token_manager.get(token_str, app.origin)
-        if token is None:
+        try:
+            token = self.token_manager.get(token_str, app.origin, raise_error=True)
+        except TokenExpired as err:
+            await self.middleware.log_audit_message(app, "AUTHENTICATION", {
+                "credentials": {
+                    "credentials": "TOKEN",
+                    "credentials_data": {
+                        "token": token_str,
+                    }
+                },
+                "error": err.errmsg,
+            }, False, user=TOKEN_EXPIRED)
+        except TokenError as err:
             await self.middleware.log_audit_message(app, "AUTHENTICATION", {
                 "credentials": {
                     "credentials": "TOKEN",
                     "credentials_data": {
                         "token": token_str,
                     }
                 },
-                "error": "Invalid token",
+                "error": err.errmsg,
             }, False)
             return False
 

src/middlewared/middlewared/utils/audit.py

@@ -10,6 +10,7 @@
 NODE_SESSION = '.TRUENAS_NODE'
 UNAUTHENTICATED = '.UNAUTHENTICATED'
 UNKNOWN_SESSION = '.UNKNOWN'
+TOKEN_EXPIRED = '.TOKEN_EXPIRED'  # used for expired tokens in auth.py
 
 
 def audit_username_from_session(cred) -> str: