Merge pull request #105 from JoelEager/log-all-the-things

And there was logging

Author: JoelEager

config.env.py

@@ -7,6 +7,8 @@
 SERVER_NAME = environ.get("PACKET_SERVER_NAME", IP + ":" + PORT)
 SECRET_KEY = environ.get("PACKET_SECRET_KEY", "PLEASE_REPLACE_ME")
 
+LOG_LEVEL = environ.get("PACKET_LOG_LEVEL", "INFO")
+
 # OpenID Connect SSO config
 REALM = environ.get("PACKET_REALM", "csh")
 

packet/__init__.py

@@ -3,6 +3,7 @@
 """
 
 import os
+import logging
 
 import csh_ldap
 from flask import Flask
@@ -23,6 +24,9 @@
 
 app.config["VERSION"] = __version__
 
+# Logger configuration
+logging.getLogger().setLevel(app.config["LOG_LEVEL"])
+
 # Initialize the extensions
 db = SQLAlchemy(app)
 migrate = Migrate(app, db)
@@ -36,6 +40,8 @@
 # LDAP
 _ldap = csh_ldap.CSHLDAP(app.config["LDAP_BIND_DN"], app.config["LDAP_BIND_PASS"])
 
+app.logger.info("DB and LDAP configured")
+
 # pylint: disable=wrong-import-position
 from . import models
 from . import context_processors
@@ -46,3 +52,5 @@
     from .routes import upperclassmen
 else:
     from .routes import freshmen
+
+app.logger.info("Routes registered")

packet/debug_utils.py

@@ -0,0 +1,42 @@
+"""
+General utilities for logging metadata
+"""
+
+from functools import wraps
+from datetime import datetime
+
+from packet import context_processors, app
+
+
+def log_time(func):
+    """
+    Decorator for logging the execution time of a function
+    """
+    @wraps(func)
+    def wrapped_function(*args, **kwargs):
+        start = datetime.now()
+
+        result = func(*args, **kwargs)
+
+        seconds = (datetime.now() - start).total_seconds()
+        app.logger.info("{}.{}() returned after {} seconds".format(func.__module__, func.__name__, seconds))
+
+        return result
+
+    return wrapped_function
+
+
+def log_cache(func):
+    """
+    Decorator for logging cache info
+    """
+    @wraps(func)
+    def wrapped_function(*args, **kwargs):
+        result = func(*args, **kwargs)
+
+        app.logger.info("get_csh_name(): {}, get_rit_name(): {}".format(context_processors.get_csh_name.cache_info(),
+                                                                        context_processors.get_rit_name.cache_info()))
+
+        return result
+
+    return wrapped_function

packet/log_utils.py

@@ -103,14 +103,12 @@ def did_sign(self, username, is_csh):
         # The user must be a misc CSHer that hasn't signed this packet or an off-floor freshmen
         return False
 
-
     def is_100(self):
         """
         Checks if this packet has reached 100%
         """
         return self.signatures_required().total == self.signatures_recieved().total
 
-
     @classmethod
     def open_packets(cls):
         """

packet/models.py

@@ -15,24 +15,26 @@ def sign(packet_id, info):
             # Check if the CSHer is an upperclassman and if so, sign that row
             for sig in filter(lambda sig: sig.member == info["uid"], packet.upper_signatures):
                 sig.signed = True
-                db.session.commit()
-                if not was_100 and packet.is_100():
-                    notify_slack(packet.freshman.name)
-                return "Success: Signed Packet: " + packet.freshman_username
+                app.logger.info("Member {} signed packet {} as an upperclassman".format(info["uid"], packet_id))
+                return commit_sig(packet, was_100)
 
             # The CSHer is a misc so add a new row
             db.session.add(MiscSignature(packet=packet, member=info["uid"]))
-            db.session.commit()
-            if not was_100 and packet.is_100():
-                notify_slack(packet.freshman.name)
-            return "Success: Signed Packet: " + packet.freshman_username
+            app.logger.info("Member {} signed packet {} as a misc".format(info["uid"], packet_id))
+            return commit_sig(packet, was_100)
         else:
             # Check if the freshman is onfloor and if so, sign that row
             for sig in filter(lambda sig: sig.freshman_username == info["uid"], packet.fresh_signatures):
                 sig.signed = True
