From 059aa8c1f66337bc927db7aefde5639fc70ecf5f Mon Sep 17 00:00:00 2001 From: Bogdan Dobrelya Date: Mon, 22 Oct 2018 12:22:10 +0200 Subject: [PATCH] Fix logging to stdout and file in classes/commands Fix logging to console to depend on input CLI args. By default, keep logging to stdout. Make --log-file argument working as well. Use the input verbosity parameters as a controlling switch for logs verbosity. Evaluate log levels as: * 1 (WARNING+) - the default log level if neither -v nor --debug used * 2 (INFO+) - applies if -v / --verbose * 4 (DEBUG+) - applies if --debug, dumps command results to file, if --log-file is requested. * 5 (DEBUG+) - applies if --debug and -v. Like the latter mode, but also dumps the executed commands results to console. This is needed for better deployments troubleshootng. Closes-Bug: #1799182 Change-Id: I653ac4cc520e40f3eb4d029e8c99ab482b17a859 Signed-off-by: Bogdan Dobrelya (cherry picked from commit d3c83259bfe59ed6713c7b5f7bb34128f39aae24) --- paunch/__init__.py | 56 ++++++++++----- paunch/builder/compose1.py | 52 +++++++------- paunch/cmd.py | 61 +++++++++++++--- paunch/runner.py | 58 +++++++++------- paunch/tests/test_builder_compose1.py | 69 +++++++++++-------- paunch/tests/test_paunch.py | 30 +++++--- paunch/utils/common.py | 31 +++++++++ .../notes/logging-1517682a7b0037cf.yaml | 5 ++ 8 files changed, 244 insertions(+), 118 deletions(-) create mode 100644 releasenotes/notes/logging-1517682a7b0037cf.yaml diff --git a/paunch/__init__.py b/paunch/__init__.py index 73f048a..d8170f3 100644 --- a/paunch/__init__.py +++ b/paunch/__init__.py @@ -13,19 +13,18 @@ '''Stable library interface to managing containers with paunch.''' import json -import logging import pbr.version import yaml from paunch.builder import compose1 from paunch import runner +from paunch.utils import common __version__ = pbr.version.VersionInfo('paunch').version_string() -LOG = logging.getLogger(__name__) - -def apply(config_id, config, managed_by, labels=None, docker_cmd=None): +def apply(config_id, config, managed_by, labels=None, docker_cmd=None, + log_level=None, log_file=None): """Execute supplied container configuration. :param str config_id: Unique config ID, should not be re-used until any @@ -38,23 +37,29 @@ def apply(config_id, config, managed_by, labels=None, docker_cmd=None): :param dict labels: Optional keys/values of labels to apply to containers created with this invocation. :param str docker_cmd: Optional override to the docker command to run. + :param int log_level: optional log level for loggers + :param int log_file: optional log file for messages :returns (list, list, int) lists of stdout and stderr for each execution, and a single return code representing the overall success of the apply. :rtype: tuple """ - r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd) + log = common.configure_logging(__name__, log_level, log_file) + + r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd, log=log) builder = compose1.ComposeV1Builder( config_id=config_id, config=config, runner=r, - labels=labels + labels=labels, + log=log ) return builder.apply() -def cleanup(config_ids, managed_by, docker_cmd=None): +def cleanup(config_ids, managed_by, docker_cmd=None, log_level=None, + log_file=None): """Delete containers no longer applied, rename others to preferred name. :param list config_ids: List of config IDs still applied. All containers @@ -63,25 +68,33 @@ def cleanup(config_ids, managed_by, docker_cmd=None): :param str managed_by: Name of the tool managing the containers. Only containers labelled with this will be modified. :param str docker_cmd: Optional override to the docker command to run. + :param int log_level: optional log level for loggers + :param int log_file: optional log file for messages """ - r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd) + log = common.configure_logging(__name__, log_level, log_file) + + r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd, log=log) r.delete_missing_configs(config_ids) r.rename_containers() -def list(managed_by, docker_cmd=None): +def list(managed_by, docker_cmd=None, log_level=None, log_file=None): """List all containers associated with all config IDs. + :param int log_level: optional log level for loggers + :param int log_file: optional log file for messages :returns a dict where the key is the config ID and the value is a list of 'docker inspect' dicts for each container. :rtype: defaultdict(list) """ - r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd) + log = common.configure_logging(__name__, log_level, log_file) + + r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd, log=log) return r.list_configs() def debug(config_id, container_name, action, config, managed_by, labels=None, - docker_cmd=None): + docker_cmd=None, log_level=None, log_file=None): """Execute supplied container configuration. :param str config_id: Unique config ID, should not be re-used until any @@ -97,18 +110,22 @@ def debug(config_id, container_name, action, config, managed_by, labels=None, :param dict labels: Optional keys/values of labels to apply to containers created with this invocation. :param str docker_cmd: Optional override to the docker command to run. + :param int log_level: optional log level for loggers + :param int log_file: optional log file for messages :returns integer return value from running command or failure for any other reason. :rtype: int """ + log = common.configure_logging(__name__, log_level, log_file) - r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd) + r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd, log=log) builder = compose1.ComposeV1Builder( config_id=config_id, config=config, runner=r, - labels=labels + labels=labels, + log=log ) if action == 'print-cmd': cmd = [ @@ -127,7 +144,7 @@ def debug(config_id, container_name, action, config, managed_by, labels=None, r.unique_container_name(container_name) ] builder.docker_run_args(cmd, container_name) - return r.execute_interactive(cmd) + return r.execute_interactive(cmd, log) elif action == 'dump-yaml': print(yaml.safe_dump(config, default_flow_style=False)) elif action == 'dump-json': @@ -137,7 +154,8 @@ def debug(config_id, container_name, action, config, managed_by, labels=None, '"print-cmd", or "run"') -def delete(config_ids, managed_by, docker_cmd=None): +def delete(config_ids, managed_by, docker_cmd=None, log_level=None, + log_file=None): """Delete containers with the specified config IDs. :param list config_ids: List of config IDs to delete the containers for. @@ -145,9 +163,11 @@ def delete(config_ids, managed_by, docker_cmd=None): containers labelled with this will be modified. :param str docker_cmd: Optional override to the docker command to run. """ - if not config_ids: - LOG.warn('No config IDs specified') + log = common.configure_logging(__name__, log_level, log_file) - r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd) + if not config_ids: + log.warn('No config IDs specified') + + r = runner.DockerRunner(managed_by, docker_cmd=docker_cmd, log=log) for conf_id in config_ids: r.remove_containers(conf_id) diff --git a/paunch/builder/compose1.py b/paunch/builder/compose1.py index 6c10bdc..167b13c 100644 --- a/paunch/builder/compose1.py +++ b/paunch/builder/compose1.py @@ -12,22 +12,21 @@ # import json -import logging import tenacity import yaml from paunch.utils import common -LOG = logging.getLogger(__name__) - class ComposeV1Builder(object): - def __init__(self, config_id, config, runner, labels=None): + def __init__(self, config_id, config, runner, labels=None, log=None): self.config_id = config_id self.config = config self.labels = labels self.runner = runner + # Leverage pre-configured logger + self.log = log or common.configure_logging(__name__) def apply(self): @@ -46,13 +45,14 @@ class ComposeV1Builder(object): desired_names = set([cn[-1] for cn in container_names]) for container in sorted(self.config, key=key_fltr): - LOG.debug("Running container: %s" % container) + self.log.debug("Running container: %s" % container) action = self.config[container].get('action', 'run') exit_codes = self.config[container].get('exit_codes', [0]) if action == 'run': if container in desired_names: - LOG.debug('Skipping existing container: %s' % container) + self.log.debug( + 'Skipping existing container: %s' % container) continue cmd = [ @@ -67,21 +67,22 @@ class ComposeV1Builder(object): cmd = [self.runner.docker_cmd, 'exec'] self.docker_exec_args(cmd, container) - (cmd_stdout, cmd_stderr, returncode) = self.runner.execute(cmd) + (cmd_stdout, cmd_stderr, returncode) = self.runner.execute( + cmd, self.log) if cmd_stdout: stdout.append(cmd_stdout) if cmd_stderr: stderr.append(cmd_stderr) if returncode not in exit_codes: - LOG.error("Error running %s. [%s]\n" % (cmd, returncode)) - LOG.error("stdout: %s" % cmd_stdout) - LOG.error("stderr: %s" % cmd_stderr) + self.log.error("Error running %s. [%s]\n" % (cmd, returncode)) + self.log.error("stdout: %s" % cmd_stdout) + self.log.error("stderr: %s" % cmd_stderr) deploy_status_code = returncode else: - LOG.debug('Completed $ %s' % ' '.join(cmd)) - LOG.info("stdout: %s" % cmd_stdout) - LOG.info("stderr: %s" % cmd_stderr) + self.log.debug('Completed $ %s' % ' '.join(cmd)) + self.log.info("stdout: %s" % cmd_stdout) + self.log.info("stderr: %s" % cmd_stderr) return stdout, stderr, deploy_status_code def delete_missing_and_updated(self): @@ -91,15 +92,15 @@ class ComposeV1Builder(object): # if the desired name is not in the config, delete it if cn[-1] not in self.config: - LOG.debug("Deleting container (removed): %s" % container) + self.log.debug("Deleting container (removed): %s" % container) self.runner.remove_container(container) continue ex_data_str = self.runner.inspect( container, '{{index .Config.Labels "config_data"}}') if not ex_data_str: - LOG.debug("Deleting container (no config_data): %s" - % container) + self.log.debug("Deleting container (no config_data): %s" % + container) self.runner.remove_container(container) continue @@ -110,8 +111,8 @@ class ComposeV1Builder(object): new_data = self.config.get(cn[-1]) if new_data != ex_data: - LOG.debug("Deleting container (changed config_data): %s" - % container) + self.log.debug("Deleting container (changed config_data): %s" % + container) self.runner.remove_container(container) # deleting containers is an opportunity for renames to their @@ -247,13 +248,14 @@ class ComposeV1Builder(object): returncode = e.rc cmd_stdout = e.stdout cmd_stderr = e.stderr - LOG.error("Error pulling %s. [%s]\n" % (image, returncode)) - LOG.error("stdout: %s" % e.stdout) - LOG.error("stderr: %s" % e.stderr) + self.log.error("Error pulling %s. [%s]\n" % + (image, returncode)) + self.log.error("stdout: %s" % e.stdout) + self.log.error("stderr: %s" % e.stderr) else: - LOG.debug('Pulled %s' % image) - LOG.info("stdout: %s" % cmd_stdout) - LOG.info("stderr: %s" % cmd_stderr) + self.log.debug('Pulled %s' % image) + self.log.info("stdout: %s" % cmd_stdout) + self.log.info("stderr: %s" % cmd_stderr) if cmd_stdout: stdout.append(cmd_stdout) @@ -269,7 +271,7 @@ class ComposeV1Builder(object): ) def _pull(self, image): cmd = [self.runner.docker_cmd, 'pull', image] - (stdout, stderr, rc) = self.runner.execute(cmd) + (stdout, stderr, rc) = self.runner.execute(cmd, self.log) if rc != 0: raise PullException(stdout, stderr, rc) return stdout, stderr diff --git a/paunch/cmd.py b/paunch/cmd.py index d069230..31ab012 100644 --- a/paunch/cmd.py +++ b/paunch/cmd.py @@ -12,7 +12,6 @@ # import collections -import logging from cliff import command from cliff import lister @@ -24,7 +23,7 @@ import paunch class Apply(command.Command): - log = logging.getLogger(__name__) + log = None def get_parser(self, prog_name): parser = super(Apply, self).get_parser(prog_name) @@ -60,6 +59,11 @@ class Apply(command.Command): def take_action(self, parsed_args): + # takes 1, or 2 if --verbose, or 4 - 5 if --debug + log_level = (self.app_args.verbose_level + + int(self.app_args.debug) * 3) + self.log = paunch.utils.common.configure_logging( + __name__, log_level, self.app_args.log_file) labels = collections.OrderedDict() for l in parsed_args.labels: k, v = l.split(('='), 1) @@ -72,7 +76,9 @@ class Apply(command.Command): parsed_args.config_id, config, managed_by='paunch', - labels=labels + labels=labels, + log_level=log_level, + log_file=self.app_args.log_file ) return rc @@ -80,7 +86,7 @@ class Apply(command.Command): class Cleanup(command.Command): - log = logging.getLogger(__name__) + log = None def get_parser(self, prog_name): parser = super(Cleanup, self).get_parser(prog_name) @@ -101,15 +107,22 @@ class Cleanup(command.Command): return parser def take_action(self, parsed_args): + # takes 1, or 2 if --verbose, or 4 - 5 if --debug + log_level = (self.app_args.verbose_level + + int(self.app_args.debug) * 3) + self.log = paunch.utils.common.configure_logging( + __name__, log_level, self.app_args.log_file) paunch.cleanup( parsed_args.config_id, - managed_by=parsed_args.managed_by + managed_by=parsed_args.managed_by, + log_level=log_level, + log_file=self.app_args.log_file ) class Delete(command.Command): - log = logging.getLogger(__name__) + log = None def get_parser(self, prog_name): parser = super(Delete, self).get_parser(prog_name) @@ -129,12 +142,22 @@ class Delete(command.Command): return parser def take_action(self, parsed_args): - paunch.delete(parsed_args.config_id, parsed_args.managed_by) + # takes 1, or 2 if --verbose, or 4 - 5 if --debug + log_level = (self.app_args.verbose_level + + int(self.app_args.debug) * 3) + self.log = paunch.utils.common.configure_logging( + __name__, log_level, self.app_args.log_file) + paunch.delete( + parsed_args.config_id, + parsed_args.managed_by, + log_level=log_level, + log_file=self.app_args.log_file + ) class Debug(command.Command): - log = logging.getLogger(__name__) + log = None def get_parser(self, prog_name): parser = super(Debug, self).get_parser(prog_name) @@ -216,6 +239,11 @@ class Debug(command.Command): def take_action(self, parsed_args): + # takes 1, or 2 if --verbose, or 4 - 5 if --debug + log_level = (self.app_args.verbose_level + + int(self.app_args.debug) * 3) + self.log = paunch.utils.common.configure_logging( + __name__, log_level, self.app_args.log_file) labels = collections.OrderedDict() for l in parsed_args.labels: k, v = l.split(('='), 1) @@ -256,13 +284,15 @@ class Debug(command.Command): parsed_args.action, cconfig, parsed_args.managed_by, - labels=labels + labels=labels, + log_level=log_level, + log_file=self.app_args.log_file ) class List(lister.Lister): - log = logging.getLogger(__name__) + log = None def get_parser(self, prog_name): parser = super(List, self).get_parser(prog_name) @@ -276,7 +306,16 @@ class List(lister.Lister): return parser def take_action(self, parsed_args): - configs = paunch.list(parsed_args.managed_by) + # takes 1, or 2 if --verbose, or 4 - 5 if --debug + log_level = (self.app_args.verbose_level + + int(self.app_args.debug) * 3) + self.log = paunch.utils.common.configure_logging( + __name__, log_level, self.app_args.log_file) + configs = paunch.list( + parsed_args.managed_by, + log_level=log_level, + log_file=self.app_args.log_file + ) columns = [ 'config', 'container', diff --git a/paunch/runner.py b/paunch/runner.py index 72025f7..19d800f 100644 --- a/paunch/runner.py +++ b/paunch/runner.py @@ -13,36 +13,40 @@ import collections import json -import logging import random import string import subprocess - -LOG = logging.getLogger(__name__) +from paunch.utils import common class DockerRunner(object): - def __init__(self, managed_by, docker_cmd=None): + def __init__(self, managed_by, docker_cmd=None, log=None): self.managed_by = managed_by self.docker_cmd = docker_cmd or 'docker' + # Leverage pre-configured logger + self.log = log or common.configure_logging(__name__) @staticmethod - def execute(cmd): - LOG.debug('$ %s' % ' '.join(cmd)) + def execute(cmd, log=None): + if not log: + log = common.configure_logging(__name__) + log.debug('$ %s' % ' '.join(cmd)) subproc = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) cmd_stdout, cmd_stderr = subproc.communicate() - LOG.debug(cmd_stdout) - LOG.debug(cmd_stderr) + log.debug(cmd_stdout) + log.debug(cmd_stderr) return (cmd_stdout.decode('utf-8'), cmd_stderr.decode('utf-8'), subproc.returncode) @staticmethod - def execute_interactive(cmd): - LOG.debug('$ %s' % ' '.join(cmd)) + def execute_interactive(cmd, log=None): + if not log: + log = common.configure_logging(__name__) + log.debug('$ %s' % ' '.join(cmd)) return subprocess.call(cmd) def current_config_ids(self): @@ -52,7 +56,7 @@ class DockerRunner(object): '--filter', 'label=managed_by=%s' % self.managed_by, '--format', '{{.Label "config_id"}}' ] - cmd_stdout, cmd_stderr, returncode = self.execute(cmd) + cmd_stdout, cmd_stderr, returncode = self.execute(cmd, self.log) if returncode != 0: return set() return set(cmd_stdout.split()) @@ -63,7 +67,7 @@ class DockerRunner(object): '--filter', 'label=managed_by=%s' % self.managed_by, '--filter', 'label=config_id=%s' % conf_id ] - cmd_stdout, cmd_stderr, returncode = self.execute(cmd) + cmd_stdout, cmd_stderr, returncode = self.execute(cmd, self.log) if returncode != 0: return [] @@ -75,10 +79,10 @@ class DockerRunner(object): def remove_container(self, container): cmd = [self.docker_cmd, 'rm', '-f', container] - cmd_stdout, cmd_stderr, returncode = self.execute(cmd) + cmd_stdout, cmd_stderr, returncode = self.execute(cmd, self.log) if returncode != 0: - LOG.error('Error removing container: %s' % container) - LOG.error(cmd_stderr) + self.log.error('Error removing container: %s' % container) + self.log.error(cmd_stderr) def container_names(self, conf_id=None): # list every container name, and its container_name label @@ -93,7 +97,7 @@ class DockerRunner(object): cmd.extend(( '--format', '{{.Names}} {{.Label "container_name"}}' )) - cmd_stdout, cmd_stderr, returncode = self.execute(cmd) + cmd_stdout, cmd_stderr, returncode = self.execute(cmd, self.log) if returncode != 0: return for line in cmd_stdout.split("\n"): @@ -118,19 +122,20 @@ class DockerRunner(object): for current, desired in sorted(need_renaming.items()): if desired in current_containers: - LOG.info('Cannot rename "%s" since "%s" still exists' % ( - current, desired)) + self.log.info('Cannot rename "%s" since "%s" ' + 'still exists' % (current, desired)) else: - LOG.info('Renaming "%s" to "%s"' % (current, desired)) + self.log.info('Renaming "%s" to "%s"' % ( + current, desired)) self.rename_container(current, desired) current_containers.append(desired) def rename_container(self, container, name): cmd = [self.docker_cmd, 'rename', container, name] - cmd_stdout, cmd_stderr, returncode = self.execute(cmd) + cmd_stdout, cmd_stderr, returncode = self.execute(cmd, self.log) if returncode != 0: - LOG.error('Error renaming container: %s' % container) - LOG.error(cmd_stderr) + self.log.error('Error renaming container: %s' % container) + self.log.error(cmd_stderr) def inspect(self, name, format=None, type='container'): cmd = [self.docker_cmd, 'inspect', '--type', type] @@ -138,7 +143,7 @@ class DockerRunner(object): cmd.append('--format') cmd.append(format) cmd.append(name) - (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd) + (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd, self.log) if returncode != 0: return try: @@ -147,7 +152,7 @@ class DockerRunner(object): else: return json.loads(cmd_stdout)[0] except Exception as e: - LOG.error('Problem parsing docker inspect: %s' % e) + self.log.error('Problem parsing docker inspect: %s' % e) def unique_container_name(self, container): container_name = container @@ -170,7 +175,7 @@ class DockerRunner(object): '--format', '{{.Names}}' ] - (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd) + (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd, self.log) if returncode != 0: return container names = cmd_stdout.split() @@ -184,7 +189,8 @@ class DockerRunner(object): for conf_id in self.current_config_ids(): if conf_id not in config_ids: - LOG.debug('%s no longer exists, deleting containers' % conf_id) + self.log.debug('%s no longer exists, deleting containers' % + conf_id) self.remove_containers(conf_id) def list_configs(self): diff --git a/paunch/tests/test_builder_compose1.py b/paunch/tests/test_builder_compose1.py index 64e2e3d..95e0af3 100644 --- a/paunch/tests/test_builder_compose1.py +++ b/paunch/tests/test_builder_compose1.py @@ -95,40 +95,43 @@ class TestComposeV1Builder(base.TestCase): # inspect existing image centos:6 mock.call( ['docker', 'inspect', '--type', 'image', - '--format', 'exists', 'centos:6'] + '--format', 'exists', 'centos:6'], mock.ANY ), # inspect and pull missing image centos:7 mock.call( ['docker', 'inspect', '--type', 'image', - '--format', 'exists', 'centos:7'] + '--format', 'exists', 'centos:7'], mock.ANY ), # first pull attempt fails mock.call( - ['docker', 'pull', 'centos:7'] + ['docker', 'pull', 'centos:7'], mock.ANY ), # second pull attempt succeeds mock.call( - ['docker', 'pull', 'centos:7'] + ['docker', 'pull', 'centos:7'], mock.ANY ), # ps for delete_missing_and_updated container_names mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', '--filter', 'label=config_id=foo', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # ps for after delete_missing_and_updated renames mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # ps to only create containers which don't exist mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', '--filter', 'label=config_id=foo', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # run one mock.call( @@ -137,7 +140,8 @@ class TestComposeV1Builder(base.TestCase): '--label', 'container_name=one', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['one']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # run two mock.call( @@ -146,7 +150,8 @@ class TestComposeV1Builder(base.TestCase): '--label', 'container_name=two', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['two']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # run three mock.call( @@ -155,7 +160,8 @@ class TestComposeV1Builder(base.TestCase): '--label', 'container_name=three', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['three']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:6'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:6'], + mock.ANY ), # run four mock.call( @@ -164,11 +170,12 @@ class TestComposeV1Builder(base.TestCase): '--label', 'container_name=four', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['four']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # execute within four mock.call( - ['docker', 'exec', 'four-12345678', 'ls', '-l', '/'] + ['docker', 'exec', 'four-12345678', 'ls', '-l', '/'], mock.ANY ), ]) @@ -250,39 +257,42 @@ three-12345678 three''', '', 0), # inspect image centos:7 mock.call( ['docker', 'inspect', '--type', 'image', - '--format', 'exists', 'centos:7'] + '--format', 'exists', 'centos:7'], mock.ANY ), # ps for delete_missing_and_updated container_names mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', '--filter', 'label=config_id=foo', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # rm containers not in config - mock.call(['docker', 'rm', '-f', 'five']), - mock.call(['docker', 'rm', '-f', 'six']), + mock.call(['docker', 'rm', '-f', 'five'], mock.ANY), + mock.call(['docker', 'rm', '-f', 'six'], mock.ANY), # rm two, changed config mock.call(['docker', 'inspect', '--type', 'container', '--format', '{{index .Config.Labels "config_data"}}', - 'two-12345678']), - mock.call(['docker', 'rm', '-f', 'two-12345678']), + 'two-12345678'], mock.ANY), + mock.call(['docker', 'rm', '-f', 'two-12345678'], mock.ANY), # check three, config hasn't changed mock.call(['docker', 'inspect', '--type', 'container', '--format', '{{index .Config.Labels "config_data"}}', - 'three-12345678']), + 'three-12345678'], mock.ANY), # ps for after delete_missing_and_updated renames mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # ps to only create containers which don't exist mock.call( ['docker', 'ps', '-a', '--filter', 'label=managed_by=tester', '--filter', 'label=config_id=foo', - '--format', '{{.Names}} {{.Label "container_name"}}'] + '--format', '{{.Names}} {{.Label "container_name"}}'], + mock.ANY ), # run one mock.call( @@ -291,7 +301,8 @@ three-12345678 three''', '', 0), '--label', 'container_name=one', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['one']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # run two mock.call( @@ -300,7 +311,8 @@ three-12345678 three''', '', 0), '--label', 'container_name=two', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['two']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # don't run three, its already running # run four @@ -310,11 +322,12 @@ three-12345678 three''', '', 0), '--label', 'container_name=four', '--label', 'managed_by=tester', '--label', 'config_data=%s' % json.dumps(config['four']), - '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'] + '--detach=true', '--cpuset-cpus=0,1,2,3', 'centos:7'], + mock.ANY ), # execute within four mock.call( - ['docker', 'exec', 'four-12345678', 'ls', '-l', '/'] + ['docker', 'exec', 'four-12345678', 'ls', '-l', '/'], mock.ANY ), ]) @@ -372,15 +385,15 @@ three-12345678 three''', '', 0), # inspect existing image centos:6 mock.call( ['docker', 'inspect', '--type', 'image', - '--format', 'exists', 'centos:6'] + '--format', 'exists', 'centos:6'], mock.ANY ), # inspect and pull missing image centos:7 mock.call( ['docker', 'inspect', '--type', 'image', - '--format', 'exists', 'centos:7'] + '--format', 'exists', 'centos:7'], mock.ANY ), mock.call( - ['docker', 'pull', 'centos:7'] + ['docker', 'pull', 'centos:7'], mock.ANY ), ]) diff --git a/paunch/tests/test_paunch.py b/paunch/tests/test_paunch.py index 8e91da2..3478f16 100644 --- a/paunch/tests/test_paunch.py +++ b/paunch/tests/test_paunch.py @@ -24,12 +24,14 @@ class TestPaunch(base.TestCase): @mock.patch('paunch.runner.DockerRunner', autospec=True) def test_apply(self, runner, builder): paunch.apply('foo', {'bar': 'baz'}, 'tester') - runner.assert_called_once_with('tester', docker_cmd=None) + runner.assert_called_once_with('tester', docker_cmd=None, + log=mock.ANY) builder.assert_called_once_with( config_id='foo', config={'bar': 'baz'}, runner=runner.return_value, - labels=None + labels=None, + log=mock.ANY ) builder.return_value.apply.assert_called_once_with() @@ -42,19 +44,22 @@ class TestPaunch(base.TestCase): managed_by='tester', labels={'bink': 'boop'}) - runner.assert_called_once_with('tester', docker_cmd=None) + runner.assert_called_once_with('tester', docker_cmd=None, + log=mock.ANY) builder.assert_called_once_with( config_id='foo', config={'bar': 'baz'}, runner=runner.return_value, - labels={'bink': 'boop'} + labels={'bink': 'boop'}, + log=mock.ANY ) builder.return_value.apply.assert_called_once_with() @mock.patch('paunch.runner.DockerRunner', autospec=True) def test_cleanup(self, runner): paunch.cleanup(['foo', 'bar'], 'tester') - runner.assert_called_once_with('tester', docker_cmd=None) + runner.assert_called_once_with('tester', docker_cmd=None, + log=mock.ANY) runner.return_value.delete_missing_configs.assert_called_once_with( ['foo', 'bar']) runner.return_value.rename_containers.assert_called_once_with() @@ -62,13 +67,15 @@ class TestPaunch(base.TestCase): @mock.patch('paunch.runner.DockerRunner', autospec=True) def test_list(self, runner): paunch.list('tester') - runner.assert_called_once_with('tester', docker_cmd=None) + runner.assert_called_once_with('tester', docker_cmd=None, + log=mock.ANY) runner.return_value.list_configs.assert_called_once_with() @mock.patch('paunch.runner.DockerRunner', autospec=True) def test_delete(self, runner): paunch.delete(['foo', 'bar'], 'tester') - runner.assert_called_once_with('tester', docker_cmd=None) + runner.assert_called_once_with('tester', docker_cmd=None, + log=mock.ANY) runner.return_value.remove_containers.assert_has_calls([ mock.call('foo'), mock.call('bar') ]) @@ -77,11 +84,14 @@ class TestPaunch(base.TestCase): @mock.patch('paunch.runner.DockerRunner') def test_debug(self, runner, builder): paunch.debug('foo', 'testcont', 'run', {'bar': 'baz'}, 'tester', - docker_cmd='docker') + docker_cmd='docker', log_level=42, + log_file='/dev/null') builder.assert_called_once_with( config_id='foo', config={'bar': 'baz'}, runner=runner.return_value, - labels=None + labels=None, + log=mock.ANY ) - runner.assert_called_once_with('tester', docker_cmd='docker') + runner.assert_called_once_with('tester', docker_cmd='docker', + log=mock.ANY) diff --git a/paunch/utils/common.py b/paunch/utils/common.py index 5b790b9..0b74179 100644 --- a/paunch/utils/common.py +++ b/paunch/utils/common.py @@ -13,7 +13,9 @@ # License for the specific language governing permissions and limitations # under the License. +import logging import psutil +import sys def get_cpus_allowed_list(**args): @@ -30,3 +32,32 @@ def get_all_cpus(**args): :return: Value computed by psutil, e.g. '0-3' """ return "0-" + str(psutil.cpu_count() - 1) + + +def configure_logging(name, level=3, log_file=None): + '''Mimic oslo_log default levels and formatting for the logger. ''' + log = logging.getLogger(name) + + if level and level > 2: + ll = logging.DEBUG + elif level and level == 2: + ll = logging.INFO + else: + ll = logging.WARNING + + log.setLevel(ll) + handler = logging.StreamHandler(sys.stdout) + handler.setLevel(ll) + if log_file: + fhandler = logging.FileHandler(log_file) + formatter = logging.Formatter( + '%(asctime)s.%(msecs)03d %(process)d %(levelname)s ' + '%(name)s [ ] %(message)s', + '%Y-%m-%d %H:%M:%S') + fhandler.setLevel(ll) + fhandler.setFormatter(formatter) + log.addHandler(fhandler) + log.addHandler(handler) + log.propagate = False + + return log diff --git a/releasenotes/notes/logging-1517682a7b0037cf.yaml b/releasenotes/notes/logging-1517682a7b0037cf.yaml new file mode 100644 index 0000000..1255533 --- /dev/null +++ b/releasenotes/notes/logging-1517682a7b0037cf.yaml @@ -0,0 +1,5 @@ +--- +other: + - | + Logging verbosity and destination file can be controled with ``--debug`` + ``--verbose`` and ``--log-file``.