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

[Leo Arias]

Use the python logger.

The python logger is nice. I've just done the basic config to keep the previous behaviour, but there are many options. At some point we should add an extra handler to send the logs to a file.

By using this logger, now it becomes testable too. I've added some tests, but to add the rest I need to learn a little more about snapcraft.

[Michael Vogt (mvo)]

Thanks for this branch. I like it and code-wise it looks great, just two comments inline (which are the same) where a small comment might be helpful. I +1 on this branch but I will leave the top-approve to Mike.

review: Approve

[Michael Terry (mterry)]

A) This has conflicts now

B) Does this keep the bold text output? I thought that was rather valuable for separating the non-bold output of plugin subprocesses from the bold output of snapcraft itself (bracketing plugin output when going through the stages).

I'd prefer to keep that if possible.

review: Needs Information

[Leo Arias (elopio)]

> A) This has conflicts now

and it requires sergio to add fixtures to the machine :(

> B) Does this keep the bold text output? I thought that was rather valuable
> for separating the non-bold output of plugin subprocesses from the bold output
> of snapcraft itself (bracketing plugin output when going through the stages).
>
> I'd prefer to keep that if possible.

No, it doesn't. I can do it with with separate handlers and filters, I think. Let me try.

[Leo Arias (elopio)]

> Thanks for this branch. I like it and code-wise it looks great, just two
> comments inline (which are the same) where a small comment might be helpful. I
> +1 on this branch but I will leave the top-approve to Mike.

Thanks for the review. I added comments on all the checks for the return code.

[Leo Arias (elopio)]

> A) This has conflicts now

Merged and all tests passing.

> B) Does this keep the bold text output? I thought that was rather valuable
> for separating the non-bold output of plugin subprocesses from the bold output
> of snapcraft itself (bracketing plugin output when going through the stages).
>
> I'd prefer to keep that if possible.

Now the logger format has the bold wrapper. Please check if that's what you wanted.

[lp:~elopio/snapcraft/fix1476452-python_log]

110. By Leo Arias on 2015-07-28

Merged with trunk.

[Michael Terry (mterry)]

From IRC:

<mterry> elopio, looking at your branch -- now some things are bold that weren't before
<mterry> elopio, look at the diff in LP and you can see some things were just print() lines before
 elopio, specifically when we ran a subcommand, it would not be bold
 elopio, and a couple tiny other places
 elopio, what's the cleanest way to distinguish there? Use another logger command than info?

[Leo Arias (elopio)]

> From IRC:
>
>
> <mterry> elopio, looking at your branch -- now some things are bold that
> weren't before
> <mterry> elopio, look at the diff in LP and you can see some things were just
> print() lines before
> elopio, specifically when we ran a subcommand, it would not be bold
> elopio, and a couple tiny other places
> elopio, what's the cleanest way to distinguish there? Use another logger
> command than info?l

No, I think the correct way is to define a different logger, like:
subcommand_logger = logging.getLogger(__name__ + '.subcommand')

And then we add a handler to that subcommand_logger that has a formatter without the bold wrapper.
However, if you see at the statements that use print:

66 - print(' '.join(cmd))

141 - snapcraft.common.log("Wrote the following as snapcraft.yaml.")
142 - print()
143 - print(yaml)

170 - print("Installing required packages on the host system: " + ", ".join(newPackages))

I fail to see a pattern in there that we can generalize in a logger. So maybe instead, each call to the logger should decide if it should be wrapped in bold or not. And IMO, instead of using \bold it would be clearer to use the name of the package. Like:

snapcraft log message-1
plugin.ubuntu: ubuntu log message-1
...
plugin.ubuntu: ubuntu log message-n
snapcraft log message-last

In the end, I think we should define a logging policy so we can be consistent on how to use it, and then define the logger hierarchy so it's easy to use. For now, I'll revert those lines to use print so this branch will introduce the loggers while keeping the exact same behaviour as before. And lets start the discussion.

[lp:~elopio/snapcraft/fix1476452-python_log]

111. By Leo Arias on 2015-07-29

