Merge ~cjwatson/snapstore-client:better-logging into snapstore-client:master

[Colin Watson]

Set up better output logging

Using a logger rather than plain `print` makes it easier to unit-test
things without extensive monkey-patching, and is just generally better
style.

The general approach is borrowed from snapcraft, although I changed a
number of details: in particular, I only use colours for errors to avoid
sensory overload.

Note that we must use %-style rather than {}-style formatting, since the
latter can't safely be used in logging records without considerable
complications.

[Adam Collard (adam-collard)]

Some comments inline, awaiting info on the peril you describe about using {}-style formatting (I contend that if we interpolate before passing the string into the logging subsystem, we won't have any complications)

review: Needs Information

[Adam Collard (adam-collard)]

As discussed on IRC, we'll stick with %-formatting since we can't interpolate using {} beforehand in case any the resulting string contains '%' (which would cause problems)

[Adam Collard (adam-collard)]

+1 but please see inline-comments

review: Approve

[Colin Watson (cjwatson)]

Thanks. I've fixed all of those now.

diff --git a/serve-snaps.py b/serve-snaps.py
index 2e9133f..7ab8f5d 100755
--- a/serve-snaps.py
+++ b/serve-snaps.py
@@ -2,9 +2,11 @@
 # -*- coding: utf-8 -*-
 # Copyright 2017 Canonical Ltd.
 
-"""serve snaps from a dictory on disk."""
-import os
+"""Serve snaps from a directory on disk."""
+
 import http.server
+import logging
+import os
 from urllib.error import HTTPError
 from urllib.parse import (
     urlsplit,
@@ -12,8 +14,12 @@ from urllib.parse import (
 )
 from urllib.request import urlopen
 
-from siab_client.config import read_config
 from siab_client import get_storage_root
+from siab_client.cli import configure_logging
+from siab_client.config import read_config
+
+
+logger = logging.getLogger(__name__)
 
 
 class SometimesProxyingButOtherwisePrettySimpleHTTPRequestHandler(
@@ -43,6 +49,7 @@ class SometimesProxyingButOtherwisePrettySimpleHTTPRequestHandler(
 
 
 def main():
+    configure_logging()
     # TODO: perhaps this should come from config instead?
     os.chdir(get_storage_root())
     config = read_config()
@@ -52,8 +59,9 @@ def main():
     httpd = http.server.HTTPServer(
         (listen_host, listen_port),
         SometimesProxyingButOtherwisePrettySimpleHTTPRequestHandler)
-    print("serving at port", listen_port)
+    logger.info('Serving at port %d', listen_port)
     httpd.serve_forever()
 
+
 if __name__ == '__main__':
     main()
diff --git a/siab_client/cli.py b/siab_client/cli.py
new file mode 100644
index 0000000..0ee6e66
--- /dev/null
+++ b/siab_client/cli.py
@@ -0,0 +1,66 @@
+# Copyright 2017 Canonical Ltd.
+
+"""Command-line interface niceties for this service."""
+
+import logging
+import os
+import sys
+
+
+class _StdoutFilter(logging.Filter):
+
+    def filter(self, record):
+        return record.levelno <= logging.WARNING
+
+
+class _StderrFilter(logging.Filter):
+
+    def filter(self, record):
+        return record.levelno >= logging.ERROR
+
+
+def _is_dumb_terminal():
+    """Return True if on a dumb terminal."""
+    is_stdout_tty = os.isatty(sys.stdout.fileno())
+    is_term_dumb = os.environ.get('TERM', '') == 'dumb'
+    return not is_stdout_tty or is_term_dumb
+
+
+class _ColouredFormatter(logging.Formatter):
+
+    _reset = '\033[0m'
+    _level_colours = {
+        'ERROR': '\033[0;31m',  # Dark red
+    }
+
+    def format(self, record):
+        colour = self._level_colours.get(record.levelname)
+        log_message = super().format(record)
+        if colour is not None:
+            return colour + log_message + self._reset
+        else:
+            return log_message
+
+
+def configure_logging(logger_name=None, log_level=logging.INFO):
+    stdout_handler = logging.StreamHandler(stream=sys.stdout)
+    stdout_handler.addFilter(_StdoutFilter())
+    stderr_handler = logging.StreamHandler(stream=sys.stderr)
+    stderr_handler.addFilter(_StderrFilter())
+    handlers = [stdout_handler, stderr_handler]
+    if _is_dumb_terminal():
+        formatter = logging.Formatter(style='{')
+    else:
+        formatter = _ColouredFormatter(style='{')
+    logger = logging.getLogger(logger_name)
+    for handler in handlers:
+        handler.setFormatter(formatter)
+        logger.addHandler(handler)
+    logger.setLevel(log_level)
+
+    # The requests library is too noisy at INFO level.
+    if log_level == logging.DEBUG:
+        logging.getLogger('requests').setLevel(log_level)
+    else:
+        logging.getLogger('requests').setLevel(
+            max(logging.WARNING, log_level))
diff --git a/siab_client/logic/dump.py b/siab_client/logic/dump.py
index 14a27ec..554ced5 100644
--- a/siab_client/logic/dump.py
+++ b/siab_client/logic/dump.py
@@ -5,6 +5,7 @@ import codecs
 import csv
 import itertools
 import json
+import logging
 import os.path
 
 import yaml
@@ -16,6 +17,9 @@ from siab_client import (
 from siab_client import webservices as ws
 
 
+logger = logging.getLogger(__name__)
+
+
 RISK_ORDER = ['stable', 'candidate', 'beta', 'edge']
 
 
@@ -29,7 +33,7 @@ def parse_channel(channel):
 
 
 def import_dump(args):
-    print('Importing from {}.'.format(args.root))
+    logger.info('Importing from %s.', args.root)
     for snap_id in args.snap_id:
         snap_root = os.path.join(args.root, snap_id)
         _import_snap(snap_root)
@@ -38,7 +42,7 @@ def import_dump(args):
 def _import_snap(dir):
     with open(os.path.join(dir, 'snap.json')) as f:
         snap_meta = json.loads(f.read())
-    print(' {} -> {}'.format(snap_meta['snap_id'], snap_meta['name']))
+    logger.info(' %s -> %s', snap_meta['snap_id'], snap_meta['name'])
 
     # XXX: Series and authority hardcoded.
     error = ws.register_snap_name_and_blob(
@@ -134,7 +138,7 @@ def import_snapsection_dump(args):
     Assumes tsv takes form:
     snap_id\tfeatured\tscore\tsection_name
     """
-    print('Importing snapsections from {}.'.format(args.tsv_file))
+    logger.info('Importing snapsections from %s.', args.tsv_file)
 
     sections = {}
     with open(args.tsv_file, 'r') as tsvin:
diff --git a/siab_client/logic/upload.py b/siab_client/logic/upload.py
index 6dda1f6..86264c0 100644
--- a/siab_client/logic/upload.py
+++ b/siab_client/logic/upload.py
@@ -1,6 +1,7 @@
 # Copyright 2017 Canonical Ltd.
 
 import hashlib
+import logging
 import os
 import random
 import shutil
@@ -21,6 +22,9 @@ if sys.version < '3.6':
     import sha3  # noqa
 
 
+logger = logging.getLogger(__name__)
+
+
 def upload_snap(args):
     snap_path = args.snap
     with tempfile.TemporaryDirectory() as workdir:
@@ -38,15 +42,15 @@ def upload_snap(args):
 
         snap_yaml = _read_snap_yaml(workdir, snap_path)
 
-        print("Name: %s" % name)
-        print("version: %s" % version)
-        print("Summary: %s" % summary)
-        print("description: %s" % description)
-        print("Confinement: %s" % confinement)
-        print("Architectures: %s" % ', '.join(architectures))
-        print("Sha3_384: %s" % sha3_384)
-        print("Sha512: %s" % sha512)
-        print("Binary filesize: %d" % binary_filesize)
+        logger.info("Name: %s", name)
+        logger.info("Version: %s", version)
+        logger.info("Summary: %s", summary)
+        logger.info("Description: %s", description)
+        logger.info("Confinement: %s", confinement)
+        logger.info("Architectures: %s", ', '.join(architectures))
+        logger.info("Sha3_384: %s", sha3_384)
+        logger.info("Sha512: %s", sha512)
+        logger.info("Binary filesize: %d", binary_filesize)
 
         series = '16'
 
@@ -66,7 +70,7 @@ def upload_snap(args):
         latest_revision = ws.get_latest_revision_for_snap_id(snap_id)
         next_revision = latest_revision + 1 if latest_revision else 1
         binary_path = _store_snap(snap_path, name, next_revision)
-        print("Binary file path: %s" % binary_path)
+        logger.info("Binary file path: %s", binary_path)
         registration_success = ws.create_revision(
             snap_id,
             next_revision,
diff --git a/siab_client/tests/test_cli.py b/siab_client/tests/test_cli.py
new file mode 100644
index 0000000..18b7b8d
--- /dev/null
+++ b/siab_client/tests/test_cli.py
@@ -0,0 +1,64 @@
+# Copyright 2017 Canonical Ltd.
+
+import logging
+
+import fixtures
+from testtools import TestCase
+
+from siab_client import cli
+
+
+class ConfigureLoggingTests(TestCase):
+
+    def setUp(self):
+        super().setUp()
+        self.logger = logging.getLogger(__name__)
+        self.addCleanup(
+            self._restoreLogger,
+            self.logger, self.logger.level, list(self.logger.handlers))
+        self.stdout = self.useFixture(fixtures.StringStream('stdout')).stream
+        self.stdout.fileno = lambda: 1
+        self.useFixture(fixtures.MonkeyPatch('sys.stdout', self.stdout))
+        self.stderr = self.useFixture(fixtures.StringStream('stderr')).stream
+        self.useFixture(fixtures.MonkeyPatch('sys.stderr', self.stderr))
+
+    @staticmethod
+    def _restoreLogger(logger, level, handlers):
+        logger.setLevel(logger.level)
+        for handler in list(logger.handlers):
+            logger.removeHandler(handler)
+        for handler in handlers:
+            logger.addHandler(handler)
+
+    def test_log_levels(self):
+        self.useFixture(fixtures.MonkeyPatch('os.isatty', lambda fd: True))
+        cli.configure_logging(__name__)
+        self.assertEqual(logging.INFO, self.logger.level)
+        self.logger.debug('Debug')
+        self.logger.info('Info')
+        self.logger.warning('Warning: %s', 'smoke')
+        self.logger.error('Error: %s', 'fire')
+        self.stdout.seek(0)
+        self.assertEqual('Info\nWarning: smoke\n', self.stdout.read())
+        self.stderr.seek(0)
+        self.assertEqual('\033[0;31mError: fire\033[0m\n', self.stderr.read())
+
+    def test_requests_log_level_default(self):
+        cli.configure_logging(__name__)
+        self.assertEqual(logging.WARNING, logging.getLogger('requests').level)
+
+    def test_requests_log_level_debug(self):
+        cli.configure_logging(__name__, logging.DEBUG)
+        self.assertEqual(logging.DEBUG, logging.getLogger('requests').level)
+
+    def test_requests_log_level_error(self):
+        cli.configure_logging(__name__, logging.ERROR)
+        self.assertEqual(logging.ERROR, logging.getLogger('requests').level)
+
+    def test_no_tty(self):
+        self.useFixture(fixtures.MonkeyPatch('os.isatty', lambda fd: False))
+        self.useFixture(fixtures.EnvironmentVariable('TERM', 'xterm'))
+        cli.configure_logging(__name__)
+        self.logger.error('Error: %s', 'fire')
+        self.stderr.seek(0)
+        self.assertEqual('Error: fire\n', self.stderr.read())
diff --git a/siab_client/webservices.py b/siab_client/webservices.py
index 792fd67..addfd0f 100644
--- a/siab_client/webservices.py
+++ b/siab_client/webservices.py
@@ -4,6 +4,7 @@ import base64
 import binascii
 import datetime
 import json
+import logging
 import os.path
 import urllib.parse
 
@@ -12,8 +13,11 @@ import requests
 from siab_client import config
 
 
+logger = logging.getLogger(__name__)
+
+
 def get_snap_id_for_name(snap_name, series):
-    """Return the snap_name associated with this snam_name.
+    """Return the snap_name associated with this snap_name.
 
     Returns None if the snap_name has not been associated with a snap_id yet.
     """
@@ -57,10 +61,11 @@ def register_snap_name_and_blob(snap_id, snap_name, series, snap_blob,
         urllib.parse.urljoin(ident_root, '/snaps/update'),
         json={'snaps': [data]})
     if resp.status_code == 200:
-        print(
-            "Snap '{}' ({}) registered for series '{}'.".format(
-                snap_name, snap_id, series)
+        logger.info(
+            "Snap '%s' (%s) registered for series '%s'.",
+            snap_name, snap_id, series
         )
+        return False
     else:
         _print_error_message('register snap', resp)
         return True
@@ -92,11 +97,11 @@ def release_revision(snap_id, snap_name, series, channel, arches,
         }
     )
     if resp.status_code == 200:
-        print(
-            "Snap '{}' ({}) revision {} released to series={}, "
-            "channel={}, arches={}".format(
-                snap_name, snap_id, revision, series, channel,
-                ','.join(arches))
+        logger.info(
+            "Snap '%s' (%s) revision %s released to series=%s, "
+            "channel=%s, arches=%s",
+            snap_name, snap_id, revision, series, channel,
+            ','.join(arches)
         )
     else:
         _print_error_message('release revision', resp)
@@ -151,12 +156,12 @@ def create_revision(snap_id, revision, architectures, binary_path, filesize,
         _print_error_message('create revision', resp)
         return False
 
-    print("Revision {} of {} created.".format(revision, snap_id))
+    logger.info("Revision %s of %s created.", revision, snap_id)
     return True
 
 
 def create_snapsections(payload):
-    print('Updating sections and snapsections...')
+    logger.info('Updating sections and snapsections...')
 
     snapfind_root = config.read_config()['services']['snapfind']
     snapfind_snapsection_endpoint = urllib.parse.urljoin(
@@ -164,9 +169,9 @@ def create_snapsections(payload):
 
     response = requests.post(snapfind_snapsection_endpoint, json=payload)
     if response.ok:
-        print('Done.')
+        logger.info('Done.')
     else:
-        print(response.text)
+        logger.error(response.text)
 
 
 def get_assertion(root, type_, key):
@@ -187,7 +192,7 @@ def create_or_update_assertions(
 
     if get_assertion(
             assertions_root, 'snap-declaration', (series, snap_id)) is None:
-        print("Creating snap-declaration ...")
+        logger.info("Creating snap-declaration ...")
         assertion_headers = {
             'type': 'snap-declaration',
             'revision': '0',
@@ -201,7 +206,7 @@ def create_or_update_assertions(
         assertion = sign_assertion(assertion_headers)
         save_assertion(assertion)
 
-    print("Creating snap-revision ...")
+    logger.info("Creating snap-revision ...")
     snap_sha3_384 = base64.urlsafe_b64encode(
         binascii.a2b_hex(binary_sha3_384)).decode().rstrip("=")
     snap_size = str(binary_filesize)
@@ -257,16 +262,17 @@ def sign_assertion(assertion_headers):
 
 def _print_error_message(action, response):
     """Print failure messages from other services in a standard way."""
-    print("Failed to %s:" % action)
+    logger.error("Failed to %s:", action)
     if response.status_code == 500:
-        print("Server sent 500 response.")
+        logger.error("Server sent 500 response.")
     else:
         try:
             json_document = response.json()
             for error in json_document['error_list']:
-                    print(error['message'])
+                logger.error(error['message'])
         except json.JSONDecodeError:
-            print("Server sent non-json response, printed verbatim below:")
-            print('=' * 20)
-            print(response.content)
-            print('=' * 20)
+            logger.error(
+                "Server sent non-json response, printed verbatim below:")
+            logger.error('=' * 20)
+            logger.error(response.content)
+            logger.error('=' * 20)
diff --git a/snapstore b/snapstore
index b111e94..5d66fe9 100755
--- a/snapstore
+++ b/snapstore
@@ -7,6 +7,7 @@
 import argparse
 import sys
 
+from siab_client.cli import configure_logging
 from siab_client.logic.upload import upload_snap
 from siab_client.logic.dump import (
     import_dump,
@@ -15,6 +16,7 @@ from siab_client.logic.dump import (
 
 
 def main():
+    configure_logging()
     args = parse_args()
     args.func(args)