Merge lp:~javier.collado/utah/wrap-latecommand into lp:utah

[Javier Collado]

This branch moves the contens of the late command (and the success command in
desktop images) to a separate script file that uses "set -e" so that the
scripts stop on any failure and its return code can be used to detect that
situation.

The idea about this is to be able to detect when something in the late command
failed to troubleshoot problems faster.

The plan about these changes are as follows:
- do a similar thing for the failure command in desktop installations
- update the log messages to use rsyslog (for now /var/log/utah-install is used)
- refactor the wrapper script to move part of it to utah-latecommand so that the
  wrapper just contains what it was in the original preseed and utah-latecommand
  has what it has been added by utah

I've tested the changes with {desktop,server} {i386,amd64} and worked fine,
that is, the installation was successful and the contents of
/var/log/utah-install was the expected one.

[Andy Doan (doanac)]

+1

[Javier Collado (javier.collado)]

I've updated the code in this branch to better separate what is added by UTAH
and what was in the original preseed.

After the changes, there are two scripts:
- utah-latecommand: Performs the file copying that is needed to get some files in
the target filesystems: SSH keys, UUID, etc.
- utah-latcommand-in-target: Installs the packages needed to connect through SSH
and updates /etc/rc.local to retry the package installation just in case some
problem happened.

Log messages are written both to /var/log/utah-install and the installer
syslog. Incidentally, I've found that, in desktop installations, messages
appear only in the syslog file available in the utah server side and doesn't
contain the ones requested by the in target script. However, for server
installations all messages are available in the syslog in the utah server side
and those messages are written to the installer syslog in the client side.

One more feature that has been added is the ability to add the
late_command/success_command to the preseed if isn't present. Hence, that line
is no longer needed in the default preseed and has been removed. I believe the
[ "$?" -eq "0" ] command was just a placeholder to ensure that something was
there, but please let me know if that's not the case.

Note that a great deal of effort has been made regarding readability, that is,
templates are written in such a way that the final files (include
/etc/rc.local) contain code easier to read than before. In particular, trailing
backlashes have been removed where there were not needed and indentation has
been preserved to make clear control structures such as while loops.

As usual, I've tested the changes with {desktop,server} {i386,amd64} images and
worked fine. However, I haven't tested different rewriting options which I
think was one of the concerns expressed by Max yesterday. We can discuss today
the use cases we need to cover (I believe nobody is really using it) to make
sure that option works fine.

review: Needs Resubmitting

[Andy Doan (doanac)]

looking at:

+ template = self.template_env.get_template('check-locks-command.jinja2')
+ check_locks_command = template.render()
+ template = self.template_env.get_template('install-commands.jinja2')
+ install_commands = template.render(
+ packages=config.installpackages,
+ check_locks_command=check_locks_command,
+ log_file='/var/log/utah-install')
+ template = self.template_env.get_template(
+ 'utah-latecommand-in-target.jinja2')
+ latecommand = template.render(install_commands=install_commands)

I get a little confused trying to read through all three templates to understand how the file gets constructed. It seems like these 3 templates could become a single template and it would be easier to understand.

[lp:~javier.collado/utah/wrap-latecommand]

822. By Javier Collado on 2013-02-27

Added battery_measurements boolean variable to runlist (defaults to False)

Source branch: lp:~javier.collado/utah/battery_measurements_config

[Javier Collado (javier.collado)]

@Andy

The reason for having three different templates is that the two that are
rendered before the third one are used in multiple places.

In `utah-latecommand-in-target.jinja2`, you'll see that `install_commands` is
used twice (one for installing packages during the installation and the other
one to retry during boot up).

In `install_commands.jinja2` you'll see that `check_locks_command` is used, but
also the same template is used in `install-deb-command.jinja2` by means of an
include statement.

Anyway, I agree on that the code might look overly complicated. The include
statement would be useful to render just one template in the code, but I
haven't been able to get the template contents and then indent it for the sake
of readability. In the jinja documentation I see that maybe this can be done
with macros, so I'm going to give it a try.

[Javier Collado (javier.collado)]

The code has been updated to use macros in the templates and render just a
single template in the code when needed.

review: Needs Resubmitting

[Andy Doan (doanac)]

1 merge conflict:

=== modified file 'debian/changelog'
--- debian/changelog 2013-02-27 08:32:22 +0000
+++ debian/changelog 2013-02-27 11:17:22 +0000
@@ -1,9 +1,18 @@
+<<<<<<< TREE
 utah (0.9ubuntu1) UNRELEASED; urgency=low

   * Added battery_measurements boolean variable to runlist (defaults to False)

  -- Javier Collado <email address hidden> Wed, 27 Feb 2013 09:28:58 +0100

