From 82a73b049276d38800be14a506e13d3e8293a884 Mon Sep 17 00:00:00 2001
From: David Lehman <dlehman@redhat.com>
Date: Thu, 14 May 2015 16:53:14 -0500
Subject: [PATCH 51/51] Use logging module for console debug.

Eventually this should probably become a "uevent" facility and the
console logger would be configurable with facility and level.
---
 blivet/actionlist.py        |  5 ++---
 blivet/devices/lvm.py       |  4 ++++
 blivet/devices/partition.py | 10 ++++++++++
 blivet/devices/storage.py   | 13 +++++++++++++
 blivet/event.py             |  6 ++----
 blivet/formats/__init__.py  |  8 +++++++-
 blivet/formats/fs.py        | 10 ++++++++++
 blivet/handler.py           | 46 ++++++++++++++++++++++-----------------------
 blivet/util.py              | 15 ++++++++++++++-
 9 files changed, 84 insertions(+), 33 deletions(-)

diff --git a/blivet/actionlist.py b/blivet/actionlist.py
index 53b4467..cae2b5f 100644
--- a/blivet/actionlist.py
+++ b/blivet/actionlist.py
@@ -35,6 +35,7 @@ from .threads import blivet_lock, SynchronizedMeta
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 @add_metaclass(SynchronizedMeta)
 class ActionList(object):
@@ -301,9 +302,7 @@ class ActionList(object):
         self._preProcess(devices=devices)
 
         for action in self._actions[:]:
-            if flags.console_debug:
-                print "executing: %s" % action
-            log.info("executing action: %s", action)
+            console_log.info("executing action: %s", action)
             if dryRun:
                 continue
 
diff --git a/blivet/devices/lvm.py b/blivet/devices/lvm.py
index 7a94078..8ec195a 100644
--- a/blivet/devices/lvm.py
+++ b/blivet/devices/lvm.py
@@ -40,6 +40,7 @@ from ..threads import SynchronizedABCMeta
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 from .device import Device
 from .storage import StorageDevice
@@ -706,10 +707,13 @@ class LVMLogicalVolumeDevice(DMDevice):
         except Exception:
             raise
         else:
