Merge lp:~doanac/utah/rsyslog-config into lp:utah

[Andy Doan]

This helps fix our current configuration issues we are having and should help get us ready for the next release

[Max Brustkern (nuclearbob)]

How does this line (303 in the merge) work:
self.assertTrue(abs(time.time() - start - 5), 2)
? In the documentation on assertTrue, it looks like 2 should be picked up as the mesg argument?

Also, I'm a little worried about the regression potential of 432-435. Are we sure we don't have any test cases that currently take longer than 4 hours?

On line 531 of the merge, I get removing the steps. Was the previous reason for the seealso because the other method had steps, or because it was similar? Maybe the seealso still makes sense?

Looks like that also happened on 589, so maybe there's a consistent reason for it.

It looks like the timeout in wait_for_steps is now the timeout for the whole process rather than each step. That seems reasonable, and I'm assuming that since the previous default values were whole-process timeouts, we don't need to worry about updating them.

The rest of it looks reasonable to me, assuming it all tests out okay.

[Max Brustkern (nuclearbob)]

For 432-435, if we run this branch on a machine that still has None in the config file, the whole config file will be ignored. If the config files is all defaults anyway, it'll be fine, but that seems like it could have the potential to cause problems. Maybe if we do want to move to int for that, we can introduce that as a default now and then remove null from the schema in another version or two. I'm still concerned about the 4 hour timeout, since part of the job of the utah client is to ensure that things don't run forever.

[Max Brustkern (nuclearbob)]

I got good tests of this on virtual and physical machines. I think once we determine how to address the configuration changes around timeouts, we should be good to go.

[Andy Doan (doanac)]

On 06/13/2013 07:14 PM, Max Brustkern wrote:
> How does this line (303 in the merge) work:
> self.assertTrue(abs(time.time() - start - 5), 2) ? In the
> documentation on assertTrue, it looks like 2 should be picked up as
> the mesg argument?

typo, was supposed to assertLessThan

> Also, I'm a little worried about the regression potential of 432-435.
> Are we sure we don't have any test cases that currently take longer
> than 4 hours?

I was just making an educated guess. You also said in your next thread:

  | I'm still concerned about the 4 hour timeout, since part of the job
  | of the utah client is to ensure that things don't run forever.

I think we should backout this change to config.py. The wait_for_run
already checks if the value is None and will default to a 2 day timeout.

> On line 531 of the merge, I get removing the steps. Was the previous
> reason for the seealso because the other method had steps, or because
> it was similar? Maybe the seealso still makes sense?
>
> Looks like that also happened on 589, so maybe there's a consistent
> reason for it.

I think it was just because of the steps and how they were documented

> It looks like the timeout in wait_for_steps is now the timeout for
> the whole process rather than each step. That seems reasonable, and
> I'm assuming that since the previous default values were
> whole-process timeouts, we don't need to worry about updating them.

that was my hope :)

> The rest of it looks reasonable to me, assuming it all tests out
> okay.

Sounds like I have two things to fix. I'll probably do that tomorrow and
re-submit.

[lp:~doanac/utah/rsyslog-config]

943. By Andy Doan on 2013-06-14

typo found by max

944. By Andy Doan on 2013-06-14

backout runtimeout change in config.py

removing the option for None was going to cause regressions. And
4 hours might not be a good guess either.

[Andy Doan (doanac)]

screw it. i couldn't sleep knowing it should be easy to fix your concerns.

review: Needs Resubmitting

[Max Brustkern (nuclearbob)]

This seems good to me. If nobody objects, I'm in favor of merging it today.

review: Approve

=== modified file 'tests/test_rsyslog.py'
--- tests/test_rsyslog.py	2013-06-04 20:46:41 +0000
+++ tests/test_rsyslog.py	2013-06-14 03:44:27 +0000
@@ -19,6 +19,8 @@
 import itertools
 import logging
 import mock
+import os
+import shutil
 import socket
 import time
 import tempfile
@@ -67,14 +69,21 @@
                 time.sleep(1)
                 truncate = False
 
