Merge ~jslarraz/review-tools:use-logging-module into review-tools:master

[Jorge Sancho Larraz]

Use python logging module instead of custom error, warn, msg and debug functions defined in reviewtools.common

[Jorge Sancho Larraz (jslarraz)]

This MR slighly changes the output format under certain circumstances. It removes the ability to return json formatted errors for errors generated by the cli script caused during the cli arguments validation/processing. This behaviour looks desirable to me anyway tbh

See inline comments!

[Alex Murray (alexmurray)]

Thanks for the very extensive comments to help walk-through this MR - it was very valuable. I really like this cleanup and it makes the code more pythonic by using the standard logging module, plus I actually like the CLI printing the errors directly rather than including them in the json output. LGTM!

review: Approve

diff --git a/bin/create-snap-declaration b/bin/create-snap-declaration
index 4666a65..a924e93 100755
--- a/bin/create-snap-declaration
+++ b/bin/create-snap-declaration
@@ -5,6 +5,7 @@ import json
 import re
 import sys
 
+from reviewtools import logger
 from reviewtools.common import read_snapd_base_declaration
 
 decl = {}
@@ -158,9 +159,8 @@ def add_missing():
 
                 cstr_s = "allow-%s" % cstr
                 if in_base and cstr_s not in decl[side][iface]:
