Synced log module and its dependencies from olso-incubator

Old version of 'log' module depended on oslo-incubator RPC layer
implementation. This sync is intended to copy the following fix that
makes log module use oslo.messaging.notify.log_handler if available:

  * 109e325e: Use oslo.messaging to publish log errors

blueprint oslo-messaging

Change-Id: Ieb26df4e9fbb2aa4d319c79be7510006fc8461ab

neutron/openstack/common/gettextutils.py

@@ -373,8 +373,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):
+    for (locale_, alias) in six.iteritems(aliases):
-        if locale in language_list and alias not in language_list:
+        if locale_ in language_list and alias not in language_list:
             language_list.append(alias)
 
     _AVAILABLE_LANGUAGES[domain] = language_list

neutron/openstack/common/importutils.py

@@ -24,10 +24,10 @@ import traceback
 def import_class(import_str):
     """Returns a class from a string including module and class."""
     mod_str, _sep, class_str = import_str.rpartition('.')
+    __import__(mod_str)
     try:
-        __import__(mod_str)
         return getattr(sys.modules[mod_str], class_str)
-    except (ValueError, AttributeError):
+    except AttributeError:
         raise ImportError('Class %s cannot be found (%s)' %
                           (class_str,
                            traceback.format_exception(*sys.exc_info())))
@@ -58,6 +58,13 @@ def import_module(import_str):
     return sys.modules[import_str]
 
 
+def import_versioned_module(version, submodule=None):
+    module = 'neutron.v%s' % version
+    if submodule:
+        module = '.'.join((module, submodule))
+    return import_module(module)
+
+
 def try_import(import_str, default=None):
     """Try to import a module and if it fails return default."""
     try:

neutron/openstack/common/jsonutils.py

@@ -168,12 +168,12 @@ def dumps(value, default=to_primitive, **kwargs):
     return json.dumps(value, default=default, **kwargs)
 
 
-def loads(s, encoding='utf-8'):
+def loads(s, encoding='utf-8', **kwargs):
-    return json.loads(strutils.safe_decode(s, encoding))
+    return json.loads(strutils.safe_decode(s, encoding), **kwargs)
 
 
-def load(fp, encoding='utf-8'):
+def load(fp, encoding='utf-8', **kwargs):
-    return json.load(codecs.getreader(encoding)(fp))
+    return json.load(codecs.getreader(encoding)(fp), **kwargs)
 
 
 try:

neutron/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
@@ -59,7 +59,10 @@ _SANITIZE_PATTERNS = []
 _FORMAT_PATTERNS = [r'(%(key)s\s*[=]\s*[\"\']).*?([\"\'])',
                     r'(<%(key)s>).*?(</%(key)s>)',
                     r'([\"\']%(key)s[\"\']\s*:\s*[\"\']).*?([\"\'])',
-                    r'([\'"].*?%(key)s[\'"]\s*:\s*u?[\'"]).*?([\'"])']
+                    r'([\'"].*?%(key)s[\'"]\s*:\s*u?[\'"]).*?([\'"])',
+                    r'([\'"].*?%(key)s[\'"]\s*,\s*\'--?[A-z]+\'\s*,\s*u?[\'"])'
+                    '.*?([\'"])',
+                    r'(%(key)s\s*--?[A-z]+\s*).*?([\s])']
 
 for key in _SANITIZE_KEYS:
     for pattern in _FORMAT_PATTERNS:
@@ -84,14 +87,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 '
+               help='The name of a logging configuration file. This file '
-                    'disable existing loggers, but just appends specified '
+                    'is appended to any existing logging configuration '
-                    'logging configuration to any other existing logging '
+                    'files. For details about logging configuration files, '
-                    'options. Please see the Python logging module '
+                    'see the Python logging module documentation.'),
-                    'documentation for details on logging configuration '
-                    'files.'),
     cfg.StrOpt('log-format',
-               default=None,
                metavar='FORMAT',
                help='DEPRECATED. '
                     'A logging.Formatter log message format string which may '
@@ -103,7 +103,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,19 +112,30 @@ 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.')
 ]
 
 log_opts = [
@@ -132,18 +143,18 @@ log_opts = [
                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',
@@ -152,27 +163,29 @@ log_opts = [
                     'qpid=WARN',
                     'sqlalchemy=WARN',
                     'suds=INFO',
+                    'oslo.messaging=INFO',
                     'iso8601=WARN',
+                    'requests.packages.urllib3.connectionpool=WARN'
                 ],
-                help='list of logger=LEVEL pairs'),
+                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 '
+               help='The format for an instance that is passed with the log '
-                    'it like this'),
+                    'message. '),
     cfg.StrOpt('instance_uuid_format',
                default='[instance: %(uuid)s] ',
-               help='If an instance UUID is passed with the log message, '
+               help='The format for an instance UUID that is passed with the '
-                    'format it like this'),
+                    'log message. '),
 ]
 
 CONF = cfg.CONF
@@ -292,18 +305,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 +358,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 +424,10 @@ class JSONFormatter(logging.Formatter):
 
 def _create_logging_excepthook(product_name):
     def logging_excepthook(exc_type, value, tb):
-        extra = {}
+        extra = {'exc_info': (exc_type, value, tb)}
-        if CONF.verbose:
+        getLogger(product_name).critical(
-            extra['exc_info'] = (exc_type, value, tb)
+            "".join(traceback.format_exception_only(exc_type, value)),
-        getLogger(product_name).critical(str(value), **extra)
+            **extra)
     return logging_excepthook
 
 
@@ -415,22 +449,21 @@ def _load_log_config(log_config_append):
         logging.config.fileConfig(log_config_append,
                                   disable_existing_loggers=False)
     except moves.configparser.Error as exc:
-        raise LogConfigError(log_config_append, str(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,
+    cfg.set_defaults(
-                     logging_context_format_string=
+        log_opts, logging_context_format_string=logging_context_format_string)
-                     logging_context_format_string)
 
 
 def _find_facility_from_conf():
@@ -457,15 +490,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',
+        # TODO(bogdando) use the format provided by RFCSysLogHandler
-                                                facility=facility)
+        #   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 +540,14 @@ def _setup_logging_from_conf():
         log_root.addHandler(streamlog)
 
     if CONF.publish_errors:
-        handler = importutils.import_object(
+        try:
-            "neutron.openstack.common.log_handler.PublishErrorsHandler",
+            handler = importutils.import_object(
-            logging.ERROR)
+                "neutron.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 +560,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 +573,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 +612,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 +626,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):
+        if record.__dict__.get('request_id'):
-            self._fmt = CONF.logging_context_format_string
+            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)

neutron/openstack/common/log_handler.py

@@ -1,30 +0,0 @@
-# Copyright 2013 IBM Corp.
-#
-#    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.
-
-import logging
-
-from oslo.config import cfg
-
-from neutron.openstack.common import notifier
-
-
-class PublishErrorsHandler(logging.Handler):
-    def emit(self, record):
-        if ('neutron.openstack.common.notifier.log_notifier' in
-                cfg.CONF.notification_driver):
-            return
-        notifier.api.notify(None, 'error.publisher',
-                            'error_notification',
-                            notifier.api.ERROR,
-                            dict(error=record.getMessage()))

neutron/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

openstack-common.conf

@@ -15,7 +15,6 @@ module=jsonutils
 module=local
 module=lockutils
 module=log
-module=log_handler
 module=loopingcall
 module=middleware
 module=network_utils