Merge branch 'devel'

Author: ehrenfeu

CHANGELOG.md

@@ -4,6 +4,18 @@
 
 NOTE: potentially breaking changes are flagged with a 🧨 symbol.
 
+## 3.2.0
+
+### Added
+
+- `pyppms.booking.PpmsBooking.last_served_from_cache` has been added to indicate
+  if the last request was served from the cache or on-line.
+
+### Changed
+
+- Several log messages have been demoted to lower levels for further reducing
+  logging clutter.
+
 ## 3.1.0
 
 ### Added

src/pyppms/common.py

@@ -140,7 +140,7 @@ def parse_multiline_response(text, graceful=True):
     try:
         lines = text.splitlines()
         if len(lines) < 2:
-            log.info("Response has less than TWO lines: >>>{}<<<", text)
+            log.debug("Response has less than TWO lines: >>>{}<<<", text)
             if not graceful:
                 raise NoDataError("Invalid response format!")
             return []

src/pyppms/ppms.py

@@ -40,6 +40,8 @@ class PpmsConnection:
     cache_users_only : bool
         Flag indicating that only PPMS user details will be stored in the
         on-disk cache, nothing else.
+    last_served_from_cache
+        Indicates if the last request was served from the cache or on-line.
     users : dict
         A dict with usernames as keys, mapping to the related
         :py:class:`pyppms.user.PpmsUser` object, serves as a cache during the object's
@@ -108,6 +110,8 @@ def __init__(self, url, api_key, timeout=10, cache="", cache_users_only=False):
         }
         self.cache_path = cache
         self.cache_users_only = cache_users_only
+        self.last_served_from_cache = False
+        """Indicates if the last request was served from the cache or on-line."""
 
         # run in cache-only mode (e.g. for testing or off-line usage) if no API
         # key has been specified, skip authentication then:
@@ -126,7 +130,7 @@ def __authenticate(self):
         requests.exceptions.ConnectionError
             Raised in case authentication failed for any reason.
         """
-        log.debug(
+        log.trace(
             "Attempting authentication against {} with key [{}...{}]",
             self.url,
             self.api_key[:2],
@@ -167,7 +171,7 @@ def __authenticate(self):
             log.error(msg)
             raise requests.exceptions.ConnectionError(msg)
 
-        log.info(
+        log.debug(
             "Authentication succeeded, response=[{}], http_status=[{}]",
             response.text,
             response.status_code,
@@ -208,18 +212,18 @@ def request(self, action, parameters={}, skip_cache=False):
         # log.debug("Request parameters: {}", parameters)
 
         response = None
-        read_from_cache = False
         try:
             if skip_cache:  # pragma: no cover
                 raise LookupError("Skipping the cache has been requested")
             response = self.__intercept_read(req_data)
-            read_from_cache = True
+            self.last_served_from_cache = True
         except LookupError as err:
-            log.debug(f"Doing an on-line request: {err}")
+            log.trace(f"Doing an on-line request: {err}")
             response = requests.post(self.url, data=req_data, timeout=self.timeout)
+            self.last_served_from_cache = False
 
         # store the response if it hasn't been read from the cache before:
-        if not read_from_cache:  # pragma: no cover
+        if not self.last_served_from_cache:  # pragma: no cover
             self.__intercept_store(req_data, response)
 
         # NOTE: the HTTP status code returned is always `200` even if
@@ -390,7 +394,7 @@ def flush_cache(self, keep_users=False):
             will be kept, by default `False`.
         """
         if self.cache_path == "":
-            log.info("No cache path configured, not flushing!")
+            log.debug("No cache path configured, not flushing!")
             return
 
         dirs_to_remove = [self.cache_path]  # by default remove the entire cache dir
@@ -404,11 +408,11 @@ def flush_cache(self, keep_users=False):
                     continue
                 dirs_to_remove.append(os.path.join(self.cache_path, subdir))
 
-        log.info("Flushing the on-disk cache at [{}] {}...", self.cache_path, keep_msg)
+        log.debug("Flushing the on-disk cache at [{}] {}...", self.cache_path, keep_msg)
         for directory in dirs_to_remove:
             try:
                 shutil.rmtree(directory)
-                log.debug("Removed directory [{}].", directory)
+                log.trace("Removed directory [{}].", directory)
             except Exception as ex:  # pylint: disable-msg=broad-except
                 log.warning("Removing the cache at [{}] failed: {}", directory, ex)
 
@@ -427,7 +431,7 @@ def get_admins(self):
         for username in admins:
             user = self.get_user(username)
             users.append(user)
-        log.debug("{} admins in the PPMS database: {}", len(admins), ", ".join(admins))
+        log.trace("{} admins in the PPMS database: {}", len(admins), ", ".join(admins))
         return users
 
     def get_booking(self, system_id, booking_type="get"):
