#64 More logging overall, especially in the builder plugin
Merged 4 years ago by nphilipp. Opened 4 years ago by nphilipp.
fedora-infra/ nphilipp/rpmautospec master--ramp-up-logging  into  master

@@ -1,10 +1,15 @@ 

  import inspect

+ import logging

  

  from koji.plugin import callback

  

  from rpmautospec import process_distgit

  

  

+ _log = logging.getLogger(__name__)

+ _log.setLevel(logging.DEBUG)

+ 

+ 

  def _steal_buildroot_object_from_frame_stack():

      buildroot = frame_info = frame = stack = None

      try:
@@ -38,17 +43,36 @@ 

          return

  

      if not process_distgit.needs_processing(srcdir):

+         _log.info("No %autorel/%autochangelog found, skipping.")

          return

  

      buildroot = kwargs.get("buildroot")

      if not buildroot:

+         _log.debug("Stealing buildroot from caller.")

          buildroot = _steal_buildroot_object_from_frame_stack()

  

+     # Save previous log level of the buildroot logger...

+     buildroot_loglevel = buildroot.logger.level

+ 

+     # ...and set our own

+     buildroot.logger.setLevel(logging.DEBUG)

+ 

      br_packages = buildroot.getPackageList()

      if not any(p["name"] == "python3-rpmautospec" for p in br_packages):

+         _log.info("Installing python3-rpmautospec into build root")

          buildroot.mock(["--install", "python3-rpmautospec"])

  

      srcdir_within = buildroot.path_without_to_within(srcdir)

      buildroot.mock(

-         ["--shell", "rpmautospec", "process-distgit", "--process-specfile", srcdir_within]

+         [

+             "--shell",

+             "rpmautospec",

+             "--debug",

+             "process-distgit",

+             "--process-specfile",

+             srcdir_within,

+         ]

      )

+ 

+     # Restore log level of the buildroot logger

+     buildroot.logger.level = buildroot_loglevel

@@ -46,8 +46,7 @@ 

          repo = match.group("repo")

          commit = match.group("commit")

          if not repo or not commit:

-             info = "Could not parse repo and commit from {}, skipping."

-             _log.info(info.format(build["source"]))

+             _log.info("Could not parse repo and commit from %s, skipping.", build["source"])

              return

      else:

          _log.info("No source for this build, skipping.")

file modified
+10 -9
@@ -11,6 +11,7 @@ 

  from .misc import run_command

  from .py2compat.tagging import unescape_tag

  

+ 

  _log = logging.getLogger(__name__)

  

  
@@ -57,7 +58,7 @@ 

      if target:

          cmd.extend(["--", target])

  

-     _log.debug(f"git_get_log {' '.join(cmd)}")

+     _log.debug("git_get_log(): %s", cmd)

      return run_command(cmd, cwd=path).decode("UTF-8").strip().split("\n")

  

  