+    def setUp(self):
+        """Create a temporary directory for logging."""
+        self.logdir = tempfile.mkdtemp()
+        self.logfile = os.path.join(self.logdir, 'tmp.log')
+
+    def tearDown(self):
+        """Cleanup artifacts from setUp."""
+        shutil.rmtree(self.logdir)
+
     def test_easy(self):
         """Make sure we can match a typical first message."""
         steps = [
             {
                 "message": "test_easy",
                 "pattern": ".*log source = /proc/kmsg started",
-                "timeout": 120,
-                "booted": False,
             },
         ]
 
@@ -82,9 +91,9 @@
             'test 1',
             '<13>Feb 20 13:38:55 host user: log source = /proc/kmsg started',
         ]
-        r = RSyslog("utah-test", '/tmp')
+        r = RSyslog("utah-test", self.logdir)
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
-        r.wait_for_install(steps)
+        r._wait_for_steps(steps, 5, self.logfile, {})
 
     def test_fail_pattern(self):
         """Exception is raised on fail_pattern match."""
@@ -93,7 +102,6 @@
                 "message": "test_late_command_failure",
                 "pattern": "finished",
                 "fail_pattern": "failure",
-                "timeout": 120,
             },
         ]
 
@@ -103,9 +111,10 @@
             'finished',
         ]
 
-        r = RSyslog('utah-test', '/tmp')
+        r = RSyslog("utah-test", self.logdir)
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
-        self.assertRaises(UTAHException, r.wait_for_install, steps)
+        with self.assertRaises(UTAHException):
+            r._wait_for_steps(steps, 5, self.logfile, {})
 
     def test_future(self):
         """Test handling a missing message."""
@@ -115,18 +124,15 @@
                 "pattern": ".*log source = /proc/kmsg started",
                 # set a really small timeout to prove we properly calculate
                 # future timeout logic
-                "timeout": 0.01,
                 "booted": True,
             },
             {
                 "message": "hit skipped",
                 "pattern": "hit skipped",
-                "timeout": 120,
             },
             {
                 "message": "message 3",
                 "pattern": "message 3",
-                "timeout": 120,
             },
         ]
 
@@ -136,7 +142,7 @@
             'message 3',
         ]
 
-        r = RSyslog("utah-test", '/tmp')
+        r = RSyslog("utah-test", self.logdir)
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
 
         def booted_cb(match):
@@ -145,7 +151,7 @@
 
         self.test_future_booted = False
         with patch.object(r.logger, 'warn') as mock_method:
-            r.wait_for_install(steps, booted_cb)
+            r._wait_for_steps(steps, 5, self.logfile, {'booted': booted_cb})
             mock_method.assert_called_with(
                 'Expected pattern missed, matched future pattern: %s',
                 'hit skipped')
@@ -158,18 +164,15 @@
             {
                 "message": "test callbacks",
                 "pattern": ".*log source = /proc/kmsg started",
-                "timeout": 120,
                 "booted": True,
             },
             {
                 "message": "hit skipped",
                 "pattern": "hit skipped",
-                "timeout": 120,
             },
             {
                 "message": "message 3",
                 "pattern": "message 3",
-                "timeout": 120,
                 "blah": True,
             },
         ]
@@ -180,7 +183,7 @@
             'message 3',
         ]
 
-        r = RSyslog("utah-test", '/tmp')
+        r = RSyslog("utah-test", self.logdir)
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
 
         def booted_cb(match):
@@ -196,61 +199,66 @@
             'booted': booted_cb,
             'blah': blah_cb,
         }
-        r._wait_for_steps(steps, "/dev/null", callbacks)
+        r._wait_for_steps(steps, 5, "/dev/null", callbacks)
         self.assertTrue(self.test_callbacks_booted, 'booted callback not made')
         self.assertTrue(self.test_callbacks_blah, 'blah callback not made')
 