@@ -478,7 +482,7 @@ def get_booking(self, system_id, booking_type="get"):
         if booking_type == "get":
             desc = "a currently active booking"
         if not response.text.strip():
-            log.debug("System [{}] doesn't have {}", system_id, desc)
+            log.trace("System [{}] doesn't have {}", system_id, desc)
             return None
 
         return PpmsBooking(response.text, booking_type, system_id)
@@ -502,7 +506,7 @@ def get_group(self, group_id):
             line of the PUMAPI response, values from the data line.
         """
         response = self.request("getgroup", {"unitlogin": group_id})
-        log.debug("Group details returned by PPMS (raw): {}", response.text)
+        log.trace("Group details returned by PPMS (raw): {}", response.text)
 
         if not response.text:
             msg = f"Group [{group_id}] is unknown to PPMS"
@@ -511,7 +515,7 @@ def get_group(self, group_id):
 
         details = dict_from_single_response(response.text)
 
-        log.debug("Details of group {}: {}", group_id, details)
+        log.trace("Details of group {}: {}", group_id, details)
         return details
 
     def get_group_users(self, unitlogin):
@@ -534,7 +538,7 @@ def get_group_users(self, unitlogin):
         for username in members:
             user = self.get_user(username)
             users.append(user)
-        log.debug(
+        log.trace(
             "{} members in PPMS group [{}]: {}",
             len(members),
             unitlogin,
@@ -553,7 +557,7 @@ def get_groups(self):
         response = self.request("getgroups")
 
         groups = response.text.splitlines()
-        log.debug("{} groups in the PPMS database: {}", len(groups), ", ".join(groups))
+        log.trace("{} groups in the PPMS database: {}", len(groups), ", ".join(groups))
         return groups
 
     def get_next_booking(self, system_id):
@@ -593,17 +597,17 @@ def get_running_sheet(self, core_facility_ref, date, ignore_uncached_users=False
             "plateformid": f"{core_facility_ref}",
             "day": date.strftime("%Y-%m-%d"),
         }
-        log.debug("Requesting runningsheet for {}", parameters["day"])
+        log.trace("Requesting runningsheet for {}", parameters["day"])
         response = self.request("getrunningsheet", parameters)
         try:
             entries = parse_multiline_response(response.text, graceful=False)
         except NoDataError:
             # in case no bookings exist the response will be empty!
-            log.debug("Runningsheet for the given day was empty!")
+            log.trace("Runningsheet for the given day was empty!")
             return []
         except Exception as err:  # pylint: disable-msg=broad-except
             log.error("Parsing runningsheet details failed: {}", err)
-            log.debug("Runningsheet PUMPAI response was: >>>{}<<<", response.text)
+            log.trace("Runningsheet PUMPAI response was: >>>{}<<<", response.text)
             return []
 
         for entry in entries:
@@ -613,14 +617,14 @@ def get_running_sheet(self, core_facility_ref, date, ignore_uncached_users=False
                     log.debug("Ignoring booking for uncached user [{}]", full)
                     continue
 
-                log.info("Booking for an uncached user ({}) found!", full)
+                log.debug("Booking for an uncached user ({}) found!", full)
                 self.update_users()
 
             if full not in self.fullname_mapping:
                 log.error("PPMS doesn't seem to know user [{}], skipping", full)
                 continue
 
-            log.info(
+            log.trace(
                 "Booking for user '{}' ({}) found", self.fullname_mapping[full], full
             )
             system_name = entry["Object"]
@@ -659,7 +663,7 @@ def get_systems(self, force_refresh=False):
             fails for any reason, the system is skipped entirely.
         """
         if self.systems and not force_refresh:
-            log.debug("Using cached details for {} systems", len(self.systems))
+            log.trace("Using cached details for {} systems", len(self.systems))
         else:
             self.update_systems()
 
@@ -702,7 +706,7 @@ def get_systems_matching(self, localisation, name_contains):
         if localisation == "":
             loc_desc = "(no location filter given)"
 
