diff --git a/app/__init__.py b/app/__init__.py index ac7893a..c7b74ac 100644 --- a/app/__init__.py +++ b/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 diff --git a/app/routes.py b/app/routes.py index 36606ea..f542c02 100644 --- a/app/routes.py +++ b/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): - print(str(deck) + " | " + str(deck.export_file)) - + # Use current_app.logger for debug info + 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( @@ -247,10 +255,13 @@ def process_access_code(access_code: str): if password is not None: if not password.is_expired(): - update_token(password.decks) + 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///') @main.route('/slides///') 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: + + 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, Deck) + assert isinstance(deck_obj, Deck) - if not is_deck_unlocked(deck.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: + + 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, Deck) + assert isinstance(deck_obj, Deck) - if not is_deck_unlocked(deck.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//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') diff --git a/app/utils.py b/app/utils.py index a266c9c..f82d9ce 100644 --- a/app/utils.py +++ b/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) - 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 + 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') - if not token: + token_cookie = request.cookies.get('access_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()