From: Tony Asleson <tasleson@redhat.com>
Date: Mon, 21 Mar 2016 22:22:56 +0000 (-0500)
Subject: lvmdbusd: Add lvm flight recorder
X-Git-Tag: v2_02_148~22
X-Git-Url: https://sourceware.org/git/?a=commitdiff_plain;h=ca28ea88bedbc0ecb64e5579c1b3076b9a7cd533;p=lvm2.git

lvmdbusd: Add lvm flight recorder

To help out with debug, when an exception is thrown in the dbus service we
will dump all the information we have on the last 16 commands that were
executed along with the stack strace.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---

diff --git a/daemons/lvmdbusd/cfg.py b/daemons/lvmdbusd/cfg.py
index bde6a641a..8aec8aeed 100644
--- a/daemons/lvmdbusd/cfg.py
+++ b/daemons/lvmdbusd/cfg.py
@@ -78,3 +78,6 @@ load = None
 
 # Global cached state
 db = None
+
+# lvm flight recorder
+blackbox = None
diff --git a/daemons/lvmdbusd/cmdhandler.py b/daemons/lvmdbusd/cmdhandler.py
index 370fb618c..1522ebf2d 100644
--- a/daemons/lvmdbusd/cmdhandler.py
+++ b/daemons/lvmdbusd/cmdhandler.py
@@ -11,6 +11,7 @@ from subprocess import Popen, PIPE
 import time
 import threading
 from itertools import chain
+import collections
 
 try:
 	from . import cfg
@@ -28,13 +29,51 @@ total_count = 0
 
 # We need to prevent different threads from using the same lvm shell
 # at the same time.
-cmd_lock = threading.Lock()
+cmd_lock = threading.RLock()
 
 # The actual method which gets called to invoke the lvm command, can vary
 # from forking a new process to using lvm shell
 _t_call = None
 
 
+class LvmExecutionMeta(object):
+
+	def __init__(self, start, ended, cmd, ec, stdout_txt, stderr_txt):
+		self.start = start
+		self.ended = ended
+		self.cmd = cmd
+		self.ec = ec
+		self.stdout_txt = stdout_txt
+		self.stderr_txt = stderr_txt
+
+	def __str__(self):
+		return "EC= %d for %s\n" \
+			"STARTED: %f, ENDED: %f\n" \
+			"STDOUT=%s\n" \
+			"STDERR=%s\n" % \
+			(self.ec, str(self.cmd), self.start, self.ended, self.stdout_txt,
+			self.stderr_txt)
+
+
+class LvmFlightRecorder(object):
+
+	def __init__(self):
+		self.queue = collections.deque(maxlen=16)
+
+	def add(self, lvm_exec_meta):
+		self.queue.append(lvm_exec_meta)
+
+	def dump(self):
+		with cmd_lock:
+			log_error("LVM dbus flight recorder START")
+			for c in self.queue:
+				log_error(str(c))
+			log_error("LVM dbus flight recorder END")
+
+
+cfg.blackbox = LvmFlightRecorder()
+
+
 def _debug_c(cmd, exit_code, out):
 	log_error('CMD= %s' % ' '.join(cmd))
 	log_error(("EC= %d" % exit_code))
@@ -105,9 +144,10 @@ def time_wrapper(command, debug=False):
 	with cmd_lock:
 		start = time.time()
 		results = _t_call(command, debug)
-		total_time += (time.time() - start)
+		ended = time.time()
+		total_time += (ended - start)
 		total_count += 1
-
+		cfg.blackbox.add(LvmExecutionMeta(start, ended, command, *results))
 	return results
 
 
diff --git a/daemons/lvmdbusd/request.py b/daemons/lvmdbusd/request.py
index cf258f182..02f8c889e 100644
--- a/daemons/lvmdbusd/request.py
+++ b/daemons/lvmdbusd/request.py
@@ -69,6 +69,7 @@ class RequestEntry(object):
 			# have gotten a job by the time we hit an error
 			# Lets get the stacktrace and set that to the error message
 			st = traceback.format_exc()
+			cfg.blackbox.dump()
 			log_error("Exception returned to client: \n%s" % st)
 			self.register_error(-1, str(e), e)