WIP

app/__init__.py

@@ -1,3 +1,4 @@
+from logging.config import dictConfig
 from flask import Flask
 from flask_socketio import SocketIO
 from .models import db
@@ -8,6 +9,60 @@ from .seed_db import seed_courses
 socketio = SocketIO(async_mode='eventlet', cors_allowed_origins="*")
 
 def create_app():
+    # Configure logging BEFORE creating the application object
+    dictConfig({
+        'version': 1,
+        'disable_existing_loggers': False,
+        'formatters': {
+            'default': {
+                'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s',
+            },
+            'plain': {
+                'format': '%(message)s',
+            }
+        },
+        'handlers': {
+            # Console handler (keeps logs visible in terminal)
+            'wsgi': {
+                'class': 'logging.StreamHandler',
+                'stream': 'ext://flask.logging.wsgi_errors_stream',
+                'formatter': 'default'
+            },
+            # File handler for Application Logs (slides.log)
+            'slides_file': {
+                'class': 'logging.handlers.RotatingFileHandler',
+                'filename': 'slides.log',
+                'maxBytes': 1024 * 1024 * 10,  # 10 MB
+                'backupCount': 5,
+                'formatter': 'default',
+                'level': 'INFO',
+                'encoding': 'utf8'
+            },
+            # File handler for Request Logs (requests.log)
+            'requests_file': {
+                'class': 'logging.handlers.RotatingFileHandler',
+                'filename': 'requests.log',
+                'maxBytes': 1024 * 1024 * 10,  # 10 MB
+                'backupCount': 5,
+                'formatter': 'plain', # Requests already have timestamps/formatting
+                'level': 'INFO',
+                'encoding': 'utf8'
+            }
+        },
+        'root': {
+            'level': 'INFO',
+            'handlers': ['wsgi', 'slides_file']
+        },
+        'loggers': {
+            # Isolate the Werkzeug request logger
+            'werkzeug': {
+                'level': 'INFO',
+                'handlers': ['wsgi', 'requests_file'],
+                'propagate': False # Prevent requests from leaking into slides.log
+            }
+        }
+    })
+
     app = Flask(__name__, static_folder='static', static_url_path='/static')
     app.config.from_object('config.Config')
     db.init_app(app)
@@ -20,7 +75,6 @@ def create_app():
     init_serializer(app)
     init_auth(app)
 
-
     socketio.init_app(app)
 
     from .routes import main

app/routes.py

