From 2bbdf42c8504ca242266309fbe7095deae9de527 Mon Sep 17 00:00:00 2001 From: Sean Dague Date: Fri, 11 Jul 2014 07:58:33 -0400 Subject: [PATCH] olso log sync The oslo log fix to actually print out CRITICAL exceptions is needed to debug tempest/javelin2 in any real way. Change-Id: I5a91cff829fec268ebf9c01a5fe84225e4fe72d1 --- etc/tempest.conf.sample | 54 ++-- tempest/openstack/common/gettextutils.py | 67 ++--- tempest/openstack/common/jsonutils.py | 36 +-- tempest/openstack/common/log.py | 298 ++++++++++++++--------- tempest/openstack/common/strutils.py | 295 ++++++++++++++++++++++ tempest/openstack/common/timeutils.py | 4 +- 6 files changed, 556 insertions(+), 198 deletions(-) create mode 100644 tempest/openstack/common/strutils.py diff --git a/etc/tempest.conf.sample b/etc/tempest.conf.sample index 858fce9c54..8a7ad9c5d4 100644 --- a/etc/tempest.conf.sample +++ b/etc/tempest.conf.sample @@ -23,47 +23,48 @@ # of default WARNING level). (boolean value) #verbose=false -# Log output to standard error (boolean value) +# Log output to standard error. (boolean value) #use_stderr=true -# format string to use for log messages with context (string +# Format string to use for log messages with context. (string # value) #logging_context_format_string=%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s -# format string to use for log messages without context +# Format string to use for log messages without context. # (string value) #logging_default_format_string=%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [-] %(instance)s%(message)s -# data to append to log format when level is DEBUG (string +# Data to append to log format when level is DEBUG. (string # value) #logging_debug_format_suffix=%(funcName)s %(pathname)s:%(lineno)d -# prefix each line of exception output with this format +# Prefix each line of exception output with this format. # (string value) #logging_exception_prefix=%(asctime)s.%(msecs)03d %(process)d TRACE %(name)s %(instance)s -# list of logger=LEVEL pairs (list value) -#default_log_levels=amqp=WARN,amqplib=WARN,boto=WARN,qpid=WARN,sqlalchemy=WARN,suds=INFO,iso8601=WARN +# List of logger=LEVEL pairs. (list value) +#default_log_levels=amqp=WARN,amqplib=WARN,boto=WARN,qpid=WARN,sqlalchemy=WARN,suds=INFO,oslo.messaging=INFO,iso8601=WARN,requests.packages.urllib3.connectionpool=WARN,urllib3.connectionpool=WARN -# publish error events (boolean value) +# Enables or disables publication of error events. (boolean +# value) #publish_errors=false -# make deprecations fatal (boolean value) +# Enables or disables fatal status of deprecations. (boolean +# value) #fatal_deprecations=false -# If an instance is passed with the log message, format it -# like this (string value) +# The format for an instance that is passed with the log +# message. (string value) #instance_format="[instance: %(uuid)s] " -# If an instance UUID is passed with the log message, format -# it like this (string value) +# The format for an instance UUID that is passed with the log +# message. (string value) #instance_uuid_format="[instance: %(uuid)s] " -# The name of logging configuration file. It does not disable -# existing loggers, but just appends specified logging -# configuration to any other existing logging options. Please -# see the Python logging module documentation for details on -# logging configuration files. (string value) +# The name of a logging configuration file. This file is +# appended to any existing logging configuration files. For +# details about logging configuration files, see the Python +# logging module documentation. (string value) # Deprecated group/name - [DEFAULT]/log_config #log_config_append= @@ -75,7 +76,7 @@ #log_format= # Format string for %%(asctime)s in log records. Default: -# %(default)s (string value) +# %(default)s . (string value) #log_date_format=%Y-%m-%d %H:%M:%S # (Optional) Name of log file to output to. If no default is @@ -84,14 +85,23 @@ #log_file= # (Optional) The base directory used for relative --log-file -# paths (string value) +# paths. (string value) # Deprecated group/name - [DEFAULT]/logdir #log_dir= -# Use syslog for logging. (boolean value) +# Use syslog for logging. Existing syslog format is DEPRECATED +# during I, and will change in J to honor RFC5424. (boolean +# value) #use_syslog=false -# syslog facility to receive log lines (string value) +# (Optional) Enables or disables syslog rfc5424 format for +# logging. If enabled, prefixes the MSG part of the syslog +# message with APP-NAME (RFC5424). The format without the APP- +# NAME is deprecated in I, and will be removed in J. (boolean +# value) +#use_syslog_rfc_format=false + +# Syslog facility to receive log lines. (string value) #syslog_log_facility=LOG_USER diff --git a/tempest/openstack/common/gettextutils.py b/tempest/openstack/common/gettextutils.py index 6102e677ee..872d58ea51 100644 --- a/tempest/openstack/common/gettextutils.py +++ b/tempest/openstack/common/gettextutils.py @@ -23,7 +23,6 @@ Usual usage in an openstack.common module: """ import copy -import functools import gettext import locale from logging import handlers @@ -42,7 +41,7 @@ class TranslatorFactory(object): """Create translator functions """ - def __init__(self, domain, lazy=False, localedir=None): + def __init__(self, domain, localedir=None): """Establish a set of translation functions for the domain. :param domain: Name of translation domain, @@ -55,7 +54,6 @@ class TranslatorFactory(object): :type localedir: str """ self.domain = domain - self.lazy = lazy if localedir is None: localedir = os.environ.get(domain.upper() + '_LOCALEDIR') self.localedir = localedir @@ -75,16 +73,19 @@ class TranslatorFactory(object): """ if domain is None: domain = self.domain - if self.lazy: - return functools.partial(Message, domain=domain) - t = gettext.translation( - domain, - localedir=self.localedir, - fallback=True, - ) - if six.PY3: - return t.gettext - return t.ugettext + t = gettext.translation(domain, + localedir=self.localedir, + fallback=True) + # Use the appropriate method of the translation object based + # on the python version. + m = t.gettext if six.PY3 else t.ugettext + + def f(msg): + """oslo.i18n.gettextutils translation function.""" + if USE_LAZY: + return Message(msg, domain=domain) + return m(msg) + return f @property def primary(self): @@ -147,19 +148,11 @@ def enable_lazy(): your project is importing _ directly instead of using the gettextutils.install() way of importing the _ function. """ - # FIXME(dhellmann): This function will be removed in oslo.i18n, - # because the TranslatorFactory makes it superfluous. - global _, _LI, _LW, _LE, _LC, USE_LAZY - tf = TranslatorFactory('tempest', lazy=True) - _ = tf.primary - _LI = tf.log_info - _LW = tf.log_warning - _LE = tf.log_error - _LC = tf.log_critical + global USE_LAZY USE_LAZY = True -def install(domain, lazy=False): +def install(domain): """Install a _() function using the given translation domain. Given a translation domain, install a _() function using gettext's @@ -170,26 +163,14 @@ def install(domain, lazy=False): a translation-domain-specific environment variable (e.g. NOVA_LOCALEDIR). + Note that to enable lazy translation, enable_lazy must be + called. + :param domain: the translation domain - :param lazy: indicates whether or not to install the lazy _() function. - The lazy _() introduces a way to do deferred translation - of messages by installing a _ that builds Message objects, - instead of strings, which can then be lazily translated into - any available locale. """ - if lazy: - from six import moves - tf = TranslatorFactory(domain, lazy=True) - moves.builtins.__dict__['_'] = tf.primary - else: - localedir = '%s_LOCALEDIR' % domain.upper() - if six.PY3: - gettext.install(domain, - localedir=os.environ.get(localedir)) - else: - gettext.install(domain, - localedir=os.environ.get(localedir), - unicode=True) + from six import moves + tf = TranslatorFactory(domain) + moves.builtins.__dict__['_'] = tf.primary class Message(six.text_type): @@ -373,8 +354,8 @@ def get_available_languages(domain): 'zh_Hant_HK': 'zh_HK', 'zh_Hant': 'zh_TW', 'fil': 'tl_PH'} - for (locale, alias) in six.iteritems(aliases): - if locale in language_list and alias not in language_list: + for (locale_, alias) in six.iteritems(aliases): + if locale_ in language_list and alias not in language_list: language_list.append(alias) _AVAILABLE_LANGUAGES[domain] = language_list diff --git a/tempest/openstack/common/jsonutils.py b/tempest/openstack/common/jsonutils.py index 53c0ad4048..cb83557fee 100644 --- a/tempest/openstack/common/jsonutils.py +++ b/tempest/openstack/common/jsonutils.py @@ -31,25 +31,29 @@ This module provides a few things: ''' +import codecs import datetime import functools import inspect import itertools -import json -try: - import xmlrpclib -except ImportError: - # NOTE(jaypipes): xmlrpclib was renamed to xmlrpc.client in Python3 - # however the function and object call signatures - # remained the same. This whole try/except block should - # be removed and replaced with a call to six.moves once - # six 1.4.2 is released. See http://bit.ly/1bqrVzu - import xmlrpc.client as xmlrpclib +import sys + +if sys.version_info < (2, 7): + # On Python <= 2.6, json module is not C boosted, so try to use + # simplejson module if available + try: + import simplejson as json + except ImportError: + import json +else: + import json import six +import six.moves.xmlrpc_client as xmlrpclib from tempest.openstack.common import gettextutils from tempest.openstack.common import importutils +from tempest.openstack.common import strutils from tempest.openstack.common import timeutils netaddr = importutils.try_import("netaddr") @@ -164,12 +168,16 @@ def dumps(value, default=to_primitive, **kwargs): return json.dumps(value, default=default, **kwargs) -def loads(s): - return json.loads(s) +def dump(obj, fp, *args, **kwargs): + return json.dump(obj, fp, *args, **kwargs) -def load(s): - return json.load(s) +def loads(s, encoding='utf-8', **kwargs): + return json.loads(strutils.safe_decode(s, encoding), **kwargs) + + +def load(fp, encoding='utf-8', **kwargs): + return json.load(codecs.getreader(encoding)(fp), **kwargs) try: diff --git a/tempest/openstack/common/log.py b/tempest/openstack/common/log.py index 7bebfdbacc..44102c06e3 100644 --- a/tempest/openstack/common/log.py +++ b/tempest/openstack/common/log.py @@ -15,7 +15,7 @@ # License for the specific language governing permissions and limitations # under the License. -"""Openstack logging handler. +"""OpenStack logging handler. This module adds to logging functionality by adding the option to specify a context object when calling the various log methods. If the context object @@ -33,7 +33,6 @@ import logging import logging.config import logging.handlers import os -import re import sys import traceback @@ -45,27 +44,13 @@ from tempest.openstack.common.gettextutils import _ from tempest.openstack.common import importutils from tempest.openstack.common import jsonutils from tempest.openstack.common import local +# NOTE(flaper87): Pls, remove when graduating this module +# from the incubator. +from tempest.openstack.common.strutils import mask_password # noqa _DEFAULT_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S" -_SANITIZE_KEYS = ['adminPass', 'admin_pass', 'password', 'admin_password'] - -# NOTE(ldbragst): Let's build a list of regex objects using the list of -# _SANITIZE_KEYS we already have. This way, we only have to add the new key -# to the list of _SANITIZE_KEYS and we can generate regular expressions -# for XML and JSON automatically. -_SANITIZE_PATTERNS = [] -_FORMAT_PATTERNS = [r'(%(key)s\s*[=]\s*[\"\']).*?([\"\'])', - r'(<%(key)s>).*?()', - r'([\"\']%(key)s[\"\']\s*:\s*[\"\']).*?([\"\'])', - r'([\'"].*?%(key)s[\'"]\s*:\s*u?[\'"]).*?([\'"])'] - -for key in _SANITIZE_KEYS: - for pattern in _FORMAT_PATTERNS: - reg_ex = re.compile(pattern % {'key': key}, re.DOTALL) - _SANITIZE_PATTERNS.append(reg_ex) - common_cli_opts = [ cfg.BoolOpt('debug', @@ -84,14 +69,11 @@ logging_cli_opts = [ cfg.StrOpt('log-config-append', metavar='PATH', deprecated_name='log-config', - help='The name of logging configuration file. It does not ' - 'disable existing loggers, but just appends specified ' - 'logging configuration to any other existing logging ' - 'options. Please see the Python logging module ' - 'documentation for details on logging configuration ' - 'files.'), + help='The name of a logging configuration file. This file ' + 'is appended to any existing logging configuration ' + 'files. For details about logging configuration files, ' + 'see the Python logging module documentation.'), cfg.StrOpt('log-format', - default=None, metavar='FORMAT', help='DEPRECATED. ' 'A logging.Formatter log message format string which may ' @@ -103,7 +85,7 @@ logging_cli_opts = [ default=_DEFAULT_LOG_DATE_FORMAT, metavar='DATE_FORMAT', help='Format string for %%(asctime)s in log records. ' - 'Default: %(default)s'), + 'Default: %(default)s .'), cfg.StrOpt('log-file', metavar='PATH', deprecated_name='logfile', @@ -112,67 +94,76 @@ logging_cli_opts = [ cfg.StrOpt('log-dir', deprecated_name='logdir', help='(Optional) The base directory used for relative ' - '--log-file paths'), + '--log-file paths.'), cfg.BoolOpt('use-syslog', default=False, - help='Use syslog for logging.'), + help='Use syslog for logging. ' + 'Existing syslog format is DEPRECATED during I, ' + 'and will change in J to honor RFC5424.'), + cfg.BoolOpt('use-syslog-rfc-format', + # TODO(bogdando) remove or use True after existing + # syslog format deprecation in J + default=False, + help='(Optional) Enables or disables syslog rfc5424 format ' + 'for logging. If enabled, prefixes the MSG part of the ' + 'syslog message with APP-NAME (RFC5424). The ' + 'format without the APP-NAME is deprecated in I, ' + 'and will be removed in J.'), cfg.StrOpt('syslog-log-facility', default='LOG_USER', - help='syslog facility to receive log lines') + help='Syslog facility to receive log lines.') ] generic_log_opts = [ cfg.BoolOpt('use_stderr', default=True, - help='Log output to standard error') + help='Log output to standard error.') ] +DEFAULT_LOG_LEVELS = ['amqp=WARN', 'amqplib=WARN', 'boto=WARN', + 'qpid=WARN', 'sqlalchemy=WARN', 'suds=INFO', + 'oslo.messaging=INFO', 'iso8601=WARN', + 'requests.packages.urllib3.connectionpool=WARN', + 'urllib3.connectionpool=WARN'] + log_opts = [ cfg.StrOpt('logging_context_format_string', default='%(asctime)s.%(msecs)03d %(process)d %(levelname)s ' '%(name)s [%(request_id)s %(user_identity)s] ' '%(instance)s%(message)s', - help='format string to use for log messages with context'), + help='Format string to use for log messages with context.'), cfg.StrOpt('logging_default_format_string', default='%(asctime)s.%(msecs)03d %(process)d %(levelname)s ' '%(name)s [-] %(instance)s%(message)s', - help='format string to use for log messages without context'), + help='Format string to use for log messages without context.'), cfg.StrOpt('logging_debug_format_suffix', default='%(funcName)s %(pathname)s:%(lineno)d', - help='data to append to log format when level is DEBUG'), + help='Data to append to log format when level is DEBUG.'), cfg.StrOpt('logging_exception_prefix', default='%(asctime)s.%(msecs)03d %(process)d TRACE %(name)s ' '%(instance)s', - help='prefix each line of exception output with this format'), + help='Prefix each line of exception output with this format.'), cfg.ListOpt('default_log_levels', - default=[ - 'amqp=WARN', - 'amqplib=WARN', - 'boto=WARN', - 'qpid=WARN', - 'sqlalchemy=WARN', - 'suds=INFO', - 'iso8601=WARN', - ], - help='list of logger=LEVEL pairs'), + default=DEFAULT_LOG_LEVELS, + help='List of logger=LEVEL pairs.'), cfg.BoolOpt('publish_errors', default=False, - help='publish error events'), + help='Enables or disables publication of error events.'), cfg.BoolOpt('fatal_deprecations', default=False, - help='make deprecations fatal'), + help='Enables or disables fatal status of deprecations.'), # NOTE(mikal): there are two options here because sometimes we are handed # a full instance (and could include more information), and other times we # are just handed a UUID for the instance. cfg.StrOpt('instance_format', default='[instance: %(uuid)s] ', - help='If an instance is passed with the log message, format ' - 'it like this'), + help='The format for an instance that is passed with the log ' + 'message.'), cfg.StrOpt('instance_uuid_format', default='[instance: %(uuid)s] ', - help='If an instance UUID is passed with the log message, ' - 'format it like this'), + help='The format for an instance UUID that is passed with the ' + 'log message.'), ] CONF = cfg.CONF @@ -231,40 +222,6 @@ def _get_log_file_path(binary=None): return None -def mask_password(message, secret="***"): - """Replace password with 'secret' in message. - - :param message: The string which includes security information. - :param secret: value with which to replace passwords. - :returns: The unicode value of message with the password fields masked. - - For example: - - >>> mask_password("'adminPass' : 'aaaaa'") - "'adminPass' : '***'" - >>> mask_password("'admin_pass' : 'aaaaa'") - "'admin_pass' : '***'" - >>> mask_password('"password" : "aaaaa"') - '"password" : "***"' - >>> mask_password("'original_password' : 'aaaaa'") - "'original_password' : '***'" - >>> mask_password("u'original_password' : u'aaaaa'") - "u'original_password' : u'***'" - """ - message = six.text_type(message) - - # NOTE(ldbragst): Check to see if anything in message contains any key - # specified in _SANITIZE_KEYS, if not then just return the message since - # we don't have to mask any passwords. - if not any(key in message for key in _SANITIZE_KEYS): - return message - - secret = r'\g<1>' + secret + r'\g<2>' - for pattern in _SANITIZE_PATTERNS: - message = re.sub(pattern, secret, message) - return message - - class BaseLoggerAdapter(logging.LoggerAdapter): def audit(self, msg, *args, **kwargs): @@ -282,6 +239,11 @@ class LazyAdapter(BaseLoggerAdapter): def logger(self): if not self._logger: self._logger = getLogger(self.name, self.version) + if six.PY3: + # In Python 3, the code fails because the 'manager' attribute + # cannot be found when using a LoggerAdapter as the + # underlying logger. Work around this issue. + self._logger.manager = self._logger.logger.manager return self._logger @@ -292,18 +254,39 @@ class ContextAdapter(BaseLoggerAdapter): self.logger = logger self.project = project_name self.version = version_string + self._deprecated_messages_sent = dict() @property def handlers(self): return self.logger.handlers def deprecated(self, msg, *args, **kwargs): + """Call this method when a deprecated feature is used. + + If the system is configured for fatal deprecations then the message + is logged at the 'critical' level and :class:`DeprecatedConfig` will + be raised. + + Otherwise, the message will be logged (once) at the 'warn' level. + + :raises: :class:`DeprecatedConfig` if the system is configured for + fatal deprecations. + + """ stdmsg = _("Deprecated: %s") % msg if CONF.fatal_deprecations: self.critical(stdmsg, *args, **kwargs) raise DeprecatedConfig(msg=stdmsg) - else: - self.warn(stdmsg, *args, **kwargs) + + # Using a list because a tuple with dict can't be stored in a set. + sent_args = self._deprecated_messages_sent.setdefault(msg, list()) + + if args in sent_args: + # Already logged this message, so don't log it again. + return + + sent_args.append(args) + self.warn(stdmsg, *args, **kwargs) def process(self, msg, kwargs): # NOTE(mrodden): catch any Message/other object and @@ -324,7 +307,7 @@ class ContextAdapter(BaseLoggerAdapter): extra.update(_dictify_context(context)) instance = kwargs.pop('instance', None) - instance_uuid = (extra.get('instance_uuid', None) or + instance_uuid = (extra.get('instance_uuid') or kwargs.pop('instance_uuid', None)) instance_extra = '' if instance: @@ -390,10 +373,10 @@ class JSONFormatter(logging.Formatter): def _create_logging_excepthook(product_name): def logging_excepthook(exc_type, value, tb): - extra = {} - if CONF.verbose: - extra['exc_info'] = (exc_type, value, tb) - getLogger(product_name).critical(str(value), **extra) + extra = {'exc_info': (exc_type, value, tb)} + getLogger(product_name).critical( + "".join(traceback.format_exception_only(exc_type, value)), + **extra) return logging_excepthook @@ -414,23 +397,31 @@ def _load_log_config(log_config_append): try: logging.config.fileConfig(log_config_append, disable_existing_loggers=False) - except moves.configparser.Error as exc: - raise LogConfigError(log_config_append, str(exc)) + except (moves.configparser.Error, KeyError) as exc: + raise LogConfigError(log_config_append, six.text_type(exc)) -def setup(product_name): +def setup(product_name, version='unknown'): """Setup logging.""" if CONF.log_config_append: _load_log_config(CONF.log_config_append) else: - _setup_logging_from_conf() + _setup_logging_from_conf(product_name, version) sys.excepthook = _create_logging_excepthook(product_name) -def set_defaults(logging_context_format_string): - cfg.set_defaults(log_opts, - logging_context_format_string= - logging_context_format_string) +def set_defaults(logging_context_format_string, + default_log_levels=None): + # Just in case the caller is not setting the + # default_log_level. This is insurance because + # we introduced the default_log_level parameter + # later in a backwards in-compatible change + if default_log_levels is None: + default_log_levels = DEFAULT_LOG_LEVELS + cfg.set_defaults( + log_opts, + logging_context_format_string=logging_context_format_string, + default_log_levels=default_log_levels) def _find_facility_from_conf(): @@ -457,15 +448,38 @@ def _find_facility_from_conf(): return facility -def _setup_logging_from_conf(): +class RFCSysLogHandler(logging.handlers.SysLogHandler): + def __init__(self, *args, **kwargs): + self.binary_name = _get_binary_name() + # Do not use super() unless type(logging.handlers.SysLogHandler) + # is 'type' (Python 2.7). + # Use old style calls, if the type is 'classobj' (Python 2.6) + logging.handlers.SysLogHandler.__init__(self, *args, **kwargs) + + def format(self, record): + # Do not use super() unless type(logging.handlers.SysLogHandler) + # is 'type' (Python 2.7). + # Use old style calls, if the type is 'classobj' (Python 2.6) + msg = logging.handlers.SysLogHandler.format(self, record) + msg = self.binary_name + ' ' + msg + return msg + + +def _setup_logging_from_conf(project, version): log_root = getLogger(None).logger for handler in log_root.handlers: log_root.removeHandler(handler) if CONF.use_syslog: facility = _find_facility_from_conf() - syslog = logging.handlers.SysLogHandler(address='/dev/log', - facility=facility) + # TODO(bogdando) use the format provided by RFCSysLogHandler + # after existing syslog format deprecation in J + if CONF.use_syslog_rfc_format: + syslog = RFCSysLogHandler(address='/dev/log', + facility=facility) + else: + syslog = logging.handlers.SysLogHandler(address='/dev/log', + facility=facility) log_root.addHandler(syslog) logpath = _get_log_file_path() @@ -484,9 +498,14 @@ def _setup_logging_from_conf(): log_root.addHandler(streamlog) if CONF.publish_errors: - handler = importutils.import_object( - "tempest.openstack.common.log_handler.PublishErrorsHandler", - logging.ERROR) + try: + handler = importutils.import_object( + "tempest.openstack.common.log_handler.PublishErrorsHandler", + logging.ERROR) + except ImportError: + handler = importutils.import_object( + "oslo.messaging.notify.log_handler.PublishErrorsHandler", + logging.ERROR) log_root.addHandler(handler) datefmt = CONF.log_date_format @@ -499,7 +518,9 @@ def _setup_logging_from_conf(): log_root.info('Deprecated: log_format is now deprecated and will ' 'be removed in the next release') else: - handler.setFormatter(ContextFormatter(datefmt=datefmt)) + handler.setFormatter(ContextFormatter(project=project, + version=version, + datefmt=datefmt)) if CONF.debug: log_root.setLevel(logging.DEBUG) @@ -510,9 +531,15 @@ def _setup_logging_from_conf(): for pair in CONF.default_log_levels: mod, _sep, level_name = pair.partition('=') - level = logging.getLevelName(level_name) logger = logging.getLogger(mod) - logger.setLevel(level) + # NOTE(AAzza) in python2.6 Logger.setLevel doesn't convert string name + # to integer code. + if sys.version_info < (2, 7): + level = logging.getLevelName(level_name) + logger.setLevel(level) + else: + logger.setLevel(level_name) + _loggers = {} @@ -543,7 +570,7 @@ class WritableLogger(object): self.level = level def write(self, msg): - self.logger.log(self.level, msg) + self.logger.log(self.level, msg.rstrip()) class ContextFormatter(logging.Formatter): @@ -557,27 +584,64 @@ class ContextFormatter(logging.Formatter): For information about what variables are available for the formatter see: http://docs.python.org/library/logging.html#formatter + If available, uses the context value stored in TLS - local.store.context + """ + def __init__(self, *args, **kwargs): + """Initialize ContextFormatter instance + + Takes additional keyword arguments which can be used in the message + format string. + + :keyword project: project name + :type project: string + :keyword version: project version + :type version: string + + """ + + self.project = kwargs.pop('project', 'unknown') + self.version = kwargs.pop('version', 'unknown') + + logging.Formatter.__init__(self, *args, **kwargs) + def format(self, record): """Uses contextstring if request_id is set, otherwise default.""" - # NOTE(sdague): default the fancier formating params + + # store project info + record.project = self.project + record.version = self.version + + # store request info + context = getattr(local.store, 'context', None) + if context: + d = _dictify_context(context) + for k, v in d.items(): + setattr(record, k, v) + + # NOTE(sdague): default the fancier formatting params # to an empty string so we don't throw an exception if # they get used - for key in ('instance', 'color'): + for key in ('instance', 'color', 'user_identity'): if key not in record.__dict__: record.__dict__[key] = '' - if record.__dict__.get('request_id', None): - self._fmt = CONF.logging_context_format_string + if record.__dict__.get('request_id'): + fmt = CONF.logging_context_format_string else: - self._fmt = CONF.logging_default_format_string + fmt = CONF.logging_default_format_string if (record.levelno == logging.DEBUG and CONF.logging_debug_format_suffix): - self._fmt += " " + CONF.logging_debug_format_suffix + fmt += " " + CONF.logging_debug_format_suffix - # Cache this on the record, Logger will respect our formated copy + if sys.version_info < (3, 2): + self._fmt = fmt + else: + self._style = logging.PercentStyle(fmt) + self._fmt = self._style._fmt + # Cache this on the record, Logger will respect our formatted copy if record.exc_info: record.exc_text = self.formatException(record.exc_info, record) return logging.Formatter.format(self, record) diff --git a/tempest/openstack/common/strutils.py b/tempest/openstack/common/strutils.py new file mode 100644 index 0000000000..605cc029e9 --- /dev/null +++ b/tempest/openstack/common/strutils.py @@ -0,0 +1,295 @@ +# Copyright 2011 OpenStack Foundation. +# All Rights Reserved. +# +# Licensed 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. + +""" +System-level utilities and helper functions. +""" + +import math +import re +import sys +import unicodedata + +import six + +from tempest.openstack.common.gettextutils import _ + + +UNIT_PREFIX_EXPONENT = { + 'k': 1, + 'K': 1, + 'Ki': 1, + 'M': 2, + 'Mi': 2, + 'G': 3, + 'Gi': 3, + 'T': 4, + 'Ti': 4, +} +UNIT_SYSTEM_INFO = { + 'IEC': (1024, re.compile(r'(^[-+]?\d*\.?\d+)([KMGT]i?)?(b|bit|B)$')), + 'SI': (1000, re.compile(r'(^[-+]?\d*\.?\d+)([kMGT])?(b|bit|B)$')), +} + +TRUE_STRINGS = ('1', 't', 'true', 'on', 'y', 'yes') +FALSE_STRINGS = ('0', 'f', 'false', 'off', 'n', 'no') + +SLUGIFY_STRIP_RE = re.compile(r"[^\w\s-]") +SLUGIFY_HYPHENATE_RE = re.compile(r"[-\s]+") + + +# NOTE(flaper87): The following 3 globals are used by `mask_password` +_SANITIZE_KEYS = ['adminPass', 'admin_pass', 'password', 'admin_password'] + +# NOTE(ldbragst): Let's build a list of regex objects using the list of +# _SANITIZE_KEYS we already have. This way, we only have to add the new key +# to the list of _SANITIZE_KEYS and we can generate regular expressions +# for XML and JSON automatically. +_SANITIZE_PATTERNS = [] +_FORMAT_PATTERNS = [r'(%(key)s\s*[=]\s*[\"\']).*?([\"\'])', + r'(<%(key)s>).*?()', + r'([\"\']%(key)s[\"\']\s*:\s*[\"\']).*?([\"\'])', + r'([\'"].*?%(key)s[\'"]\s*:\s*u?[\'"]).*?([\'"])', + r'([\'"].*?%(key)s[\'"]\s*,\s*\'--?[A-z]+\'\s*,\s*u?[\'"])' + '.*?([\'"])', + r'(%(key)s\s*--?[A-z]+\s*)\S+(\s*)'] + +for key in _SANITIZE_KEYS: + for pattern in _FORMAT_PATTERNS: + reg_ex = re.compile(pattern % {'key': key}, re.DOTALL) + _SANITIZE_PATTERNS.append(reg_ex) + + +def int_from_bool_as_string(subject): + """Interpret a string as a boolean and return either 1 or 0. + + Any string value in: + + ('True', 'true', 'On', 'on', '1') + + is interpreted as a boolean True. + + Useful for JSON-decoded stuff and config file parsing + """ + return bool_from_string(subject) and 1 or 0 + + +def bool_from_string(subject, strict=False, default=False): + """Interpret a string as a boolean. + + A case-insensitive match is performed such that strings matching 't', + 'true', 'on', 'y', 'yes', or '1' are considered True and, when + `strict=False`, anything else returns the value specified by 'default'. + + Useful for JSON-decoded stuff and config file parsing. + + If `strict=True`, unrecognized values, including None, will raise a + ValueError which is useful when parsing values passed in from an API call. + Strings yielding False are 'f', 'false', 'off', 'n', 'no', or '0'. + """ + if not isinstance(subject, six.string_types): + subject = six.text_type(subject) + + lowered = subject.strip().lower() + + if lowered in TRUE_STRINGS: + return True + elif lowered in FALSE_STRINGS: + return False + elif strict: + acceptable = ', '.join( + "'%s'" % s for s in sorted(TRUE_STRINGS + FALSE_STRINGS)) + msg = _("Unrecognized value '%(val)s', acceptable values are:" + " %(acceptable)s") % {'val': subject, + 'acceptable': acceptable} + raise ValueError(msg) + else: + return default + + +def safe_decode(text, incoming=None, errors='strict'): + """Decodes incoming text/bytes string using `incoming` if they're not + already unicode. + + :param incoming: Text's current encoding + :param errors: Errors handling policy. See here for valid + values http://docs.python.org/2/library/codecs.html + :returns: text or a unicode `incoming` encoded + representation of it. + :raises TypeError: If text is not an instance of str + """ + if not isinstance(text, (six.string_types, six.binary_type)): + raise TypeError("%s can't be decoded" % type(text)) + + if isinstance(text, six.text_type): + return text + + if not incoming: + incoming = (sys.stdin.encoding or + sys.getdefaultencoding()) + + try: + return text.decode(incoming, errors) + except UnicodeDecodeError: + # Note(flaper87) If we get here, it means that + # sys.stdin.encoding / sys.getdefaultencoding + # didn't return a suitable encoding to decode + # text. This happens mostly when global LANG + # var is not set correctly and there's no + # default encoding. In this case, most likely + # python will use ASCII or ANSI encoders as + # default encodings but they won't be capable + # of decoding non-ASCII characters. + # + # Also, UTF-8 is being used since it's an ASCII + # extension. + return text.decode('utf-8', errors) + + +def safe_encode(text, incoming=None, + encoding='utf-8', errors='strict'): + """Encodes incoming text/bytes string using `encoding`. + + If incoming is not specified, text is expected to be encoded with + current python's default encoding. (`sys.getdefaultencoding`) + + :param incoming: Text's current encoding + :param encoding: Expected encoding for text (Default UTF-8) + :param errors: Errors handling policy. See here for valid + values http://docs.python.org/2/library/codecs.html + :returns: text or a bytestring `encoding` encoded + representation of it. + :raises TypeError: If text is not an instance of str + """ + if not isinstance(text, (six.string_types, six.binary_type)): + raise TypeError("%s can't be encoded" % type(text)) + + if not incoming: + incoming = (sys.stdin.encoding or + sys.getdefaultencoding()) + + if isinstance(text, six.text_type): + return text.encode(encoding, errors) + elif text and encoding != incoming: + # Decode text before encoding it with `encoding` + text = safe_decode(text, incoming, errors) + return text.encode(encoding, errors) + else: + return text + + +def string_to_bytes(text, unit_system='IEC', return_int=False): + """Converts a string into an float representation of bytes. + + The units supported for IEC :: + + Kb(it), Kib(it), Mb(it), Mib(it), Gb(it), Gib(it), Tb(it), Tib(it) + KB, KiB, MB, MiB, GB, GiB, TB, TiB + + The units supported for SI :: + + kb(it), Mb(it), Gb(it), Tb(it) + kB, MB, GB, TB + + Note that the SI unit system does not support capital letter 'K' + + :param text: String input for bytes size conversion. + :param unit_system: Unit system for byte size conversion. + :param return_int: If True, returns integer representation of text + in bytes. (default: decimal) + :returns: Numerical representation of text in bytes. + :raises ValueError: If text has an invalid value. + + """ + try: + base, reg_ex = UNIT_SYSTEM_INFO[unit_system] + except KeyError: + msg = _('Invalid unit system: "%s"') % unit_system + raise ValueError(msg) + match = reg_ex.match(text) + if match: + magnitude = float(match.group(1)) + unit_prefix = match.group(2) + if match.group(3) in ['b', 'bit']: + magnitude /= 8 + else: + msg = _('Invalid string format: %s') % text + raise ValueError(msg) + if not unit_prefix: + res = magnitude + else: + res = magnitude * pow(base, UNIT_PREFIX_EXPONENT[unit_prefix]) + if return_int: + return int(math.ceil(res)) + return res + + +def to_slug(value, incoming=None, errors="strict"): + """Normalize string. + + Convert to lowercase, remove non-word characters, and convert spaces + to hyphens. + + Inspired by Django's `slugify` filter. + + :param value: Text to slugify + :param incoming: Text's current encoding + :param errors: Errors handling policy. See here for valid + values http://docs.python.org/2/library/codecs.html + :returns: slugified unicode representation of `value` + :raises TypeError: If text is not an instance of str + """ + value = safe_decode(value, incoming, errors) + # NOTE(aababilov): no need to use safe_(encode|decode) here: + # encodings are always "ascii", error handling is always "ignore" + # and types are always known (first: unicode; second: str) + value = unicodedata.normalize("NFKD", value).encode( + "ascii", "ignore").decode("ascii") + value = SLUGIFY_STRIP_RE.sub("", value).strip().lower() + return SLUGIFY_HYPHENATE_RE.sub("-", value) + + +def mask_password(message, secret="***"): + """Replace password with 'secret' in message. + + :param message: The string which includes security information. + :param secret: value with which to replace passwords. + :returns: The unicode value of message with the password fields masked. + + For example: + + >>> mask_password("'adminPass' : 'aaaaa'") + "'adminPass' : '***'" + >>> mask_password("'admin_pass' : 'aaaaa'") + "'admin_pass' : '***'" + >>> mask_password('"password" : "aaaaa"') + '"password" : "***"' + >>> mask_password("'original_password' : 'aaaaa'") + "'original_password' : '***'" + >>> mask_password("u'original_password' : u'aaaaa'") + "u'original_password' : u'***'" + """ + message = six.text_type(message) + + # NOTE(ldbragst): Check to see if anything in message contains any key + # specified in _SANITIZE_KEYS, if not then just return the message since + # we don't have to mask any passwords. + if not any(key in message for key in _SANITIZE_KEYS): + return message + + secret = r'\g<1>' + secret + r'\g<2>' + for pattern in _SANITIZE_PATTERNS: + message = re.sub(pattern, secret, message) + return message diff --git a/tempest/openstack/common/timeutils.py b/tempest/openstack/common/timeutils.py index d5ed81d3e3..c48da95f12 100644 --- a/tempest/openstack/common/timeutils.py +++ b/tempest/openstack/common/timeutils.py @@ -114,7 +114,7 @@ def utcnow(): def iso8601_from_timestamp(timestamp): - """Returns a iso8601 formated date from timestamp.""" + """Returns an iso8601 formatted date from timestamp.""" return isotime(datetime.datetime.utcfromtimestamp(timestamp)) @@ -134,7 +134,7 @@ def set_time_override(override_time=None): def advance_time_delta(timedelta): """Advance overridden time using a datetime.timedelta.""" - assert(not utcnow.override_time is None) + assert utcnow.override_time is not None try: for dt in utcnow.override_time: dt += timedelta