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 1ad73338b8)

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

ironic/tests/unit/drivers/modules/test_console_utils.py

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

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.