Merge lp:~javier.collado/utah/bug1169510 into lp:utah

[Javier Collado]

The changes in this branch are intended to make sure that timeouts are timely
handled when the utah client is running through SSH.

The problem here is that the SIGALRM isn't called until the call to the client
is finished (which might take hours) as explained in the following bug:
http://bugs.python.org/issue9504

To fix the problem, a timeout is set in the ssh socket, so that the call to the
client is interrupted in case of a timeout instead of waiting for the client to
finish before calling the signal handler.

In addition to this, there are a few exception related changes to make sure
that UTAHTimeout isn't caught by accident (making it a subclass of SystemExit)
and also to make sure that error messages are printed after cleanup messages to
make easier to troubleshoot problems.

[Andy Doan (doanac)]

LGTM - didn't know about SystemExit, so I've learned something new.

review: Approve

[Max Brustkern (nuclearbob)]

This looks great, it'll simplify some things nicely.

review: Approve

=== modified file 'debian/changelog'
--- debian/changelog	2013-04-17 08:26:37 +0000
+++ debian/changelog	2013-04-18 14:31:13 +0000
@@ -4,6 +4,9 @@
   * Check squashfs on the server images as well during ISO static
     validation.
 
+  [ Javier Collado ]
+  * Use socket timeout in SSH commands instead of SIGALRM (LP: #1169510)
+
  -- Max Brustkern <[e-mail]>  Tue, 16 Apr 2013 09:21:19 -0400
 
 utah (0.10ubuntu1) UNRELEASED; urgency=low

=== modified file 'examples/run_install_test.py'
--- examples/run_install_test.py	2013-04-10 15:34:49 +0000
+++ examples/run_install_test.py	2013-04-18 14:31:13 +0000
@@ -81,13 +81,6 @@
             preseed=args.preseed, rewrite=args.rewrite,
             series=args.series, xml=args.xml)
         exitstatus, locallogs = run_tests(args, machine)
-
-    except UTAHException as error:
-        sys.stderr.write('Exception: ' + str(error))
-        exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
-    except Exception:
-        logging.exception('Unhandled error in UTAH')
-        exitstatus = ReturnCodes.UNHANDLED_ERROR
     finally:
         if not args.no_destroy and machine is not None:
             try:

=== modified file 'examples/run_utah_tests.py'
--- examples/run_utah_tests.py	2013-04-04 15:39:49 +0000
+++ examples/run_utah_tests.py	2013-04-18 14:31:13 +0000
@@ -21,6 +21,7 @@
 import argparse
 import logging
 import sys
+from traceback import format_exception
 
 from utah import config
 from utah.cleanup import cleanup
@@ -92,23 +93,16 @@
         def run_provisioned_tests(args):
             """Run test cases in a provisioned machine."""
             locallogs = []
-            exitstatus = ReturnCodes.SUCCESS
             try:
                 # TBD: Inventory should be used to verify machine
                 # is not running other tests
                 machine = ProvisionedMachine(name=args.name)
                 exitstatus, locallogs = run_tests(args, machine)
-            except UTAHException as error:
-                sys.stderr.write('Exception: ' + str(error))
-                exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
-            except Exception:
-                logging.exception('Unhandled error in UTAH')
-                exitstatus = ReturnCodes.UNHANDLED_ERROR
             finally:
                 if len(locallogs) != 0:
                     print('Test logs copied to the following files:')
                     print("\t" + "\n\t".join(locallogs))
-            sys.exit(exitstatus)
+            sys.exit(ReturnCodes.SUCCESS)
 
         function = run_provisioned_tests
     if args.arch is not None and 'arm' in args.arch:
@@ -124,16 +118,22 @@
 
 if __name__ == '__main__':
     try:
-        if isinstance(config.jobtimeout, int):
-            try:
+        try:
+            if isinstance(config.jobtimeout, int):
                 timeout(config.jobtimeout, run_utah_tests)
-            except UTAHTimeout:
-                sys.stderr.write('Job failed to complete after '
-                                 + str(config.jobtimeout) + ' seconds.')
-                sys.exit(ReturnCodes.TIMEOUT_ERROR)
-        else:
+            else:
+                run_utah_tests()
+        except AttributeError:
             run_utah_tests()
-    except AttributeError:
-        run_utah_tests()
-    finally:
-        cleanup.run()
+        finally:
+            cleanup.run()
+    except UTAHTimeout as exception:
+        sys.stderr.write('UTAH timeout: {}'.format(exception.message))
+        sys.exit(ReturnCodes.TIMEOUT_ERROR)
+    except UTAHException as error:
+        sys.stderr.write('UTAH exception: '.format(error))
+        sys.exit(ReturnCodes.UTAH_EXCEPTION_ERROR)
+    except Exception:
+        sys.stderr.write('Unhandled error in UTAH:\n{}'
+                         .format(''.join(format_exception(*sys.exc_info()))))
+        sys.exit(ReturnCodes.UNHANDLED_ERROR)

