Add a basic "high level" log for BlivetUtils

Basically log all "user action" calls from the GUI -- e.g. adding
a new device, deleting device etc.

blivet-gui_event.conf

@@ -2,3 +2,4 @@ EVENT=notify component=blivet-gui
     # Copy log files of crashed process
     cp /var/log/blivet-gui/blivet.log blivet.log
     cp /var/log/blivet-gui/program.log program.log
+    cp /var/log/blivet-gui/blivet-gui-utils.log blivet-gui-utils.log

blivetgui/blivet_utils.py

@@ -35,9 +35,11 @@
 import re
 import traceback
 import parted
+import subprocess
 
-from .logs import set_logging
+from .logs import set_logging, log_utils_call
 from .i18n import _
+from . import __version__
 
 # ---------------------------------------------------------------------------- #
 
@@ -48,6 +50,11 @@
 # ---------------------------------------------------------------------------- #
 
 
+def lsblk():
+    p = subprocess.run(["lsblk", "-f", "-a"], stdout=subprocess.PIPE)
+    return p.stdout.decode()
+
+
 class RawFormatDevice(object):
     """ Special class to represent formatted disk without a disklabel
     """
@@ -162,6 +169,12 @@ def __init__(self, ignored_disks=None):
 
         self.ignored_disks = ignored_disks
 
+        # create our log now, creating blivet.Blivet instance may fail
+        # and log some basic information -- version and lsblk output
+        _log_file, self.log = set_logging(component="blivet-gui-utils")
+        self.log.info("BlivetUtils, version: %s", __version__)
+        self.log.info("lsblk output:\n%s", lsblk())
+
         self.storage = blivet.Blivet()
 
         # logging
@@ -517,6 +530,10 @@ def delete_device(self, blivet_device, delete_parents):
 
         """
 
+        log_msg = "Deleting device '%s':\n" % blivet_device.name
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input={"device": blivet_device, "delete_parents": delete_parents})
+
         actions = []
 
         if isinstance(blivet_device, RawFormatDevice):
@@ -656,6 +673,10 @@ def device_resizable(self, blivet_device):
                                       max_size=blivet_device.size)
 
     def format_device(self, user_input):
+        log_msg = "Formatting device '%s'\n" % user_input.edit_device.name
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input=user_input)
+
         fmt_actions = []
 
         if user_input.edit_device.format.type is not None:
@@ -676,6 +697,10 @@ def format_device(self, user_input):
     def resize_device(self, user_input):
         device = user_input.edit_device
 
+        log_msg = "Resizing device '%s'\n" % device.name
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input=user_input)
+
         if not user_input.resize or user_input.size == device.size:
             return ProxyDataContainer(success=True, actions=None, message=None, exception=None, traceback=None)
 
@@ -1139,6 +1164,10 @@ def add_device(self, user_input):
 
         """
 
+        log_msg = "Adding a new '%s' device:\n" % user_input.device_type
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input=user_input)
+
         add_function = self.add_dict[user_input.device_type]
 
         try:
@@ -1243,6 +1272,10 @@ def create_disk_label(self, blivet_device, label_type):
 
         """
 
+        log_msg = "Creating a new disklabel on '%s':\n" % blivet_device.name
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input={"device": blivet_device, "label_type": label_type})
+
         actions = []
 
         if blivet_device.format.type:
@@ -1267,6 +1300,10 @@ def luks_decrypt(self, blivet_device, passphrase):
 
         """
 
+        log_msg = "Opening LUKS device '%s':\n" % blivet_device
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input={"device": blivet_device})
+
         blivet_device.format.passphrase = passphrase
 
         try:
@@ -1286,6 +1323,10 @@ def blivet_cancel_actions(self, actions):
         """ Cancel scheduled actions
         """
 
+        log_msg = "Cancelling scheduled actions:\n"
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input={"actions": actions})
+
         actions.reverse()
         for action in actions:
             self.storage.devicetree.actions.remove(action)
@@ -1294,6 +1335,10 @@ def blivet_reset(self):
         """ Blivet.reset()
         """
 
+        log_msg = "Running reset\n"
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input=None)
+
         if self.ignored_disks is not None:
             self.storage.config.ignored_disks = self.ignored_disks
 
