openstack
/
paunch
Code Issues Proposed changes

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 <bdobreli@redhat.com>
(cherry picked from commit d3c83259bf)
This commit is contained in:
Bogdan Dobrelya 2018-10-22 12:22:10 +02:00
parent 2ddf40d833
commit 059aa8c1f6
8 changed files with 244 additions and 118 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

56
paunch/__init__.py
View File

@ -13,19 +13,18 @@
'''Stable library interface to managing containers with paunch.''' '''Stable library interface to managing containers with paunch.'''
import json import json
import logging
import pbr.version import pbr.version
import yaml import yaml
from paunch.builder import compose1 from paunch.builder import compose1
from paunch import runner from paunch import runner
from paunch.utils import common
__version__ = pbr.version.VersionInfo('paunch').version_string() __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. """Execute supplied container configuration.
:param str config_id: Unique config ID, should not be re-used until any :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 :param dict labels: Optional keys/values of labels to apply to containers
created with this invocation. created with this invocation.
:param str docker_cmd: Optional override to the docker command to run. :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, :returns (list, list, int) lists of stdout and stderr for each execution,
and a single return code representing the and a single return code representing the
overall success of the apply. overall success of the apply.
:rtype: tuple :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( builder = compose1.ComposeV1Builder(
config_id=config_id, config_id=config_id,
config=config, config=config,
runner=r, runner=r,
labels=labels labels=labels,
log=log
) )
return builder.apply() 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. """Delete containers no longer applied, rename others to preferred name.
:param list config_ids: List of config IDs still applied. All containers :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 :param str managed_by: Name of the tool managing the containers. Only
containers labelled with this will be modified. containers labelled with this will be modified.
:param str docker_cmd: Optional override to the docker command to run. :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.delete_missing_configs(config_ids)
r.rename_containers() 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. """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 :returns a dict where the key is the config ID and the value is a list of
'docker inspect' dicts for each container. 'docker inspect' dicts for each container.
:rtype: defaultdict(list) :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() return r.list_configs()
def debug(config_id, container_name, action, config, managed_by, labels=None, 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. """Execute supplied container configuration.
:param str config_id: Unique config ID, should not be re-used until any :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 :param dict labels: Optional keys/values of labels to apply to containers
created with this invocation. created with this invocation.
:param str docker_cmd: Optional override to the docker command to run. :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 :returns integer return value from running command or failure for any
other reason. other reason.
:rtype: int :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( builder = compose1.ComposeV1Builder(
config_id=config_id, config_id=config_id,
config=config, config=config,
runner=r, runner=r,
labels=labels labels=labels,
log=log
) )
if action == 'print-cmd': if action == 'print-cmd':
cmd = [ cmd = [
@ -127,7 +144,7 @@ def debug(config_id, container_name, action, config, managed_by, labels=None,
r.unique_container_name(container_name) r.unique_container_name(container_name)
] ]
builder.docker_run_args(cmd, container_name) builder.docker_run_args(cmd, container_name)
return r.execute_interactive(cmd) return r.execute_interactive(cmd, log)
elif action == 'dump-yaml': elif action == 'dump-yaml':
print(yaml.safe_dump(config, default_flow_style=False)) print(yaml.safe_dump(config, default_flow_style=False))
elif action == 'dump-json': elif action == 'dump-json':
@ -137,7 +154,8 @@ def debug(config_id, container_name, action, config, managed_by, labels=None,
'"print-cmd", or "run"') '"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. """Delete containers with the specified config IDs.
:param list config_ids: List of config IDs to delete the containers for. :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. containers labelled with this will be modified.
:param str docker_cmd: Optional override to the docker command to run. :param str docker_cmd: Optional override to the docker command to run.
""" """
if not config_ids: log = common.configure_logging(__name__, log_level, log_file)
LOG.warn('No config IDs specified')
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: for conf_id in config_ids:
r.remove_containers(conf_id) r.remove_containers(conf_id)

52
paunch/builder/compose1.py
View File

@ -12,22 +12,21 @@
# #
import json import json
import logging
import tenacity import tenacity
import yaml import yaml
from paunch.utils import common from paunch.utils import common
LOG = logging.getLogger(__name__)
class ComposeV1Builder(object): 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_id = config_id
self.config = config self.config = config
self.labels = labels self.labels = labels
self.runner = runner self.runner = runner
# Leverage pre-configured logger
self.log = log or common.configure_logging(__name__)
def apply(self): def apply(self):
@ -46,13 +45,14 @@ class ComposeV1Builder(object):
desired_names = set([cn[-1] for cn in container_names]) desired_names = set([cn[-1] for cn in container_names])
for container in sorted(self.config, key=key_fltr): 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') action = self.config[container].get('action', 'run')
exit_codes = self.config[container].get('exit_codes', [0]) exit_codes = self.config[container].get('exit_codes', [0])
if action == 'run': if action == 'run':
if container in desired_names: if container in desired_names:
LOG.debug('Skipping existing container: %s' % container) self.log.debug(
'Skipping existing container: %s' % container)
continue continue
cmd = [ cmd = [
@ -67,21 +67,22 @@ class ComposeV1Builder(object):
cmd = [self.runner.docker_cmd, 'exec'] cmd = [self.runner.docker_cmd, 'exec']
self.docker_exec_args(cmd, container) 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: if cmd_stdout:
stdout.append(cmd_stdout) stdout.append(cmd_stdout)
if cmd_stderr: if cmd_stderr:
stderr.append(cmd_stderr) stderr.append(cmd_stderr)
if returncode not in exit_codes: if returncode not in exit_codes:
LOG.error("Error running %s. [%s]\n" % (cmd, returncode)) self.log.error("Error running %s. [%s]\n" % (cmd, returncode))
LOG.error("stdout: %s" % cmd_stdout) self.log.error("stdout: %s" % cmd_stdout)
LOG.error("stderr: %s" % cmd_stderr) self.log.error("stderr: %s" % cmd_stderr)
deploy_status_code = returncode deploy_status_code = returncode
else: else:
LOG.debug('Completed $ %s' % ' '.join(cmd)) self.log.debug('Completed $ %s' % ' '.join(cmd))
LOG.info("stdout: %s" % cmd_stdout) self.log.info("stdout: %s" % cmd_stdout)
LOG.info("stderr: %s" % cmd_stderr) self.log.info("stderr: %s" % cmd_stderr)
return stdout, stderr, deploy_status_code return stdout, stderr, deploy_status_code
def delete_missing_and_updated(self): 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 the desired name is not in the config, delete it
if cn[-1] not in self.config: 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) self.runner.remove_container(container)
continue continue
ex_data_str = self.runner.inspect( ex_data_str = self.runner.inspect(
container, '{{index .Config.Labels "config_data"}}') container, '{{index .Config.Labels "config_data"}}')
if not ex_data_str: if not ex_data_str:
LOG.debug("Deleting container (no config_data): %s" self.log.debug("Deleting container (no config_data): %s" %
% container) container)
self.runner.remove_container(container) self.runner.remove_container(container)
continue continue
@ -110,8 +111,8 @@ class ComposeV1Builder(object):
new_data = self.config.get(cn[-1]) new_data = self.config.get(cn[-1])
if new_data != ex_data: if new_data != ex_data:
LOG.debug("Deleting container (changed config_data): %s" self.log.debug("Deleting container (changed config_data): %s" %
% container) container)
self.runner.remove_container(container) self.runner.remove_container(container)
# deleting containers is an opportunity for renames to their # deleting containers is an opportunity for renames to their
@ -247,13 +248,14 @@ class ComposeV1Builder(object):
returncode = e.rc returncode = e.rc
cmd_stdout = e.stdout cmd_stdout = e.stdout
cmd_stderr = e.stderr cmd_stderr = e.stderr
LOG.error("Error pulling %s. [%s]\n" % (image, returncode)) self.log.error("Error pulling %s. [%s]\n" %
LOG.error("stdout: %s" % e.stdout) (image, returncode))
LOG.error("stderr: %s" % e.stderr) self.log.error("stdout: %s" % e.stdout)
self.log.error("stderr: %s" % e.stderr)
else: else:
LOG.debug('Pulled %s' % image) self.log.debug('Pulled %s' % image)
LOG.info("stdout: %s" % cmd_stdout) self.log.info("stdout: %s" % cmd_stdout)
LOG.info("stderr: %s" % cmd_stderr) self.log.info("stderr: %s" % cmd_stderr)
if cmd_stdout: if cmd_stdout:
stdout.append(cmd_stdout) stdout.append(cmd_stdout)
@ -269,7 +271,7 @@ class ComposeV1Builder(object):
) )
def _pull(self, image): def _pull(self, image):
cmd = [self.runner.docker_cmd, 'pull', 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: if rc != 0:
raise PullException(stdout, stderr, rc) raise PullException(stdout, stderr, rc)
return stdout, stderr return stdout, stderr

61
paunch/cmd.py
View File

@ -12,7 +12,6 @@
# #
import collections import collections
import logging
from cliff import command from cliff import command
from cliff import lister from cliff import lister
@ -24,7 +23,7 @@ import paunch
class Apply(command.Command): class Apply(command.Command):
log = logging.getLogger(__name__) log = None
def get_parser(self, prog_name): def get_parser(self, prog_name):
parser = super(Apply, self).get_parser(prog_name) parser = super(Apply, self).get_parser(prog_name)
@ -60,6 +59,11 @@ class Apply(command.Command):
def take_action(self, parsed_args): 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() labels = collections.OrderedDict()
for l in parsed_args.labels: for l in parsed_args.labels:
k, v = l.split(('='), 1) k, v = l.split(('='), 1)
@ -72,7 +76,9 @@ class Apply(command.Command):
parsed_args.config_id, parsed_args.config_id,
config, config,
managed_by='paunch', managed_by='paunch',
labels=labels labels=labels,
log_level=log_level,
log_file=self.app_args.log_file
) )
return rc return rc
@ -80,7 +86,7 @@ class Apply(command.Command):
class Cleanup(command.Command): class Cleanup(command.Command):
log = logging.getLogger(__name__) log = None
def get_parser(self, prog_name): def get_parser(self, prog_name):
parser = super(Cleanup, self).get_parser(prog_name) parser = super(Cleanup, self).get_parser(prog_name)
@ -101,15 +107,22 @@ class Cleanup(command.Command):
return parser return parser
def take_action(self, parsed_args): 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( paunch.cleanup(
parsed_args.config_id, 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): class Delete(command.Command):
log = logging.getLogger(__name__) log = None
def get_parser(self, prog_name): def get_parser(self, prog_name):
parser = super(Delete, self).get_parser(prog_name) parser = super(Delete, self).get_parser(prog_name)
@ -129,12 +142,22 @@ class Delete(command.Command):
return parser return parser
def take_action(self, parsed_args): 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): class Debug(command.Command):
log = logging.getLogger(__name__) log = None
def get_parser(self, prog_name): def get_parser(self, prog_name):
parser = super(Debug, self).get_parser(prog_name) parser = super(Debug, self).get_parser(prog_name)
@ -216,6 +239,11 @@ class Debug(command.Command):
def take_action(self, parsed_args): 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() labels = collections.OrderedDict()
for l in parsed_args.labels: for l in parsed_args.labels:
k, v = l.split(('='), 1) k, v = l.split(('='), 1)
@ -256,13 +284,15 @@ class Debug(command.Command):
parsed_args.action, parsed_args.action,
cconfig, cconfig,
parsed_args.managed_by, parsed_args.managed_by,
labels=labels labels=labels,
log_level=log_level,
log_file=self.app_args.log_file
) )
class List(lister.Lister): class List(lister.Lister):
log = logging.getLogger(__name__) log = None
def get_parser(self, prog_name): def get_parser(self, prog_name):
parser = super(List, self).get_parser(prog_name) parser = super(List, self).get_parser(prog_name)
@ -276,7 +306,16 @@ class List(lister.Lister):
return parser return parser
def take_action(self, parsed_args): 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 = [ columns = [
'config', 'config',
'container', 'container',

58
paunch/runner.py
View File

@ -13,36 +13,40 @@
import collections import collections
import json import json
import logging
import random import random
import string import string
import subprocess import subprocess
from paunch.utils import common
LOG = logging.getLogger(__name__)
class DockerRunner(object): 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.managed_by = managed_by
self.docker_cmd = docker_cmd or 'docker' self.docker_cmd = docker_cmd or 'docker'
# Leverage pre-configured logger
self.log = log or common.configure_logging(__name__)
@staticmethod @staticmethod
def execute(cmd): def execute(cmd, log=None):
LOG.debug('$ %s' % ' '.join(cmd)) if not log:
log = common.configure_logging(__name__)
log.debug('$ %s' % ' '.join(cmd))
subproc = subprocess.Popen(cmd, stdout=subprocess.PIPE, subproc = subprocess.Popen(cmd, stdout=subprocess.PIPE,
stderr=subprocess.PIPE) stderr=subprocess.PIPE)
cmd_stdout, cmd_stderr = subproc.communicate() cmd_stdout, cmd_stderr = subproc.communicate()
LOG.debug(cmd_stdout) log.debug(cmd_stdout)
LOG.debug(cmd_stderr) log.debug(cmd_stderr)
return (cmd_stdout.decode('utf-8'), return (cmd_stdout.decode('utf-8'),
cmd_stderr.decode('utf-8'), cmd_stderr.decode('utf-8'),
subproc.returncode) subproc.returncode)
@staticmethod @staticmethod
def execute_interactive(cmd): def execute_interactive(cmd, log=None):
LOG.debug('$ %s' % ' '.join(cmd)) if not log:
log = common.configure_logging(__name__)
log.debug('$ %s' % ' '.join(cmd))
return subprocess.call(cmd) return subprocess.call(cmd)
def current_config_ids(self): def current_config_ids(self):
@ -52,7 +56,7 @@ class DockerRunner(object):
'--filter', 'label=managed_by=%s' % self.managed_by, '--filter', 'label=managed_by=%s' % self.managed_by,
'--format', '{{.Label "config_id"}}' '--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: if returncode != 0:
return set() return set()
return set(cmd_stdout.split()) return set(cmd_stdout.split())
@ -63,7 +67,7 @@ class DockerRunner(object):
'--filter', 'label=managed_by=%s' % self.managed_by, '--filter', 'label=managed_by=%s' % self.managed_by,
'--filter', 'label=config_id=%s' % conf_id '--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: if returncode != 0:
return [] return []
@ -75,10 +79,10 @@ class DockerRunner(object):
def remove_container(self, container): def remove_container(self, container):
cmd = [self.docker_cmd, 'rm', '-f', 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: if returncode != 0:
LOG.error('Error removing container: %s' % container) self.log.error('Error removing container: %s' % container)
LOG.error(cmd_stderr) self.log.error(cmd_stderr)
def container_names(self, conf_id=None): def container_names(self, conf_id=None):
# list every container name, and its container_name label # list every container name, and its container_name label
@ -93,7 +97,7 @@ class DockerRunner(object):
cmd.extend(( cmd.extend((
'--format', '{{.Names}} {{.Label "container_name"}}' '--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: if returncode != 0:
return return
for line in cmd_stdout.split("\n"): for line in cmd_stdout.split("\n"):
@ -118,19 +122,20 @@ class DockerRunner(object):
for current, desired in sorted(need_renaming.items()): for current, desired in sorted(need_renaming.items()):
if desired in current_containers: if desired in current_containers:
LOG.info('Cannot rename "%s" since "%s" still exists' % ( self.log.info('Cannot rename "%s" since "%s" '
current, desired)) 'still exists' % (current, desired))
else: else:
LOG.info('Renaming "%s" to "%s"' % (current, desired)) self.log.info('Renaming "%s" to "%s"' % (
current, desired))
self.rename_container(current, desired) self.rename_container(current, desired)
current_containers.append(desired) current_containers.append(desired)
def rename_container(self, container, name): def rename_container(self, container, name):
cmd = [self.docker_cmd, 'rename', 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: if returncode != 0:
LOG.error('Error renaming container: %s' % container) self.log.error('Error renaming container: %s' % container)
LOG.error(cmd_stderr) self.log.error(cmd_stderr)
def inspect(self, name, format=None, type='container'): def inspect(self, name, format=None, type='container'):
cmd = [self.docker_cmd, 'inspect', '--type', type] cmd = [self.docker_cmd, 'inspect', '--type', type]
@ -138,7 +143,7 @@ class DockerRunner(object):
cmd.append('--format') cmd.append('--format')
cmd.append(format) cmd.append(format)
cmd.append(name) cmd.append(name)
(cmd_stdout, cmd_stderr, returncode) = self.execute(cmd) (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd, self.log)
if returncode != 0: if returncode != 0:
return return
try: try:
@ -147,7 +152,7 @@ class DockerRunner(object):
else: else:
return json.loads(cmd_stdout)[0] return json.loads(cmd_stdout)[0]
except Exception as e: 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): def unique_container_name(self, container):
container_name = container container_name = container
@ -170,7 +175,7 @@ class DockerRunner(object):
'--format', '--format',
'{{.Names}}' '{{.Names}}'
] ]
(cmd_stdout, cmd_stderr, returncode) = self.execute(cmd) (cmd_stdout, cmd_stderr, returncode) = self.execute(cmd, self.log)
if returncode != 0: if returncode != 0:
return container return container
names = cmd_stdout.split() names = cmd_stdout.split()
@ -184,7 +189,8 @@ class DockerRunner(object):
for conf_id in self.current_config_ids(): for conf_id in self.current_config_ids():
if conf_id not in 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) self.remove_containers(conf_id)
def list_configs(self): def list_configs(self):

69
paunch/tests/test_builder_compose1.py
View File

@ -95,40 +95,43 @@ class TestComposeV1Builder(base.TestCase):
# inspect existing image centos:6 # inspect existing image centos:6
mock.call( mock.call(
['docker', 'inspect', '--type', 'image', ['docker', 'inspect', '--type', 'image',
'--format', 'exists', 'centos:6'] '--format', 'exists', 'centos:6'], mock.ANY
), ),
# inspect and pull missing image centos:7 # inspect and pull missing image centos:7
mock.call( mock.call(
['docker', 'inspect', '--type', 'image', ['docker', 'inspect', '--type', 'image',
'--format', 'exists', 'centos:7'] '--format', 'exists', 'centos:7'], mock.ANY
), ),
# first pull attempt fails # first pull attempt fails
mock.call( mock.call(
['docker', 'pull', 'centos:7'] ['docker', 'pull', 'centos:7'], mock.ANY
), ),
# second pull attempt succeeds # second pull attempt succeeds
mock.call( mock.call(
['docker', 'pull', 'centos:7'] ['docker', 'pull', 'centos:7'], mock.ANY
), ),
# ps for delete_missing_and_updated container_names # ps for delete_missing_and_updated container_names
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--filter', 'label=managed_by=tester',
'--filter', 'label=config_id=foo', '--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 # ps for after delete_missing_and_updated renames
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--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 # ps to only create containers which don't exist
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--filter', 'label=managed_by=tester',
'--filter', 'label=config_id=foo', '--filter', 'label=config_id=foo',
'--format', '{{.Names}} {{.Label "container_name"}}'] '--format', '{{.Names}} {{.Label "container_name"}}'],
mock.ANY
), ),
# run one # run one
mock.call( mock.call(
@ -137,7 +140,8 @@ class TestComposeV1Builder(base.TestCase):
'--label', 'container_name=one', '--label', 'container_name=one',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['one']), '--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 # run two
mock.call( mock.call(
@ -146,7 +150,8 @@ class TestComposeV1Builder(base.TestCase):
'--label', 'container_name=two', '--label', 'container_name=two',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['two']), '--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 # run three
mock.call( mock.call(
@ -155,7 +160,8 @@ class TestComposeV1Builder(base.TestCase):
'--label', 'container_name=three', '--label', 'container_name=three',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['three']), '--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 # run four
mock.call( mock.call(
@ -164,11 +170,12 @@ class TestComposeV1Builder(base.TestCase):
'--label', 'container_name=four', '--label', 'container_name=four',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['four']), '--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 # execute within four
mock.call( 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 # inspect image centos:7
mock.call( mock.call(
['docker', 'inspect', '--type', 'image', ['docker', 'inspect', '--type', 'image',
'--format', 'exists', 'centos:7'] '--format', 'exists', 'centos:7'], mock.ANY
), ),
# ps for delete_missing_and_updated container_names # ps for delete_missing_and_updated container_names
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--filter', 'label=managed_by=tester',
'--filter', 'label=config_id=foo', '--filter', 'label=config_id=foo',
'--format', '{{.Names}} {{.Label "container_name"}}'] '--format', '{{.Names}} {{.Label "container_name"}}'],
mock.ANY
), ),
# rm containers not in config # rm containers not in config
mock.call(['docker', 'rm', '-f', 'five']), mock.call(['docker', 'rm', '-f', 'five'], mock.ANY),
mock.call(['docker', 'rm', '-f', 'six']), mock.call(['docker', 'rm', '-f', 'six'], mock.ANY),
# rm two, changed config # rm two, changed config
mock.call(['docker', 'inspect', '--type', 'container', mock.call(['docker', 'inspect', '--type', 'container',
'--format', '{{index .Config.Labels "config_data"}}', '--format', '{{index .Config.Labels "config_data"}}',
'two-12345678']), 'two-12345678'], mock.ANY),
mock.call(['docker', 'rm', '-f', 'two-12345678']), mock.call(['docker', 'rm', '-f', 'two-12345678'], mock.ANY),
# check three, config hasn't changed # check three, config hasn't changed
mock.call(['docker', 'inspect', '--type', 'container', mock.call(['docker', 'inspect', '--type', 'container',
'--format', '{{index .Config.Labels "config_data"}}', '--format', '{{index .Config.Labels "config_data"}}',
'three-12345678']), 'three-12345678'], mock.ANY),
# ps for after delete_missing_and_updated renames # ps for after delete_missing_and_updated renames
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--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 # ps to only create containers which don't exist
mock.call( mock.call(
['docker', 'ps', '-a', ['docker', 'ps', '-a',
'--filter', 'label=managed_by=tester', '--filter', 'label=managed_by=tester',
'--filter', 'label=config_id=foo', '--filter', 'label=config_id=foo',
'--format', '{{.Names}} {{.Label "container_name"}}'] '--format', '{{.Names}} {{.Label "container_name"}}'],
mock.ANY
), ),
# run one # run one
mock.call( mock.call(
@ -291,7 +301,8 @@ three-12345678 three''', '', 0),
'--label', 'container_name=one', '--label', 'container_name=one',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['one']), '--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 # run two
mock.call( mock.call(
@ -300,7 +311,8 @@ three-12345678 three''', '', 0),
'--label', 'container_name=two', '--label', 'container_name=two',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['two']), '--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 # don't run three, its already running
# run four # run four
@ -310,11 +322,12 @@ three-12345678 three''', '', 0),
'--label', 'container_name=four', '--label', 'container_name=four',
'--label', 'managed_by=tester', '--label', 'managed_by=tester',
'--label', 'config_data=%s' % json.dumps(config['four']), '--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 # execute within four
mock.call( 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 # inspect existing image centos:6
mock.call( mock.call(
['docker', 'inspect', '--type', 'image', ['docker', 'inspect', '--type', 'image',
'--format', 'exists', 'centos:6'] '--format', 'exists', 'centos:6'], mock.ANY
), ),
# inspect and pull missing image centos:7 # inspect and pull missing image centos:7
mock.call( mock.call(
['docker', 'inspect', '--type', 'image', ['docker', 'inspect', '--type', 'image',
'--format', 'exists', 'centos:7'] '--format', 'exists', 'centos:7'], mock.ANY
), ),
mock.call( mock.call(
['docker', 'pull', 'centos:7'] ['docker', 'pull', 'centos:7'], mock.ANY
), ),
]) ])

30
paunch/tests/test_paunch.py
View File

@ -24,12 +24,14 @@ class TestPaunch(base.TestCase):
@mock.patch('paunch.runner.DockerRunner', autospec=True) @mock.patch('paunch.runner.DockerRunner', autospec=True)
def test_apply(self, runner, builder): def test_apply(self, runner, builder):
paunch.apply('foo', {'bar': 'baz'}, 'tester') 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( builder.assert_called_once_with(
config_id='foo', config_id='foo',
config={'bar': 'baz'}, config={'bar': 'baz'},
runner=runner.return_value, runner=runner.return_value,
labels=None labels=None,
log=mock.ANY
) )
builder.return_value.apply.assert_called_once_with() builder.return_value.apply.assert_called_once_with()
@ -42,19 +44,22 @@ class TestPaunch(base.TestCase):
managed_by='tester', managed_by='tester',
labels={'bink': 'boop'}) 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( builder.assert_called_once_with(
config_id='foo', config_id='foo',
config={'bar': 'baz'}, config={'bar': 'baz'},
runner=runner.return_value, runner=runner.return_value,
labels={'bink': 'boop'} labels={'bink': 'boop'},
log=mock.ANY
) )
builder.return_value.apply.assert_called_once_with() builder.return_value.apply.assert_called_once_with()
@mock.patch('paunch.runner.DockerRunner', autospec=True) @mock.patch('paunch.runner.DockerRunner', autospec=True)
def test_cleanup(self, runner): def test_cleanup(self, runner):
paunch.cleanup(['foo', 'bar'], 'tester') 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( runner.return_value.delete_missing_configs.assert_called_once_with(
['foo', 'bar']) ['foo', 'bar'])
runner.return_value.rename_containers.assert_called_once_with() runner.return_value.rename_containers.assert_called_once_with()
@ -62,13 +67,15 @@ class TestPaunch(base.TestCase):
@mock.patch('paunch.runner.DockerRunner', autospec=True) @mock.patch('paunch.runner.DockerRunner', autospec=True)
def test_list(self, runner): def test_list(self, runner):
paunch.list('tester') 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() runner.return_value.list_configs.assert_called_once_with()
@mock.patch('paunch.runner.DockerRunner', autospec=True) @mock.patch('paunch.runner.DockerRunner', autospec=True)
def test_delete(self, runner): def test_delete(self, runner):
paunch.delete(['foo', 'bar'], 'tester') 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([ runner.return_value.remove_containers.assert_has_calls([
mock.call('foo'), mock.call('bar') mock.call('foo'), mock.call('bar')
]) ])
@ -77,11 +84,14 @@ class TestPaunch(base.TestCase):
@mock.patch('paunch.runner.DockerRunner') @mock.patch('paunch.runner.DockerRunner')
def test_debug(self, runner, builder): def test_debug(self, runner, builder):
paunch.debug('foo', 'testcont', 'run', {'bar': 'baz'}, 'tester', 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( builder.assert_called_once_with(
config_id='foo', config_id='foo',
config={'bar': 'baz'}, config={'bar': 'baz'},
runner=runner.return_value, 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)

31
paunch/utils/common.py
View File

@ -13,7 +13,9 @@
# License for the specific language governing permissions and limitations # License for the specific language governing permissions and limitations
# under the License. # under the License.
import logging
import psutil import psutil
import sys
def get_cpus_allowed_list(**args): 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: Value computed by psutil, e.g. '0-3'
""" """
return "0-" + str(psutil.cpu_count() - 1) 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

5
releasenotes/notes/logging-1517682a7b0037cf.yaml Normal file
View File

@ -0,0 +1,5 @@
---
other:
- |
Logging verbosity and destination file can be controled with ``--debug``
``--verbose`` and ``--log-file``.