Store build logs automatically

This updates the builder to store individual build logs in dedicated
files, one per build, named for the image and build id.  Old logs are
automatically pruned.  By default, they are stored in
/var/log/nodepool/builds, but this can be changed.

This removes the need to specially configure logging handler for the
image build logs.

Change-Id: Ia7415d2fbbb320f8eddc4e46c3a055414df5f997

.zuul.yaml

@@ -27,6 +27,8 @@
         s-proxy: false
       devstack_plugins:
         nodepool: https://git.openstack.org/openstack-infra/nodepool
+      zuul_copy_output:
+        '/var/log/nodepool/builds': 'logs'
 
 - job:
     name: nodepool-functional-py35

devstack/plugin.sh

@@ -168,6 +168,9 @@ EOF
 EOF
     sudo mv /tmp/secure.conf $NODEPOOL_SECURE
 
+    sudo mkdir /var/log/nodepool
+    sudo chown -R stack:stack /var/log/nodepool
+
     if use_library_from_git "glean"; then
         git --git-dir=$DEST/glean/.git checkout -b devstack
         DIB_GLEAN_INSTALLTYPE="DIB_INSTALLTYPE_simple_init: 'repo'"

doc/source/configuration.rst

@@ -65,6 +65,34 @@ Example::
 
   images-dir: /path/to/images/dir
 
+.. _build-log-dir:
+
+build-log-dir
+-------------
+
+The builder will store build logs in this directory.  It will create
+one file for each build, named `<image>-<build-id>.log`; for example,
+`fedora-0000000004.log`.  It defaults to ``/var/log/nodepool/builds``.
+
+Example::
+
+  build-log-dir: /path/to/log/dir
+
+.. _build-log-retention:
+
+build-log-retention
+-------------------
+
+At the start of each build, the builder will remove old build logs if
+they exceed a certain number.  This option specifies how many will be
+kept (usually you will see one more, as deletion happens before
+starting a new build).  By default, the last 7 old build logs are
+kept.
+
+Example::
+
+  build-log-retention: 14
+
 zookeeper-servers
 -----------------
 Lists the ZooKeeper servers uses for coordinating information between

nodepool/builder.py

@@ -547,6 +547,29 @@ class BuildWorker(BaseWorker):
         self.name = 'BuildWorker.%s' % name
         self.dib_cmd = dib_cmd
 