+    def test_install(self):
+        """Make sure wait_for_install works."""
+        messages = [
+            'blah',
+            'ubiquity[11]: Ubiquity 1',
+            'finish-install: umount',
+        ]
+
+        def cb(match):
+            self.test_install_cb = True
+
+        self.test_install_cb = False
+        r = RSyslog("utah-test", self.logdir)
+        r.logger = mock.Mock()
+        threading.Thread(target=self.producer, args=(r.port, messages)).start()
+        r.wait_for_install(cb)
+        self.assertFalse(r.logger.error.called)
+        self.assertTrue(self.test_install_cb)
+
+        r = RSyslog("utah-test", self.logdir)
+        messages[-1] = 'utah: Late command failure detected'
+        threading.Thread(target=self.producer, args=(r.port, messages)).start()
+        with self.assertRaises(UTAHException):
+            r.wait_for_install()
+
     def test_booted(self):
         """Make sure wait_for_booted works."""
         tst_uuid = str(uuid.uuid4())
-        steps = [
-            {
-                "message": "test booted",
-                "pattern": ".*log source = /proc/kmsg started",
-                "timeout": 120,
-            },
-            {
-                "message": "test uuid",
-                "uuid": True,
-                "pattern": '.*Machine UUID:\s+(.*)',
-                "timeout": 2,
-            },
-        ]
-
         messages = [
             'test 1',
             '<13>Feb 20 13:38:55 host user: log source = /proc/kmsg started',
             '<13>Feb 21 13:40:55 host user: Machine UUID: {}'.format(tst_uuid),
         ]
 
-        r = RSyslog("utah-test", '/tmp')
+        r = RSyslog("utah-test", self.logdir)
         r.logger = mock.Mock()
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
-        r.wait_for_booted(steps, tst_uuid)
+        r.wait_for_booted(tst_uuid)
         self.assertFalse(r.logger.error.called)
 
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
         with self.assertRaises(UTAHProvisioningException):
-            r.wait_for_booted(steps, 'bad')
+            r.wait_for_booted('bad')
 
     def test_booted_workaround(self):
         """Test that wait_for_booted doesn't raise an exception on timeout."""
-        steps = [
-            {
-                "message": "test booted",
-                "pattern": "Wait forever for a line that never comes",
-                "timeout": 5,
-            },
-        ]
-
-        r = RSyslog("utah-test", '/tmp')
-
-        r.wait_for_booted(steps, None)
+        orig = config.boottimeout
+        try:
+            config.boottimeout = 0.5
+            r = RSyslog("utah-test", self.logdir)
+            r.wait_for_booted(None)
+        finally:
+            config.boottimeout = orig
 
     def test_wait_for_run(self):
         """Test that wait_for_utah_run works."""
-        steps = config.autorun_steps
-
         messages = [
             'test 1',
             'utah: completed /etc/utah/autorun/01_run-utah rc=7',
@@ -261,7 +269,7 @@
 
         r = RSyslog("utah-test", '/tmp')
         threading.Thread(target=self.producer, args=(r.port, messages)).start()
-        r.wait_for_utah_run(steps, cb)
+        r.wait_for_utah_run(cb)
         self.assertEqual(7, self.utah_run_rc)
 
     def usefile(self, truncate):
@@ -270,7 +278,6 @@
             {
                 "message": "truncate test",
                 "pattern": ".*log source = /proc/kmsg started",
-                "timeout": 60,
             },
         ]
 
@@ -282,12 +289,12 @@
         ]
 
         with tempfile.NamedTemporaryFile() as f:
-            r = RSyslog("utah-test", '/tmp', f.name)
+            r = RSyslog("utah-test", self.logdir, f.name)
             t = threading.Thread(
                 target=self.file_producer,
                 args=(f, messages, truncate))
             t.start()
-            r.wait_for_booted(steps, None)
+            r._wait_for_steps(steps, 5, self.logfile, {})
             t.join()
 
     def test_usefile(self):
@@ -304,31 +311,31 @@
             {
                 "message": "message_1",
                 "pattern": "finished",
-                "timeout": 1,
             },
             {
                 "message": "message_2",
                 "pattern": "pattern",
-                "timeout": 1,
             },
             {
                 "message": "message_3",
                 "pattern": "pattern",
-                "timeout": 1,
             },
         ]
 
