Read in non-blocking fashion when starting console

As PID file is created by daemon, it might happen that although the
return code is 0, the PID file does not exist yet. And afterwards,
communicate() call might hang for some reason. As there is no way to
put timeout on communicate call in python2, and in order to make
this change more backportable, this patch uses non-blocking read to
get the values of stdout and stderr of the call.

Story: 2006514
Task: 36511
Change-Id: I0bf38321b0135ea17439d35081b5727fd4d827c8
(cherry picked from commit efc2d5fcd3e4c3d8e24801b45f61f7f747b7f340)

3 files changed, 108 insertions, 23 deletions

diff --git a/ironic/drivers/modules/console_utils.py b/ironic/drivers/modules/console_utils.py
index 73828e61b..59e52fb36 100644
--- a/ironic/drivers/modules/console_utils.py
+++ b/ironic/drivers/modules/console_utils.py
@@ -20,6 +20,7 @@ Ironic console utilities.
 """
 
 import errno
+import fcntl
 import os
 import signal
 import subprocess
@@ -159,6 +160,41 @@ def get_shellinabox_console_url(port):
                                                'port': port}
 
 
+class _PopenNonblockingPipe(object):
+    def __init__(self, source):
+        self._source = source
+        self._output = b''
+        self._wait = False
+        self._finished = False
+        self._set_async()
+
+    def _set_async(self):
+        flags = fcntl.fcntl(self._source, fcntl.F_GETFL)
+        fcntl.fcntl(self._source, fcntl.F_SETFL, flags | os.O_NONBLOCK)
+
+    def read(self, num_bytes=4096):
+        if self._finished:
+            return
+        try:
+            if self._wait:
+                time.sleep(1)
+                self._wait = False
+            data = os.read(self._source.fileno(), num_bytes)
+            self._output += data
+            if len(data) < num_bytes:
+                self._wait = True
+        except OSError:
+            self._finished = True
+
+    @property
+    def output(self):
+        return self._output
+
+    @property
+    def finished(self):
+        return self._finished
+
+
 def start_shellinabox_console(node_uuid, port, console_cmd):
     """Open the serial console for a node.
 
@@ -215,6 +251,9 @@ def start_shellinabox_console(node_uuid, port, console_cmd):
             'node': node_uuid,
             'command': ' '.join(args)}
 
+    stdout_pipe, stderr_pipe = (
+        _PopenNonblockingPipe(obj.stdout), _PopenNonblockingPipe(obj.stderr))
+
     def _wait(node_uuid, popen_obj):
         locals['returncode'] = popen_obj.poll()
 
@@ -226,14 +265,16 @@ def start_shellinabox_console(node_uuid, port, console_cmd):
             raise loopingcall.LoopingCallDone()
 
         if locals['returncode'] is not None:
-            (stdout, stderr) = popen_obj.communicate()
+            watched = (stdout_pipe, stderr_pipe)
+            while time.time() < expiration and not all(
+                    (i.finished for i in watched)):
+                for pipe in watched:
+                    pipe.read()
             locals['errstr'] = error_message + _(
-                "Exit code: %(return_code)s.\n"
-                "Stdout: %(stdout)r\n"
+                "Exit code: %(return_code)s.\nStdout: %(stdout)r\n"
                 "Stderr: %(stderr)r") % {
                     'return_code': locals['returncode'],
-                    'stdout': stdout,
-                    'stderr': stderr}
+                    'stdout': stdout_pipe.output, 'stderr': stderr_pipe.output}
             raise loopingcall.LoopingCallDone()
 
         if time.time() > expiration:
diff --git a/ironic/tests/unit/drivers/modules/test_console_utils.py b/ironic/tests/unit/drivers/modules/test_console_utils.py
index f433a1520..c010fdef5 100644
--- a/ironic/tests/unit/drivers/modules/test_console_utils.py
+++ b/ironic/tests/unit/drivers/modules/test_console_utils.py
@@ -18,12 +18,14 @@
 """Test class for console_utils driver module."""
 
 import errno
+import fcntl
 import os
 import random
 import signal
 import string
 import subprocess
 import tempfile
+import time
 
 from ironic_lib import utils as ironic_utils
 import mock
@@ -262,10 +264,11 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                           filepath,
                           'password')
 
+    @mock.patch.object(fcntl, 'fcntl', autospec=True)
     @mock.patch.object(console_utils, 'open',
                        mock.mock_open(read_data='12345\n'))
     @mock.patch.object(os.path, 'exists', autospec=True)
