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
This commit is contained in:
Vladyslav Drok 2019-08-22 19:44:40 +02:00 committed by Julia Kreger
parent 028ab71d3f
commit 1ad73338b8
3 changed files with 48 additions and 14 deletions

View File

@ -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'])

View File

@ -331,11 +331,10 @@ 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()
@ -344,6 +343,29 @@ class ConsoleUtilsTestCase(db_base.DbTestCase):
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()
mock_popen.assert_called_once_with(mock.ANY,
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'))
@mock.patch.object(os.path, 'exists', autospec=True)

View File

@ -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.