-        messages = itertools.repeat('log example')
+        messages = ['message_1', 'message_2', 'message_4']
         pattern = (r'Timeout \(\d+\) occurred for {} message.\n'
                    r'Remaining messages: {}'
                    .format(steps[0]['message'],
                            ', '.join([step['message']
                                      for step in steps[1:]])))
 
-        r = RSyslog('utah-test', '/tmp')
+        r = RSyslog('utah-test', self.logdir)
         thread = threading.Thread(target=self.producer,
                                   args=(r.port, messages))
         thread.daemon = True
         thread.start()
-        self.assertRaisesRegexp(UTAHTimeout, pattern,
-                                r.wait_for_install, steps)
+        start = time.time()
+        with self.assertRaisesRegexp(UTAHTimeout, pattern):
+            r._wait_for_steps(steps, 5, self.logfile, {})
+        # assert the timeout was within 2 seconds of what we expect
+        self.assertLess(abs(time.time() - start - 5), 2)

=== modified file 'utah/config.py'
--- utah/config.py	2013-06-05 15:56:26 +0000
+++ utah/config.py	2013-06-14 03:44:27 +0000
@@ -46,67 +46,17 @@
         "$schema": "http://json-schema.org/draft-04/schema#",
         'title': 'UTAH configuration',
         'type': 'object',
-        'additionalProperties': False,
+        'additionalProperties': True,
         'properties': {
             'arch': {
                 'description': 'Default architecture',
                 'type': 'string',
             },
-            'autorun_steps': {
-                'description': 'rsyslog patterns matched during autorun',
-                'type': 'array',
-                'items': {'type': 'object'},
-                'default': [
-                    {
-                        'message': 'UTAH setup',
-                        'pattern': ('.*utah: completed '
-                                    '/etc/utah/autorun/\d+_utah-setup'),
-                        'timeout': 180,
-                    },
-                    {
-                        'message': 'UTAH client install',
-                        'pattern': ('.*utah: completed '
-                                    '/etc/utah/autorun/\d+_install-client'),
-                        'timeout': 180,
-                    },
-                    {
-                        'message': 'UTAH runlist',
-                        'pattern': ('.*utah: completed '
-                                    '/etc/utah/autorun/\d+_run-utah rc=(\d+)'),
-                        'completed': True,
-                        'timeout': 7200,  # 2 hours
-                    },
-                ],
-            },
             'boot': {
                 'description': 'Default kernel parameters',
                 'type': ['string', 'null'],
                 'default': None,
             },
-            'boot_steps': {
-                'description': 'rsyslog patterns matched during boot',
-                'type': 'array',
-                'items': {'type': 'object'},
-                'default': [
-                    {
-                        'message': 'system booted',
-                        'pattern': '.*Linux version \\d',
-                        'timeout': 600,
-                    },
-                    {
-                        'message': 'disk mounted',
-                        'pattern': '.*mounted filesystem with ordered data',
-                        'timeout': 600,
-                    },
-                    {
-                        'message': 'UTAH uuid received',
-                        # binds this to the callback for wait_for_booted
-                        'uuid': True,
-                        'pattern': '.*Machine UUID:\s+(.*)',
-                        'timeout': 600,
-                    },
-                ],
-            },
             'boottimeout': {
                 'description': 'Time to wait for installed system to boot',
                 'type': 'integer',
@@ -223,50 +173,6 @@
                 'format': 'path',
                 'default': None,
             },
-            'install_steps': {
-                'description': 'rsyslog patterns matched during installation',
-                'type': 'array',
-                'items': {'type': 'object'},
-                'default': [
-                    {
-                        'message': 'system started',
-                        'pattern': '.*',
-                        'booted': True,
-                        'timeout': 360,
-                    },
-                    {
-                        'message': 'install started',
-                        'pattern': [
-                            '.*ubiquity\\[\\d+\\]: Ubiquity \\d',
-                            # needed for non-ubiquity installs
-                            '.*anna-install',
-                        ],
-                        'timeout': 120,
-                    },
-                    {
-                        'message': 'install complete',
-                        'pattern': [
-                            '.*ubiquity reboot',
-                            '.*log-output -t ubiquity umount /target$',
-                            # for server bootspeed
-                            '.*finish-install.d/94save-logs',
-                            '.*finish-install: umount',
-                            # a catch-all
-                            '.*rsyslogd:.*exiting on signal 15.',
-                        ],
-                        'fail_pattern': [
-                            # ubiquity/failure_command
-                            '.*utah: Installation failure detected',
-                            # ubiquity/success_command
-                            # and d-i/late_command failures
-                            '.*utah: Late command failure detected',
-                            # d-i installation failure
-                            '.*exited with status [^0]',
-                        ],
-                        'timeout': 3600,
-                    },
-                ],
-            },
             'installpackages': {
                 'description': 'Packages to install on system',
                 'type': 'array',

=== modified file 'utah/provisioning/baremetal/bamboofeeder.py'
--- utah/provisioning/baremetal/bamboofeeder.py	2013-06-10 05:48:52 +0000
+++ utah/provisioning/baremetal/bamboofeeder.py	2013-06-14 03:44:27 +0000
@@ -271,8 +271,8 @@
         self.restart()
         self.logger.info('System installing')
 
-        self.rsyslog.wait_for_install(config.install_steps)
-        self.rsyslog.wait_for_booted(config.boot_steps, self.uuid)
+        self.rsyslog.wait_for_install()
+        self.rsyslog.wait_for_booted(self.uuid)
         retry(self.sshcheck, logmethod=self.logger.info,
               retry_timeout=config.checktimeout)
 

=== modified file 'utah/provisioning/baremetal/cobbler.py'
--- utah/provisioning/baremetal/cobbler.py	2013-06-10 05:57:49 +0000
+++ utah/provisioning/baremetal/cobbler.py	2013-06-14 03:44:27 +0000
@@ -202,8 +202,7 @@
                         for arg in self.machineinfo])
 
         self.restart()
