Merge lp:~elopio/snapcraft/log_handler into lp:~snappy-dev/snapcraft/core

[Leo Arias]

Send error logs to stderr and message logs to stdout.

On the original logging prints, some messages went to stdout and some to stderr. That was not consistent, nor tested. So this branch adds two handlers to recover that behavoiur, but cleaner.

[lp:~elopio/snapcraft/log_handler]

115. By Leo Arias on 2015-07-30

Added the test file.

[Michael Terry (mterry)]

LGTM, thanks Leo! And nice that we have a separate log module for any future additions.

review: Approve

=== added file 'snapcraft/log.py'
--- snapcraft/log.py	1970-01-01 00:00:00 +0000
+++ snapcraft/log.py	2015-07-30 14:52:01 +0000
@@ -0,0 +1,52 @@
+#!/usr/bin/python3
+# -*- Mode:Python; indent-tabs-mode:nil; tab-width:4 -*-
+#
+# Copyright (C) 2015 Canonical Ltd
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License version 3 as
+# published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+import logging
+import sys
+
+
+_COLOR_BOLD = '\033[1m'
+_COLOR_END = '\033[0m'
+
+
+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 configure(logger_name=None):
+    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]
+
+    formatter = logging.Formatter(
+        _COLOR_BOLD + '{msg}' + _COLOR_END, style='{')
+    logger = logging.getLogger(logger_name)
+    for handler in handlers:
+        handler.setFormatter(formatter)
+        logger.addHandler(handler)
+
+    logger.setLevel(logging.INFO)

=== modified file 'snapcraft/main.py'
--- snapcraft/main.py	2015-07-23 14:32:16 +0000
+++ snapcraft/main.py	2015-07-30 14:52:01 +0000
@@ -16,20 +16,14 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 import argparse
-import logging
 import sys
 
 import snapcraft.cmds
-
-
-_COLOR_BOLD = '\033[1m'
-_COLOR_END = '\033[0m'
+from snapcraft import log
 
 
 def main():
-    logging.basicConfig(
-        format=_COLOR_BOLD + '%(message)s' + _COLOR_END, level=logging.INFO)
-
+    log.configure()
     root_parser = argparse.ArgumentParser()
     subparsers = root_parser.add_subparsers(dest='cmd')
 

=== added file 'snapcraft/tests/test_log.py'
--- snapcraft/tests/test_log.py	1970-01-01 00:00:00 +0000
+++ snapcraft/tests/test_log.py	2015-07-30 14:52:01 +0000
@@ -0,0 +1,86 @@
+# -*- Mode:Python; indent-tabs-mode:nil; tab-width:4 -*-
+#
+# Copyright (C) 2015 Canonical Ltd
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License version 3 as
+# published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+import io
+import logging
+from unittest import mock
+
+from snapcraft import (
+    log,
+    tests
+)
+
+
[e-mail]('sys.stdout', new_callable=io.StringIO)
[e-mail]('sys.stderr', new_callable=io.StringIO)
+class LogTestCase(tests.TestCase):
+
+    def test_configure_must_send_messages_to_stdout(
+            self, mock_stderr, mock_stdout):
+        logger_name = self.id()
+        log.configure(logger_name)
+        logger = logging.getLogger(logger_name)
+        # Overwrite the level to log everything.
+        logger.setLevel(logging.DEBUG)
+
+        logger.debug('Test debug')
+        logger.info('Test info')
+        logger.warning('Test warning')
+
+        expected_out = (
+            '\033[1mTest debug\033[0m\n'
+            '\033[1mTest info\033[0m\n'
+            '\033[1mTest warning\033[0m\n')
+        self.assertEqual(expected_out, mock_stdout.getvalue())
+        self.assertEqual('', mock_stderr.getvalue())
+
+    def test_configure_must_send_errors_to_stderr(
+            self, mock_stderr, mock_stdout):
+        logger_name = self.id()
+        log.configure(logger_name)
+        logger = logging.getLogger(logger_name)
+        # Overwrite the level to log everything.
+        logger.setLevel(logging.DEBUG)
+
+        logger.error('Test error')
+        logger.critical('Test critical')
+
+        expected_err = (
+            '\033[1mTest error\033[0m\n'
+            '\033[1mTest critical\033[0m\n')
+        self.assertEqual(expected_err, mock_stderr.getvalue())
+        self.assertEqual('', mock_stdout.getvalue())
+
+    def test_configure_must_log_info_and_higher(
+            self, mock_stderr, mock_stdout):
+        logger_name = self.id()
+        log.configure(logger_name)
+        logger = logging.getLogger(logger_name)
+
+        logger.debug('Test debug')
+        logger.info('Test info')
+        logger.warning('Test warning')
+        logger.error('Test error')
+        logger.critical('Test critical')
+
+        expected_out = (
+            '\033[1mTest info\033[0m\n'
+            '\033[1mTest warning\033[0m\n')
+        expected_err = (
+            '\033[1mTest error\033[0m\n'
+            '\033[1mTest critical\033[0m\n')
+        self.assertEqual(expected_out, mock_stdout.getvalue())
+        self.assertEqual(expected_err, mock_stderr.getvalue())