Repository: incubator-ariatosca Updated Branches: refs/heads/ARIA-138-Make-logging-more-informative 38dfa1b72 -> d4380fb8f
review1 fixups Project: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/commit/cec57cd5 Tree: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/tree/cec57cd5 Diff: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/diff/cec57cd5 Branch: refs/heads/ARIA-138-Make-logging-more-informative Commit: cec57cd51f78dc42d07a7ff7f4ea678a3a3cd32b Parents: 38dfa1b Author: max-orlov <ma...@gigaspaces.com> Authored: Wed Apr 19 21:45:11 2017 +0300 Committer: max-orlov <ma...@gigaspaces.com> Committed: Thu Apr 20 11:44:17 2017 +0300 ---------------------------------------------------------------------- aria/cli/commands/__init__.py | 1 - aria/cli/commands/executions.py | 10 +-- aria/cli/commands/logs.py | 9 +-- aria/cli/execution_logging.py | 81 ++++++++++++++---------- aria/cli/logger.py | 2 +- aria/orchestrator/context/common.py | 8 +-- aria/orchestrator/workflows/executor/dry.py | 12 ++-- 7 files changed, 66 insertions(+), 57 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/cli/commands/__init__.py ---------------------------------------------------------------------- diff --git a/aria/cli/commands/__init__.py b/aria/cli/commands/__init__.py index 5d76ea6..a01a029 100644 --- a/aria/cli/commands/__init__.py +++ b/aria/cli/commands/__init__.py @@ -1,4 +1,3 @@ - # Licensed to the Apache Software Foundation (ASF) under one or more # contributor license agreements. See the NOTICE file distributed with # this work for additional information regarding copyright ownership. http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/cli/commands/executions.py ---------------------------------------------------------------------- diff --git a/aria/cli/commands/executions.py b/aria/cli/commands/executions.py index 082c020..3b17abf 100644 --- a/aria/cli/commands/executions.py +++ b/aria/cli/commands/executions.py @@ -144,17 +144,17 @@ def start(workflow_name, logger.info('Starting {0}execution. Press Ctrl+C cancel'.format('dry ' if dry else '')) execution_thread.start() - log_consumer = cli_logger.ModelLogConsumer(model_storage, workflow_runner.execution_id) + log_iterator = cli_logger.ModelLogIterator(model_storage, workflow_runner.execution_id) try: while execution_thread.is_alive(): - for log in log_consumer: - execution_logging.load(log).log() + execution_logging.drain(log_iterator) except KeyboardInterrupt: _cancel_execution(workflow_runner, execution_thread, logger) - for log in log_consumer: - execution_logging.load(log).log() + # It might be the case where some logs were written and the execution was terminated, thus we + # need to drain the remaining logs. + execution_logging.drain(log_iterator) # raise any errors from the execution thread (note these are not workflow execution errors) execution_thread.raise_error_if_exists() http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/cli/commands/logs.py ---------------------------------------------------------------------- diff --git a/aria/cli/commands/logs.py b/aria/cli/commands/logs.py index e87ee3b..b3b29e9 100644 --- a/aria/cli/commands/logs.py +++ b/aria/cli/commands/logs.py @@ -12,7 +12,7 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. -from ..logger import ModelLogConsumer +from ..logger import ModelLogIterator from ..cli import aria from .. import execution_logging @@ -34,12 +34,9 @@ def list(execution_id, model_storage, logger): """Display logs for an execution """ logger.info('Listing logs for execution id {0}'.format(execution_id)) - log_consumer = ModelLogConsumer(model_storage, execution_id) - any_logs = False + log_iterator = ModelLogIterator(model_storage, execution_id) - for log in log_consumer: - execution_logging.load(log).log() - any_logs = True + any_logs = execution_logging.drain(log_iterator) if not any_logs: logger.info('\tNo logs') http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/cli/execution_logging.py ---------------------------------------------------------------------- diff --git a/aria/cli/execution_logging.py b/aria/cli/execution_logging.py index 16a7d1a..bd05549 100644 --- a/aria/cli/execution_logging.py +++ b/aria/cli/execution_logging.py @@ -14,53 +14,68 @@ # limitations under the License. import os +from StringIO import StringIO from . import logger from .env import env DEFAULT_FORMATTING = { - logger.NO_VERBOSE: {'main_msg': '{item.msg}'}, + logger.NO_VERBOSE: {'message': '{item.msg}'}, logger.LOW_VERBOSE: { - 'main_msg': '{created_at} | {item.level[0]} | {item.msg}', - 'created_at': '%H:%M:%S' - } + 'message': '{timestamp} | {item.level[0]} | {item.msg}', + 'timestamp': '%H:%M:%S' + }, + logger.MEDIUM_VERBOSE: { + 'message': '{timestamp} | {item.level[0]} | {item.msg} | {implementation}', + 'timestamp': '%H:%M:%S' + }, + logger.HIGH_VERBOSE: { + 'message': '{timestamp} | {item.level[0]} | {item.msg} | {implementation}({inputs})', + 'timestamp': '%H:%M:%S' + }, } -class load(object): +def _str(item, formatting=None): + # Only NO_VERBOSE and LOW_VERBOSE are configurable formats. configuring + # the low verbose level should affect any higher level. + formats = formatting or DEFAULT_FORMATTING + formatting = formats[env.logging.verbosity_level] + msg = StringIO() - def __init__(self, item, formats=None): - self._item = item - self._formats = formats or DEFAULT_FORMATTING + kwargs = dict(item=item) - def __repr__(self): - # Only NO_VERBOSE and LOW_VERBOSE are configurable formats. configuring - # the low verbose level should affect any higher level. - formats = self._formats[min(env.logging.verbosity_level, logger.LOW_VERBOSE)] + if item.task: + kwargs['implementation'] = item.task.implementation + kwargs['inputs'] = dict(i.unwrap() for i in item.task.inputs.values()) + else: + kwargs['implementation'] = item.execution.workflow_name + kwargs['inputs'] = dict(i.unwrap() for i in item.execution.inputs.values()) - kwargs = dict(item=self._item) - if 'created_at' in formats: - kwargs['created_at'] = self._item.created_at.strftime(formats['created_at']) - if 'level' in formats: - kwargs['level'] = formats['level'].format(self._item.level) - if 'msg' in formats: - kwargs['msg'] = formats['msg'].format(self._item.msg) + if 'timestamp' in formatting: + kwargs['timestamp'] = item.created_at.strftime(formatting['timestamp']) + else: + kwargs['timestamp'] = item.created_at - if 'actor' in formats and self._item.task: - kwargs['actor'] = formats['actor'].format(self._item.task.actor) - if 'execution' in formats: - kwargs['execution'] = formats['execution'].format(self._item.execution) + # If no format was supplied just print out the original msg. + msg.write(formatting.get('message', '{item.msg}').format(**kwargs)) - # If no format was supplied just print out the original msg. - msg = formats.get('main_msg', '{item.msg}').format(**kwargs) + # Add the exception and the error msg. + if item.traceback and env.logging.verbosity_level >= logger.MEDIUM_VERBOSE: + for line in item.traceback.splitlines(True): + msg.write('\t' + '|' + line) - # Add the exception and the error msg. - if self._item.traceback and env.logging.verbosity_level >= logger.MEDIUM_VERBOSE: - msg += os.linesep + '------>' - for line in self._item.traceback.splitlines(True): - msg += '\t' + '|' + line + return msg.getvalue() - return msg - def log(self, *args, **kwargs): - return getattr(env.logging.logger, self._item.level.lower())(self, *args, **kwargs) +def log(item, *args, **kwargs): + return getattr(env.logging.logger, item.level.lower())(_str(item), *args, **kwargs) + + +def drain(iterator): + any_logs = False + for item in iterator: + log(item) + any_logs = True + return any_logs + http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/cli/logger.py ---------------------------------------------------------------------- diff --git a/aria/cli/logger.py b/aria/cli/logger.py index f130616..c240f02 100644 --- a/aria/cli/logger.py +++ b/aria/cli/logger.py @@ -114,7 +114,7 @@ class Logging(object): dictconfig.dictConfig(logger_dict) -class ModelLogConsumer(object): +class ModelLogIterator(object): def __init__(self, model_storage, execution_id, filters=None, sort=None): self._last_visited_id = 0 http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/orchestrator/context/common.py ---------------------------------------------------------------------- diff --git a/aria/orchestrator/context/common.py b/aria/orchestrator/context/common.py index 67dffcd..64ef9a4 100644 --- a/aria/orchestrator/context/common.py +++ b/aria/orchestrator/context/common.py @@ -42,11 +42,11 @@ class BaseContext(object): self._logger = base_logger self._task_id = task_id - def __getattr__(self, item): - if item.upper() in logging._levelNames: - return partial(self._logger_with_task_id, _level=item) + def __getattr__(self, attribute): + if attribute.upper() in logging._levelNames: + return partial(self._logger_with_task_id, _level=attribute) else: - return getattr(self._logger, item) + return getattr(self._logger, attribute) def _logger_with_task_id(self, *args, **kwargs): level = kwargs.pop('_level') http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/cec57cd5/aria/orchestrator/workflows/executor/dry.py ---------------------------------------------------------------------- diff --git a/aria/orchestrator/workflows/executor/dry.py b/aria/orchestrator/workflows/executor/dry.py index d894b25..ce18580 100644 --- a/aria/orchestrator/workflows/executor/dry.py +++ b/aria/orchestrator/workflows/executor/dry.py @@ -34,15 +34,13 @@ class DryExecutor(BaseExecutor): task.started_at = datetime.utcnow() task.status = task.STARTED - actor_type = type(task.actor).__name__.lower() - implementation = '{0} > '.format(task.plugin) if task.plugin else '' - implementation += task.implementation - inputs = dict(inp.unwrap() for inp in task.inputs.values()) + task.context.logger.info( + '<dry> {actor.name} {task.interface_name}.{task.operation_name} started...' + .format(actor=task.actor, task=task)) task.context.logger.info( - 'Executing {actor_type} {task.actor.name} operation {task.interface_name} ' - '{task.operation_name}: {implementation} (Inputs: {inputs})' - .format(actor_type=actor_type, task=task, implementation=implementation, inputs=inputs)) + '<dry> {actor.name} {task.interface_name}.{task.operation_name} successful' + .format(actor=task.actor, task=task)) # updating the task manually instead of calling self._task_succeeded(task), # to avoid any side effects raising that event might cause