Revert to prints for now to keep the exact same behaviour as before. Pending discussion of a hierarcy of loggers for different sources.

112. By Leo Arias on 2015-07-29

Updated the cmd test.

[Michael Terry (mterry)]

Looks good. We can go over the bold/not-bold stuff separately. I'm sure there's a nicer way to distinguish those.

review: Approve

=== modified file 'integration-tests/units/jobs.pxu'
--- integration-tests/units/jobs.pxu	2015-07-24 16:21:07 +0000
+++ integration-tests/units/jobs.pxu	2015-07-29 04:38:10 +0000
@@ -3,7 +3,7 @@
 estimated_duration: 0.1
 command:
     set -x
-    OUTPUT=$(${SNAPCRAFT} pull)
+    OUTPUT=$(${SNAPCRAFT} pull 2>&1)
     test $? = 1 || exit 1
     echo $OUTPUT | grep "Could not find snapcraft\.yaml\."
 
@@ -13,7 +13,7 @@
 command:
     set -x
     cp -rT $PLAINBOX_PROVIDER_DATA/assemble .
-    OUTPUT=$(${SNAPCRAFT} assemble)
+    OUTPUT=$(${SNAPCRAFT} assemble 2>&1)
     test $? = 1 || exit 1
     echo $OUTPUT | grep "Missing snappy metadata file"
 
@@ -123,7 +123,7 @@
 command:
     set -x
     cp -rT $PLAINBOX_PROVIDER_DATA/conflicts .
-    OUTPUT=$(${SNAPCRAFT} stage)
+    OUTPUT=$(${SNAPCRAFT} stage 2>&1)
     test $? = 1 || exit 1
     echo $OUTPUT | grep "Error: parts p1 and p2 have the following files in common: bin/test" # squished output by bash
 
@@ -146,7 +146,7 @@
     set -x
     cp -rT $PLAINBOX_PROVIDER_DATA/dependencies .
     sed -i "s/p1:/p1:\n    after: [p3]/" snapcraft.yaml
-    OUTPUT=$(${SNAPCRAFT} pull)
+    OUTPUT=$(${SNAPCRAFT} pull 2>&1)
     test $? = 1 || exit 1
     echo $OUTPUT | grep -i "circular dependency"
 

=== modified file 'snapcraft/__init__.py'
--- snapcraft/__init__.py	2015-07-24 01:23:44 +0000
+++ snapcraft/__init__.py	2015-07-29 04:38:10 +0000
@@ -14,6 +14,7 @@
 # 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 os
 import re
 import tarfile
@@ -22,6 +23,9 @@
 import snapcraft.common
 
 
+logger = logging.getLogger(__name__)
+
+
 class BasePlugin:
 
     def __init__(self, name, options):
@@ -73,7 +77,8 @@
 
     def pull_git(self, source, source_tag=None, source_branch=None):
         if source_tag and source_branch:
-            snapcraft.common.fatal("You can't specify both source-tag and source-branch for a git source (part '%s')." % self.name)
+            logger.error("You can't specify both source-tag and source-branch for a git source (part '%s')." % self.name)
+            snapcraft.common.fatal()
 
         if os.path.exists(os.path.join(self.sourcedir, ".git")):
             refspec = 'HEAD'
@@ -143,11 +148,13 @@
             elif source.startswith("git:"):
                 source_type = 'git'
             elif self.isurl(source):
-                snapcraft.common.fatal("Unrecognized source '%s' for part '%s'." % (source, self.name))
+                logger.error("Unrecognized source '%s' for part '%s'." % (source, self.name))
+                snapcraft.common.fatal()
 
         if source_type == 'bzr':
             if source_branch:
-                snapcraft.common.fatal("You can't specify source-branch for a bzr source (part '%s')." % self.name)
+                logger.error("You can't specify source-branch for a bzr source (part '%s')." % self.name)
+                snapcraft.common.fatal()
             if not self.pull_bzr(source, source_tag=source_tag):
                 return False
             if not self.run(['cp', '-Trfa', self.sourcedir, self.builddir]):