-    @mock.patch.object(subprocess, 'Popen', autospec=True)
+    @mock.patch.object(subprocess, 'Popen')
     @mock.patch.object(psutil, 'pid_exists', autospec=True)
     @mock.patch.object(console_utils, '_ensure_console_pid_dir_exists',
                        autospec=True)
@@ -274,8 +277,10 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                                        mock_dir_exists,
                                        mock_pid_exists,
                                        mock_popen,
-                                       mock_path_exists):
+                                       mock_path_exists, mock_fcntl):
         mock_popen.return_value.poll.return_value = 0
+        mock_popen.return_value.stdout.return_value.fileno.return_value = 0
+        mock_popen.return_value.stderr.return_value.fileno.return_value = 1
         mock_pid_exists.return_value = True
         mock_path_exists.return_value = True
 
@@ -291,10 +296,11 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                                            stderr=subprocess.PIPE)
         mock_popen.return_value.poll.assert_called_once_with()
 
+    @mock.patch.object(fcntl, 'fcntl', autospec=True)
     @mock.patch.object(console_utils, 'open',
                        mock.mock_open(read_data='12345\n'))
     @mock.patch.object(os.path, 'exists', autospec=True)
-    @mock.patch.object(subprocess, 'Popen', autospec=True)
+    @mock.patch.object(subprocess, 'Popen')
     @mock.patch.object(psutil, 'pid_exists', autospec=True)
     @mock.patch.object(console_utils, '_ensure_console_pid_dir_exists',
                        autospec=True)
@@ -303,10 +309,12 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                                              mock_dir_exists,
                                              mock_pid_exists,
                                              mock_popen,
-                                             mock_path_exists):
+                                             mock_path_exists, mock_fcntl):
         # no existing PID file before starting
         mock_stop.side_effect = exception.NoConsolePid('/tmp/blah')
         mock_popen.return_value.poll.return_value = 0
+        mock_popen.return_value.stdout.return_value.fileno.return_value = 0
+        mock_popen.return_value.stderr.return_value.fileno.return_value = 1
         mock_pid_exists.return_value = True
         mock_path_exists.return_value = True
 
@@ -322,36 +330,54 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                                            stderr=subprocess.PIPE)
         mock_popen.return_value.poll.assert_called_once_with()
 
-    @mock.patch.object(subprocess, 'Popen', autospec=True)
+    @mock.patch.object(time, 'sleep', autospec=True)
+    @mock.patch.object(os, 'read', autospec=True)
+    @mock.patch.object(fcntl, 'fcntl', autospec=True)
+    @mock.patch.object(subprocess, 'Popen')
     @mock.patch.object(console_utils, '_ensure_console_pid_dir_exists',
                        autospec=True)
     @mock.patch.object(console_utils, '_stop_console', autospec=True)
-    def test_start_shellinabox_console_fail(self, mock_stop, mock_dir_exists,
-                                            mock_popen):
+    def test_start_shellinabox_console_fail(
+            self, mock_stop, mock_dir_exists, mock_popen, mock_fcntl,
+            mock_os_read, mock_sleep):
         mock_popen.return_value.poll.return_value = 1
-        mock_popen.return_value.communicate.return_value = ('output', 'error')
+        stdout = mock_popen.return_value.stdout
+        stderr = mock_popen.return_value.stderr
+        stdout.return_value.fileno.return_value = 0
+        stderr.return_value.fileno.return_value = 1
+        err_output = b'error output'
+        mock_os_read.side_effect = [err_output] * 2 + [OSError] * 2
+        mock_fcntl.side_effect = [1, mock.Mock()] * 2
 
         self.assertRaisesRegex(
-            exception.ConsoleSubprocessFailed, "Stdout: 'output'",
+            exception.ConsoleSubprocessFailed, "Stdout: %r" % err_output,
             console_utils.start_shellinabox_console, self.info['uuid'],
             self.info['port'], 'ls&')
 
         mock_stop.assert_called_once_with(self.info['uuid'])
+        mock_sleep.assert_has_calls([mock.call(1), mock.call(1)])
         mock_dir_exists.assert_called_once_with()
+        for obj in (stdout, stderr):
+            mock_fcntl.assert_has_calls([
+                mock.call(obj, fcntl.F_GETFL),
+                mock.call(obj, fcntl.F_SETFL, 1 | os.O_NONBLOCK)])
         mock_popen.assert_called_once_with(mock.ANY,
                                            stdout=subprocess.PIPE,
                                            stderr=subprocess.PIPE)
         mock_popen.return_value.poll.assert_called_with()
 