-        self.rsyslog.wait_for_install(config.install_steps,
-                                      self._disable_netboot)
+        self.rsyslog.wait_for_install(self._disable_netboot)
 
         # TODO: wait_for_booted isn't working on d-i installs and
         # autopilot jobs like:
@@ -211,7 +210,7 @@
         # ps-unity-autopilot-release-testing/140/label=autopilot-nvidia/
         # For now, it seems to be a problem on all installs, so we're going to
         # handle it in rsyslog.py
-        self.rsyslog.wait_for_booted(config.boot_steps, self.uuid)
+        self.rsyslog.wait_for_booted(self.uuid)
 
         retry(self.sshcheck, logmethod=self.logger.info,
               retry_timeout=config.checktimeout)

=== modified file 'utah/provisioning/rsyslog.py'
--- utah/provisioning/rsyslog.py	2013-05-22 16:56:32 +0000
+++ utah/provisioning/rsyslog.py	2013-06-14 03:44:27 +0000
@@ -23,6 +23,7 @@
 import sys
 import time
 
+from utah.config import config
 from utah.exceptions import UTAHException
 from utah.provisioning.exceptions import UTAHProvisioningException
 from utah.timeout import UTAHTimeout
@@ -70,65 +71,85 @@
         """Return UDP port number used to listen for syslog messages."""
         return self._port
 
-    def wait_for_install(self, steps, booted_callback=None):
+    def wait_for_install(self, booted_callback=None):
         """Monitor rsyslog messages during the installation.
 
         Works through each step in the steps array to find messages in the
         syslog indicating what part of the install we are in.
 
-        :param steps: Set of steps that the installation will go through.
-        :type steps: list(dict)
         :param booted_callback:
             function to be called once the system has been booted
         :type booted_callback: callable | None
 
-        An example of a valid steps argument would be as follows::
-
-            {
-              "message": "system started",
-              "pattern": ".*log source = /proc/kmsg started",
-              "fail_pattern": ".*exited with status [^0]",
-              "timeout": 1000,
-              "booted": false
-            },
-            {
-              "message": "system started",
-              "pattern": [
-                ".*log source = /proc/kmsg started"
-              ],
-              "timeout": 1000,
-              "booted": false
-            }
-
-        where:
-
-            - ``pattern`` can an array or string.
-            - ``booted`` is optional, but can be used to indicate that the
-              system is fully operational. This can be used in conjunction with
-              the ``booted_callback`` function.
-
-        .. seealso:: :meth:`wait_for_booted`
-
         """
