Merge lp:~blake-rouse/maas/fix-1387133-1.7 into lp:maas/1.7

[Blake Rouse]

Handle wierd race that will delete a synced boot images. Add more logging to the importing of images on the region. Enable simplestreams to log to maas-django.log, without modifing the maas_local_settings.py file.

Backport: https://code.launchpad.net/~blake-rouse/maas/fix-1387133/+merge/240132

[Blake Rouse (blake-rouse)]

Self-approve.

Already approved for 1.7 landing here: https://code.launchpad.net/~blake-rouse/maas/fix-1387133/+merge/240132

review: Approve

[Blake Rouse (blake-rouse)]

review: Approve

[Andres Rodriguez (andreserl)]

This is a huge diff and I see merge conflcist. Can you check that this is
the correct branch?
On Oct 30, 2014 2:50 PM, "Blake Rouse" <email address hidden> wrote:

> Review: Approve
>
> Self-approve.
>
> Already approved for 1.7 landing here:
> https://code.launchpad.net/~blake-rouse/maas/fix-1387133/+merge/240132
> --
> https://code.launchpad.net/~blake-rouse/maas/fix-1387133-1.7/+merge/240153
> You are subscribed to branch lp:maas.
>

[Blake Rouse (blake-rouse)]

Yeah it was incorrect, I fixed the MP.

On Thu, Oct 30, 2014 at 3:42 PM, Andres Rodriguez <email address hidden>
wrote:

> This is a huge diff and I see merge conflcist. Can you check that this is
> the correct branch?
> On Oct 30, 2014 2:50 PM, "Blake Rouse" <email address hidden> wrote:
>
>> Review: Approve
>>
>> Self-approve.
>>
>> Already approved for 1.7 landing here:
>> https://code.launchpad.net/~blake-rouse/maas/fix-1387133/+merge/240132
>> --
>> https://code.launchpad.net/~blake-rouse/maas/fix-1387133-1.7/+merge/240153
>> You are subscribed to branch lp:maas.
>>
>

=== modified file 'src/maas/__init__.py'
--- src/maas/__init__.py	2014-08-13 21:49:35 +0000
+++ src/maas/__init__.py	2014-10-30 18:49:24 +0000
@@ -15,6 +15,7 @@
 __all__ = [
     "import_settings",
     "import_local_settings",
+    "log_sstreams",
     ]
 
 import sys
@@ -59,6 +60,25 @@
         target.update(source)
 
 
+def log_sstreams(LOGGING):
+    """Turn on simplestreams logging.
+
+    Copies the exact logging configuration for maasserver into sstreams,
+    unless a sstreams config already exists.
+    """
+    if 'loggers' not in LOGGING:
+        # No loggers in LOGGING, can't do anthing.
+        return
+    if 'sstreams' in LOGGING['loggers']:
+        # Already have a simplestreams config for logging.
+        return
+    if 'maasserver' not in LOGGING['loggers']:
+        # No maasserver logger present to copy, no way of know what it
+        # should be set to.
+        return
+    LOGGING['loggers']['sstreams'] = LOGGING['loggers']['maasserver']
+
+
 try:
     import maasfascist
     maasfascist  # Silence lint.

=== modified file 'src/maas/demo.py'
--- src/maas/demo.py	2014-09-24 14:54:56 +0000
+++ src/maas/demo.py	2014-10-30 18:49:24 +0000
@@ -73,6 +73,10 @@
         'twisted': {
             'handlers': ['console'],
             'propagate': True,
+        },
+        'sstreams': {
+            'handlers': ['console'],
+            'propagate': True,
         }
     },
 }

=== modified file 'src/maas/settings.py'
--- src/maas/settings.py	2014-10-15 20:39:07 +0000
+++ src/maas/settings.py	2014-10-30 18:49:24 +0000
@@ -19,7 +19,10 @@
 # Use new style url tag:
 # https://docs.djangoproject.com/en/dev/releases/1.3/#changes-to-url-and-ssi
 import django.template
-from maas import import_local_settings
+from maas import (
+    import_local_settings,
+    log_sstreams,
+    )
 from maas.monkey import patch_get_script_prefix
 from metadataserver.address import guess_server_host
 from provisioningserver.utils import compose_URL
@@ -318,3 +321,6 @@
 
 # Patch the get_script_prefix method to allow twisted to work with django.
 patch_get_script_prefix()
+
+# Enable the logging of simplestreams
+log_sstreams(LOGGING)

=== modified file 'src/maasserver/bootresources.py'
--- src/maasserver/bootresources.py	2014-10-28 14:17:28 +0000
+++ src/maasserver/bootresources.py	2014-10-30 18:49:24 +0000
@@ -395,6 +395,11 @@
                 rtype=BOOT_RESOURCE_TYPE.SYNCED)
             }
 
