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

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"
+                "Exit code: %(return_code)s.\nStdout: %(stdout)r\n"
-                "Stdout: %(stdout)r\n"
                 "Stderr: %(stderr)r") % {
                     'return_code': locals['returncode'],
-                    'stdout': stdout,
+                    'stdout': stdout_pipe.output, 'stderr': stderr_pipe.output}
-                    'stderr': stderr}
             raise loopingcall.LoopingCallDone()
 
         if time.time() > expiration:

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,
+    def test_start_shellinabox_console_fail(
-                                            mock_popen):
+            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,
+    def test_start_shellinabox_console_fail_no_pid(
-                                                   mock_dir_exists,
+            self, mock_stop, mock_dir_exists, mock_pid_exists, mock_popen,
-                                                   mock_pid_exists,
+            mock_path_exists, mock_fcntl, mock_os_read, mock_sleep):
-                                                   mock_popen,
-                                                   mock_path_exists):
         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,

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.