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

[Leo Arias]

Added filters to better handle the bold in the log.

Here again I went the extra mile to keep the existing behaviour. But this stuff opens the way to fancier and consistent logging, so we can change it whenever we like.

[Michael Terry (mterry)]

This handles the specific case of the "Wrote the following as snapcraft.yaml:" message. But it feels a bit too magic to me. Doesn't it feel weird to automatically bold things based on whether a colon-newline appears in the string?

This also doesn't address the other print() statements (like when we run a subcommand.

Wouldn't it make more sense to have an argument to the info() call (maybe provided by a subclassed Logger class from snapcraft.log)?

[Leo Arias (elopio)]

> Wouldn't it make more sense to have an argument to the info() call (maybe
> provided by a subclassed Logger class from snapcraft.log)?

That was my first approach, extending the Format class. But then it breaks the original behaviour, where all the args and kwars passed will be used to create the string. Like:
logger.info('test {} {var}', 'v1', var='v2')

If you prefer handling the arguments ourselfs, I can easily revert.

[Leo Arias (elopio)]

> This also doesn't address the other print() statements (like when we run a
> subcommand.

That's the following branch. Looking for some free time to do it.
What I have in mind for that is to have a separate logger, named like __name__ + '.plugin'
Using a namespace, I can easily set a different format for it, without the bold.

[Sergio Schvezov (sergiusens)]

what is the gain here?

[Leo Arias (elopio)]

By putting it into a filter then all the logs we send will follow the same style. The alternatives require the caller to know too much about the formatting specifics, which will result in inconsistencies.

[Sergio Schvezov (sergiusens)]

I'll take another look at this if you merge with trunk again.

Unmerged revisions

116. By Leo Arias on 2015-07-30

Added filters to better handle the bold in the log.

=== modified file 'snapcraft/cmds.py'
--- snapcraft/cmds.py	2015-07-29 15:21:18 +0000
+++ snapcraft/cmds.py	2015-07-30 21:43:43 +0000
@@ -47,9 +47,7 @@
     yaml = yaml.strip()
     with open('snapcraft.yaml', mode='w+') as f:
         f.write(yaml)
-    logger.info('Wrote the following as snapcraft.yaml.')
-    print()
-    print(yaml)
+    logger.info('Wrote the following as snapcraft.yaml:\n%s', yaml)
     sys.exit(0)
 
 

=== modified file 'snapcraft/log.py'
--- snapcraft/log.py	2015-07-30 21:43:43 +0000
+++ snapcraft/log.py	2015-07-30 21:43:43 +0000
@@ -23,6 +23,20 @@
 _COLOR_END = '\033[0m'
 
 
+class _BoldFilter(logging.Filter):
+
+    def filter(self, record):
+        record.msg = _wrap_bold(record.msg)
+        return super().filter(record)
+
+
+class _HeaderBoldFilter(logging.Filter):
+
+    def filter(self, record):
+        record.msg = _wrap_header_bold(record.msg)
+        return super().filter(record)
+
+
 class _StdoutFilter(logging.Filter):
 
     def filter(self, record):
@@ -35,18 +49,25 @@
         return record.levelno >= logging.ERROR
 
 
+def _wrap_bold(string):
+    return _COLOR_BOLD + string + _COLOR_END
+
+
+def _wrap_header_bold(string):
+    header, sep, rest = string.partition(':\n')
+    return _wrap_bold(header + sep) + rest
+
+
 def configure(logger_name=None):
     stdout_handler = logging.StreamHandler(stream=sys.stdout)
     stdout_handler.addFilter(_StdoutFilter())
+    stdout_handler.addFilter(_HeaderBoldFilter())
     stderr_handler = logging.StreamHandler(stream=sys.stderr)
     stderr_handler.addFilter(_StderrFilter())
-    handlers = [stdout_handler, stderr_handler]
+    stderr_handler.addFilter(_BoldFilter())
 
-    formatter = logging.Formatter(
-        _COLOR_BOLD + '{msg}' + _COLOR_END, style='{')
     logger = logging.getLogger(logger_name)
-    for handler in handlers:
-        handler.setFormatter(formatter)
+    for handler in [stdout_handler, stderr_handler]:
         logger.addHandler(handler)
 
     logger.setLevel(logging.INFO)

=== modified file 'snapcraft/tests/test_cmds.py'
--- snapcraft/tests/test_cmds.py	2015-07-29 15:21:18 +0000
+++ snapcraft/tests/test_cmds.py	2015-07-30 21:43:43 +0000
@@ -95,7 +95,8 @@
 
         self.assertEqual(raised.exception.code, 0, 'Wrong exit code returned.')
         self.assertEqual(
-            'Wrote the following as snapcraft.yaml.\n',
+            'Wrote the following as snapcraft.yaml:\n'
+            'parts:\n',
             fake_logger.output)
 
 

=== modified file 'snapcraft/tests/test_log.py'
--- snapcraft/tests/test_log.py	2015-07-30 21:43:43 +0000
+++ snapcraft/tests/test_log.py	2015-07-30 21:43:43 +0000
@@ -84,3 +84,16 @@
             '\033[1mTest critical\033[0m\n')
         self.assertEqual(expected_out, mock_stdout.getvalue())
         self.assertEqual(expected_err, mock_stderr.getvalue())
+
+    def test_log_with_args_must_only_make_message_bold(self, _, mock_stdout):
+        logger_name = self.id()
+        log.configure(logger_name)
+        logger = logging.getLogger(logger_name)
+
+        logger.info('Test info:\n%s\n%s', 'args1', 'args2')
+
+        expected_out = (
+            '\033[1mTest info:\n\033[0m'
+            'args1\n'
+            'args2\n')
+        self.assertEqual(expected_out, mock_stdout.getvalue())