lmprove logging by prefixing logs with username when possible (#8)

* Improve logging by prefixing logs with username when possible

* Bump version: 0.3.4 → 0.3.5

TokenExchangeAuthenticator/.bumpversion.cfg

@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 0.3.4
+current_version = 0.3.5
 commit = True
 tag = True
 

TokenExchangeAuthenticator/setup.py

@@ -21,7 +21,7 @@ def read(filename):
 
 setup(
     name="TokenExchangeAuthenticator",
-    version="0.3.4",
+    version="0.3.5",
     url="https://github.com/statisticsnorway/jupyterhub-extensions",
     license='MIT',
 

TokenExchangeAuthenticator/tokenexchangeauthenticator/_version.py

@@ -1 +1 @@
-__version__ = '0.3.4'
+__version__ = '0.3.5'

TokenExchangeAuthenticator/tokenexchangeauthenticator/auth.py

@@ -108,32 +108,33 @@ async def authenticate(self, handler, data=None):
         try:
             user['auth_state']['exchanged_tokens'] = await self._exchange_tokens(user['auth_state']['access_token'])
         except KeyError:
-            self.log.error('Exchanged tokens missing from auth_state for user %s', user['name'])
+            self.log.error(
+                prefix_log_message('Exchanged tokens missing from auth_state for user', user['name']))
             handler.clear_cookie("jupyterhub-hub-login")
             handler.clear_cookie("jupyterhub-session-id")
             return None
         except HTTPClientError as error:
-            self.log.error('Token exchange failed for user %s with response %s\n%s', user['name'], error,
-                           error.response)
+            self.log.error(prefix_log_message(
+                f'Token exchange failed for user, with {error =}, {error.response =}', user['name']))
             handler.clear_cookie("jupyterhub-hub-login")
             handler.clear_cookie("jupyterhub-session-id")
             return None
 
-        self.log.info("Authentication Successful for user: %s" % user['name'])
+        self.log.info(prefix_log_message("Authentication Successful", user['name']))
         return user
 
     async def pre_spawn_start(self, user, spawner):
         """Pass upstream_token to spawner via environment variable"""
-        self.log.info('Calling pre_spawn_start for %s ' % user.name)
+        self.log.info(prefix_log_message('Calling pre_spawn_start', user.name))
         # Retrieve user authentication info from JH
         auth_state = await user.get_auth_state()
         if not auth_state:
             # user has no auth state
-            self.log.error('User has no auth state')
+            self.log.error(prefix_log_message('User has no auth state', user.name))
             return
 
         # update env var to pass to notebooks
-        self.log.info('Starting notebook for: ' + user.name)
+        self.log.info(prefix_log_message('Starting notebook', user.name))
 
     async def refresh_user(self, user, handler=None):
         """
@@ -155,17 +156,20 @@ async def refresh_user(self, user, handler=None):
             if diff_access > self.auth_refresh_age:
                 if 'exchanged_tokens' in auth_state and await self._is_expired_exchange_tokens(auth_state):
                     auth_state['exchanged_tokens'] = await self._exchange_tokens(auth_state['access_token'])
-                    self.log.info("New exchange_tokens updated for user %s" % user.name)
+                    self.log.info(prefix_log_message("New exchange_tokens updated for user", user.name))
                     return {
                         'auth_state': auth_state
                     }
                 # All tokens are still valid and will stay until next refresh
-                self.log.info("All tokens are still valid and will stay until next refresh")
+                self.log.info(
+                    prefix_log_message("All tokens are still valid and will stay until next refresh",
+                                       user.name))
                 return True
 
             elif diff_refresh < 0:
                 # Refresh token not valid, need to re-authenticate again
-                self.log.info("Refresh token not valid, need to re-authenticate again")
+                self.log.info(
+                    prefix_log_message("Refresh token not valid, need to re-authenticate again", user.name))
                 await handler.stop_single_user(user, user.spawner.name)
                 handler.clear_cookie("jupyterhub-hub-login")
                 handler.clear_cookie("jupyterhub-session-id")
@@ -176,21 +180,23 @@ async def refresh_user(self, user, handler=None):
                 # We need to refresh access token (which will also refresh the refresh token)
                 access_token, refresh_token = await self._refresh_token(auth_state['refresh_token'])
                 # check signature for new access token, if it fails we catch in the exception below
-                self.log.info("Refresh user token")
+                self.log.info(prefix_log_message("Refresh user token", user.name))
                 self._decode_token(access_token)
                 auth_state['access_token'] = access_token
                 auth_state['refresh_token'] = refresh_token
                 auth_state['exchanged_tokens'] = await self._exchange_tokens(access_token)
 
-                self.log.info('User %s oAuth tokens refreshed' % user.name)
+                self.log.info(prefix_log_message('User oAuth tokens refreshed', user.name))
                 return {
                     'auth_state': auth_state
                 }
         except HTTPError as e:
-            self.log.error("Failure calling the renew endpoint: %s (code: %s)" % (e.read(), e.code))
+            self.log.error(
+                prefix_log_message(f"Failure calling the renew endpoint: {e.read()} (code: {e.code})",
+                                   user.name))
 
         except:
-            self.log.error("Failed to refresh the oAuth tokens", exc_info=True)
+            self.log.error(prefix_log_message("Failed to refresh the oAuth tokens", user.name), exc_info=True)
 
         return False
 
@@ -288,7 +294,7 @@ async def get(self):
             self.log.info('User is none')
             raise web.HTTPError(403)
 
-        self.log.info('User is ' + user.name)
+        self.log.info(prefix_log_message('User exists', user.name))
         # Force auth refresh to override the auth_refresh_age of 300 secs
         user = await self.refresh_auth(user, force=True)
         auth_state = await user.get_auth_state()
@@ -303,3 +309,7 @@ async def get(self):
             "refresh_token": auth_state['refresh_token'],
             "exchanged_tokens": auth_state['exchanged_tokens']
         })
+
+
+def prefix_log_message(msg, user):
+    return f"[User: {user}] {msg}"

TokenExchangeAuthenticator/tokenexchangeauthenticator/tests/test_auth.py

@@ -6,6 +6,8 @@
 
 import jwt
 import time
+
+import pytest
 from pytest import fixture, raises, mark
 from tornado.web import HTTPError
 
@@ -66,20 +68,23 @@ def oauth_client(client):
     return client
 
 
+@pytest.mark.asyncio
 async def test_authenticator(get_authenticator, oauth_client):
     authenticator = get_authenticator()
     handler = oauth_client.handler_for_user(user_model('john.doe', email='fake@email.com'))
     user_info = await authenticator.authenticate(handler)
-    assert sorted(user_info) == ['auth_state', 'name']
+    assert sorted(user_info) == ['admin', 'auth_state', 'name']
     name = user_info['name']
     assert name == 'john.doe'
     auth_state = user_info['auth_state']
     assert 'access_token' in auth_state
     assert 'oauth_user' in auth_state
     assert 'refresh_token' in auth_state
     assert 'scope' in auth_state
+    assert user_info['admin'] is None
 
 
+@pytest.mark.asyncio
 async def test_authenticator_with_local_user_exposed_path(get_authenticator, oauth_client):
     authenticator = get_authenticator(local_user_exposed_path='/custom-api/userinfo')
 
@@ -89,12 +94,13 @@ async def test_authenticator_with_local_user_exposed_path(get_authenticator, oau
     assert any([h == AuthHandler for h in handlers])
 
 
+@pytest.mark.asyncio
 async def test_authenticator_with_token_exchange(get_authenticator, oauth_client):
     authenticator = get_authenticator(exchange_tokens=['ext_idp'])
 
     handler = oauth_client.handler_for_user(user_model('john.doe', email='fake@email.com'))
     user_info = await authenticator.authenticate(handler)
-    assert sorted(user_info) == ['auth_state', 'name']
+    assert sorted(user_info) == ['admin', 'auth_state', 'name']
     name = user_info['name']
     assert name == 'john.doe'
     auth_state = user_info['auth_state']
@@ -106,8 +112,10 @@ async def test_authenticator_with_token_exchange(get_authenticator, oauth_client
     assert 'ext_idp' in auth_state['exchanged_tokens']
     assert 'access_token' in auth_state['exchanged_tokens']['ext_idp']
     assert 'exp' in auth_state['exchanged_tokens']['ext_idp']
+    assert user_info['admin'] is None
 
 
+@pytest.mark.asyncio
 async def test_authenticator_refresh_all_valid(get_authenticator, oauth_client):
     authenticator = get_authenticator()
 
@@ -116,6 +124,7 @@ async def test_authenticator_refresh_all_valid(get_authenticator, oauth_client):
 
     class SimpleUser:
         def __init__(self, user_info):
+            self.name = "test-user@ssb.no"
             self.user_info = user_info
             dt = datetime.now() + timedelta(hours=1)
             user_info['access_token'] = jwt.encode({'exp': dt}, 'secret', algorithm='HS256')
@@ -134,6 +143,8 @@ async def get_auth_state(self):
     # Still valid
     assert result is True
 
+
+@pytest.mark.asyncio
 @mark.skip("Fails on azure pipelines")
 async def test_authenticator_refresh_all_invalid(get_authenticator, oauth_client):
     authenticator = get_authenticator()
@@ -165,6 +176,7 @@ async def get_auth_state(self):
     assert 'exchanged_tokens' in auth_state
 
 
+@pytest.mark.asyncio
 async def test_authenticator_refresh_token_exchange(get_authenticator, oauth_client):
     authenticator = get_authenticator()
 
@@ -195,6 +207,7 @@ async def get_auth_state(self):
     assert 'exchanged_tokens' in auth_state
 
 
+@pytest.mark.asyncio
 async def test_hosted_domain(get_authenticator, oauth_client):
     authenticator = get_authenticator(hosted_domain=['email.com', 'mycollege.edu'])
 
@@ -209,6 +222,7 @@ async def test_hosted_domain(get_authenticator, oauth_client):
     assert exc.value.status_code == 403
 
 
+@pytest.mark.asyncio
 async def test_custom_logout(monkeypatch):
     login_url = "http://myhost/login"
     authenticator = _get_authenticator()

TokenExchangeAuthenticator/tox.ini

@@ -5,4 +5,4 @@ envlist = py39
 commands = pytest -s {posargs}
 deps = pytest
        pytest-asyncio
-       -rrequirements.txt
+       -r requirements.txt