+        steps = [
+            {
+                'message': 'system started',
+                'pattern': ['.*'],
+                'booted': True,
+            },
+            {
+                'message': 'install started',
+                'pattern': [
+                    '.*ubiquity\\[\\d+\\]: Ubiquity \\d',
+                    # needed for non-ubiquity installs
+                    '.*anna-install',
+                ],
+            },
+            {
+                'message': 'install complete',
+                'pattern': [
+                    '.*ubiquity reboot',
+                    '.*log-output -t ubiquity umount /target$',
+                    # for server bootspeed
+                    '.*finish-install.d/94save-logs',
+                    '.*finish-install: umount',
+                    # a catch-all
+                    '.*rsyslogd:.*exiting on signal 15.',
+                ],
+                'fail_pattern': [
+                    # ubiquity/failure_command
+                    '.*utah: Installation failure detected',
+                    # ubiquity/success_command
+                    # and d-i/late_command failures
+                    '.*utah: Late command failure detected',
+                    # d-i installation failure
+                    '.*exited with status [^0]',
+                ],
+            },
+        ]
+
         logfile = '{}/{}-install.log'.format(self._logpath, self._host)
         callbacks = {'booted': booted_callback}
-        self._wait_for_steps(steps, logfile, callbacks)
+        self._wait_for_steps(steps, config.installtimeout, logfile, callbacks)
 
-    def wait_for_booted(self, steps, uuid):
+    def wait_for_booted(self, uuid):
         """Monitor rsyslog during boot up.
 
         Works the same as the :meth:`wait_for_install` method but takes in
         steps that determine a system has booted after the install has
         completed.
 
-        :param steps: Set of steps that the boot up will go through.
-        :type steps: list(dict)
         :param uuid: The UUID generated by provisioning code.
         :type uuid: string
 
-        .. seealso:: :meth:`wait_for_install`
-
         """
+        steps = [
+            {
+                'message': 'system booted',
+                'pattern': '.*Linux version \\d',
+            },
+            {
+                'message': 'disk mounted',
+                'pattern': '.*mounted filesystem with ordered data',
+            },
+            {
+                'message': 'UTAH uuid received',
+                # binds this to the callback for wait_for_booted
+                'uuid': True,
+                'pattern': '.*Machine UUID:\s+(.*)',
+            },
+        ]
         logfile = '{}/{}-boot.log'.format(self._logpath, self._host)
 
         def _cb(match):
@@ -140,7 +161,7 @@
         # TODO: Resolve the issues around this and get it back to normal
         # i.e. LP#1100386
         try:
-            self._wait_for_steps(steps, logfile, callbacks)
+            self._wait_for_steps(steps, config.boottimeout, logfile, callbacks)
             if not _cb.uuid:
                 self.logger.error('UUID not sent from target')
             elif uuid and uuid != _cb.uuid:
@@ -149,39 +170,60 @@
         except UTAHTimeout:
             self.logger.warning('Timed out waiting for boot, but continuing')
 
-    def wait_for_utah_run(self, steps, completed_cb=None):
+    def wait_for_utah_run(self, completed_cb=None):
         """Monitor rsyslog while waiting for utah-client to finish autorun.
 
-        :param steps: Set of steps that the boot up will go through.
-        :type steps: list(dict)
         :param completed_cb: A callback function that will include the utah
         exit code.
         :type completed_cb: function
 
         """
+        steps = [
+            {
+                'message': 'UTAH setup',
+                'pattern': ('.*utah: completed '
+                            '/etc/utah/autorun/\d+_utah-setup'),
+            },
+            {
+                'message': 'UTAH client install',
+                'pattern': ('.*utah: completed '
+                            '/etc/utah/autorun/\d+_install-client'),
+            },
+            {
+                'message': 'UTAH runlist',
+                'pattern': ('.*utah: completed '
+                            '/etc/utah/autorun/\d+_run-utah rc=(\d+)'),
+                'completed': True,
+            },
+        ]
         logfile = '{}/{}-utah-run.log'.format(self._logpath, self._host)
         callbacks = {'completed': completed_cb}
