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

[Javier Collado]

In this branch:
- url_argument adds temporary directories to be cleaned up later
- cleanup code has been moved to utah.cleanup module (needed by url_argument)
- Machine._runargs method has been moved to utah.process.Process runner (needed by cleanup)

Aside from this, I've changed the way cleanup is run. In particular, it no
longer relies on __del__ method since in my tests I had some problems like os
module not being available at cleanup time. Hence, I decided to use a simple
try/finally block in the run scripts which I find more readable because it's
explicit.

[Max Brustkern (nuclearbob)]

This reiterates to me the need to clean up the run scripts. It's causing everybody who's not me lots of extra work.

Should there be any exception handling associated with ProcessRunner? Even if ProcessRunner itself isn't handling exceptions, I think maybe the cleanup call should have it in a try block so that one failed process run won't spoil the whole cleanup process.

Maybe this is needless indirection, but would it make any sense to set Machine._runargs to ProcessRunner? Then, we don't have to change every instance of that, and, if for some unholy reason a Machine subclass wants to define its own ProcessRunner, it can? Since you've already done the hard part of replacing all the _runargs bits, maybe this is superfluous.

Also, I'd still like the Machine class to at least try to call cleanup when it's destroyed. Right now, it looks to me like the only time a Machine ever cleans up is when a run script specifically tells it to clean up. I think the Machine classes should be more self-sufficient than that, and I do sometimes use them directly. bootspeed also uses them directly right now (although we'd like that to go away eventually.) If we implemented this without adding explicit cleanup command to the bootspeed script, we'd start leaking resources. Maybe using atexit in the Cleanup class would work? I also wonder about what happens if we're trying to, in the future, for some weird reason, manage multiple Machines in the same script. Being able to clean them up separately might be nice, but it's not really strictly necessary. I think in that case, an atexit-based solution would be better than something in the Machine class destructor, unless we want each Machine object to have its own Cleanup object. That's also a possibility, but I'm not sure what we'd gain from it.

[Javier Collado (javier.collado)]

@Max

Thanks for your comments. Please find my answer to them below.

I don't think we should catch any exception in ProcessRunner unless we know we
want to handle any possible exception in the same way and that pretty much
depends on the command being executed, so that probably should be handled on a
case by case basis by the caller.

Regarding keeping a _runargs method in the Machine class, I'm not sure if
there's a use case for that. There's already a run method that is used only for
SSH commands, but I guess it can be expanded to terminal commands or whatever.
The way I see it, ProcessRunner is just a facility to execute commands locally
in the system where the server process is running, but it's not intended to
execute remote commands in the machine being provisioned.

Using atexit to register cleanup methods should work fine, it's just that I
like to see a explicit call in the code to keep in mind that that the cleanup
is actually happening. Anyway, I can give a try to that approach and see how it
works.

By the way, some other thing I'd like to do is review the documentation strings
before merging the changes.

[Max Brustkern (nuclearbob)]

I think the leaving exception handling out of ProcessRunner makes sense. I think the Cleanup class should handle exceptions generated by ProcessRunner. If some class registers a bad cleanup routine, that shouldn't stop other cleanup routines from running. I don't know if we just want to log that there's a problem, or try to catch exceptions and re-raise them at the end of the cleanup process, but we need some way for the process to not be completely stopped by a single problematic instruction.

I think an explicit cleanup call is a good thing to do, I just want to minimize things falling through the cracks when that isn't done. atexit can be a last resort.

I looked at the documentation strings and they seemed reasonable to me. We should probably add sphinx stuff to them at some point, but that's something we are doing as part of a separate effort, so if we don't do it now, we do at least have a plan for doing it later.

[lp:~javier.collado/utah/bug1101186]

860. By Javier Collado on 2013-03-28

Added atexit registration to run cleanup even if not called explicitly

Changes suggested by Max.

861. By Javier Collado on 2013-03-28

Capture and log command exceptions when running cleanup

862. By Javier Collado on 2013-03-28

Fixed cleanfunction wrapping

863. By Javier Collado on 2013-03-28

Added documentation for the cleanup module

864. By Javier Collado on 2013-03-28

Updated documentation for clean methods in Machine class

865. By Javier Collado on 2013-03-28

Added warning about cleanup singleton object

866. By Javier Collado on 2013-03-28

Updated documentation for the process module

[Javier Collado (javier.collado)]

@Max

I've updated the code following your advice:
- atexit used to run cleanup as a fallback.
- ProcessRunner exceptions caught and logged during cleanup to clean as much as
  possible (that was a good catch, thanks).

Aside from this, I've also updated the documentation.

review: Needs Resubmitting

[Max Brustkern (nuclearbob)]

Would it make any sense for line 222 to be in a finally clause? I guess if we're catching all exceptions there, then it doesn't need to be.

Good call on updating the rst file, I always forget to do that. We should include any other needed updates to that as part of the upcoming documentation changes that I'd like to look at next week (after I've sorted out all the code review things related to that that we raised.)

Finally, some of the whitespace around the docstrings (lines 384 and 386) looks weird to me, but I haven't read PEP 257 very well, so if that's explained there, then I'll know about it shortly.

review: Approve

[Andy Doan (doanac)]

Additional comments:

ProcessRunner feels funny defined as a class with just an __init__, but I like how you now have explicit things like .returncode rather than ['returncode']. So no real objection - just found it interesting.

Cleanup._clean_dir: can we remove the self.logger.warning call about the permissions? It seems to make the end of our log files nearly unreadable and things still work properly.

