diff --git a/src/ladok3/cli.nw b/src/ladok3/cli.nw index 5329ea7..d2c9ecc 100644 --- a/src/ladok3/cli.nw +++ b/src/ladok3/cli.nw @@ -28,6 +28,7 @@ import getpass import json import keyring import ladok3 +import logging import os import pickle import re @@ -69,24 +70,25 @@ if __name__ == "__main__": We want uniform error handling. We will use the function [[err]] for errors and [[warn]] for warnings, both inspired by err(3) and warn(3) in the BSD world. +We use the [[logging]] module to output these messages. <>= def err(rc, msg): - """Print error message to stderr and exit with given return code. + """Log error message and exit with given return code. Args: rc (int): Return code to exit with. msg (str): Error message to display. """ - print(f"{sys.argv[0]}: error: {msg}", file=sys.stderr) + logging.error(msg) sys.exit(rc) def warn(msg): - """Print warning message to stderr. + """Log warning message. Args: msg (str): Warning message to display. """ - print(f"{sys.argv[0]}: {msg}", file=sys.stderr) + logging.warning(msg) @ @@ -115,6 +117,7 @@ subp = argp.add_subparsers( <> argcomplete.autocomplete(argp) args = argp.parse_args() +<> <> <> <> @@ -140,6 +143,48 @@ if "func" in args: @ +\section{Configure logging based on verbosity} + +We configure the logging module based on the verbosity level specified by the +user. +The user can increase verbosity with [[-v]] (which can be repeated) and +decrease it with [[-q]] (which can also be repeated). +We compute the net verbosity as [[verbose - quiet]]. + +The logging levels are: +\begin{description} +\item[CRITICAL (50)] Critical errors and application failures (net verbosity -2 or lower) +\item[ERROR (40)] Errors (net verbosity -1) +\item[WARNING (30)] Warnings (default, net verbosity 0) +\item[INFO (20)] Informational messages (net verbosity 1) +\item[DEBUG (10)] Debug messages (net verbosity 2 or higher) +\end{description} +<>= +verbosity = args.verbose - args.quiet +# Map verbosity to logging level: default is WARNING (30) +# -2 or less: CRITICAL, -1: ERROR, 0: WARNING, 1: INFO, 2+: DEBUG +if verbosity <= -2: + log_level = logging.CRITICAL +elif verbosity == -1: + log_level = logging.ERROR +elif verbosity == 0: + log_level = logging.WARNING +elif verbosity == 1: + log_level = logging.INFO +else: # verbosity >= 2 + log_level = logging.DEBUG + +# Only configure logging if not already configured +if not logging.getLogger().handlers: + logging.basicConfig( + level=log_level, + format='%(levelname)s: %(message)s', + stream=sys.stderr + ) +logging.debug(f"Logging configured to {logging.getLevelName(log_level)} level") +@ + + \section{Create the LadokSession~[[ls]]} We have several options for creating the LadokSession object~[[ls]] that must @@ -171,11 +216,14 @@ We use [[LADOK_VARS]] as credentials, since it contains the credentials. <>= LADOK_INST, LADOK_VARS = load_credentials(args.config_file) try: + logging.debug("Attempting to restore cached LADOK session") ls = restore_ladok_session(LADOK_VARS) <> if not ls: + logging.info(f"Creating new LADOK session for {LADOK_INST}") ls = ladok3.LadokSession(LADOK_INST, vars=LADOK_VARS) <>= +logging.debug("Storing LADOK session to cache") store_ladok_session(ls, LADOK_VARS) @ @@ -213,6 +261,7 @@ def store_ladok_session(ls, credentials): """ if not os.path.isdir(dirs.user_cache_dir): os.makedirs(dirs.user_cache_dir) + logging.debug(f"Created cache directory: {dirs.user_cache_dir}") file_path = dirs.user_cache_dir + "/LadokSession" @@ -221,6 +270,7 @@ def store_ladok_session(ls, credentials): with open(file_path, "wb") as file: file.write(encrypted_ls) + logging.debug(f"Saved encrypted session to {file_path}") def restore_ladok_session(credentials): """Restore a LadokSession object from disk. @@ -237,11 +287,15 @@ def restore_ladok_session(credentials): file_path = dirs.user_cache_dir + "/LadokSession" if os.path.isfile(file_path): + logging.debug(f"Found cached session at {file_path}") with open(file_path, "rb") as file: encrypted_ls = file.read() <> if pickled_ls: + logging.debug("Successfully restored session from cache") return pickle.loads(pickled_ls) + else: + logging.debug("No cached session found") return None @ @@ -311,12 +365,28 @@ We want to allow the user to specify different locations for the configuration. We want the user to be able to specify the location of the configuration file. + +\paragraph{Verbosity control} + +We also provide options to control the verbosity of diagnostic output. +The user can use [[-v]] to increase verbosity (can be repeated) and [[-q]] to +decrease verbosity (can also be repeated). +The net verbosity is calculated as [[verbose - quiet]], and this maps to +logging levels from [[CRITICAL]] to [[DEBUG]]. <>= argp.add_argument("-f", "--config-file", default=f"{dirs.user_config_dir}/config.json", help="Path to configuration file " f"(default: {dirs.user_config_dir}/config.json) " "or set LADOK_USER and LADOK_PASS environment variables.") +argp.add_argument("-v", "--verbose", + action="count", + default=0, + help="Increase verbosity (can be repeated, e.g., -vv for debug level)") +argp.add_argument("-q", "--quiet", + action="count", + default=0, + help="Decrease verbosity (can be repeated)") @ Since we provide the default value here, we can always rely on it to be available, so we can use [[args.config_file]] directly when we want to access the configuration file. @@ -576,6 +646,7 @@ try: "password": os.environ["LADOK_PASS"] } if institution and vars["username"] and vars["password"]: + logging.debug(f"Loaded credentials from environment for {institution}") return institution, vars except: pass @@ -599,6 +670,7 @@ try: <> if institution and vars: + logging.debug(f"Loaded credentials from LADOK_VARS for {institution}") return institution, vars except: pass @@ -622,6 +694,7 @@ try: institution = config.pop("institution", "KTH Royal Institute of Technology") + logging.debug(f"Loaded credentials from config file for {institution}") return institution, config except: pass @@ -643,6 +716,7 @@ try: vars[key] = value if institution and vars: + logging.debug(f"Loaded credentials from keyring for {institution}") return institution, vars except: pass @@ -656,6 +730,7 @@ try: username = keyring.get_password("ladok3", "username") password = keyring.get_password("ladok3", "password") if username and password: + logging.debug(f"Loaded credentials from keyring (legacy format) for {institution}") return institution, {"username": username, "password": password} except: pass diff --git a/src/ladok3/ladok3.nw b/src/ladok3/ladok3.nw index b67f888..ffc3ca2 100644 --- a/src/ladok3/ladok3.nw +++ b/src/ladok3/ladok3.nw @@ -13,6 +13,7 @@ import datetime import functools import html import json +import logging import operator import re import requests @@ -246,6 +247,43 @@ retry_strategy = Retry( adapter = HTTPAdapter(max_retries=retry_strategy) self.__session.mount("http://", adapter) self.__session.mount("https://", adapter) +self.__session = LoggingSessionWrapper(self.__session) +@ + +\subsection{Logging wrapper for API requests} + +To provide visibility into API requests and cache performance, we wrap the +session with a logging wrapper. +This wrapper logs all HTTP requests at DEBUG level and is transparent to the +rest of the code. + +The wrapper logs: +\begin{itemize} +\item HTTP method and URL for each request (DEBUG level) +\item Response status code and timing (DEBUG level) +\end{itemize} + +For cache hits and misses, we add logging to the cached methods themselves +(covered in their respective sections). +<>= +class LoggingSessionWrapper: + """Wrapper for requests.Session that logs API calls at DEBUG level""" + def __init__(self, session): + self._session = session + + def __getattr__(self, name): + """Delegate attribute access to wrapped session""" + attr = getattr(self._session, name) + # If it's a request method, wrap it with logging + if name in ['get', 'post', 'put', 'delete', 'patch', 'head', 'options']: + def logged_method(*args, **kwargs): + url = args[0] if args else kwargs.get('url', 'unknown') + logging.debug(f"LADOK API request: {name.upper()} {url}") + response = attr(*args, **kwargs) + logging.debug(f"LADOK API response: {response.status_code} from {name.upper()} {url}") + return response + return logged_method + return attr @ The [[mount]] method attaches the retry-enabled adapter to both HTTP and HTTPS @@ -643,6 +681,11 @@ We start with the method that returns the grading-scales objects. This method interacts with LADOK, so we want to cache its responses. We also want to be able to filter the responses, we do this by keyword arguments. + +We add INFO level logging for cache misses. +Note that cache hits cannot be logged from within the method itself, as the +[[cachetools.cachedmethod]] decorator returns the cached value before the +method body executes. <>= @cachetools.cachedmethod( operator.attrgetter("cache"), @@ -650,6 +693,7 @@ arguments. def get_grade_scales(self, /, **kwargs): """Return a list of (un)filtered grade scales""" if len(kwargs) == 0: + logging.info(f"Cache miss for grade scales, fetching from LADOK") return [GradeScale(**scale_data) for scale_data in self.grade_scales_JSON()] @@ -819,6 +863,9 @@ However, we an delegate this job to the [[Student]] class. def get_student(self, id): """Get a student by unique ID, returns a Student object""" # note that self is the required LadokSession object + # Only cache misses are logged; cache hits are handled by cachetools before + # this method body executes + logging.info(f"Cache miss for student {id}, fetching from LADOK") return Student(ladok=self, id=id) @ @@ -1187,6 +1234,9 @@ def search_course_rounds(self, /, **kwargs): """Query LADOK about course rounds, possible keys: code, round_code, name """ + # Only cache misses are logged; cache hits are handled by cachetools before + # this method body executes + logging.info(f"Cache miss for search_course_rounds({kwargs}), fetching from LADOK") results = self.search_course_rounds_JSON(**kwargs) return [CourseRound(ladok=self, **result) for result in results] @ diff --git a/src/ladok3/report.nw b/src/ladok3/report.nw index 03637e6..33af311 100644 --- a/src/ladok3/report.nw +++ b/src/ladok3/report.nw @@ -27,6 +27,7 @@ We need access to LADOK through the [[ladok3]] module. import csv import datetime import ladok3 +import logging import sys <> @@ -125,15 +126,9 @@ many_parser.add_argument("-d", "--delimiter", "use `-d,` or `-d ,` to get comma-separated values.") @ -We also want to handle errors and confirmations. -When reporting in bulk, we don't want unnecessary errors. We also want to have a summary of the changes. -<>= -many_parser.add_argument("-v", "--verbose", - action="count", default=0, - help="Increases the verbosity of the output: -v will print results that " - "were reported to standard out. Otherwise only errors are printed.") -@ +When reporting in bulk, successes are logged at INFO level, +so use the global [[-v]] flag (or [[-vv]] for debug level) to see them. Then we can actually report the result using the values read from [[stdin]]. <>= @@ -142,9 +137,8 @@ try: student_id, course_code, component_code, grade, date, graders) except Exception as err: <> - print(f"{course_code} {component_code}={grade} ({date}) {student}: " - f"{err}", - file=sys.stderr) + logging.error(f"{course_code} {component_code}={grade} ({date}) {student}: " + f"{err}") @ The reason we want to resolve the student from LADOK is that the [[student_id]] @@ -199,12 +193,13 @@ def set_grade(ladok, args, if not component.attested and component.grade != grade: <> component.set_grade(grade, date) + logging.debug(f"Set grade for course {course_code} component {component_code} to {grade} on {date}") if args.finalize: component.finalize(graders) - if args.verbose: - print(f"{course_code} {student}: reported " - f"{component.component} = {component.grade} ({date}) " - f"by {', '.join(graders)}.") + logging.debug(f"Finalized grade for course {course_code} component {component_code}") + logging.info(f"{course_code} {student}: reported " + f"{component.component} = {component.grade} ({date}) " + f"by {', '.join(graders)}.") elif component.grade != grade: raise ladok3.LadokValidationError(f"attested {component.component} " f"result {component.grade} ({component.date}) " @@ -235,11 +230,11 @@ if not isinstance(date, datetime.date): date = datetime.date.fromisoformat(date) if date < course.start: - print(f"{course_code} {component_code}={grade} " - f"({date}) {student}: " - f"Grade date ({date}) is before " - f"course start date ({course.start}), " - f"using course start date instead.") + logging.warning(f"{course_code} {component_code}={grade} " + f"({date}) {student}: " + f"Grade date ({date}) is before " + f"course start date ({course.start}), " + f"using course start date instead.") date = course.start @ @@ -275,10 +270,9 @@ we got the arguments. <>= if not (args.course_code and args.component_code and args.student_id and args.grade): - print(f"{sys.argv[0]} report: " - "not all positional args given: " - "course_code, component, student, grade", - file=sys.stderr) + logging.error("report: " + "not all positional args given: " + "course_code, component, student, grade") sys.exit(1) @ @@ -313,9 +307,8 @@ try: except Exception as err: student_id = args.student_id <> - print(f"{args.course_code} {args.component_code}={args.grade} ({args.date}) " - f"{student}: {err}", - file=sys.stderr) + logging.error(f"{args.course_code} {args.component_code}={args.grade} ({args.date}) " + f"{student}: {err}") @