ARIA-146 Support colorful execution logging
Project: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/commit/5bc28b66 Tree: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/tree/5bc28b66 Diff: http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/diff/5bc28b66 Branch: refs/heads/ARIA-148-extra-cli-commands Commit: 5bc28b6641c2e749b0eebca05281790d21bf3c00 Parents: 8dc7b00 Author: max-orlov <ma...@gigaspaces.com> Authored: Thu Apr 20 18:51:46 2017 +0300 Committer: max-orlov <ma...@gigaspaces.com> Committed: Thu Apr 27 15:34:09 2017 +0300 ---------------------------------------------------------------------- aria/cli/color.py | 95 ++++++++++++ aria/cli/commands/executions.py | 6 +- aria/cli/commands/logs.py | 6 +- aria/cli/config/config.py | 25 ++- aria/cli/config/config_template.yaml | 32 +++- aria/cli/core/aria.py | 9 ++ aria/cli/execution_logging.py | 232 +++++++++++++++++++++++----- aria/cli/helptexts.py | 1 + aria/cli/logger.py | 1 - aria/orchestrator/context/operation.py | 8 +- 10 files changed, 366 insertions(+), 49 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/color.py ---------------------------------------------------------------------- diff --git a/aria/cli/color.py b/aria/cli/color.py new file mode 100644 index 0000000..5e0355a --- /dev/null +++ b/aria/cli/color.py @@ -0,0 +1,95 @@ +# 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. +# The ASF licenses this file to You under the Apache License, Version 2.0 +# (the "License"); you may not use this file except in compliance with +# the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# 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 StringIO import StringIO +import re + +import colorama + +colorama.init() + + +class StringStylizer(object): + def __init__(self, str_, color_spec=None): + self._str = str_ + self._color_spec = color_spec + + def __repr__(self): + if self._color_spec: + return '{schema}{str}{reset}'.format( + schema=self._color_spec, str=str(self._str), reset=Colors.Style.RESET_ALL) + return self._str + + def __add__(self, other): + return str(self) + other + + def __radd__(self, other): + return other + str(self) + + def color(self, color_spec): + self._color_spec = color_spec + + def replace(self, old, new, **kwargs): + self._str = self._str.replace(str(old), str(new), **kwargs) + + def format(self, *args, **kwargs): + self._str = self._str.format(*args, **kwargs) + + def highlight(self, pattern, schema): + if pattern is None: + return + for match in set(re.findall(re.compile(pattern), self._str)): + self.replace(match, schema + match + Colors.Style.RESET_ALL + self._color_spec) + + +def _get_colors(color_type): + for name in dir(color_type): + if not name.startswith('_'): + yield (name.lower(), getattr(color_type, name)) + + +class Colors(object): + Fore = colorama.Fore + Back = colorama.Back + Style = colorama.Style + + _colors = { + 'fore': dict(_get_colors(Fore)), + 'back': dict(_get_colors(Back)), + 'style': dict(_get_colors(Style)) + } + + +class ColorSpec(object): + def __init__(self, fore=None, back=None, style=None): + """ + It is possible to provide fore, back and style arguments. each could be either + the color is lower case letter, or the actual color from colorama. + + """ + self._kwargs = dict(fore=fore, back=back, style=style) + self._str = StringIO() + for type_, colors in Colors._colors.items(): + value = self._kwargs.get(type_, None) + # the former case is if the value is a string, the latter is in case of an object. + self._str.write(colors.get(value) or value) + + def __str__(self): + return self._str.getvalue() + + def __add__(self, other): + return str(self) + str(other) + + def __radd__(self, other): + return str(other) + str(self) http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/commands/executions.py ---------------------------------------------------------------------- diff --git a/aria/cli/commands/executions.py b/aria/cli/commands/executions.py index cb86376..6176ea2 100644 --- a/aria/cli/commands/executions.py +++ b/aria/cli/commands/executions.py @@ -109,6 +109,7 @@ def list(service_name, @aria.options.dry_execution @aria.options.task_max_attempts() @aria.options.task_retry_interval() +@aria.options.mark_pattern() @aria.options.verbose() @aria.pass_model_storage @aria.pass_resource_storage @@ -120,6 +121,7 @@ def start(workflow_name, dry, task_max_attempts, task_retry_interval, + mark_pattern, model_storage, resource_storage, plugin_manager, @@ -146,7 +148,7 @@ def start(workflow_name, log_iterator = cli_logger.ModelLogIterator(model_storage, workflow_runner.execution_id) try: while execution_thread.is_alive(): - execution_logging.log_list(log_iterator) + execution_logging.log_list(log_iterator, mark_pattern=mark_pattern) execution_thread.join(1) except KeyboardInterrupt: @@ -154,7 +156,7 @@ def start(workflow_name, # 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.log_list(log_iterator) + execution_logging.log_list(log_iterator, mark_pattern=mark_pattern) # 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/5bc28b66/aria/cli/commands/logs.py ---------------------------------------------------------------------- diff --git a/aria/cli/commands/logs.py b/aria/cli/commands/logs.py index 79aff07..2f7f361 100644 --- a/aria/cli/commands/logs.py +++ b/aria/cli/commands/logs.py @@ -18,6 +18,7 @@ from ..core import aria @aria.group(name='logs') +@aria.options.verbose() def logs(): """Show logs from workflow executions """ @@ -28,15 +29,16 @@ def logs(): short_help='List execution logs') @aria.argument('execution-id') @aria.options.verbose() +@aria.options.mark_pattern() @aria.pass_model_storage @aria.pass_logger -def list(execution_id, model_storage, logger): +def list(execution_id, mark_pattern, model_storage, logger): """Display logs for an execution """ logger.info('Listing logs for execution id {0}'.format(execution_id)) log_iterator = ModelLogIterator(model_storage, execution_id) - any_logs = execution_logging.log_list(log_iterator) + any_logs = execution_logging.log_list(log_iterator, mark_pattern=mark_pattern) if not any_logs: logger.info('\tNo logs') http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/config/config.py ---------------------------------------------------------------------- diff --git a/aria/cli/config/config.py b/aria/cli/config/config.py index 99f46ca..8c4214c 100644 --- a/aria/cli/config/config.py +++ b/aria/cli/config/config.py @@ -52,10 +52,6 @@ class CliConfig(object): return cls(config_path) @property - def colors(self): - return self._config.get('colors', False) - - @property def logging(self): return self.Logging(self._config.get('logging')) @@ -71,3 +67,24 @@ class CliConfig(object): @property def loggers(self): return self._logging.get('loggers', {}) + + @property + def execution(self): + return self.Execution(self._logging.get('execution')) + + class Execution(object): + + def __init__(self, execution_logging): + self._execution_logging = execution_logging + + @property + def colors_enabled(self): + return self.colors.get('enabled', False) + + @property + def colors(self): + return self._execution_logging.get('colors', {}) + + @property + def formats(self): + return self._execution_logging.get('formats', {}) http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/config/config_template.yaml ---------------------------------------------------------------------- diff --git a/aria/cli/config/config_template.yaml b/aria/cli/config/config_template.yaml index 13f2cf9..94fcac3 100644 --- a/aria/cli/config/config_template.yaml +++ b/aria/cli/config/config_template.yaml @@ -1,4 +1,3 @@ -colors: {{ enable_colors }} logging: @@ -10,3 +9,34 @@ logging: # main logger of the cli. provides basic descriptions for executed operations. aria.cli.main: info + + execution: + formats: + # According to verbosity level 0 - no verbose. 3 - high verbose + 0: '{message}' + 1: '{timestamp:%H:%M:%S} | {level[0]} | {message}' + 2: '{timestamp:%H:%M:%S} | {level[0]} | {implementation} | {message}' + 3: '{timestamp:%H:%M:%S} | {level[0]} | {implementation} | {inputs} | {message}' + + colors: + enabled: true + + level: + default: {'fore': 'lightmagenta_ex'} + error: {'fore': 'red', 'style': 'bright'} + timestamp: + default: {'fore': 'lightmagenta_ex'} + error: {'fore': 'red', 'style': 'bright'} + message: + default: {'fore': 'lightblue_ex'} + error: {'fore': 'red', 'style': 'bright'} + implementation: + default: {'fore': 'lightblack_ex'} + error: {'fore': 'red', 'style': 'bright'} + inputs: + default: {'fore': 'blue'} + error: {'fore': 'red', 'style': 'bright'} + traceback: + default: {'fore': 'red'} + + marker: 'lightyellow_ex' http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/core/aria.py ---------------------------------------------------------------------- diff --git a/aria/cli/core/aria.py b/aria/cli/core/aria.py index ed7c490..ed6afa1 100644 --- a/aria/cli/core/aria.py +++ b/aria/cli/core/aria.py @@ -425,5 +425,14 @@ class Options(object): required=required, help=helptexts.SERVICE_ID) + @staticmethod + def mark_pattern(): + return click.option( + '-m', + '--mark-pattern', + help=helptexts.MARK_PATTERN, + type=str, + required=False + ) options = Options() http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/execution_logging.py ---------------------------------------------------------------------- diff --git a/aria/cli/execution_logging.py b/aria/cli/execution_logging.py index 8baf6d7..b23165f 100644 --- a/aria/cli/execution_logging.py +++ b/aria/cli/execution_logging.py @@ -12,67 +12,227 @@ # 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. - +import os +import re from StringIO import StringIO +from functools import partial -from . import logger +from . import ( + logger, + color +) from .env import env -DEFAULT_FORMATTING = { - logger.NO_VERBOSE: {'message': '{item.msg}'}, - logger.LOW_VERBOSE: { - 'message': '{timestamp} | {item.level[0]} | {item.msg}', - 'timestamp': '%H:%M:%S' + +FIELD_TYPE = 'field_type' +LEVEL = 'level' +TIMESTAMP = 'timestamp' +MESSAGE = 'message' +IMPLEMENTATION = 'implementation' +INPUTS = 'inputs' +TRACEBACK = 'traceback' +MARKER = 'marker' + +FINAL_STATES = 'final_states' +SUCCESS_STATE = 'succeeded' +CANCEL_STATE = 'canceled' +FAIL_STATE = 'failed' + +_EXECUTION_PATTERN = "\'.*\' workflow execution {0}".format +# In order to be able to format a string into this regex pattern, we need to provide support +# in adding this string into double curly brackets. This is an issue with python format, so we add +# this via format itself. +_FIELD_TYPE_PATTERN = partial('.*({starting}{0}{closing}).*'.format, starting='{', closing='.*?}') + +_PATTERNS = { + FINAL_STATES: { + SUCCESS_STATE: re.compile(_EXECUTION_PATTERN(SUCCESS_STATE)), + CANCEL_STATE: re.compile(_EXECUTION_PATTERN(CANCEL_STATE)), + FAIL_STATE: re.compile(_EXECUTION_PATTERN(FAIL_STATE)), }, - logger.MEDIUM_VERBOSE: { - 'message': '{timestamp} | {item.level[0]} | {implementation} | {item.msg} ', - 'timestamp': '%H:%M:%S' + FIELD_TYPE: { + IMPLEMENTATION: re.compile(_FIELD_TYPE_PATTERN(IMPLEMENTATION)), + LEVEL: re.compile(_FIELD_TYPE_PATTERN(LEVEL)), + MESSAGE: re.compile(_FIELD_TYPE_PATTERN(MESSAGE)), + INPUTS: re.compile(_FIELD_TYPE_PATTERN(INPUTS)), + TIMESTAMP: re.compile(_FIELD_TYPE_PATTERN(TIMESTAMP)) + } +} + +_FINAL_STATES = { + SUCCESS_STATE: color.Colors.Fore.GREEN, + CANCEL_STATE: color.Colors.Fore.YELLOW, + FAIL_STATE: color.Colors.Fore.RED +} + +_DEFAULT_COLORS = { + LEVEL: { + 'default': {'fore': 'lightmagenta_ex'}, + 'error': {'fore': 'red', 'style': 'bright'}, + }, + TIMESTAMP: { + 'default': {'fore': 'lightmagenta_ex'}, + 'error': {'fore': 'red', 'style': 'bright'}, }, - logger.HIGH_VERBOSE: { - 'message': '{timestamp} | {item.level[0]} | {implementation}({inputs}) | {item.msg} ', - 'timestamp': '%H:%M:%S' + MESSAGE: { + 'default': {'fore': 'lightblue_ex'}, + 'error': {'fore': 'red', 'style': 'bright'}, }, + IMPLEMENTATION:{ + 'default': {'fore': 'lightblack_ex'}, + 'error': {'fore': 'red', 'style': 'bright'}, + }, + INPUTS: { + 'default': {'fore': 'blue'}, + 'error': {'fore': 'red', 'style': 'bright'}, + }, + TRACEBACK: {'default': {'fore': 'red'}}, + + MARKER: 'lightyellow_ex' } +_DEFAULT_FORMATS = { + logger.NO_VERBOSE: '{message}', + logger.LOW_VERBOSE: '{timestamp:%H:%M:%S} | {level[0]} | {message}', + logger.MEDIUM_VERBOSE: '{timestamp:%H:%M:%S} | {level[0]} | {implementation} | {message}', + logger.HIGH_VERBOSE: + '{timestamp:%H:%M:%S} | {level[0]} | {implementation} | {inputs} | {message}' +} -def _str(item, formats=None): - # If no formats are passed we revert to the default formats (per level) - formats = formats or {} - formatting = formats.get(env.logging.verbosity_level, - DEFAULT_FORMATTING[env.logging.verbosity_level]) - msg = StringIO() - formatting_kwargs = dict(item=item) +def stylize_log(item, mark_pattern): + # implementation if item.task: - formatting_kwargs['implementation'] = item.task.implementation - formatting_kwargs['inputs'] = dict(i.unwrap() for i in item.task.inputs.values()) - else: - formatting_kwargs['implementation'] = item.execution.workflow_name - formatting_kwargs['inputs'] = dict(i.unwrap() for i in item.execution.inputs.values()) - - if 'timestamp' in formatting: - formatting_kwargs['timestamp'] = item.created_at.strftime(formatting['timestamp']) + # operation task + implementation = item.task.implementation + inputs = dict(i.unwrap() for i in item.task.inputs.values()) else: - formatting_kwargs['timestamp'] = item.created_at + # execution task + implementation = item.execution.workflow_name + inputs = dict(i.unwrap() for i in item.execution.inputs.values()) - msg.write(formatting['message'].format(**formatting_kwargs)) + stylized_str = color.StringStylizer(_get_format()) + _populate_level(stylized_str, item) + _populate_timestamp(stylized_str, item) + _populate_message(stylized_str, item, mark_pattern) + _populate_inputs(stylized_str, inputs, item, mark_pattern) + _populate_implementation(stylized_str, implementation, item, mark_pattern) + msg = StringIO() + msg.write(str(stylized_str)) # 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) + msg.write(os.linesep) + msg.writelines(_color_traceback('\t' + '|' + line, item, mark_pattern) + for line in item.traceback.splitlines(True)) return msg.getvalue() -def log(item, *args, **kwargs): - return getattr(env.logging.logger, item.level.lower())(_str(item), *args, **kwargs) +def log(item, mark_pattern=None, *args, **kwargs): + leveled_log = getattr(env.logging.logger, item.level.lower()) + return leveled_log(stylize_log(item, mark_pattern), *args, **kwargs) -def log_list(iterator): +def log_list(iterator, mark_pattern=None): any_logs = False for item in iterator: - log(item) + log(item, mark_pattern) any_logs = True return any_logs + + +def _get_format(): + return (env.config.logging.execution.formats.get(env.logging.verbosity_level) or + _DEFAULT_FORMATS.get(env.logging.verbosity_level)) + + +def _get_styles(field_type): + return env.config.logging.execution.colors[field_type] + + +def _is_color_enabled(): + # If styling is enabled and the current log_item isn't final string + return env.config.logging.execution.colors_enabled + + +def _get_marker_schema(): + return color.ColorSpec(back=_get_styles(MARKER)) + + +def _populate_implementation(str_, implementation, log_item, mark_pattern=None): + _stylize(str_, implementation, log_item, IMPLEMENTATION, mark_pattern) + + +def _populate_inputs(str_, inputs, log_item, mark_pattern=None): + _stylize(str_, inputs, log_item, INPUTS, mark_pattern) + + +def _populate_timestamp(str_, log_item): + _stylize(str_, log_item.created_at, log_item, TIMESTAMP) + + +def _populate_message(str_, log_item, mark_pattern=None): + _stylize(str_, log_item.msg, log_item, MESSAGE, mark_pattern) + + +def _populate_level(str_, log_item): + _stylize(str_, log_item.level[0], log_item, LEVEL) + + +def _stylize(stylized_str, msg, log_item, msg_type, mark_pattern=None): + match = re.match(_PATTERNS[FIELD_TYPE][msg_type], stylized_str._str) + if not match: + return + matched_substr = match.group(1) + + substring = color.StringStylizer(matched_substr) + + # handle format + substring.format(**{msg_type: msg}) + + if _is_color_enabled(): + # handle color + substring.color(_resolve_schema(msg_type, log_item)) + if not _is_end_execution_log(log_item): + # handle highlighting + substring.highlight(mark_pattern, _get_marker_schema()) + + stylized_str.replace(matched_substr, substring) + + +def _color_traceback(traceback, log_item, mark_pattern): + if _is_color_enabled(): + stylized_string = color.StringStylizer(traceback, _resolve_schema(TRACEBACK, log_item)) + stylized_string.highlight(mark_pattern, _get_marker_schema()) + return stylized_string + return traceback + + +def _is_end_execution_log(log_item): + return not log_item.task and bool(_end_execution_schema(log_item)) + + +def _end_execution_schema(log_item): + for state, pattern in _PATTERNS[FINAL_STATES].items(): + if re.match(pattern, log_item.msg): + return _FINAL_STATES[state] + + +def _resolve_schema(msg_type, log_item): + if _is_end_execution_log(log_item): + return _end_execution_schema(log_item) + else: + return color.ColorSpec( + **( + # retrieve the schema from the user config according to the level + _get_styles(msg_type).get(log_item.level.lower()) or + # retrieve the default schema from the user config + _get_styles(msg_type).get('default') or + # retrieve the schema from the aria default config according to the level + _DEFAULT_COLORS[msg_type].get(log_item.level.lower()) or + # retrieve the default schema from the aria default config + _DEFAULT_COLORS[msg_type].get('default') + ) + ) http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/helptexts.py ---------------------------------------------------------------------- diff --git a/aria/cli/helptexts.py b/aria/cli/helptexts.py index 1a3f6c0..8641822 100644 --- a/aria/cli/helptexts.py +++ b/aria/cli/helptexts.py @@ -47,3 +47,4 @@ IGNORE_AVAILABLE_NODES = "Delete the service even if it has available nodes" SORT_BY = "Key for sorting the list" DESCENDING = "Sort list in descending order [default: False]" JSON_OUTPUT = "Output logs in a consumable JSON format" +MARK_PATTERN = "Mark a regex pattern in the logs" http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/cli/logger.py ---------------------------------------------------------------------- diff --git a/aria/cli/logger.py b/aria/cli/logger.py index c240f02..5de3701 100644 --- a/aria/cli/logger.py +++ b/aria/cli/logger.py @@ -19,7 +19,6 @@ import copy import logging from logutils import dictconfig - HIGH_VERBOSE = 3 MEDIUM_VERBOSE = 2 LOW_VERBOSE = 1 http://git-wip-us.apache.org/repos/asf/incubator-ariatosca/blob/5bc28b66/aria/orchestrator/context/operation.py ---------------------------------------------------------------------- diff --git a/aria/orchestrator/context/operation.py b/aria/orchestrator/context/operation.py index c383958..68a02aa 100644 --- a/aria/orchestrator/context/operation.py +++ b/aria/orchestrator/context/operation.py @@ -30,11 +30,12 @@ class BaseOperationContext(BaseContext): """ def __init__(self, task_id, actor_id, **kwargs): - super(BaseOperationContext, self).__init__(**kwargs) self._task_id = task_id self._actor_id = actor_id self._thread_local = threading.local() - self._register_logger(task_id=self.task.id) + logger_level = kwargs.pop('logger_level', None) + super(BaseOperationContext, self).__init__(**kwargs) + self._register_logger(task_id=self.task.id, level=logger_level) def __repr__(self): details = 'implementation={task.implementation}; ' \ @@ -80,7 +81,8 @@ class BaseOperationContext(BaseContext): 'workdir': self._workdir, 'model_storage': self.model.serialization_dict if self.model else None, 'resource_storage': self.resource.serialization_dict if self.resource else None, - 'execution_id': self._execution_id + 'execution_id': self._execution_id, + 'logger_level': self.logger.level } return { 'context_cls': context_cls,