Add verbosity control with -v/-q flags and logging integration

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.
 <<functions>>=
 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(
 <<add subparsers to subp>>
 argcomplete.autocomplete(argp)
 args = argp.parse_args()
+<<configure logging based on verbosity>>
 <<create or restore the LadokSession ls>>
 <<execute subcommand>>
 <<save LadokSession ls>>
@@ -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}
+<<configure logging based on verbosity>>=
+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.
 <<create or restore the LadokSession ls>>=
 LADOK_INST, LADOK_VARS = load_credentials(args.config_file)
 try:
+  logging.debug("Attempting to restore cached LADOK session")
   ls = restore_ladok_session(LADOK_VARS)
 <<handle exceptions during restore of [[ls]]>>
 if not ls:
+  logging.info(f"Creating new LADOK session for {LADOK_INST}")
   ls = ladok3.LadokSession(LADOK_INST, vars=LADOK_VARS)
 <<save LadokSession ls>>=
+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()
       <<decrypt encrypted ls>>
       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]].
 <<add global configuration options>>=
 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:
       <<print warning about missing variable in [[LADOK_VARS]]>>
 
   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

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).
+<<classes>>=
+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,13 +681,19 @@ 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.
 <<LadokSession data methods>>=
 @cachetools.cachedmethod(
   operator.attrgetter("cache"),
   key=functools.partial(cachetools.keys.hashkey, "grade_scale"))
 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]
 @