Cleanup._clean_dir: Do we really have to traverse the tree to make sure everything is writeable in order to safely call shutil.rmtree? If so, subprocess.check_call(['rm', '-r', '-f', dir]) is looking a lot more desirable to me.

Given cleanup.py now has an atexit, is there any real gain by updating all the run scripts? I feel like we are exposing too much internal details with such a high level API. Another cheap way might be just to handle clean up in the _runtests function in run.py.

[Max Brustkern (nuclearbob)]

> Additional comments:
>
> ProcessRunner feels funny defined as a class with just an __init__, but I like
> how you now have explicit things like .returncode rather than ['returncode'].
> So no real objection - just found it interesting.
>
> Cleanup._clean_dir: can we remove the self.logger.warning call about the
> permissions? It seems to make the end of our log files nearly unreadable and
> things still work properly.
Maybe this should be debug instead of warning? Or we could drop it, I guess nobody's looking at that warning and taking appropriate action.
>
> Cleanup._clean_dir: Do we really have to traverse the tree to make sure
> everything is writeable in order to safely call shutil.rmtree? If so,
> subprocess.check_call(['rm', '-r', '-f', dir]) is looking a lot more desirable
> to me.
We've had a general trend of moving away from shelling out whenever possible, but in this case, that implementation may be more trouble than it's worth. It predates this, though, so any problems with it are my fault and not Javier's.
>
> Given cleanup.py now has an atexit, is there any real gain by updating all the
> run scripts? I feel like we are exposing too much internal details with such a
> high level API. Another cheap way might be just to handle clean up in the
> _runtests function in run.py.
As Javier pointed at before, some testing indicated problems with os availability during atexit. I think we should raise the priority of run_ script consolidation so we don't have to keep going through this.

[Andy Doan (doanac)]

On 03/28/2013 02:34 PM, Max Brustkern wrote:
>> Cleanup._clean_dir: can we remove the self.logger.warning call about the
>> permissions? It seems to make the end of our log files nearly unreadable and
>> things still work properly.
> Maybe this should be debug instead of warning? Or we could drop it, I guess nobody's looking at that warning and taking appropriate action.

I thought about changing to debug, but I run with debug enabled so much
it still drives me nuts. But maybe that's a better compromise. I'll let
Javier choose since its his MP and he's been around longer - no big deal
to me either way.

>> Cleanup._clean_dir: Do we really have to traverse the tree to make sure
>> everything is writeable in order to safely call shutil.rmtree? If so,
>> subprocess.check_call(['rm', '-r', '-f', dir]) is looking a lot more desirable
>> to me.
> We've had a general trend of moving away from shelling out whenever possible, but in this case, that implementation may be more trouble than it's worth. It predates this, though, so any problems with it are my fault and not Javier's.

Yeah, I hate shelling out. Do we know for a fact/why you must change the
permissions? I just set up a dummy test locally with read-only files and
shutil.rmtree still worked.

>> Given cleanup.py now has an atexit, is there any real gain by updating all the
>> run scripts? I feel like we are exposing too much internal details with such a
>> high level API. Another cheap way might be just to handle clean up in the
>> _runtests function in run.py.
> As Javier pointed at before, some testing indicated problems with os availability during atexit. I think we should raise the priority of run_ script consolidation so we don't have to keep going through this.

yes - sorry I forgot.

+1 on the run_script fixes.

[Max Brustkern (nuclearbob)]

On 03/28/2013 03:40 PM, Andy Doan wrote:
> On 03/28/2013 02:34 PM, Max Brustkern wrote:
> ...
>>> Cleanup._clean_dir: Do we really have to traverse the tree to make sure
>>> everything is writeable in order to safely call shutil.rmtree? If so,
>>> subprocess.check_call(['rm', '-r', '-f', dir]) is looking a lot more
>>> desirable
>>> to me.
>> We've had a general trend of moving away from shelling out whenever
>> possible, but in this case, that implementation may be more trouble
>> than it's worth. It predates this, though, so any problems with it
>> are my fault and not Javier's.
>
> Yeah, I hate shelling out. Do we know for a fact/why you must change
> the permissions? I just set up a dummy test locally with read-only
> files and shutil.rmtree still worked.
>
I thought that I had had problems with that before, but if it seems to
work okay now, maybe I was wrong, and we can just use rmtree

[Andy Doan (doanac)]

On 03/28/2013 02:44 PM, Max Brustkern wrote:
> On 03/28/2013 03:40 PM, Andy Doan wrote:
>> On 03/28/2013 02:34 PM, Max Brustkern wrote:
> I thought that I had had problems with that before, but if it seems to
> work okay now, maybe I was wrong, and we can just use rmtree

hmm - i don't want to distract too much from Javier's intent here. I'll
leave it up to him to decide if he want to do that in this change or
just land this and let us re-visit later.

[lp:~javier.collado/utah/bug1101186]

867. By Javier Collado on 2013-03-29

Moved clean command code to its own method.

Command removed in finally block. Not really needed, but better in terms of
readability.

868. By Javier Collado on 2013-03-29

Added note to make clear that process is launched right away

869. By Javier Collado on 2013-03-29

Removed log message that turned out to be too verbose

[Javier Collado (javier.collado)]

Some comments:
- I like the comment about the finally clause. It's not needed, but it improves
  readability, so I've done that (and moved the code to a separate method).

