Merge lp:~vila/tarmac/1392339-verify-timeout into lp:tarmac

[Vincent Ladeuil]

Protect tarmac from committing suicide, allow config to specify a verify_timeout for verify_command

This adds a test to exercise the timeout handling for verify_command.

This test revealed several issues that are fixed here:

- by default 'verify_command' will not create a new process group so having
  a safe-guard in place avoid killing tarmac itself,

- the code was expecting a command.config.debug, protect against this
  attribute not being set,

- add a verify_timeout config option so the default timeout can be
  overridden.

That last one is used in the test itself and is needed on my project where
the verify_command includes a juju deployment that can take more than 15
minutes (the default timeout).

[lp:~vila/tarmac/1392339-verify-timeout]

435. By Vincent Ladeuil on 2014-11-13

Mark the bug as fixed

[dobey (dobey)]

review: Needs Fixing

[Vincent Ladeuil (vila)]

I've reverted the copyright changes (even though they are generated from bzr history by a plugin, feedback welcome).

I've added tests for bogus verify_timeout values.

See more details in inline comments.

[lp:~vila/tarmac/1392339-verify-timeout]

436. By Vincent Ladeuil on 2014-11-14

Add test to cover bogus verify_timeout values handling.

437. By Vincent Ladeuil on 2014-11-14

Revert the controversial change.

[dobey (dobey)]

Some replies below, but also, I just realized I forgot to mention that
as you're making the verify command timeout configurable, you'll also
need to update that plug-in's section in docs/introduction.txt to
include documentation on the configuration option.

On Fri, 2014-11-14 at 08:53 +0000, Vincent Ladeuil wrote:
> Not according to bzr annotate which is what
> https://launchpad.net/bzr-update-copyright uses to update this line.

The bzr log/annotate/etc… commands do not understand the structure of
copyright law. They simply show data. Maybe all the dates in the file
need some fixing, but I would not trust a script to do that
automatically, in general. For projects where all copyright is always
assigned to a single entity, maybe it would be reasonable, but tarmac is
not such a project.

> Regarding the format that needs to be used in that line, do you have a
> reference so a proper bug can be filed against that plugin ?

See "The Double-Date Problem" section of:
http://blog.apastyle.org/apastyle/2010/01/the-generic-reference-when.html

> > # Copyright 2009 Paul Hummer
>
> This also says that 2013-2014 is wrong no ?

No. It says that Paul owns copyright on some code he wrote, in the file,
in 2009. The changes in 2013 were not by him. And that copyright was not
assigned to Canonical. The tarmac project is not under the CLA, and
multiple parties can/may own copyright.

> As mentioned in the cover letter:
> - the code was expecting a command.config.debug, protect against this
> attribute not being set,

I understand what was changed. The commit message doesn't tell me why it
was changed though. A bug describing the problem in detail can help me
understand the problem you are trying to fix with this change, better.
And a separate branch will let me more easily review the two issues
separately (even if one depends on the other).

> The code related to command.config.debug is reached only when the
> timeout triggers. It *is* related and the timeout handling *cannot* be
> fixed without fixing that.

But the changes to the timeout value and add a config setting for the
timeout, are not required to fix the debug issue. It may be *related*,
but it is a *separate* issue. A separate bug is preferred for that, with
a separate branch (which the timeout fix can have a prerequisite on, if
it requires that fix), ideally with tests to validate the fix for the
debug problem.

I'm not against the change itself, if it's necessary. I just prefer to
review it separately, as it is a separate problem. The timeout fix might
depend on it, but it does not depend on the timeout fix. As such, a
separate bug, and a separate branch, with regression tests, is the best
way to resolve it, and makes it easier for both changes to be reviewed.
So please split the change into one branch for the debug fixes, and a
branch for the timeout fixes, which may depend on the debug fix branch.
Thanks.

Unmerged revisions

437. By Vincent Ladeuil on 2014-11-14

Revert the controversial change.

436. By Vincent Ladeuil on 2014-11-14

Add test to cover bogus verify_timeout values handling.

435. By Vincent Ladeuil on 2014-11-13

Mark the bug as fixed

434. By Vincent Ladeuil on 2014-11-13

Protect tarmac from being killed with verify_command is killed.
Add a verify_timeout for long commands.
Drive-by fix command.config.debug not being set.

433. By Vincent Ladeuil on 2014-11-13

Add a test to exercise the timeout handling for very_command. This reveals that the test runner is terminated as part of the process group of the verify_command.

=== modified file 'tarmac/plugins/command.py'
--- tarmac/plugins/command.py	2013-10-30 22:24:25 +0000
+++ tarmac/plugins/command.py	2014-11-14 08:53:16 +0000
@@ -26,10 +26,10 @@
 tempfile = None
 time = None
 
-# The TIMEOUT setting (expressed in seconds) affects how long a test will run
-# before it is deemed to be hung, and then appropriately terminated.
-# It's principal use is preventing a job from hanging indefinitely and
-# backing up the queue.
+# The default TIMEOUT setting (expressed in seconds) affects how long a test
+# will run before it is deemed to be hung, and then appropriately terminated.
+# It's principal use is preventing a job from hanging indefinitely and backing
+# up the queue.
 # e.g. Usage: TIMEOUT = 60 * 15
 # This will set the timeout to 15 minutes.
 TIMEOUT = 60 * 15
