General Logging

some extra logging around problem areas

.gitignore

@@ -14,3 +14,4 @@ locale.xml
 app/luclient/*
 app/cache/*
 property_files/*
+*.log

app/__init__.py

@@ -1,5 +1,5 @@
 import os
-from flask import Flask, url_for, g, redirect
+from flask import Flask, url_for, g, redirect, render_template
 from functools import wraps
 from flask_assets import Environment
 from webassets import Bundle
@@ -7,7 +7,7 @@ import time
 from app.models import db, migrate, PlayKey
 from app.schemas import ma
 from app.forms import CustomUserManager
-from flask_user import user_registered, current_user
+from flask_user import user_registered, current_user, user_logged_in
 from flask_wtf.csrf import CSRFProtect
 from flask_apscheduler import APScheduler
 from app.luclient import query_cdclient, register_luclient_jinja_helpers
@@ -15,6 +15,11 @@ from app.luclient import query_cdclient, register_luclient_jinja_helpers
 from app.commands import init_db, init_accounts, load_property, gen_image_cache, gen_model_cache
 from app.models import Account, AccountInvitation
 
+import logging
+from logging.handlers import RotatingFileHandler
+
+from werkzeug.exceptions import HTTPException
+
 # Instantiate Flask extensions
 csrf_protect = CSRFProtect()
 scheduler = APScheduler()
@@ -22,7 +27,6 @@ scheduler = APScheduler()
 
 
 def create_app():
-
     app = Flask(__name__, instance_relative_config=True)
 
     # decrement uses on a play key after a successful registration
@@ -33,8 +37,19 @@ def create_app():
             play_key_used = PlayKey.query.filter(PlayKey.id == user.play_key_id).first()
             play_key_used.key_uses = play_key_used.key_uses - 1
             play_key_used.times_used = play_key_used.times_used + 1
+            app.logger.info(
+                f"USERS::REGISTRATION User with ID {user.id} and name {user.username} Registered \
+                using Play Key ID {play_key_used.id} : {play_key_used.key_string}"
+                )
             db.session.add(play_key_used)
             db.session.commit()
+        else:
+            app.logger.info(f"USERS::REGISTRATION User with ID {user.id} and name {user.username} Registered")
+
+
+    @user_logged_in.connect_via(app)
+    def _after_login_hook(sender, user, **extra):
+        app.logger.info(f"{user.username} Logged in")
 
     # A bunch of jinja filters to make things easiers
     @app.template_filter('ctime')
@@ -51,15 +66,24 @@ def create_app():
         else:
             return 0 & (1 << bit)
 
+    @app.template_filter('debug')
+    def debug(text):
+        print(text)
+
     @app.teardown_appcontext
     def close_connection(exception):
         cdclient = getattr(g, '_cdclient', None)
         if cdclient is not None:
             cdclient.close()
 
-    @app.template_filter('debug')
-    def debug(text):
-        print(text)
+    @app.errorhandler(Exception)
+    def handle_exception(e):
+        app.logger.error(e)
+        # pass through HTTP errors
+        if isinstance(e, HTTPException):
+            return e
+        # now you're handling non-HTTP exceptions only
+        return render_template("status_codes/500.html.j2", exception=e), 500
 
     # add the commands to flask cli
     app.cli.add_command(init_db)
@@ -68,6 +92,7 @@ def create_app():
     app.cli.add_command(gen_image_cache)
     app.cli.add_command(gen_model_cache)
 
+    register_logging(app)
     register_settings(app)
     register_extensions(app)
     register_blueprints(app)
@@ -132,6 +157,14 @@ def register_blueprints(app):
     app.register_blueprint(reports_blueprint, url_prefix='/reports')
 
 
+def register_logging(app):
+    # file logger
+    file_handler = RotatingFileHandler('nexus_dashboard.log', maxBytes=1024 * 1024 * 100, backupCount=20)
+    file_handler.setLevel(logging.INFO)
+    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+    file_handler.setFormatter(formatter)
+    app.logger.addHandler(file_handler)
+
 
 def register_settings(app):
     """Register setting from setting and env

app/accounts.py

@@ -1,4 +1,4 @@
-from flask import render_template, Blueprint, redirect, url_for, request, abort, current_app, flash
+from flask import render_template, Blueprint, redirect, url_for, request, abort, current_app, flash, current_app
 from flask_user import login_required, current_user
 import json
 from datatables import ColumnDT, DataTables

app/reports.py

@@ -1,4 +1,4 @@
-from flask import render_template, Blueprint, redirect, url_for, request, abort, flash, request
+from flask import render_template, Blueprint, redirect, url_for, request, abort, flash, request, current_app
 from flask_user import login_required, current_user
 from app.models import db, CharacterInfo, Account, CharacterXML, Reports
 from app import gm_level, scheduler
@@ -37,119 +37,131 @@ def uscore_by_date(date):
 
 @scheduler.task("cron", id="gen_item_report", hour=23)
 def gen_item_report():
-    with scheduler.app.app_context():
-        date = datetime.date.today().strftime('%Y-%m-%d')
-        report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="items").first()
+    try:
+        current_app.logger.info("Start Item Report Generation")
+        with scheduler.app.app_context():
+            date = datetime.date.today().strftime('%Y-%m-%d')
+            report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="items").first()
 
-        # Only one report per day
-        if report != None:
-            return f"Item Report Already Generated for {date}"
+            # Only one report per day
+            if report != None:
+                current_app.logger.info(f"Item Report Already Generated for {date}")
 
-        char_xmls = CharacterXML.query.join(
-                        CharacterInfo,
-                        CharacterInfo.id==CharacterXML.id
-                    ).join(
-                        Account,
-                        CharacterInfo.account_id==Account.id
-                    ).filter(Account.gm_level < 3).all()
+            char_xmls = CharacterXML.query.join(
+                            CharacterInfo,
+                            CharacterInfo.id==CharacterXML.id
+                        ).join(
+                            Account,
+                            CharacterInfo.account_id==Account.id
+                        ).filter(Account.gm_level < 3).all()
 
-        report_data={}
+            report_data={}
 
-        for char_xml in char_xmls:
-            character_json = xmltodict.parse(
-                char_xml.xml_data,
-                attr_prefix="attr_"
+            for char_xml in char_xmls:
+                character_json = xmltodict.parse(
+                    char_xml.xml_data,
+                    attr_prefix="attr_"
+                )
+                for inv in character_json["obj"]["inv"]["items"]["in"]:
+                    if "i" in inv.keys() and type(inv["i"]) == list and (int(inv["attr_t"])==0 or int(inv["attr_t"])==0):
+                        for item in inv["i"]:
+                            if item["attr_l"] in report_data:
+                                report_data[item["attr_l"]] = report_data[item["attr_l"]] + int(item["attr_c"])
+                            else:
+                                report_data[item["attr_l"]] = int(item["attr_c"])
+
+            new_report = Reports(
+                data=report_data,
+                report_type="items",
+                date=date
             )
-            for inv in character_json["obj"]["inv"]["items"]["in"]:
-                if "i" in inv.keys() and type(inv["i"]) == list and (int(inv["attr_t"])==0 or int(inv["attr_t"])==0):
-                    for item in inv["i"]:
-                        if item["attr_l"] in report_data:
-                            report_data[item["attr_l"]] = report_data[item["attr_l"]] + int(item["attr_c"])
-                        else:
-                            report_data[item["attr_l"]] = int(item["attr_c"])
 
-        new_report = Reports(
-            data=report_data,
-            report_type="items",
-            date=date
-        )
-
-        new_report.save()
-
-        return f"Generated Item Report for {date}"
+            new_report.save()
+        current_app.logger.info(f"Generated Item Report for {date}")
+    except Exception as e:
+        current_app.logger.critical(f"REPORT::ITEMS - {e}")
+    return
 
 
 @scheduler.task("cron", id="gen_currency_report", hour=23)
 def gen_currency_report():
-    with scheduler.app.app_context():
-        date = datetime.date.today().strftime('%Y-%m-%d')
-        report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="currency").first()
+    try:
+        current_app.logger.info("Start Currency Report Generation")
+        with scheduler.app.app_context():
+            date = datetime.date.today().strftime('%Y-%m-%d')
+            report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="currency").first()
 
-        # Only one report per day
-        if report != None:
-            return f"Currency Report Already Generated for {date}"
+            # Only one report per day
+            if report != None:
+                current_app.logger.info(f"Currency Report Already Generated for {date}")
 
-        characters = CharacterXML.query.join(
-                        CharacterInfo,
-                        CharacterInfo.id==CharacterXML.id
-                    ).join(
-                        Account,
-                        CharacterInfo.account_id==Account.id
-                    ).filter(Account.gm_level < 3).all()
+            characters = CharacterXML.query.join(
+                            CharacterInfo,
+                            CharacterInfo.id==CharacterXML.id
+                        ).join(
+                            Account,
+                            CharacterInfo.account_id==Account.id
+                        ).filter(Account.gm_level < 3).all()
 
-        report_data={}
+            report_data={}
 
-        for character in characters:
-            character_json = xmltodict.parse(
-                character.xml_data,
-                attr_prefix="attr_"
+            for character in characters:
+                character_json = xmltodict.parse(
+                    character.xml_data,
+                    attr_prefix="attr_"
+                )
+                report_data[CharacterInfo.query.filter(CharacterInfo.id==character.id).first().name] = int(character_json["obj"]["char"]["attr_cc"])
+
+            new_report = Reports(
+                data=report_data,
+                report_type="currency",
+                date=date
             )
-            report_data[CharacterInfo.query.filter(CharacterInfo.id==character.id).first().name] = int(character_json["obj"]["char"]["attr_cc"])
 
-        new_report = Reports(
-            data=report_data,
-            report_type="currency",
-            date=date
-        )
-
-        new_report.save()
-
-        return f"Generated Currency Report for {date}"
+            new_report.save()
+        current_app.logger.info(f"Generated Currency Report for {date}")
+    except Exception as e:
+        current_app.logger.critical(f"REPORT::CURRENCY - {e}")
+    return
 
 
 @scheduler.task("cron", id="gen_uscore_report", hour=23)
 def gen_uscore_report():
-    with scheduler.app.app_context():
-        date = datetime.date.today().strftime('%Y-%m-%d')
-        report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="uscore").first()
+    try:
+        current_app.logger.info("Start U-Score Report Generation")
+        with scheduler.app.app_context():
+            date = datetime.date.today().strftime('%Y-%m-%d')
+            report = Reports.query.filter(Reports.date==date).filter(Reports.report_type=="uscore").first()
 
-        # Only one report per day
-        if report != None:
-            return f"U-Score Report Already Generated for {date}"
+            # Only one report per day
+            if report != None:
+                current_app.logger.info(f"U-Score Report Already Generated for {date}")
 
-        characters = CharacterXML.query.join(
-                        CharacterInfo,
-                        CharacterInfo.id==CharacterXML.id
-                    ).join(
-                        Account,
-                        CharacterInfo.account_id==Account.id
-                    ).filter(Account.gm_level < 3).all()
+            characters = CharacterXML.query.join(
+                            CharacterInfo,
+                            CharacterInfo.id==CharacterXML.id
+                        ).join(
+                            Account,
+                            CharacterInfo.account_id==Account.id
+                        ).filter(Account.gm_level < 3).all()
 
-        report_data={}
+            report_data={}
 
-        for character in characters:
-            character_json = xmltodict.parse(
-                character.xml_data,
-                attr_prefix="attr_"
+            for character in characters:
+                character_json = xmltodict.parse(
+                    character.xml_data,
+                    attr_prefix="attr_"
+                )
+                report_data[CharacterInfo.query.filter(CharacterInfo.id==character.id).first().name] = int(character_json["obj"]["char"]["attr_ls"])
+
+            new_report = Reports(
+                data=report_data,
+                report_type="uscore",
+                date=date
             )
-            report_data[CharacterInfo.query.filter(CharacterInfo.id==character.id).first().name] = int(character_json["obj"]["char"]["attr_ls"])
 
-        new_report = Reports(
-            data=report_data,
-            report_type="uscore",
-            date=date
-        )
-
-        new_report.save()
-
-        return f"Generated U-Score Report for {date}"
+            new_report.save()
+        current_app.logger.info(f"Generated U-Score Report for {date}")
+    except Exception as e:
+        current_app.logger.critical(f"REPORT::U-SCORE - {e}")
+    return