@@ -159,9 +166,11 @@
                 return False
         elif source_type == 'tar':
             if source_branch:
-                snapcraft.common.fatal("You can't specify source-branch for a tar source (part '%s')." % self.name)
+                logger.error("You can't specify source-branch for a tar source (part '%s')." % self.name)
+                snapcraft.common.fatal()
             if source_tag:
-                snapcraft.common.fatal("You can't specify source-tag for a tar source (part '%s')." % self.name)
+                logger.error("You can't specify source-tag for a tar source (part '%s')." % self.name)
+                snapcraft.common.fatal()
             if not self.pull_tarball(source):
                 return False
             if not self.extract_tarball(source):

=== modified file 'snapcraft/cmds.py'
--- snapcraft/cmds.py	2015-07-22 21:05:20 +0000
+++ snapcraft/cmds.py	2015-07-29 04:38:10 +0000
@@ -15,6 +15,7 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 import glob
+import logging
 import os
 import shlex
 import snapcraft.common
@@ -27,9 +28,12 @@
 import yaml
 
 
+logger = logging.getLogger(__name__)
+
+
 def init(args):
     if os.path.exists("snapcraft.yaml"):
-        snapcraft.common.log("snapcraft.yaml already exists!", file=sys.stderr)
+        logger.error('snapcraft.yaml already exists!')
         sys.exit(1)
     yaml = 'parts:\n'
     for part_name in args.part:
@@ -41,7 +45,7 @@
     yaml = yaml.strip()
     with open('snapcraft.yaml', mode='w+') as f:
         f.write(yaml)
-    snapcraft.common.log("Wrote the following as snapcraft.yaml.")
+    logger.info('Wrote the following as snapcraft.yaml.')
     print()
     print(yaml)
     sys.exit(0)
@@ -84,7 +88,7 @@
         snapcraft.common.run(
             ['cp', '-arvT', config.data['snappy-metadata'], snapcraft.common.snapdir + '/meta'])
     if not os.path.exists('snap/meta/package.yaml'):
-        snapcraft.common.log("Missing snappy metadata file 'meta/package.yaml'.  Try specifying 'snappy-metadata' in snapcraft.yaml, pointing to a meta directory in your source tree.")
+        logger.error("Missing snappy metadata file 'meta/package.yaml'.  Try specifying 'snappy-metadata' in snapcraft.yaml, pointing to a meta directory in your source tree.")
         sys.exit(1)
 
     # wrap all included commands
@@ -186,7 +190,7 @@
         for otherPartName in partsFiles:
             common = partFiles & partsFiles[otherPartName]
             if common:
-                snapcraft.common.log("Error: parts %s and %s have the following files in common:\n  %s" % (otherPartName, part.names()[0], '\n  '.join(sorted(common))))
+                logger.error('Error: parts %s and %s have the following files in common:\n  %s' % (otherPartName, part.names()[0], '\n  '.join(sorted(common))))
                 return False
 
         # And add our files to the list
@@ -232,5 +236,5 @@
             snapcraft.common.env = config.build_env_for_part(part)
             force = forceAll or cmd == forceCommand
             if not getattr(part, cmd)(force=force):
-                snapcraft.common.log("Failed doing %s for %s!" % (cmd, part.names()[0]))
+                logger.error('Failed doing %s for %s!' % (cmd, part.names()[0]))
                 sys.exit(1)

=== modified file 'snapcraft/common.py'
--- snapcraft/common.py	2015-07-14 21:15:07 +0000
+++ snapcraft/common.py	2015-07-29 04:38:10 +0000
@@ -39,12 +39,7 @@
         return subprocess.call(['/bin/sh', f.name] + cmd, **kwargs) == 0
 
 
-def log(msg, file=None):
-    print('\033[01m' + msg + '\033[0m', file=None)
-
-
 def fatal(msg):
-    log(msg, file=sys.stderr)
     sys.exit(1)
 
 

