From 1ccdbaeacbfdfb197fdd8da69c0542418599a64d Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 01:41:35 +0100 Subject: [PATCH 01/17] Implement sophisticated logging for stdout and files --- cookiecutter/logging.py | 66 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 66 insertions(+) create mode 100644 cookiecutter/logging.py diff --git a/cookiecutter/logging.py b/cookiecutter/logging.py new file mode 100644 index 000000000..a8e470813 --- /dev/null +++ b/cookiecutter/logging.py @@ -0,0 +1,66 @@ +# -*- coding: utf-8 -*- + +import logging + +LOG_LEVELS = { + 'DEBUG': logging.DEBUG, + 'INFO': logging.INFO, + 'WARNING': logging.WARNING, + 'ERROR': logging.ERROR, + 'CRITICAL': logging.CRITICAL, +} + +LOG_FORMATS = { + 'DEBUG': u'%(levelname)s [%(template)s] %(name)s: %(message)s', + 'INFO': u'%(levelname)s: %(message)s', +} + + +class ContextFilter(logging.Filter): + """Logging filter that holds the name of the used template.""" + + def __init__(self, template): + super(ContextFilter, self).__init__() + self.template = template + + def filter(self, record): + """Add 'template' as extra information on a logging record.""" + record.template = self.template + return record + + +def create_logger(template, level='DEBUG', log_file=None): + # Get settings for given log level + log_level = LOG_LEVELS[level] + log_format = LOG_FORMATS[level] + + # Set up 'cookiecutter' logger + logger = logging.getLogger('cookiecutter') + logger.setLevel(log_level) + + # Remove all attached handlers, in case there was + # a logger with using the name 'cookiecutter' + del logger.handlers[:] + + # Add additional information to the logger + context_filter = ContextFilter(template) + + # Create formatter based on the given level + log_formatter = logging.Formatter(log_format) + + # Create a file handler if a log file is provided + if log_file is not None: + file_handler = logging.FileHandler(log_file) + file_handler.setLevel(log_level) + file_handler.setFormatter(log_formatter) + file_handler.addFilter(context_filter) + logger.addHandler(file_handler) + + # Create a stream handler + stream_handler = logging.StreamHandler() + stream_handler.setLevel(log_level) + stream_handler.setFormatter(log_formatter) + stream_handler.addFilter(context_filter) + logger.addHandler(stream_handler) + + return logger From 3274157296f961a30eaf37b4565070135c2585bb Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 02:01:33 +0100 Subject: [PATCH 02/17] Use new helper rather than basicConfig to set up logging --- cookiecutter/cli.py | 45 +++++++++++++++++++++++---------------------- 1 file changed, 23 insertions(+), 22 deletions(-) diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py index 87edc98bf..4a45bdaeb 100644 --- a/cookiecutter/cli.py +++ b/cookiecutter/cli.py @@ -9,13 +9,13 @@ import os import sys -import logging import json import click from cookiecutter import __version__ from cookiecutter.config import USER_CONFIG_PATH +from cookiecutter.logging import create_logger from cookiecutter.main import cookiecutter from cookiecutter.exceptions import ( OutputDirExistsException, @@ -27,8 +27,6 @@ RepositoryCloneFailed ) -logger = logging.getLogger(__name__) - def version_msg(): """Returns the Cookiecutter version, location and Python powering it.""" @@ -89,28 +87,31 @@ 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'--log-file', type=click.Path(), default=None, + help=u'File to be used as a stream for logging', +) +def main( + template, extra_context, no_input, checkout, verbose, + replay, overwrite_if_exists, output_dir, config_file, + default_config, log_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) + + template_name = os.path.basename(os.path.abspath(template)) + logger = create_logger( + template_name, + level='DEBUG' if verbose else 'INFO', + log_file=log_file, + ) + + try: user_config = None if default_config else config_file cookiecutter( From 201f3332a82b52ee64ae9d5474585e93318f9394 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 02:33:31 +0100 Subject: [PATCH 03/17] Update logging to track the package/module hierarchy --- cookiecutter/find.py | 6 ++++-- cookiecutter/generate.py | 32 +++++++++++++++++--------------- cookiecutter/hooks.py | 8 +++++--- cookiecutter/main.py | 2 +- cookiecutter/utils.py | 4 +++- cookiecutter/vcs.py | 4 +++- 6 files changed, 33 insertions(+), 23 deletions(-) diff --git a/cookiecutter/find.py b/cookiecutter/find.py index 3755bd1b5..c6f3246aa 100644 --- a/cookiecutter/find.py +++ b/cookiecutter/find.py @@ -7,6 +7,8 @@ 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 {0} for the project template.'.format(repo_dir)) repo_dir_contents = os.listdir(repo_dir) @@ -26,7 +28,7 @@ def find_template(repo_dir): if project_template: project_template = os.path.join(repo_dir, project_template) - logging.debug( + logger.debug( 'The project template appears to be {0}'.format(project_template) ) return project_template diff --git a/cookiecutter/generate.py b/cookiecutter/generate.py index e1a6a8a82..b03e3ed17 100644 --- a/cookiecutter/generate.py +++ b/cookiecutter/generate.py @@ -26,6 +26,8 @@ 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 {0}'.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('Generating file {0}'.format(infile)) # Render the path to the output file (not including the root project dir) outfile_tmpl = env.from_string(infile) @@ -137,15 +139,15 @@ 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('outfile is {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 {0} to see if it's a binary".format(infile)) if is_binary(infile): - logging.debug('Copying binary {0} to {1} without rendering' + logger.debug('Copying binary {0} to {1} without rendering' .format(infile, outfile)) shutil.copyfile(infile, outfile) else: @@ -163,7 +165,7 @@ def generate_file(project_dir, infile, context, env): raise rendered_file = tmpl.render(**context) - logging.debug('Writing {0}'.format(outfile)) + logger.debug('Writing {0}'.format(outfile)) with io.open(outfile, 'w', encoding='utf-8') as fh: fh.write(rendered_file) @@ -177,7 +179,7 @@ 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( + logger.debug('Rendered dir {0} must exist in output_dir {1}'.format( rendered_dirname, output_dir )) @@ -189,7 +191,7 @@ def render_and_create_dir(dirname, context, output_dir, environment, if overwrite_if_exists: if output_dir_exists: - logging.debug('Output directory {} already exists,' + logger.debug('Output directory {} already exists,' 'overwriting it'.format(dir_to_create)) else: if output_dir_exists: @@ -215,7 +217,7 @@ 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" + logger.error("Stopping generation because %s" " hook script didn't exit successfully" % hook_name) raise @@ -231,7 +233,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 {0}...'.format(template_dir)) context = context or {} unrendered_dir = os.path.split(template_dir)[1] @@ -260,7 +262,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_dir is {0}'.format(project_dir)) _run_hook_from_repo_dir(repo_dir, 'pre_gen_project', project_dir, context) @@ -287,7 +289,7 @@ 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( + logger.debug( 'Copying dir {0} to {1} without rendering' ''.format(indir, outdir) ) @@ -318,14 +320,14 @@ 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( + logger.debug( 'Copying file {0} to {1} without rendering' ''.format(infile, outfile) ) shutil.copyfile(infile, outfile) shutil.copymode(infile, outfile) continue - logging.debug('f is {0}'.format(f)) + logger.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 259189a94..352c25fd8 100644 --- a/cookiecutter/hooks.py +++ b/cookiecutter/hooks.py @@ -14,6 +14,8 @@ 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 {0}'.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,6 @@ 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 run_script_with_context(script, project_dir, context) diff --git a/cookiecutter/main.py b/cookiecutter/main.py index 9f387579a..08d8f17b2 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 {0}'.format(context_file)) context = generate_context( context_file=context_file, diff --git a/cookiecutter/utils.py b/cookiecutter/utils.py index 7f1a8473e..920e4f8d6 100644 --- a/cookiecutter/utils.py +++ b/cookiecutter/utils.py @@ -15,6 +15,8 @@ import stat import shutil +logger = logging.getLogger(__name__) + def force_delete(func, path, exc_info): """ @@ -44,7 +46,7 @@ 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: {0}'.format(path)) try: os.makedirs(path) except OSError as exception: diff --git a/cookiecutter/vcs.py b/cookiecutter/vcs.py index c6b3efee3..491c8550a 100644 --- a/cookiecutter/vcs.py +++ b/cookiecutter/vcs.py @@ -21,6 +21,8 @@ from .prompt import read_user_yes_no from .utils import make_sure_path_exists, rmtree +logger = logging.getLogger(__name__) + BRANCH_ERRORS = [ 'error: pathspec', @@ -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) From 087aaf3a9e99e2a60e1711cc0b1a97d778c5f995 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 03:13:28 +0100 Subject: [PATCH 04/17] Improve log messages and remove py26 left-overs --- cookiecutter/generate.py | 47 +++++++++++++++++++++++----------------- cookiecutter/hooks.py | 3 ++- cookiecutter/utils.py | 3 ++- 3 files changed, 31 insertions(+), 22 deletions(-) diff --git a/cookiecutter/generate.py b/cookiecutter/generate.py index b03e3ed17..c67acc83f 100644 --- a/cookiecutter/generate.py +++ b/cookiecutter/generate.py @@ -106,7 +106,7 @@ def generate_context(context_file='cookiecutter.json', default_context=None, if extra_context: apply_overwrites_to_context(obj, extra_context) - logger.debug('Context generated is {0}'.format(context)) + logger.debug('Context generated is {}'.format(context)) return context @@ -131,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. """ - logger.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) @@ -142,13 +142,15 @@ def generate_file(project_dir, infile, context, env): logger.debug('The resulting file name is empty: {0}'.format(outfile)) return - logger.debug('outfile is {0}'.format(outfile)) + logger.debug('Created file at {0}'.format(outfile)) # Just copy over binary files. Don't render. - logger.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): - logger.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 @@ -165,7 +167,7 @@ def generate_file(project_dir, infile, context, env): raise rendered_file = tmpl.render(**context) - logger.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) @@ -179,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) - logger.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: - logger.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) @@ -217,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) - logger.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 @@ -233,7 +241,7 @@ def generate_files(repo_dir, context=None, output_dir='.', if it exists. """ template_dir = find_template(repo_dir) - logger.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] @@ -262,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) - logger.debug('project_dir is {0}'.format(project_dir)) + logger.debug('project_dir is {}'.format(project_dir)) _run_hook_from_repo_dir(repo_dir, 'pre_gen_project', project_dir, context) @@ -290,7 +298,7 @@ def generate_files(repo_dir, context=None, output_dir='.', indir = os.path.normpath(os.path.join(root, copy_dir)) outdir = os.path.normpath(os.path.join(project_dir, indir)) logger.debug( - 'Copying dir {0} to {1} without rendering' + 'Copying dir {} to {} without rendering' ''.format(indir, outdir) ) shutil.copytree(indir, outdir) @@ -321,13 +329,12 @@ def generate_files(repo_dir, context=None, output_dir='.', outfile_rendered = outfile_tmpl.render(**context) outfile = os.path.join(project_dir, outfile_rendered) logger.debug( - 'Copying file {0} to {1} without rendering' + 'Copying file {} to {} without rendering' ''.format(infile, outfile) ) shutil.copyfile(infile, outfile) shutil.copymode(infile, outfile) continue - logger.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 352c25fd8..bd39be8e5 100644 --- a/cookiecutter/hooks.py +++ b/cookiecutter/hooks.py @@ -35,7 +35,7 @@ def find_hooks(): """ hooks_dir = 'hooks' hooks = {} - logger.debug('hooks_dir is {0}'.format(hooks_dir)) + logger.debug('hooks_dir is {}'.format(hooks_dir)) if not os.path.isdir(hooks_dir): logger.debug('No hooks/ dir in template_dir') @@ -109,4 +109,5 @@ def run_hook(hook_name, project_dir, context): if script is None: 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/utils.py b/cookiecutter/utils.py index 920e4f8d6..9f661df66 100644 --- a/cookiecutter/utils.py +++ b/cookiecutter/utils.py @@ -46,9 +46,10 @@ def make_sure_path_exists(path): :param path: A directory path. """ - logger.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 From 2fe1e2817163f1ad5cfc2f93041779cf1510480d Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 03:23:34 +0100 Subject: [PATCH 05/17] Rename cookiecutter.logging module to log --- cookiecutter/cli.py | 4 ++-- cookiecutter/{logging.py => log.py} | 0 2 files changed, 2 insertions(+), 2 deletions(-) rename cookiecutter/{logging.py => log.py} (100%) diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py index 4a45bdaeb..6f4d0d4f8 100644 --- a/cookiecutter/cli.py +++ b/cookiecutter/cli.py @@ -15,7 +15,7 @@ from cookiecutter import __version__ from cookiecutter.config import USER_CONFIG_PATH -from cookiecutter.logging import create_logger +from cookiecutter.log import create_logger from cookiecutter.main import cookiecutter from cookiecutter.exceptions import ( OutputDirExistsException, @@ -105,7 +105,7 @@ def main( template_name = os.path.basename(os.path.abspath(template)) - logger = create_logger( + create_logger( template_name, level='DEBUG' if verbose else 'INFO', log_file=log_file, diff --git a/cookiecutter/logging.py b/cookiecutter/log.py similarity index 100% rename from cookiecutter/logging.py rename to cookiecutter/log.py From 8df7a212dfe557b814617a1861b5b928bba3cdd9 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 15:31:52 +0100 Subject: [PATCH 06/17] Change logging to always log on DEBUG to file --- cookiecutter/log.py | 24 +++++++++++------------- 1 file changed, 11 insertions(+), 13 deletions(-) diff --git a/cookiecutter/log.py b/cookiecutter/log.py index a8e470813..2663e598b 100644 --- a/cookiecutter/log.py +++ b/cookiecutter/log.py @@ -29,14 +29,10 @@ def filter(self, record): return record -def create_logger(template, level='DEBUG', log_file=None): - # Get settings for given log level - log_level = LOG_LEVELS[level] - log_format = LOG_FORMATS[level] - +def create_logger(template, stream_level='DEBUG', debug_file=None): # Set up 'cookiecutter' logger logger = logging.getLogger('cookiecutter') - logger.setLevel(log_level) + logger.setLevel(logging.DEBUG) # Remove all attached handlers, in case there was # a logger with using the name 'cookiecutter' @@ -45,17 +41,19 @@ def create_logger(template, level='DEBUG', log_file=None): # Add additional information to the logger context_filter = ContextFilter(template) - # Create formatter based on the given level - log_formatter = logging.Formatter(log_format) - # Create a file handler if a log file is provided - if log_file is not None: - file_handler = logging.FileHandler(log_file) - file_handler.setLevel(log_level) - file_handler.setFormatter(log_formatter) + 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) file_handler.addFilter(context_filter) 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_handler.setLevel(log_level) From 2fd299998ea10edfe112323ae6eb051ae764b249 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 15:32:25 +0100 Subject: [PATCH 07/17] Rename command line flag for the log file --- cookiecutter/cli.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py index 6f4d0d4f8..476e14a40 100644 --- a/cookiecutter/cli.py +++ b/cookiecutter/cli.py @@ -88,13 +88,13 @@ def validate_extra_context(ctx, param, value): help=u'Do not load a config file. Use the defaults instead' ) @click.option( - u'--log-file', type=click.Path(), default=None, - help=u'File to be used as a stream for logging', + 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, log_file): + default_config, debug_file): """Create a project from a Cookiecutter project template (TEMPLATE).""" # If you _need_ to support a local template in a directory @@ -107,8 +107,8 @@ def main( create_logger( template_name, - level='DEBUG' if verbose else 'INFO', - log_file=log_file, + stream_level='DEBUG' if verbose else 'INFO', + debug_file=debug_file, ) try: From e2576ba5ab3b8edee6b2f502ef4da54bc90bf6d2 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 18:03:22 +0100 Subject: [PATCH 08/17] Implement tests for the new debug_file flag --- tests/test_cli.py | 50 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/tests/test_cli.py b/tests/test_cli.py index ca75e522a..6331a2c9f 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -374,3 +374,53 @@ def test_cli_extra_context_invalid_format(): 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(debug_file): + assert not debug_file.exists() + + result = runner.invoke(main, [ + '--no-input', + '--debug-file', + str(debug_file), + 'tests/fake-repo-pre/', + ]) + assert result.exit_code == 0 + + assert debug_file.exists() + + context_log = ( + "DEBUG [fake-repo-pre] 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(debug_file): + assert not debug_file.exists() + + result = runner.invoke(main, [ + '--verbose', + '--no-input', + '--debug-file', + str(debug_file), + 'tests/fake-repo-pre/', + ]) + assert result.exit_code == 0 + + assert debug_file.exists() + + context_log = ( + "DEBUG [fake-repo-pre] 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 From 8c1408d4c7db373f493167601c1641372d9bc060 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 19:37:25 +0100 Subject: [PATCH 09/17] Set stream to stdout --- cookiecutter/log.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/cookiecutter/log.py b/cookiecutter/log.py index 2663e598b..223e62636 100644 --- a/cookiecutter/log.py +++ b/cookiecutter/log.py @@ -1,6 +1,7 @@ # -*- coding: utf-8 -*- import logging +import sys LOG_LEVELS = { 'DEBUG': logging.DEBUG, @@ -55,7 +56,7 @@ def create_logger(template, stream_level='DEBUG', debug_file=None): log_level = LOG_LEVELS[stream_level] # Create a stream handler - stream_handler = logging.StreamHandler() + stream_handler = logging.StreamHandler(stream=sys.stdout) stream_handler.setLevel(log_level) stream_handler.setFormatter(log_formatter) stream_handler.addFilter(context_filter) From 228a4d40deeb78adf1aed66cfcbd6250292149c2 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 31 Jul 2016 22:49:02 +0100 Subject: [PATCH 10/17] Implement tests for log.py and add pytest-catchlog --- tests/test_log.py | 134 ++++++++++++++++++++++++++++++++++++++++++++++ tox.ini | 1 + 2 files changed, 135 insertions(+) create mode 100644 tests/test_log.py diff --git a/tests/test_log.py b/tests/test_log.py new file mode 100644 index 000000000..0697e84f8 --- /dev/null +++ b/tests/test_log.py @@ -0,0 +1,134 @@ +# -*- coding: utf-8 -*- + +import logging + +import pytest + +from cookiecutter.log import create_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 [pytest-plugin] cookiecutter: ' + 'Welcome to Cookiecutter', + + 'DEBUG [pytest-plugin] cookiecutter: ' + 'Generating project from pytest-plugin', + + 'INFO [pytest-plugin] cookiecutter.foo: ' + 'Loading user config from home dir', + + "DEBUG [pytest-plugin] cookiecutter.foo.bar: " + "I don't know.", + + 'DEBUG [pytest-plugin] cookiecutter.foo.bar: ' + 'I wanted to save the world.', + + 'ERROR [pytest-plugin] cookiecutter.foo: ' + 'Aw, snap! Something went wrong', + + 'DEBUG [pytest-plugin] cookiecutter: ' + 'Successfully generated project', + ] + + +@pytest.fixture +def info_logger(): + return create_logger('pytest-plugin', stream_level='INFO') + + +@pytest.fixture +def debug_logger(): + return create_logger('pytest-plugin', stream_level='DEBUG') + + +@pytest.fixture +def debug_file(tmpdir): + return tmpdir / 'pytest-plugin.log' + + +@pytest.fixture +def info_logger_with_file(debug_file): + return create_logger( + 'pytest-plugin', + 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 + [''] diff --git a/tox.ini b/tox.ini index b984fb106..9a7e3b4b4 100644 --- a/tox.ini +++ b/tox.ini @@ -10,6 +10,7 @@ commands = py.test --cov=cookiecutter {posargs:tests} deps = pytest pytest-cov pytest-mock + pytest-catchlog freezegun [testenv:flake8] From b99c67504cb23c5ff2ab99d964f1cd18756a7b16 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Mon, 1 Aug 2016 08:54:07 +0100 Subject: [PATCH 11/17] Rename logging helper function to configure_logger --- cookiecutter/cli.py | 4 ++-- cookiecutter/log.py | 2 +- tests/test_log.py | 8 ++++---- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py index 476e14a40..dfc3870a6 100644 --- a/cookiecutter/cli.py +++ b/cookiecutter/cli.py @@ -15,7 +15,7 @@ from cookiecutter import __version__ from cookiecutter.config import USER_CONFIG_PATH -from cookiecutter.log import create_logger +from cookiecutter.log import configure_logger from cookiecutter.main import cookiecutter from cookiecutter.exceptions import ( OutputDirExistsException, @@ -105,7 +105,7 @@ def main( template_name = os.path.basename(os.path.abspath(template)) - create_logger( + configure_logger( template_name, stream_level='DEBUG' if verbose else 'INFO', debug_file=debug_file, diff --git a/cookiecutter/log.py b/cookiecutter/log.py index 223e62636..c68fc1967 100644 --- a/cookiecutter/log.py +++ b/cookiecutter/log.py @@ -30,7 +30,7 @@ def filter(self, record): return record -def create_logger(template, stream_level='DEBUG', debug_file=None): +def configure_logger(template, stream_level='DEBUG', debug_file=None): # Set up 'cookiecutter' logger logger = logging.getLogger('cookiecutter') logger.setLevel(logging.DEBUG) diff --git a/tests/test_log.py b/tests/test_log.py index 0697e84f8..f618966fa 100644 --- a/tests/test_log.py +++ b/tests/test_log.py @@ -4,7 +4,7 @@ import pytest -from cookiecutter.log import create_logger +from cookiecutter.log import configure_logger def create_log_records(): @@ -58,12 +58,12 @@ def debug_messages(): @pytest.fixture def info_logger(): - return create_logger('pytest-plugin', stream_level='INFO') + return configure_logger('pytest-plugin', stream_level='INFO') @pytest.fixture def debug_logger(): - return create_logger('pytest-plugin', stream_level='DEBUG') + return configure_logger('pytest-plugin', stream_level='DEBUG') @pytest.fixture @@ -73,7 +73,7 @@ def debug_file(tmpdir): @pytest.fixture def info_logger_with_file(debug_file): - return create_logger( + return configure_logger( 'pytest-plugin', stream_level='INFO', debug_file=str(debug_file), From 5a0ba1a6eb2e1a40f123aa5681a2eb6c94c98e53 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Mon, 1 Aug 2016 20:51:53 +0100 Subject: [PATCH 12/17] Update new cli tests to use fixture from #790 --- tests/test_cli.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/tests/test_cli.py b/tests/test_cli.py index 98169cae6..55fac0258 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -382,15 +382,15 @@ def debug_file(tmpdir): @pytest.mark.usefixtures('remove_fake_project_dir') -def test_debug_file_non_verbose(debug_file): +def test_debug_file_non_verbose(cli_runner, debug_file): assert not debug_file.exists() - result = runner.invoke(main, [ + result = cli_runner( '--no-input', '--debug-file', str(debug_file), 'tests/fake-repo-pre/', - ]) + ) assert result.exit_code == 0 assert debug_file.exists() @@ -404,16 +404,16 @@ def test_debug_file_non_verbose(debug_file): @pytest.mark.usefixtures('remove_fake_project_dir') -def test_debug_file_verbose(debug_file): +def test_debug_file_verbose(cli_runner, debug_file): assert not debug_file.exists() - result = runner.invoke(main, [ + result = cli_runner( '--verbose', '--no-input', '--debug-file', str(debug_file), 'tests/fake-repo-pre/', - ]) + ) assert result.exit_code == 0 assert debug_file.exists() From 405cd4700cde85bc95362bb7ee1accff2958e439 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Fri, 19 Aug 2016 18:27:35 +0100 Subject: [PATCH 13/17] Remove context filter with template name from logger --- cookiecutter/cli.py | 3 --- cookiecutter/log.py | 22 ++-------------------- tests/test_cli.py | 4 ++-- tests/test_log.py | 19 +++++++++---------- 4 files changed, 13 insertions(+), 35 deletions(-) diff --git a/cookiecutter/cli.py b/cookiecutter/cli.py index dfc3870a6..6db44a090 100644 --- a/cookiecutter/cli.py +++ b/cookiecutter/cli.py @@ -103,10 +103,7 @@ def main( click.echo(click.get_current_context().get_help()) sys.exit(0) - template_name = os.path.basename(os.path.abspath(template)) - configure_logger( - template_name, stream_level='DEBUG' if verbose else 'INFO', debug_file=debug_file, ) diff --git a/cookiecutter/log.py b/cookiecutter/log.py index c68fc1967..97bd04581 100644 --- a/cookiecutter/log.py +++ b/cookiecutter/log.py @@ -12,25 +12,12 @@ } LOG_FORMATS = { - 'DEBUG': u'%(levelname)s [%(template)s] %(name)s: %(message)s', + 'DEBUG': u'%(levelname)s %(name)s: %(message)s', 'INFO': u'%(levelname)s: %(message)s', } -class ContextFilter(logging.Filter): - """Logging filter that holds the name of the used template.""" - - def __init__(self, template): - super(ContextFilter, self).__init__() - self.template = template - - def filter(self, record): - """Add 'template' as extra information on a logging record.""" - record.template = self.template - return record - - -def configure_logger(template, stream_level='DEBUG', debug_file=None): +def configure_logger(stream_level='DEBUG', debug_file=None): # Set up 'cookiecutter' logger logger = logging.getLogger('cookiecutter') logger.setLevel(logging.DEBUG) @@ -39,16 +26,12 @@ def configure_logger(template, stream_level='DEBUG', debug_file=None): # a logger with using the name 'cookiecutter' del logger.handlers[:] - # Add additional information to the logger - context_filter = ContextFilter(template) - # 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) - file_handler.addFilter(context_filter) logger.addHandler(file_handler) # Get settings based on the given stream_level @@ -59,7 +42,6 @@ def configure_logger(template, stream_level='DEBUG', debug_file=None): stream_handler = logging.StreamHandler(stream=sys.stdout) stream_handler.setLevel(log_level) stream_handler.setFormatter(log_formatter) - stream_handler.addFilter(context_filter) logger.addHandler(stream_handler) return logger diff --git a/tests/test_cli.py b/tests/test_cli.py index 55fac0258..9d0cdef86 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -396,7 +396,7 @@ def test_debug_file_non_verbose(cli_runner, debug_file): assert debug_file.exists() context_log = ( - "DEBUG [fake-repo-pre] cookiecutter.main: context_file is " + "DEBUG cookiecutter.main: context_file is " "tests/fake-repo-pre/cookiecutter.json" ) assert context_log in debug_file.readlines(cr=False) @@ -419,7 +419,7 @@ def test_debug_file_verbose(cli_runner, debug_file): assert debug_file.exists() context_log = ( - "DEBUG [fake-repo-pre] cookiecutter.main: context_file is " + "DEBUG cookiecutter.main: context_file is " "tests/fake-repo-pre/cookiecutter.json" ) assert context_log in debug_file.readlines(cr=False) diff --git a/tests/test_log.py b/tests/test_log.py index f618966fa..4448bca70 100644 --- a/tests/test_log.py +++ b/tests/test_log.py @@ -33,37 +33,37 @@ def info_messages(): @pytest.fixture def debug_messages(): return [ - 'INFO [pytest-plugin] cookiecutter: ' + 'INFO cookiecutter: ' 'Welcome to Cookiecutter', - 'DEBUG [pytest-plugin] cookiecutter: ' + 'DEBUG cookiecutter: ' 'Generating project from pytest-plugin', - 'INFO [pytest-plugin] cookiecutter.foo: ' + 'INFO cookiecutter.foo: ' 'Loading user config from home dir', - "DEBUG [pytest-plugin] cookiecutter.foo.bar: " + "DEBUG cookiecutter.foo.bar: " "I don't know.", - 'DEBUG [pytest-plugin] cookiecutter.foo.bar: ' + 'DEBUG cookiecutter.foo.bar: ' 'I wanted to save the world.', - 'ERROR [pytest-plugin] cookiecutter.foo: ' + 'ERROR cookiecutter.foo: ' 'Aw, snap! Something went wrong', - 'DEBUG [pytest-plugin] cookiecutter: ' + 'DEBUG cookiecutter: ' 'Successfully generated project', ] @pytest.fixture def info_logger(): - return configure_logger('pytest-plugin', stream_level='INFO') + return configure_logger(stream_level='INFO') @pytest.fixture def debug_logger(): - return configure_logger('pytest-plugin', stream_level='DEBUG') + return configure_logger(stream_level='DEBUG') @pytest.fixture @@ -74,7 +74,6 @@ def debug_file(tmpdir): @pytest.fixture def info_logger_with_file(debug_file): return configure_logger( - 'pytest-plugin', stream_level='INFO', debug_file=str(debug_file), ) From 9d10b74e4ffc5d4f62597ddb6884d35690656172 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 11 Sep 2016 10:50:34 +0100 Subject: [PATCH 14/17] Remove Python 2.6 compat from format --- cookiecutter/find.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cookiecutter/find.py b/cookiecutter/find.py index c6f3246aa..ac02fb7f1 100644 --- a/cookiecutter/find.py +++ b/cookiecutter/find.py @@ -16,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. """ - logger.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) @@ -29,7 +29,7 @@ def find_template(repo_dir): if project_template: project_template = os.path.join(repo_dir, project_template) logger.debug( - 'The project template appears to be {0}'.format(project_template) + 'The project template appears to be {}'.format(project_template) ) return project_template else: From c23e92b866c2df27c147ca6dac280d19902fcf58 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 11 Sep 2016 11:09:46 +0100 Subject: [PATCH 15/17] Use better name for project directory in log --- cookiecutter/generate.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cookiecutter/generate.py b/cookiecutter/generate.py index c67acc83f..56c918b82 100644 --- a/cookiecutter/generate.py +++ b/cookiecutter/generate.py @@ -270,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) - logger.debug('project_dir is {}'.format(project_dir)) + logger.debug('Project directory is {}'.format(project_dir)) _run_hook_from_repo_dir(repo_dir, 'pre_gen_project', project_dir, context) From a693f27047223e1c239557fcc73554ed648b2d61 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 11 Sep 2016 11:13:38 +0100 Subject: [PATCH 16/17] Remove index from str.format --- cookiecutter/main.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cookiecutter/main.py b/cookiecutter/main.py index 08d8f17b2..b67da95fe 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') - logger.debug('context_file is {0}'.format(context_file)) + logger.debug('context_file is {}'.format(context_file)) context = generate_context( context_file=context_file, From a42528a66edaf4c760b964dc75b5a8a44ab242a9 Mon Sep 17 00:00:00 2001 From: Raphael Pierzina Date: Sun, 11 Sep 2016 11:16:50 +0100 Subject: [PATCH 17/17] Remove pos index from format in vcs.py --- cookiecutter/vcs.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cookiecutter/vcs.py b/cookiecutter/vcs.py index 491c8550a..7c3e4b5de 100644 --- a/cookiecutter/vcs.py +++ b/cookiecutter/vcs.py @@ -44,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')