From 8fde280b869ce6ccd913896477f923b8046374f6 Mon Sep 17 00:00:00 2001 From: Alexis Lee Date: Wed, 16 Mar 2016 16:34:20 +0000 Subject: [PATCH] Reload log_config_append config on SIGHUP On SIGHUP the mutate_hook will be called. Call fileConfig to reconfigure logging if log-config-append changes or the timestamp of the file it points to changes. Implements: bp mutable-logging Change-Id: I8ca8e6b4e9218f3a2edaf9ecf53653d829bc0c12 --- oslo_log/_options.py | 1 + oslo_log/log.py | 22 +- oslo_log/tests/unit/test_log.py | 292 ++++++++++++++++-- .../reload_log_config-743817192b1172b6.yaml | 5 + 4 files changed, 283 insertions(+), 37 deletions(-) create mode 100644 releasenotes/notes/reload_log_config-743817192b1172b6.yaml diff --git a/oslo_log/_options.py b/oslo_log/_options.py index aaaf235d..3a2fb2fa 100644 --- a/oslo_log/_options.py +++ b/oslo_log/_options.py @@ -49,6 +49,7 @@ logging_cli_opts = [ cfg.StrOpt('log-config-append', metavar='PATH', deprecated_name='log-config', + mutable=True, help='The name of a logging configuration file. This file ' 'is appended to any existing logging configuration ' 'files. For details about logging configuration files, ' diff --git a/oslo_log/log.py b/oslo_log/log.py index c956f501..1d7f3e2a 100644 --- a/oslo_log/log.py +++ b/oslo_log/log.py @@ -212,9 +212,20 @@ class LogConfigError(Exception): def _load_log_config(log_config_append): try: - logging.config.fileConfig(log_config_append, - disable_existing_loggers=False) - except (moves.configparser.Error, KeyError) as exc: + 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.level = 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 (moves.configparser.Error, KeyError, os.error) as exc: raise LogConfigError(log_config_append, six.text_type(exc)) @@ -226,6 +237,11 @@ def _mutate_hook(conf, fresh): if (None, 'debug') in fresh: _refresh_root_level(conf.debug, conf.verbose) + 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.""" diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py index 61b76cca..35b79f8a 100644 --- a/oslo_log/tests/unit/test_log.py +++ b/oslo_log/tests/unit/test_log.py @@ -16,6 +16,7 @@ # License for the specific language governing permissions and limitations # under the License. +from contextlib import contextmanager import copy import datetime import logging @@ -48,6 +49,20 @@ from oslo_log import handlers from oslo_log import log +MIN_LOG_INI = b"""[loggers] +keys=root + +[formatters] +keys= + +[handlers] +keys= + +[logger_root] +handlers= +""" + + def _fake_context(): ctxt = context.RequestContext(1, 1, overwrite=True) ctxt.user = 'myuser' @@ -967,32 +982,254 @@ class FastWatchedFileHandlerTestCase(BaseTestCase): self.assertTrue(os.path.exists(log_path)) -class ConfigTestCase(test_base.BaseTestCase): - def test_mutate(self): - conf = cfg.CONF - old_config = ("[DEFAULT]\n" - "debug = false\n") - new_config = ("[DEFAULT]\n" - "debug = true\n") - paths = self.create_tempfiles([('old', old_config), - ('new', new_config)]) - log.register_options(conf) - conf(['--config-file', paths[0]]) +class MutateTestCase(BaseTestCase): + def setup_confs(self, *confs): + paths = self.create_tempfiles( + ('conf_%d' % i, conf) for i, conf in enumerate(confs)) + self.CONF(['--config-file', paths[0]]) + return paths + + def test_debug(self): + paths = self.setup_confs( + "[DEFAULT]\ndebug = false\n", + "[DEFAULT]\ndebug = true\n") log_root = log.getLogger(None).logger - - log._setup_logging_from_conf(conf, 'test', 'test') - self.assertEqual(conf.debug, False) - - self.assertEqual(conf.verbose, True) + log._setup_logging_from_conf(self.CONF, 'test', 'test') + self.assertEqual(self.CONF.debug, False) + self.assertEqual(self.CONF.verbose, True) self.assertEqual(log.INFO, log_root.getEffectiveLevel()) shutil.copy(paths[1], paths[0]) - conf.mutate_config_files() + self.CONF.mutate_config_files() - self.assertEqual(conf.debug, True) - self.assertEqual(conf.verbose, True) + self.assertEqual(self.CONF.debug, True) + self.assertEqual(self.CONF.verbose, True) self.assertEqual(log.DEBUG, log_root.getEffectiveLevel()) + @mock.patch.object(logging.config, "fileConfig") + def test_log_config_append(self, mock_fileConfig): + logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] + paths = self.setup_confs( + "[DEFAULT]\nlog_config_append = no_exist\n", + "[DEFAULT]\nlog_config_append = %s\n" % logini) + self.assertRaises(log.LogConfigError, log.setup, self.CONF, '') + self.assertFalse(mock_fileConfig.called) + + shutil.copy(paths[1], paths[0]) + self.CONF.mutate_config_files() + + mock_fileConfig.assert_called_once_with( + logini, disable_existing_loggers=False) + + @mock.patch.object(logging.config, "fileConfig") + def test_log_config_append_no_touch(self, mock_fileConfig): + logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] + self.setup_confs("[DEFAULT]\nlog_config_append = %s\n" % logini) + log.setup(self.CONF, '') + mock_fileConfig.assert_called_once_with( + logini, disable_existing_loggers=False) + mock_fileConfig.reset_mock() + + self.CONF.mutate_config_files() + + self.assertFalse(mock_fileConfig.called) + + @mock.patch.object(logging.config, "fileConfig") + def test_log_config_append_touch(self, mock_fileConfig): + logini = self.create_tempfiles([('log.ini', MIN_LOG_INI)])[0] + self.setup_confs("[DEFAULT]\nlog_config_append = %s\n" % logini) + log.setup(self.CONF, '') + mock_fileConfig.assert_called_once_with( + logini, disable_existing_loggers=False) + mock_fileConfig.reset_mock() + + # No thread sync going on here, just ensure the mtimes are different + time.sleep(0.1) + os.utime(logini, None) + self.CONF.mutate_config_files() + + mock_fileConfig.assert_called_once_with( + logini, disable_existing_loggers=False) + + def mk_log_config(self, data): + """Turns a dictConfig-like structure into one suitable for fileConfig. + + The schema is not validated as this is a test helper not production + code. Garbage in, garbage out. Particularly, don't try to use filters, + fileConfig doesn't support them. + + Handler args must be passed like 'args': (1, 2). dictConfig passes + keys by keyword name and fileConfig passes them by position so + accepting the dictConfig form makes it nigh impossible to produce the + fileConfig form. + + I traverse dicts by sorted keys for output stability but it doesn't + matter if defaulted keys are out of order. + """ + lines = [] + for section in ['formatters', 'handlers', 'loggers']: + items = data.get(section, {}) + keys = sorted(items) + skeys = ",".join(keys) + if section == 'loggers' and 'root' in data: + skeys = ("root," + skeys) if skeys else "root" + lines.extend(["[%s]" % section, + "keys=%s" % skeys]) + for key in keys: + lines.extend(["", + "[%s_%s]" % (section[:-1], key)]) + item = items[key] + lines.extend("%s=%s" % (k, item[k]) for k in sorted(item)) + if section == 'handlers': + if 'args' not in item: + lines.append("args=()") + elif section == 'loggers': + lines.append("qualname=%s" % key) + if 'handlers' not in item: + lines.append("handlers=") + lines.append("") + root = data.get('root', {}) + if root: + lines.extend(["[logger_root]"]) + lines.extend("%s=%s" % (k, root[k]) for k in sorted(root)) + if 'handlers' not in root: + lines.append("handlers=") + return "\n".join(lines) + + def test_mk_log_config_full(self): + data = {'loggers': {'aaa': {'level': 'INFO'}, + 'bbb': {'level': 'WARN', + 'propagate': False}}, + 'handlers': {'aaa': {'level': 'INFO'}, + 'bbb': {'level': 'WARN', + 'propagate': False, + 'args': (1, 2)}}, + 'formatters': {'aaa': {'level': 'INFO'}, + 'bbb': {'level': 'WARN', + 'propagate': False}}, + 'root': {'level': 'INFO', + 'handlers': 'aaa'}, + } + full = """[formatters] +keys=aaa,bbb + +[formatter_aaa] +level=INFO + +[formatter_bbb] +level=WARN +propagate=False + +[handlers] +keys=aaa,bbb + +[handler_aaa] +level=INFO +args=() + +[handler_bbb] +args=(1, 2) +level=WARN +propagate=False + +[loggers] +keys=root,aaa,bbb + +[logger_aaa] +level=INFO +qualname=aaa +handlers= + +[logger_bbb] +level=WARN +propagate=False +qualname=bbb +handlers= + +[logger_root] +handlers=aaa +level=INFO""" + self.assertEqual(full, self.mk_log_config(data)) + + def test_mk_log_config_empty(self): + """Ensure mk_log_config tolerates missing bits""" + empty = """[formatters] +keys= + +[handlers] +keys= + +[loggers] +keys= +""" + self.assertEqual(empty, self.mk_log_config({})) + + @contextmanager + def mutate_conf(self, conf1, conf2): + loginis = self.create_tempfiles([ + ('log1.ini', self.mk_log_config(conf1)), + ('log2.ini', self.mk_log_config(conf2))]) + confs = self.setup_confs( + "[DEFAULT]\nlog_config_append = %s\n" % loginis[0], + "[DEFAULT]\nlog_config_append = %s\n" % loginis[1]) + log.setup(self.CONF, '') + + yield loginis, confs + shutil.copy(confs[1], confs[0]) + self.CONF.mutate_config_files() + + @mock.patch.object(logging.config, "fileConfig") + def test_log_config_append_change_file(self, mock_fileConfig): + with self.mutate_conf({}, {}) as (loginis, confs): + mock_fileConfig.assert_called_once_with( + loginis[0], disable_existing_loggers=False) + mock_fileConfig.reset_mock() + + mock_fileConfig.assert_called_once_with( + loginis[1], disable_existing_loggers=False) + + def set_root_stream(self): + root = logging.getLogger() + self.assertEqual(1, len(root.handlers)) + handler = root.handlers[0] + handler.stream = six.StringIO() + return handler.stream + + def test_remove_handler(self): + fake_handler = {'class': 'logging.StreamHandler', + 'args': ()} + conf1 = {'root': {'handlers': 'fake'}, + 'handlers': {'fake': fake_handler}} + conf2 = {'root': {'handlers': ''}} + with self.mutate_conf(conf1, conf2) as (loginis, confs): + stream = self.set_root_stream() + root = logging.getLogger() + root.error("boo") + self.assertEqual("boo\n", stream.getvalue()) + stream.truncate(0) + root.error("boo") + self.assertEqual("", stream.getvalue()) + + def test_remove_logger(self): + fake_handler = {'class': 'logging.StreamHandler'} + fake_logger = {'level': 'WARN'} + conf1 = {'root': {'handlers': 'fake'}, + 'handlers': {'fake': fake_handler}, + 'loggers': {'a.a': fake_logger}} + conf2 = {'root': {'handlers': 'fake'}, + 'handlers': {'fake': fake_handler}} + stream = six.StringIO() + with self.mutate_conf(conf1, conf2) as (loginis, confs): + stream = self.set_root_stream() + log = logging.getLogger("a.a") + log.info("info") + log.warn("warn") + self.assertEqual("warn\n", stream.getvalue()) + stream = self.set_root_stream() + log.info("info") + log.warn("warn") + self.assertEqual("info\nwarn\n", stream.getvalue()) + class LogConfigOptsTestCase(BaseTestCase): @@ -1103,22 +1340,9 @@ class LogConfigOptsTestCase(BaseTestCase): class LogConfigTestCase(BaseTestCase): - minimal_config = b"""[loggers] -keys=root - -[formatters] -keys= - -[handlers] -keys= - -[logger_root] -handlers= -""" - def setUp(self): super(LogConfigTestCase, self).setUp() - names = self.create_tempfiles([('logging', self.minimal_config)]) + names = self.create_tempfiles([('logging', MIN_LOG_INI)]) self.log_config_append = names[0] def test_log_config_append_ok(self): @@ -1133,7 +1357,7 @@ handlers= 'test_log_config_append') def test_log_config_append_invalid(self): - names = self.create_tempfiles([('logging', self.minimal_config[5:])]) + names = self.create_tempfiles([('logging', MIN_LOG_INI[5:])]) self.log_config_append = names[0] self.config(log_config_append=self.log_config_append) self.assertRaises(log.LogConfigError, log.setup, diff --git a/releasenotes/notes/reload_log_config-743817192b1172b6.yaml b/releasenotes/notes/reload_log_config-743817192b1172b6.yaml new file mode 100644 index 00000000..f21f7279 --- /dev/null +++ b/releasenotes/notes/reload_log_config-743817192b1172b6.yaml @@ -0,0 +1,5 @@ +--- +features: + - The log_config_append configuration option is now mutable and the logging + settings it controls are reconfigured when the configuration file is reread. + This can be used to, for example, change logger or handler levels.