=== modified file 'snapcraft/main.py'
--- snapcraft/main.py	2015-07-17 17:19:04 +0000
+++ snapcraft/main.py	2015-07-29 04:38:10 +0000
@@ -16,12 +16,20 @@
 # 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'
+
+
 def main():
+    logging.basicConfig(
+        format=_COLOR_BOLD + '%(message)s' + _COLOR_END, level=logging.INFO)
+
     root_parser = argparse.ArgumentParser()
     subparsers = root_parser.add_subparsers(dest='cmd')
 

=== modified file 'snapcraft/plugin.py'
--- snapcraft/plugin.py	2015-07-22 18:59:28 +0000
+++ snapcraft/plugin.py	2015-07-29 04:38:10 +0000
@@ -16,6 +16,7 @@
 
 import glob
 import importlib
+import logging
 import os
 import snapcraft
 import snapcraft.common
@@ -23,6 +24,9 @@
 import yaml
 
 
+logger = logging.getLogger(__name__)
+
+
 def is_local_plugin(name):
     return name.startswith("x-")
 
@@ -69,7 +73,7 @@
     def _load_config(self, name):
         configPath = os.path.join(plugindir(name), name + ".yaml")
         if not os.path.exists(configPath):
-            snapcraft.common.log("Unknown plugin %s" % name, file=sys.stderr)
+            logger.error("Unknown plugin %s" % name)
             raise PluginError()
         with open(configPath, 'r') as fp:
             self.config = yaml.load(fp) or {}
@@ -86,7 +90,7 @@
                 setattr(options, attrname, properties[opt])
             else:
                 if opt_parameters.get('required', False):
-                    snapcraft.common.log("Required field %s missing on part %s" % (opt, name), file=sys.stderr)
+                    logger.error("Required field %s missing on part %s" % (opt, name))
                     raise PluginError()
                 setattr(options, attrname, None)
 
@@ -147,7 +151,7 @@
         return self.part_names
 
     def notify_stage(self, stage, hint=''):
-        snapcraft.common.log(stage + " " + self.part_names[0] + hint)
+        logger.info(stage + " " + self.part_names[0] + hint)
 
     def is_dirty(self, stage):
         try:
@@ -274,6 +278,6 @@
 def load_plugin(part_name, plugin_name, properties={}, load_code=True):
     part = PluginHandler(plugin_name, part_name, properties, load_code=load_code)
     if not part.is_valid():
-        snapcraft.common.log("Could not load part %s" % plugin_name, file=sys.stderr)
+        logger.error("Could not load part %s" % plugin_name)
         sys.exit(1)
     return part

=== modified file 'snapcraft/plugins/ant_project.py'
--- snapcraft/plugins/ant_project.py	2015-07-22 18:23:16 +0000
+++ snapcraft/plugins/ant_project.py	2015-07-29 04:38:10 +0000
@@ -15,10 +15,15 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 import glob
+import logging
 import os
+import sys
+
 import snapcraft
 import snapcraft.common
-import sys
+
+
+logger = logging.getLogger(__name__)
 
 
 class AntProjectPlugin(snapcraft.BasePlugin):
@@ -31,7 +36,7 @@
             return False
         files = glob.glob(os.path.join(self.builddir, 'target', '*.jar'))
         if not files:
-            snapcraft.common.log('Could not find any built jar files for part %s' % self.name)
+            logger.error('Could not find any built jar files for part %s' % self.name)
             sys.exit(1)
         jardir = os.path.join(self.installdir, 'jar')
         return self.run(['mkdir', '-p', jardir]) and \

=== modified file 'snapcraft/plugins/copy.py'
--- snapcraft/plugins/copy.py	2015-07-22 14:55:48 +0000
+++ snapcraft/plugins/copy.py	2015-07-29 04:38:10 +0000
@@ -14,11 +14,15 @@
 # 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 os
 
 import snapcraft
 
 
+logger = logging.getLogger(__name__)
+
+
 class CopyPlugin(snapcraft.BasePlugin):
 
     def build(self):
@@ -26,7 +30,7 @@
         for src in sorted(self.options.files):
             dst = self.options.files[src]
             if not os.path.lexists(src):