-    @mock.patch.object(subprocess, 'Popen', autospec=True)
+    @mock.patch.object(fcntl, 'fcntl', autospec=True)
+    @mock.patch.object(subprocess, 'Popen')
     @mock.patch.object(console_utils, '_ensure_console_pid_dir_exists',
                        autospec=True)
     @mock.patch.object(console_utils, '_stop_console', autospec=True)
     def test_start_shellinabox_console_timeout(
-            self, mock_stop, mock_dir_exists, mock_popen):
+            self, mock_stop, mock_dir_exists, mock_popen, mock_fcntl):
         self.config(subprocess_timeout=0, group='console')
         self.config(subprocess_checking_interval=0, group='console')
         mock_popen.return_value.poll.return_value = None
+        mock_popen.return_value.stdout.return_value.fileno.return_value = 0
+        mock_popen.return_value.stderr.return_value.fileno.return_value = 1
 
         self.assertRaisesRegex(
             exception.ConsoleSubprocessFailed, 'Timeout or error',
@@ -366,22 +392,28 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
         mock_popen.return_value.poll.assert_called_with()
         self.assertEqual(0, mock_popen.return_value.communicate.call_count)
 
+    @mock.patch.object(time, 'sleep', autospec=True)
+    @mock.patch.object(os, 'read', autospec=True)
+    @mock.patch.object(fcntl, 'fcntl', autospec=True)
     @mock.patch.object(console_utils, 'open',
                        mock.mock_open(read_data='12345\n'))
     @mock.patch.object(os.path, 'exists', autospec=True)
-    @mock.patch.object(subprocess, 'Popen', autospec=True)
+    @mock.patch.object(subprocess, 'Popen')
     @mock.patch.object(psutil, 'pid_exists', autospec=True)
     @mock.patch.object(console_utils, '_ensure_console_pid_dir_exists',
                        autospec=True)
     @mock.patch.object(console_utils, '_stop_console', autospec=True)
-    def test_start_shellinabox_console_fail_no_pid(self, mock_stop,
-                                                   mock_dir_exists,
-                                                   mock_pid_exists,
-                                                   mock_popen,
-                                                   mock_path_exists):
+    def test_start_shellinabox_console_fail_no_pid(
+            self, mock_stop, mock_dir_exists, mock_pid_exists, mock_popen,
+            mock_path_exists, mock_fcntl, mock_os_read, mock_sleep):
         mock_popen.return_value.poll.return_value = 0
+        stdout = mock_popen.return_value.stdout
+        stderr = mock_popen.return_value.stderr
+        stdout.return_value.fileno.return_value = 0
+        stderr.return_value.fileno.return_value = 1
         mock_pid_exists.return_value = False
-        mock_popen.return_value.communicate.return_value = ('output', 'error')
+        mock_os_read.side_effect = [b'error output'] * 2 + [OSError] * 2
+        mock_fcntl.side_effect = [1, mock.Mock()] * 2
         mock_path_exists.return_value = True
 
         self.assertRaises(exception.ConsoleSubprocessFailed,
@@ -391,7 +423,12 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
                           'ls&')
 
         mock_stop.assert_called_once_with(self.info['uuid'])
+        mock_sleep.assert_has_calls([mock.call(1), mock.call(1)])
         mock_dir_exists.assert_called_once_with()
+        for obj in (stdout, stderr):
+            mock_fcntl.assert_has_calls([
+                mock.call(obj, fcntl.F_GETFL),
+                mock.call(obj, fcntl.F_SETFL, 1 | os.O_NONBLOCK)])
         mock_pid_exists.assert_called_with(12345)
         mock_popen.assert_called_once_with(mock.ANY,
                                            stdout=subprocess.PIPE,
diff --git a/releasenotes/notes/fix-shellinabox-pipe-not-ready-f860c4b7a1ef71a8.yaml b/releasenotes/notes/fix-shellinabox-pipe-not-ready-f860c4b7a1ef71a8.yaml
new file mode 100644
index 000000000..c8254218d
--- /dev/null
+++ b/releasenotes/notes/fix-shellinabox-pipe-not-ready-f860c4b7a1ef71a8.yaml
@@ -0,0 +1,7 @@
+---
+fixes:
+  - |
+    Fixes a possible
+    `console lockup issue <https://storyboard.openstack.org/#!/story/2006514>`_
+    in case of PID file not being yet created while daemon start has call
+    already returned success return code.