+        # XXX blake_r 2014-10-30 bug=1387133: We store a copy of the resources
+        # to delete, so we can check if all the same resources will be delete
+        # in the finalize call.
+        self._init_resources_to_delete = set(self._resources_to_delete)
+
     def prevent_resource_deletion(self, resource):
         """Remove the `BootResource` from the resources to delete list.
 
@@ -605,7 +610,7 @@
         else:
             ident = self.get_resource_file_log_identifier(
                 rfile, resource_set, resource)
-            maaslog.debug('Boot resource already up-to-date %s.' % ident)
+            maaslog.debug('Boot image already up-to-date %s.', ident)
 
     def write_content(self, rfile, reader):
         """Writes the data from the given reader, into the object storage
@@ -613,7 +618,7 @@
         ident = self.get_resource_file_log_identifier(rfile)
         cksummer = sutil.checksummer(
             {'sha256': rfile.largefile.sha256})
-        maaslog.debug("Syncing boot resource %s." % ident)
+        maaslog.debug("Finalizing boot image %s.", ident)
 
         # Write the contents into the database, while calculating the sha256
         # hash for the read data.
@@ -630,14 +635,13 @@
             # simplestreams is telling us it should be. This resource file
             # will be deleted since it is corrupt.
             maaslog.error(
-                "Failed to sync boot resource %s. Unexpected "
-                "checksum '%s' (found: %s expected: %s)" % (
-                    ident, cksummer.algorithm,
-                    cksummer.hexdigest(), cksummer.expected,
-                    ))
+                "Failed to finalize boot image %s. Unexpected "
+                "checksum '%s' (found: %s expected: %s)",
+                ident, cksummer.algorithm,
+                cksummer.hexdigest(), cksummer.expected)
             rfile.delete()
         else:
-            maaslog.debug('Finished syncing boot resource %s.' % ident)
+            maaslog.debug('Finalized boot image %s.', ident)
 
     @transactional
     def write_content_thread(self, rid, reader):
@@ -689,6 +693,9 @@
                     rtype=BOOT_RESOURCE_TYPE.SYNCED,
                     name=name, architecture=architecture))
             if delete_resource is not None:
+                maaslog.debug(
+                    "Deleting boot image %s.",
+                    self.get_resource_identity(delete_resource))
                 delete_resource.delete()
 
     @transactional
@@ -727,6 +734,25 @@
         This will remove the un-needed `BootResource`'s and write the
         file data into the large object store.
         """
+        # XXX blake_r 2014-10-30 bug=1387133: A scenario can occur where insert
+        # never gets called by the writer, causing this method to delete all
+        # of the synced resources. The actual cause of this issue is unknown,
+        # but we want to handle the case or all the images will be deleted and
+        # no nodes will be able to be provisioned.
+        maaslog.debug(
+            "Finalize will delete %d images(s).",
+            len(self._resources_to_delete))
+        maaslog.debug(
+            "Finalize will save %d new images(s).",
+            len(self._content_to_finalize))
+        if (self._resources_to_delete == self._init_resources_to_delete and
+                len(self._content_to_finalize) == 0):
+            maaslog.error(
+                "Finalization of imported images skipped, "
+                "or all %s synced images would be deleted.",
+                self._resources_to_delete)
+            close_old_connections()
+            return
         self.resource_cleaner()
         self.perform_write()
         self.resource_set_cleaner()
@@ -799,13 +825,16 @@
     :param product_mapping: A `ProductMapping` describing the resources to be
         downloaded.
     """
+    maaslog.debug("Initializing BootResourceStore.")
     if store is None:
         store = BootResourceStore()
     assert isinstance(store, BootResourceStore)
     for source in sources:
+        maaslog.info("Importing images from source: %s", source['url'])
         download_boot_resources(
             source['url'], store, product_mapping,
             keyring_file=source.get('keyring'))
+    maaslog.debug("Finalizing BootResourceStore.")
     store.finalize()
 
 