-                snapcraft.common.log("WARNING: file '%s' missing" % src)
+                logger.warning("WARNING: file '%s' missing" % src)
                 res = False
                 continue
             dst = os.path.join(self.installdir, dst)

=== modified file 'snapcraft/plugins/ubuntu.py'
--- snapcraft/plugins/ubuntu.py	2015-07-22 18:23:16 +0000
+++ snapcraft/plugins/ubuntu.py	2015-07-29 04:38:10 +0000
@@ -14,12 +14,18 @@
 # 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 apt
+import logging
 import os
-import snapcraft.common
 import subprocess
 import sys
 
+import apt
+
+import snapcraft.common
+
+
+logger = logging.getLogger(__name__)
+
 
 class UbuntuPlugin(snapcraft.BasePlugin):
 
@@ -32,7 +38,7 @@
         else:
             # User didn't specify a package, use the part name
             if name == 'ubuntu':
-                snapcraft.common.log("Part %s needs either a package option or a name" % name)
+                logger.error('Part %s needs either a package option or a name' % name)
                 sys.exit(1)
             self.included_packages.append(name)
 
@@ -83,7 +89,7 @@
         for p in packages:
             if p not in alldeps:
                 exit = True
-                snapcraft.common.log("Package %s not recognized" % p, file=sys.stderr)
+                logger.error('Package %s not recognized' % p, file=sys.stderr)
         if exit:
             sys.exit(1)
 

=== modified file 'snapcraft/tests/test_cmds.py'
--- snapcraft/tests/test_cmds.py	2015-07-15 09:00:46 +0000
+++ snapcraft/tests/test_cmds.py	2015-07-29 04:38:10 +0000
@@ -14,18 +14,23 @@
 # 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 os
 import tempfile
 from unittest import mock
 
-from snapcraft.cmds import check_for_collisions
+import fixtures
+
+from snapcraft import cmds
 from snapcraft.tests import TestCase
 
 
 class TestCommands(TestCase):
 
-    @mock.patch('snapcraft.common.log')
-    def test_check_for_collisions(self, logmock):
+    def test_check_for_collisions(self):
+        fake_logger = fixtures.FakeLogger(level=logging.ERROR)
+        self.useFixture(fake_logger)
+
         tmpdirObject = tempfile.TemporaryDirectory()
         self.addCleanup(tmpdirObject.cleanup)
         tmpdir = tmpdirObject.name
@@ -52,8 +57,40 @@
         open(part3.installdir + '/1', mode='w').close()
         open(part3.installdir + '/a/2', mode='w').close()
 
-        self.assertTrue(check_for_collisions([part1, part2]))
-        self.assertFalse(logmock.called)
-
-        self.assertFalse(check_for_collisions([part1, part2, part3]))
-        logmock.assert_called_with("Error: parts part2 and part3 have the following files in common:\n  1\n  a/2")
+        self.assertTrue(cmds.check_for_collisions([part1, part2]))
+        self.assertEqual('', fake_logger.output)
+
+        self.assertFalse(cmds.check_for_collisions([part1, part2, part3]))
+        self.assertEqual(
+            'Error: parts part2 and part3 have the following files in common:\n'
+            '  1\n'
+            '  a/2\n',
+            fake_logger.output)
+
+
+class InitTestCase(TestCase):
+
+    def test_init_with_existing_snapcraft_yaml_must_fail(self):
+        fake_logger = fixtures.FakeLogger(level=logging.ERROR)
+        self.useFixture(fake_logger)
+
+        open('snapcraft.yaml', 'w').close()
+
+        with self.assertRaises(SystemExit) as raised:
+            cmds.init('dummy args')
+        self.assertEqual(raised.exception.code, 1, 'Wrong exit code returned.')
+        self.assertEqual(
+            'snapcraft.yaml already exists!\n', fake_logger.output)
+
+    def test_init_without_parts_must_write_snapcraft_yaml(self):
+        fake_logger = fixtures.FakeLogger(level=logging.INFO)
+        self.useFixture(fake_logger)
+
+        snap_without_parts = type('obj', (object, ), {'part': []})
+        with self.assertRaises(SystemExit) as raised:
+            cmds.init(snap_without_parts)
+
+        self.assertEqual(raised.exception.code, 0, 'Wrong exit code returned.')
+        self.assertEqual(
+            'Wrote the following as snapcraft.yaml.\n',
+            fake_logger.output)

