Add logging throughout API and auth code.

calefaction/__init__.py

@@ -1,2 +1,7 @@
+import logging
+
 __version__ = "0.1.dev0"
 __release__ = "0.1"
+
+baseLogger = logging.getLogger("calefaction")
+del logging

calefaction/auth.py

@@ -5,6 +5,7 @@ from datetime import datetime, timedelta
 from flask import g, session, url_for
 from itsdangerous import BadSignature, URLSafeSerializer
 
+from . import baseLogger
 from .exceptions import AccessDeniedError
 
 __all__ = ["AuthManager"]
@@ -19,10 +20,14 @@ class AuthManager:
         self._config = config
         self._eve = eve
 
+        self._logger = baseLogger.getChild("auth")
+        self._debug = self._logger.debug
+
     def _get_session_id(self):
         """Return the current session ID, allocating a new one if necessary."""
         if "id" not in session:
             session["id"] = g.db.new_session()
+            self._debug("Allocated session id=%d", session["id"])
             g._session_checked = True
             g._session_expired = False
         return session["id"]
@@ -33,7 +38,9 @@ class AuthManager:
         Remove it from the database and from the user's cookies.
         """
         if "id" in session:
-            g.db.drop_session(session["id"])
+            sid = session["id"]
+            g.db.drop_session(sid)
+            self._debug("Dropped session id=%d", sid)
             del session["id"]
 
     def _check_session(self):
@@ -51,6 +58,7 @@ class AuthManager:
         g._session_checked = check = g.db.has_session(session["id"])
         if not check:
             g._session_expired = True
+            self._debug("Session expired id=%d", session["id"])
             self._invalidate_session()
         return check
 
@@ -74,9 +82,13 @@ class AuthManager:
         try:
             value = serializer.loads(state)
         except BadSignature:
+            self._debug("Bad signature for session id=%d", session["id"])
             self._invalidate_session()
             return False
+
         if value != session["id"]:
+            self._debug("Got session id=%d, expected id=%d", value,
+                        session["id"])
             self._invalidate_session()
             return False
         return True
@@ -117,23 +129,29 @@ class AuthManager:
         """
         result = g.db.get_auth(cid)
         if not result:
+            self._debug("No auth info in database for char id=%d", cid)
             return None
 
         token, expires, refresh = result
         seconds_til_expiry = (expires - datetime.utcnow()).total_seconds()
         if seconds_til_expiry >= self.EXPIRY_THRESHOLD:
+            self._debug("Using cached access token for char id=%d", cid)
             return token
 
         result = self._fetch_new_token(refresh, refresh=True)
         if not result:
+            self._debug("Couldn't refresh token for char id=%d", cid)
             g.db.drop_auth(cid)
             return None
 
         token, expires, refresh, char_id, char_name = result
         if char_id != cid:
+            self._debug("Refreshed token has incorrect char id=%d for "
+                        "char id=%d", char_id, cid)
             g.db.drop_auth(cid)
             return None
 
+        self._debug("Using fresh access token for char id=%d", cid)
         g.db.put_character(cid, char_name)
         g.db.update_auth(cid, token, expires, refresh)
         return token
@@ -145,6 +163,8 @@ class AuthManager:
         """
         resp = self._eve.esi(token).v3.characters(char_id).get()
         if resp.get("corporation_id") != self._config.get("corp.id"):
+            self._debug("Access denied per corp membership for char id=%d "
+                        "session id=%d", char_id, session["id"])
             g.db.drop_auth(char_id)
             self._invalidate_session()
             raise AccessDeniedError()
@@ -184,17 +204,24 @@ class AuthManager:
 
         EVEAPIError or AccessDeniedError may be raised.
         """
+        if "id" in session:
+            self._debug("Checking auth for session id=%d", session["id"])
+
         cid = self.get_character_id()
         if not cid:
             return False
 
         token = self._get_token(cid)
         if not token:
+            self._debug("No valid token for char id=%d session id=%d", cid,
+                        session["id"])
             self._invalidate_session()
             return False
 
         self._check_access(token, cid)
 
+        self._debug("Access granted for char id=%d session id=%d", cid,
+                    session["id"])
         g.db.touch_session(session["id"])
         return True
 
@@ -219,20 +246,25 @@ class AuthManager:
         """
         if not code or not state:
             return False
+
+        if "id" in session:
+            self._debug("Logging in session id=%d", session["id"])
         if not self._check_session():
             return False
         if not self._verify_state_hash(state):
             return False
 
+        sid = session["id"]
         result = self._fetch_new_token(code)
         if not result:
+            self._debug("Couldn't fetch token for session id=%d", sid)
             self._invalidate_session()
             return False
 
         token, expires, refresh, char_id, char_name = result
         self._check_access(token, char_id)
 
-        sid = session["id"]
+        self._debug("Logged in char id=%d session id=%d", char_id, sid)
         g.db.put_character(char_id, char_name)
         g.db.set_auth(char_id, token, expires, refresh)
         g.db.attach_session(sid, char_id)
@@ -244,5 +276,8 @@ class AuthManager:
 
         Invalidates their session and clears the session cookie.
         """
