From 5f289aec9e6fb680a5383b9a84f4efc2f144308c Mon Sep 17 00:00:00 2001 From: Ben Kurtovic Date: Tue, 20 Dec 2016 04:09:24 -0500 Subject: [PATCH] Add logging throughout API and auth code. --- calefaction/__init__.py | 5 +++++ calefaction/auth.py | 39 +++++++++++++++++++++++++++++++++++++-- calefaction/eve/__init__.py | 7 ++++--- calefaction/eve/esi.py | 19 ++++++++++++++----- calefaction/eve/sso.py | 30 ++++++++++++++++++++++-------- 5 files changed, 82 insertions(+), 18 deletions(-) diff --git a/calefaction/__init__.py b/calefaction/__init__.py index d3bf032..3049625 100644 --- a/calefaction/__init__.py +++ b/calefaction/__init__.py @@ -1,2 +1,7 @@ +import logging + __version__ = "0.1.dev0" __release__ = "0.1" + +baseLogger = logging.getLogger("calefaction") +del logging diff --git a/calefaction/auth.py b/calefaction/auth.py index b726f45..018fb3b 100644 --- a/calefaction/auth.py +++ b/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() diff --git a/calefaction/eve/__init__.py b/calefaction/eve/__init__.py index 2ae5a2e..3dc1ead 100644 --- a/calefaction/eve/__init__.py +++ b/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): diff --git a/calefaction/eve/esi.py b/calefaction/eve/esi.py index 625cea9..9b12766 100644 --- a/calefaction/eve/esi.py +++ b/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) diff --git a/calefaction/eve/sso.py b/calefaction/eve/sso.py index 2efff77..65f70ef 100644 --- a/calefaction/eve/sso.py +++ b/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