+=======
+utah (0.9ubuntu1) UNRELEASED; urgency=low
+
+ * Added success command failure detection (LP: #1126115)
+

[Andy Doan (doanac)]

I'm basically +1. This check_locks logic seems to be the thing that keeps this a little tricky. I wonder if we shouldn't make that thing its own script and then you wouldn't even need the macro stuff you added. However, then you'd have to copy the script to /target/usr/local/bin/ and other stuff, so my "simplification" might be making this harder. Your choice - I'm fine either way once the merge conflict is fixed.

[lp:~javier.collado/utah/wrap-latecommand]

826. By Javier Collado on 2013-02-22

Moved utah-latecommand script to the latecommand-wrapper script

827. By Javier Collado on 2013-02-22

Refactored utah-latecommand to use functions

The late command script is going to become larger, so functions are used to
group code that is related.

828. By Javier Collado on 2013-02-25

Moved package installation commands to a script that is executed in target

829. By Javier Collado on 2013-02-25

Moved postinstall commands the the in-target script

With this change, the latecommand wrapper contains a call to the utah
latecommand scripts and the commands in the original preseed in a way that is
easier to read.

830. By Javier Collado on 2013-02-25

Replaced echo with logger to log messages to syslog during installation

831. By Javier Collado on 2013-02-25

Refactored installation commands to reuse them properly

In addition to this /etc/rc.local readability has improved.

832. By Javier Collado on 2013-02-25

Moved log function to its own template

833. By Javier Collado on 2013-02-26

Added python-jinja2 dependency

834. By Javier Collado on 2013-02-26

Updated code to create late_command section if not present in the preseed

835. By Javier Collado on 2013-02-26

Added success command failure detection (LP: #1126115)

836. By Javier Collado on 2013-02-27

Refactored templates to use macros

Macros let templates grab content from other templates and apply filters (this
isn't provided by the include statement). This makes code simpler since there's
no need to render a template and pass the result as an argument to another
template.

[Javier Collado (javier.collado)]

I've rebased the changes to fix the merge conflict.

As you said, the script has both advantages and disadvantages, so I prefer to
stick with this solution unless we find some other issue.

I'm merging the changes right away.

review: Approve

=== modified file 'conf/utah/default-preseed.cfg'
--- conf/utah/default-preseed.cfg	2012-08-13 14:16:46 +0000
+++ conf/utah/default-preseed.cfg	2013-02-27 16:06:21 +0000
@@ -37,4 +37,3 @@
 d-i pkgsel/include string openssh-server python-yaml bzr git gdebi-core
 #need this for non-desktop
 d-i finish-install/reboot_in_progress note
-d-i preseed/late_command string [ "$?" -eq "0" ]

=== modified file 'debian/changelog'
--- debian/changelog	2013-02-27 08:32:22 +0000
+++ debian/changelog	2013-02-27 16:06:21 +0000
@@ -1,6 +1,7 @@
 utah (0.9ubuntu1) UNRELEASED; urgency=low
 
   * Added battery_measurements boolean variable to runlist (defaults to False)
+  * Added success command failure detection (LP: #1126115)
 
  -- Javier Collado <[e-mail]>  Wed, 27 Feb 2013 09:28:58 +0100
 

=== modified file 'debian/control'
--- debian/control	2013-01-23 20:31:02 +0000
+++ debian/control	2013-02-27 16:06:21 +0000
@@ -14,7 +14,7 @@
 Architecture: all
 Depends: ${misc:Depends}, ${python:Depends},
          bsdtar, libvirt-bin, lzma,
-         python-apt, python-libvirt,
+         python-apt, python-jinja2, python-libvirt,
          python-netifaces, python-paramiko, python-psutil,
          utah-client (=${binary:Version})
 Recommends: dl-ubuntu-test-iso, kvm
@@ -24,7 +24,7 @@
 Package: utah-all
 Architecture: all
 Depends: ${misc:Depends}, ${python:Depends}, utah-bamboofeeder, utah-cobbler,
-         utah-parser         
+         utah-parser
 Description: Ubuntu Test Automation Harness Complete Package
  Automation framework for testing in Ubuntu, all sections
 
@@ -59,7 +59,7 @@
 Depends: ${misc:Depends}, ${python:Depends}
 Description: Ubuntu Test Automation Harness Common Files
  Automation framework for testing in Ubuntu, common files
- 
+
 Package: utah-parser
 Architecture: all
 Depends: ${misc:Depends}, ${python:Depends},

=== modified file 'templates/casper-preseed-script.jinja2'
--- templates/casper-preseed-script.jinja2	2013-02-20 16:05:59 +0000
+++ templates/casper-preseed-script.jinja2	2013-02-27 16:06:21 +0000
@@ -1,4 +1,5 @@
 #!/bin/sh
-
-cp preseed.cfg utah-ssh-key utah-latecommand /root
+# Copy preseed and late command scripts
+cp preseed.cfg utah-latecommand utah-latecommand-in-target latecommand-wrapper /root
+cp utah-ssh-key /root
 cp 50-utahdefault.conf /root/etc/rsyslog.d

=== modified file 'templates/check-locks-command.jinja2'
--- templates/check-locks-command.jinja2	2013-02-20 15:41:34 +0000
+++ templates/check-locks-command.jinja2	2013-02-27 16:06:21 +0000
@@ -1,9 +1,11 @@
+{% macro check_locks_command() -%}
 {# Check lock files before package installation -#}
-while (fuser /var/lib/dpkg/lock \
-             /var/cache/apt/archives/lock \
-             /var/lib/apt/lists/lock \
-       >/dev/null 2>&1); \
-do \
-    echo "Waiting for dpkg lock to become available"; \
-    sleep 10; \
-done; \
+while fuser /var/lib/dpkg/lock \
+            /var/cache/apt/archives/lock \
+            /var/lib/apt/lists/lock \
+      >/dev/null 2>&1
+do
+    logger -t utah "Waiting for packaging locks to become available..."
+    sleep 10
+done
+{%- endmacro %}

=== added file 'templates/install-commands.jinja2'
--- templates/install-commands.jinja2	1970-01-01 00:00:00 +0000
+++ templates/install-commands.jinja2	2013-02-27 16:06:21 +0000
@@ -0,0 +1,26 @@
+{% macro install_commands(packages, log_file) -%}
+{% include "log-function.jinja2" %}
+
+{% from "check-locks-command.jinja2" import check_locks_command -%}
+# Check lock files before package installation
+check_locks() {
+    {{ check_locks_command() | indent }}
+}
+
+install_package() {
+    package=$1
+    check_locks
+    log "Installing ${package}..."
+    apt-get install -y ${package} --force-yes  >>{{log_file}} 2>&1
+}
+
+install_packages() {
+    log "Installing packages..."
+    for package in $@
+    do
+        install_package ${package}
+    done
+}
+
+install_packages {{packages | join(' ')}}
+{%- endmacro %}

=== modified file 'templates/install-deb-command.jinja2'
--- templates/install-deb-command.jinja2	2013-02-20 18:22:37 +0000
+++ templates/install-deb-command.jinja2	2013-02-27 16:06:21 +0000
@@ -1,2 +1,3 @@
-{% include "check-locks-command.jinja2" %}
+{% from "check-locks-command.jinja2" import check_locks_command -%}
+{{ check_locks_command() }}
 DEBIAN_FRONTEND=noninteractive gdebi -n -q {{deb}}

=== added file 'templates/latecommand-wrapper.jinja2'
--- templates/latecommand-wrapper.jinja2	1970-01-01 00:00:00 +0000
+++ templates/latecommand-wrapper.jinja2	2013-02-27 16:06:21 +0000
@@ -0,0 +1,13 @@
+#!/bin/sh
+set -e
+{% include "log-function.jinja2" %}
+
+log "Running UTAH late command..."
+sh utah-latecommand
+log "Running UTAH late command in-target..."
+in-target sh /tmp/utah-latecommand-in-target
+{% if latecommand -%}
+log "Running original late command..."
+{{latecommand}}
+{% endif -%}
+log "Late command success"

=== added file 'templates/log-function.jinja2'
--- templates/log-function.jinja2	1970-01-01 00:00:00 +0000
+++ templates/log-function.jinja2	2013-02-27 16:06:21 +0000
@@ -0,0 +1,3 @@
+log() {
+    logger -s -t utah "$1" 2>>{{log_file}}
+}

=== removed file 'templates/preseed-install-commands.jinja2'
--- templates/preseed-install-commands.jinja2	2013-02-20 15:41:34 +0000
+++ templates/preseed-install-commands.jinja2	1970-01-01 00:00:00 +0000
@@ -1,5 +0,0 @@
-{% for package_name in package_names -%}
-{% include "check-locks-command.jinja2" %}
-{# Install package -#}
-apt-get install -y --force-yes {{package_name}} >>{{log_file}} 2>&1; \
-{% endfor %}

=== removed file 'templates/preseed-postinstall-commands.jinja2'
--- templates/preseed-postinstall-commands.jinja2	2013-02-20 16:02:11 +0000
+++ templates/preseed-postinstall-commands.jinja2	1970-01-01 00:00:00 +0000
@@ -1,4 +0,0 @@
-sed -i -e '/^exit 0$/i\
-    {{install_commands | indent}}
-'\
-/etc/rc.local;

=== removed file 'templates/preseed-success-command.jinja2'
--- templates/preseed-success-command.jinja2	2013-02-20 15:41:34 +0000
+++ templates/preseed-success-command.jinja2	1970-01-01 00:00:00 +0000
@@ -1,8 +0,0 @@
-{# Note that since the chroot command is passed to sh within single quotes, the
-single quotes inside the chroot command have to be escaped using '"'"'.
-For more information, please refer to:
-http://stackoverflow.com/q/1250079/183066 -#}
-\
-    in-target sh -c '\
-        {{commands | replace('\'', '\'"\'"\'') | indent(8)}}\
-        '; 

=== added file 'templates/utah-latecommand-in-target.jinja2'
--- templates/utah-latecommand-in-target.jinja2	1970-01-01 00:00:00 +0000
+++ templates/utah-latecommand-in-target.jinja2	2013-02-27 16:06:21 +0000
@@ -0,0 +1,12 @@
+#!/bin/sh
+set -e
+{% from "install-commands.jinja2" import install_commands -%}
+{{ install_commands(packages, log_file) }}
+
+log "Adding installation commands to rc.local..."
+sed -i -e '/^exit 0$/i\
+{# Escape backslashes and add new ones for each line to make sed command work -#}
+{{ install_commands(packages, log_file) |
+    replace('\\', '\\\\') |
+    add_backslash }}
+' /etc/rc.local

=== modified file 'templates/utah-latecommand.jinja2'
--- templates/utah-latecommand.jinja2	2013-02-20 16:01:13 +0000
+++ templates/utah-latecommand.jinja2	2013-02-27 16:06:21 +0000
@@ -1,18 +1,33 @@
 #!/bin/sh
-
-ROOTDIR=/target/root/.ssh
-USERDIR=/target/home/{{user}}/.ssh
-
-for DIR in $ROOTDIR $USERDIR
-do
-  mkdir -p $DIR
-  cp utah-ssh-key $DIR/authorized_keys
-  chmod 700 $DIR
-done
-
-chown -R root:root $ROOTDIR
-chown -R 1000:1000 $USERDIR
-
-mkdir -p /target/etc/utah
-echo "{{uuid}}" > /target/etc/utah/uuid
-echo "{{user}}" >> /target/etc/utah/users
+set -e
+{% include "log-function.jinja2" %}
+
+# Copy SSH keys to access to later to provisioned machine
+copy_ssh_keys() {
+    log "Copying UTAH SSH keys to system under test.."
+
+    ROOTDIR=/target/root/.ssh
+    USERDIR=/target/home/{{user}}/.ssh
+
+    for DIR in $ROOTDIR $USERDIR
+    do
+      mkdir -p $DIR
+      cp utah-ssh-key $DIR/authorized_keys
+      chmod 700 $DIR
+    done
+    chown -R root:root $ROOTDIR
+    chown -R 1000:1000 $USERDIR
+}
+
+write_utah_data() {
+    log "Writing UTAH installation data..."
+    mkdir -p /target/etc/utah
+    echo "{{uuid}}" > /target/etc/utah/uuid
+    echo "{{user}}" >> /target/etc/utah/users
+}
+
+copy_ssh_keys
+write_utah_data
+
+log "Copying UTAH latecommmand in-target script..."
+cp utah-latecommand-in-target /target/tmp

=== modified file 'utah/provisioning/provisioning.py'
--- utah/provisioning/provisioning.py	2013-02-20 18:22:37 +0000
+++ utah/provisioning/provisioning.py	2013-02-27 16:06:21 +0000
@@ -209,6 +209,12 @@
         self.template_env = \
             Environment(loader=FileSystemLoader(config.template_dir))
 
+        def add_backslash_filter(value):
+            """Append backslash character to each line"""
+            return '\n'.join(['{}\\'.format(line)
+                              for line in value.splitlines()])
+        self.template_env.filters['add_backslash'] = add_backslash_filter
+
         self.logger.debug('Machine init finished')
 
     def _namesetup(self, name=None):
@@ -779,14 +785,25 @@
         shutil.copyfile(config.sshpublickey,
                         os.path.join(tmpdir, 'initrd.d', 'utah-ssh-key'))
 
-        self.logger.info('Creating latecommand script')
+        self.logger.info('Creating latecommand scripts')
         template = self.template_env.get_template('utah-latecommand.jinja2')
         latecommand = template.render(user=config.user,
-                                      uuid=self.uuid)
+                                      uuid=self.uuid,
+                                      log_file='/target/var/log/utah-install')
         filename = os.path.join(tmpdir, 'initrd.d', 'utah-latecommand')
         with open(filename, 'w') as f:
             f.write(latecommand)
 
+        template = self.template_env.get_template(
+            'utah-latecommand-in-target.jinja2')
+        latecommand = template.render(
+            packages=config.installpackages,
+            log_file='/var/log/utah-install')
+        filename = os.path.join(tmpdir, 'initrd.d',
+                                'utah-latecommand-in-target')
+        with open(filename, 'w') as f:
+            f.write(latecommand)
+
     def _setuppreseed(self, tmpdir=None):
         """
         Rewrite the preseed to include what we need for an automated install
@@ -800,13 +817,7 @@
         if self.rewrite in ['all', 'minimal']:
             with open(self.preseed) as f:
                 preseed = Preseed(f)
-            if 'preseed/late_command' in preseed:
-                # Note that this might change question name
-                # from preseed/latecommand to ubiquity/sucess_command,
-                # so don't move below the call to self._rewrite_success_command
-                self._rewrite_latecommand(preseed)
-            if 'ubiquity/success_command' in preseed:
-                self._rewrite_success_command(preseed)
+            self._rewrite_latecommand(preseed, tmpdir)
             if self.rewrite == 'all':
                 if 'pkgsel/include' in preseed:
                     self._rewrite_pkgsel_include(preseed)
@@ -828,48 +839,35 @@
                 self.rewrite in ['all', 'minimal', 'casperonly']):
             self._preseedcasper(tmpdir=tmpdir)
 
-    def _rewrite_latecommand(self, preseed):
+    def _rewrite_latecommand(self, preseed, tmpdir):
         """
         Rewrite latecommand in preseed
         """
+        # Create a late command question if not present already
+        if not 'preseed/late_command' in preseed:
+            preseed.append('d-i preseed/late_command string')
         question = preseed['preseed/late_command']
+
+        log_file = '/var/log/utah-install'
         if self.installtype == 'desktop':
             self.logger.info('Changing d-i latecommand '
                              'to ubiquity success_command '
                              'and prepending ubiquity lines')
             question.owner = 'ubiquity'
             question.qname = 'ubiquity/success_command'
-            log_file = '/var/log/utah-install'
-
-            template = self.template_env.get_template(
-                'preseed-install-commands.jinja2')
-            install_commands = template.render(
-                package_names=config.installpackages,
-                log_file=log_file)
-            template = self.template_env.get_template(
-                'preseed-postinstall-commands.jinja2')
-            postinstall_commands = template.render(
-                install_commands=install_commands)
-            template = self.template_env.get_template(
-                'preseed-success-command.jinja2')
-            chroot_command = template.render(
-                commands=''.join([install_commands,
-                                  postinstall_commands]))
-            question.value.prepend(chroot_command)
-            question.prepend("ubiquity ubiquity/summary note")
-            question.prepend("ubiquity ubiquity/reboot boolean true")
-        else:
-            self.logger.info('Prepending latecommand')
-            question.value.prepend('\\\n    sh utah-latecommand; ')
-
-    def _rewrite_success_command(self, preseed):
-        """
-        Add utah-latecommand script to ubiquity/success_command
-        in the preseed
-        """
-        self.logger.info('Prepending success_command')
-        question = preseed['ubiquity/success_command']
-        question.value.prepend('\\\n    sh utah-latecommand; ')
+            question.prepend('ubiquity ubiquity/summary note')
+            question.prepend('ubiquity ubiquity/reboot boolean true')
+
+        template = self.template_env.get_template('latecommand-wrapper.jinja2')
+        filename = os.path.join(tmpdir, 'initrd.d', 'latecommand-wrapper')
+        target_log_file = '/target{}'.format(log_file)
+        with open(filename, 'w') as f:
+            f.write(template.render(latecommand=question.value.text,
+                                    log_file=target_log_file))
+        question.value = (
+            'sh latecommand-wrapper || '
+            'logger -s -t utah "Late command failure detected" '
+            '2>>{}'.format(target_log_file))
 
     def _rewrite_pkgsel_include(self, preseed):
         """