-                    print(
-                        "WARN: adding missing '%s' for '%s' from base decl"
-                        % (cstr, iface)
+                    logger.warning(
+                        "adding missing '%s' for '%s' from base decl" % (cstr, iface)
                     )
                     decl[side][iface][cstr_b] = bool2str(base_decl[side][iface][cstr_b])
                     if isinstance(decl[side][iface][cstr_b], dict):
diff --git a/bin/dump-tool b/bin/dump-tool
index 1361328..4a9658b 100755
--- a/bin/dump-tool
+++ b/bin/dump-tool
@@ -57,7 +57,7 @@ import textwrap
 import yaml
 
 import reviewtools.common as common
-from reviewtools.common import error, warn, msg, debug
+from reviewtools import logger
 
 # TODO:
 # - --file read in one at a time and flush to disk (either --output or
@@ -72,11 +72,11 @@ def _read_store_dump(input, warn_if_empty=False, progress=False, merge=None):
     """
 
     def _add_entry(db, id, rev, y):
-        debug("adding: id=%s,rev=%s,yaml=\n%s" % (id, rev, y))
+        logger.debug("adding: id=%s,rev=%s,yaml=\n%s" % (id, rev, y))
         try:
             snap_yaml = yaml.load(y, Loader=yaml.SafeLoader)
         except Exception as e:
-            warn("Skipping %s|%s: %s" % (cId, cRev, e))
+            logger.warning("Skipping %s|%s: %s" % (cId, cRev, e))
             return
 
         # skipping existing entries
@@ -115,7 +115,7 @@ def _read_store_dump(input, warn_if_empty=False, progress=False, merge=None):
                 (cId, cRev, cYaml) = line.split("|")
                 if cYaml == "\n":  # id|rev|
                     if warn_if_empty and not progress:
-                        warn("Skipping %s|%s: empty" % (cId, cRev))
+                        logger.warning("Skipping %s|%s: empty" % (cId, cRev))
                     cId = None
             elif cId is not None:
                 cYaml += "%s" % (line)
@@ -139,7 +139,7 @@ def _write_json_db(db, fn, stdout=False):
         return
 
     if os.path.exists(fn):
-        error("%s exists. Aborting" % (fn))
+        logger.error("%s exists. Aborting" % (fn))
     with open(fn, "w") as fh:
         json.dump(db, fh, sort_keys=True, indent=2)
         fh.write("\n")
@@ -183,21 +183,21 @@ def main():
 
     # Arg validation
     if not (args.file) and not (args.db_file):
-        error("Must specify either --file or --db-file")
+        logger.error("Must specify either --file or --db-file")
     elif (args.file) and (args.db_file):
         if not os.path.exists(args.file) or not os.path.exists(args.db_file):
-            error("Both --file and --db-file must exist when used together")
+            logger.error("Both --file and --db-file must exist when used together")
         if not args.force_merge:
             ans = input("Merge '%s' into '%s' (y|N)? " % (args.file, args.db_file))
             if ans.strip().lower() not in ["y", "yes"]:
-                msg("Aborting")
+                logger.info("Aborting")
                 sys.exit(0)
 
     if args.db_file:  # read the existing db
         try:
             db = common.read_file_as_json_dict(args.db_file)
         except json.decoder.JSONDecodeError as e:
-            error("Could not read '%s': %s" % (args.db_file, e))
+            logger.error("Could not read '%s': %s" % (args.db_file, e))
 
     if args.file and args.db_file:
         db = _read_store_dump(
diff --git a/bin/rock-check-notices b/bin/rock-check-notices
index e2e0271..2b7303c 100755
--- a/bin/rock-check-notices
+++ b/bin/rock-check-notices
@@ -18,12 +18,11 @@ import argparse
 import json
 import os
 import sys
+from reviewtools import logger
 
 import reviewtools.common as common
 from reviewtools.common import (
     cmd,
-    debug,
-    warn,
     fetch_usn_db,
     get_debug_info_from_environment,
     initialize_environment_variables,
@@ -67,10 +66,10 @@ def main():
         available = "%s/bin/rock-updates-available" % os.path.abspath(
             os.environ["SNAP"]
         )
-        debug("Running " + available)
+        logger.debug("Running " + available)
     else:
         available = "review-tools.rock-updates-available"
-        debug("SNAP not set. Defaulting to 'review-tools.*'")
+        logger.debug("SNAP not set. Defaulting to 'review-tools.*'")
 
     reports = dict()
     had_debug = get_debug_info_from_environment()
@@ -78,7 +77,7 @@ def main():
     for pkg in argv:
         valid_rock, warn_msg = is_rock_valid(pkg)
         if not valid_rock:
-            warn(warn_msg)
+            logger.warning(warn_msg)
             continue
 
         # The expected rock name for this initial implementation is:
@@ -89,7 +88,7 @@ def main():
             rev = os.path.splitext(os.path.basename(pkg))[0].split("_")[1]
 
         if rock in reports and rev in reports[rock]:
-            debug("Skipping %s with revision %s" % (rock, rev))
+            logger.debug("Skipping %s with revision %s" % (rock, rev))
             continue
 
         usndb_fn = os.path.join(os.environ["SNAP_USER_COMMON"], usndb)
@@ -112,7 +111,7 @@ def main():
             os.environ["SNAP_DEBUG"] = had_debug
 
         if rc != 0:
-            warn(out)
+            logger.warning(out)
             continue
 
         if rock not in reports:
diff --git a/bin/rock-updates-available b/bin/rock-updates-available
index 77a8c42..a6f12bf 100755
--- a/bin/rock-updates-available
+++ b/bin/rock-updates-available
@@ -44,7 +44,7 @@ import textwrap
 import reviewtools.available as available
 
 import reviewtools.common as common
-from reviewtools.common import error
+from reviewtools import logger
 
 
 def main():
@@ -80,13 +80,13 @@ def main():
 
     # Arg validation
     if args.rock and not args.usn_db:
-        error("Must specify --usn-db with --rock")
+        logger.error("Must specify --usn-db with --rock")
     elif args.rock and args.store_db:
-        error("Must not specify --store-db with --rock")
+        logger.error("Must not specify --store-db with --rock")
     elif not args.rock and not args.store_db:
-        error("Must specify --rock or --store-db")
+        logger.error("Must specify --rock or --store-db")
     elif args.with_cves and not args.rock:
-        error("--with-cves should only be used with --rock")
+        logger.error("--with-cves should only be used with --rock")
 
     ignore_pockets = [pocket.strip() for pocket in args.ignore_pockets.split(",")]
 
@@ -97,7 +97,7 @@ def main():
                 args.usn_db, args.rock, args.with_cves, ignore_pockets
             )
         except ValueError as e:
-            error(e)
+            logger.error(e)
     elif args.store_db:
         (_, errors) = available.scan_store(
             args.usn_db,
@@ -108,7 +108,7 @@ def main():
             ignore_pockets,
         )
         if len(errors):
-            error("Errors encountered when scanning store entries")
+            logger.error("Errors encountered when scanning store entries")
 
     if report != "":
         print(report)
diff --git a/bin/snap-check-notices b/bin/snap-check-notices
index e1b16c2..81f2bc0 100755
--- a/bin/snap-check-notices
+++ b/bin/snap-check-notices
@@ -19,11 +19,10 @@ import json
 import os
 import sys
 
+from reviewtools import logger
 import reviewtools.common as common
 from reviewtools.common import (
     cmd,
-    debug,
-    warn,
     fetch_usn_db,
     initialize_environment_variables,
     get_debug_info_from_environment,
@@ -66,17 +65,17 @@ def main():
         available = "%s/bin/snap-updates-available" % os.path.abspath(
             os.environ["SNAP"]
         )
-        debug("Running " + available)
+        logger.debug("Running " + available)
     else:
         available = "review-tools.updates-available"
-        debug("SNAP not set. Defaulting to 'review-tools.*'")
+        logger.debug("SNAP not set. Defaulting to 'review-tools.*'")
 
     reports = dict()
     had_debug = get_debug_info_from_environment()
 
     for pkg in argv:
         if not os.path.isfile(pkg):
-            warn("Skipping '%s', not a regular file" % pkg)
+            logger.warning("Skipping '%s', not a regular file" % pkg)
             continue
 
         snap = os.path.basename(pkg).split("_")[0]
@@ -85,7 +84,7 @@ def main():
             rev = os.path.splitext(os.path.basename(pkg))[0].split("_")[1]
 
         if snap in reports and rev in reports[snap]:
-            debug("Skipping %s with revision %s" % (snap, rev))
+            logger.debug("Skipping %s with revision %s" % (snap, rev))
             continue
 
         usndb_fn = os.path.join(os.environ["SNAP_USER_COMMON"], usndb)
@@ -111,7 +110,7 @@ def main():
             os.environ["SNAP_DEBUG"] = had_debug
 
         if rc != 0:
-            warn(out)
+            logger.warning(out)
             continue
 
         if snap not in reports:
diff --git a/bin/snap-review b/bin/snap-review
index 8199929..fa891d9 100755
--- a/bin/snap-review
+++ b/bin/snap-review
@@ -11,9 +11,9 @@ import tempfile
 import textwrap
 import logging
 
+from reviewtools import logger
 from reviewtools.common import (
     MKDTEMP_PREFIX,
-    error,
     init_override_state_input,
     verify_override_state,
 )
@@ -72,14 +72,8 @@ def main():
     parser.add_argument("--state-output", default=None, help="store state output blob")
     args = parser.parse_args()
 
-    error_output_type = "console"
-    if args.json or args.sdk:
-        error_output_type = "json"
-
     if not os.path.exists(args.filename):
-        error(
-            "file '%s' does not exist." % args.filename, output_type=error_output_type
-        )
+        logger.error("file '%s' does not exist." % args.filename)
 
     modules = modules_mod.get_modules()
     if not modules:
@@ -93,14 +87,14 @@ def main():
                 overrides["snap_decl_plugs"] = json.loads(plugs_file.read())
                 validate_json(overrides["snap_decl_plugs"])
         except Exception as e:
-            error("Failed to read plugs: %s" % e, output_type=error_output_type)
+            logger.error("Failed to read plugs: %s" % e)
     if args.slots:
         try:
             with open(args.slots, "r") as slots_file:
                 overrides["snap_decl_slots"] = json.loads(slots_file.read())
                 validate_json(overrides["snap_decl_slots"])
         except Exception as e:
-            error("Failed to read slots: %s" % e, output_type=error_output_type)
+            logger.error("Failed to read slots: %s" % e)
     if args.allow_classic:
         overrides["snap_allow_classic"] = args.allow_classic
     if args.allow_gadget:
@@ -112,27 +106,23 @@ def main():
 
     # --state-input alone is unsupported
     if args.state_input and not args.state_output:
-        error(
+        logger.error(
             "Must specify --state-output with --state-input",
-            output_type=error_output_type,
         )
 
     if args.state_output:
         if args.state_input:
             # --state-input --state-output indicates we have previous state
             if not os.path.exists(args.state_input):
-                error(
+                logger.error(
                     "file '%s' does not exist." % args.state_input,
-                    output_type=error_output_type,
                 )
             try:
                 with open(args.state_input, "rb") as in_f:
                     st = in_f.read().decode("utf-8")
                     overrides["state_input"] = json.loads(st)
             except Exception as e:
-                error(
-                    "Could not read state input: %s" % e, output_type=error_output_type
-                )
+                logger.error("Could not read state input: %s" % e)
         else:
             # --state-output alone indicates we are bootstrapping
             overrides["state_input"] = init_override_state_input()
@@ -141,7 +131,7 @@ def main():
         try:
             verify_override_state(overrides["state_input"])
         except Exception as e:
-            error("state-input failed to verify: %s" % e, output_type=error_output_type)
+            logger.error("state-input failed to verify: %s" % e)
 
         overrides["state_output"] = copy.deepcopy(overrides["state_input"])
 
diff --git a/bin/snap-updates-available b/bin/snap-updates-available
index 4db68f9..98e888a 100755
--- a/bin/snap-updates-available
+++ b/bin/snap-updates-available
@@ -45,7 +45,7 @@ import textwrap
 import reviewtools.available as available
 
 import reviewtools.common as common
-from reviewtools.common import error
+from reviewtools import logger
 
 
 def main():
@@ -86,19 +86,19 @@ def main():
 
     # Arg validation
     if args.check_shared_publishers and args.snap:
-        error("--snap should not be used with --check-shared-publishers")
+        logger.error("--snap should not be used with --check-shared-publishers")
     elif args.check_shared_publishers and args.usn_db:
-        error("--usn-db should not be used with --check-shared-publishers")
+        logger.error("--usn-db should not be used with --check-shared-publishers")
     elif args.check_shared_publishers and not args.store_db:
-        error("Must specify --store-db with --check-shared-publishers")
+        logger.error("Must specify --store-db with --check-shared-publishers")
     elif args.snap and not args.usn_db:
-        error("Must specify --usn-db with --snap")
+        logger.error("Must specify --usn-db with --snap")
     elif args.snap and args.store_db:
-        error("Must not specify --store-db with --snap")
+        logger.error("Must not specify --store-db with --snap")
     elif not args.snap and not args.store_db:
-        error("Must specify --snap or --store-db")
+        logger.error("Must specify --snap or --store-db")
     elif args.with_cves and not args.snap:
-        error("--with-cves should only be used with --snap")
+        logger.error("--with-cves should only be used with --snap")
 
     ignore_pockets = [pocket.strip() for pocket in args.ignore_pockets.split(",")]
 
@@ -111,7 +111,7 @@ def main():
                 args.usn_db, args.snap, args.with_cves, ignore_pockets
             )
         except ValueError as e:
-            error(e)
+            logger.error(e)
     elif args.store_db:
         (_, errors) = available.scan_store(
             args.usn_db,
@@ -122,7 +122,7 @@ def main():
             ignore_pockets,
         )
         if len(errors):
-            error("Errors encountered when scanning store entries")
+            logger.error("Errors encountered when scanning store entries")
 
     if report != "":
         print(report)
diff --git a/bin/snap-verify-declaration b/bin/snap-verify-declaration
index 7d7ee40..cb97a90 100755
--- a/bin/snap-verify-declaration
+++ b/bin/snap-verify-declaration
@@ -22,7 +22,7 @@ import json
 import sys
 import textwrap
 
-from reviewtools.common import error
+from reviewtools import logger
 import reviewtools.sr_declaration as sr_declaration
 
 
@@ -50,12 +50,12 @@ def main():
     )
     args = parser.parse_args()
 
-    error_output_type = "console"
+    output_type = "console"
     if args.json:
-        error_output_type = "json"
+        output_type = "json"
 
     if not args.plugs and not args.slots:
-        error("Must specify --plugs and/or --slots", output_type=error_output_type)
+        logger.error("Must specify --plugs and/or --slots")
 
     # Read in the snap declaration
     snap_decl = {"plugs": {}, "slots": {}}
@@ -65,25 +65,22 @@ def main():
                 snap_decl["plugs"] = json.loads(plugs_file.read())
                 sr_declaration.validate_json(snap_decl["plugs"])
         except Exception as e:
-            error("Failed to read plugs: %s" % e, output_type=error_output_type)
+            logger.error("Failed to read plugs: %s" % e)
     if args.slots:
         try:
             with open(args.slots, "r") as slots_file:
                 snap_decl["slots"] = json.loads(slots_file.read())
                 sr_declaration.validate_json(snap_decl["slots"])
         except Exception as e:
-            error("Failed to read slots: %s" % e, output_type=error_output_type)
+            logger.error("Failed to read slots: %s" % e)
 
     try:
         review = sr_declaration.verify_snap_declaration(snap_decl)
     except Exception as e:
-        error(
-            "verify_snap_declaration() raised exception for snap decl: %s" % e,
-            output_type=error_output_type,
-        )
+        logger.error("verify_snap_declaration() raised exception for snap decl: %s" % e)
 
     report = review.review_report
-    report.show_summary(error_output_type)
+    report.show_summary(output_type)
 
     rc = 0
     if report.errors:
diff --git a/bin/store-query b/bin/store-query
index e6b22b8..420e81f 100755
--- a/bin/store-query
+++ b/bin/store-query
@@ -35,7 +35,7 @@ import requests
 import yaml
 
 import reviewtools.common as common
-from reviewtools.common import debug, error
+from reviewtools import logger
 
 from reviewtools.sr_common import SnapReview
 
@@ -140,10 +140,10 @@ def _fetch(url, headers=None):
 
     h = str(headers)
     if url in responses and h in responses[url]:
-        debug("Cache: %s, headers=%s" % (url, headers))
+        logger.debug("Cache: %s, headers=%s" % (url, headers))
         return responses[url][h]
 
-    debug("Fetch: %s, headers=%s" % (url, headers))
+    logger.debug("Fetch: %s, headers=%s" % (url, headers))
     if headers is None:
         r = requests.get(url)
     else:
@@ -152,7 +152,7 @@ def _fetch(url, headers=None):
     if r.status_code != 200:
         raise Exception("Status code: %s (%s)" % (r.status_code, r.headers))
 
-    debug("Response headers=%s" % r.headers)
+    logger.debug("Response headers=%s" % r.headers)
 
     if url not in responses:
         responses[url] = {}
@@ -264,7 +264,7 @@ def _get_snap_yaml(snap_name, channel=None, arch=None):
         ):
             return yaml.load(item["snap-yaml"], Loader=yaml.SafeLoader)
 
-    debug(format_resp(res, output_json=True))
+    logger.debug(format_resp(res, output_json=True))
     raise Exception(
         "Could not find snap-yaml for (channel=%s, arch=%s)" % (channel, arch)
     )
@@ -360,10 +360,12 @@ def main():
     args = parser.parse_args()
 
     if args.name_or_id is None and args.snap_id is None:
-        error("Must specify a snap name or snap id. Aborting")
+        logger.error("Must specify a snap name or snap id. Aborting")
 
     if not args.snap_decl and not args.snap_info and not args.snap_yaml:
-        error("Must specify one of --snap-decl, --snap-info or --snap-yaml. Aborting")
+        logger.error(
+            "Must specify one of --snap-decl, --snap-info or --snap-yaml. Aborting"
+        )
 
     # Note snap names are lower case, with numbers and '-' but snap ids are
     # alphanumerics of exactly 32. While possible that a snap-id and a name
@@ -398,7 +400,7 @@ def main():
                     if mf < 0:
                         raise ValueError
                 except ValueError:
-                    error("--max-format should be 'all' or integer >= 0")
+                    logger.error("--max-format should be 'all' or integer >= 0")
 
         if args.max_format == "all":
             snap_decl = _get_all_snap_declarations_by_id(snap_id)
@@ -416,4 +418,4 @@ if __name__ == "__main__":
     try:
         main()
     except KeyboardInterrupt:
-        error("Aborted.")
+        logger.error("Aborted.")
diff --git a/reviewtools/__init__.py b/reviewtools/__init__.py
index e69de29..4ce6539 100644
--- a/reviewtools/__init__.py
+++ b/reviewtools/__init__.py
@@ -0,0 +1,16 @@
+import logging
+
+
+class ShutdownHandler(logging.StreamHandler):
+    def emit(self, record):
+        super().emit(record)
+        if record.levelno >= logging.ERROR:
+            exit(1)
+
+
+logger = logging.getLogger(__name__)
+
+handler = ShutdownHandler()
+myFormatter = logging.Formatter("%(levelname)s: %(message)s")
+handler.setFormatter(myFormatter)
+logger.addHandler(handler)
diff --git a/reviewtools/available.py b/reviewtools/available.py
index 5b0dd3c..94bfbe1 100755
--- a/reviewtools/available.py
+++ b/reviewtools/available.py
@@ -18,10 +18,8 @@ import os
 import shutil
 import tempfile
 
+from reviewtools import logger
 from reviewtools.common import (
-    error,
-    debug,
-    warn,
     open_file_write,
     read_file_as_json_dict,
     MKDTEMP_PREFIX,
@@ -356,7 +354,7 @@ def _email_report_for_pkg(pkg_db, seen_db):
 
     email.send(email_to_addr, subj, body, bcc)
 
-    debug("Sent email for '%s'" % pkgname)
+    logger.debug("Sent email for '%s'" % pkgname)
     return (email_to_addr, subj, body)
 
 
@@ -469,7 +467,7 @@ def scan_store(
             continue
 
         if body is None:  # pragma: nocover
-            debug("Skipped email for '%s': up to date" % pkg_db["name"])
+            logger.debug("Skipped email for '%s': up to date" % pkg_db["name"])
 
         if seen_db_fn:
             _update_seen(seen_db_fn, seen_db, pkg_db)
@@ -477,7 +475,7 @@ def scan_store(
     if len(errors) > 0:
         for p in errors:
             for e in errors[p]:
-                warn("%s: %s" % (p, e))
+                logger.warning("%s: %s" % (p, e))
 
     return sent, errors
 
@@ -489,7 +487,7 @@ def scan_snap(secnot_db_fn, snap_fn, with_cves=False, ignore_pockets=list()):
         snap = SnapContainer(snap_fn)
         (man, dpkg) = snap.get_snap_manifest()
     except ContainerException as e:
-        error(str(e))
+        logger.error(str(e))
     man = get_faked_build_and_stage_packages(man)
 
     # Use dpkg.list when the snap ships it in a spot we honor. This is limited
diff --git a/reviewtools/common.py b/reviewtools/common.py
index eaaadee..2b8472e 100644
--- a/reviewtools/common.py
+++ b/reviewtools/common.py
@@ -20,6 +20,7 @@ import copy
 from enum import Enum
 import inspect
 import json
+from reviewtools import logger
 import os
 from pkg_resources import resource_filename
 import re
@@ -229,51 +230,9 @@ class ReviewBase(object):
 #
 
 
-def error(out, exit_code=1, do_exit=True, output_type=None):
-    """Print error message and exit"""
-    global REPORT_OUTPUT
-    if output_type is None:
-        output_type = REPORT_OUTPUT
-
-    if output_type == "json":
-        report = Report()
-        report.add_result("runtime-errors", "error", "msg", out, manual_review=True)
-        report.show_results(output_type)
-    else:
-        print("ERROR: %s" % (out), file=sys.stderr)
-
-    if do_exit:
-        sys.exit(exit_code)
-
-
-def warn(out):
-    """Print warning message"""
-    try:
-        print("WARN: %s" % (out), file=sys.stderr)
-    except IOError:
-        pass
-
-
-def msg(out, output=sys.stdout):
-    """Print message"""
-    try:
-        print("%s" % (out), file=output)
-    except IOError:
-        pass
-
-
-def debug(out):
-    """Print debug message"""
-    if "SNAP_DEBUG" in os.environ:
-        try:
-            print("DEBUG: %s" % (out), file=sys.stderr)
-        except IOError:
-            pass
-
-
 def cmd(command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT):
     """Try to execute the given command."""
-    debug(" ".join(command))
+    logger.debug(" ".join(command))
     try:
         sp = subprocess.Popen(command, stdout=stdout, stderr=stderr)
     except OSError as ex:
@@ -595,14 +554,14 @@ def _unpack_rock_tar(rock_pkg, dest):
                 # https://docs.python.org/3/library/tarfile.html#tarfile.TarFile.extractall
                 for name in tar.getnames():
                     if name.startswith("..") or name.startswith("/"):
-                        error(
+                        logger.error(
                             "Bad path %s while extracting archive at %s"
                             % (name, rock_pkg)
                         )
 
                 tar.extractall(path=d)
         except Exception as e:
-            error("Unexpected exception while unpacking rock %s" % e)
+            logger.error("Unexpected exception while unpacking rock %s" % e)
             if os.path.isdir(d):
                 recursive_rm(d)
 
@@ -615,17 +574,17 @@ def _unpack_rock_tar(rock_pkg, dest):
 
         return dest
     else:
-        error(error_msg)
+        logger.error(error_msg)
 
 
 def check_dir(dest):
     if dest is not None and os.path.exists(dest):
-        error("'%s' exists. Aborting." % dest)
+        logger.error("'%s' exists. Aborting." % dest)
 
 
 def check_fn(fn):
     if not os.path.isfile(fn):
-        error("Could not find '%s'" % fn)
+        logger.error("Could not find '%s'" % fn)
     pkg = fn
     if not pkg.startswith("/"):
         pkg = os.path.abspath(pkg)
@@ -636,7 +595,7 @@ def check_max_pkg_size(pkg):
     size = os.stat(pkg)[stat.ST_SIZE]
     max = MAX_COMPRESSED_SIZE * 1024 * 1024 * 1024
     if size > max:
-        error(
+        logger.error(
             "compressed file is too large (%dM > %dM)"
             % (size / 1024 / 1024, max / 1024 / 1024)
         )
@@ -654,7 +613,7 @@ def unpack_rock(fn, dest=None):
     if tarfile.is_tarfile(pkg):
         return _unpack_rock_tar(fn, dest)
 
-    error("Unsupported package format (not tar)")
+    logger.error("Unsupported package format (not tar)")
 
 
 def open_file_read(path):
@@ -895,7 +854,7 @@ def check_results(
 def read_file_as_json_dict(fn):
     """Read in filename as json dict"""
     # XXX: consider reading in as stream
-    debug("Loading: %s" % fn)
+    logger.debug("Loading: %s" % fn)
     raw = {}
     with open_file_read(fn) as fd:
         try:
@@ -965,7 +924,7 @@ def build_manifest_from_rock_tar(man_fn, unpack_tmp_dir):
 
     if not dpkg_query:
         recursive_rm(unpack_tmp_dir)
-        error("%s not in %s" % (man_fn, unpack_tmp_dir))
+        logger.error("%s not in %s" % (man_fn, unpack_tmp_dir))
 
     return build_man_from_dpkg_query_file_content(dpkg_query)
 
@@ -1037,7 +996,7 @@ def extract_dpkg_query_file_from_rock(dpkg_query, unpack_tmp_dir):
                 if dpkg_query:
                     return dpkg_query
         except Exception as e:
-            error("Could not extract manifest %s" % e)
+            logger.error("Could not extract manifest %s" % e)
             recursive_rm(unpack_tmp_dir)
 
     return dpkg_query
@@ -1061,7 +1020,7 @@ def read_snapd_base_declaration():
     if not os.path.exists(bd_fn):
         bd_fn = resource_filename(__name__, "data/snapd-base-declaration.yaml")
         if not os.path.exists(bd_fn):
-            error("could not find '%s'" % bd_fn)
+            logger.error("could not find '%s'" % bd_fn)
     fd = open_file_read(bd_fn)
     contents = fd.read()
     fd.close()
@@ -1128,12 +1087,12 @@ def initialize_environment_variables():
         os.environ["SNAP_USER_COMMON"] = (
             "%s/snap/review-tools/common" % os.environ["HOME"]
         )
-        debug(
+        logger.debug(
             "SNAP_USER_COMMON not set. Defaulting to %s"
             % os.environ["SNAP_USER_COMMON"]
         )
         if not os.path.exists(os.environ["SNAP_USER_COMMON"]):
-            error(
+            logger.error(
                 "SNAP_USER_COMMON not set and %s does not exist"
                 % os.environ["SNAP_USER_COMMON"]
             )
@@ -1162,9 +1121,9 @@ def fetch_usn_db(args):
     ):
         rc, out = cmd([fetchdb, "%s.bz2" % usndb])
         if rc != 0:
-            error(out)
+            logger.error(out)
     else:
-        debug("Reusing %s" % usndb)
+        logger.debug("Reusing %s" % usndb)
     os.chdir(curdir)
     return usndb
 
diff --git a/reviewtools/sr_declaration.py b/reviewtools/sr_declaration.py
index edfe023..e4df23b 100644
--- a/reviewtools/sr_declaration.py
+++ b/reviewtools/sr_declaration.py
@@ -15,8 +15,9 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 from __future__ import print_function
+from reviewtools import logger
 from reviewtools.sr_common import SnapReview, SnapReviewException
-from reviewtools.common import error, ReviewBase, read_snapd_base_declaration
+from reviewtools.common import ReviewBase, read_snapd_base_declaration
 from reviewtools.overrides import sec_iface_ref_overrides
 from reviewtools.schemas.schema_validator import load_schema
 import copy
@@ -1521,7 +1522,7 @@ def verify_snap_declaration(snap_decl, base_decl=None):
     try:
         SnapReviewDeclaration._verify_declaration(review, base_decl, base=True)
     except Exception as e:  # pragma: nocover
-        error("_verify_declaration() raised exception for base decl: %s" % e)
+        logger.error("_verify_declaration() raised exception for base decl: %s" % e)
 
     # First make sure that the interfaces in the snap declaration are known to
     # the base declaration
@@ -1543,6 +1544,6 @@ def verify_snap_declaration(snap_decl, base_decl=None):
     try:
         SnapReviewDeclaration._verify_declaration(review, snap_decl, base=False)
     except Exception as e:  # pragma: nocover
-        error("_verify_declaration() raised exception for snap decl: %s" % e)
+        logger.error("_verify_declaration() raised exception for snap decl: %s" % e)
 
     return review
diff --git a/reviewtools/store.py b/reviewtools/store.py
index e84cd00..2d0a3ac 100644
--- a/reviewtools/store.py
+++ b/reviewtools/store.py
@@ -19,9 +19,8 @@ import yaml
 
 import reviewtools.debversion as debversion
 
+from reviewtools import logger
 from reviewtools.common import (
-    debug,
-    warn,
     get_os_codename,
     assign_type_to_dict_values,
     _add_error,  # make a class
@@ -233,7 +232,7 @@ def get_pkg_revisions(item, secnot_db, errors, pkg_type="snap", ignore_pockets=l
             continue
 
         r = str(rev["revision"])  # ensure yaml and json agree on type
-        debug("Checking %s r%s" % (item["name"], r))
+        logger.debug("Checking %s r%s" % (item["name"], r))
 
         if "manifest_yaml" not in rev:
             _add_error(
@@ -359,11 +358,11 @@ def get_staged_and_build_packages_from_manifest(m):
     If not, obtain it from stage-packages for various parts instead
     """
     if "parts" not in m:
-        debug("Could not find 'parts' in manifest")
+        logger.debug("Could not find 'parts' in manifest")
         return None
 
     if not m["parts"]:
-        debug("'parts' exists in manifest but it is empty")
+        logger.debug("'parts' exists in manifest but it is empty")
         return None
 
     d = {}
@@ -407,18 +406,18 @@ def get_staged_and_build_packages_from_manifest(m):
     if len(d) == 0:
         return None
 
-    debug("\n" + pprint.pformat(d))
+    logger.debug("\n" + pprint.pformat(d))
     return d
 
 
 def get_staged_packages_from_rock_manifest(m):
     """Obtain list of packages in stage-packages if section is present."""
     if "stage-packages" not in m:
-        debug("Could not find 'stage-packages' in manifest")
+        logger.debug("Could not find 'stage-packages' in manifest")
         return None
 
     if not m["stage-packages"]:
-        debug("'stage-packages' exists in manifest but it is empty")
+        logger.debug("'stage-packages' exists in manifest but it is empty")
         return None
 
     d = {}
@@ -426,7 +425,7 @@ def get_staged_packages_from_rock_manifest(m):
     if len(d) == 0:
         return None
 
-    debug("\n" + pprint.pformat(d))
+    logger.debug("\n" + pprint.pformat(d))
     return d
 
 
@@ -440,11 +439,11 @@ def get_packages_from_manifest_section(d, manifest_section, package_type):
     """
     for entry in manifest_section:
         if "=" not in entry:
-            warn("'%s' not properly formatted. Skipping" % entry)
+            logger.warning("'%s' not properly formatted. Skipping" % entry)
             continue
         pkg, ver = entry.split("=")
         if pkg in update_binaries_ignore:
-            debug("Skipping ignored binary: '%s'" % pkg)
+            logger.debug("Skipping ignored binary: '%s'" % pkg)
             continue
         if package_type not in d:
             d[package_type] = {}
@@ -467,7 +466,7 @@ def get_packages_from_rock_manifest_section(d, manifest_section, package_type):
         # rock manifest v1 stage-packages section is a list of
         # "<binpkg1>=<version>,<srcpkg1>=<src version>"
         if "=" not in entry or "," not in entry:
-            warn("'%s' not properly formatted. Skipping" % entry)
+            logger.warning("'%s' not properly formatted. Skipping" % entry)
             continue
         pkg_info = entry.split(",")
         if len(pkg_info) == 2:
@@ -485,7 +484,7 @@ def get_packages_from_rock_manifest_section(d, manifest_section, package_type):
                     binary_pkg_name = arch_qualifier_parts[0]
                 ver = binary_pkg[1]
                 if binary_pkg_name in update_binaries_ignore:
-                    debug("Skipping ignored binary: '%s'" % binary_pkg_name)
+                    logger.debug("Skipping ignored binary: '%s'" % binary_pkg_name)
                     continue
                 if package_type not in d:
                     d[package_type] = {}
@@ -494,10 +493,10 @@ def get_packages_from_rock_manifest_section(d, manifest_section, package_type):
                 if ver not in d[package_type][binary_pkg_name]:
                     d[package_type][binary_pkg_name].append(ver)
             else:
-                warn("'%s' not properly formatted. Skipping" % pkg_info)
+                logger.warning("'%s' not properly formatted. Skipping" % pkg_info)
                 continue
         else:
-            warn("'%s' not properly formatted. Skipping" % pkg_info)
+            logger.warning("'%s' not properly formatted. Skipping" % pkg_info)
             continue
 
 
@@ -544,7 +543,7 @@ def get_secnots_for_manifest(
     ignore_pockets=list(),
 ):
     """Find new security notifications for packages in the manifest"""
-    debug(manifest_type + "/manifest.yaml:\n" + pprint.pformat(manifest))
+    logger.debug(manifest_type + "/manifest.yaml:\n" + pprint.pformat(manifest))
     stage_and_build_pkgs = None
     rel = get_ubuntu_release_from_manifest(
         manifest, manifest_type
@@ -561,7 +560,7 @@ def get_secnots_for_manifest(
 
     pending_secnots = {}
     if stage_and_build_pkgs is None:
-        debug("no stage-packages found")
+        logger.debug("no stage-packages found")
         return pending_secnots
     # Since stage_and_build_pkgs can have stage-packages and build-packages
     # keys, adding secnots into each group
@@ -594,7 +593,7 @@ def get_secnots_for_manifest(
                                         if key in manifest["parts"][part]:
                                             for entry in manifest["parts"][part][key]:
                                                 if "=" not in entry:
-                                                    warn(
+                                                    logger.warning(
                                                         "'%s' not properly "
                                                         "formatted. Skipping" % entry
                                                     )
@@ -616,7 +615,7 @@ def get_secnots_for_manifest(
                             secnotversion = secnot_db[rel][pkg][secnot]["version"]
 
                         if debversion.compare(pkgversion, secnotversion) < 0:
-                            debug(
+                            logger.debug(
                                 "adding %s: %s (pkg:%s < secnot:%s)"
                                 % (
                                     pkg,
@@ -641,7 +640,7 @@ def get_secnots_for_manifest(
                                 else:
                                     pending_secnots[pkg_type][pkg].append(secnot)
                         else:
-                            debug(
+                            logger.debug(
                                 "skipping %s: %s (pkg:%s >= secnot:%s)"
                                 % (
                                     pkg,
@@ -675,7 +674,7 @@ def get_ubuntu_release_from_manifest_snap(m):
         if "installed-snaps" in m["parts"][part]:
             for entry in m["parts"][part]["installed-snaps"]:
                 if "=" not in entry:
-                    warn("'%s' not properly formatted. Skipping" % entry)
+                    logger.warning("'%s' not properly formatted. Skipping" % entry)
                     continue
                 pkg = entry.split("=")[0]  # we don't care about the version
 
@@ -689,7 +688,7 @@ def get_ubuntu_release_from_manifest_snap(m):
             ubuntu_release = get_os_codename(
                 m["snapcraft-os-release-id"], m["snapcraft-os-release-version-id"]
             )
-            debug("Ubuntu release=%s" % ubuntu_release)
+            logger.debug("Ubuntu release=%s" % ubuntu_release)
             return ubuntu_release
         except ValueError:
             pass
@@ -720,7 +719,7 @@ def get_ubuntu_release_from_manifest_snap(m):
                 ubuntu_release = get_os_codename(
                     "ubuntu", m["snapcraft-os-release-version-id"]
                 )
-                debug(
+                logger.debug(
                     "Could not determine Ubuntu release (non-core base)."
                     "Guessing based on snapcraft-os-release-version-id: %s"
                     % (m["snapcraft-os-release-version-id"])
@@ -731,7 +730,7 @@ def get_ubuntu_release_from_manifest_snap(m):
         if ubuntu_release is None:
             # no installed snaps, use default
             if len(installed_snaps) == 0:
-                debug(
+                logger.debug(
                     "Could not determine Ubuntu release (non-core base with "
                     "no "
                     "installed snaps). Defaulting to '%s'" % default
@@ -757,7 +756,7 @@ def get_ubuntu_release_from_manifest_rock(m):
             ubuntu_release = get_os_codename(
                 m["os-release-id"], str(m["os-release-version-id"])
             )
-            debug("Ubuntu release=%s" % ubuntu_release)
+            logger.debug("Ubuntu release=%s" % ubuntu_release)
         except ValueError:
             pass
     else:
@@ -775,7 +774,7 @@ def get_ubuntu_release_from_manifest(m, m_type="snap"):
         ubuntu_release = get_ubuntu_release_from_manifest_rock(m)
     else:
         raise TypeError("Unsupported manifest type %s" % m_type)
-    debug("Ubuntu release=%s" % ubuntu_release)
+    logger.debug("Ubuntu release=%s" % ubuntu_release)
 
     return ubuntu_release
 
@@ -789,5 +788,5 @@ def get_snapcraft_version_from_manifest(m):
         try:
             return debversion.DebVersion(m["snapcraft-version"])
         except ValueError as e:
-            warn("Invalid Snapcraft version: %s" % e)
+            logger.warning("Invalid Snapcraft version: %s" % e)
             return None
diff --git a/tests/test-dump-tool.sh.expected b/tests/test-dump-tool.sh.expected
index 702666e..1cc4104 100644
--- a/tests/test-dump-tool.sh.expected
+++ b/tests/test-dump-tool.sh.expected
@@ -14,14 +14,14 @@ Done: 10 revisions read
 
 = Test --file --warn-if-empty =
 Running: dump-tool --warn-if-empty --file ./tests/test-store-dump.1
-WARN: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|1: empty
-WARN: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|2: empty
-WARN: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|3: empty
-WARN: Skipping 99T7MUlRhtI3U0QFgl5mXXESAiSwt776|1: empty
-WARN: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|1: empty
-WARN: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|2: empty
-WARN: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|3: empty
-WARN: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|4: empty
+WARNING: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|1: empty
+WARNING: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|2: empty
+WARNING: Skipping 4ZWSHtNHDBdBsoGCTVgKkk8F9MtvjZS1|3: empty
+WARNING: Skipping 99T7MUlRhtI3U0QFgl5mXXESAiSwt776|1: empty
+WARNING: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|1: empty
+WARNING: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|2: empty
+WARNING: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|3: empty
+WARNING: Skipping UqFziVZDHLSyO3TqSWgNBoAdHbLI4dAH|4: empty
 
 = Test --db-file =
 Running: dump-tool --db-file ./tests/test-store-dump.1.json
diff --git a/tests/test-snap-verify-declaration.sh.expected b/tests/test-snap-verify-declaration.sh.expected
index 0149682..88f34ee 100644
--- a/tests/test-snap-verify-declaration.sh.expected
+++ b/tests/test-snap-verify-declaration.sh.expected
@@ -4,7 +4,7 @@ usage: snap-verify-declaration [-h] [--json] [--plugs PLUGS] [--slots SLOTS]
 
 Check a snap declaration for errors
 
-optional arguments:
+options:
   -h, --help     show this help message and exit
   --json         print json output
   --plugs PLUGS  file specifying snap declaration for plugs
@@ -138,18 +138,7 @@ Running: snap-verify-declaration --plugs=./plugs
 ERROR: Failed to read plugs: Expecting property name enclosed in double quotes: line 2 column 1 (char 2)
 
 Running: snap-verify-declaration --json --plugs=./plugs
-{
-  "runtime-errors": {
-    "error": {
-      "msg": {
-        "manual_review": true,
-        "text": "Failed to read plugs: Expecting property name enclosed in double quotes: line 2 column 1 (char 2)"
-      }
-    },
-    "info": {},
-    "warn": {}
-  }
-}
+ERROR: Failed to read plugs: Expecting property name enclosed in double quotes: line 2 column 1 (char 2)
 
 Running: snap-verify-declaration --plugs=./plugs
 {'error': {'snap-declaration-verify_v2:valid_interface:nonexistent': {'manual_review': False,
@@ -208,16 +197,5 @@ Running: snap-verify-declaration --plugs=./plugs
 ERROR: Failed to read plugs: bare <class 'bool'> value True for 'mir:allow-auto-connection' is not allowed - this should be a string "true" instead
 
 Running: snap-verify-declaration --json --plugs=./plugs
-{
-  "runtime-errors": {
-    "error": {
-      "msg": {
-        "manual_review": true,
-        "text": "Failed to read plugs: bare <class 'bool'> value True for 'mir:allow-auto-connection' is not allowed - this should be a string \"true\" instead"
-      }
-    },
-    "info": {},
-    "warn": {}
-  }
-}
+ERROR: Failed to read plugs: bare <class 'bool'> value True for 'mir:allow-auto-connection' is not allowed - this should be a string "true" instead
 
diff --git a/tests/test-updates-available.sh.expected b/tests/test-updates-available.sh.expected
index f6957fe..47edb1c 100644
--- a/tests/test-updates-available.sh.expected
+++ b/tests/test-updates-available.sh.expected
@@ -1419,7 +1419,7 @@ Running: snap-updates-available --with-cves --usn-db='./tests/test-usn-unittest-
 }
 
 Running: ./bin/snap-updates-available --usn-db='./tests/test-usn-unittest-1.db' --store-db='./tests/test-store-unittest-bad-1.db'
-WARN: 1ad: required field 'revisions' not found
+WARNING: 1ad: required field 'revisions' not found
 ERROR: Errors encountered when scanning store entries
 From: Snap Store <[e-mail]>
 To: [e-mail]
@@ -1655,10 +1655,10 @@ References:
 
 
 Running: ./bin/snap-updates-available --usn-db='./tests/test-usn-unittest-build-pkgs.db' --store-db='./tests/test-store-unittest-invalid-snapcraft-version.db'
-WARN: Invalid Snapcraft version: '4.4.3' not a valid Debian version
+WARNING: Invalid Snapcraft version: '4.4.3' not a valid Debian version
 
 Running: ./bin/snap-updates-available --usn-db='./tests/test-usn-unittest-build-pkgs.db' --store-db='./tests/test-store-kernel-invalid-snapcraft-version.db'
-WARN: Invalid Snapcraft version: '2.3' not a valid Debian version
+WARNING: Invalid Snapcraft version: '2.3' not a valid Debian version
 
 Running: snap-updates-available --usn-db='./tests/test-usn-unittest-lp1841848.db' --snap='./tests/test-check-notices_0.1_amd64.snap'