- What is bothering me isn't the warning message, but the debug message for
  each file whose permissions are changed because there are a lot of them in
  the image directory. I've removed that and what I get now is the old output
  that ends with the location where the yaml file has been downloaded. I think
  we can go with this and check if there are so many warnings in the lab.

  Anyway, if for some reason those messages are needed and we don't want them
  in the debug output, then we can create a new log level name that is lower
  than debug, but is only written to the log file.

- The problems I got during cleanup were when relying on __del__, not on
  atexit. Anyway, it doesn't make any harm to run cleanup twice, so I'd prefer
  to keep the try/finally block as it's now.

- I've added a note in the ProcessRunner documentation to make clear that the
  command is executed immediately.

- I don't know PEP257 by heart, but I trust pep257
  (https://pypi.python.org/pypi/pep257/) which includes the nice -e/--explain
  option to print the paragraph from PEP257 that is being violated. For the
  whitespace around docstrings, what you'd get would something as follows:

================================================================================
Note: checks are relaxed for scripts (with #!) compared to modules.
process.py:24:4: PEP257 Class docstring should have 1 blank line around them.
PEP257 Class docstring should have 1 blank line around them.

    Insert a blank line before and after all docstrings (one-line or
    multi-line) that document a class -- generally speaking, the class's
    methods are separated from each other by a single blank line, and the
    docstring needs to be offset from the first method by a blank line;
    for symmetry, put a blank line between the class header and the
    docstring.

[Javier Collado (javier.collado)]

Maybe this wasn't clear from my previous message, but note that when I write
PEP257 I talk about the pep itself (http://www.python.org/dev/peps/pep-0257/)
and when I write pep257 I refer to the command line tool
(https://pypi.python.org/pypi/pep257/).

[Max Brustkern (nuclearbob)]

> Maybe this wasn't clear from my previous message, but note that when I write
> PEP257 I talk about the pep itself (http://www.python.org/dev/peps/pep-0257/)
> and when I write pep257 I refer to the command line tool
> (https://pypi.python.org/pypi/pep257/).

That was clear to me. In any case, I think this looks good.

review: Approve

[Andy Doan (doanac)]

+1 - this branch has some things I've been wanting or a long time :)

review: Approve

=== modified file 'debian/changelog'
--- debian/changelog	2013-03-28 03:45:47 +0000
+++ debian/changelog	2013-03-29 09:03:24 +0000
@@ -1,6 +1,7 @@
 utah (0.10ubuntu1) UNRELEASED; urgency=low
 
   * Return error code on unhandled error (LP: #1160857)
+  * Remove temporary files downloaded based on URL (LP: #1101186)
 
  -- Javier Collado <[e-mail]>  Wed, 27 Mar 2013 13:00:47 +0100
 

=== modified file 'debian/control'
--- debian/control	2013-02-26 08:12:33 +0000
+++ debian/control	2013-03-29 09:03:24 +0000
@@ -49,7 +49,7 @@
 Package: utah-client
 Architecture: all
 Depends: ${misc:Depends}, ${python:Depends},
-         bzr, python-jsonschema (>= 0.5~), python-yaml, utah-common
+         bzr, python-jsonschema (>= 0.5~), python-psutil, python-yaml, utah-common
 Recommends: git
 Description: Ubuntu Test Automation Harness Client
  Automation framework for testing in Ubuntu, client portion

=== modified file 'docs/source/reference.rst'
--- docs/source/reference.rst	2013-02-27 09:05:41 +0000
+++ docs/source/reference.rst	2013-03-29 09:03:24 +0000
@@ -7,6 +7,12 @@
 
 .. automodule:: utah
 
+``utah.cleanup``
+----------------
+
+.. automodule:: utah.cleanup
+   :members: _Cleanup, cleanup
+
 .. automodule:: utah.commandstr
    :members:
 
@@ -35,6 +41,9 @@
    :members:
    :member-order: bysource
 
+``utah.process``
+----------------
+
 .. automodule:: utah.process
    :members:
 

=== modified file 'examples/run_install_test.py'
--- examples/run_install_test.py	2013-03-27 11:57:11 +0000
+++ examples/run_install_test.py	2013-03-29 09:03:24 +0000
@@ -19,6 +19,7 @@
 import logging
 import sys
 
+from utah.cleanup import cleanup
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
 from utah.provisioning.vm.vm import CustomVM, TinySQLiteInventory
@@ -106,4 +107,7 @@
 
 
 if __name__ == '__main__':
-    run_install_test()
+    try:
+        run_install_test()
+    finally:
+        cleanup.run()

=== modified file 'examples/run_test_bamboo_feeder.py'
--- examples/run_test_bamboo_feeder.py	2013-03-27 11:57:11 +0000
+++ examples/run_test_bamboo_feeder.py	2013-03-29 09:03:24 +0000
@@ -20,6 +20,7 @@
 import sys
 import logging
 
+from utah.cleanup import cleanup
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
 from utah.provisioning.baremetal.bamboofeeder import BambooFeederMachine
@@ -106,4 +107,7 @@
 
 
 if __name__ == '__main__':
-    run_test_bamboo_feeder()
+    try:
+        run_test_bamboo_feeder()
+    finally:
+        cleanup.run()

=== modified file 'examples/run_test_cobbler.py'
--- examples/run_test_cobbler.py	2013-03-27 11:57:11 +0000
+++ examples/run_test_cobbler.py	2013-03-29 09:03:24 +0000
@@ -19,6 +19,7 @@
 import sys
 import logging
 
+from utah.cleanup import cleanup
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
 from utah.provisioning.baremetal.cobbler import CobblerMachine
@@ -111,4 +112,7 @@
 
 
 if __name__ == '__main__':
-    run_test_cobbler()
+    try:
+        run_test_cobbler()
+    finally:
+        cleanup.run()

=== modified file 'examples/run_test_vm.py'
--- examples/run_test_vm.py	2013-03-27 11:57:11 +0000
+++ examples/run_test_vm.py	2013-03-29 09:03:24 +0000
@@ -19,6 +19,7 @@
 import logging
 import sys
 
+from utah.cleanup import cleanup
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
 from utah.provisioning.vm.vm import TinySQLiteInventory
@@ -100,4 +101,7 @@
 
 
 if __name__ == '__main__':
-    run_test_vm()
+    try:
+        run_test_vm()
+    finally:
+        cleanup.run()

=== modified file 'examples/run_utah_tests.py'
--- examples/run_utah_tests.py	2013-03-27 11:57:11 +0000
+++ examples/run_utah_tests.py	2013-03-29 09:03:24 +0000
@@ -20,6 +20,7 @@
 import sys
 
 from utah import config
+from utah.cleanup import cleanup
 from utah.group import check_user_group, print_group_error_message
 from utah.run import (
     common_arguments,
@@ -131,3 +132,5 @@
             run_utah_tests()
     except AttributeError:
         run_utah_tests()
+    finally:
+        cleanup.run()

=== added file 'utah/cleanup.py'
--- utah/cleanup.py	1970-01-01 00:00:00 +0000
+++ utah/cleanup.py	2013-03-29 09:03:24 +0000
@@ -0,0 +1,210 @@
+# Ubuntu Testing Automation Harness
+# Copyright 2012 Canonical Ltd.
+
+# This program is free software: you can redistribute it and/or modify it
+# under the terms of the GNU General Public License version 3, as published
+# by the Free Software Foundation.
+
+# This program is distributed in the hope that it will be useful, but
+# WITHOUT ANY WARRANTY; without even the implied warranties of
+# MERCHANTABILITY, SATISFACTORY QUALITY, or FITNESS FOR A PARTICULAR
+# PURPOSE.  See the GNU General Public License for more details.
+
+# You should have received a copy of the GNU General Public License along
+# with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+"""Generic functionality to execute callbacks on exit."""
+
+import atexit
+import logging
+import os
+import shutil
+import traceback
+
+from utah.commandstr import commandstr
+from utah.orderedcollections import (
+    HashableDict,
+    OrderedSet,
+)
+from utah.process import ProcessRunner
+import utah.timeout
+
+
+class _Cleanup(object):
+
+    """Cleanup allocated resources on exit.
+
+    .. warning::
+        This is private class not expected to be instanciated
+        please use :attr:`utah.cleanup.cleanup` singleton
+        object to call any of the methods documented below.
+
+    """
+
+    def __init__(self):
+        self.paths = OrderedSet()
+        self.functions = OrderedSet()
+        self.commands = OrderedSet()
+        self.logger = logging.getLogger('cleanup')
+
+    def run(self):
+        """Run cleanup for the resources that have been allocated."""
+        self.logger.debug('Running cleanup')
+        for function in self.functions:
+            self._clean_function(function)
+        for command in self.commands:
+            self._clean_command(command)
+        for path in self.paths:
+            self._clean_path(path)
+
+    def _clean_function(self, function):
+        """Run clean function.
+
+        :param function:
+            Data needed to run the clean function: timeout, callable,
+            positional arguments and keyword arguments.
+        :type function: tuple
+
+        """
+        timeout, command, args, kw = function
+        self.logger.debug('Running: ' +
+                          commandstr(command, *args, **kw))
+        try:
+            utah.timeout.timeout(timeout, command, *args, **kw)
+        except Exception as err:
+            self.logger.warning(
+                'Exception while running cleanup function: {}'
+                .format(str(err)))
+        self.functions.remove(function)
+
+    def _clean_command(self, command):
+        """Run clean command.
+
+        :param command: A command as would be passed to `subprocess.Popen`
+        :type command: iterable
+
+        """
+        # All exceptions are captured and logged to make sure the cleanup
+        # process is completed as much as possible
+        try:
+            ProcessRunner(command)
+        except:
+            self.logger.error('Cleanup error: {}'
+                              .format(traceback.format_exc()))
+        finally:
+            self.commands.remove(command)
+
+    def _clean_path(self, path):
+        """Clean path.
+
+        :param path: Path to a link, file or directory.
+        :type path: str
+
+        """
+        if os.path.islink(path):
+            self.logger.debug('Removing link ' + path)
+            os.unlink(path)
+        elif os.path.isfile(path):
+            self._clean_file(path)
+        elif os.path.isdir(path):
+            self._clean_dir(path)
+        else:
+            self.logger.debug(
+                '{} is not a link, file, or directory; not removing'
+                .format(path))
+        self.paths.remove(path)
+
+    def _clean_file(self, path):
+        """Clean file.
+
+        :param path: Path to a file.
+        :type path: str
+
+        """
+        self.logger.debug('Changing permissions of ' + path)
+        try:
+            os.chmod(path, 0664)
+        except OSError as err:
+            self.logger.warning(
+                'OSError when changing file permissions: {}'
+                .format(str(err)))
+        self.logger.debug('Removing file ' + path)
+        try:
+            os.unlink(path)
+        except OSError as err:
+            self.logger.warning('OSError when removing file: {}'
+                                .format(str(err)))
+
+    def _clean_dir(self, path):
+        """Clean directory.
+
+        :param path: Path to a directory.
+        :type paty: str
+
+        """
+        # Cribbed from http://svn.python.org
+        # /projects/python/trunk/Mac/BuildScript/build-installer.py
+        for dirpath, dirnames, filenames in os.walk(path):
+            for name in (dirnames + filenames):
+                absolute_name = os.path.join(dirpath, name)
+                if not os.path.islink(absolute_name):
+                    try:
+                        os.chmod(absolute_name, 0775)
+                    except OSError as err:
+                        self.logger.warning(
+                            'OSError when changing directory permissions: {}'
+                            .format(str(err)))
+        self.logger.debug('Recursively Removing directory {}'.format(path))
+        try:
+            shutil.rmtree(path)
+        except OSError as err:
+            self.logger.warning('OSError when removing directory: {}'
+                                .format(str(err)))
+
+    def add_path(self, path):
+        """Register a path to be cleaned later.
+
+        The way to clean different paths is as follows:
+            - Links will be unlinked.
+            - Files will have permissions changed to 664 and unlinked.
+            - Directories will recursively have permissions changed to 775
+              (except for links contained within) and then be recursively
+              removed.
+
+        :param path: A link, file, or directory to be cleaned later.
+        :type path: str
+
+        """
+        self.paths.add(path)
+
+    def add_function(self, timeout, function, *args, **kw):
+        """Register a function to be run on cleanup.
+
+        The function will be run through :func:`utah.timeout.timeout`.
+
+        :param timeout: Timeout in seconds for the function to return a result.
+        :type timeout: int
+        :param function: A callable that will do some cleanup.
+        :type function: callable
+        :param args: Positional arguments to the function.
+        :type args: Tuple
+        :param kw: Keyword arguments to the function.
+        :type args: dict
+
+        """
+        self.functions.add((timeout, function, args, HashableDict(kw)))
+
+    def add_command(self, cmd):
+        """Register a command to be run on cleanup.
+
+        :param cmd: A command as would be passed `subprocess.Popen`.
+        :type cmd: iterable
+
+        """
+        self.commands.add(cmd)
+
+#: Singleton object used to cleanup everything
+cleanup = _Cleanup()
+
+# Make sure cleanup is executed even if it's not explicitly called
+atexit.register(cleanup.run)

=== modified file 'utah/process.py'
--- utah/process.py	2012-12-08 02:10:12 +0000
+++ utah/process.py	2013-03-29 09:03:24 +0000
@@ -13,16 +13,17 @@
 # You should have received a copy of the GNU General Public License along
 # with this program.  If not, see <http://www.gnu.org/licenses/>.
 
-"""
-Process checking utilities
-"""
+"""Process related utilities."""
+import logging
+import subprocess
+
 import psutil
 
 
 class ProcessChecker(object):
-    """
-    Check all running process looking for a given pattern
-    """
+
+    """Check all running process looking for a given pattern."""
+
     MESSAGE_TEMPLATE = (
         "{app} application is running.\n"
         "Please stop it before launching utah since "
@@ -30,8 +31,17 @@
         "(Kernel-based Virtual Machine)\n")
 
     def check_cmdline(self, pattern):
-        """
-        Check if the command line of any process matches the given pattern
+        """Check if the command line of any process matches the given pattern.
+
+        :param pattern:
+            A fragment of the string that should be included in the command
+            line.
+        :type pattern: str
+        :returns:
+            Whether there's a process command line that matches the given
+            pattern.
+        :rtype: bool
+
         """
         pids = psutil.get_pid_list()
         cmdlines = []
@@ -43,7 +53,42 @@
         return any(pattern in cmdline for cmdline in cmdlines)
 
     def get_error_message(self, app):
-        """
-        Return error message for an incompatible application process running
-        """
+        """Return error message for an incompatible application running."""
         return self.MESSAGE_TEMPLATE.format(app=app)
+
+
+class ProcessRunner(object):
+
+    """Run a command in a subprocess and log output properly.
+
+    :param arglist: Argument list as would be passsed to `subprocess.Popen`
+    :type arglist: list
+
+    :attribute output: Command output (both stdout and stderr)
+    :attribute returncode: Command return code
+
+    .. note::
+        Process is launched when object is instantiated, there isn't any
+        separate `run` method.
+
+    """
+
+    def __init__(self, arglist):
+        logging.debug('Running command: ' + ' '.join(arglist))
+        logging.debug('Output follows:')
+        p = subprocess.Popen(arglist,
+                             stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        output = []
+        while p.poll() is None:
+            line = p.stdout.readline().strip()
+            logging.debug(line)
+            output.append(line)
+
+        if p.returncode == 0:
+            logging.debug('Return code: {}'.format(p.returncode))
+        else:
+            logging.warning('Command ({}) failed with return code: {}'
+                            .format(' '.join(arglist), p.returncode))
+
+        self.output = '\n'.join(output)
+        self.returncode = p.returncode

=== modified file 'utah/provisioning/baremetal/bamboofeeder.py'
--- utah/provisioning/baremetal/bamboofeeder.py	2013-03-18 14:35:14 +0000
+++ utah/provisioning/baremetal/bamboofeeder.py	2013-03-29 09:03:24 +0000
@@ -24,6 +24,7 @@
 import tempfile
 
 from utah import config
+from utah.process import ProcessRunner
 from utah.provisioning.baremetal.exceptions import UTAHBMProvisioningException
 from utah.provisioning.baremetal.power import PowerMixin
 from utah.provisioning.provisioning import (
@@ -105,7 +106,7 @@
         self.cleanfunction(self._umountimage)
         self.logger.debug('Mounting ' + self.wwwimage + ' at ' +
                           self.imagedir)
-        self._runargs(['sudo', 'mount', self.wwwimage, self.imagedir,
+        ProcessRunner(['sudo', 'mount', self.wwwimage, self.imagedir,
                        '-o', 'loop', '-o', 'offset=' + str(self.sector * 512),
                        '-o', 'uid=' + config.user])
 
@@ -168,7 +169,7 @@
             raise UTAHBMProvisioningException(
                 'Unpacking initrd exited with status: {}'.format(exitstatus))
         self.logger.debug('Creating uInitrd with mkimage')
-        self._runargs(['mkimage',
+        ProcessRunner(['mkimage',
                        '-A', 'arm',
                        '-O', 'linux',
                        '-T', 'ramdisk',
@@ -184,7 +185,7 @@
         Unmount the image after we're done with it."
         """
         self.logger.info('Unmounting image')
-        self._runargs(['sudo', 'umount', self.imagedir])
+        ProcessRunner(['sudo', 'umount', self.imagedir])
 
     def _cmdlinesetup(self, boot=None):
         """
@@ -238,7 +239,7 @@
                                '01-' + self.macaddress.replace(':', '-'))
         self.cleancommand(('sudo', 'rm', '-f', pxefile))
         self.logger.debug('Copying ' + tmppxefile + ' to ' + pxefile)
-        self._runargs(['sudo', 'cp', tmppxefile, pxefile])
+        ProcessRunner(['sudo', 'cp', tmppxefile, pxefile])
         preenvfile = os.path.join(config.wwwdir, self.name + '.preEnv')
         # TODO: sort this out with self.boot
         # figure out which one should be what and customizable
@@ -307,5 +308,5 @@
         """
         super(BambooFeederMachine, self)._depcheck()
         cmd = ['which', 'mkimage']
-        if self._runargs(cmd)['returncode'] != 0:
+        if ProcessRunner(cmd).returncode != 0:
             raise UTAHBMProvisioningException('u-boot-tools not installed')

=== modified file 'utah/provisioning/baremetal/cobbler.py'
--- utah/provisioning/baremetal/cobbler.py	2013-03-28 03:45:47 +0000
+++ utah/provisioning/baremetal/cobbler.py	2013-03-29 09:03:24 +0000
@@ -23,6 +23,7 @@
 import tempfile
 
 from utah import config
+from utah.process import ProcessRunner
 from utah.provisioning.baremetal.exceptions import UTAHBMProvisioningException
 from utah.provisioning.baremetal.power import PowerMixin
 from utah.provisioning.provisioning import (
@@ -102,10 +103,10 @@
             self.cleanfunction(self._removenfs)
             os.makedirs(self.isodir, mode=0775)
             self.logger.debug('Mounting ISO')
-            result = self._runargs(['sudo', 'mount', '-o', 'loop',
+            result = ProcessRunner(['sudo', 'mount', '-o', 'loop',
                                     self.image.image,
                                     self.isodir])
-            returncode = result['returncode']
+            returncode = result.returncode
             if returncode != 0:
                 raise UTAHBMProvisioningException(
                     'Mount failed with return code: {} Output: {}'
@@ -170,7 +171,7 @@
                 raise UTAHBMProvisioningException(
                     'Failed to setup NFS: {}'.format(err))
             self.logger.debug('Reloading NFS config')
-            self._runargs(config.nfscommand + ['reload'])
+            ProcessRunner(config.nfscommand + ['reload'])
             self.logger.debug('Adding NFS boot options')
             ip = self._ipaddr(config.nfsiface)
             self.cmdline += (' root=/dev/nfs netboot=nfs nfsroot=' +
@@ -227,7 +228,7 @@
             tail_process = subprocess.Popen(
                 ['tail', '-n0', '-f', '/var/log/cobbler/cobbler.log'],
                 stdout=subprocess.PIPE)
-            command_results = self._runargs(['sudo', 'cobbler'] + cmd)
+            command_results = ProcessRunner(['sudo', 'cobbler'] + cmd)
             retcode = command_results['returncode']
             if retcode != 0:
                 error_msg = 'Cobbler command failed: ' + ' '.join(cmd)
@@ -259,7 +260,7 @@
         if retcode != 0:
             self.logger.info('Cobbler power command failed; falling back to '
                              'manual command')
-            self._runargs(self.powercommand() + ['on'])
+            ProcessRunner(self.powercommand() + ['on'])
         self.active = True
 
     def stop(self):
@@ -273,7 +274,7 @@
         if retcode != 0:
             self.logger.info('Cobbler power command failed; falling back to '
                              'manual command')
-            self._runargs(self.powercommand() + ['off'])
+            ProcessRunner(self.powercommand() + ['off'])
         self.active = False
 
     def _removenfs(self):
@@ -282,12 +283,12 @@
         """
         if self.isodir is not None:
             self.logger.info('Removing NFS share')
-            self._runargs(['sudo', 'sed', '/' + self.isodir.replace('/', '\/')
+            ProcessRunner(['sudo', 'sed', '/' + self.isodir.replace('/', '\/')
                            + '/d', '-i', config.nfsconfigfile])
             self.logger.debug('Reloading NFS config')
-            self._runargs(config.nfscommand + ['reload'])
+            ProcessRunner(config.nfscommand + ['reload'])
             self.logger.info('Unmounting ISO')
-            self._runargs(['sudo', 'umount', self.isodir])
+            ProcessRunner(['sudo', 'umount', self.isodir])
             self.logger.debug('Removing directory')
             os.rmdir(self.isodir)
             self.isodir = None
@@ -299,7 +300,7 @@
         super(CobblerMachine, self)._depcheck()
         if self.installtype in ['alternate', 'desktop', 'server']:
             cmd = config.nfscommand + ['status']
-            if self._runargs(cmd)['returncode'] != 0:
+            if ProcessRunner(cmd).returncode != 0:
                 raise UTAHBMProvisioningException(
                     'NFS needed for {} install'.format(self.installtype))
             if not os.path.isfile(config.nfsconfigfile):

=== modified file 'utah/provisioning/baremetal/power.py'
--- utah/provisioning/baremetal/power.py	2012-12-11 09:37:12 +0000
+++ utah/provisioning/baremetal/power.py	2013-03-29 09:03:24 +0000
@@ -21,6 +21,7 @@
 import time
 
 from utah import config
+from utah.process import ProcessRunner
 from utah.provisioning.baremetal.exceptions import UTAHBMProvisioningException
 
 
@@ -70,14 +71,14 @@
         Use the machine's powercommand to start the machine.
         """
         self.logger.debug('Starting system')
-        self._runargs(self.powercommand() + ['on'])
+        ProcessRunner(self.powercommand() + ['on'])
 
     def stop(self):
         """
         Use the machine's powercommand to stop the machine.
         """
         self.logger.debug('Stopping system')
-        self._runargs(self.powercommand() + ['off'])
+        ProcessRunner(self.powercommand() + ['off'])
 
     def restart(self):
         """

=== modified file 'utah/provisioning/provisioning.py'
--- utah/provisioning/provisioning.py	2013-03-18 14:35:14 +0000
+++ utah/provisioning/provisioning.py	2013-03-29 09:03:24 +0000
@@ -38,12 +38,9 @@
 import utah.timeout
 
 from utah import config
-from utah.commandstr import commandstr
+from utah.cleanup import cleanup
+from utah.process import ProcessRunner
 from utah.iso import ISO
-from utah.orderedcollections import (
-    HashableDict,
-    OrderedSet,
-)
 from utah.preseed import Preseed
 from utah.provisioning.rsyslog import RSyslog
 from utah.provisioning.exceptions import UTAHProvisioningException
@@ -128,10 +125,6 @@
         else:
             self.clean = clean
 
-        self.cleanfiles = OrderedSet()
-        self.cleanfunctions = OrderedSet()
-        self.cleancommands = OrderedSet()
-
         self._namesetup(name)
         self._dirsetup(directory)
 
@@ -317,7 +310,7 @@
         """
         self.logger.info('Checking network connectivity (ping)')
         returncode = \
-            self._runargs(['ping', '-c1', '-w5', self.name])['returncode']
+            ProcessRunner(['ping', '-c1', '-w5', self.name]).returncode
         if returncode != 0:
             err = 'Ping returned {0}'.format(returncode)
             raise UTAHProvisioningException(err, retry=True)
@@ -446,8 +439,6 @@
         Destroying the install on a physical machine is optional.
         """
         self.provisioned = False
-        self.__del__()
-        del self
         return True
 
     def _load(self):
@@ -582,106 +573,45 @@
             .format(cls=self.__class__.__name__,
                     method=method))
 
-    def cleanup(self):
-        """
-        Clean up temporary files and tear down other setup (VM, etc.).
-        If a subset is specified, only that subset will be cleaned.
-        This can be used to clean up install files after the install has
-        started.
-        Files are removed first.
-        Functions are run second.
-        Commands are run third.
-        """
-        if self.clean:
-            self.logger.debug('Running cleanup')
-            for function in self.cleanfunctions:
-                timeout, command, args, kw = function
-                self.logger.debug('Running: ' +
-                                  commandstr(command, *args, **kw))
-                try:
-                    utah.timeout.timeout(timeout, command, *args, **kw)
-                except Exception as err:
-                    self.logger.warning('Exception while running cleanup '
-                                        'function: {}'.format(str(err)))
-                self.cleanfunctions.remove(function)
-            for command in self.cleancommands:
-                self._runargs(command)
-                self.cleancommands.remove(command)
-            for path in self.cleanfiles:
-                if os.path.islink(path):
-                    self.logger.debug('Removing link ' + path)
-                    os.unlink(path)
-                elif os.path.isfile(path):
-                    self.logger.debug('Changing permissions of ' + path)
-                    try:
-                        os.chmod(path, 0664)
-                    except OSError as err:
-                        self.logger.warning('OSError when changing file '
-                                            'permissions: {}'
-                                            .format(str(err)))
-                    self.logger.debug('Removing file ' + path)
-                    try:
-                        os.unlink(path)
-                    except OSError as err:
-                        self.logger.warning('OSError when removing file: {}'
-                                            .format(str(err)))
-                elif os.path.isdir(path):
-                # Cribbed from http://svn.python.org
-                # /projects/python/trunk/Mac/BuildScript/build-installer.py
-                    for dirpath, dirnames, filenames in os.walk(path):
-                        for name in (dirnames + filenames):
-                            absolute_name = os.path.join(dirpath, name)
-                            if not os.path.islink(absolute_name):
-                                self.logger.debug('Changing permissions of '
-                                                  + absolute_name)
-                                try:
-                                    os.chmod(absolute_name, 0775)
-                                except OSError as err:
-                                    self.logger.warning(
-                                        'OSError when '
-                                        'changing directory permissions: {}'
-                                        .format(str(err)))
-                    self.logger.debug('Recursively Removing directory '
-                                      + path)
-                    try:
-                        shutil.rmtree(path)
-                    except OSError as err:
-                        self.logger.warning('OSError when removing '
-                                            'directory: {}'
-                                            .format(str(err)))
-                else:
-                    self.logger.debug(path + ' is not a link, file, or '
-                                      'directory; not removing')
-                self.cleanfiles.remove(path)
-        else:
-            self.logger.debug('Not cleaning up')
-
     def cleanfile(self, path):
-        """
-        Register a link, file, or directory to be cleaned later.
-        Links will be unlinked.
-        Files will have permissions changed to 664 and unlinked.
-        Directories will recursively have permissions changed to 775 (except
-        for links contained within) and then be recursively removed.
-        """
-        self.cleanfiles.add(path)
+        """Register a path to be cleaned later.
+
+        :param path: A link, file, or directory to be cleaned later.
+        :type path: str
+
+        .. seealso:: :meth:`utah.cleanup._Cleanup.add_path`
+
+        """
+        if self.clean:
+            cleanup.add_path(path)
 
     def cleanfunction(self, function, *args, **kw):
-        """
-        Register a function to be run on cleanup.
-        Functions are run through utah.timeout.timeout.
-        """
-        self.cleanfunctions.add((60, function, args, HashableDict(kw)))
+        """Register a function to be run on cleanup.
+
+        :param function: A callable that will do some cleanup.
+        :type function: callable
+        :param args: Positional arguments to the function.
+        :type args: Tuple
+        :param kw: Keyword arguments to the function.
+        :type args: dict
+
+        .. seealso:: :meth:`utah.cleanup._Cleanup.add_function`
+
+        """
+        if self.clean:
+            cleanup.add_function(60, function, args, kw)
 
     def cleancommand(self, cmd):
-        """
-        Register a command to be run on cleanup.
-        Commands are run through Machine._runargs.
-        """
-        self.cleancommands.add(cmd)
-
-    def __del__(self):
-        self.cleanup()
+        """Register a command to be run on cleanup.
+
+        :param cmd: A command as would be passed `subprocess.Popen`.
+        :type cmd: iterable
+
+        .. seealso:: :meth:`utah.cleanup._Cleanup.add_command`
+
+        """
+        if self.clean:
+            cleanup.add_command(cmd)
 
     def _uuid_check(self):
         uuid_check_command = ('[ "{uuid}" == "$(cat /etc/utah/uuid)" ]'
@@ -956,12 +886,12 @@
         os.chmod(filename, 0755)
 
         orderfilename = os.path.join(casper_dir, 'ORDER')
-        exitstatus = self._runargs(
+        exitstatus = ProcessRunner(
             ['sed', '-i',
              '1i/scripts/casper-bottom/'
              'utah\\n'
              '[ -e /conf/param.conf ] && . /conf/param.conf',
-             orderfilename])['returncode']
+             orderfilename]).returncode
         if exitstatus != 0:
             raise UTAHProvisioningException('Failed to setup casper script')
 

=== modified file 'utah/provisioning/vm/vm.py'
--- utah/provisioning/vm/vm.py	2013-03-05 21:03:40 +0000
+++ utah/provisioning/vm/vm.py	2013-03-29 09:03:24 +0000
@@ -28,7 +28,7 @@
 from xml.etree import ElementTree
 
 from utah import config
-from utah.process import ProcessChecker
+from utah.process import ProcessChecker, ProcessRunner
 from utah.provisioning.inventory.sqlite import SQLiteInventory
 from utah.provisioning.provisioning import CustomInstallMixin, Machine
 from utah.provisioning.rsyslog import RSyslog
@@ -266,7 +266,7 @@
                 cmd = ['qemu-img', 'create', '-f', 'qcow2', diskfile, disksize]
                 self.logger.debug('Creating ' + disksize + ' disk using:')
                 self.logger.debug(' '.join(cmd))
-                if self._runargs(cmd)['returncode'] != 0:
+                if ProcessRunner(cmd).returncode != 0:
                     raise UTAHVMProvisioningException(
                         'Could not create disk image at ' + diskfile)
             disk = {'bus': self.diskbus,
@@ -500,6 +500,7 @@
         self.logger.info('Creating custom virtual machine')
 
         tmpdir = tempfile.mkdtemp(prefix='/tmp/' + self.name + '_')
+        self.cleanfile(tmpdir)
         self.logger.debug('Working dir: ' + tmpdir)
         os.chdir(tmpdir)
 
@@ -536,7 +537,6 @@
         self.logger.info('Setting up final VM')
         self.vm = self.lv.defineXML(ElementTree.tostring(xml.getroot()))
 
-        self.cleanfile(tmpdir)
         return True
 
     def _start(self):

=== modified file 'utah/url.py'
--- utah/url.py	2013-03-13 16:30:11 +0000
+++ utah/url.py	2013-03-29 09:03:24 +0000
@@ -31,6 +31,7 @@
 import bzrlib.plugin
 import bzrlib.errors
 
+from utah.cleanup import cleanup
 from utah.exceptions import UTAHException
 from utah.timeout import timeout
 from utah.retry import retry
@@ -214,6 +215,7 @@
         cmd = bzrlib.builtins.cmd_export()
         assert cmd is not None
         tmp_dir = tempfile.mkdtemp(prefix='utah_')
+        cleanup.add_path(tmp_dir)
 
         def bzr_export_retriable():
             """bzr export a URL retrying on http errors