Unify all logfile handling into utils_logfile

Most importantly, for better decoupling with aexpect we provide
sessions with close hooks that should have the same effect of
closing the open log file descriptors but in a more decoupled
fashion.

The logging functionality in utils_misc has been fully deprecated
for the sake of the same functionality in a fully devoted module.

Signed-off-by: Plamen Dimitrov <[email protected]>

avocado_vt/test.py

@@ -31,6 +31,7 @@
 from virttest import funcatexit
 from virttest import utils_env
 from virttest import utils_params
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import version
 from virttest._wrappers import load_source
@@ -111,7 +112,7 @@ def __init__(self, **kwargs):
         self.__vt_params = vt_params
         self.debugdir = self.logdir
         self.resultsdir = self.logdir
-        utils_misc.set_log_file_dir(self.logdir)
+        utils_logfile.set_log_file_dir(self.logdir)
         self.__status = None
         self.__exc_info = None
 

virttest/ip_sniffing.py

@@ -18,7 +18,7 @@
 
 import six
 
-from virttest.utils_misc import log_line
+from virttest.utils_logfile import log_line
 from virttest.utils_version import VersionInterval
 
 LOG = logging.getLogger('avocado.' + __name__)

virttest/libvirt_vm.py

@@ -23,6 +23,7 @@
 from avocado.core import exceptions
 
 from virttest import error_context
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import cpu
 from virttest import virt_vm
@@ -1455,9 +1456,10 @@ def _create_serial_console(self):
                 cmd += (" console %s %s" % (self.name, self.serial_ports[0]))
             except IndexError:
                 raise virt_vm.VMConfigMissingError(self.name, "serial")
-            output_func = utils_misc.log_line  # Because qemu-kvm uses this
+            output_func = utils_logfile.log_line  # Because qemu-kvm uses this
+            port = self.serial_ports[0]
             # Because qemu-kvm hard-codes this
-            output_filename = self.get_serial_console_filename(self.serial_ports[0])
+            output_filename = self.get_serial_console_filename(port)
             output_params = (output_filename,)
             prompt = self.params.get("shell_prompt", "[\#\$]")
             LOG.debug("Command used to create serial console: %s", cmd)
@@ -1467,10 +1469,11 @@ def _create_serial_console(self):
                                                        prompt=prompt)
             if not self.serial_console.is_alive():
                 LOG.error("Failed to create serial_console")
