Merge lp:~doanac/utah/uuid_check_rsyslog into lp:utah

[Andy Doan]

get the uuid from rsyslog at system boot rather than using ssh.

[Max Brustkern (nuclearbob)]

I've read that $() is better than `` for portability, but we do appear to be using `` in other spots in the code, so it's obviously not breaking anything right now.

I have two more substantive concerns. Are we going to receive a UUID on systems where the wait_for_booted isn't working? Is it safe to change the incorrect uuid behavior from an Exception to logging an error? The intent of this check is to ensure we're actually running on the system we installed, and I don't think logging an error and then continuing the test is necessarily an appropriate response. We could consider doing a retry, but I think continuing is a problem.

[Javier Collado (javier.collado)]

Line 228 in the diff will conflict with:
https://code.launchpad.net/~javier.collado/utah/bug1176076/+merge/162382

In this merge proposal 'match.string' is used while 'pattern' is used in mine.

Any of them is probably fine, but I think 'pattern' is slightly better because the error message says "matched future pattern" instead of something like "matched text". Anyway, I think that change should be removed from this merge request since it's already included in the other one. Do you agree on this?

Aside from this, it isn't completely clear to me what the 'uuid: True' line in the configuration file does. Maybe and explanation about it should be added to the docstring in wait_for_install where an example of valid steps is provided.

[Andy Doan (doanac)]

On 05/03/2013 10:29 AM, Max Brustkern wrote:

> I have two more substantive concerns. Are we going to receive a UUID
> on systems where the wait_for_booted isn't working?

no

> Is it safe to
> change the incorrect uuid behavior from an Exception to logging an
> error? The intent of this check is to ensure we're actually running
> on the system we installed, and I don't think logging an error and
> then continuing the test is necessarily an appropriate response. We
> could consider doing a retry, but I think continuing is a problem.

so - I'm probably downplaying the importance of the UUID here.
Originally I liked this better but this is probably worth debate.

The *real* reason I shuffled this around is because this need to make an
SSH connection to the target after install gets in the way of doing an
autostart of UTAH from rc.local. So if we make a retry type thing here,
its still going to be a problem for my next planned patchset.

[Andy Doan (doanac)]

On 05/03/2013 10:30 AM, Javier Collado wrote:
> Any of them is probably fine, but I think 'pattern' is slightly better because the error message says "matched future pattern" instead of something like "matched text". Anyway, I think that change should be removed from this merge request since it's already included in the other one. Do you agree on this?

your way is better.

> Aside from this, it isn't completely clear to me what the 'uuid: True' line in the configuration file does. Maybe and explanation about it should be added to the docstring in wait_for_install where an example of valid steps is provided.

+1

[lp:~doanac/utah/uuid_check_rsyslog]

888. By Andy Doan on 2013-05-03

as per max's review

this raises an exception when UUID mismatches since its a provisioning
issue.

889. By Andy Doan on 2013-05-03

add a comment about uuid conf as per javier

890. By Andy Doan on 2013-05-06

improve timeout logic with regards to future_patterns

The future pattern logic works correctly. However, it hinges on the
pattern being hit within the limits of the previous timeout interval.
This change adds up the future timeouts and makes us wait that whole
duration so we can properly detect future messages. This happens most
often on the wait_for_booted logic.

891. By Andy Doan on 2013-05-06

wait for network before running install commands

in the case of this running during the installer, nothing will change.
in the case of booting an image and running from rc.local, we should
be safer now and always get the rsyslog messages.

This seems to fix the issues we had with wait_for_booted not always
working.

[Andy Doan (doanac)]

I think this fixes the main issues.

verified with saucy server/desktop

revno 891 - is pretty big fix. This seems to ensure rc.local's rsyslog messages will make it to UTAH.
revno 890 - makes our wait_for timeout smarter by taking into account future pattern timeout values.

review: Needs Resubmitting

[lp:~doanac/utah/uuid_check_rsyslog]

892. By Andy Doan on 2013-05-10

restart rsyslog when network comes alive

