From 6473d2082b1519003ed9475c448b0c4232c5f3d4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Thu, 7 Jun 2018 19:51:47 +0200 Subject: [PATCH 1/6] Drop TunedAdminException, it's not raised anywhere MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Ondřej Lysoněk --- tuned-adm.py | 6 ------ tuned/admin/exceptions.py | 3 --- 2 files changed, 9 deletions(-) diff --git a/tuned-adm.py b/tuned-adm.py index 0f5e943..847c183 100755 --- a/tuned-adm.py +++ b/tuned-adm.py @@ -93,12 +93,6 @@ if __name__ == "__main__": admin = tuned.admin.Admin(dbus, debug, async, timeout) 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/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 From bd91f06d170b4d822b0254a6e9dd4e13713bc49a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Fri, 8 Jun 2018 12:18:46 +0200 Subject: [PATCH 2/6] log: Introduce log level CONSOLE MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This level has the highest severity. It is meant for important messages about situations which may require user intervention. These messages will be shown to the user on the console when running tuned-adm (this is implemented in a followup commit). Signed-off-by: Ondřej Lysoněk --- tuned/consts.py | 3 +++ tuned/logs.py | 4 ++++ 2 files changed, 7 insertions(+) diff --git a/tuned/consts.py b/tuned/consts.py index d81b69b..00a841c 100644 --- a/tuned/consts.py +++ b/tuned/consts.py @@ -110,3 +110,6 @@ 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" diff --git a/tuned/logs.py b/tuned/logs.py index e3da574..d881b54 100644 --- a/tuned/logs.py +++ b/tuned/logs.py @@ -40,6 +40,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 +81,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) From 1be86c857aab2b6d1c2c4140570b637585fe6950 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Fri, 8 Jun 2018 12:21:48 +0200 Subject: [PATCH 3/6] systemd: Change log level of message about running dracut MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Change the log level of the message about running dracut to CONSOLE. It is an important message which should always be logged. It informs the user that they may be required to do something. Signed-off-by: Ondřej Lysoněk --- tuned/plugins/plugin_systemd.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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): From 829c7de36c3e653377d1a1291f653417ae2993f9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Sun, 10 Jun 2018 13:10:15 +0200 Subject: [PATCH 4/6] Support sending logs over DBus MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add two DBus calls: log_capture_start(log_level, timeout) * This will instruct Tuned to create a new log handler, which will start writing log messages with level 'log_level' and higher to a buffer. The log levels are standard Python log levels (e.g. logging.INFO) or Tuned's custom log level LOG_LEVEL_CONSOLE which is defined as 60. The handler will be destroyed after 'timeout' seconds if contents of the buffer are not collected using log_capture_finish() before the timeout. If 'timeout' <= 0, log messages will be collected for as long as it takes before log_capture_finish() is called (use with care, so that you don't fill up memory with Tuned logs). This call returns a string ID of the log handler, a token, which should be passed to log_capture_finish(). log_capture_finish(token) * This will return (as a string) log messages collected by a log handler associated with the 'token'. It will also destroy the log handler. These calls are privileged. They can only be called by the root user or by a user logged in on a local console (just like the change-profile DBus calls). This restriction is meant to prevent ordinary users from forcing Tuned to allocate an insane amount of memory for the log buffers and crash it (or other processes). In the future we may wish to replace this restriction with a configurable policy which determines how many (and how big) log buffers can a user with a given UID create. We may also want to destroy the log handler when the original caller disconnects from DBus. Signed-off-by: Ondřej Lysoněk --- TODO | 7 +++++ com.redhat.tuned.policy | 20 +++++++++++++ tuned/daemon/controller.py | 57 ++++++++++++++++++++++++++++++++++++-- tuned/logs.py | 56 +++++++++++++++++++++++++++++++++++++ 4 files changed, 138 insertions(+), 2 deletions(-) create mode 100644 TODO diff --git a/TODO b/TODO new file mode 100644 index 0000000..9d24865 --- /dev/null +++ b/TODO @@ -0,0 +1,7 @@ +* 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. 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/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 d881b54..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: From 6c1df704ce65de429b90bd99102188be39a463d0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Sun, 10 Jun 2018 13:12:02 +0200 Subject: [PATCH 5/6] tuned-adm: Print log excerpt when changing profile MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Print messages logged during a profile switch to stderr (this affects the "profile" and "auto_profile" commands). By default messages with log level ERROR and higher are printed. This can be changed using the --loglevel command line option. Valid values are debug, info, warn, error, console, none ('none' can be used to disable the log printing). E.g.: tuned-adm --loglevel info profile powersave Log printing cannot be used when --async is used. Resolves: rhbz#1538745 Signed-off-by: Ondřej Lysoněk --- TODO | 3 +++ tuned-adm.py | 19 ++++++++++++++++++- tuned/admin/admin.py | 30 +++++++++++++++++++++++++++++- tuned/admin/dbus_controller.py | 15 +++++++++++++++ tuned/consts.py | 11 +++++++++++ 5 files changed, 76 insertions(+), 2 deletions(-) diff --git a/TODO b/TODO index 9d24865..e2d7b03 100644 --- a/TODO +++ b/TODO @@ -5,3 +5,6 @@ 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/tuned-adm.py b/tuned-adm.py index 847c183..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,12 +101,13 @@ 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: diff --git a/tuned/admin/admin.py b/tuned/admin/admin.py index 968e8e5..8cc704b 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,17 @@ 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 + self._error(log_msgs) + 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 +245,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 +290,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/consts.py b/tuned/consts.py index 00a841c..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" @@ -113,3 +115,12 @@ 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, + } From 0a37ff6373516cd85ec6ca0fc6079d6e139f5732 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Lyson=C4=9Bk?= Date: Mon, 11 Jun 2018 14:40:42 +0200 Subject: [PATCH 6/6] tuned-adm: Don't print superfluous newline after log messages MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Ondřej Lysoněk --- tuned/admin/admin.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tuned/admin/admin.py b/tuned/admin/admin.py index 8cc704b..5dffb6c 100644 --- a/tuned/admin/admin.py +++ b/tuned/admin/admin.py @@ -234,7 +234,8 @@ class Admin(object): log_msgs = self._controller.log_capture_finish( self._log_token) self._log_token = None - self._error(log_msgs) + 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.")