@@ -1303,6 +1348,10 @@ def blivet_do_it(self, progress_report_hook):
         """ Blivet.do_it()
         """
 
+        log_msg = "Running do_it\n"
+        log_utils_call(log=self.log, message=log_msg,
+                       user_input=None)
+
         progress_clbk = lambda clbk_data: progress_report_hook(clbk_data.msg)
 
         callbacks_reg = blivet.callbacks.create_new_callbacks_register(report_progress=progress_clbk)

blivetgui/config.py

@@ -29,6 +29,7 @@ def __init__(self, *args, **kwargs):
         super().__init__(self, *args, **kwargs)
 
         self["default_fstype"] = "ext4"
+        self["log_dir"] = "/var/log/blivet-gui"
 
     def __getattr__(self, name):
         if name not in self.keys() and not hasattr(self, name):

blivetgui/logs.py

@@ -26,11 +26,12 @@
 import logging
 from logging.handlers import RotatingFileHandler
 
-from . import __app_name__
+from blivet.devices.storage import StorageDevice
 
-# ---------------------------------------------------------------------------- #
+from .communication.proxy_utils import ProxyDataContainer
+from .config import config
 
-LOG_DIR = "/var/log/%s" % __app_name__
+# ---------------------------------------------------------------------------- #
 
 
 def set_logging(component, logging_level=logging.DEBUG):
@@ -43,11 +44,11 @@ def set_logging(component, logging_level=logging.DEBUG):
 
     """
 
-    if not os.path.isdir(LOG_DIR) or not os.access(LOG_DIR, os.W_OK):
+    if not os.path.isdir(config.log_dir) or not os.access(config.log_dir, os.W_OK):
         log_handler = logging.NullHandler()
         log_file = ""
     else:
-        log_file = "/var/log/blivet-gui/%s.log" % component
+        log_file = os.path.join(config.log_dir, "%s.log" % component)
 
         rotate = os.path.isfile(log_file)
 
@@ -64,3 +65,58 @@ def set_logging(component, logging_level=logging.DEBUG):
     logger.setLevel(logging_level)
 
     return log_file, logger
+
+
+def _unpack_input(user_input, level, devices, message):
+    # value is a list --> just unpack all its items
+    if isinstance(user_input, (list, tuple)):
+        for i in user_input:
+            message, devices = _unpack_input(i, level, devices, message)
+
+    # value is a dict or our "container" --> unpack to print key-value pairs
+    elif isinstance(user_input, (dict, ProxyDataContainer)):
+        message += "\n"
+        for item in user_input:
+            message += "\t" * level
+            message += "%s:" % item
+
+            # we don't want to save passphrase to the log
+            if item == "passphrase" and user_input[item]:
+                value = "*****"
+            else:
+                value = user_input[item]
+
+            message, devices = _unpack_input(value, level + 1, devices, message)
+
+    else:
+        # and finally append value to the message
+        message += " %s\n" % user_input
+
+        # if value is actually a blivet device, save it for future use
+        if isinstance(user_input, StorageDevice):
+            devices.append(user_input)
+
+    return (message, devices)
+
+
+def log_utils_call(log, message, user_input):
+    devices = []
+    message += "=" * 80
+    message += "\n"
+
+    try:
+        if user_input is not None:
+            message += "**User input:**\n"
+            message, devices = _unpack_input(user_input, 1, devices, message)
+            message += "\n"
+
+        if devices:
+            message += "**Involved devices:**\n\n"
+            for device in devices:
+                message += repr(device)
+                message += "\n"
+    except Exception as e:  # pylint: disable=broad-except
+        # really don't want to crash because of a logging issue
+        log.debug("Logging failed: %s", str(e))
+    else:
+        log.debug(message)

blivetgui/osinstall.py

@@ -41,6 +41,7 @@
 from .dialogs import message_dialogs
 from .i18n import _
 from .gui_utils import locate_ui_file, locate_css_file
+from .logs import set_logging
 
 from contextlib import contextmanager
 
@@ -51,6 +52,7 @@ def __init__(self):
         # pylint: disable=super-init-not-called
 
         self._storage = None
+        _log_file, self.log = set_logging(component="blivet-gui-utils")
 
     @property
     def storage(self):