pkg_in_pipe: log the progress, the cache usage and the source problems during the generation (#849)

* Fix plane connection error blocking the script execution

It's meant to generate a message in the report, not block the report
generation

Signed-off-by: Gaëtan Lehmann <gaetan.lehmann@vates.tech>

* pkg_in_pipe: log the progress, the cache usage and the source problems during the generation

Add a --debug option and log the koji tag and the build being processed, whether
values come from the cache or are fetched again, and warn when the plane tickets
or github can't be reached, using the same logger setup as gen-dnf-proxy.py.

Signed-off-by: Gaëtan Lehmann <gaetan.lehmann@vates.tech>

---------

Signed-off-by: Gaëtan Lehmann <gaetan.lehmann@vates.tech>

Author: glehmann

scripts/pkg_in_pipe/README.md

@@ -16,6 +16,8 @@ environment variable or the `--plane-token` command line option.
 
 An extra `--generated-info` command line option may be used to add some info about the report generation process.
 
+The `--debug` option logs more details about the generation on stderr.
+
 A machine readable version of the report can also be generated with the `--json-output` option:
 
 ```sh

scripts/pkg_in_pipe/pkg_in_pipe.py

@@ -2,8 +2,10 @@
 import argparse
 import io
 import json
+import logging
 import os
 import re
+import sys
 import tomllib
 from collections import defaultdict
 from datetime import datetime
@@ -19,6 +21,31 @@
 from github.GithubException import BadCredentialsException
 from github.PullRequest import PullRequest
 
+log = logging.getLogger(__name__)
+
+
+class ColorFormatter(logging.Formatter):
+    colors = {
+        logging.CRITICAL: '\033[31m',
+        logging.ERROR: '\033[31m',
+        logging.WARNING: '\033[33m',
+        logging.DEBUG: '\033[34m',
+    }
+
+    def __init__(self, use_color: bool) -> None:
+        super().__init__(fmt='{message}', style='{')
+        self.use_color = use_color
+
+    def format(self, record: logging.LogRecord) -> str:
+        message = super().format(record)
+        if record.levelno == logging.INFO:
+            return message
+
+        prefix = f'{record.levelname.lower()}: '
+        if color := self.colors.get(record.levelno) if self.use_color else None:
+            prefix = f'{color}{prefix}\033[0m'
+        return '\n'.join(f'{prefix}{line}' for line in message.splitlines() or [''])
+
 
 with open(os.path.join(os.path.dirname(__file__), 'missing_sources.toml'), 'rb') as missing_sources_file:
     MISSING_SOURCES = tomllib.load(missing_sources_file)
@@ -254,6 +281,21 @@ def find_released_build(build_tag, package_name):
             return get_koji_build(max(tagged, key=lambda t: t['build_id'])['build_id'])
     return None
 
+def cached(key):
+    """Return the value cached for that key, or None when it must be fetched again."""
+    if args.re_cache:
+        log.debug("cache ignored because of --re-cache: %s", key)
+        return None
+    if key in CACHE:
+        log.debug("cache hit: %s", key)
+        return CACHE[key]
+    log.debug("cache miss: %s", key)
+    return None
+
+def cache(key, value):
+    log.debug("caching: %s", key)
+    CACHE.set(key, value, expire=RETENTION_TIME)
+
 def find_commits(gh, repo, start_sha, end_sha) -> list[Commit]:
     """
     List the commits in the range [start_sha,end_sha[.
@@ -262,24 +304,24 @@ def find_commits(gh, repo, start_sha, end_sha) -> list[Commit]:
     A commit older that the end_sha commit and added by a merge commit won't appear in this list.
     """
     cache_key = f'commits-2-{start_sha}-{end_sha}'
-    if not args.re_cache and cache_key in CACHE:
-        return cast(list[Commit], CACHE[cache_key])
+    if (commits := cast(list[Commit], cached(cache_key))) is not None:
+        return commits
     commits = []
     if gh:
         for commit in gh.get_repo(repo).get_commits(start_sha):
             if commit.sha == end_sha:
                 break
             commits.append(commit)
-        CACHE.set(cache_key, commits, expire=RETENTION_TIME)
+        cache(cache_key, commits)
     return commits
 
 def find_pull_requests(repo, start_sha, end_sha):
     """Find the pull requests for the commits in the [start_sha,end_sha[ range."""
     prs = set()
     for commit in find_commits(GITHUB, repo, start_sha, end_sha):
         cache_key = f'commit-prs-6-{commit.sha}'
-        if not args.re_cache and cache_key in CACHE:
-            prs.update(cast(list[PullRequest], CACHE[cache_key]))
+        if (commit_prs := cast(list[PullRequest], cached(cache_key))) is not None:
+            prs.update(commit_prs)
         elif GITHUB:
             commit_prs = list(commit.get_pulls())
             if not commit_prs:
@@ -295,17 +337,17 @@ def find_pull_requests(repo, start_sha, end_sha):
             # commit. The latter is needed for the PRs merged by rebase or squash, whose merge
             # commit on the base branch is not one of the PR commits.
             commit_prs = [pr for pr in commit_prs if commit in pr.get_commits() or commit.sha == pr.merge_commit_sha]
-            CACHE.set(cache_key, commit_prs, expire=RETENTION_TIME)
+            cache(cache_key, commit_prs)
             prs.update(commit_prs)
     return sorted(prs, key=lambda p: p.number, reverse=True)
 
 def get_koji_build(build_id) -> dict:
     cache_key = f'koji-build-{build_id}'
-    if not args.re_cache and cache_key in CACHE:
-        return cast(dict, CACHE[cache_key])
+    if (build := cast(dict, cached(cache_key))) is not None:
+        return build
     else:
         build = KOJI.getBuild(build_id)
-        CACHE.set(cache_key, build, expire=RETENTION_TIME)
+        cache(cache_key, build)
         return build
 
 def get_plane_issues(plane_token):
@@ -409,8 +451,15 @@ def get_plane_issues_with_milestones(plane_token):
 )
 parser.add_argument('--re-cache', help="Refresh the cache", action='store_true')
 parser.add_argument('--json-output', help="Also write a machine readable report in json format to this path")
+parser.add_argument('--debug', help="Log more details on stderr", action='store_true')
 args = parser.parse_args()
 
+handler = logging.StreamHandler()
+handler.setFormatter(ColorFormatter(
+    not os.environ.get('NO_COLOR') and (bool(os.environ.get('FORCE_COLOR')) or sys.stderr.isatty()),
+))
+logging.basicConfig(level=logging.DEBUG if args.debug else logging.INFO, handlers=[handler])
+
 CACHE = diskcache.Cache(args.cache)
 RETENTION_TIME = 24 * 60 * 60  # 24 hours
 
@@ -426,9 +475,9 @@ def get_plane_issues_with_milestones(plane_token):
 # load the issues from plane, so we can search for the plane card related to a build
 try:
     issues = get_plane_issues_with_milestones(args.plane_token)
-except Exception:
+except Exception as e:
     issues = []
-    raise
+    log.warning("failed to load the tickets from plane: %s", e)
 
 # connect to github
 GITHUB = None
@@ -438,6 +487,12 @@ def get_plane_issues_with_milestones(plane_token):
         GITHUB.get_repo('xcp-ng/xcp')  # check that the token is valid
     except BadCredentialsException:
         GITHUB = None
+        log.warning("the github token is invalid")
+    except github.GithubException as e:
+        GITHUB = None
+        log.warning("failed to connect to github: %s", e)
+else:
+    log.warning("no github token, the pull requests come from the cache")
 
 # load the packages maintainers
 with urlopen('https://github.com/xcp-ng/xcp/raw/refs/heads/master/scripts/rpm_owners/packages.json') as f:
@@ -464,6 +519,7 @@ def get_plane_issues_with_milestones(plane_token):
             KOJI = koji.ClientSession('https://kojihub.xcp-ng.org', config)
             KOJI.ssl_login(config['cert'], None, config['serverca'])
             for tag in tags:
+                log.info('processing tag %s', tag)
                 tag_data = {'tag': tag, 'builds': []}
                 report_data['tags'].append(tag_data)
                 tag_history = dict(
@@ -475,6 +531,8 @@ def get_plane_issues_with_milestones(plane_token):
                 taggeds = (t for t in taggeds if t['package_name'] in args.packages or args.packages == [])
                 taggeds = sorted(taggeds, key=lambda t: (tag_history[t['build_id']], t['build_id']), reverse=True)
                 for tagged in taggeds:
+                    build_url = f'https://koji.xcp-ng.org/buildinfo?buildID={tagged["build_id"]}'
+                    log.info('  processing build %s (%s)', tagged['nvr'], build_url)
                     build = get_koji_build(tagged['build_id'])
                     prs: list[PullRequest] = []
                     maintained_by = None
@@ -484,7 +542,6 @@ def get_plane_issues_with_milestones(plane_token):
                         (repo, sha) = parse_source(build['source'])
                         prs = find_pull_requests(repo, sha, previous_build_sha)
                     maintained_by = PACKAGES.get(tagged['package_name'], {}).get('maintainer')
-                    build_url = f'https://koji.xcp-ng.org/buildinfo?buildID={tagged["build_id"]}'
                     build_issues = filter_issues(issues, [build_url] + [pr.html_url for pr in prs])
                     print_table_line(
                         temp_out, tagged['nvr'], build_url, build_issues, tagged['owner_name'], prs, maintained_by