Repository: audreyr/cookiecutter (python)

Issue:
A "log what was done" option would be nice
Perhaps an option that writes a log file in the generated tree containing just the list of files created?

Pull request:
Improve logging
This PR adds sophisticated logging to cookiecutter! 😃 

``$ cookiecutter --debug-file generate-plugin.log cookiecutter-pytest-plugin``

Rather than using ``logging.basicConfig`` to set up the root logger and a handler, a ``cookiecutter`` logger with one or two handlers:

- ``StreamHandler`` logging on ``DEBUG`` or ``INFO`` based on ``--verbose``
- ``FileHandler`` logging **always** on ``DEBUG``, but only added if a file is provided via ``--debug-file=foo.log``

The idea is to allow users to optionally output information about files/directories generated w/o polluting ``stdout``. The format for ``DEBUG`` logging now also mentions the template as specified by the user to the log messages, which will come in handy especially when using the debug file .

Resolves #633 

---

While working on [cibopath](https://github.com/hackebrot/cibopath) I noticed side effects of using ``logging.basicConfig`` which luckily never caused problems in Cookiecutter. This PR solves this problem by explicitly setting up the ``cookiecutter`` logger.

```python
# -*- coding: utf-8 -*-

import logging

# This causes problems when run before basicConfig
# Comment out to see different stdout logging
# or to ``logging.getLogger('foo').info('Before basicConfig')``
logging.info('Before basicConfig')

logging.basicConfig(
    format=u'%(levelname)s: %(message)s',
    level=logging.DEBUG
)

logging.info('After basicConfig')
logging.debug('After basicConfig')
```



Patch:
diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py
index 87edc98..6db44a0 100644
--- a/cookiecutter/cli.py
+++ b/cookiecutter/cli.py
@@ -9,13 +9,13 @@ Main `cookiecutter` CLI.
 
 import os
 import sys
-import logging
 import json
 
 import click
 
 from cookiecutter import __version__
 from cookiecutter.config import USER_CONFIG_PATH
+from cookiecutter.log import configure_logger
 from cookiecutter.main import cookiecutter
 from cookiecutter.exceptions import (
     OutputDirExistsException,
@@ -27,8 +27,6 @@ from cookiecutter.exceptions import (
     RepositoryCloneFailed
 )
 
-logger = logging.getLogger(__name__)
-
 
 def version_msg():
     """Returns the Cookiecutter version, location and Python powering it."""
@@ -89,28 +87,28 @@ def validate_extra_context(ctx, param, value):
     u'--default-config', is_flag=True,
     help=u'Do not load a config file. Use the defaults instead'
 )
-def main(template, extra_context, no_input, checkout, verbose, replay,
-         overwrite_if_exists, output_dir, config_file, default_config):
+@click.option(
+    u'--debug-file', type=click.Path(), default=None,
+    help=u'File to be used as a stream for DEBUG logging',
+)
+def main(
+        template, extra_context, no_input, checkout, verbose,
+        replay, overwrite_if_exists, output_dir, config_file,
+        default_config, debug_file):
     """Create a project from a Cookiecutter project template (TEMPLATE)."""
-    if verbose:
-        logging.basicConfig(
-            format=u'%(levelname)s %(filename)s: %(message)s',
-            level=logging.DEBUG
-        )
-    else:
-        # Log info and above to console
-        logging.basicConfig(
-            format=u'%(levelname)s: %(message)s',
-            level=logging.INFO
-        )
 
-    try:
-        # If you _need_ to support a local template in a directory
-        # called 'help', use a qualified path to the directory.
-        if template == u'help':
-            click.echo(click.get_current_context().get_help())
-            sys.exit(0)
+    # If you _need_ to support a local template in a directory
+    # called 'help', use a qualified path to the directory.
+    if template == u'help':
+        click.echo(click.get_current_context().get_help())
+        sys.exit(0)
 
+    configure_logger(
+        stream_level='DEBUG' if verbose else 'INFO',
+        debug_file=debug_file,
+    )
+
+    try:
         user_config = None if default_config else config_file
 
         cookiecutter(
diff --git a/cookiecutter/find.py b/cookiecutter/find.py
index 3755bd1..ac02fb7 100644
--- a/cookiecutter/find.py
+++ b/cookiecutter/find.py
@@ -7,6 +7,8 @@ import os
 
 from .exceptions import NonTemplatedInputDirException
 
+logger = logging.getLogger(__name__)
+
 
 def find_template(repo_dir):
     """Determine which child directory of `repo_dir` is the project template.
@@ -14,7 +16,7 @@ def find_template(repo_dir):
     :param repo_dir: Local directory of newly cloned repo.
     :returns project_template: Relative path to project template.
     """
-    logging.debug('Searching {0} for the project template.'.format(repo_dir))
+    logger.debug('Searching {} for the project template.'.format(repo_dir))
 
     repo_dir_contents = os.listdir(repo_dir)
 
@@ -26,8 +28,8 @@ def find_template(repo_dir):
 
     if project_template:
         project_template = os.path.join(repo_dir, project_template)
-        logging.debug(
-            'The project template appears to be {0}'.format(project_template)
+        logger.debug(
+            'The project template appears to be {}'.format(project_template)
         )
         return project_template
     else:
diff --git a/cookiecutter/generate.py b/cookiecutter/generate.py
index e1a6a8a..56c918b 100644
--- a/cookiecutter/generate.py
+++ b/cookiecutter/generate.py
@@ -26,6 +26,8 @@ from .find import find_template
 from .utils import make_sure_path_exists, work_in, rmtree
 from .hooks import run_hook
 
+logger = logging.getLogger(__name__)
+
 
 def copy_without_render(path, context):
     """Return True if `path` matches context dict pattern.
@@ -104,7 +106,7 @@ def generate_context(context_file='cookiecutter.json', default_context=None,
     if extra_context:
         apply_overwrites_to_context(obj, extra_context)
 
-    logging.debug('Context generated is {0}'.format(context))
+    logger.debug('Context generated is {}'.format(context))
     return context
 
 
@@ -129,7 +131,7 @@ def generate_file(project_dir, infile, context, env):
     :param context: Dict for populating the cookiecutter's variables.
     :param env: Jinja2 template execution environment.
     """
-    logging.debug('Generating file {0}'.format(infile))
+    logger.debug('Processing file {}'.format(infile))
 
     # Render the path to the output file (not including the root project dir)
     outfile_tmpl = env.from_string(infile)
@@ -137,16 +139,18 @@ def generate_file(project_dir, infile, context, env):
     outfile = os.path.join(project_dir, outfile_tmpl.render(**context))
     file_name_is_empty = os.path.isdir(outfile)
     if file_name_is_empty:
-        logging.debug('The resulting file name is empty: {0}'.format(outfile))
+        logger.debug('The resulting file name is empty: {0}'.format(outfile))
         return
 
-    logging.debug('outfile is {0}'.format(outfile))
+    logger.debug('Created file at {0}'.format(outfile))
 
     # Just copy over binary files. Don't render.
-    logging.debug("Check {0} to see if it's a binary".format(infile))
+    logger.debug("Check {} to see if it's a binary".format(infile))
     if is_binary(infile):
-        logging.debug('Copying binary {0} to {1} without rendering'
-                      .format(infile, outfile))
+        logger.debug(
+            'Copying binary {} to {} without rendering'
+            ''.format(infile, outfile)
+        )
         shutil.copyfile(infile, outfile)
     else:
         # Force fwd slashes on Windows for get_template
@@ -163,7 +167,7 @@ def generate_file(project_dir, infile, context, env):
             raise
         rendered_file = tmpl.render(**context)
 
-        logging.debug('Writing {0}'.format(outfile))
+        logger.debug('Writing contents to file {}'.format(outfile))
 
         with io.open(outfile, 'w', encoding='utf-8') as fh:
             fh.write(rendered_file)
@@ -177,20 +181,24 @@ def render_and_create_dir(dirname, context, output_dir, environment,
     """Render name of a directory, create the directory, return its path."""
     name_tmpl = environment.from_string(dirname)
     rendered_dirname = name_tmpl.render(**context)
-    logging.debug('Rendered dir {0} must exist in output_dir {1}'.format(
-        rendered_dirname,
-        output_dir
-    ))
+
     dir_to_create = os.path.normpath(
         os.path.join(output_dir, rendered_dirname)
     )
 
+    logger.debug('Rendered dir {} must exist in output_dir {}'.format(
+        dir_to_create,
+        output_dir
+    ))
+
     output_dir_exists = os.path.exists(dir_to_create)
 
     if overwrite_if_exists:
         if output_dir_exists:
-            logging.debug('Output directory {} already exists,'
-                          'overwriting it'.format(dir_to_create))
+            logger.debug(
+                'Output directory {} already exists,'
+                'overwriting it'.format(dir_to_create)
+            )
     else:
         if output_dir_exists:
             msg = 'Error: "{}" directory already exists'.format(dir_to_create)
@@ -215,8 +223,10 @@ def _run_hook_from_repo_dir(repo_dir, hook_name, project_dir, context):
             run_hook(hook_name, project_dir, context)
         except FailedHookException:
             rmtree(project_dir)
-            logging.error("Stopping generation because %s"
-                          " hook script didn't exit successfully" % hook_name)
+            logger.error(
+                "Stopping generation because {} hook "
+                "script didn't exit successfully".format(hook_name)
+            )
             raise
 
 
@@ -231,7 +241,7 @@ def generate_files(repo_dir, context=None, output_dir='.',
         if it exists.
     """
     template_dir = find_template(repo_dir)
-    logging.debug('Generating project from {0}...'.format(template_dir))
+    logger.debug('Generating project from {}...'.format(template_dir))
     context = context or {}
 
     unrendered_dir = os.path.split(template_dir)[1]
@@ -260,7 +270,7 @@ def generate_files(repo_dir, context=None, output_dir='.',
     # absolute path for the target folder (project_dir)
 
     project_dir = os.path.abspath(project_dir)
-    logging.debug('project_dir is {0}'.format(project_dir))
+    logger.debug('Project directory is {}'.format(project_dir))
 
     _run_hook_from_repo_dir(repo_dir, 'pre_gen_project', project_dir, context)
 
@@ -287,8 +297,8 @@ def generate_files(repo_dir, context=None, output_dir='.',
             for copy_dir in copy_dirs:
                 indir = os.path.normpath(os.path.join(root, copy_dir))
                 outdir = os.path.normpath(os.path.join(project_dir, indir))
-                logging.debug(
-                    'Copying dir {0} to {1} without rendering'
+                logger.debug(
+                    'Copying dir {} to {} without rendering'
                     ''.format(indir, outdir)
                 )
                 shutil.copytree(indir, outdir)
@@ -318,14 +328,13 @@ def generate_files(repo_dir, context=None, output_dir='.',
                     outfile_tmpl = env.from_string(infile)
                     outfile_rendered = outfile_tmpl.render(**context)
                     outfile = os.path.join(project_dir, outfile_rendered)
-                    logging.debug(
-                        'Copying file {0} to {1} without rendering'
+                    logger.debug(
+                        'Copying file {} to {} without rendering'
                         ''.format(infile, outfile)
                     )
                     shutil.copyfile(infile, outfile)
                     shutil.copymode(infile, outfile)
                     continue
-                logging.debug('f is {0}'.format(f))
                 try:
                     generate_file(project_dir, infile, context, env)
                 except UndefinedError as err:
diff --git a/cookiecutter/hooks.py b/cookiecutter/hooks.py
index 259189a..bd39be8 100644
--- a/cookiecutter/hooks.py
+++ b/cookiecutter/hooks.py
@@ -14,6 +14,8 @@ from jinja2 import Template
 from cookiecutter import utils
 from .exceptions import FailedHookException
 
+logger = logging.getLogger(__name__)
+
 
 _HOOKS = [
     'pre_gen_project',
@@ -33,10 +35,10 @@ def find_hooks():
     """
     hooks_dir = 'hooks'
     hooks = {}
-    logging.debug('hooks_dir is {0}'.format(hooks_dir))
+    logger.debug('hooks_dir is {}'.format(hooks_dir))
 
     if not os.path.isdir(hooks_dir):
-        logging.debug('No hooks/ dir in template_dir')
+        logger.debug('No hooks/ dir in template_dir')
         return hooks
 
     for f in os.listdir(hooks_dir):
@@ -105,6 +107,7 @@ def run_hook(hook_name, project_dir, context):
     """
     script = find_hooks().get(hook_name)
     if script is None:
-        logging.debug('No hooks found')
+        logger.debug('No hooks found')
         return
+    logger.debug('Running hook {}'.format(hook_name))
     run_script_with_context(script, project_dir, context)
diff --git a/cookiecutter/log.py b/cookiecutter/log.py
new file mode 100644
index 0000000..97bd045
--- /dev/null
+++ b/cookiecutter/log.py
@@ -0,0 +1,47 @@
+# -*- coding: utf-8 -*-
+
+import logging
+import sys
+
+LOG_LEVELS = {
+    'DEBUG': logging.DEBUG,
+    'INFO': logging.INFO,
+    'WARNING': logging.WARNING,
+    'ERROR': logging.ERROR,
+    'CRITICAL': logging.CRITICAL,
+}
+
+LOG_FORMATS = {
+    'DEBUG': u'%(levelname)s %(name)s: %(message)s',
+    'INFO': u'%(levelname)s: %(message)s',
+}
+
+
+def configure_logger(stream_level='DEBUG', debug_file=None):
+    # Set up 'cookiecutter' logger
+    logger = logging.getLogger('cookiecutter')
+    logger.setLevel(logging.DEBUG)
+
+    # Remove all attached handlers, in case there was
+    # a logger with using the name 'cookiecutter'
+    del logger.handlers[:]
+
+    # Create a file handler if a log file is provided
+    if debug_file is not None:
+        debug_formatter = logging.Formatter(LOG_FORMATS['DEBUG'])
+        file_handler = logging.FileHandler(debug_file)
+        file_handler.setLevel(LOG_LEVELS['DEBUG'])
+        file_handler.setFormatter(debug_formatter)
+        logger.addHandler(file_handler)
+
+    # Get settings based on the given stream_level
+    log_formatter = logging.Formatter(LOG_FORMATS[stream_level])
+    log_level = LOG_LEVELS[stream_level]
+
+    # Create a stream handler
+    stream_handler = logging.StreamHandler(stream=sys.stdout)
+    stream_handler.setLevel(log_level)
+    stream_handler.setFormatter(log_formatter)
+    logger.addHandler(stream_handler)
+
+    return logger
diff --git a/cookiecutter/main.py b/cookiecutter/main.py
index 9f38757..b67da95 100644
--- a/cookiecutter/main.py
+++ b/cookiecutter/main.py
@@ -67,7 +67,7 @@ def cookiecutter(
         context = load(config_dict['replay_dir'], template_name)
     else:
         context_file = os.path.join(repo_dir, 'cookiecutter.json')
-        logging.debug('context_file is {0}'.format(context_file))
+        logger.debug('context_file is {}'.format(context_file))
 
         context = generate_context(
             context_file=context_file,
diff --git a/cookiecutter/utils.py b/cookiecutter/utils.py
index 7f1a847..9f661df 100644
--- a/cookiecutter/utils.py
+++ b/cookiecutter/utils.py
@@ -15,6 +15,8 @@ import os
 import stat
 import shutil
 
+logger = logging.getLogger(__name__)
+
 
 def force_delete(func, path, exc_info):
     """
@@ -44,9 +46,10 @@ def make_sure_path_exists(path):
     :param path: A directory path.
     """
 
-    logging.debug('Making sure path exists: {0}'.format(path))
+    logger.debug('Making sure path exists: {}'.format(path))
     try:
         os.makedirs(path)
+        logger.debug('Created directory at: {}'.format(path))
     except OSError as exception:
         if exception.errno != errno.EEXIST:
             return False
diff --git a/cookiecutter/vcs.py b/cookiecutter/vcs.py
index c6b3efe..7c3e4b5 100644
--- a/cookiecutter/vcs.py
+++ b/cookiecutter/vcs.py
@@ -21,6 +21,8 @@ from .exceptions import (
 from .prompt import read_user_yes_no
 from .utils import make_sure_path_exists, rmtree
 
+logger = logging.getLogger(__name__)
+
 
 BRANCH_ERRORS = [
     'error: pathspec',
@@ -42,8 +44,8 @@ def prompt_and_delete_repo(repo_dir, no_input=False):
         ok_to_delete = True
     else:
         question = (
-            "You've cloned {0} before. "
-            'Is it okay to delete and re-clone it?'
+            "You've cloned {} before. "
+            "Is it okay to delete and re-clone it?"
         ).format(repo_dir)
 
         ok_to_delete = read_user_yes_no(question, 'yes')
@@ -117,7 +119,7 @@ def clone(repo_url, checkout=None, clone_to_dir='.', no_input=False):
                                                  tail.rsplit('.git')[0]))
     elif repo_type == 'hg':
         repo_dir = os.path.normpath(os.path.join(clone_to_dir, tail))
-    logging.debug('repo_dir is {0}'.format(repo_dir))
+    logger.debug('repo_dir is {0}'.format(repo_dir))
 
     if os.path.isdir(repo_dir):
         prompt_and_delete_repo(repo_dir, no_input=no_input)
diff --git a/tox.ini b/tox.ini
index f9152e9..d8f498c 100644
--- a/tox.ini
+++ b/tox.ini
@@ -10,6 +10,7 @@ commands = py.test --cov=cookiecutter {posargs:tests}
 deps = pytest
        pytest-cov
        pytest-mock==1.1
+       pytest-catchlog
        freezegun
 
 [testenv:flake8]


Test patch:
diff --git a/tests/test_cli.py b/tests/test_cli.py
index a56a319..9d0cdef 100644
--- a/tests/test_cli.py
+++ b/tests/test_cli.py
@@ -374,3 +374,53 @@ def test_cli_extra_context_invalid_format(cli_runner):
     assert result.exit_code == 2
     assert 'Error: Invalid value for "extra_context"' in result.output
     assert 'should contain items of the form key=value' in result.output
+
+
+@pytest.fixture
+def debug_file(tmpdir):
+    return tmpdir / 'fake-repo.log'
+
+
+@pytest.mark.usefixtures('remove_fake_project_dir')
+def test_debug_file_non_verbose(cli_runner, debug_file):
+    assert not debug_file.exists()
+
+    result = cli_runner(
+        '--no-input',
+        '--debug-file',
+        str(debug_file),
+        'tests/fake-repo-pre/',
+    )
+    assert result.exit_code == 0
+
+    assert debug_file.exists()
+
+    context_log = (
+        "DEBUG cookiecutter.main: context_file is "
+        "tests/fake-repo-pre/cookiecutter.json"
+    )
+    assert context_log in debug_file.readlines(cr=False)
+    assert context_log not in result.output
+
+
+@pytest.mark.usefixtures('remove_fake_project_dir')
+def test_debug_file_verbose(cli_runner, debug_file):
+    assert not debug_file.exists()
+
+    result = cli_runner(
+        '--verbose',
+        '--no-input',
+        '--debug-file',
+        str(debug_file),
+        'tests/fake-repo-pre/',
+    )
+    assert result.exit_code == 0
+
+    assert debug_file.exists()
+
+    context_log = (
+        "DEBUG cookiecutter.main: context_file is "
+        "tests/fake-repo-pre/cookiecutter.json"
+    )
+    assert context_log in debug_file.readlines(cr=False)
+    assert context_log in result.output
diff --git a/tests/test_log.py b/tests/test_log.py
new file mode 100644
index 0000000..4448bca
--- /dev/null
+++ b/tests/test_log.py
@@ -0,0 +1,133 @@
+# -*- coding: utf-8 -*-
+
+import logging
+
+import pytest
+
+from cookiecutter.log import configure_logger
+
+
+def create_log_records():
+    cookiecutter_logger = logging.getLogger('cookiecutter')
+    foo_logger = logging.getLogger('cookiecutter.foo')
+    foobar_logger = logging.getLogger('cookiecutter.foo.bar')
+
+    cookiecutter_logger.info('Welcome to Cookiecutter')
+    cookiecutter_logger.debug('Generating project from pytest-plugin')
+    foo_logger.info('Loading user config from home dir')
+    foobar_logger.debug("I don't know.")
+    foobar_logger.debug('I wanted to save the world.')
+    foo_logger.error('Aw, snap! Something went wrong')
+    cookiecutter_logger.debug('Successfully generated project')
+
+
+@pytest.fixture
+def info_messages():
+    return [
+        'INFO: Welcome to Cookiecutter',
+        'INFO: Loading user config from home dir',
+        'ERROR: Aw, snap! Something went wrong',
+    ]
+
+
+@pytest.fixture
+def debug_messages():
+    return [
+        'INFO cookiecutter: '
+        'Welcome to Cookiecutter',
+
+        'DEBUG cookiecutter: '
+        'Generating project from pytest-plugin',
+
+        'INFO cookiecutter.foo: '
+        'Loading user config from home dir',
+
+        "DEBUG cookiecutter.foo.bar: "
+        "I don't know.",
+
+        'DEBUG cookiecutter.foo.bar: '
+        'I wanted to save the world.',
+
+        'ERROR cookiecutter.foo: '
+        'Aw, snap! Something went wrong',
+
+        'DEBUG cookiecutter: '
+        'Successfully generated project',
+    ]
+
+
+@pytest.fixture
+def info_logger():
+    return configure_logger(stream_level='INFO')
+
+
+@pytest.fixture
+def debug_logger():
+    return configure_logger(stream_level='DEBUG')
+
+
+@pytest.fixture
+def debug_file(tmpdir):
+    return tmpdir / 'pytest-plugin.log'
+
+
+@pytest.fixture
+def info_logger_with_file(debug_file):
+    return configure_logger(
+        stream_level='INFO',
+        debug_file=str(debug_file),
+    )
+
+
+def test_info_stdout_logging(caplog, info_logger, info_messages):
+    """Test that stdout logs use info format and level."""
+    [stream_handler] = info_logger.handlers
+    assert isinstance(stream_handler, logging.StreamHandler)
+    assert stream_handler.level == logging.INFO
+
+    create_log_records()
+
+    stream_messages = [
+        stream_handler.format(r)
+        for r in caplog.records
+        if r.levelno >= stream_handler.level
+    ]
+
+    assert stream_messages == info_messages
+
+
+def test_debug_stdout_logging(caplog, debug_logger, debug_messages):
+    """Test that stdout logs use debug format and level."""
+    [stream_handler] = debug_logger.handlers
+    assert isinstance(stream_handler, logging.StreamHandler)
+    assert stream_handler.level == logging.DEBUG
+
+    create_log_records()
+
+    stream_messages = [
+        stream_handler.format(r)
+        for r in caplog.records
+        if r.levelno >= stream_handler.level
+    ]
+
+    assert stream_messages == debug_messages
+
+
+def test_debug_file_logging(
+        caplog, info_logger_with_file, debug_file, debug_messages):
+    """Test that logging to stdout uses a different format and level than
+    the the file handler.
+    """
+
+    [file_handler, stream_handler] = info_logger_with_file.handlers
+    assert isinstance(file_handler, logging.FileHandler)
+    assert isinstance(stream_handler, logging.StreamHandler)
+    assert stream_handler.level == logging.INFO
+    assert file_handler.level == logging.DEBUG
+
+    create_log_records()
+
+    assert debug_file.exists()
+
+    # Last line in the log file is an empty line
+    assert debug_file.readlines(cr=False) == debug_messages + ['']