+        if "id" in session:
+            self._debug("Logging out session id=%d", session["id"])
+
         self._invalidate_session()
         session.clear()

calefaction/eve/__init__.py

@@ -8,7 +8,7 @@ from .clock import Clock
 from .esi import EVESwaggerInterface
 from .image import ImageServer
 from .sso import SSOManager
-from .. import __release__
+from .. import __release__, baseLogger
 
 __all__ = ["EVE"]
 
@@ -19,11 +19,12 @@ class EVE:
         session = requests.Session()
         agent = self._get_user_agent(config.get("site.contact"))
         session.headers["User-Agent"] = agent
+        logger = baseLogger.getChild("eve")
 
         self._clock = Clock()
-        self._esi = EVESwaggerInterface(session)
+        self._esi = EVESwaggerInterface(session, logger.getChild("esi"))
         self._image = ImageServer()
-        self._sso = SSOManager(session)
+        self._sso = SSOManager(session, logger.getChild("sso"))
 
     @staticmethod
     def _get_user_agent(contact):

calefaction/eve/esi.py

@@ -130,8 +130,11 @@ class EVESwaggerInterface:
     data = esi(token).v1.universe.names.post(ids=[entity_id]})
     """
 
-    def __init__(self, session):
+    def __init__(self, session, logger):
         self._session = session
+        self._logger = logger
+        self._debug = logger.debug
+
         self._base_url = "https://esi.tech.ccp.is"
         self._data_source = "tranquility"
         self._cache = _ESICache()
@@ -148,8 +151,13 @@ class EVESwaggerInterface:
             pkey = self._cache.freeze_dict(params)
             key = "|".join((method.__name__, self._data_source, query, pkey))
             cached = self._cache.fetch(key)
-            if cached:
-                return cached
+        else:
+            cached = None
+
+        self._debug("[%s] [%s] %s", method.__name__.upper(),
+                    "cache" if cached else "fresh", query)
+        if cached:
+            return cached
 
         headers = {
             "Accept": "application/json",
@@ -164,8 +172,9 @@ class EVESwaggerInterface:
                           headers=headers, timeout=10)
             resp.raise_for_status()
             result = resp.json() if resp.content else None
-        except (requests.RequestException, ValueError) as exc:
-            raise EVEAPIError(str(exc))
+        except (requests.RequestException, ValueError):
+            self._logger.exception("ESI request failed")
+            raise EVEAPIError()
 
         if can_cache and result is not None:
             self._cache.insert(key, result, resp)

calefaction/eve/sso.py

@@ -11,9 +11,12 @@ __all__ = ["SSOManager"]
 class SSOManager:
     """EVE API module for Single Sign-On (SSO)."""
 
-    def __init__(self, session):
+    def __init__(self, session, logger):
         self._session = session
 
+        self._logger = logger
+        self._debug = logger.debug
+
     def get_authorize_url(self, client_id, redirect_uri, scopes=None,
                           state=None):
         """Return a URL that the end user can use to start a login."""
@@ -46,26 +49,32 @@ class SSOManager:
             params["grant_type"] = "refresh_token"
         else:
             params["grant_type"] = "authorization_code"
+        self._debug("[POST] /oauth/token")
 
         try:
             resp = self._session.post(url, data=params, timeout=10,
                                       auth=(client_id, client_secret))
             json = resp.json()
-        except (requests.RequestException, ValueError) as exc:
-            raise EVEAPIError(str(exc))
+        except (requests.RequestException, ValueError):
+            self._logger.exception("Access token fetch failed")
+            raise EVEAPIError()
 
         if not resp.ok or "error" in json:
+            self._debug("Access token fetch error: %s", json["error"])
             return None
 
         if json.get("token_type") != "Bearer":
-            raise EVEAPIError("invalid token_type in response body")
+            self._logger.error("Invalid token_type in response body: %s",
+                               json.get("token_type"))
+            raise EVEAPIError()
 
         token = json.get("access_token")
         expiry = json.get("expires_in")
         refresh = json.get("refresh_token")
 
         if not token or not expiry or not refresh:
-            raise EVEAPIError("missing data in token response body")
+            self._logger.error("Missing data in token response body")
+            raise EVEAPIError()
 
         return token, expiry, refresh
 
@@ -78,19 +87,24 @@ class SSOManager:
         """
         url = "https://login.eveonline.com/oauth/verify"
         headers = {"Authorization": "Bearer " + token}
+        self._debug("[GET] /oauth/verify")
+
         try:
             resp = self._session.get(url, timeout=10, headers=headers)
             json = resp.json()
-        except (requests.RequestException, ValueError) as exc:
-            raise EVEAPIError(str(exc))
+        except (requests.RequestException, ValueError):
+            self._logger.exception("Access token verify failed")
+            raise EVEAPIError()
 
         if not resp.ok or "error" in json:
+            self._debug("Access token verify error: %s", json["error"])
             return None
 
         char_id = json.get("CharacterID")
         char_name = json.get("CharacterName")
 
         if not char_id or not char_name:
-            raise EVEAPIError("missing character ID or name in response body")
+            self._logger.error("Missing character ID or name in response body")
+            raise EVEAPIError()
 
         return char_id, char_name