I've seen an issue mostly with server images and rsyslog. The issue
is that rsyslog starts running before the network is up. It seems
to detect this and at some point stop trying to send things to the
remote syslog server (or at least waits a bit before trying again).
This is causing our first few syslog messages to not always show up,
and these messages are critical for UTAH to understand how things
are working.

This restarts rsyslogd after we know the network is up so that we
can reliably get these messages.

[Andy Doan (doanac)]

This branch is stable now and has been tested most of the week. revno 892 seems to be the magic commit that makes things reliable.

review: Needs Resubmitting

[Max Brustkern (nuclearbob)]

If rsyslog is now reliable enough for the uuid check, we should remove the workaround to log a warning instead of timing out during wait_for_booted. I think in the current code, a timeout would issue a warning and then possibly cause the system to proceed with no uuid check occurring.

[Javier Collado (javier.collado)]

I've tested with a desktop i386 image and the pass runlist and it worked fine.
However, I have the feeling that there's some duplication in the code that is a
little bit confusing. In particular, I've seen that the machine UUID is written
twice to the syslog file.

The reason for this is that the commands in `install-commands.jinja2` are
written both to the late command script and also to `/etc/rc.local`. Given that
UUID is expected to be captured during the boot sequence, I believe it should
only be in `/etc/rc.local`, not in the late command script.

[Max Brustkern (nuclearbob)]

Maybe we should move the install commands into rc.local only? I think we've been discussing relying less on the preseed for a while.

[Andy Doan (doanac)]

On 05/16/2013 10:35 AM, Max Brustkern wrote:
> If rsyslog is now reliable enough for the uuid check, we should remove the workaround to log a warning instead of timing out during wait_for_booted. I think in the current code, a timeout would issue a warning and then possibly cause the system to proceed with no uuid check occurring.

I *think* it probably is, but I was kind of wanting to see this in wild
first ie in 0.13 and then make that an error for 0.14 just to be safe.

[Andy Doan (doanac)]

On 05/16/2013 11:15 AM, Javier Collado wrote:
> I've tested with a desktop i386 image and the pass runlist and it worked fine.
> However, I have the feeling that there's some duplication in the code that is a
> little bit confusing. In particular, I've seen that the machine UUID is written
> twice to the syslog file.
>
> The reason for this is that the commands in `install-commands.jinja2` are
> written both to the late command script and also to `/etc/rc.local`. Given that
> UUID is expected to be captured during the boot sequence, I believe it should
> only be in `/etc/rc.local`, not in the late command script.

I think sending it twice is harmless. I have another branch that's
dependent on this that does some more refactoring around this area that
might be a better place to address.

On 05/16/2013 01:33 PM, Max Brustkern wrote:
 > Maybe we should move the install commands into rc.local only? I
 > think we've been discussing relying less on the preseed for a while.

I think this is what we should shoot for. I'm not totally sure we should
do it in this change though?

[Max Brustkern (nuclearbob)]

> On 05/16/2013 11:15 AM, Javier Collado wrote:
> > I've tested with a desktop i386 image and the pass runlist and it worked
> fine.
> > However, I have the feeling that there's some duplication in the code that
> is a
> > little bit confusing. In particular, I've seen that the machine UUID is
> written
> > twice to the syslog file.
> >
> > The reason for this is that the commands in `install-commands.jinja2` are
> > written both to the late command script and also to `/etc/rc.local`. Given
> that
> > UUID is expected to be captured during the boot sequence, I believe it
> should
> > only be in `/etc/rc.local`, not in the late command script.
>

I think you may be right about that being out of scope here, but I'm also worried about a temporary situation that's less reliable than where we were before and where we're going. Am I crazy for imagining a situation where some rogue preseed fakes us into thinking that the install is done in the latecommand, and then we check the uuid, declare it valid, and then reboot into a system that hasn't installed correctly? That seems pretty unlikely I guess.
> I think sending it twice is harmless. I have another branch that's
> dependent on this that does some more refactoring around this area that
> might be a better place to address.
>
> On 05/16/2013 01:33 PM, Max Brustkern wrote:
> > Maybe we should move the install commands into rc.local only? I
> > think we've been discussing relying less on the preseed for a while.
>
> I think this is what we should shoot for. I'm not totally sure we should
> do it in this change though?