-        self._wait_for_steps(steps, logfile, callbacks)
+        timeout = config.runtimeout
+        if not timeout:
+            # this means forever, but lets give something sensible to help
+            # prevent jobs from hanging forever
+            timeout = 172800  # 2 days
+        self._wait_for_steps(steps, timeout, logfile, callbacks)
 
-    def _wait_for_steps(self, steps, logfile, callbacks):
+    def _wait_for_steps(self, steps, timeout, logfile, callbacks):
         with open(logfile, 'w') as f:
             x = 0
+            deadline = time.time() + timeout
             while x < len(steps):
                 message = steps[x]['message']
                 pattern = steps[x]['pattern']
                 fail_pattern = steps[x].get('fail_pattern', [])
-                timeout = steps[x]['timeout']
 
                 if not isinstance(pattern, list):
                     pattern = [pattern]
                 if not isinstance(fail_pattern, list):
                     fail_pattern = [fail_pattern]
                 pattern.extend(fail_pattern)
-                future_pats, future_timeout = self._future_patterns(steps, x)
+                future_pats = self._future_patterns(steps, x)
                 pattern.extend(future_pats)
-                self.logger.info('Waiting %ds for: %s', timeout, message)
-                timeout += future_timeout
-                pattern, match = self._wait_for(f, pattern, message, timeout)
+                self.logger.info(
+                    'Waiting %ds for: %s', deadline - time.time(), message)
+                pattern, match = self._wait_for(f, pattern, message, deadline)
                 if match is None:
                     remaining_messages = [step['message']
                                           for step in steps[x + 1:]]
@@ -217,16 +259,14 @@
     @staticmethod
     def _future_patterns(steps, index):
         patterns = []
-        timeout = 0
         index += 1
         for step in steps[index:]:
             pattern = step['pattern']
-            timeout += step['timeout']
             if not isinstance(pattern, list):
                 patterns.append(pattern)
             else:
                 patterns.extend(pattern)
-        return patterns, timeout
+        return patterns
 
     @staticmethod
     def _fast_forward(steps, pattern, match, callbacks):
@@ -252,11 +292,10 @@
 
             x += 1
 
-    def _wait_for(self, writer, patterns, message, timeout):
+    def _wait_for(self, writer, patterns, message, deadline):
         pats = [re.compile(x) for x in patterns]
 
-        endtime = time.time() + timeout
-        while(time.time() < endtime):
+        while(time.time() < deadline):
             data = self._read_line()
             if data:
                 if self.logger.level <= logging.DEBUG:

=== modified file 'utah/provisioning/vm.py'
--- utah/provisioning/vm.py	2013-06-11 04:23:34 +0000
+++ utah/provisioning/vm.py	2013-06-14 03:44:27 +0000
@@ -415,7 +415,7 @@
                                         '{}.syslog.log'.format(self.name))
             self.logger.info('Logs will be written to %s', log_filename)
 
-            self.rsyslog.wait_for_install(config.install_steps)
+            self.rsyslog.wait_for_install()
             while vm.isActive() is not 0:
                 pass
 
@@ -550,7 +550,7 @@
         else:
             raise UTAHVMProvisioningException('Failed to provision VM')
 
-        self.rsyslog.wait_for_booted(config.boot_steps, self.uuid)
+        self.rsyslog.wait_for_booted(self.uuid)
         try:
             self.logger.info(
                 'Waiting %d seconds for ping response', config.boottimeout)

=== modified file 'utah/run.py'
--- utah/run.py	2013-06-10 04:54:50 +0000
+++ utah/run.py	2013-06-14 03:44:27 +0000
@@ -234,7 +234,7 @@
             raise UTAHException('Failed to get return code from UTAH runlist')
         _provision_and_run.rc = int(match.group(1))
 
-    machine.rsyslog.wait_for_utah_run(config.autorun_steps, _complete_cb)
+    machine.rsyslog.wait_for_utah_run(_complete_cb)
     return _provision_and_run.rc, tgt_report