diff options
author | Vladyslav Drok <vdrok@mirantis.com> | 2019-08-22 19:44:40 +0200 |
---|---|---|
committer | Vladyslav Drok <vdrok@mirantis.com> | 2019-08-28 11:07:34 +0000 |
commit | 2f3b5e929b2bbad7c23e5198c4d5d310556db101 (patch) | |
tree | 57c3c52c6abbc5867f312bd80ad144afe90d9533 | |
parent | ba0e73fa1550339f696431490fdb7d7723ef0903 (diff) | |
download | ironic-2f3b5e929b2bbad7c23e5198c4d5d310556db101.tar.gz |
Do not wait for console being started on timeout
Current logic tries to call communicate on Popen object when
starting shellinabox console even if console.subprocess_timeout
is hit. This blocks until the command is finished, with timeout
having no effect on it. It means that node lock is not released
until communicate call finishes.
Story: 2006429
Task: 36333
Change-Id: Ic7b878cd432990218a3d87047905ce0828b8da2a
(cherry picked from commit 1ad73338b83ac0bf1e3a48298fe00a922bd571a2)
3 files changed, 48 insertions, 14 deletions
diff --git a/ironic/drivers/modules/console_utils.py b/ironic/drivers/modules/console_utils.py index 5af583588..73828e61b 100644 --- a/ironic/drivers/modules/console_utils.py +++ b/ironic/drivers/modules/console_utils.py @@ -209,6 +209,12 @@ def start_shellinabox_console(node_uuid, port, console_cmd): LOG.warning(error) raise exception.ConsoleSubprocessFailed(error=error) + error_message = _( + "Timeout or error while waiting for console subprocess to start for " + "node: %(node)s.\nCommand: %(command)s.\n") % { + 'node': node_uuid, + 'command': ' '.join(args)} + def _wait(node_uuid, popen_obj): locals['returncode'] = popen_obj.poll() @@ -216,24 +222,22 @@ def start_shellinabox_console(node_uuid, port, console_cmd): # if it is, then the shellinaboxd is invoked successfully as a daemon. # otherwise check the error. if (locals['returncode'] == 0 and os.path.exists(pid_file) - and psutil.pid_exists(_get_console_pid(node_uuid))): + and psutil.pid_exists(_get_console_pid(node_uuid))): raise loopingcall.LoopingCallDone() - if (time.time() > expiration or locals['returncode'] is not None): + if locals['returncode'] is not None: (stdout, stderr) = popen_obj.communicate() - locals['errstr'] = _( - "Timeout or error while waiting for console " - "subprocess to start for node: %(node)s.\n" - "Command: %(command)s.\n" + locals['errstr'] = error_message + _( "Exit code: %(return_code)s.\n" "Stdout: %(stdout)r\n" "Stderr: %(stderr)r") % { - 'node': node_uuid, - 'command': ' '.join(args), 'return_code': locals['returncode'], 'stdout': stdout, 'stderr': stderr} - LOG.warning(locals['errstr']) + raise loopingcall.LoopingCallDone() + + if time.time() > expiration: + locals['errstr'] = error_message raise loopingcall.LoopingCallDone() locals = {'returncode': None, 'errstr': ''} @@ -242,6 +246,7 @@ def start_shellinabox_console(node_uuid, port, console_cmd): timer.start(interval=CONF.console.subprocess_checking_interval).wait() if locals['errstr']: + LOG.warning(locals['errstr']) raise exception.ConsoleSubprocessFailed(error=locals['errstr']) diff --git a/ironic/tests/unit/drivers/modules/test_console_utils.py b/ironic/tests/unit/drivers/modules/test_console_utils.py index 4c83fb169..f433a1520 100644 --- a/ironic/tests/unit/drivers/modules/test_console_utils.py +++ b/ironic/tests/unit/drivers/modules/test_console_utils.py @@ -331,11 +331,32 @@ class ConsoleUtilsTestCase(db_base.DbTestCase): mock_popen.return_value.poll.return_value = 1 mock_popen.return_value.communicate.return_value = ('output', 'error') - self.assertRaises(exception.ConsoleSubprocessFailed, - console_utils.start_shellinabox_console, - self.info['uuid'], - self.info['port'], - 'ls&') + self.assertRaisesRegex( + exception.ConsoleSubprocessFailed, "Stdout: 'output'", + console_utils.start_shellinabox_console, self.info['uuid'], + self.info['port'], 'ls&') + + mock_stop.assert_called_once_with(self.info['uuid']) + mock_dir_exists.assert_called_once_with() + 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(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.config(subprocess_timeout=0, group='console') + self.config(subprocess_checking_interval=0, group='console') + mock_popen.return_value.poll.return_value = None + + self.assertRaisesRegex( + exception.ConsoleSubprocessFailed, 'Timeout or error', + console_utils.start_shellinabox_console, self.info['uuid'], + self.info['port'], 'ls&') mock_stop.assert_called_once_with(self.info['uuid']) mock_dir_exists.assert_called_once_with() @@ -343,6 +364,7 @@ class ConsoleUtilsTestCase(db_base.DbTestCase): stdout=subprocess.PIPE, stderr=subprocess.PIPE) mock_popen.return_value.poll.assert_called_with() + self.assertEqual(0, mock_popen.return_value.communicate.call_count) @mock.patch.object(console_utils, 'open', mock.mock_open(read_data='12345\n')) diff --git a/releasenotes/notes/fix-shellinabox-console-subprocess-timeout-d3eccfe0440013d7.yaml b/releasenotes/notes/fix-shellinabox-console-subprocess-timeout-d3eccfe0440013d7.yaml new file mode 100644 index 000000000..10a3f09d0 --- /dev/null +++ b/releasenotes/notes/fix-shellinabox-console-subprocess-timeout-d3eccfe0440013d7.yaml @@ -0,0 +1,7 @@ +--- +fixes: + - | + Fixed the `issue <https://storyboard.openstack.org/#!/story/2006429>`_ + with node being locked for longer than ``[console]subprocess_timeout`` + seconds when shellinabox process fails to start before the specifed timeout + elapses. |