[Andy Doan (doanac)]

On 05/16/2013 03:03 PM, Max Brustkern wrote:
> I think you may be right about that being out of scope here, but I'm
> also worried about a temporary situation that's less reliable than
> where we were before and where we're going.

sounds good

> Am I crazy for imagining
> a situation where some rogue preseed fakes us into thinking that the
> install is done in the latecommand, and then we check the uuid,
> declare it valid, and then reboot into a system that hasn't installed
> correctly?

I don't think this is possible. We only check for UUID in the
boot_steps, not the install_steps. So UUID is basically ignored if
printed during the install.

[Max Brustkern (nuclearbob)]

> > Am I crazy for imagining
> > a situation where some rogue preseed fakes us into thinking that the
> > install is done in the latecommand, and then we check the uuid,
> > declare it valid, and then reboot into a system that hasn't installed
> > correctly?
>
> I don't think this is possible. We only check for UUID in the
> boot_steps, not the install_steps. So UUID is basically ignored if
> printed during the install.

That's what I'm trying to figure out: is there any way we could think the install is done before it is?

[Andy Doan (doanac)]

On 05/16/2013 03:17 PM, Max Brustkern wrote:
> That's what I'm trying to figure out: is there any way we could think the install is done before it is?

I don't see how.

[Javier Collado (javier.collado)]

> I don't see how.

I think I agree on this because of the separation of the install and boot
steps. Otherwise, it would be possible to match a pattern in the future for the
first uuid that is printed and consider that the boot up is done.

[Max Brustkern (nuclearbob)]

Okay, we should be in good shape to merge, then.

=== modified file 'templates/install-commands.jinja2'
--- templates/install-commands.jinja2	2013-02-27 11:10:59 +0000
+++ templates/install-commands.jinja2	2013-05-10 15:36:27 +0000
@@ -7,6 +7,24 @@
     {{ check_locks_command() | indent }}
 }
 
