Improve debian reposync logging (bsc#1227859)

python/spacewalk/common/repo.py

@@ -17,11 +17,15 @@
 
 import requests
 
+from spacewalk.common import suseLib
+
 # pylint:disable=W0612,W0212,C0301
 
 SPACEWALK_LIB = "/var/lib/spacewalk"
 SPACEWALK_GPG_HOMEDIR = os.path.join(SPACEWALK_LIB, "gpgdir")
 
+logger = logging.getLogger(__name__)
+
 
 class GeneralRepoException(Exception):
     """
@@ -39,6 +43,7 @@ class DpkgRepo:
     PKG_GZ = "Packages.gz"
     PKG_XZ = "Packages.xz"
     PKG_RW = "Packages"
+    GPG_VERIFICATION_FAILED = "GPG verification failed"
 
     class ReleaseEntry:  # pylint: disable=W0612,R0903
         """
@@ -103,6 +108,13 @@ def __init__(
         self.gpg_verify = gpg_verify
         self.timeout = timeout
 
+    def __repr__(self):
+        return (
+            f"DpkgRepo(url={suseLib.URL(self._url).getURL(stripPw=True)}, "
+            f"proxies={self.proxies}, gpg_verify={self.gpg_verify}, "
+            f"timemout={self.timeout})"
+        )
+
     def append_index_file(self, index_file: str) -> str:
         """
         Append an index file, such as Packages.gz or Packagex.xz etc
@@ -115,7 +127,7 @@ def append_index_file(self, index_file: str) -> str:
         path = p_url.path
         if not path.endswith(index_file):
             if index_file in path:
-                logging.error(
+                logger.error(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "URL has already {} mentioned in it. Raising \
                                GeneralRepoException!".format(
@@ -155,7 +167,7 @@ def get_pkg_index_raw(self) -> typing.Tuple[str, bytes]:
                             self._pkg_index = cnt_fname, f.read()
                             break
                     except FileNotFoundError as ex:
-                        logging.debug(
+                        logger.debug(
                             # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                             "File not found: {}".format(
                                 packages_url.replace("file://", "")
@@ -189,13 +201,13 @@ def decompress_pkg_index(self) -> str:
             elif fname == DpkgRepo.PKG_XZ:
                 cnt_data = lzma.decompress(cnt_data)
         except (zlib.error, lzma.LZMAError) as exc:
-            logging.exception(
+            logger.exception(
                 "Exception during decompression of pkg index", exc_info=True
             )
             # pylint: disable-next=raise-missing-from
             raise GeneralRepoException(exc)
         except Exception as exc:
-            logging.exception(
+            logger.exception(
                 "Unknown exception during decompression of \
                                pkg index. Raising GeneralRepoException",
                 exc_info=True,
@@ -301,7 +313,7 @@ def _has_valid_gpg_signature(self, uri: str, response=None) -> bool:
                     )
                     out = process.wait(timeout=90)
                 else:
-                    logging.error(
+                    logger.error(
                         # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                         "Signature file for GPG check could not be accessed: \
                                    '{}. Raising GeneralRepoException.".format(
@@ -315,7 +327,7 @@ def _has_valid_gpg_signature(self, uri: str, response=None) -> bool:
                         )
                     )
             else:
-                logging.error(
+                logger.error(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "No release file found: '{}'. Raising GeneralRepoException.".format(
                         uri
@@ -363,10 +375,10 @@ def _has_valid_gpg_signature(self, uri: str, response=None) -> bool:
                     out = process.wait(timeout=90)
 
         if process.returncode == 0:
-            logging.debug("GPG signature is valid")
+            logger.debug("GPG signature is valid")
             return True
         else:
-            logging.debug(
+            logger.debug(
                 # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                 "GPG signature is invalid. gpg return code: {}".format(
                     process.returncode
@@ -392,7 +404,7 @@ def get_release_index(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntry"]:
 
     def _get_release_index_from_file(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntry"]:
         # InRelease files take precedence per uyuni-rfc 00057-deb-repo-sync-gpg-check
-        logging.debug(
+        logger.debug(
             # pylint: disable-next=logging-format-interpolation,consider-using-f-string
             "Fetching release file from local filesystem: {}".format(
                 self._url.replace("file://", "")
@@ -415,18 +427,17 @@ def _get_release_index_from_file(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
         # Repo format is not flat
         if not self.is_flat():
             if self.gpg_verify and not self._has_valid_gpg_signature(local_path):
-                # pylint: disable-next=logging-format-interpolation,consider-using-f-string
-                logging.error("GPG verification failed: {}".format(release_file))
-                logging.error("Raising GeneralRepoException!")
+                # pylint: disable-next=logging-fstring-interpolation
+                logger.error(f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {release_file}")
+                logger.error("Raising GeneralRepoException!")
                 raise GeneralRepoException(
-                    # pylint: disable-next=consider-using-f-string
-                    "GPG verification failed: {}".format(release_file)
+                    f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {release_file}"
                 )
             try:
                 with open(release_file, "rb") as f:
                     self._release = self._parse_release_index(f.read().decode("utf-8"))
             except IOError as ex:
-                logging.exception(
+                logger.exception(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "IOError while accessing file: '{}'. Raising \
                                    GeneralRepoException!".format(
@@ -446,7 +457,7 @@ def _get_release_index_from_file(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
             elif os.access(self._get_parent_url(local_path, 0, "Release"), os.R_OK):
                 release_file = self._get_parent_url(local_path, 0, "Release")
             else:
-                logging.error(
+                logger.error(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "No release file found in '{}'. Raising \
                                    GeneralRepoException.".format(
@@ -466,20 +477,16 @@ def _get_release_index_from_file(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
                     if self.gpg_verify and not self._has_valid_gpg_signature(
                         local_path
                     ):
-                        logging.error(
-                            # pylint: disable-next=logging-format-interpolation,consider-using-f-string
-                            "GPG verification failed: '{}'. \
-                                           Raising GeneralRepoException.".format(
-                                release_file
-                            )
+                        # pylint: disable-next=logging-fstring-interpolation
+                        logger.error(
+                            f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {release_file}. Raising GeneralRepoException."
                         )
                         raise GeneralRepoException(
-                            # pylint: disable-next=consider-using-f-string
-                            "GPG verification failed: {}".format(release_file)
+                            f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {release_file}"
                         )
                     self._release = self._parse_release_index(release_file_content)
             except IOError as ex:
-                logging.exception(
+                logger.exception(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "IOError while accessing file: '{}'. Raising \
                                    GeneralRepoException.".format(
@@ -497,7 +504,7 @@ def _get_release_index_from_file(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
     def _get_release_index_from_http(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntry"]:
         # InRelease files take precedence per uyuni-rfc 00057-deb-repo-sync-gpg-check
         # pylint: disable-next=logging-format-interpolation,consider-using-f-string
-        logging.debug("Fetching release file from local http: {}".format(self._url))
+        logger.debug("Fetching release file from local http: {}".format(self._url))
         resp = requests.get(
             self._get_parent_url(self._url, 2, "InRelease"),
             proxies=self.proxies,
@@ -516,7 +523,7 @@ def _get_release_index_from_http(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
                 http.HTTPStatus.OK,
                 http.HTTPStatus.FORBIDDEN,
             ]:
-                logging.error(
+                logger.error(
                     # pylint: disable-next=logging-format-interpolation,consider-using-f-string
                     "Fetching release index failed with http status \
                                '{}'. Raising GeneralRepoException.".format(
@@ -541,12 +548,11 @@ def _get_release_index_from_http(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
                 and self.gpg_verify
                 and not self._has_valid_gpg_signature(resp.url, resp)
             ):
-                logging.error(
+                logger.error(
                     "Repo has no valid GPG signature. Raising GeneralRepoException."
                 )
                 raise GeneralRepoException(
-                    # pylint: disable-next=consider-using-f-string
-                    "GPG verification failed: {}".format(resp.url)
+                    f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {resp.url}"
                 )
 
             self._release = self._parse_release_index(resp.content.decode("utf-8"))
@@ -568,12 +574,11 @@ def _get_release_index_from_http(self) -> typing.Dict[str, "DpkgRepo.ReleaseEntr
                     if self.gpg_verify and not self._has_valid_gpg_signature(
                         resp.url, resp
                     ):
-                        logging.error(
+                        logger.error(
                             "Repo has no valid GPG signature. GeneralRepoException will be raised!"
                         )
                         raise GeneralRepoException(
-                            # pylint: disable-next=consider-using-f-string
-                            "GPG verification failed: {}".format(resp.url)
+                            f"{DpkgRepo.GPG_VERIFICATION_FAILED}: {resp.url}"
                         )
                     self._release = self._parse_release_index(
                         resp.content.decode("utf-8")

python/spacewalk/common/rhnLog.py

@@ -39,6 +39,7 @@
 import atexit
 
 from spacewalk.common.rhnConfig import cfg_component
+import logging
 from uyuni.common.fileutils import getUidGid
 
 
@@ -91,6 +92,7 @@ def initLOG(log_file="stderr", level=0, component=""):
         if log_file is None or LOG.file == log_file:
             # Keep the same logging object, change only the log level
             LOG.level = level
+            align_root_logger()
             return
         # We need a different type, so destroy the old one
         LOG = None
@@ -134,6 +136,7 @@ def initLOG(log_file="stderr", level=0, component=""):
     # At this point, LOG is None and log_file is not None
     # Get a new LOG
     LOG = rhnLog(log_file, level, component)
+    align_root_logger()
     return 0
 
 
@@ -306,6 +309,43 @@ def _exit():
 atexit.register(_exit)
 
 
+def log_level_to_logging_constant(rhnlog_log_level: int):
+    mapping = {
+        0: logging.ERROR,
+        1: logging.WARNING,
+        2: logging.INFO,
+        3: logging.DEBUG,
+    }
+    # 4+: logging.DEBUG
+    return mapping.get(rhnlog_log_level, logging.DEBUG)
+
+
+def align_root_logger():
+    """Align the root logger with LOG.
+
+    Makes sure the root_logger has a single handler with the same destination as
+    LOG.file and a log level that corresponds to LOG.level
+    """
+    # initLOG() not called or didn't finish correctly
+    if LOG is None or LOG.file is None or LOG.level is None:
+        return
+
+    if LOG.file == "stderr":
+        handler = logging.StreamHandler(sys.stderr)
+    elif LOG.file == "stdout":
+        handler = logging.StreamHandler(stream=sys.stdout)
+    else:
+        handler = logging.FileHandler(filename=LOG.file)
+
+    formatter = logging.Formatter(
+        fmt="%(asctime)s - %(name)s - %(message)s", datefmt="%Y/%m/%d %H:%M:%S"
+    )
+    handler.setFormatter(formatter)
+    root_logger = logging.getLogger(None)
+    root_logger.handlers = [handler]
+    root_logger.setLevel(log_level_to_logging_constant(LOG.level))
+
+
 # ------------------------------------------------------------------------------
 if __name__ == "__main__":
     print("You can not run this module by itself")

python/spacewalk/satellite_tools/repo_plugins/deb_src.py

@@ -212,9 +212,11 @@ def verify(self):
 
         :return:
         """
-        if not repo.DpkgRepo(
+        dpkg_repo = repo.DpkgRepo(
             self.url, self._get_proxies(), self.gpg_verify, self.timeout
-        ).verify_packages_index():
+        )
+        log.debug("DebRepo.verify() dpkg_repo=%s", dpkg_repo)
+        if not dpkg_repo.verify_packages_index():
             raise repo.GeneralRepoException("Package index checksum failure")
 
     def _get_proxies(self):
@@ -456,6 +458,7 @@ def get_mediaproducts(self):
     def list_packages(self, filters, latest):
         """list packages"""
 
+        log.debug("ContentSource.list_packages(filters=%s, latest=%s)", filters, latest)
         pkglist = self.repo.get_package_list()
         self.num_packages = len(pkglist)
         if latest:
@@ -490,8 +493,11 @@ def list_packages(self, filters, latest):
                     pack.name, pack.version, pack.release, pack.epoch, pack.arch
                 )
             except ValueError as e:
-                log(0, "WARNING: package contains incorrect metadata. SKIPPING!")
-                log(0, e)
+                log.error(
+                    "Skipping package %s. Package contains incorrect metadata.\n%s",
+                    new_pack,
+                    e,
+                )
                 continue
             new_pack.unique_id = pack
             new_pack.checksum_type = pack.checksum_type