-                db.session.commit()
-                if not was_100 and packet.is_100():
-                    notify_slack(packet.freshman.name)
-                return "Success: Signed Packet: " + packet.freshman_username
+                app.logger.info("Freshman {} signed packet {}".format(info["uid"], packet_id))
+                return commit_sig(packet, was_100)
 
+    app.logger.warn("Failed to add {}'s signature to packet {}".format(info["uid"], packet_id))
     return "Error: Signature not valid.  Reason: Unknown"
+
+def commit_sig(packet, was_100):
+    db.session.commit()
+    if not was_100 and packet.is_100():
+        notify_slack(packet.freshman.name)
+
+    return "Success: Signed Packet: " + packet.freshman_username

packet/routes/api.py

@@ -45,6 +45,7 @@ def submit_essays(packet_id, info=None):
         packet.info_achieve = request.form.get("info_achieve", None)
 
         db.session.commit()
+        app.logger.info("Updated essays for {}".format(info["uid"]))
         return redirect(url_for("essays", packet_id=packet_id), 302)
     else:
         return redirect(url_for("index"), 302)

packet/routes/freshmen.py

@@ -7,6 +7,7 @@
 from packet import auth, app
 from packet.utils import before_request, packet_auth
 from packet.models import Packet
+from packet.log_utils import log_cache, log_time
 
 
 @app.route("/logout/")
@@ -16,8 +17,10 @@ def logout():
 
 
 @app.route("/packet/<packet_id>/")
+@log_cache
 @packet_auth
 @before_request
+@log_time
 def freshman_packet(packet_id, info=None):
     packet = Packet.by_id(packet_id)
 
@@ -43,8 +46,10 @@ def freshman_packet(packet_id, info=None):
 
 
 @app.route("/packets/")
+@log_cache
 @packet_auth
 @before_request
+@log_time
 def packets(info=None):
     open_packets = Packet.open_packets()
 

packet/routes/shared.py

@@ -9,6 +9,7 @@
 from packet import app
 from packet.models import Packet, MiscSignature
 from packet.utils import before_request, packet_auth
+from packet.log_utils import log_cache, log_time
 
 
 @app.route("/")
@@ -18,8 +19,10 @@ def index():
 
 
 @app.route("/member/<uid>/")
+@log_cache
 @packet_auth
 @before_request
+@log_time
 def upperclassman(uid, info=None):
     open_packets = Packet.open_packets()
 
@@ -37,8 +40,10 @@ def upperclassman(uid, info=None):
 
 
 @app.route("/upperclassmen/")
+@log_cache
 @packet_auth
 @before_request
+@log_time
 def upperclassmen_total(info=None):
     open_packets = Packet.open_packets()
 

packet/routes/upperclassmen.py

@@ -79,7 +79,9 @@ def packet_auth(func):
     @wraps(func)
     def wrapped_function(*args, **kwargs):
         if app.config["REALM"] == "csh":
-            if ldap_is_intromember(ldap_get_member(str(session["userinfo"].get("preferred_username", "")))):
+            username = str(session["userinfo"].get("preferred_username", ""))
+            if ldap_is_intromember(ldap_get_member(username)):
+                app.logger.warn("Stopped intro member {} from accessing upperclassmen packet".format(username))
                 return "Sorry, upperclassmen packet is not available to intro members.", 401
 
         return func(*args, **kwargs)
@@ -88,10 +90,12 @@ def wrapped_function(*args, **kwargs):
 
 def notify_slack(name: str):
     """
-    Sends a congratulate on sight decree to Slack.
+    Sends a congratulate on sight decree to Slack
     """
     if app.config["SLACK_WEBHOOK_URL"] is None:
-        print("SLACK_WEBHOOK_URL not configured, not sending message to slack.")
+        app.logger.warn("SLACK_WEBHOOK_URL not configured, not sending message to slack.")
         return
+
     msg = f'{name} got :100: on packet. Shower on sight.'
     requests.put(app.config["SLACK_WEBHOOK_URL"], json={'text':msg})
+    app.logger.info("Posted 100% notification to slack for " + name)