Merge "Read in non-blocking fashion when starting console"

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.