+            console_log.debug("LVMLogicalVolumeDevice.resize set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("LVMLogicalVolumeDevice.resize wait %s", self.name)
             event_sync.wait()
         finally:
             event_sync.reset()
+            console_log.debug("LVMLogicalVolumeDevice.resize notify %s", self.name)
             event_sync.notify()
 
     @property
diff --git a/blivet/devices/partition.py b/blivet/devices/partition.py
index f255a0b..6bd33a3 100644
--- a/blivet/devices/partition.py
+++ b/blivet/devices/partition.py
@@ -35,6 +35,7 @@ from ..size import Size, MiB
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 from .device import Device
 from .storage import StorageDevice
@@ -561,10 +562,13 @@ class PartitionDevice(StorageDevice):
             log.error(str(e))
             err = True
         finally:
+            console_log.debug("PartitionDevice.wipe1 set ready %s", self.name)
             event_sync.set_ready()
             timeout = 2 if err else None
+            console_log.debug("PartitionDevice.wipe1 wait %s", self.name)
             event_sync.wait(timeout=timeout)
             event_sync.reset()
+            console_log.debug("PartitionDevice.wipe1 notify %s", self.name)
             event_sync.notify()
             # If a udev device is created with the watch option, then
             # a change uevent is synthesized and we need to wait for
@@ -608,9 +612,12 @@ class PartitionDevice(StorageDevice):
             try:
                 self.format.wipe()
             finally:
+                console_log.debug("PartitionDevice.wipe2 set ready %s", self.name)
                 self.format.eventSync.set_ready()
+                console_log.debug("PartitionDevice.wipe2 wait %s", self.name)
                 self.format.eventSync.wait()
                 self.format.eventSync.reset()
+                console_log.debug("PartitionDevice.wipe2 notify %s", self.name)
                 self.format.eventSync.notify()
 
     def _computeResize(self, partition, newsize=None):
@@ -673,10 +680,13 @@ class PartitionDevice(StorageDevice):
         except Exception:
             raise
         else:
+            console_log.debug("PartitionDevice.resize set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("PartitionDevice.resize wait %s", self.name)
             event_sync.wait()
         finally:
             event_sync.reset()
+            console_log.debug("PartitionDevice.resize notify %s", self.name)
             event_sync.notify()
 
         self.updateSize()
diff --git a/blivet/devices/storage.py b/blivet/devices/storage.py
index 87d9df5..114dc68 100644
--- a/blivet/devices/storage.py
+++ b/blivet/devices/storage.py
@@ -35,6 +35,7 @@ from ..synchronizer import StorageEventSynchronizer
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 from .device import Device
 from .network import NetworkStorageDevice
@@ -382,10 +383,13 @@ class StorageDevice(Device):
         """ Perform post-setup operations. """
         event_sync = self.controlSync
         if self.__class__._setup != StorageDevice._setup:
+            console_log.debug("StorageDevice.setup set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("StorageDevice.setup wait %s", self.name)
             event_sync.wait()
 
         event_sync.reset()
+        console_log.debug("StorageDevice.setup notify %s", self.name)
         event_sync.notify()
         if not flags.uevents:
             udev.settle()
@@ -447,10 +451,13 @@ class StorageDevice(Device):
         """ Perform post-teardown operations. """
         event_sync = self.controlSync
         if self.__class__._teardown != StorageDevice._teardown:
+            console_log.debug("StorageDevice.teardown set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("StorageDevice.teardown wait %s", self.name)
             event_sync.wait(timeout=self._postTeardownWaitTimeout)
 
         event_sync.reset()
+        console_log.debug("StorageDevice.teardown notify %s", self.name)
         event_sync.notify()
         self.sysfsPath = ""
 
@@ -493,11 +500,14 @@ class StorageDevice(Device):
         #     they are created
         event_sync = self.modifySync
         if self.__class__._create != StorageDevice._create:
+            console_log.debug("StorageDevice.create set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("StorageDevice.create wait %s", self.name)
             event_sync.wait() # wait for notification the event was received
 
         event_sync.reset()
         self.exists = True
+        console_log.debug("StorageDevice.create notify %s", self.name)
         event_sync.notify() # notify event handler we're done post-processing
 
         if not flags.uevents:
@@ -547,11 +557,14 @@ class StorageDevice(Device):
         """ Perform post-destruction operations. """
         event_sync = self.modifySync
         if self.__class__._destroy != StorageDevice._destroy:
+            console_log.debug("StorageDevice.destroy set ready %s", self.name)
             event_sync.set_ready()
+            console_log.debug("StorageDevice.destroy wait %s", self.name)
             event_sync.wait() # wait for notification that event was received
 
         event_sync.reset()
         self.exists = False
+        console_log.debug("StorageDevice.destroy notify %s", self.name)
         event_sync.notify() # notify the handler we're done post-processing
         self.sysfsPath = ""
 
diff --git a/blivet/event.py b/blivet/event.py
index 259c3fa..fa8dcea 100644
--- a/blivet/event.py
+++ b/blivet/event.py
@@ -35,7 +35,7 @@ from .flags import flags
 from .threads import SynchronizedABCMeta
 
 import logging
-log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 ##
 ## Event
@@ -286,9 +286,7 @@ class UdevEventManager(EventManager):
 
     def enqueue_event(self, *args, **kwargs):
         event = UdevEvent(args[0], args[1])
-        if flags.console_debug:
-            print "-> %s" % event
-        log.debug("-> %s", event)
+        console_log.debug("-> %s", event)
         self._queue.enqueue(event)
 
     def handle_event(self, *args, **kwargs):
diff --git a/blivet/formats/__init__.py b/blivet/formats/__init__.py
index eebc963..e823416 100644
--- a/blivet/formats/__init__.py
+++ b/blivet/formats/__init__.py
@@ -40,7 +40,7 @@ from ..threads import SynchronizedMeta
 
 import logging
 log = logging.getLogger("blivet")
-
+console_log = logging.getLogger("console")
 
 device_formats = {}
 def register_device_format(fmt_class):
@@ -408,9 +408,12 @@ class DeviceFormat(ObjectID):
     # pylint: disable=unused-argument
     def _postCreate(self, **kwargs):
         if self.createGeneratesEvent:
+            console_log.debug("DeviceFormat.create set ready %s", self.device)
             self.eventSync.set_ready()
+            console_log.debug("DeviceFormat.create wait %s", self.device)
             self.eventSync.wait()
             self.eventSync.reset()
+            console_log.debug("DeviceFormat.create notify %s", self.device)
             self.eventSync.notify()
 
         self.exists = True
@@ -485,11 +488,14 @@ class DeviceFormat(ObjectID):
     def _postDestroy(self, **kwargs):
         notify = kwargs.pop("notify", True)
         if notify and self.destroyGeneratesEvent:
+            console_log.debug("DeviceFormat.destroy set ready %s", self.device)
             self.eventSync.set_ready()
+            console_log.debug("DeviceFormat.destroy set ready %s", self.device)
             self.eventSync.wait()
         self.exists = False
         self.eventSync.reset()
         if notify and self.destroyGeneratesEvent:
+            console_log.debug("DeviceFormat.destroy set ready %s", self.device)
             self.eventSync.notify()
 
     def setup(self, **kwargs):
diff --git a/blivet/formats/fs.py b/blivet/formats/fs.py
index c5c61bc..125ee22 100644
--- a/blivet/formats/fs.py
+++ b/blivet/formats/fs.py
@@ -44,6 +44,7 @@ from ..synchronizer import KEY_PRESENT
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 kernel_filesystems = []
 nodev_filesystems = []
@@ -513,10 +514,13 @@ class FS(DeviceFormat):
         except OSError as e:
             raise FSResizeError(e, self.device)
         else:
+            console_log.debug("FS.resize set ready %s", self.device)
             self.eventSync.set_ready()
+            console_log.debug("FS.resize set ready %s", self.device)
             self.eventSync.wait()
         finally:
             self.eventSync.reset()
+            console_log.debug("FS.resize set ready %s", self.device)
             self.eventSync.notify()
 
         if ret:
@@ -560,10 +564,13 @@ class FS(DeviceFormat):
         except OSError as e:
             raise FSError("filesystem check failed: %s" % e)
         finally:
+            console_log.debug("FS.check set ready %s", self.device)
             self.eventSync.set_ready()
+            console_log.debug("FS.check set ready %s", self.device)
             # it may not have been opened r/w, so just wait briefly
             self.eventSync.wait(timeout=2)
             self.eventSync.reset()
+            console_log.debug("FS.check set ready %s", self.device)
             self.eventSync.notify()
 
         if self._fsckFailed(ret):
@@ -821,11 +828,14 @@ class FS(DeviceFormat):
         except Exception:
             raise
         else:
+            console_log.debug("FS.label set ready %s", self.device)
             self.eventSync.set_ready()
             timeout = 2 if rc else None
+            console_log.debug("FS.label set ready %s", self.device)
             self.eventSync.wait(timeout=timeout)
         finally:
             self.eventSync.reset()
+            console_log.debug("FS.label set ready %s", self.device)
             self.eventSync.notify()
 
         if rc:
diff --git a/blivet/handler.py b/blivet/handler.py
index 304777e..646e4c7 100644
--- a/blivet/handler.py
+++ b/blivet/handler.py
@@ -36,6 +36,7 @@ from .threads import SynchronizedMeta
 
 import logging
 log = logging.getLogger("blivet")
+console_log = logging.getLogger("console")
 
 @add_metaclass(SynchronizedMeta)
 class EventHandler(object):
@@ -49,13 +50,11 @@ class EventHandler(object):
         try:
             event = eventManager.next_event()
         except EventQueueEmptyError:
-            log.debug("uevent queue is empty")
+            console_log.debug("uevent queue is empty")
             return
 
-        if flags.console_debug:
-            print "* %s" % event
         currentThread().name = "Event%d" % event.id
-        log.debug("event: %s", event)
+        console_log.debug("-- %s", event)
         if event.action == "add":
             self.deviceAddedCB(event)
         elif event.action == "remove":
@@ -63,10 +62,9 @@ class EventHandler(object):
         elif event.action == "change":
             self.deviceChangedCB(event)
         else:
-            log.info("unknown event: %s", event)
+            console_log.info("unknown event: %s", event)
 
-        if flags.console_debug:
-            print "<- %s" % event
+        console_log.debug("<- %s", event)
 
     def deviceAddedCB(self, event, force=False):
         """ Handle an "add" uevent on a block device.
@@ -495,7 +493,7 @@ class EventHandler(object):
         if action in ("add", "change") and device and \
            device.modifySync.creating and not device.delegateModifyEvents and \
            device.modifySync.validate(event):
-            log.debug("* create %s", device.name)
+            console_log.debug("* create %s", device.name)
             ## device create without event delegation (eg: partition)
             event_sync = device.modifySync
         elif action in ("add", "change"):
@@ -506,7 +504,7 @@ class EventHandler(object):
             if device and device.controlSync.starting and \
                not device.delegateControlEvents:
                 ## device setup
-                log.debug("* setup %s", device.name)
+                console_log.debug("* setup %s", device.name)
                 # update sysfsPath since the device will not have access to it
                 # until later in the change handler
                 device.sysfsPath = sysfs_path
@@ -517,24 +515,24 @@ class EventHandler(object):
                 ## loop device teardown
                 # XXX HACK You don't get a remove event when you deactivate a
                 #          loop device.
-                log.debug("* teardown %s", device.name)
+                console_log.debug("* teardown %s", device.name)
                 name = device.name
                 event_sync = device.controlSync
             elif action == "change" and device and device.modifySync.resizing:
                 ## device resize
-                log.debug("* resize %s", device.name)
+                console_log.debug("* resize %s", device.name)
                 event_sync = device.modifySync
             elif action == "change" and device and \
                  device.controlSync.changing and \
                  device.controlSync.validate(event):
                 ## device change (eg: event on pv for vg or lv creation)
-                log.debug("* change %s", device.name)
+                console_log.debug("* change %s", device.name)
                 event_sync = device.controlSync
             elif action == "change" and device and \
                  device.format.eventSync.active and \
                  device.format.eventSync.validate(event):
                 ## any change to a format
-                log.debug("* change %s format", device.name)
+                console_log.debug("* change %s format", device.name)
                 event_sync = device.format.eventSync
             elif actions:
                 # see if this action is on a device or format that is scheduled
@@ -559,7 +557,7 @@ class EventHandler(object):
                            action.format.eventSync.validate(event):
                             ## any change to a format scheduled for destruction
                             ## on a device not scheduled for destruction
-                            log.debug("*** change %s format", action.device.name)
+                            console_log.debug("*** change %s format", action.device.name)
                             event_sync = action.format.eventSync
                             name = action.device.name
                             break
@@ -575,7 +573,7 @@ class EventHandler(object):
                        not current_action.device.delegateControlEvents:
                         ## setup of device scheduled for destruction
                         name = current_action.device.name
-                        log.debug("** setup %s", current_action.device.name)
+                        console_log.debug("** setup %s", current_action.device.name)
                         event_sync = current_action.device.controlSync
                     elif action == "change" and \
                          current_action.device.modifySync.destroying and \
@@ -583,7 +581,7 @@ class EventHandler(object):
                          current_action.device.delegateModifyEvents:
                         # change to pv when removing lv or vg
                         name = current_action.device.name
-                        log.debug("** destroy %s", current_action.device.name)
+                        console_log.debug("** destroy %s", current_action.device.name)
                         event_sync = current_action.device.modifySync
                     elif action == "change" and \
                          current_action.format.eventSync.active and \
@@ -591,13 +589,13 @@ class EventHandler(object):
                         ## any change to a format on a device scheduled for
                         ## destruction
                         name = current_action.device.name
-                        log.debug("** change %s format", current_action.device.name)
+                        console_log.debug("** change %s format", current_action.device.name)
                         event_sync = current_action.format.eventSync
 
         elif action == "remove" and device and device.controlSync.stopping and \
              not device.delegateControlEvents:
             ## device teardown
-            log.debug("* teardown %s", device.name)
+            console_log.debug("* teardown %s", device.name)
             event_sync = device.controlSync
         elif action == "remove":
             ## device destroy
@@ -611,26 +609,26 @@ class EventHandler(object):
                current_action.device.modifySync.destroying and \
                not current_action.device.delegateModifyEvents:
                 device = current_action.device
-                log.debug("* destroy %s", device.name)
+                console_log.debug("* destroy %s", device.name)
                 event_sync = device.modifySync
             elif current_action and \
                  current_action.device.exists and \
                  current_action.device.controlSync.stopping and \
                  not current_action.device.delegateControlEvents:
-                log.debug("*** teardown %s", current_action.device.name)
+                console_log.debug("*** teardown %s", current_action.device.name)
                 event_sync = current_action.device.controlSync
 
         if event_sync is not None:
-            print "waiting for ready " + name
+            console_log.debug("waiting for ready %s", name)
             event_sync.wait_for_ready()
             # Clear flags ASAP to avoid erroneously associating another event
             # with the same operation.
             event_sync.reset()
-            print "notify " + name
+            console_log.debug("notify %s", name)
             event_sync.notify()
-            print "wait " + name
+            console_log.debug("wait %s", name)
             event_sync.wait()
-            print "done " + name
+            console_log.debug("done synchronizing %s", name)
             ret = True
 
         return ret
diff --git a/blivet/util.py b/blivet/util.py
index e9c37ba..82f5637 100644
--- a/blivet/util.py
+++ b/blivet/util.py
@@ -20,6 +20,7 @@ import six
 import logging
 log = logging.getLogger("blivet")
 program_log = logging.getLogger("program")
+console_log = logging.getLogger("console")
 
 from threading import Lock
 # this will get set to anaconda's program_log_lock in enable_installer_mode
@@ -488,7 +489,7 @@ def compare(first, second):
 ##
 ## Convenience functions for examples and tests
 ##
-def set_up_logging(log_file='/tmp/blivet.log'):
+def set_up_logging(log_file='/tmp/blivet.log', console=False):
     """ Configure the blivet logger to write out a log file.
 
         :keyword str log_file: path to the log file (default: /tmp/blivet.log)
@@ -499,10 +500,22 @@ def set_up_logging(log_file='/tmp/blivet.log'):
     handler.setLevel(logging.DEBUG)
     formatter = logging.Formatter("%(asctime)s %(levelname)s %(name)s/%(threadName)s: %(message)s")
     handler.setFormatter(formatter)
+
     log.addHandler(handler)
     program_log.addHandler(handler)
+    console_log.addHandler(handler)
+    if console:
+        set_up_console_log()
     log.info("sys.argv = %s", sys.argv)
 
+def set_up_console_log():
+    handler = logging.StreamHandler()
+    console_log.setLevel(logging.DEBUG)
+    handler.setLevel(logging.DEBUG)
+    formatter = logging.Formatter("%(threadName)s: %(message)s")
+    handler.setFormatter(formatter)
+    console_log.addHandler(handler)
+
 def create_sparse_tempfile(name, size):
     """ Create a temporary sparse file.
 
-- 
2.1.0