+wait_for_net()
+{
+	log "waiting for network"
+	timeout 2m sh <<EOF
+	gw=""
+	while [ -z "\$gw" ] ; do
+		sleep 2
+		gw=\`ip route | grep default\`
+	done
+
+	# rsyslog may start skipping remote logging if it got too many
+	# messages to send before the network was up. This makes it
+	# start afresh and deliver our messages.
+	restart rsyslog
+	sleep 1
+EOF
+}
+
 install_package() {
     package=$1
     check_locks
@@ -22,5 +40,10 @@
     done
 }
 
+wait_for_net
 install_packages {{packages | join(' ')}}
+
+# NOTE: do syslog at the end, so we do not try and start connecting via
+# ssh or running other stuff before the target is ready
+log "Machine UUID: `cat /etc/utah/uuid`"
 {%- endmacro %}
 
=== modified file 'tests/test_rsyslog.py'
--- tests/test_rsyslog.py	2013-05-01 20:51:33 +0000
+++ tests/test_rsyslog.py	2013-05-10 15:36:27 +0000
@@ -18,15 +18,18 @@
 
 import itertools
 import logging
+import mock
 import socket
 import time
 import tempfile
 import threading
 import unittest
+import uuid
 
 from mock import patch
 
 from utah.exceptions import UTAHException
+from utah.provisioning.exceptions import UTAHProvisioningException
 from utah.provisioning.rsyslog import RSyslog
 from utah.timeout import UTAHTimeout
 
@@ -109,7 +112,9 @@
             {
                 "message": "test_future",
                 "pattern": ".*log source = /proc/kmsg started",
-                "timeout": 120,
+                # set a really small timeout to prove we properly calculate
+                # future timeout logic
+                "timeout": 0.01,
                 "booted": True,
             },
             {
@@ -194,24 +199,39 @@
         self.assertTrue(self.test_callbacks_booted, 'booted callback not made')
         self.assertTrue(self.test_callbacks_blah, 'blah callback not made')
 
-    def test_booted(self):
+    @mock.patch('test_rsyslog.TestRsyslog.logger')
+    def test_booted(self, logger):
         """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')
-        threading.Thread(target=self.producer, args=(r.port, messages)).start()
-        r.wait_for_booted(steps)
+        r.logger = logger
+        threading.Thread(target=self.producer, args=(r.port, messages)).start()
+        r.wait_for_booted(steps, tst_uuid)
+        self.assertFalse(logger.error.called)
+
+        threading.Thread(target=self.producer, args=(r.port, messages)).start()
+        with self.assertRaises(UTAHProvisioningException):
+            r.wait_for_booted(steps, 'bad')
 
     def test_booted_workaround(self):
         """Test that wait_for_booted doesn't raise an exception on timeout."""
@@ -225,7 +245,7 @@
 
         r = RSyslog("utah-test", '/tmp')
 
-        r.wait_for_booted(steps)
+        r.wait_for_booted(steps, None)
 
     def usefile(self, truncate):
         """Make sure wait_for_booted works when tailing a file."""
@@ -246,10 +266,12 @@
 
         with tempfile.NamedTemporaryFile() as f:
             r = RSyslog("utah-test", '/tmp', f.name)
-            threading.Thread(
+            t = threading.Thread(
                 target=self.file_producer,
-                args=(f, messages, truncate)).start()
-            r.wait_for_booted(steps)
+                args=(f, messages, truncate))
+            t.start()
+            r.wait_for_booted(steps, None)
+            t.join()
 
     def test_usefile(self):
         """Test tailing a file."""
@@ -270,18 +292,19 @@
             {
                 "message": "message_2",
                 "pattern": "pattern",
+                "timeout": 1,
             },
             {
                 "message": "message_3",
                 "pattern": "pattern",
+                "timeout": 1,
             },
         ]
 
         messages = itertools.repeat('log example')
-        pattern = (r'Timeout \({}\) occurred for {} message.\n'
+        pattern = (r'Timeout \(\d+\) occurred for {} message.\n'
                    r'Remaining messages: {}'
-                   .format(steps[0]['timeout'],
-                           steps[0]['message'],
+                   .format(steps[0]['message'],
                            ', '.join([step['message']
                                      for step in steps[1:]])))
 
 
=== modified file 'utah/config.py'
--- utah/config.py	2013-05-03 23:07:50 +0000
+++ utah/config.py	2013-05-10 15:36:27 +0000
@@ -228,14 +228,11 @@
             'timeout': 180,
         },
         {
-            'message': 'network active',
-            'pattern': [
-                '.*NetworkManager',
-                '.*dhclient: bound to',  # needed for minimal server installs
-            ],
-
+            'message': 'UTAH uuid received',
+            'uuid': True,  # binds this to the callback for wait_for_booted
+            'pattern': '.*Machine UUID:\s+(.*)',
             'timeout': 180,
-        }
+        },
     ],
 )
 
 
=== modified file 'utah/provisioning/baremetal/bamboofeeder.py'
--- utah/provisioning/baremetal/bamboofeeder.py	2013-04-26 13:36:08 +0000
+++ utah/provisioning/baremetal/bamboofeeder.py	2013-05-10 15:36:27 +0000
@@ -276,7 +276,7 @@
         self.logger.info('System installing')
 
         self.rsyslog.wait_for_install(config.install_steps)
-        self.rsyslog.wait_for_booted(config.boot_steps)
+        self.rsyslog.wait_for_booted(config.boot_steps, 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-04-26 13:36:08 +0000
+++ utah/provisioning/baremetal/cobbler.py	2013-05-10 15:36:27 +0000
@@ -206,7 +206,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.rsyslog.wait_for_booted(config.boot_steps, self.uuid)
 
         retry(self.sshcheck, logmethod=self.logger.info,
               retry_timeout=config.checktimeout)
 
=== modified file 'utah/provisioning/provisioning.py'
--- utah/provisioning/provisioning.py	2013-05-03 23:08:37 +0000
+++ utah/provisioning/provisioning.py	2013-05-10 15:36:27 +0000
@@ -398,7 +398,6 @@
                 self.logger.debug('Failed to load machine: %s', str(err))
         self._create()
         self.provisioned = True
-        self._uuid_check()
 
     def _create(self):
         # TODO: discuss separation of this vs. start when separating Install
@@ -590,17 +589,6 @@
         if self.clean:
             cleanup.add_command(cmd)
 
-    def _uuid_check(self):
-        """Check uuid to verify we've installed correctly."""
-        uuid_check_command = ('[ "{uuid}" == "$(cat /etc/utah/uuid)" ]'
-                              .format(uuid=self.uuid))
-        if self.run(uuid_check_command)[0] != 0:
-            self.provisioned = False
-            raise UTAHProvisioningException(
-                'Installed UUID differs from Machine UUID; '
-                'installation probably failed. '
-                'Try rerunning install.')
-
 
 class CustomInstallMixin(object):
 
 
=== modified file 'utah/provisioning/rsyslog.py'
--- utah/provisioning/rsyslog.py	2013-05-03 15:58:24 +0000
+++ utah/provisioning/rsyslog.py	2013-05-10 15:36:27 +0000
@@ -24,6 +24,7 @@
 import time
 
 from utah.exceptions import UTAHException
+from utah.provisioning.exceptions import UTAHProvisioningException
 from utah.timeout import UTAHTimeout
 
 
@@ -113,7 +114,7 @@
         callbacks = {'booted': booted_callback}
         self._wait_for_steps(steps, logfile, callbacks)
 
-    def wait_for_booted(self, steps):
+    def wait_for_booted(self, steps, uuid):
         """Monitor rsyslog during boot up.
 
         Works the same as the :meth:`wait_for_install` method but takes in
@@ -122,16 +123,29 @@
 
         :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`
 
         """
         logfile = '{}/{}-boot.log'.format(self._logpath, self._host)
-        callbacks = {}
+
+        def _cb(match):
+            if match:
+                _cb.uuid = match.group(1).strip()
+
+        _cb.uuid = None
+        callbacks = {'uuid': _cb}
         # TODO: Resolve the issues around this and get it back to normal
         # i.e. LP#1100386
         try:
             self._wait_for_steps(steps, logfile, callbacks)
+            if not _cb.uuid:
+                self.logger.error('UUID not sent from target')
+            elif uuid and uuid != _cb.uuid:
+                msg = 'Incorrect UUID: {} != {}'.format(uuid, _cb.uuid)
+                raise UTAHProvisioningException(msg)
         except UTAHTimeout:
             self.logger.warning('Timed out waiting for boot, but continuing')
 
@@ -149,9 +163,10 @@
                 if not isinstance(fail_pattern, list):
                     fail_pattern = [fail_pattern]
                 pattern.extend(fail_pattern)
-                future_pats = self._future_patterns(steps, x)
+                future_pats, future_timeout = 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)
                 if match is None:
                     remaining_messages = [step['message']
@@ -170,7 +185,11 @@
                                         .format(pattern))
                 if pattern in future_pats:
                     msg = 'Expected pattern missed, matched future pattern: %s'
+<<<<<<< TREE
                     self.logger.warn(msg, pattern)
+=======
+                    self.logger.warn(msg, match.string)
+>>>>>>> MERGE-SOURCE
                     x = self._fast_forward(steps, pattern, match, callbacks)
                 else:
                     self.logger.info('Matched pattern %r for %r message',
@@ -188,14 +207,16 @@
     @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
+        return patterns, timeout
 
     @staticmethod
     def _fast_forward(steps, pattern, match, callbacks):
 
=== modified file 'utah/provisioning/vm.py'
--- utah/provisioning/vm.py	2013-05-09 19:51:42 +0000
+++ utah/provisioning/vm.py	2013-05-10 15:36:27 +0000
@@ -546,7 +546,7 @@
         else:
             raise UTAHVMProvisioningException('Failed to provision VM')
 
-        self.rsyslog.wait_for_booted(config.boot_steps)
+        self.rsyslog.wait_for_booted(config.boot_steps, self.uuid)
         try:
             self.logger.info(
                 'Waiting %d seconds for ping response', self.boottimeout)