@@ -10,7 +10,7 @@ import pytz
 from flask import (
     Blueprint,
     abort,
-    current_app,
+    current_app, # Used for logging
     flash,
     make_response,
     redirect,
@@ -51,6 +51,7 @@ slidev_all_pattern = re.compile(r"^\/slides\/([^\/]+)\/([^\/]+)(?:\/presenter)?\
 def on_connect():
     if flask_login.current_user.is_authenticated:
         join_room("instructor")
+        current_app.logger.info(f"Instructor connected to socket: {flask_login.current_user.id}")
 
 @main.after_request
 def inject_confused_button(response):
@@ -101,9 +102,8 @@ def index():
     if not token:
         return redirect(url_for("main.set_token")) 
     else:
-        for deck in get_unlocked_decks(token):
+        # Use current_app.logger for debug info
-            print(str(deck) + " | " + str(deck.export_file))
+        current_app.logger.debug(f"User {token.name} is viewing index with {len(token.decks)} decks unlocked.")
-
         return render_template('index.html', active_banner=get_active_banner(), decks=get_unlocked_decks(token), user_name=token.name, active_course_name=token.active_course.name, courses=get_all_courses())
 
 def set_cookie(token):
@@ -141,10 +141,10 @@ def set_token():
         
         if not token:
             flash(f'The username "{user_name}" does not exist.', 'error')
+            current_app.logger.warning(f"Login failed: Username '{user_name}' not found.")
             return render_template('set_token.html')
 
-        print(f"Set token {session}")
+        current_app.logger.info(f"User logged in: {user_name}")
-
         return set_cookie(token)
 
     return render_template('set_token.html')
@@ -177,7 +177,7 @@ def register():
 
         # If all validation passes, "register" the user
         token = create_token(user_name) 
-        print(f"User registered: {user_name}")
+        current_app.logger.info(f"New user registered: {user_name}")
 
         return set_cookie(token)
 
@@ -186,6 +186,10 @@ def register():
 
 @main.route('/logout', methods=['POST'])
 def logout():
+    token = get_token()
+    user_name = token.name if token else "Unknown"
+    current_app.logger.info(f"User logout: {user_name}")
+    
     resp = make_response(redirect(url_for('main.index'))) # Redirect to a safe page, e.g., index or login
     resp.set_cookie('access_token', '', expires=0) # Clears the cookie
     return resp
@@ -202,6 +206,9 @@ def switch_course(new_course: int):
     if switched:
         token.active_course = switched 
         db.session.commit()
+        current_app.logger.info(f"User {token.name} switched to course: {switched.name}")
+    else:
+        current_app.logger.warning(f"User {token.name} attempted to switch to invalid course ID: {new_course}")
 
     return redirect(url_for("main.index"))
 
@@ -217,6 +224,7 @@ def admin_login():
         user = user_loader(user_name)
         if user and check_password(user, password):
             flask_login.login_user(user)
+            current_app.logger.info(f"Admin login successful: {user_name}")
             next = request.args.get('next')
             if next is None:
                 return redirect(url_for('main.index'))
@@ -226,18 +234,18 @@ def admin_login():
 
             return redirect(next)
         else:
+            current_app.logger.warning(f"Failed admin login attempt: {user_name}")
             flash('Incorrect username or password. Please try again.', 'error')
     return render_template("admin_login.html", form=form)
 
 
 def process_access_code(access_code: str):
     token = get_token() 
-    print(f"Process {token}")
 
     if not token:
         # remember where the user wanted to go
         session['next_url'] = url_for('main.access_get', access_code=access_code)
-        print(f"Process {session}")
+        current_app.logger.debug("Access code used without session. Redirecting to login.")
         return redirect(url_for('main.set_token'))
 
     password = db.session.execute(
@@ -248,9 +256,12 @@ def process_access_code(access_code: str):
     if password is not None:
         if not password.is_expired():
             update_token(password.decks)
+            current_app.logger.info(f"User {token.name} used valid access code.")
         else:
+            current_app.logger.info(f"User {token.name} used expired access code.")
             flash('Password has expired. Please obtain a new one.', 'expired')
     else:
+        current_app.logger.warning(f"User {token.name} used invalid access code: {access_code}")
         flash('Password is not valid. Please check the code and try again.', 'error')    
     return redirect(url_for('main.index'))
 
@@ -271,6 +282,10 @@ def access_get(access_code: str):
 
 @main.route('/confused', methods=['POST'])
 def confused():
+    token = get_token()
+    user = token.name if token else "Anonymous"
+    current_app.logger.info(f"Confused button clicked by: {user}")
+    
     socketio.emit(
         "confused",
         {
@@ -280,34 +295,52 @@ def confused():
     )
     return ("", 204)
 
+def log_404(reason: str, deck: str, course: str, path: str):
+    """
+    Helper function to log 404 errors with the user's identity.
+    Uses current_app.logger to ensure logs are handled by the app's config.
+    """
+    token = get_token()
+    user_identity = f"User: {token.name} (ID: {token.id})" if token else "User: Anonymous"
+    current_app.logger.warning(f"404 Not Found [{reason}] | {user_identity} | Resource: {course}/{deck}/{path}")
+
 @main.route('/slides/<course_folder>/<deck>/')
 @main.route('/slides/<course_folder>/<deck>/<path:path>')
 def serve_deck(deck, course_folder, path='index.html'):
     course = db.session.execute(db.select(Course).where(Course.folder==course_folder)).scalar()
+    
     if not course:
+        log_404("Course not found", deck, course_folder, path)
         abort(404)
     assert isinstance(course, Course)
-    deck = db.session.execute(db.select(Deck).where(Deck.deck==deck and Deck.course_id == course.id)).scalar()
-    if not deck:
-        abort(404)
-    assert isinstance(deck, Deck)
     
-    if not is_deck_unlocked(deck.deck):
+    deck_obj = db.session.execute(db.select(Deck).where(Deck.deck==deck and Deck.course_id == course.id)).scalar()
+    if not deck_obj:
+        log_404("Deck not in database", deck, course_folder, path)
+        abort(404)
+    assert isinstance(deck_obj, Deck)
+
+    if not is_deck_unlocked(deck_obj.deck):
+        # We generally do not log redirects for locked content as 404s, 
+        # but you could log a warning here if desired.
+        current_app.logger.info(f"Access denied (locked) for user {get_token().name if get_token() else 'Anon'} -> {deck}")
         return redirect(url_for('main.index'))
 
     slides_dir = os.path.join(current_app.config['SLIDES_DIR'], course.folder)
-    deck_path = os.path.join(slides_dir, deck.deck)
+    deck_path = os.path.join(slides_dir, deck_obj.deck)
 
     if not os.path.exists(deck_path):
+        log_404("Deck directory missing on disk", deck, course_folder, path)
         return f"Deck '{deck}' not found.", 404
 
     if slidev_all_pattern.match(request.path):
-        return send_from_directory(deck_path, deck.index_file)
+        return send_from_directory(deck_path, deck_obj.index_file)
 
     requested_file = os.path.join(deck_path, path)
     if os.path.isfile(requested_file):
         return send_from_directory(deck_path, path)
 
+    log_404("File missing within deck", deck, course_folder, path)
     abort(404)
 
 
@@ -315,20 +348,26 @@ def serve_deck(deck, course_folder, path='index.html'):
 def serve_export(deck, course_folder, path):
     course = db.session.execute(db.select(Course).where(Course.folder==course_folder)).scalar()
     if not course:
+        log_404("Export: Course not found", deck, course_folder, path)
         abort(404)
     assert isinstance(course, Course)
-    deck = db.session.execute(db.select(Deck).where(Deck.deck==deck and Deck.course_id == course.id)).scalar()
-    if not deck:
-        abort(404)
-    assert isinstance(deck, Deck)
     
-    if not is_deck_unlocked(deck.deck):
+    deck_obj = db.session.execute(db.select(Deck).where(Deck.deck==deck and Deck.course_id == course.id)).scalar()
+    if not deck_obj:
+        log_404("Export: Deck not in database", deck, course_folder, path)
+        abort(404)
+    assert isinstance(deck_obj, Deck)
+
+    if not is_deck_unlocked(deck_obj.deck):
         return redirect(url_for('main.index'))
+    
     exports_dir = os.path.join(current_app.config['EXPORTS_DIR'], course.folder)
-    deck_path = os.path.join(exports_dir, deck.deck)
+    deck_path = os.path.join(exports_dir, deck_obj.deck)
     requested_file = os.path.join(deck_path, path)
     if os.path.isfile(requested_file):
         return send_from_directory(deck_path, path)
+    
+    log_404("Export file missing", deck, course_folder, path)
     abort(404)
 
 
@@ -337,6 +376,7 @@ def serve_export(deck, course_folder, path):
 def admin():
     active_course = get_course(flask_login.current_user.active_course_id)
     if active_course is None:
+        current_app.logger.error(f"Admin user {flask_login.current_user.id} has invalid active_course_id.")
         raise Exception
     deck_form = DeckForm()
     password_form = PasswordForm()
@@ -357,6 +397,7 @@ def admin():
             )
             db.session.add(deck)
             db.session.commit()
+            current_app.logger.info(f"Admin created deck: {deck.name}")
 
         if "submit_password" in request.form:
             if password_form.validate():
@@ -374,11 +415,12 @@ def admin():
                 password.decks.extend(decks)
                 db.session.add(password)
                 db.session.commit()
+                current_app.logger.info(f"Admin created password: {value} (Expires: {expires_at})")
             else:
                 # Form was submitted but validation failed
                 for field, errors in password_form.errors.items():
                     for error in errors:
-                        print(f"Error in {getattr(password_form, field).label.text}: {error}", flush=True)
+                        current_app.logger.warning(f"Admin form validation error ({field}): {error}")
         return redirect(url_for('main.admin'))
 
     return render_template("admin.html", deck_form=deck_form, password_form=password_form, decks=decks, passwords=get_passwords(active_course), courses=get_all_courses(), active_course_name=active_course.name)
@@ -389,6 +431,7 @@ def switch_course_admin(new_course: int):
     user = flask_login.current_user
     if get_course(new_course):
         user.active_course_id = new_course
+        current_app.logger.info(f"Admin {user.id} switched to course ID {new_course}")
     return redirect(url_for("main.admin"))
 
 @main.route('/admin/banner', methods=['POST', 'GET'])
@@ -401,12 +444,14 @@ def banner():
         banner = InfoBanner(content=content)
         db.session.add(banner)
         db.session.commit()
+        current_app.logger.info(f"Admin added banner: {content[:30]}...")
     return render_template("banner.html", banner_form=banner_form, banners=db.session.execute(db.select(InfoBanner)).scalars())
 
 @main.route('/admin/decks/<int:deck_id>/delete', methods=['POST'])
 @flask_login.login_required
 def delete_deck(deck_id: int):
     deck = Deck.query.get_or_404(deck_id)
+    current_app.logger.info(f"Admin deleted deck: {deck.name}")
     db.session.delete(deck)
     db.session.commit()
     return redirect(url_for('main.admin'))
@@ -415,6 +460,7 @@ def delete_deck(deck_id: int):
 @flask_login.login_required
 def delete_password(password_id: int):
     password = Password.query.get_or_404(password_id)
+    current_app.logger.info(f"Admin deleted password ID {password_id}")
     db.session.delete(password)
     db.session.commit()
     return redirect(url_for('main.admin'))
@@ -430,6 +476,7 @@ def set_active_banner(banner_id):
             active_banner.is_active = False
         banner.is_active = True
         db.session.commit()
+        current_app.logger.info(f"Admin activated banner ID {banner_id}")
     return redirect(url_for('main.banner'))
 
 @main.route('/admin/banner/hide', methods=['POST'])
@@ -439,6 +486,7 @@ def hide_active_banner():
     if banner:
         banner.is_active = False
         db.session.commit()
+        current_app.logger.info("Admin hid active banner")
     return redirect(url_for('main.banner'))
 
 @main.route('/admin/confused')

app/utils.py

@@ -1,4 +1,5 @@
 import os
+import logging
 
 from flask import Flask, request, session
 from typing import cast
@@ -7,10 +8,14 @@ from xkcdpass import xkcd_password
 
 from .models import Deck, InfoBanner, Token, db, Course
 
+# Create a module-level logger per Flask/Python standards
+logger = logging.getLogger(__name__)
+
 def init_password_generator():
     wordfile = xkcd_password.locate_wordfile()
     global words
     words = xkcd_password.generate_wordlist(wordfile=wordfile, min_length=3, max_length=6)
+    logger.info("Password generator initialized.")
 
 def init_serializer(app: Flask):
     global serializer
@@ -21,9 +26,14 @@ def get_active_banner() -> InfoBanner | None:
 
 def get_available_decks(app: Flask, course: Course):
     slides_dir = os.path.join(app.config['SLIDES_DIR'], course.folder)
+    try:
         deck_names = [name for name in os.listdir(slides_dir) if os.path.isdir(os.path.join(slides_dir, name))]
         deck_names.sort()
         return deck_names
+    except FileNotFoundError:
+        # Log this error as it indicates a configuration or filesystem issue
+        logger.error(f"Slides directory not found for course {course.folder}: {slides_dir}")
+        return []
 
 def generate_username() -> str:
     return cast(str, xkcd_password.generate_xkcdpassword(wordlist=words, numwords=3, delimiter="-"))
@@ -42,6 +52,8 @@ def generate_token() -> Token:
         if not db.session.execute(db.select(Token).where(Token.name == user_name)).scalar():
             break
     else:
+        # Critical error: Application cannot register new users
+        logger.critical(f"Failed to generate unique username after {max_tries} tries.")
         raise RuntimeError(f"Unique username could not be generated after {max_tries} tries")
     return create_token(user_name)
 
@@ -49,20 +61,23 @@ def create_token(user_name : str) -> Token:
     token = Token(user_name)
     db.session.add(token)
     db.session.commit()
+    logger.info(f"Created new token for user: {user_name}")
     return token
 
 def serialize_token(token: Token) -> str:
     return serializer.dumps(token.id)
 
 def get_token() -> (Token | None):
-    token = request.cookies.get('access_token')
+    token_cookie = request.cookies.get('access_token')
-    if not token:
+    if not token_cookie:
         return None
     try:
-        id = serializer.loads(token)
+        id = serializer.loads(token_cookie)
         token = db.session.get(Token, id)
         return token 
     except BadSignature:
+        # Warning: Client sent a tampered or invalid cookie
+        logger.warning("Invalid signature for token cookie encountered.")
         return None
 
 def retrieve_token(username : str):
@@ -77,7 +92,6 @@ def get_unlocked_decks(token: (Token|None)):
  
 def is_deck_unlocked(deck: str):
     token = get_token() 
-    print(token)
     if token:
         return token.is_unlocked(deck)
     else:
@@ -89,8 +103,11 @@ def update_token(decks: list[Deck]):
     """
     token = get_token()
     if token is None:
+        logger.error("Attempted to update token decks, but token is None.")
         raise ValueError("Invalid token is set")
     else:
+        # Log the update action
+        logger.info(f"Updating decks for user {token.name}. Adding {len(decks)} decks.")
         token.decks = list(set(decks + token.decks))
     db.session.commit()