Merge pull request #104 from olysonek/log_to_tuned_adm

Print log excerpt in tuned-adm when changing the profile

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.

com.redhat.tuned.policy

@@ -127,6 +127,26 @@
     </defaults>
   </action>
 
+  <action id="com.redhat.tuned.log_capture_start">
+    <description>Start log capture</description>
+    <message>Authentication is required to start log capture</message>
+    <defaults>
+      <allow_any>auth_admin</allow_any>
+      <allow_inactive>auth_admin</allow_inactive>
+      <allow_active>yes</allow_active>
+    </defaults>
+  </action>
+
+  <action id="com.redhat.tuned.log_capture_finish">
+    <description>Stop log capture and return captured log</description>
+    <message>Authentication is required to stop log capture</message>
+    <defaults>
+      <allow_any>auth_admin</allow_any>
+      <allow_inactive>auth_admin</allow_inactive>
+      <allow_active>yes</allow_active>
+    </defaults>
+  </action>
+
   <action id="com.redhat.tuned.auto_profile">
     <description>Enable automatic profile selection mode</description>
     <message>Authentication is required to change profile selection mode</message>

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)

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))

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")
 

tuned/admin/exceptions.py

@@ -1,7 +1,4 @@
 import tuned.exceptions
 
-class TunedAdminException(tuned.exceptions.TunedException):
-	pass
-
 class TunedAdminDBusException(tuned.exceptions.TunedException):
 	pass

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,
+		}

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):

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)

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):