@@ -851,6 +880,7 @@
     """
     # If the lock is already held, then import is already running.
     if locks.import_images.is_locked():
+        maaslog.debug("Skipping import as another import is already running.")
         return
 
     # If we're not being forced, don't sync unless we've already done it once
@@ -878,7 +908,8 @@
         # Timeout occurred, kill the thread and exit.
         kill_event.set()
         lock_thread.join()
-        maaslog.error("Another import task is already running.")
+        maaslog.debug(
+            "Unable to grab import lock, another import is already running.")
         return
 
     try:
@@ -890,20 +921,24 @@
             env['http_proxy'] = http_proxy
             env['https_proxy'] = http_proxy
         with environment_variables(env), tempdir('keyrings') as keyrings_path:
-            maaslog.info("Started importing of boot resources.")
             sources = get_boot_sources()
             sources = write_all_keyrings(keyrings_path, sources)
+            maaslog.info(
+                "Started importing of boot images from %d source(s).",
+                len(sources))
 
             image_descriptions = download_all_image_descriptions(sources)
             if image_descriptions.is_empty():
                 maaslog.warn(
-                    "Unable to import boot resources, no image "
+                    "Unable to import boot images, no image "
                     "descriptions avaliable.")
                 return
             product_mapping = map_products(image_descriptions)
 
             download_all_boot_resources(sources, product_mapping)
-            maaslog.info("Finished importing of boot resources.")
+            maaslog.info(
+                "Finished importing of boot images from %d source(s).",
+                len(sources))
 
         # Tell the clusters to download the data from the region.
         NodeGroup.objects.import_boot_images_on_accepted_clusters()

=== modified file 'src/maasserver/tests/test_bootresources.py'
--- src/maasserver/tests/test_bootresources.py	2014-10-28 14:17:28 +0000
+++ src/maasserver/tests/test_bootresources.py	2014-10-30 18:49:24 +0000
@@ -757,15 +757,40 @@
         store.write_content(rfile, reader)
         self.assertFalse(BootResourceFile.objects.filter(id=rfile.id).exists())
 
-    def test_finalize_calls_methods(self):
-        store = BootResourceStore()
-        mock_resource_cleaner = self.patch(store, 'resource_cleaner')
-        mock_perform_write = self.patch(store, 'perform_write')
-        mock_resource_set_cleaner = self.patch(store, 'resource_set_cleaner')
-        store.finalize()
-        self.assertTrue(mock_resource_cleaner, MockCalledOnceWith())
-        self.assertTrue(mock_perform_write, MockCalledOnceWith())
-        self.assertTrue(mock_resource_set_cleaner, MockCalledOnceWith())
+    def test_finalize_does_nothing_if_resources_to_delete_hasnt_changed(self):
+        factory.make_BootResource(rtype=BOOT_RESOURCE_TYPE.SYNCED)
+        store = BootResourceStore()
+        mock_resource_cleaner = self.patch(store, 'resource_cleaner')
+        mock_perform_write = self.patch(store, 'perform_write')
+        mock_resource_set_cleaner = self.patch(store, 'resource_set_cleaner')
+        store.finalize()
+        self.expectThat(mock_resource_cleaner, MockNotCalled())
+        self.expectThat(mock_perform_write, MockNotCalled())
+        self.expectThat(mock_resource_set_cleaner, MockNotCalled())
+
+    def test_finalize_calls_methods_if_new_resources_need_to_be_saved(self):
+        factory.make_BootResource(rtype=BOOT_RESOURCE_TYPE.SYNCED)
+        store = BootResourceStore()
+        store._content_to_finalize = [sentinel.content]
+        mock_resource_cleaner = self.patch(store, 'resource_cleaner')
+        mock_perform_write = self.patch(store, 'perform_write')
+        mock_resource_set_cleaner = self.patch(store, 'resource_set_cleaner')
+        store.finalize()
+        self.expectThat(mock_resource_cleaner, MockCalledOnceWith())
+        self.expectThat(mock_perform_write, MockCalledOnceWith())
+        self.expectThat(mock_resource_set_cleaner, MockCalledOnceWith())
+
+    def test_finalize_calls_methods_if_resources_to_delete_has_changed(self):
+        factory.make_BootResource(rtype=BOOT_RESOURCE_TYPE.SYNCED)
+        store = BootResourceStore()
+        store._resources_to_delete = set()
+        mock_resource_cleaner = self.patch(store, 'resource_cleaner')
+        mock_perform_write = self.patch(store, 'perform_write')
+        mock_resource_set_cleaner = self.patch(store, 'resource_set_cleaner')
+        store.finalize()
+        self.expectThat(mock_resource_cleaner, MockCalledOnceWith())
+        self.expectThat(mock_perform_write, MockCalledOnceWith())
+        self.expectThat(mock_resource_set_cleaner, MockCalledOnceWith())
 
 
 class TestBootResourceTransactional(TransactionTestCase):
@@ -1036,7 +1061,7 @@
     def test__import_resources_calls_functions_with_correct_parameters(self):
         fake_write_all_keyrings = self.patch(
             bootresources, 'write_all_keyrings')
-        fake_write_all_keyrings.return_value = sentinel.sources
+        fake_write_all_keyrings.return_value = [sentinel.source]
         fake_image_descriptions = self.patch(
             bootresources, 'download_all_image_descriptions')
         descriptions = Mock()
@@ -1055,13 +1080,13 @@
             MockCalledOnceWith(ANY, []))
         self.assertThat(
             fake_image_descriptions,
-            MockCalledOnceWith(sentinel.sources))
+            MockCalledOnceWith([sentinel.source]))
         self.assertThat(
             fake_map_products,
             MockCalledOnceWith(descriptions))
         self.assertThat(
             fake_download_all_boot_resources,
-            MockCalledOnceWith(sentinel.sources, sentinel.mapping))
+            MockCalledOnceWith([sentinel.source], sentinel.mapping))
 
     def test__import_resources_has_env_GNUPGHOME_set(self):
         fake_image_descriptions = self.patch(