=== modified file 'utah/provisioning/provisioning.py'
--- utah/provisioning/provisioning.py	2013-04-08 19:16:05 +0000
+++ utah/provisioning/provisioning.py	2013-04-18 14:31:13 +0000
@@ -315,7 +315,7 @@
             try:
                 utah.timeout.timeout(config.installtimeout, self._provision)
             except utah.timeout.UTAHTimeout:
-                raise UTAHProvisioningException(
+                raise utah.timeout.UTAHTimeout(
                     'Machine install timed out.  '
                     'Consider adjusting timeout values in '
                     '/etc/utah/conf, ~/.utah/conf, or '

=== modified file 'utah/provisioning/ssh.py'
--- utah/provisioning/ssh.py	2013-04-04 17:07:22 +0000
+++ utah/provisioning/ssh.py	2013-04-18 14:31:13 +0000
@@ -21,6 +21,7 @@
 import logging
 import os
 import paramiko
+import signal
 import socket
 
 from stat import S_ISDIR
@@ -57,7 +58,7 @@
         self.ssh_client = ssh_client
         self.ssh_logger = logging.getLogger('ssh')
 
-    def run(self, command, quiet=False, root=False, timeout=None):
+    def run(self, command, quiet=False, root=False, command_timeout=None):
         """Run a command through SSH.
 
         :param command: Command to execute on the remote machine
@@ -70,11 +71,11 @@
             Run command as root user when this flag is set. Otherwise, use the
             user specified in the configuration file.
         :type root: bool
-        :param timeout:
+        :param command_timeout:
             Amount of time in seconds to wait for the command to complete.
 
             .. seealso:: :func:`utah.timeout.timeout`
-        :type timeout: int
+        :type command_timeout: int
 
         """
         if isinstance(command, basestring):
@@ -107,11 +108,26 @@
                                  .format(commandstring))
             stdout = channel.makefile('rb')
             stderr = channel.makefile_stderr('rb')
-            if timeout is None:
-                channel.exec_command(commandstring)
-            else:
-                utah.timeout.timeout(timeout, channel.exec_command,
-                                     commandstring)
+
+            # Get remaining SIGALRM timeout
+            alarm_timeout = signal.alarm(0)
+            signal.alarm(alarm_timeout)
+
+            # Discard 0 or None timeout values
+            timeouts = filter(None, [command_timeout, alarm_timeout])
+            if timeouts:
+                timeout = min(timeouts)
+                channel.settimeout(timeout)
+
+            channel.exec_command(commandstring)
+            try:
+                # Make sure socket.timeout is raised
+                channel.recv(0)
+            except socket.timeout:
+                raise utah.timeout.UTAHTimeout(
+                    'SSH command timed out {!r} after {} seconds'
+                    .format(commandstring, timeout))
+
             retval = channel.recv_exit_status()
 
         except paramiko.BadHostKeyException as err:

=== modified file 'utah/run.py'
--- utah/run.py	2013-04-17 08:26:37 +0000
+++ utah/run.py	2013-04-18 14:31:13 +0000
@@ -24,7 +24,6 @@
 import socket
 import sys
 import time
-import traceback
 import urllib
 
 import jsonschema
@@ -341,21 +340,17 @@
                  .format(report_type, machine.installtype))
 
     locallogs = []
-    try:
-        machine.installclient()
-    except Exception:
-        traceback.print_exc()
-        exitstatus = 1
-    else:
-        # Server will return success code only if the execution
-        # of every runlist was successful
-        exitstatus = _run(args.runlist)
-
-        if args.files is not None:
-            try:
-                locallogs += getfiles(args, machine)
-            except UTAHException as err:
-                logging.warning('Failed to download files: %s', str(err))
+    machine.installclient()
+
+    # Server will return success code only if the execution
+    # of every runlist was successful
+    exitstatus = _run(args.runlist)
+
+    if args.files is not None:
+        try:
+            locallogs += getfiles(args, machine)
+        except UTAHException as err:
+            logging.warning('Failed to download files: %s', str(err))
 
     # Provisioned systems have an image already installed
     # and the preseed file is no longer available

=== modified file 'utah/timeout.py'
--- utah/timeout.py	2013-04-03 21:17:26 +0000
+++ utah/timeout.py	2013-04-18 14:31:13 +0000
@@ -21,11 +21,10 @@
 import subprocess
 import sys
 
-from utah.exceptions import UTAHException
 from utah.commandstr import commandstr
 
 
-class UTAHTimeout(UTAHException):
+class UTAHTimeout(SystemExit):
 
     """Provide a special exception to indicate an operation timed out."""
 
@@ -83,7 +82,7 @@
                 return retval
             except UTAHTimeout:
                 raise UTAHTimeout(
-                    '{} timed out after {} seconds'
+                    '{} timed out after {} seconds\n'
                     .format(commandstr(command, *args, **kw), str(timeout)))
     else:
         raise UTAHTimeout('0 timeout specified')