From 7cd04317206143d8ff99c160921346b52a96834d Mon Sep 17 00:00:00 2001 From: ping Date: Tue, 12 Sep 2023 15:27:24 +0800 Subject: [PATCH] Don't pre-format log messages --- calibre-plugin/config.py | 2 +- calibre-plugin/hold_actions.py | 9 ++-- calibre-plugin/libby/client.py | 59 +++++++++------------- calibre-plugin/loan_actions.py | 6 +-- calibre-plugin/magazine_download.py | 23 ++++----- calibre-plugin/overdrive/client.py | 41 ++++++---------- calibre-plugin/workers.py | 76 +++++++++++++---------------- 7 files changed, 89 insertions(+), 127 deletions(-) diff --git a/calibre-plugin/config.py b/calibre-plugin/config.py index fffc211..bd427f1 100644 --- a/calibre-plugin/config.py +++ b/calibre-plugin/config.py @@ -965,4 +965,4 @@ def save_settings(self): try: self.plugin_action.apply_settings() except Exception as err: - logger.warning(f"Error applying settings: {err}") + logger.warning(f"Error applying settings: %s", err) diff --git a/calibre-plugin/hold_actions.py b/calibre-plugin/hold_actions.py index e495b2b..e95d6c7 100644 --- a/calibre-plugin/hold_actions.py +++ b/calibre-plugin/hold_actions.py @@ -30,10 +30,9 @@ def __call__( abort=None, notifications=None, ): - logger = log notifications.put((0.5, _("Cancelling"))) libby_client.cancel_hold(hold) - logger.info("Cancelled hold for %s successfully." % get_media_title(hold)) + log.info("Cancelled hold for %s successfully." % get_media_title(hold)) return hold @@ -48,10 +47,9 @@ def __call__( abort=None, notifications=None, ): - logger = log notifications.put((0.5, _("Updating hold"))) hold = libby_client.suspend_hold(hold, days_to_suspend) - logger.info("Updated hold for %s successfully." % get_media_title(hold)) + log.info("Updated hold for %s successfully." % get_media_title(hold)) return hold @@ -66,10 +64,9 @@ def __call__( abort=None, notifications=None, ): - logger = log notifications.put((0.5, _("Creating hold"))) hold = libby_client.create_hold(media["id"], card["cardId"]) - logger.info( + log.info( "Created hold for %s at %s successfully." % (get_media_title(hold), card["advantageKey"]) ) diff --git a/calibre-plugin/libby/client.py b/calibre-plugin/libby/client.py index 6b009b4..3150f13 100644 --- a/calibre-plugin/libby/client.py +++ b/calibre-plugin/libby/client.py @@ -419,13 +419,13 @@ def _read_response(self, response, decode: bool = True) -> Union[bytes, str]: if "identity" in res_obj: res_obj["identity"] = "*" * int(len(res_obj["identity"]) / 10) self.logger.debug( - "RES BODY: {0:s}".format(json.dumps(res_obj, separators=(",", ":"))) + "RES BODY: %s", json.dumps(res_obj, separators=(",", ":")) ) except: # noqa # do nothing pass else: - self.logger.debug("RES BODY: {0:s}".format(decoded_res)) + self.logger.debug("RES BODY: %s", decoded_res) return decoded_res def send_request( @@ -495,41 +495,35 @@ def send_request( for attempt in range(0, self.max_retries + 1): try: - self.logger.debug( - "REQUEST: {0!s} {1!s}".format(req.get_method(), endpoint_url) - ) + self.logger.debug("REQUEST: %s %s", req.get_method(), endpoint_url) bearer_token = req.headers.get("Authorization", "") if _scrub_sensitive_data and bearer_token: bearer_token = bearer_token[: len("Bearer ")] + "*" * int( len(bearer_token[len("Bearer ") :]) / 10 ) self.logger.debug( - "REQ HEADERS: \n{0!s}".format( - "\n".join( - [ - "{}: {}".format( - k, v if k != "Authorization" else bearer_token - ) - for k, v in req.headers.items() - ] - ) - ) + "REQ HEADERS: \n%s", + "\n".join( + [ + "{}: {}".format( + k, v if k != "Authorization" else bearer_token + ) + for k, v in req.headers.items() + ] + ), ) if data: - self.logger.debug("REQ BODY: \n{0!s}".format(data)) + self.logger.debug("REQ BODY: \n%s", data) req_opener = self.opener if not no_redirect else self.opener_noredirect response = req_opener.open(req, timeout=self.timeout) except HTTPError as e: if e.code in (301, 302) and no_redirect: response = e else: - self.logger.debug("RESPONSE: {0:d} {1:s}".format(e.code, e.url)) + self.logger.debug("RESPONSE: %d %s", e.code, e.url) self.logger.debug( - "RES HEADERS: \n{0!s}".format( - "\n".join( - ["{}: {}".format(k, v) for k, v in e.info().items()] - ) - ) + "RES HEADERS: \n%s", + "\n".join(["{}: {}".format(k, v) for k, v in e.info().items()]), ) error_response = self._read_response(e) if ( @@ -537,9 +531,7 @@ def send_request( ): # retry for server 5XX errors # do nothing, try self.logger.warning( - "Retrying due to {}: {}".format( - e.__class__.__name__, str(e) - ) + "Retrying due to %s: %s", e.__class__.__name__, str(e) ) self.logger.debug(error_response) continue @@ -555,9 +547,9 @@ def send_request( ) as connection_error: if attempt < self.max_retries: self.logger.warning( - "Retrying due to {}: {}".format( - connection_error.__class__.__name__, str(connection_error) - ) + "Retrying due to %s: %s", + connection_error.__class__.__name__, + str(connection_error), ) # do nothing, try continue @@ -567,15 +559,10 @@ def send_request( ) ) from connection_error + self.logger.debug("RESPONSE: %d %s", response.code, response.url) self.logger.debug( - "RESPONSE: {0:d} {1:s}".format(response.code, response.url) - ) - self.logger.debug( - "RES HEADERS: \n{0!s}".format( - "\n".join( - ["{}: {}".format(k, v) for k, v in response.info().items()] - ) - ) + "RES HEADERS: \n%s", + "\n".join(["{}: {}".format(k, v) for k, v in response.info().items()]), ) if return_response: return response diff --git a/calibre-plugin/loan_actions.py b/calibre-plugin/loan_actions.py index a361aaf..7ef4680 100644 --- a/calibre-plugin/loan_actions.py +++ b/calibre-plugin/loan_actions.py @@ -30,10 +30,9 @@ def __call__( abort=None, notifications=None, ): - logger = log notifications.put((0.5, _("Returning"))) libby_client.return_loan(loan) - logger.info("Returned %s successfully." % get_media_title(loan)) + log.info("Returned %s successfully." % get_media_title(loan)) return loan @@ -47,8 +46,7 @@ def __call__( abort=None, notifications=None, ): - logger = log notifications.put((0.5, _("Renewing"))) new_loan = libby_client.renew_loan(loan) - logger.info("Renewed %s successfully." % get_media_title(loan)) + log.info("Renewed %s successfully." % get_media_title(loan)) return new_loan diff --git a/calibre-plugin/magazine_download.py b/calibre-plugin/magazine_download.py index 571a2c6..b789b7a 100644 --- a/calibre-plugin/magazine_download.py +++ b/calibre-plugin/magazine_download.py @@ -454,7 +454,6 @@ def _custom_download( abort=None, notifications=None, ) -> Path: - logger = log download_progress_fraction = 0.97 meta_progress_fraction = 1.0 - download_progress_fraction meta_tasks = 3 @@ -517,7 +516,7 @@ def _custom_download( and OverDriveClient.extract_type(loan) == LibbyMediaTypes.Magazine ): msg = _("Magazine has unsupported fixed-layout (pre-paginated) format.") - logger.error(msg) + log.error(msg) raise UnsupportedException(msg, media_info) # for finding cover image for magazines @@ -585,17 +584,17 @@ def _custom_download( for i, entry in enumerate(title_content_entries, start=1): if abort.is_set(): msg = "Abort signal received." - logger.info(msg) + log.info(msg) raise RuntimeError(msg) entry_url = entry["url"] parsed_entry_url = urlparse(entry_url) title_content_path = Path(parsed_entry_url.path[1:]) - logger.info( + log.info( "Proccesing %d/%d : %s" % (i, total_downloads, title_content_path.name) ) media_type = guess_mimetype(title_content_path.name) if not media_type: - logger.warning("Skipped roster entry: %s" % title_content_path.name) + log.warning("Skipped roster entry: %s" % title_content_path.name) continue asset_folder = book_content_folder.joinpath(title_content_path.parent) if media_type == "application/x-dtbncx+xml": @@ -671,9 +670,7 @@ def _custom_download( if not asset_font_path.exists(): css_content = css_content.replace(src_match, "") except Exception as patch_err: - logger.warning( - "Error while patching font sources: %s" % patch_err - ) + log.warning("Error while patching font sources: %s" % patch_err) with open(asset_file_path, "w", encoding="utf-8") as f_out: f_out.write(css_content) elif media_type in ("application/xhtml+xml", "text/html"): @@ -682,7 +679,7 @@ def _custom_download( if script_ele and hasattr(script_ele, "string"): mobj = contents_re.search(script_ele.string or "") if not mobj: - logger.warning( + log.warning( "Unable to extract content string for %s" % parsed_entry_url.path, ) @@ -863,7 +860,7 @@ def _custom_download( and meta_id.get("content") and meta_id["content"] != expected_book_identifier ): - logger.debug( + log.debug( 'Replacing identifier in %s: "%s" -> "%s"' % ( ncx_path.name, @@ -998,7 +995,7 @@ def _custom_download( ) tree = ET.ElementTree(container) tree.write(container_file_path, xml_declaration=True, encoding="utf-8") - logger.debug('Saved "%s"' % container_file_path) + log.debug('Saved "%s"' % container_file_path) # create epub zip with zipfile.ZipFile( @@ -1017,8 +1014,8 @@ def _custom_download( zip_archive_name = zip_archive_file.as_posix() zip_target_file = book_folder.joinpath(zip_archive_file) epub_zip.write(zip_target_file, zip_archive_name) - logger.debug( + log.debug( 'epub: Added "%s" as "%s"' % (zip_target_file, zip_archive_name) ) - logger.info('Saved "%s"' % epub_file_path) + log.info('Saved "%s"' % epub_file_path) return epub_file_path diff --git a/calibre-plugin/overdrive/client.py b/calibre-plugin/overdrive/client.py index 2c4a4f7..abc52c0 100644 --- a/calibre-plugin/overdrive/client.py +++ b/calibre-plugin/overdrive/client.py @@ -157,7 +157,7 @@ def _read_response(self, response, decode: bool = True) -> Union[bytes, str]: return res decoded_res = res.decode("utf8") - self.logger.debug("RES BODY: {0:s}".format(decoded_res)) + self.logger.debug("RES BODY: %s", decoded_res) return decoded_res def send_request( @@ -221,32 +221,26 @@ def send_request( for attempt in range(0, self.max_retries + 1): try: + self.logger.debug("REQUEST: %s %s", req.get_method(), endpoint_url) self.logger.debug( - "REQUEST: {0!s} {1!s}".format(req.get_method(), endpoint_url) - ) - self.logger.debug( - "REQ HEADERS: \n{0!s}".format( - "\n".join( - ["{}: {}".format(k, v) for k, v in req.headers.items()] - ) - ) + "REQ HEADERS: \n%s", + "\n".join(["{}: {}".format(k, v) for k, v in req.headers.items()]), ) if data: - self.logger.debug("REQ BODY: \n{0!s}".format(data)) + self.logger.debug("REQ BODY: \n%s", data) response = self.opener.open(req, timeout=self.timeout) except HTTPError as e: - self.logger.debug("RESPONSE: {0:d} {1:s}".format(e.code, e.url)) + self.logger.debug("RESPONSE: %d %s", e.code, e.url) self.logger.debug( - "RES HEADERS: \n{0!s}".format( - "\n".join(["{}: {}".format(k, v) for k, v in e.info().items()]) - ) + "RES HEADERS: \n%s", + "\n".join(["{}: {}".format(k, v) for k, v in e.info().items()]), ) if ( attempt < self.max_retries and e.code >= 500 ): # retry for server 5XX errors # do nothing, try self.logger.warning( - "Retrying due to {}: {}".format(e.__class__.__name__, str(e)) + "Retrying due to %s: %s", e.__class__.__name__, str(e) ) self.logger.debug(self._read_response(e)) continue @@ -263,9 +257,9 @@ def send_request( if attempt < self.max_retries: # do nothing, try self.logger.warning( - "Retrying due to {}: {}".format( - connection_error.__class__.__name__, str(connection_error) - ) + "Retrying due to %s: %s", + connection_error.__class__.__name__, + str(connection_error), ) continue raise ClientConnectionError( @@ -274,15 +268,10 @@ def send_request( ) ) from connection_error + self.logger.debug("RESPONSE: %d %s", response.code, response.url) self.logger.debug( - "RESPONSE: {0:d} {1:s}".format(response.code, response.url) - ) - self.logger.debug( - "RES HEADERS: \n{0!s}".format( - "\n".join( - ["{}: {}".format(k, v) for k, v in response.info().items()] - ) - ) + "RES HEADERS: \n%s", + "\n".join(["{}: {}".format(k, v) for k, v in response.info().items()]), ) if not decode_response: return self._read_response(response, decode_response) diff --git a/calibre-plugin/workers.py b/calibre-plugin/workers.py index c286e48..61bd100 100644 --- a/calibre-plugin/workers.py +++ b/calibre-plugin/workers.py @@ -53,14 +53,12 @@ def run(self): maxItems=self.max_items, format=self.formats, ) - logger.info( - "OverDrive Media Search took %f seconds" % (timer() - total_start) - ) + logger.info("OverDrive Media Search took %f seconds", timer() - total_start) self.finished.emit(results) except Exception as err: logger.info( - "OverDrive Media Search failed after %f seconds" - % (timer() - total_start) + "OverDrive Media Search failed after %f seconds", + timer() - total_start, ) self.errored.emit(err) @@ -88,14 +86,16 @@ def run(self): try: results = self.client.library_medias(self.library_key, self.query) logger.info( - "OverDrive Library Media Search (%s) took %f seconds" - % (self.library_key, timer() - total_start) + "OverDrive Library Media Search (%s) took %f seconds", + self.library_key, + timer() - total_start, ) self.finished.emit(self.library_key, results) except Exception as err: logger.info( - "OverDrive Library Media Search (%s) failed after %f seconds" - % (self.library_key, timer() - total_start) + "OverDrive Library Media Search (%s) failed after %f seconds", + self.library_key, + timer() - total_start, ) self.errored.emit(self.library_key, err) @@ -128,23 +128,20 @@ def run(self): media, rank=0 if PREFS[PreferenceKeys.USE_BEST_COVER] else -1 ) if cover_url: - logger.debug(f"Downloading cover: {cover_url}") + logger.debug("Downloading cover: %s", cover_url) br = browser() cover_res = br.open_novisit( cover_url, timeout=self.client.timeout ) media[self.cover_data_key] = cover_res.read() except Exception as cover_err: - logger.warning(f"Error loading cover: {cover_err}") + logger.warning("Error loading cover: %s", cover_err) self.media_cache.put(self.title_id, media) - logger.info( - "OverDrive Media Fetch took %f seconds" % (timer() - total_start) - ) + logger.info("OverDrive Media Fetch took %f seconds", timer() - total_start) self.finished.emit(media) except Exception as err: logger.info( - "OverDrive Media Fetch failed after %f seconds" - % (timer() - total_start) + "OverDrive Media Fetch failed after %f seconds", timer() - total_start ) self.errored.emit(err) @@ -167,14 +164,14 @@ def run(self): try: media = self.client.library_media(self.card["advantageKey"], self.title_id) logger.info( - "Total OverDrive Library Media Fetch took %f seconds" - % (timer() - total_start) + "Total OverDrive Library Media Fetch took %f seconds", + timer() - total_start, ) self.finished.emit(media) except Exception as err: logger.info( - "OverDrive Library Media Fetch failed after %f seconds" - % (timer() - total_start) + "OverDrive Library Media Fetch failed after %f seconds", + timer() - total_start, ) self.errored.emit(err) @@ -207,13 +204,12 @@ def run(self): {}, ) logger.info( - "Total Libby Auth Form Fetch took %f seconds" % (timer() - total_start) + "Total Libby Auth Form Fetch took %f seconds", timer() - total_start ) self.finished.emit(form) except Exception as err: logger.info( - "Libby Auth Form Fetch failed after %f seconds" - % (timer() - total_start) + "Libby Auth Form Fetch failed after %f seconds", timer() - total_start ) self.errored.emit(err) @@ -255,12 +251,12 @@ def run(self): {}, ) logger.info( - "Total Libby Verify Card took %f seconds" % (timer() - total_start) + "Total Libby Verify Card took %f seconds", timer() - total_start ) self.finished.emit(updated_card) except Exception as err: logger.info( - "Libby Verify Card failed after %f seconds" % (timer() - total_start) + "Libby Verify Card failed after %f seconds", timer() - total_start ) self.errored.emit(err) @@ -285,14 +281,14 @@ def run(self): self.loan["id"], self.loan["cardId"], self.format_id ) logger.info( - "Total Libby Fulfilment Details Fetch took %f seconds" - % (timer() - total_start) + "Total Libby Fulfilment Details Fetch took %f seconds", + timer() - total_start, ) self.finished.emit(fulfilment_details) except Exception as err: logger.info( - "Libby Fulfilment Details Fetch failed after %f seconds" - % (timer() - total_start) + "Libby Fulfilment Details Fetch failed after %f seconds", + timer() - total_start, ) self.errored.emit(err) @@ -353,7 +349,7 @@ def run(self): logger=logger, ) synced_state = libby_client.sync() - logger.info("Libby Sync request took %f seconds" % (timer() - start)) + logger.info("Libby Sync request took %f seconds", timer() - start) # Fetch libraries details from OD and patch it onto synced state start = timer() @@ -362,8 +358,8 @@ def run(self): uncached_website_ids, libraries = extract_cached_items( all_website_ids, self.libraries_cache ) - logger.debug("Reusing %d cached libraries" % len(libraries)) - logger.debug("Fetching %d new libraries" % len(uncached_website_ids)) + logger.debug("Reusing %d cached libraries", len(libraries)) + logger.debug("Fetching %d new libraries", len(uncached_website_ids)) od_client = OverDriveClient( max_retries=PREFS[PreferenceKeys.NETWORK_RETRY], timeout=PREFS[PreferenceKeys.NETWORK_TIMEOUT], @@ -382,14 +378,12 @@ def run(self): for library in found: self.libraries_cache.put(str(library["websiteId"]), library) libraries.extend(found) - logger.info( - "OverDrive Libraries requests took %f seconds" % (timer() - start) - ) + logger.info("OverDrive Libraries requests took %f seconds", timer() - start) synced_state["__libraries"] = libraries subbed_magazines = [] if subscriptions: - logger.info("Checking %d magazines" % len(subscriptions)) + logger.info("Checking %d magazines", len(subscriptions)) # Fetch magazine details from OD start = timer() all_parent_magazine_ids = [ @@ -421,9 +415,9 @@ def run(self): uncached_latest_magazine_ids, titles = extract_cached_items( latest_magazine_ids, self.media_cache ) - logger.debug("Reusing %d cached media" % len(titles)) + logger.debug("Reusing %d cached media", len(titles)) logger.debug( - "Fetching %d new media" % len(uncached_latest_magazine_ids) + "Fetching %d new media", len(uncached_latest_magazine_ids) ) if uncached_latest_magazine_ids: found = od_client.media_bulk( @@ -446,13 +440,13 @@ def run(self): ) subbed_magazines.extend(titles) logger.info( - "OverDrive Magazines requests took %f seconds" % (timer() - start) + "OverDrive Magazines requests took %f seconds", timer() - start ) synced_state["__subscriptions"] = subbed_magazines - logger.info("Total Sync Time took %f seconds" % (timer() - total_start)) + logger.info("Total Sync Time took %f seconds", timer() - total_start) self.finished.emit(synced_state) except Exception as err: - logger.info("Sync failed after %f seconds" % (timer() - total_start)) + logger.info("Sync failed after %f seconds", timer() - total_start) self.errored.emit(err)