From efc2d5fcd3e4c3d8e24801b45f61f7f747b7f340 Mon Sep 17 00:00:00 2001 From: Vladyslav Drok Date: Fri, 30 Aug 2019 14:52:42 +0200 Subject: [PATCH] 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 | 51 +++++++++++-- .../drivers/modules/test_console_utils.py | 73 ++++++++++++++----- ...nabox-pipe-not-ready-f860c4b7a1ef71a8.yaml | 7 ++ 3 files changed, 108 insertions(+), 23 deletions(-) create mode 100644 releasenotes/notes/fix-shellinabox-pipe-not-ready-f860c4b7a1ef71a8.yaml diff --git a/ironic/drivers/modules/console_utils.py b/ironic/drivers/modules/console_utils.py index 73828e61bc..59e52fb369 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 f433a15201..c010fdef50 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 0000000000..c8254218d4 --- /dev/null +++ b/releasenotes/notes/fix-shellinabox-pipe-not-ready-f860c4b7a1ef71a8.yaml @@ -0,0 +1,7 @@ +--- +fixes: + - | + Fixes a possible + `console lockup issue `_ + in case of PID file not being yet created while daemon start has call + already returned success return code.