-        log.info(
+        log.trace(
             "Querying PPMS for systems {}, name matching any of {}",
             loc_desc,
             name_contains,
@@ -719,7 +723,7 @@ def get_systems_matching(self, localisation, name_contains):
                 )
                 continue
 
-            # log.debug('System [{}] is matching location [{}], checking if '
+            # log.trace('System [{}] is matching location [{}], checking if '
             #           'the name is matching any of the valid pattern {}',
             #           system.name, loc, name_contains)
             for valid_name in name_contains:
@@ -729,11 +733,11 @@ def get_systems_matching(self, localisation, name_contains):
                     break
 
             # if sys_id not in system_ids:
-            #     log.debug('System [{}] does NOT match a valid name: {}',
+            #     log.trace('System [{}] does NOT match a valid name: {}',
             #               system.name, name_contains)
 
-        log.info("Found {} bookable systems {}", len(system_ids), loc_desc)
-        log.debug("IDs of matching bookable systems {}: {}", loc_desc, system_ids)
+        log.trace("Found {} bookable systems {}", len(system_ids), loc_desc)
+        log.trace("IDs of matching bookable systems {}: {}", loc_desc, system_ids)
         return system_ids
 
     def get_user(self, login_name, skip_cache=False):
@@ -826,7 +830,7 @@ def get_user_dict(self, login_name, skip_cache=False):
         #     u'true\r\n'
         # )
         details = dict_from_single_response(response.text)
-        log.debug("Details for user [{}]: {}", login_name, details)
+        log.trace("Details for user [{}]: {}", login_name, details)
         return details
 
     def get_user_experience(self, login=None, system_id=None):
@@ -854,7 +858,7 @@ def get_user_experience(self, login=None, system_id=None):
         response = self.request("getuserexp", parameters=data)
 
         parsed = parse_multiline_response(response.text)
-        log.debug(
+        log.trace(
             "Received {} experience entries for filters [user:{}] and [id:{}]",
             len(parsed),
             login,
@@ -886,8 +890,8 @@ def get_user_ids(self, active=False):
 
         users = response.text.splitlines()
         active_desc = "active " if active else ""
-        log.info("{} {}users in the PPMS database", len(users), active_desc)
-        log.debug(", ".join(users))
+        log.trace("{} {}users in the PPMS database", len(users), active_desc)
+        log.trace(", ".join(users))
         return users
 
     def get_users(self, force_refresh=False, active_only=True):
@@ -908,7 +912,7 @@ def get_users(self, force_refresh=False, active_only=True):
             A dict of PpmsUser objects with the username (login) as key.
         """
         if self.users and not force_refresh:
-            log.debug("Using cached details for {} users", len(self.users))
+            log.trace("Using cached details for {} users", len(self.users))
         else:
             self.update_users(active_only=active_only)
 
@@ -939,7 +943,7 @@ def get_users_emails(self, users=None, active=False):
             if not email:
                 log.warning("--- WARNING: no email for user [{}]! ---", user)
                 continue
-            # log.debug("{}: {}", user, email)
+            # log.trace("{}: {}", user, email)
             emails.append(email)
 
         return emails
@@ -972,14 +976,14 @@ def get_users_with_access_to_system(self, system_id):
             for line in lines:
                 permission, username = line.split(":")
                 if permission.upper() == "D":
-                    log.debug(
+                    log.trace(
                         "User [{}] is deactivated for booking system [{}], skipping",
                         username,
                         system_id,
                     )
                     continue
 
-                log.debug(
+                log.trace(
                     "User [{}] has permission to book system [{}]", username, system_id
                 )
                 users.append(username)
@@ -1068,8 +1072,8 @@ def new_user(  # pylint: disable-msg=too-many-arguments
             log.error(msg)
             raise RuntimeError(msg)
 
-        log.info("Created user [{}] in PPMS.", login)
-        log.debug("Response was: {}", response.text)
+        log.debug("Created user [{}] in PPMS.", login)
+        log.trace("Response was: {}", response.text)
 
     def remove_user_access_from_system(self, username, system_id):
         """Remove permissions for a user to book a given system in PPMS.
@@ -1156,9 +1160,9 @@ def permission_name(shortname):
         # NOTE: the 'setright' action will accept ANY permission type and return 'done'
         # on the request, so there is no way to check from the response if setting the
         # permission really worked!!
-        # log.debug('Request returned text: {}', response.text)
+        # log.trace('Request returned text: {}', response.text)
         if response.text.lower().strip() == "done":
-            log.debug(
+            log.trace(
                 "User [{}] now has permission level [{}] on system [{}]",
                 login,
                 permission_name(permission),
@@ -1184,7 +1188,7 @@ def update_systems(self):
         cache. If parsing the PUMAPI response for a system fails for any reason, the
         system is skipped entirely.
         """
-        log.debug("Updating list of bookable systems...")
+        log.trace("Updating list of bookable systems...")
         systems = {}
         parse_fails = 0
         response = self.request("getsystems")
@@ -1199,7 +1203,7 @@ def update_systems(self):
 
             systems[system.system_id] = system
 
-        log.debug(
+        log.trace(
             "Updated {} bookable systems from PPMS ({} systems failed parsing)",
             len(systems),
             parse_fails,
@@ -1228,7 +1232,7 @@ def update_users(self, user_ids=[], active_only=True):
         if not user_ids:
             user_ids = self.get_user_ids(active=active_only)
 
-        log.debug("Updating details on {} users", len(user_ids))
+        log.trace("Updating details on {} users", len(user_ids))
         for user_id in user_ids:
             self.get_user(user_id, skip_cache=True)