@@ -57,7 +57,7 @@
     """
     Kill the process group leader identified by pid and other group members
 
-    The verify_command should set it's process to a process group leader.
+    The verify_command should set its process to a process group leader.
     """
     try:
         os.killpg(os.getpgid(pid), signal)
@@ -108,7 +108,11 @@
                per_file_timestamps=False)
         os.chdir(export_dest)
 
+        # We set a new progress group by default otherwise if the veify_command
+        # doesn't set one, *we* are killed when killem() is called.
         proc = subprocess.Popen(self.verify_command,
+                                # Ensure we don't get killed
+                                preexec_fn=os.setpgrp,
                                 shell=True,
                                 stdin=subprocess.PIPE,
                                 stdout=subprocess.PIPE,
@@ -121,8 +125,19 @@
         # stderr for too long.
         open_readers = set([proc.stdout, proc.stderr])
 
+        verify_timeout = self.get_config('verify_timeout', TIMEOUT, target)
+        try:
+            verify_timeout = int(verify_timeout)
+        except (ValueError, TypeError):
+            self.logger.warn('verify_timeout value is not an int: %r'
+                             % verify_timeout)
+            verify_timeout = TIMEOUT
+
+        debug = self.get_config('debug', False, command, target)
+
         while open_readers:
-            rlist, wlist, xlist = select.select(open_readers, [], [], TIMEOUT)
+            rlist, wlist, xlist = select.select(open_readers, [], [],
+                                                verify_timeout)
 
             if len(rlist) == 0:
                 if proc.poll() is not None:
@@ -130,7 +145,7 @@
 
                 self.logger.debug(
                     "Command appears to be hung. There has been no output for"
-                    " %d seconds. Sending SIGTERM." % TIMEOUT)
+                    " %d seconds. Sending SIGTERM." % verify_timeout)
                 killem(proc.pid, signal.SIGTERM)
                 time.sleep(5)
 
@@ -140,12 +155,12 @@
 
                 # Drain the subprocess's stdout and stderr.
                 out_rest = proc.stdout.read()
-                if command.config.debug:
+                if debug:
                     sys.stdout.write(out_rest)
                 stdout.write(out_rest)
 
                 err_rest = proc.stderr.read()
-                if command.config.debug:
+                if debug:
                     sys.stderr.write(err_rest)
                 stderr.write(err_rest)
                 break
@@ -155,16 +170,16 @@
                 if chunk == "":
                     open_readers.remove(proc.stdout)
                 else:
-                    if command.config.debug:
+                    if debug:
                         sys.stdout.write(chunk)
                     stdout.write(chunk)
-                    
+
             if proc.stderr in rlist:
                 chunk = os.read(proc.stderr.fileno(), 1024)
                 if chunk == "":
                     open_readers.remove(proc.stderr)
                 else:
-                    if command.config.debug:
+                    if debug:
                         sys.stderr.write(chunk)
                     stderr.write(chunk)
 

=== modified file 'tarmac/plugins/tests/test_command.py'
--- tarmac/plugins/tests/test_command.py	2013-10-31 19:09:08 +0000
+++ tarmac/plugins/tests/test_command.py	2014-11-14 08:53:16 +0000
@@ -60,6 +60,45 @@
                           proposal=self.proposal)
 
     @patch('tarmac.plugins.command.export')
+    def test_run_timeout_exceeded(self, mocked):
+        """Test that an exceeded timeout fails correctly."""
+        target = Thing(config=Thing(verify_command="/bin/sleep 10",
+                                    verify_timeout='1'),
+                       tree=Thing(abspath=os.path.abspath))
+        self.assertRaises(command.VerifyCommandFailed,
+                          self.plugin.run,
+                          command=self.command, target=target, source=None,
+                          proposal=self.proposal)
+
+    @patch('tarmac.plugins.command.export')
+    def test_run_bogus_timeout(self, mocked):
+        """Test that a bugs timeout is ignored.
+
+        Some strings cannot be converted to an int, a log warning is emitted
+        for feedback.
+        """
+        target = Thing(config=Thing(verify_command="/bin/true",
+                                    verify_timeout='forty two'),
+                       tree=Thing(abspath=os.path.abspath))
+        self.plugin.run(
+            command=self.command, target=target, source=None,
+            proposal=self.proposal)
+
+    @patch('tarmac.plugins.command.export')
+    def test_run_also_bogus_timeout(self, mocked):
+        """Test that a bugs timeout is ignored.
+
+        A random type cannot be converted to an int, a log warning is emitted
+        for feedback.
+        """
+        target = Thing(config=Thing(verify_command="/bin/true",
+                                    verify_timeout=object()),
+                       tree=Thing(abspath=os.path.abspath))
+        self.plugin.run(
+            command=self.command, target=target, source=None,
+            proposal=self.proposal)
+
+    @patch('tarmac.plugins.command.export')
     def test_run_exported_tree(self, mocked):
         """Test that the plug-in runs the command in an exported tree."""
         target = Thing(config=Thing(