-            # Cause serial_console.close() to close open log file
-            self.serial_console.set_log_file(output_filename)
-            self.serial_console_log = os.path.join(utils_misc.get_log_file_dir(),
+            self.serial_console_log = os.path.join(utils_logfile.get_log_file_dir(),
                                                    output_filename)
+            # Cause serial_console.close() to close open log file
+            self.serial_console.set_log_file(self.serial_console_log)
+            self.serial_console.close_hooks += [utils_logfile.close_own_log_file]
 
     def set_root_serial_console(self, device, remove=False):
         """

virttest/qemu_devices/qcontainer.py

@@ -34,6 +34,7 @@
 # Internal imports
 from virttest import vt_iothread
 from virttest import utils_qemu
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import arch, storage, data_dir, virt_vm
 from virttest import qemu_storage
@@ -3174,7 +3175,7 @@ def tpm_define_by_params(self, name, params):
 
         def _handle_log(line):
             try:
-                utils_misc.log_line('%s_swtpm_setup.log' % name, line)
+                utils_logfile.log_line('%s_swtpm_setup.log' % name, line)
             except Exception as e:
                 LOG.warn("Can't log %s_swtpm_setup output: %s.", name, e)
 

virttest/qemu_devices/qdevices.py

@@ -18,6 +18,7 @@
 import aexpect
 
 from virttest import qemu_monitor, utils_numeric
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest.qemu_devices.utils import DeviceError
 from virttest.qemu_devices.utils import none_or_int
@@ -2082,7 +2083,7 @@ def _handle_log(self, line):
         """Handle the log of virtiofs daemon."""
         name = self.get_param('name')
         try:
-            utils_misc.log_line('%s-%s.log' % (self.get_qid(), name), line)
+            utils_logfile.log_line('%s-%s.log' % (self.get_qid(), name), line)
         except Exception as e:
             LOG.warn("Can't log %s-%s, output: '%s'.", self.get_qid(), name, e)
 
@@ -2155,7 +2156,7 @@ def start_daemon(self):
         if self.get_param('version') in ('2.0', ):
             tpm_cmd += ' --tpm2'
 
-        log_dir = utils_misc.get_log_file_dir()
+        log_dir = utils_logfile.get_log_file_dir()
         log_file = os.path.join(log_dir, '%s_swtpm.log' % self.get_qid())
         Path(log_file).touch(mode=0o644, exist_ok=True)
         tpm_cmd += ' --log file=%s' % log_file

virttest/qemu_io.py

@@ -3,6 +3,7 @@
 import aexpect
 from avocado.utils import process
 
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import error_context
 
@@ -27,7 +28,7 @@ def __init__(self, test, params, image_name, blkdebug_cfg="",
         self.type = ""
         if log_filename:
             log_filename += "-" + utils_misc.generate_random_string(4)
-            self.output_func = utils_misc.log_line
+            self.output_func = utils_logfile.log_line
             self.output_params = (log_filename,)
         else:
             self.output_func = None

virttest/qemu_monitor.py

@@ -18,6 +18,7 @@
 
 import six
 
+from . import utils_logfile
 from . import utils_misc
 from . import cartesian_config
 from . import data_dir
@@ -449,8 +450,7 @@ def _log_lines(self, log_str):
             raise MonitorLockError("Could not acquire exclusive lock to access"
                                    " %s" % self.open_log_files)
         try:
-            log_file_dir = utils_misc.get_log_file_dir()
-            log = utils_misc.get_path(log_file_dir, self.log_file)
+            log = utils_logfile.get_log_filename(self.log_file)
             timestr = time.strftime("%Y-%m-%d %H:%M:%S")
             try:
                 if log not in self.open_log_files:

virttest/qemu_vm.py

@@ -33,6 +33,7 @@
 import six
 from six.moves import xrange
 
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import utils_qemu
 from virttest import cpu
@@ -2929,7 +2930,7 @@ def _create_serial_console(self):
         self.serial_console = aexpect.ShellSession(
             "nc -U %s" % file_name,
             auto_close=False,
-            output_func=utils_misc.log_line,
+            output_func=utils_logfile.log_line,
             output_params=(log_name,),
             prompt=self.params.get("shell_prompt", "[\#\$]"),
             status_test_command=self.params.get("status_test_command",
@@ -3526,13 +3527,15 @@ def create(self, name=None, params=None, root_dir=None,
             self.create_serial_console()
 
             for key, value in list(self.logs.items()):
-                outfile = "%s-%s.log" % (key, name)
+                outfile = os.path.join(utils_logfile.get_log_file_dir(),
+                                       "%s-%s.log" % (key, name))
                 self.logsessions[key] = aexpect.Tail(
                     "nc -U %s" % value,
                     auto_close=False,
-                    output_func=utils_misc.log_line,
+                    output_func=utils_logfile.log_line,
                     output_params=(outfile,))
                 self.logsessions[key].set_log_file(outfile)
+                self.logsessions[key].close_hooks += [utils_logfile.close_own_log_file]
 
             # Wait for IO channels setting up completely,
             # such as serial console.

virttest/remote.py

@@ -86,7 +86,7 @@ def remote_commander(client, host, port, username, password, prompt,
         log_file = utils_logfile.get_log_filename(log_filename)
         session.set_output_func(utils_logfile.log_line)
         session.set_output_params((log_file,))
-        session.set_log_file(os.path.basename(log_file))
+        session.set_log_file(log_file)
 
     session.send_ctrl("raw")
     # Wrap io interfaces.

virttest/test_setup/__init__.py

@@ -27,6 +27,7 @@
 from virttest import data_dir
 from virttest import error_context
 from virttest import cpu
+from virttest import utils_logfile
 from virttest import utils_misc
 from virttest import versionable_class
 from virttest import openvswitch
@@ -1646,7 +1647,7 @@ def sr_iov_setup(self):
             file_name = "host_dmesg_after_load_%s.txt" % self.driver
             LOG.info("Log dmesg after loading '%s' to '%s'.", self.driver,
                      file_name)
-            utils_misc.log_line(file_name, dmesg)
+            utils_logfile.log_line(file_name, dmesg)
             self.setup = None
             return True
 

virttest/utils_logfile.py

@@ -1,6 +1,9 @@
 """
 Control log file utility functions.
-An easy way to log lines to files when the logging system can't be used
+
+An easy way to log lines to files when the logging system can't be used.
+
+Naive module that keeps tacks of some opened files and somehow manages them.
 
 :copyright: 2020 Red Hat Inc.
 """
@@ -13,7 +16,6 @@
 from avocado.core import exceptions
 from avocado.utils import aurl
 from avocado.utils import path as utils_path
-from aexpect.utils.genio import _open_log_files
 from avocado.utils.astring import string_safe_encode
 
 from virttest import data_dir
@@ -23,6 +25,9 @@
 _log_file_dir = data_dir.get_tmp_dir()
 _log_lock = threading.RLock()
 
+# File descriptor dictionary for all open log files
+_open_log_files = {}  # pylint: disable=C0103
+
 
 def _acquire_lock(lock, timeout=10):
     """
@@ -139,7 +144,7 @@ def get_log_filename(filename):
 
 def close_log_file(filename):
     """
-    Close the log file
+    Close all files that use the same base name as filename.
 
     :param filename: Log file name
     :raise: LogLockError if the lock is unavailable
@@ -150,13 +155,18 @@ def close_log_file(filename):
         raise LogLockError("Could not acquire exclusive lock to access"
                            " _open_log_files")
     try:
-        for k in _open_log_files:
-            if os.path.basename(k) == filename:
-                f = _open_log_files[k]
-                f.close()
-                remove.append(k)
+        for log_file, log_fd in _open_log_files.items():
+            if os.path.basename(log_file) == os.path.basename(filename):
+                log_fd.close()
+                remove.append(log_file)
         if remove:
             for key_to_remove in remove:
                 _open_log_files.pop(key_to_remove)
+
     finally:
         _log_lock.release()
+
+
+def close_own_log_file(self):
+    """Closing hook for sessions whose log_file attribute should be passed along."""
+    close_log_file(self.log_file)