diff --git a/TODO b/TODO new file mode 100644 index 0000000..e2d7b03 --- /dev/null +++ b/TODO @@ -0,0 +1,10 @@ +* Implement a configurable policy which determines how many (and how big) + log buffers can a user with a given UID create using the log_capture_start + DBus call. +* Destroy the log handler created by log_capture_start() when the caller + disconnects from DBus. +* Use only one timer for destroying log handlers at a time. Create a new + timer as necessary when the old timer fires. +* Handle signals in tuned-adm so that the log_capture_finish() DBus call + is called even if we receive a signal. This may require some rewriting + of tuned-adm. diff --git a/com.redhat.tuned.policy b/com.redhat.tuned.policy index b34fdab..fc64297 100644 --- a/com.redhat.tuned.policy +++ b/com.redhat.tuned.policy @@ -127,6 +127,26 @@ + + Start log capture + Authentication is required to start log capture + + auth_admin + auth_admin + yes + + + + + Stop log capture and return captured log + Authentication is required to stop log capture + + auth_admin + auth_admin + yes + + + Enable automatic profile selection mode Authentication is required to change profile selection mode diff --git a/tuned-adm.py b/tuned-adm.py index 0f5e943..ea85c54 100755 --- a/tuned-adm.py +++ b/tuned-adm.py @@ -37,6 +37,15 @@ def check_positive(value): raise argparse.ArgumentTypeError("%s has to be >= 0" % value) return val +def check_log_level(value): + try: + return consts.CAPTURE_LOG_LEVELS[value.lower()] + except KeyError: + levels = ", ".join(consts.CAPTURE_LOG_LEVELS.keys()) + raise argparse.ArgumentTypeError( + "Invalid log level: %s. Valid log levels: %s." + % (value, levels)) + if __name__ == "__main__": config = GlobalConfig() parser = argparse.ArgumentParser(description="Manage tuned daemon.") @@ -44,6 +53,13 @@ if __name__ == "__main__": parser.add_argument("--debug", "-d", action="store_true", help="show debug messages") parser.add_argument("--async", "-a", action="store_true", help="with dbus do not wait on commands completion and return immediately") parser.add_argument("--timeout", "-t", default = consts.ADMIN_TIMEOUT, type = check_positive, help="with sync operation use specific timeout instead of the default %d second(s)" % consts.ADMIN_TIMEOUT) + levels = ", ".join(consts.CAPTURE_LOG_LEVELS.keys()) + help = "level of log messages to capture (one of %s). Default: %s" \ + % (levels, consts.CAPTURE_LOG_LEVEL) + parser.add_argument("--loglevel", "-l", + default = consts.CAPTURE_LOG_LEVEL, + type = check_log_level, + help = help) subparsers = parser.add_subparsers() @@ -85,20 +101,15 @@ if __name__ == "__main__": async = options.pop("async") timeout = options.pop("timeout") action_name = options.pop("action") + log_level = options.pop("loglevel") result = False dbus = config.get_bool(consts.CFG_DAEMON, consts.CFG_DEF_DAEMON) try: - admin = tuned.admin.Admin(dbus, debug, async, timeout) + admin = tuned.admin.Admin(dbus, debug, async, timeout, log_level) result = admin.action(action_name, **options) - except tuned.admin.TunedAdminException as e: - if not debug: - print(e, file=sys.stderr) - else: - traceback.print_exc() - sys.exit(2) except: traceback.print_exc() sys.exit(3) diff --git a/tuned/admin/admin.py b/tuned/admin/admin.py index 968e8e5..5dffb6c 100644 --- a/tuned/admin/admin.py +++ b/tuned/admin/admin.py @@ -11,9 +11,12 @@ import sys import errno import time import threading +import logging class Admin(object): - def __init__(self, dbus = True, debug = False, async = False, timeout = consts.ADMIN_TIMEOUT): + def __init__(self, dbus = True, debug = False, async = False, + timeout = consts.ADMIN_TIMEOUT, + log_level = logging.ERROR): self._dbus = dbus self._debug = debug self._async = async @@ -25,6 +28,10 @@ class Admin(object): self._daemon_action_result = True self._daemon_action_errstr = "" self._controller = None + self._log_token = None + self._log_level = log_level + # 25 seconds default DBus timeout + 5 seconds safety margin + self._log_capture_timeout = self._timeout + 25 + 5 if self._dbus: self._controller = tuned.admin.DBusController(consts.DBUS_BUS, consts.DBUS_INTERFACE, consts.DBUS_OBJECT, debug) try: @@ -72,6 +79,8 @@ class Admin(object): return False if self._dbus: try: + self._controller.set_on_exit_action( + self._log_capture_finish) self._controller.set_action(action_dbus, *args, **kwargs) res = self._controller.run() except TunedAdminDBusException as e: @@ -218,6 +227,18 @@ class Admin(object): return self._controller.exit(True) return False + def _log_capture_finish(self): + if self._log_token is None or self._log_token == "": + return + try: + log_msgs = self._controller.log_capture_finish( + self._log_token) + self._log_token = None + print(log_msgs, end = "", file = sys.stderr) + sys.stderr.flush() + except TunedAdminDBusException as e: + self._error("Error: Failed to stop log capture. Restart the Tuned daemon to prevent a memory leak.") + def _action_dbus_profile(self, profiles): if len(profiles) == 0: return self._action_dbus_list() @@ -225,6 +246,10 @@ class Admin(object): if profile_name == "": return self._controller.exit(False) self._daemon_action_finished.clear() + if not self._async and self._log_level is not None: + self._log_token = self._controller.log_capture_start( + self._log_level, + self._log_capture_timeout) (ret, msg) = self._controller.switch_profile(profile_name) if self._async or not ret: return self._controller.exit(self._profile_print_status(ret, msg)) @@ -266,6 +291,10 @@ class Admin(object): def _action_dbus_auto_profile(self): profile_name = self._controller.recommend_profile() self._daemon_action_finished.clear() + if not self._async and self._log_level is not None: + self._log_token = self._controller.log_capture_start( + self._log_level, + self._log_capture_timeout) (ret, msg) = self._controller.auto_profile() if self._async or not ret: return self._controller.exit(self._profile_print_status(ret, msg)) diff --git a/tuned/admin/dbus_controller.py b/tuned/admin/dbus_controller.py index 0c0efaa..8b7c484 100644 --- a/tuned/admin/dbus_controller.py +++ b/tuned/admin/dbus_controller.py @@ -17,6 +17,7 @@ class DBusController(object): self._debug = debug self._main_loop = None self._action = None + self._on_exit_action = None self._ret = True self._exit = False self._exception = None @@ -42,12 +43,20 @@ class DBusController(object): self._exit = True if self._exit: + if self._on_exit_action is not None: + self._on_exit_action(*self._on_exit_action_args, + **self._on_exit_action_kwargs) self._main_loop.quit() return False else: time.sleep(1) return True + def set_on_exit_action(self, action, *args, **kwargs): + self._on_exit_action = action + self._on_exit_action_args = args + self._on_exit_action_kwargs = kwargs + def set_action(self, action, *args, **kwargs): self._action = action self._action_args = args @@ -96,6 +105,12 @@ class DBusController(object): def profile_info(self, profile_name): return self._call("profile_info", profile_name) + def log_capture_start(self, log_level, timeout): + return self._call("log_capture_start", log_level, timeout) + + def log_capture_finish(self, token): + return self._call("log_capture_finish", token) + def active_profile(self): return self._call("active_profile") diff --git a/tuned/admin/exceptions.py b/tuned/admin/exceptions.py index 39b8d8a..dbbd667 100644 --- a/tuned/admin/exceptions.py +++ b/tuned/admin/exceptions.py @@ -1,7 +1,4 @@ import tuned.exceptions -class TunedAdminException(tuned.exceptions.TunedException): - pass - class TunedAdminDBusException(tuned.exceptions.TunedException): pass diff --git a/tuned/consts.py b/tuned/consts.py index d81b69b..bd55a45 100644 --- a/tuned/consts.py +++ b/tuned/consts.py @@ -1,3 +1,5 @@ +import logging + GLOBAL_CONFIG_FILE = "/etc/tuned/tuned-main.conf" ACTIVE_PROFILE_FILE = "/etc/tuned/active_profile" PROFILE_MODE_FILE = "/etc/tuned/profile_mode" @@ -110,3 +112,15 @@ ADMIN_TIMEOUT = 600 # was set automatically or manually ACTIVE_PROFILE_AUTO = "auto" ACTIVE_PROFILE_MANUAL = "manual" + +LOG_LEVEL_CONSOLE = 60 +LOG_LEVEL_CONSOLE_NAME = "CONSOLE" +CAPTURE_LOG_LEVEL = "error" +CAPTURE_LOG_LEVELS = { + "debug": logging.DEBUG, + "info": logging.INFO, + "warn": logging.WARN, + "error": logging.ERROR, + "console": LOG_LEVEL_CONSOLE, + "none": None, + } diff --git a/tuned/daemon/controller.py b/tuned/daemon/controller.py index 9cde2d6..ac711c9 100644 --- a/tuned/daemon/controller.py +++ b/tuned/daemon/controller.py @@ -10,6 +10,30 @@ __all__ = ["Controller"] log = tuned.logs.get() +class TimerStore(object): + def __init__(self): + self._timers = dict() + self._timers_lock = threading.Lock() + + def store_timer(self, token, timer): + with self._timers_lock: + self._timers[token] = timer + + def drop_timer(self, token): + with self._timers_lock: + try: + timer = self._timers[token] + timer.cancel() + del self._timers[token] + except: + pass + + def cancel_all(self): + with self._timers_lock: + for timer in self._timers.values(): + timer.cancel() + self._timers.clear() + class Controller(tuned.exports.interfaces.ExportableInterface): """ Controller's purpose is to keep the program running, start/stop the tuning, @@ -22,6 +46,7 @@ class Controller(tuned.exports.interfaces.ExportableInterface): self._global_config = global_config self._terminate = threading.Event() self._cmd = commands() + self._timer_store = TimerStore() def run(self): """ @@ -54,6 +79,32 @@ class Controller(tuned.exports.interfaces.ExportableInterface): # identifying caller (with DBus it's the caller bus name) if authorized and empty # string if not authorized, caller must be the last argument + def _log_capture_abort(self, token): + tuned.logs.log_capture_finish(token) + self._timer_store.drop_timer(token) + + @exports.export("ii", "s") + def log_capture_start(self, log_level, timeout, caller = None): + if caller == "": + return "" + token = tuned.logs.log_capture_start(log_level) + if token is None: + return "" + if timeout > 0: + timer = threading.Timer(timeout, + self._log_capture_abort, args = [token]) + self._timer_store.store_timer(token, timer) + timer.start() + return "" if token is None else token + + @exports.export("s", "s") + def log_capture_finish(self, token, caller = None): + if caller == "": + return "" + res = tuned.logs.log_capture_finish(token) + self._timer_store.drop_timer(token) + return "" if res is None else res + @exports.export("", "b") def start(self, caller = None): if caller == "": @@ -70,9 +121,11 @@ class Controller(tuned.exports.interfaces.ExportableInterface): if caller == "": return False if not self._daemon.is_running(): - return True + res = True else: - return self._daemon.stop() + res = self._daemon.stop() + self._timer_store.cancel_all() + return res @exports.export("", "b") def reload(self, caller = None): diff --git a/tuned/logs.py b/tuned/logs.py index e3da574..264b677 100644 --- a/tuned/logs.py +++ b/tuned/logs.py @@ -5,11 +5,67 @@ import os import os.path import inspect import tuned.consts as consts +import random +import string +import threading +try: + from StringIO import StringIO +except: + from io import StringIO __all__ = ["get"] root_logger = None +log_handlers = {} +log_handlers_lock = threading.Lock() + +class LogHandler(object): + def __init__(self, handler, stream): + self.handler = handler + self.stream = stream + +def _random_string(length): + r = random.SystemRandom() + chars = string.ascii_letters + string.digits + res = "" + for i in range(length): + res += random.choice(chars) + return res + +def log_capture_start(log_level): + with log_handlers_lock: + for i in range(10): + token = _random_string(16) + if token not in log_handlers: + break + else: + return None + stream = StringIO() + handler = logging.StreamHandler(stream) + handler.setLevel(log_level) + formatter = logging.Formatter( + "%(levelname)-8s %(name)s: %(message)s") + handler.setFormatter(formatter) + root_logger.addHandler(handler) + log_handler = LogHandler(handler, stream) + log_handlers[token] = log_handler + root_logger.debug("Added log handler %s." % token) + return token + +def log_capture_finish(token): + with log_handlers_lock: + try: + log_handler = log_handlers[token] + except KeyError: + return None + content = log_handler.stream.getvalue() + log_handler.stream.close() + root_logger.removeHandler(log_handler.handler) + del log_handlers[token] + root_logger.debug("Removed log handler %s." % token) + return content + def get(): global root_logger if root_logger is None: @@ -40,6 +96,9 @@ class TunedLogger(logging.getLoggerClass()): self.setLevel(logging.INFO) self.switch_to_console() + def console(self, msg, *args, **kwargs): + self.log(consts.LOG_LEVEL_CONSOLE, msg, *args, **kwargs) + def switch_to_console(self): self._setup_console_handler() self.remove_all_handlers() @@ -78,5 +137,6 @@ class TunedLogger(logging.getLoggerClass()): filename, maxBytes = consts.LOG_FILE_MAXBYTES, backupCount = consts.LOG_FILE_COUNT) cls._file_handler.setFormatter(cls._formatter) +logging.addLevelName(consts.LOG_LEVEL_CONSOLE, consts.LOG_LEVEL_CONSOLE_NAME) logging.setLoggerClass(TunedLogger) atexit.register(logging.shutdown) diff --git a/tuned/plugins/plugin_systemd.py b/tuned/plugins/plugin_systemd.py index 472a800..f6857c5 100644 --- a/tuned/plugins/plugin_systemd.py +++ b/tuned/plugins/plugin_systemd.py @@ -99,7 +99,7 @@ class SystemdPlugin(base.Plugin): if full_rollback: log.info("removing '%s' systemd tuning previously added by Tuned" % consts.SYSTEMD_CPUAFFINITY_VAR) self._remove_systemd_tuning() - log.info("you may need to manualy run 'dracut -f' to update the systemd configuration in initrd image") + log.console("you may need to manualy run 'dracut -f' to update the systemd configuration in initrd image") # convert cpulist from systemd syntax to Tuned syntax and unpack it def _cpulist_convert_unpack(self, cpulist):