+    def _getBuildLogRoot(self, name):
+        log_dir = self._config.build_log_dir
+        if not log_dir:
+            log_dir = '/var/log/nodepool/builds'
+        if not os.path.exists(log_dir):
+            os.makedirs(log_dir)
+        return log_dir
+
+    def _pruneBuildLogs(self, name):
+        log_dir = self._getBuildLogRoot(name)
+        keep = max(self._config.build_log_retention, 1)
+        existing = sorted(os.listdir(log_dir))
+        existing = [f for f in existing if f.startswith(name)]
+        delete = existing[:0 - keep]
+        for f in delete:
+            fp = os.path.join(log_dir, f)
+            self.log.info("Deleting old build log %s" % (fp,))
+            os.unlink(fp)
+
+    def _getBuildLog(self, name, build_id):
+        log_dir = self._getBuildLogRoot(name)
+        return os.path.join(log_dir, '%s-%s.log' % (name, build_id))
+
     def _checkForScheduledImageUpdates(self):
         '''
         Check every DIB image to see if it has aged out and needs rebuilt.
@@ -714,10 +737,11 @@ class BuildWorker(BaseWorker):
                (self.dib_cmd, img_types, qemu_img_options, filename,
                 img_elements))
 
-        log = logging.getLogger("nodepool.image.build.%s" %
+        self._pruneBuildLogs(diskimage.name)
-                                (diskimage.name,))
+        log_fn = self._getBuildLog(diskimage.name, build_id)
 
-        self.log.info('Running %s' % cmd)
+        self.log.info('Running %s' % (cmd,))
+        self.log.info('Logging to %s' % (log_fn,))
 
         try:
             p = subprocess.Popen(
@@ -730,13 +754,17 @@ class BuildWorker(BaseWorker):
                 "Failed to exec '%s'. Error: '%s'" % (cmd, e.strerror)
             )
 
+        with open(log_fn, 'wb') as log:
             while True:
                 ln = p.stdout.readline()
-            log.info(ln.strip())
+                log.write(ln)
+                log.flush()
                 if not ln:
                     break
 
-        p.wait()
+            rc = p.wait()
+            m = "Exit code: %s\n" % rc
+            log.write(m.encode('utf8'))
 
         # It's possible the connection to the ZK cluster could have been
         # interrupted during the build. If so, wait for it to return.

nodepool/cmd/config_validator.py

@@ -58,6 +58,8 @@ class ConfigValidator:
             'webapp': webapp,
             'elements-dir': str,
             'images-dir': str,
+            'build-log-dir': str,
+            'build-log-retention': int,
             'zookeeper-servers': [{
                 'host': str,
                 'port': int,

nodepool/config.py

@@ -110,6 +110,8 @@ def loadConfig(config_path):
     newconfig.labels = {}
     newconfig.elementsdir = config.get('elements-dir')
     newconfig.imagesdir = config.get('images-dir')
+    newconfig.build_log_dir = config.get('build-log-dir')
+    newconfig.build_log_retention = config.get('build-log-retention', 7)
     newconfig.provider_managers = {}
     newconfig.zookeeper_servers = {}
     newconfig.diskimages = {}

nodepool/tests/__init__.py

@@ -286,18 +286,22 @@ class DBTestCase(BaseTestCase):
         if images_dir is None:
             images_dir = fixtures.TempDir()
             self.useFixture(images_dir)
+        build_log_dir = fixtures.TempDir()
+        self.useFixture(build_log_dir)
         configfile = os.path.join(os.path.dirname(__file__),
                                   'fixtures', filename)
         (fd, path) = tempfile.mkstemp()
         with open(configfile, 'rb') as conf_fd:
             config = conf_fd.read().decode('utf8')
             data = config.format(images_dir=images_dir.path,
+                                 build_log_dir=build_log_dir.path,
                                  zookeeper_host=self.zookeeper_host,
                                  zookeeper_port=self.zookeeper_port,
                                  zookeeper_chroot=self.zookeeper_chroot)
             os.write(fd, data.encode('utf8'))
         os.close(fd)
         self._config_images_dir = images_dir
+        self._config_build_log_dir = build_log_dir
         validator = ConfigValidator(path)
         validator.validate()
         return path

nodepool/tests/fixtures/disabled_provider.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/info_cmd_two_provider.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/info_cmd_two_provider_remove.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/integration_noocc.yaml

@@ -1,4 +1,5 @@
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: localhost

nodepool/tests/fixtures/integration_occ.yaml

@@ -1,4 +1,5 @@
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: localhost

nodepool/tests/fixtures/launcher_two_provider.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/launcher_two_provider_max_1.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/launcher_two_provider_remove.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/leaked_node.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/leaked_node_nodepool_id.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/multi_drivers.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/multiple_pools.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node.yaml

@@ -1,5 +1,7 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
+build-log-retention: 1
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_auto_floating_ip.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_az.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_boot_from_volume.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_cmd.yaml

@@ -1,4 +1,5 @@
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_disabled_label.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_diskimage_fail.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_diskimage_only.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_diskimage_pause.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_flavor_name.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_image_upload_pause.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_ipv6.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_label_provider.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_launch_retry.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_lost_requests.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_many_labels.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_max_ready_age.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_min_ready_capacity.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_net_name.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_no_min_ready.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_quota_cloud.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_quota_pool_cores.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_quota_pool_instances.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_quota_pool_ram.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_two_image.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_two_image_remove.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_two_provider.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_two_provider_remove.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_unmanaged_image.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_upload_fail.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_vhd.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/node_vhd_and_qcow2.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/pause_declined_1.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/pause_declined_2.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/secure_file_config.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: invalid_host

nodepool/tests/fixtures/unmanaged_image_provider_name.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/fixtures/wedge_test.yaml

@@ -1,5 +1,6 @@
 elements-dir: .
 images-dir: '{images_dir}'
+build-log-dir: '{build_log_dir}'
 
 zookeeper-servers:
   - host: {zookeeper_host}

nodepool/tests/test_builder.py

@@ -184,12 +184,18 @@ class TestNodePoolBuilder(tests.DBTestCase):
         configfile = self.setup_config('node.yaml')
         self.useBuilder(configfile)
         build = self.waitForBuild('fake-image', '0000000001')
+        log_path1 = os.path.join(self._config_build_log_dir.path,
+                                 'fake-image-0000000001.log')
+        self.assertTrue(os.path.exists(log_path1))
         image = self.waitForImage('fake-provider', 'fake-image')
         # Expire rebuild-age (default: 1day) to force a new build.
         build.state_time -= expire
         with self.zk.imageBuildLock('fake-image', blocking=True, timeout=1):
             self.zk.storeBuild('fake-image', build, '0000000001')
         self.waitForBuild('fake-image', '0000000002')
+        log_path2 = os.path.join(self._config_build_log_dir.path,
+                                 'fake-image-0000000002.log')
+        self.assertTrue(os.path.exists(log_path2))
         self.waitForImage('fake-provider', 'fake-image', [image])
         builds = self.zk.getBuilds('fake-image', zk.READY)
         self.assertEqual(len(builds), 2)
@@ -205,6 +211,16 @@ class TestNodePoolBuilder(tests.DBTestCase):
             self.zk.storeBuild('fake-image', build, '0000000002')
         self.waitForBuildDeletion('fake-image', '0000000001')
         self.waitForBuild('fake-image', '0000000003')
+        log_path1 = os.path.join(self._config_build_log_dir.path,
+                                 'fake-image-0000000001.log')
+        log_path2 = os.path.join(self._config_build_log_dir.path,
+                                 'fake-image-0000000002.log')
+        log_path3 = os.path.join(self._config_build_log_dir.path,
+                                 'fake-image-0000000003.log')
+        # Our log retention is set to 1, so the first log should be deleted.
+        self.assertFalse(os.path.exists(log_path1))
+        self.assertTrue(os.path.exists(log_path2))
+        self.assertTrue(os.path.exists(log_path3))
         builds = self.zk.getBuilds('fake-image', zk.READY)
         self.assertEqual(len(builds), 2)