log service id and api key id during auth

example log line:
```
API AuthError: AuthError({'token': ['Invalid token: signature, api token is not valid']}, 403, service_id=3e1ed7ea-8a05-4b4e-93ec-d7bebfea6cae, api_key_id=None)"
```

app/authentication/auth.py

@@ -8,10 +8,15 @@ from app.dao.services_dao import dao_fetch_service_by_id_with_api_keys
 
 
 class AuthError(Exception):
-    def __init__(self, message, code):
+    def __init__(self, message, code, service_id=None, api_key_id=None):
         self.message = {"token": [message]}
         self.short_message = message
         self.code = code
+        self.service_id = service_id
+        self.api_key_id = api_key_id
+
+    def __str__(self):
+        return 'AuthError({message}, {code}, service_id={service_id}, api_key_id={api_key_id})'.format(**self.__dict__)
 
     def to_dict_v2(self):
         return {
@@ -65,28 +70,34 @@ def requires_auth():
         raise AuthError("Invalid token: service not found", 403)
 
     if not service.api_keys:
-        raise AuthError("Invalid token: service has no API keys", 403)
+        raise AuthError("Invalid token: service has no API keys", 403, service_id=service.id)
 
     if not service.active:
-        raise AuthError("Invalid token: service is archived", 403)
+        raise AuthError("Invalid token: service is archived", 403, service_id=service.id)
 
     for api_key in service.api_keys:
         try:
-            get_decode_errors(auth_token, api_key.secret)
+            decode_jwt_token(auth_token, api_key.secret)
         except TokenDecodeError:
             continue
+        except TokenExpiredError:
+            err_msg = (
+                "Invalid token: Tokens must be used within 30 seconds, check that your system clock "
+                "is accurate. Try checking https://time.is/"
+            )
+            raise AuthError(err_msg, 403, service_id=service.id, api_key_id=api_key.id)
 
         if api_key.expiry_date:
-            raise AuthError("Invalid token: API key revoked", 403)
+            raise AuthError("Invalid token: API key revoked", 403, service_id=service.id, api_key_id=api_key.id)
 
         g.service_id = api_key.service_id
         _request_ctx_stack.top.authenticated_service = service
         _request_ctx_stack.top.api_user = api_key
-
+        current_app.logger.info('Succesful login for service {} with api key {}'.format(service.id, api_key.id))
         return
     else:
         # service has API keys, but none matching the one the user provided
-        raise AuthError("Invalid token: signature, api token is not valid", 403)
+        raise AuthError("Invalid token: signature, api token not found", 403, service_id=service.id)
 
 
 def __get_token_issuer(auth_token):
@@ -101,14 +112,8 @@ def __get_token_issuer(auth_token):
 
 def handle_admin_key(auth_token, secret):
     try:
-        get_decode_errors(auth_token, secret)
+        decode_jwt_token(auth_token, secret)
-        return
-    except TokenDecodeError as e:
-        raise AuthError("Invalid token: signature, api token is not valid", 403)
-
-
-def get_decode_errors(auth_token, unsigned_secret):
-    try:
-        decode_jwt_token(auth_token, unsigned_secret)
     except TokenExpiredError:
         raise AuthError("Invalid token: expired, check that your system clock is accurate", 403)
+    except TokenDecodeError as e:
+        raise AuthError("Invalid token: signature, api token is not valid", 403)

tests/app/authentication/test_authentication.py

@@ -5,42 +5,42 @@ from datetime import datetime
 from tests.conftest import set_config_values
 
 import pytest
-from flask import json, current_app
+from flask import json, current_app, request
 from freezegun import freeze_time
 from notifications_python_client.authentication import create_jwt_token
 
 from app import api_user
 from app.dao.api_key_dao import get_unsigned_secrets, save_model_api_key, get_unsigned_secret, expire_api_key
 from app.models import ApiKey, KEY_TYPE_NORMAL
+from app.authentication.auth import AuthError, requires_admin_auth, requires_auth
 
 
-# Test the require_admin_auth and require_auth methods
+@pytest.mark.parametrize('auth_fn', [requires_auth, requires_admin_auth])
-@pytest.mark.parametrize('url', ['/service', '/notifications'])
+def test_should_not_allow_request_with_no_token(client, auth_fn):
-def test_should_not_allow_request_with_no_token(client, url):
+    request.headers = {}
-    response = client.get(url)
+    with pytest.raises(AuthError) as exc:
-    assert response.status_code == 401
+        auth_fn()
-    data = json.loads(response.get_data())
+    assert exc.value.short_message == 'Unauthorized, authentication token must be provided'
-    assert data['message'] == {"token": ['Unauthorized, authentication token must be provided']}
 
 
-@pytest.mark.parametrize('url', ['/service', '/notifications'])
+@pytest.mark.parametrize('auth_fn', [requires_auth, requires_admin_auth])
-def test_should_not_allow_request_with_incorrect_header(client, url):
+def test_should_not_allow_request_with_incorrect_header(client, auth_fn):
-    response = client.get(url, headers={'Authorization': 'Basic 1234'})
+    request.headers = {'Authorization': 'Basic 1234'}
-    assert response.status_code == 401
+    with pytest.raises(AuthError) as exc:
-    data = json.loads(response.get_data())
+        auth_fn()
-    assert data['message'] == {"token": ['Unauthorized, authentication bearer scheme must be used']}
+    assert exc.value.short_message == 'Unauthorized, authentication bearer scheme must be used'
 
 
-@pytest.mark.parametrize('url', ['/service', '/notifications'])
+@pytest.mark.parametrize('auth_fn', [requires_auth, requires_admin_auth])
-def test_should_not_allow_request_with_incorrect_token(client, url):
+def test_should_not_allow_request_with_incorrect_token(client, auth_fn):
-    response = client.get(url, headers={'Authorization': 'Bearer 1234'})
+    request.headers = {'Authorization': 'Bearer 1234'}
-    assert response.status_code == 403
+    with pytest.raises(AuthError) as exc:
-    data = json.loads(response.get_data())
+        auth_fn()
-    assert data['message'] == {"token": ['Invalid token: signature, api token is not valid']}
+    assert exc.value.short_message == 'Invalid token: signature, api token is not valid'
 
 
-@pytest.mark.parametrize('url', ['/service', '/notifications'])
+@pytest.mark.parametrize('auth_fn', [requires_auth, requires_admin_auth])
-def test_should_not_allow_request_with_no_iss(client, url):
+def test_should_not_allow_request_with_no_iss(client, auth_fn):
     # code copied from notifications_python_client.authentication.py::create_jwt_token
     headers = {
         "typ": 'JWT',
@@ -54,19 +54,17 @@ def test_should_not_allow_request_with_no_iss(client, url):
 
     token = jwt.encode(payload=claims, key=str(uuid.uuid4()), headers=headers).decode()
 
-    response = client.get(url, headers={'Authorization': 'Bearer {}'.format(token)})
+    request.headers = {'Authorization': 'Bearer {}'.format(token)}
-    assert response.status_code == 403
+    with pytest.raises(AuthError) as exc:
-    data = json.loads(response.get_data())
+        auth_fn()
-    assert data['message'] == {"token": ['Invalid token: iss field not provided']}
+    assert exc.value.short_message == 'Invalid token: iss field not provided'
 
 
-@pytest.mark.parametrize('url, auth_method',
+@pytest.mark.parametrize('auth_method', [requires_auth, requires_admin_auth])
-                         [('/service', 'requires_admin_auth'),
+def test_should_not_allow_request_with_no_iat(client, sample_api_key, auth_method):
-                          ('/notifications', 'requires_auth')])
+    if auth_method == requires_admin_auth:
-def test_should_not_allow_request_with_no_iat(client, sample_api_key, url, auth_method):
-    if auth_method == 'requires_admin_auth':
         iss = current_app.config['ADMIN_CLIENT_USER_NAME']
-    if auth_method == 'requires_auth':
+    if auth_method == requires_auth:
         iss = str(sample_api_key.service_id)
     # code copied from notifications_python_client.authentication.py::create_jwt_token
     headers = {
@@ -81,10 +79,10 @@ def test_should_not_allow_request_with_no_iat(client, sample_api_key, url, auth_
 
     token = jwt.encode(payload=claims, key=str(uuid.uuid4()), headers=headers).decode()
 
-    response = client.get(url, headers={'Authorization': 'Bearer {}'.format(token)})
+    request.headers = {'Authorization': 'Bearer {}'.format(token)}
-    assert response.status_code == 403
+    with pytest.raises(AuthError) as exc:
-    data = json.loads(response.get_data())
+        auth_method()
-    assert data['message'] == {"token": ['Invalid token: signature, api token is not valid']}
+    assert exc.value.short_message == 'Invalid token: signature, api token is not valid'
 
 
 def test_should_not_allow_invalid_secret(client, sample_api_key):
@@ -193,12 +191,12 @@ def test_authentication_returns_token_expired_when_service_uses_expired_key_and_
         secret=get_unsigned_secret(expired_api_key.id),
         client_id=str(sample_api_key.service_id))
     expire_api_key(service_id=sample_api_key.service_id, api_key_id=expired_api_key.id)
-    response = client.get(
+    request.headers = {'Authorization': 'Bearer {}'.format(token)}
-        '/notifications',
+    with pytest.raises(AuthError) as exc:
-        headers={'Authorization': 'Bearer {}'.format(token)})
+        requires_auth()
-    assert response.status_code == 403
+    assert exc.value.short_message == 'Invalid token: API key revoked'
-    data = json.loads(response.get_data())
+    assert exc.value.service_id == expired_api_key.service_id
-    assert data['message'] == {"token": ['Invalid token: API key revoked']}
+    assert exc.value.api_key_id == expired_api_key.id
 
 
 def test_authentication_returns_error_when_admin_client_has_no_secrets(client):
@@ -213,7 +211,7 @@ def test_authentication_returns_error_when_admin_client_has_no_secrets(client):
         headers={'Authorization': 'Bearer {}'.format(token)})
     assert response.status_code == 403
     error_message = json.loads(response.get_data())
-    assert error_message['message'] == {"token": ["Invalid token: signature, api token is not valid"]}
+    assert error_message['message'] == {"token": ["Invalid token: signature, api token not found"]}
     current_app.config['ADMIN_CLIENT_SECRET'] = api_secret
 
 
@@ -269,12 +267,11 @@ def test_authentication_returns_error_when_service_has_no_secrets(client,
         secret=fake_uuid,
         client_id=str(sample_service.id))
 
-    response = client.get(
+    request.headers = {'Authorization': 'Bearer {}'.format(token)}
-        '/notifications',
+    with pytest.raises(AuthError) as exc:
-        headers={'Authorization': 'Bearer {}'.format(token)})
+        requires_auth()
-    assert response.status_code == 403
+    assert exc.value.short_message == 'Invalid token: service has no API keys'
-    error_message = json.loads(response.get_data())
+    assert exc.value.service_id == sample_service.id
-    assert error_message['message'] == {'token': ['Invalid token: service has no API keys']}
 
 
 def test_should_attach_the_current_api_key_to_current_app(notify_api, sample_service, sample_api_key):
@@ -293,14 +290,12 @@ def test_should_return_403_when_token_is_expired(client,
     with freeze_time('2001-01-01T12:00:00'):
         token = __create_token(sample_api_key.service_id)
     with freeze_time('2001-01-01T12:00:40'):
-        response = client.get(
+        with pytest.raises(AuthError) as exc:
-            '/notifications',
+            request.headers = {'Authorization': 'Bearer {}'.format(token)}
-            headers={'Authorization': 'Bearer {}'.format(token)})
+            requires_auth()
-    assert response.status_code == 403
+    assert 'check that your system clock is accurate' in exc.value.short_message
-    error_message = json.loads(response.get_data())
+    assert exc.value.service_id == sample_api_key.service_id
-    assert error_message['message'] == {'token': [
+    assert exc.value.api_key_id == sample_api_key.id
-        'Invalid token: expired, check that your system clock is accurate'
-    ]}
 
 
 def __create_token(service_id):