=== modified file 'snapcraft/tests/test_copy_plugin.py'
--- snapcraft/tests/test_copy_plugin.py	2015-07-22 21:05:20 +0000
+++ snapcraft/tests/test_copy_plugin.py	2015-07-29 04:38:10 +0000
@@ -14,11 +14,11 @@
 # 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 os.path
-from unittest.mock import (
-    Mock,
-    patch,
-)
+from unittest.mock import Mock
+
+import fixtures
 
 from snapcraft.plugins.copy import CopyPlugin
 from snapcraft.tests import TestCase
@@ -43,12 +43,17 @@
         }
         open("zzz", "w").close()
         c = CopyPlugin("copy", self.mock_options)
-        with patch("snapcraft.common.log") as mock_log:
-            res = c.build()
-            self.assertFalse(res)
-            mock_log.assert_called_with("WARNING: file 'src' missing")
+
+        fake_logger = fixtures.FakeLogger(level=logging.WARNING)
+        self.useFixture(fake_logger)
+
+        res = c.build()
+        self.assertFalse(res)
+        self.assertEqual("WARNING: file 'src' missing\n", fake_logger.output)
 
     def test_copy_plugin_copies(self):
+        self.useFixture(fixtures.FakeLogger())
+
         self.mock_options.files = {
             "src": "dst",
         }
@@ -59,6 +64,8 @@
         self.assertTrue(os.path.exists(os.path.join(self.dst_prefix, "dst")))
 
     def test_copy_plugin_creates_prefixes(self):
+        self.useFixture(fixtures.FakeLogger())
+
         self.mock_options.files = {
             "src": "dir/dst",
         }

=== modified file 'snapcraft/tests/test_plugin.py'
--- snapcraft/tests/test_plugin.py	2015-07-22 21:05:20 +0000
+++ snapcraft/tests/test_plugin.py	2015-07-29 04:38:10 +0000
@@ -14,25 +14,29 @@
 # 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 os
 import sys
 import tempfile
 
+import fixtures
 from unittest.mock import (
     Mock,
     patch,
 )
 
+import snapcraft.tests.mock_plugin
 from snapcraft.plugin import PluginHandler, PluginError
 from snapcraft.tests import TestCase
 
-import snapcraft.tests.mock_plugin
-
 
 class TestPlugin(TestCase):
 
+    def get_test_plugin(self):
+        return PluginHandler('mock', 'mock-part', {}, load_config=False, load_code=False)
+
     def test_is_dirty(self):
-        p = PluginHandler("mock", "mock-part", {}, load_config=False, load_code=False)
+        p = self.get_test_plugin()
         p.statefile = tempfile.NamedTemporaryFile().name
         self.addCleanup(os.remove, p.statefile)
         p.code = Mock()
@@ -45,7 +49,7 @@
         self.assertFalse(p.code.pull.called)
 
     def test_collect_snap_files(self):
-        p = PluginHandler("mock", "mock-part", {}, load_config=False, load_code=False)
+        p = self.get_test_plugin()
 
         tmpdirObject = tempfile.TemporaryDirectory()
         self.addCleanup(tmpdirObject.cleanup)
@@ -92,6 +96,15 @@
             set(['1', '1/1a', '1/1a/1b', '2', '2/2a']),
             set()))
 
+    def test_notify_stage_must_log_information(self):
+        fake_logger = fixtures.FakeLogger(level=logging.INFO)
+        self.useFixture(fake_logger)
+
+        plugin = self.get_test_plugin()
+        plugin.notify_stage('test stage')
+
+        self.assertEqual('test stage mock-part\n', fake_logger.output)
+
     def test_local_plugins(self):
         """Ensure local plugins are loaded from parts/plugins"""
         def mock_import_modules(module_name):