@@ -66,21 +67,21 @@ 

      specified commit and returns the output from git

      """

      cmd = ["git", "show", "--no-patch", "--format=%P|%H|%ct|%aN <%aE>|%s", commithash]

-     _log.debug(f"git_get_commit_info {' '.join(cmd)}")

+     _log.debug("git_get_commit_info: %s", cmd)

      return run_command(cmd, cwd=path).decode("UTF-8").strip().split("\n")

  

  

  def git_get_changed_files(path: str, commithash: str) -> typing.List[str]:

      """ Returns the list of files changed in the specified commit. """

      cmd = ["git", "diff-tree", "--no-commit-id", "--name-only", "-r", commithash]

-     _log.debug(f"git_get_changed_files {' '.join(cmd)}")

+     _log.debug("git_get_changed_files: %s", cmd)

      return run_command(cmd, cwd=path).decode("UTF-8").strip().split("\n")

  

  

  def git_get_tags(path: str) -> typing.Mapping[str, str]:

      """ Returns a dict containing for each commit tagged the corresponding tag. """

      cmd = ["git", "show-ref", "--tags", "--head"]

-     _log.debug(f"git_get_tags {' '.join(cmd)}")

+     _log.debug("git_get_tags: %s", cmd)

      tags_list = run_command(cmd, cwd=path).decode("UTF-8").strip().split("\n")

  

      output = {}
@@ -134,7 +135,7 @@ 

      with tempfile.TemporaryDirectory(prefix="rpmautospec-") as workdir:

          repocopy = f"{workdir}/{name}"

          shutil.copytree(repopath, repocopy)

-         _log.debug(f"Working directory: {repocopy}")

+         _log.debug("Working directory: %s", repocopy)

          lines = []

  

          # Get all the tags in the repo
@@ -176,7 +177,7 @@ 

              info = git_get_commit_info(repocopy, commit)

              if len(info) > 1:

                  # Ignore merge commits

-                 _log.debug(f"commit {commit} is a merge commit, skipping")

+                 _log.debug("commit %s is a merge commit, skipping", commit)

                  continue

  

              _, commithash, commit_ts, author_info, commit_summary = info[0].split("|", 4)
@@ -193,7 +194,7 @@ 

                  # they will be cut down anyway when the RPM gets built, so

                  # the gap between the commits we are gathering here and the

                  # ones in the `changelog` file can be ignored.

-                 # print(f"commit {commit} is too old, breaking iteration")

+                 _log.debug("commit %s is too old, breaking iteration", commit)

                  break

  

              files_changed = git_get_changed_files(repocopy, commit)
@@ -217,7 +218,7 @@ 

                      )

                  last_author = author_info

              else:

-                 _log.debug(f"commit {commit} is not changing a file of interest, ignoring")

+                 _log.debug("commit %s is not changing a file of interest, ignoring", commit)

  

          # Last entries

          output.append(entry)
@@ -246,4 +247,4 @@ 

  

      repopath = args.worktree_path

      changelog = produce_changelog(repopath)

-     print("\n".join(changelog))

+     _log.info("\n".join(changelog))

file modified
+43 -2
@@ -1,5 +1,7 @@ 

  import argparse

+ import logging

  import sys

+ import typing

  

  from . import changelog, process_distgit, release, tag_package

  
@@ -7,7 +9,28 @@ 

  subcmd_modules_by_name = {}

  

  

- def get_cli_args(args):

+ def setup_logging(log_level: int):

+     handlers = []

+ 

+     # We want all messages logged at level INFO or lower to be printed to stdout

+     info_handler = logging.StreamHandler(stream=sys.stdout)

+     info_handler.setLevel(log_level)

+     info_handler.addFilter(lambda record: record.levelno <= logging.INFO)

+     handlers.append(info_handler)

+ 

+     # Don't log levels <= INFO to stderr

+     logging.lastResort.addFilter(lambda record: record.levelno > logging.INFO)

+     handlers.append(logging.lastResort)

+ 

+     if log_level == logging.INFO:

+         # In normal operation, don't decorate messages

+         for handler in handlers:

+             handler.setFormatter(logging.Formatter("%(message)s"))

+ 

+     logging.basicConfig(level=log_level, handlers=handlers)

+ 

+ 

+ def get_cli_args(args: typing.List[str]) -> argparse.Namespace:

      global subcmd_modules_by_name

  

      parser = argparse.ArgumentParser(
@@ -22,7 +45,23 @@ 

          default="https://koji.fedoraproject.org/kojihub",

      )

  

-     parser.add_argument("-q", "--quiet", action="store_true", help="Be less talkative")

+     log_level_group = parser.add_mutually_exclusive_group()

+     log_level_group.add_argument(

+         "-q",

+         "--quiet",

+         action="store_const",

+         dest="log_level",

+         const=logging.WARNING,

+         default=logging.INFO,

+         help="Be less talkative",

+     )

+     log_level_group.add_argument(

+         "--debug",

+         action="store_const",

+         dest="log_level",

+         const=logging.DEBUG,

+         help="Enable debugging output",

+     )

  

      # parsers for sub-commands

  
@@ -42,6 +81,8 @@ 

  def main():

      args = get_cli_args(sys.argv[1:])

  

+     setup_logging(log_level=args.log_level)

+ 

      if args.subcommand:

          subcmd_module = subcmd_modules_by_name[args.subcommand]

          sys.exit(subcmd_module.main(args))

file modified
+3 -3
@@ -79,9 +79,9 @@ 

      try:

          output = subprocess.check_output(command, cwd=cwd, stderr=subprocess.PIPE)

      except subprocess.CalledProcessError as e:

-         _log.error("Command `{}` return code: `{}`".format(" ".join(command), e.returncode))

-         _log.error("stdout:\n-------\n{}".format(e.stdout))

-         _log.error("stderr:\n-------\n{}".format(e.stderr))

+         _log.error("Command `%s` return code: `%s`", " ".join(command), e.returncode)

+         _log.error("stdout:\n-------\n%s", e.stdout)

+         _log.error("stderr:\n-------\n%s", e.stderr)

          raise

  

      return output

@@ -143,7 +143,7 @@ 

          shutil.copy2(tmp_specfile.name, specfile_name)

  

  

- def process_distgit(srcdir, dist, session, actions=None, quiet=False):

+ def process_distgit(srcdir, dist, session, actions=None):

      if not actions:

          actions = ["process-specfile"]

  
@@ -156,7 +156,7 @@ 

              retval = processing_necessary

  

          # Only print output if explicitly requested

-         if "check" in actions and not quiet:

+         if "check" in actions:

              features_used = []

              if has_autorel:

                  features_used.append("%autorel")
@@ -164,9 +164,9 @@ 

                  features_used.append("%autochangelog")

  

              if not features_used:

-                 print("The spec file doesn't use automatic release or changelog.")

+                 _log.info("The spec file doesn't use automatic release or changelog.")

              else:

-                 print(f"Features used by the spec file: {', '.join(features_used)}")

+                 _log.info("Features used by the spec file: %s", ", ".join(features_used))

  

      if "process-specfile" in actions and processing_necessary:

          process_specfile(srcdir, dist, session, has_autorel, has_autochangelog, changelog_lineno)
@@ -181,7 +181,7 @@ 

      dist = args.dist

      kojiclient = koji_init(args.koji_url)

  

-     if process_distgit(repopath, dist, kojiclient, actions=args.actions, quiet=args.quiet):

+     if process_distgit(repopath, dist, kojiclient, actions=args.actions):

          return 0

      else:

          return 1

file modified
+11 -13
@@ -3,7 +3,6 @@ 

  from itertools import chain

  import logging

  import re

- import sys

  import typing

  

  from .misc import (
@@ -53,16 +52,18 @@ 

                  n_builds += 1

  

      if not last_build:

-         print("No build found")

+         _log.info("No build found")

          return

  

-     print(f"Last build: {last_build['nvr']}")

+     _log.info("Last build: %s", last_build["nvr"])

      pkgrel, middle, minorbump = parse_release_tag(last_build["release"])

      try:

          n_builds = max([pkgrel + 1, n_builds])

      except TypeError:

          pass

-     print(f"Next build: {last_build['name']}-{last_build['version']}-{n_builds}.{args.dist}")

+     _log.info(

+         "Next build: %s-%s-%d.%s", last_build["name"], last_build["version"], n_builds, args.dist

+     )

  

  

  def holistic_heuristic_calculate_release(
@@ -131,10 +132,7 @@ 

  ):

      match = disttag_re.match(dist)

      if not match:

-         print(

-             f"Dist tag {dist!r} has wrong format (should be e.g. 'fc31', 'epel7')", file=sys.stderr,

-         )

-         sys.exit(1)

+         raise RuntimeError("Dist tag %r has wrong format (should be e.g. 'fc31', 'epel7')", dist)

  

      distcode = match.group("distcode")

      pkgdistver = int(match.group("distver"))
@@ -157,7 +155,7 @@ 

          builds_per_distver[distver].append(build)

  

      if not builds_per_distver:

-         _log.warning(f"No matching builds found for dist tag pattern '{distcode}<number>'.")

+         _log.warning("No matching builds found for dist tag pattern '%s<number>'.", distcode)

          return

  

      for builds in builds_per_distver.values():
@@ -187,8 +185,8 @@ 

      )

      higher_bound_builds_nvr = [b["nvr"] for b in higher_bound_builds]

  

-     print(f"Highest build of lower or current distro versions: {lower_bound_nvr}")

-     print(f"Highest builds of higher distro versions: {', '.join(higher_bound_builds_nvr)}")

+     _log.info("Highest build of lower or current distro versions: %s", lower_bound_nvr)

+     _log.info("Highest builds of higher distro versions: %s", ", ".join(higher_bound_builds_nvr))

  

      lower_bound_rpmvercmp_key = rpmvercmp_key(lower_bound)

  
@@ -206,7 +204,7 @@ 

      else:

          higher_bound = higher_bound_nvr = None

  

-     print(f"Lowest satisfiable higher build in higher distro version: {higher_bound_nvr}")

+     _log.info("Lowest satisfiable higher build in higher distro version: %s", higher_bound_nvr)

  

      new_evr = holistic_heuristic_calculate_release(dist, evr, lower_bound, higher_bound)

      if new_evr["epoch"]:
@@ -214,7 +212,7 @@ 

      else:

          new_evr_str = f"{new_evr['version']}-{new_evr['release']}"

  

-     print(f"Calculated new release, EVR: {new_evr['release']}, {new_evr_str}")

+     _log.info("Calculated new release, EVR: %s, %s", new_evr["release"], new_evr_str)

  

      release = new_evr["release"]

  

file modified
+8 -6
@@ -35,7 +35,7 @@ 

          owner_name = build["owner_name"]

          # Ignore modular builds, account for staging

          if owner_name.startswith("mbs/") and owner_name.endswith(".fedoraproject.org"):

-             _log.info(f"Ignoring modular build: {nevr}")

+             _log.debug("Ignoring modular build: %s", nevr)

              continue

  

          commit = None
@@ -60,9 +60,11 @@ 

              try:

                  task = [t for t in tasks if t["method"] == "buildSRPMFromSCM"][0]

              except IndexError:

-                 _log.info(

+                 _log.debug(

                      "Ignoring build without buildSRPMFromSCM task, or any task at all, "

-                     f"probably an old dist-cvs build: {nevr} (build id: {build['build_id']})"

+                     "probably an old dist-cvs build: %s (build id: %s)",

+                     nevr,

+                     build["build_id"],

                  )

                  continue

  
@@ -86,7 +88,7 @@ 

              command = ["git", "tag", tag, commit]

              try:

                  run_command(command, cwd=repopath)

-             except RuntimeError as err:

-                 print(err)

+             except RuntimeError:

+                 _log.exception("Error while tagging %s with %s:", commit, tag)

              else:

-                 print(f"tagged commit {commit} as {tag}")

+                 _log.info("Tagged commit %s as %s", commit, tag)

@@ -120,6 +120,12 @@ 

          else:

              buildroot.mock.assert_any_call(["--install", "python3-rpmautospec"])

  

-         buildroot.mock.assert_called_with(

-             ["--shell", "rpmautospec", "process-distgit", "--process-specfile", srcdir_within]

-         )

+         mock_args = [

+             "--shell",

+             "rpmautospec",

+             "--debug",

+             "process-distgit",

+             "--process-specfile",

+             srcdir_within,

+         ]

+         buildroot.mock.assert_called_with(mock_args)

@@ -1,4 +1,5 @@ 

  import json

+ import logging

  import os.path

  from unittest import mock

  
@@ -37,7 +38,8 @@ 

      """Test the rpmautospec.release module"""

  

      @pytest.mark.parametrize("test_data", data_as_test_parameters(test_data))

-     def test_main(self, test_data, capsys):

+     def test_main(self, test_data, caplog):

+         caplog.set_level(logging.DEBUG)

          with open(

              os.path.join(

                  __here__,
@@ -69,7 +71,7 @@ 

          mock_client.getPackageID.assert_called_once()

          mock_client.listBuilds.assert_called_once()

  

-         expected_output = f"Last build: {test_data['last']}\n" f"Next build: {test_data['next']}\n"

-         captured_output = capsys.readouterr()

+         expected_messages = [f"Last build: {test_data['last']}", f"Next build: {test_data['next']}"]

  

-         assert captured_output.out == expected_output

+         for msg in expected_messages:

+             assert msg in caplog.messages

@@ -1,3 +1,4 @@ 

+ import logging

  from unittest import mock

  

  import pytest
@@ -88,8 +89,10 @@ 

      @mock.patch("rpmautospec.tag_package.run_command")

      @mock.patch("rpmautospec.tag_package.koji_init")

      @mock.patch("rpmautospec.tag_package.get_package_builds")

-     def test_main(self, get_package_builds, koji_init, run_command, phenomena, capsys):

+     def test_main(self, get_package_builds, koji_init, run_command, phenomena, caplog):

          """Test the tag_package.main() under various conditions."""

+         caplog.set_level(logging.DEBUG)

+ 

          phenomena = [p.strip() for p in phenomena.split(",")]

          koji_init.return_value = kojiclient = mock.Mock()

          get_package_builds.return_value = test_builds = get_test_builds(phenomena)
@@ -163,9 +166,7 @@ 

              tag = f"build/{nevr}"

              run_command.assert_called_once_with(["git", "tag", tag, commit], cwd=repopath)

  

-             stdout, stderr = capsys.readouterr()

- 

              if "tagcmdfails" in phenomena:

-                 assert stdout.strip() == "lp0 is on fire"

+                 assert "lp0 is on fire" in caplog.text

              else:

-                 assert stdout.strip() == f"tagged commit {commit} as {tag}"

+                 assert f"Tagged commit {commit} as {tag}" in caplog.messages