lvmdbusd: Re-work flight recorder data

Introduce a new lock for the flight recorder, so that we can dump it when
a command is block waiting for lvm to complete.  Also in all paths we will
addthe metadata to the flight recorder before it's done, so we will have
it when a command hangs and we dump the flight recorder. Add the missing
bits after the command has finished.

Cleaned up the output too.

diff --git a/daemons/lvmdbusd/background.py b/daemons/lvmdbusd/background.py
index 32b2cdc38b3597a0048182f805455a7835451889..463bb20d5ef20c3db7d718ef3335939df473df77 100644 (file)
--- a/daemons/lvmdbusd/background.py
+++ b/daemons/lvmdbusd/background.py
@@ -67,16 +67,13 @@ def _move_merge(interface_name, command, job_state):
        # the command always as we will be getting periodic output from them on
        # the status of the long running operation.
 
-       meta = LvmExecutionMeta(time.time(), 0, command, -1000, None, None)
+       meta = LvmExecutionMeta(time.time(), 0, command)
        cfg.blackbox.add(meta)
 
        ec, stdout, stderr = call_lvm(command, line_cb=_move_callback,
                                                                        cb_data=job_state)
-
-       with meta.lock:
-               meta.ended = time.time()
-               meta.ec = ec
-               meta.stderr_txt = stderr
+       ended = time.time()
+       meta.completed(ended, ec, stdout, stderr)
 
        if ec == 0:
                job_state.Percent = 100

diff --git a/daemons/lvmdbusd/cmdhandler.py b/daemons/lvmdbusd/cmdhandler.py
index 8fbcd2e3a93545328e7c4718c2c3011ef2baebc9..0c4d5cb61ab2a5569be236d3298664e932aeddf0 100644 (file)
--- a/daemons/lvmdbusd/cmdhandler.py
+++ b/daemons/lvmdbusd/cmdhandler.py
@@ -38,7 +38,7 @@ cmd_lock = threading.RLock()
 
 class LvmExecutionMeta(object):
 
-       def __init__(self, start, ended, cmd, ec, stdout_txt, stderr_txt):
+       def __init__(self, start, ended, cmd, ec=-1000, stdout_txt=None, stderr_txt=None):
                self.lock = threading.RLock()
                self.start = start
                self.ended = ended
@@ -49,26 +49,42 @@ class LvmExecutionMeta(object):
 
        def __str__(self):
                with self.lock:
-                       return "EC= %d for %s\n" \
-                               "STARTED: %f, ENDED: %f\n" \
+                       if self.ended == 0:
+                               ended_txt = "still running"
+                               self.ended = time.time()
+                       else:
+                               ended_txt = str(time.ctime(self.ended))
+
+                       return 'EC= %d for "%s"\n' \
+                               "STARTED: %s, ENDED: %s, DURATION: %f\n" \
                                "STDOUT=%s\n" \
                                "STDERR=%s\n" % \
-                               (self.ec, str(self.cmd), self.start, self.ended, self.stdout_txt,
-                               self.stderr_txt)
+                               (self.ec, " ".join(self.cmd), time.ctime(self.start), ended_txt, float(self.ended) - self.start,
+                                       self.stdout_txt,
+                                       self.stderr_txt)
+
+       def completed(self, end_time, ec, stdout_txt, stderr_txt):
+               with self.lock:
+                       self.ended = end_time
+                       self.ec = ec
+                       self.stdout_txt = stdout_txt
+                       self.stderr_txt = stderr_txt
 
 
 class LvmFlightRecorder(object):
 
        def __init__(self, size=16):
                self.queue = collections.deque(maxlen=size)
+               self.lock = threading.RLock()
 
        def add(self, lvm_exec_meta):
-               self.queue.append(lvm_exec_meta)
+               with self.lock:
+                       self.queue.append(lvm_exec_meta)
 
        def dump(self):
-               with cmd_lock:
+               with self.lock:
                        if len(self.queue):
-                               log_error("LVM dbus flight recorder START")
+                               log_error("LVM dbus flight recorder START (in order of newest to oldest)")
                                for c in reversed(self.queue):
                                        log_error(str(c))
                                log_error("LVM dbus flight recorder END")
@@ -200,11 +216,15 @@ def time_wrapper(command, debug=False):
 
        with cmd_lock:
                start = time.time()
+               meta = LvmExecutionMeta(start, 0, command)
+               # Add the partial metadata to black box, so if the command hangs
+               # we will see what it was in the block box dump.
+               cfg.blackbox.add(meta)
                results = _t_call(command, debug)
                ended = time.time()
                total_time += (ended - start)
                total_count += 1
-               cfg.blackbox.add(LvmExecutionMeta(start, ended, command, *results))
+               meta.completed(ended, *results)
        return results