# Copyright 2011 OpenStack Foundation. # Copyright 2010 United States Government as represented by the # Administrator of the National Aeronautics and Space Administration. # 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. """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 is not specified, default formatting is used. Additionally, an instance uuid may be passed as part of the log message, which is intended to make it easier for admins to find messages related to a specific instance. It also allows setting of formatting information through conf. """ import configparser import logging import logging.config import logging.handlers import os import platform import sys try: import syslog except ImportError: syslog = None from oslo_config import cfg from oslo_utils import eventletutils from oslo_utils import importutils from oslo_utils import units from oslo_log._i18n import _ from oslo_log import _options from oslo_log import formatters from oslo_log import handlers CRITICAL = logging.CRITICAL FATAL = logging.FATAL ERROR = logging.ERROR WARNING = logging.WARNING WARN = logging.WARNING INFO = logging.INFO DEBUG = logging.DEBUG NOTSET = logging.NOTSET TRACE = handlers._TRACE logging.addLevelName(TRACE, 'TRACE') LOG_ROTATE_INTERVAL_MAPPING = { 'seconds': 's', 'minutes': 'm', 'hours': 'h', 'days': 'd', 'weekday': 'w', 'midnight': 'midnight' } _EVENTLET_FIX_APPLIED = False def _get_log_file_path(conf, binary=None): logfile = conf.log_file logdir = conf.log_dir if logfile and not logdir: return logfile if logfile and logdir: return os.path.join(logdir, logfile) if logdir: binary = binary or handlers._get_binary_name() return '{}.log'.format(os.path.join(logdir, binary)) return None def _iter_loggers(): """Iterate on existing loggers.""" # Sadly, Logger.manager and Manager.loggerDict are not documented, # but there is no logging public function to iterate on all loggers. # The root logger is not part of loggerDict. yield logging.getLogger() manager = logging.Logger.manager for logger in manager.loggerDict.values(): if isinstance(logger, logging.PlaceHolder): continue yield logger class BaseLoggerAdapter(logging.LoggerAdapter): warn = logging.LoggerAdapter.warning @property def handlers(self): return self.logger.handlers def trace(self, msg, *args, **kwargs): self.log(TRACE, msg, *args, **kwargs) class KeywordArgumentAdapter(BaseLoggerAdapter): """Logger adapter to add keyword arguments to log record's extra data Keywords passed to the log call are added to the "extra" dictionary passed to the underlying logger so they are emitted with the log message and available to the format string. Special keywords: extra An existing dictionary of extra values to be passed to the logger. If present, the dictionary is copied and extended. resource A dictionary-like object containing a ``name`` key or ``type`` and ``id`` keys. """ def process(self, msg, kwargs): # Make a new extra dictionary combining the values we were # given when we were constructed and anything from kwargs. extra = {} extra.update(self.extra) if 'extra' in kwargs: extra.update(kwargs.pop('extra')) # Move any unknown keyword arguments into the extra # dictionary. for name in list(kwargs.keys()): if name == 'exc_info': continue extra[name] = kwargs.pop(name) # NOTE(dhellmann): The gap between when the adapter is called # and when the formatter needs to know what the extra values # are is large enough that we can't get back to the original # extra dictionary easily. We leave a hint to ourselves here # in the form of a list of keys, which will eventually be # attributes of the LogRecord processed by the formatter. That # allows the formatter to know which values were original and # which were extra, so it can treat them differently (see # JSONFormatter for an example of this). We sort the keys so # it is possible to write sane unit tests. extra['extra_keys'] = list(sorted(extra.keys())) # Place the updated extra values back into the keyword # arguments. kwargs['extra'] = extra # NOTE(jdg): We would like an easy way to add resource info # to logging, for example a header like 'volume-' # Turns out Nova implemented this but it's Nova specific with # instance. Also there's resource_uuid that's been added to # context, but again that only works for Instances, and it # only works for contexts that have the resource id set. resource = kwargs['extra'].get('resource', None) if resource: # Many OpenStack resources have a name entry in their db ref # of the form -, let's just use that if # it's passed in if not resource.get('name', None): # For resources that don't have the name of the format we wish # to use (or places where the LOG call may not have the full # object ref, allow them to pass in a dict: # resource={'type': volume, 'id': uuid} resource_type = resource.get('type', None) resource_id = resource.get('id', None) if resource_type and resource_id: kwargs['extra']['resource'] = ('[' + resource_type + '-' + resource_id + '] ') else: # FIXME(jdg): Since the name format can be specified via conf # entry, we may want to consider allowing this to be configured # here as well kwargs['extra']['resource'] = ('[' + resource.get('name', '') + '] ') return msg, kwargs def _create_logging_excepthook(product_name): def logging_excepthook(exc_type, value, tb): extra = {'exc_info': (exc_type, value, tb)} getLogger(product_name).critical('Unhandled error', **extra) return logging_excepthook class LogConfigError(Exception): message = _('Error loading logging config %(log_config)s: %(err_msg)s') def __init__(self, log_config, err_msg): self.log_config = log_config self.err_msg = err_msg def __str__(self): return self.message % dict(log_config=self.log_config, err_msg=self.err_msg) def _load_log_config(log_config_append): try: if not hasattr(_load_log_config, "old_time"): _load_log_config.old_time = 0 new_time = os.path.getmtime(log_config_append) if _load_log_config.old_time != new_time: # Reset all existing loggers before reloading config as fileConfig # does not reset non-child loggers. for logger in _iter_loggers(): logger.setLevel(logging.NOTSET) logger.handlers = [] logger.propagate = 1 logging.config.fileConfig(log_config_append, disable_existing_loggers=False) _load_log_config.old_time = new_time except (configparser.Error, KeyError, OSError, RuntimeError) as exc: raise LogConfigError(log_config_append, str(exc)) def _mutate_hook(conf, fresh): """Reconfigures oslo.log according to the mutated options.""" if (None, 'debug') in fresh: _refresh_root_level(conf.debug) if (None, 'log-config-append') in fresh: _load_log_config.old_time = 0 if conf.log_config_append: _load_log_config(conf.log_config_append) def register_options(conf): """Register the command line and configuration options used by oslo.log.""" # Sometimes logging occurs before logging is ready (e.g., oslo_config). # To avoid "No handlers could be found," temporarily log to sys.stderr. root_logger = logging.getLogger(None) if not root_logger.handlers: root_logger.addHandler(logging.StreamHandler()) conf.register_cli_opts(_options.common_cli_opts) conf.register_cli_opts(_options.logging_cli_opts) conf.register_opts(_options.generic_log_opts) conf.register_opts(_options.log_opts) formatters._store_global_conf(conf) conf.register_mutate_hook(_mutate_hook) def _fix_eventlet_logging(): """Properly setup logging with eventlet on native threads. Workaround for: https://github.com/eventlet/eventlet/issues/432 """ global _EVENTLET_FIX_APPLIED # If eventlet was not loaded before call to setup assume it's not used. if eventletutils.is_monkey_patched('thread') and not _EVENTLET_FIX_APPLIED: import eventlet.green.threading from oslo_log import pipe_mutex logging.threading = eventlet.green.threading logging._lock = logging.threading.RLock() logging.Handler.createLock = pipe_mutex.pipe_createLock _EVENTLET_FIX_APPLIED = True def setup(conf, product_name, version='unknown', *, fix_eventlet=True): """Setup logging for the current application.""" if fix_eventlet: _fix_eventlet_logging() if conf.log_config_append: _load_log_config(conf.log_config_append) else: _setup_logging_from_conf(conf, product_name, version) sys.excepthook = _create_logging_excepthook(product_name) def set_defaults(logging_context_format_string=None, default_log_levels=None): """Set default values for the configuration options used by oslo.log.""" # 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 not None: cfg.set_defaults( _options.log_opts, default_log_levels=default_log_levels) if logging_context_format_string is not None: cfg.set_defaults( _options.log_opts, logging_context_format_string=logging_context_format_string) def tempest_set_log_file(filename): """Provide an API for tempest to set the logging filename. .. warning:: Only Tempest should use this function. We don't want applications to set a default log file, so we don't want this in set_defaults(). Because tempest doesn't use a configuration file we don't have another convenient way to safely set the log file default. """ cfg.set_defaults(_options.logging_cli_opts, log_file=filename) def _find_facility(facility): # NOTE(jd): Check the validity of facilities at run time as they differ # depending on the OS and Python version being used. valid_facilities = [f for f in ["LOG_KERN", "LOG_USER", "LOG_MAIL", "LOG_DAEMON", "LOG_AUTH", "LOG_SYSLOG", "LOG_LPR", "LOG_NEWS", "LOG_UUCP", "LOG_CRON", "LOG_AUTHPRIV", "LOG_FTP", "LOG_LOCAL0", "LOG_LOCAL1", "LOG_LOCAL2", "LOG_LOCAL3", "LOG_LOCAL4", "LOG_LOCAL5", "LOG_LOCAL6", "LOG_LOCAL7"] if getattr(syslog, f, None)] facility = facility.upper() if not facility.startswith("LOG_"): facility = "LOG_" + facility if facility not in valid_facilities: raise TypeError(_('syslog facility must be one of: %s') % ', '.join("'%s'" % fac for fac in valid_facilities)) return getattr(syslog, facility) def _refresh_root_level(debug): """Set the level of the root logger. :param debug: If 'debug' is True, the level will be DEBUG. Otherwise the level will be INFO. """ log_root = getLogger(None).logger if debug: log_root.setLevel(logging.DEBUG) else: log_root.setLevel(logging.INFO) def _setup_logging_from_conf(conf, project, version): log_root = getLogger(None).logger # Remove all handlers for handler in list(log_root.handlers): log_root.removeHandler(handler) logpath = _get_log_file_path(conf) if logpath: # On Windows, in-use files cannot be moved or deleted. if conf.watch_log_file: raise RuntimeError('watch_log_file feature was removed because ' 'it has been broken for multiple releases.') elif conf.log_rotation_type.lower() == "interval": file_handler = logging.handlers.TimedRotatingFileHandler when = conf.log_rotate_interval_type.lower() interval_type = LOG_ROTATE_INTERVAL_MAPPING[when] # When weekday is configured, "when" has to be a value between # 'w0'-'w6' (w0 for Monday, w1 for Tuesday, and so on)' if interval_type == 'w': interval_type = interval_type + str(conf.log_rotate_interval) filelog = file_handler(logpath, when=interval_type, interval=conf.log_rotate_interval, backupCount=conf.max_logfile_count) elif conf.log_rotation_type.lower() == "size": file_handler = logging.handlers.RotatingFileHandler maxBytes = conf.max_logfile_size_mb * units.Mi filelog = file_handler(logpath, maxBytes=maxBytes, backupCount=conf.max_logfile_count) else: file_handler = logging.handlers.WatchedFileHandler filelog = file_handler(logpath) log_root.addHandler(filelog) if conf.use_stderr: if conf.log_color: streamlog = handlers.ColorHandler() else: streamlog = logging.StreamHandler() log_root.addHandler(streamlog) if conf.use_journal: if syslog is None: raise RuntimeError("syslog is not available on this platform") facility = _find_facility(conf.syslog_log_facility) journal = handlers.OSJournalHandler(facility=facility) log_root.addHandler(journal) if conf.use_eventlog: if platform.system() == 'Windows': eventlog = logging.handlers.NTEventLogHandler(project) log_root.addHandler(eventlog) else: raise RuntimeError(_("Windows Event Log is not available on this " "platform.")) # if None of the above are True, then fall back to standard out if not logpath and not conf.use_stderr and not conf.use_journal: if conf.log_color: streamlog = handlers.ColorHandler(sys.stdout) else: streamlog = logging.StreamHandler(sys.stdout) log_root.addHandler(streamlog) if conf.publish_errors: handler = importutils.import_object( "oslo_messaging.notify.log_handler.PublishErrorsHandler", logging.ERROR) log_root.addHandler(handler) if conf.use_syslog: if syslog is None: raise RuntimeError("syslog is not available on this platform") facility = _find_facility(conf.syslog_log_facility) syslog_handler = handlers.OSSysLogHandler(facility=facility) log_root.addHandler(syslog_handler) datefmt = conf.log_date_format if not conf.use_json: for handler in log_root.handlers: handler.setFormatter(formatters.ContextFormatter(project=project, version=version, datefmt=datefmt, config=conf)) else: for handler in log_root.handlers: handler.setFormatter(formatters.JSONFormatter(datefmt=datefmt)) _refresh_root_level(conf.debug) for pair in conf.default_log_levels: mod, _sep, level_name = pair.partition('=') logger = logging.getLogger(mod) numeric_level = None try: # NOTE(harlowja): integer's are valid level names, and for some # libraries they have a lower level than DEBUG that is typically # defined at level 5, so to make that accessible, try to convert # this to a integer, and if not keep the original... numeric_level = int(level_name) except ValueError: # nosec pass if numeric_level is not None: logger.setLevel(numeric_level) else: logger.setLevel(level_name) if conf.rate_limit_burst >= 1 and conf.rate_limit_interval >= 1: from oslo_log import rate_limit rate_limit.install_filter(conf.rate_limit_burst, conf.rate_limit_interval, conf.rate_limit_except_level) _loggers = {} def get_loggers(): """Return a copy of the oslo loggers dictionary.""" return _loggers.copy() def getLogger(name=None, project='unknown', version='unknown'): """Build a logger with the given name. :param name: The name for the logger. This is usually the module name, ``__name__``. :type name: string :param project: The name of the project, to be injected into log messages. For example, ``'nova'``. :type project: string :param version: The version of the project, to be injected into log messages. For example, ``'2014.2'``. :type version: string """ # NOTE(dhellmann): To maintain backwards compatibility with the # old oslo namespace package logger configurations, and to make it # possible to control all oslo logging with one logger node, we # replace "oslo_" with "oslo." so that modules under the new # non-namespaced packages get loggers as though they are. if name and name.startswith('oslo_'): name = 'oslo.' + name[5:] if name not in _loggers: _loggers[name] = KeywordArgumentAdapter(logging.getLogger(name), {'project': project, 'version': version}) return _loggers[name] def get_default_log_levels(): """Return the Oslo Logging default log levels. Returns a copy of the list so an application can change the value and not affect the default value used in the log_opts configuration setup. """ return list(_options.DEFAULT_LOG_LEVELS) def is_debug_enabled(conf): """Determine if debug logging mode is enabled.""" return conf.debug