=== modified file 'snapcraft/tests/test_yaml.py'
--- snapcraft/tests/test_yaml.py	2015-07-17 17:00:18 +0000
+++ snapcraft/tests/test_yaml.py	2015-07-29 04:38:10 +0000
@@ -14,15 +14,14 @@
 # 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 os
 import tempfile
 import unittest
-from unittest.mock import (
-    patch,
-)
+
+import fixtures
 
 from snapcraft.yaml import Config
-
 from snapcraft.tests import TestCase
 
 
@@ -46,16 +45,24 @@
             "package": "fswebcam",
         })
 
-    @patch("snapcraft.common.log")
-    def test_config_raises_on_missing_snapcraft_yaml(self, mock_log):
+    def test_config_raises_on_missing_snapcraft_yaml(self):
+        fake_logger = fixtures.FakeLogger(level=logging.ERROR)
+        self.useFixture(fake_logger)
+
         # no snapcraft.yaml
-        with self.assertRaises(SystemExit):
+        with self.assertRaises(SystemExit) as raised:
             Config()
-        mock_log.assert_called_with("""Could not find snapcraft.yaml.  Are you sure you're in the right directory?
-To start a new project, use 'snapcraft init'""")
-
-    @patch("snapcraft.common.log")
-    def test_config_loop(self, mock_log):
+
+        self.assertEqual(raised.exception.code, 1, 'Wrong exit code returned.')
+        self.assertEqual(
+            "Could not find snapcraft.yaml.  Are you sure you're in the right directory?\n"
+            "To start a new project, use 'snapcraft init'\n",
+            fake_logger.output)
+
+    def test_config_loop(self):
+        fake_logger = fixtures.FakeLogger(level=logging.ERROR)
+        self.useFixture(fake_logger)
+
         self.make_snapcraft_yaml("""parts:
   p1:
     plugin: ubuntu
@@ -64,6 +71,8 @@
     plugin: ubuntu
     after: [p1]
 """)
-        with self.assertRaises(SystemExit):
+        with self.assertRaises(SystemExit) as raised:
             Config()
-        mock_log.assert_called_with("Circular dependency chain!")
+
+        self.assertEqual(raised.exception.code, 1, 'Wrong exit code returned.')
+        self.assertEqual('Circular dependency chain!\n', fake_logger.output)

=== modified file 'snapcraft/yaml.py'
--- snapcraft/yaml.py	2015-07-22 13:57:19 +0000
+++ snapcraft/yaml.py	2015-07-29 04:38:10 +0000
@@ -14,10 +14,16 @@
 # 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
+
+import yaml
+
 import snapcraft.common
 import snapcraft.plugin
-import sys
-import yaml
+
+
+logger = logging.getLogger(__name__)
 
 
 class Config:
@@ -31,7 +37,7 @@
             with open("snapcraft.yaml", 'r') as fp:
                 self.data = yaml.load(fp)
         except FileNotFoundError:
-            snapcraft.common.log("Could not find snapcraft.yaml.  Are you sure you're in the right directory?\nTo start a new project, use 'snapcraft init'")
+            logger.error("Could not find snapcraft.yaml.  Are you sure you're in the right directory?\nTo start a new project, use 'snapcraft init'")
             sys.exit(1)
         self.build_tools = self.data.get('build-tools', [])
 
@@ -75,7 +81,7 @@
                         foundIt = True
                         break
                 if not foundIt:
-                    snapcraft.common.log("Could not find part name %s" % dep)
+                    logger.error("Could not find part name %s" % dep)
                     sys.exit(1)
 
         # Now sort them (this is super inefficient, but easy-ish to follow)
@@ -92,7 +98,7 @@
                     topPart = part
                     break
             if not topPart:
-                snapcraft.common.log("Circular dependency chain!")
+                logger.error("Circular dependency chain!")
                 sys.exit(1)
             sortedParts = [topPart] + sortedParts
             self.all_parts.remove(topPart)