From 4af4d6c4e24f78241cd41ceea741a25de6a8da7f Mon Sep 17 00:00:00 2001
From: Lucian Petrut <lpetrut@cloudbasesolutions.com>
Date: Fri, 5 Jan 2018 18:28:02 +0200
Subject: [PATCH] Flush console log file before retrieving content

Hyper-V exposes instance serial console ports through named pipes.
We're consuming those named pipes, logging the output to a file,
retrieving the content when the console output is requested.

The issue is that the log file used by os-win never gets flushed
(unless closed). For this reason, we're returning incomplete output.

This change ensures that we're flushing the log file before attempting
to read its content.

Closes-Bug: #1741494

Change-Id: Ic558b16b317e0b1478cc259327d1336f7589afe3
Depends-On: I4b5eb7579ac0c92e9c3630539b0c4d76f5b98c6d
(cherry picked from commit eb2c7b20a3e1328c1f3f5569bb5956a8ec230e8b)
---
 compute_hyperv/nova/serialconsolehandler.py         | 10 ++++++++++
 compute_hyperv/nova/serialconsoleops.py             |  4 ++++
 .../tests/unit/test_serialconsolehandler.py         | 13 ++++++++++++-
 compute_hyperv/tests/unit/test_serialconsoleops.py  |  3 +++
 4 files changed, 29 insertions(+), 1 deletion(-)

diff --git a/compute_hyperv/nova/serialconsolehandler.py b/compute_hyperv/nova/serialconsolehandler.py
index 6094afdf..cc40d836 100644
--- a/compute_hyperv/nova/serialconsolehandler.py
+++ b/compute_hyperv/nova/serialconsolehandler.py
@@ -49,6 +49,7 @@ class SerialConsoleHandler(object):
 
         self._serial_proxy = None
         self._workers = []
+        self._log_handler = None
 
     def start(self):
         self._setup_handlers()
@@ -117,6 +118,9 @@ class SerialConsoleHandler(object):
                 enable_logging=enable_logging)
             self._workers.append(handler)
 
+            if enable_logging:
+                self._log_handler = handler
+
     def _get_named_pipe_handler(self, pipe_path, pipe_type,
                                 enable_logging):
         kwargs = {}
@@ -161,3 +165,9 @@ class SerialConsoleHandler(object):
             raise exception.ConsoleTypeUnavailable(console_type='serial')
         return ctype.ConsoleSerial(host=self._listen_host,
                                    port=self._listen_port)
+
+    def flush_console_log(self):
+        if self._log_handler:
+            LOG.debug("Flushing instance %s console log.",
+                      self._instance_name)
+            self._log_handler.flush_log_file()
diff --git a/compute_hyperv/nova/serialconsoleops.py b/compute_hyperv/nova/serialconsoleops.py
index 0184e448..c713168f 100644
--- a/compute_hyperv/nova/serialconsoleops.py
+++ b/compute_hyperv/nova/serialconsoleops.py
@@ -111,6 +111,10 @@ class SerialConsoleOps(object):
         console_log_paths = self._pathutils.get_vm_console_log_paths(
             instance_name)
 
+        handler = _console_handlers.get(instance_name)
+        if handler:
+            handler.flush_console_log()
+
         try:
             log = b''
             # Start with the oldest console log file.
diff --git a/compute_hyperv/tests/unit/test_serialconsolehandler.py b/compute_hyperv/tests/unit/test_serialconsolehandler.py
index 9c6d0309..e5f8763a 100644
--- a/compute_hyperv/tests/unit/test_serialconsolehandler.py
+++ b/compute_hyperv/tests/unit/test_serialconsolehandler.py
@@ -135,7 +135,7 @@ class SerialConsoleHandlerTestCase(test_base.HyperVBaseTestCase):
 
         return mock_get_pipe_handler
 
-    def test_setup_ro_pipe_handler(self):
+    def test_setup_rw_pipe_handler(self):
         serial_port_mapping = {
             constants.SERIAL_PORT_TYPE_RW: mock.sentinel.pipe_path
         }
@@ -147,6 +147,8 @@ class SerialConsoleHandlerTestCase(test_base.HyperVBaseTestCase):
             mock.sentinel.pipe_path,
             pipe_type=constants.SERIAL_PORT_TYPE_RW,
             enable_logging=True)
+        self.assertEqual(mock_get_handler.return_value,
+                         self._consolehandler._log_handler)
 
     def test_setup_pipe_handlers(self):
         serial_port_mapping = {
@@ -251,3 +253,12 @@ class SerialConsoleHandlerTestCase(test_base.HyperVBaseTestCase):
         self.flags(enabled=False, group='serial_console')
         self.assertRaises(exception.ConsoleTypeUnavailable,
                           self._consolehandler.get_serial_console)
+
+    def test_flush_console_log(self):
+        self._consolehandler._log_handler = None
+        self._consolehandler.flush_console_log()
+
+        mock_handler = mock.Mock()
+        self._consolehandler._log_handler = mock_handler
+        self._consolehandler.flush_console_log()
+        mock_handler.flush_log_file.assert_called_once_with()
diff --git a/compute_hyperv/tests/unit/test_serialconsoleops.py b/compute_hyperv/tests/unit/test_serialconsoleops.py
index c3900082..45c243bc 100644
--- a/compute_hyperv/tests/unit/test_serialconsoleops.py
+++ b/compute_hyperv/tests/unit/test_serialconsoleops.py
@@ -109,6 +109,8 @@ class SerialConsoleOpsTestCase(test_base.HyperVBaseTestCase):
     @mock.patch.object(builtins, 'open')
     @mock.patch("os.path.exists")
     def test_get_console_output_exception(self, fake_path_exists, fake_open):
+        mock_handler = self._setup_console_handler_mock()
+
         self._serialops._vmutils.is_secure_vm.return_value = False
         self._serialops._pathutils.get_vm_console_log_paths.return_value = [
             mock.sentinel.log_path_1, mock.sentinel.log_path_2]
@@ -118,6 +120,7 @@ class SerialConsoleOpsTestCase(test_base.HyperVBaseTestCase):
         self.assertRaises(exception.ConsoleLogOutputException,
                           self._serialops.get_console_output,
                           mock.sentinel.instance_name)
+        mock_handler.flush_console_log.assert_called_once_with()
         fake_open.assert_called_once_with(mock.sentinel.log_path_2, 'rb')
 
     def test_get_console_output_secure_vm(self):