Added some basic logging.

wanikaniburned.py

@@ -1,6 +1,7 @@
 import ujson as json
 import re
 from datetime import datetime, timedelta
+import logging
 
 import flask
 from flask.ext.login import LoginManager, login_user, login_required, current_user, logout_user, login_fresh, \
@@ -11,16 +12,28 @@ import requests
 from wtforms import StringField
 from wtforms.validators import DataRequired
 
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.INFO)
+handler = logging.FileHandler('wkburned.log')
+handler.setLevel(logging.WARN)
+formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+handler.setFormatter(formatter)
+logger.addHandler(handler)
+
 app = flask.Flask(__name__)
+logger.debug("Configuring application.")
 app.config.update(
     PORT=5000,
     JSON_AS_ASCII=False
 )
 app.config.from_pyfile('config.py', silent=True)
+logger.debug("Setting up login manager.")
 login_manager = LoginManager()
 login_manager.init_app(app)
+logger.debug("Setting up database.")
 db = SQLAlchemy(app)
 filter_regex = re.compile('\d+([,-]\d+)*')
+logger.debug("Setup complete")
 
 
 class LoginForm(Form):
@@ -39,6 +52,7 @@ class User(db.Model):
 
     # auto_init and username should only be changed for testing purposes
     def __init__(self, api_key, auto_init=True, username=None):
+        logger.info("Creating new user with %s", api_key)
         self.api_key = api_key
         self.username = username
         self.last_updated = datetime.min
@@ -49,6 +63,7 @@ class User(db.Model):
             self.parse_vocabulary()
         # If a user with this name already exists, delete it as their api key has probably changed to the new input.
         if User.query.filter(User.username == self.username).first():
+            logger.info("User with username '%s' already exists, deleting old entry", self.username)
             db.session.delete(User.query.filter(User.username == self.username).first())
         db.session.add(self)
         db.session.commit()
@@ -66,10 +81,12 @@ class User(db.Model):
         return str(self.api_key)
 
     def parse_radicals_and_userdata(self):  # pragma: no cover
+        logger.debug("Parsing radicals and userdata for %s", self.api_key)
         response = requests.get("https://www.wanikani.com/api/user/" + self.api_key + "/radicals/")
         response.raise_for_status()
         data = response.json()
         if data.get('error'):
+            logger.error("Error response from WK when updating radicals and userdata. %s", data['error']['message'])
             raise ValueError(data['error']['message'])
         self.username = data['user_information']['username']
         self.gravatar = data['user_information']['gravatar']
@@ -77,24 +94,29 @@ class User(db.Model):
             self.radicals = json.dumps(data['requested_information'], ensure_ascii=False)
 
     def parse_kanji(self):  # pragma: no cover
+        logger.debug("Parsing kanji for %s", self.api_key)
         response = requests.get("https://www.wanikani.com/api/user/" + self.api_key + "/kanji/")
         response.raise_for_status()
         data = response.json()
         if data.get('error'):
+            logger.error("Error response from WK when updating kanji. %s", data['error']['message'])
             raise ValueError(data['error']['message'])
         if data.get('requested_information'):
             self.kanji = json.dumps(data['requested_information'], ensure_ascii=False)
 
     def parse_vocabulary(self):  # pragma: no cover
+        logger.debug("Parsing vocabulary for %s", self.api_key)
         response = requests.get("https://www.wanikani.com/api/user/" + self.api_key + "/vocabulary/")
         response.raise_for_status()
         data = response.json()
         if data.get('error'):
+            logger.error("Error response from WK when updating vocabulary. %s", data['error']['message'])
             raise ValueError(data['error']['message'])
         if data.get('requested_information'):
             self.vocabulary = json.dumps(data['requested_information']['general'], ensure_ascii=False)
 
     def update_all(self):  # pragma: no cover
+        logger.info("Updating all info for %s", self.api_key)
         if (datetime.utcnow() - self.last_updated) > timedelta(hours=1):
             self.parse_radicals_and_userdata()
             self.parse_kanji()
@@ -102,6 +124,7 @@ class User(db.Model):
             self.last_updated = datetime.utcnow()
             db.session.commit()
         else:
+            logger.warn("%s tried to update too frequently", self.api_key)
             raise ValueError('Cannot refresh now, try again later.')
 
 
@@ -221,6 +244,7 @@ def refresh_api():  # pragma: no cover
         current_user.update_all()
         return str(datetime_format(current_user.last_updated)), 202
     except ValueError as err:
+        logger.error("Error during /refresh. %s", str(err))
         return str(err), 500