bug(deleted jobs) Armada deleting jobs during upgrade

- Additional logging to try to expose bug around deleted jobs
  during an upgrade.
- Cleaner chart diff logging.

Change-Id: I5edfa1857aec417203e73565a39082328e3b677b

armada/cli/apply.py

@@ -181,11 +181,10 @@ class ApplyManifest(CliAction):
 
             for ch in resp[result]:
                 if not result == 'diff':
-                    msg = 'Chart {} was {}ed'.format(ch, result)
+                    msg = 'Chart {} took action: {}'.format(ch, result)
                     self.logger.info(msg)
                 else:
-                    self.logger.info('Chart values diff')
+                    self.logger.info('Chart/values diff: %s', ch)
-                    self.logger.info(ch)
 
     def invoke(self):
         if not self.ctx.obj.get('api', False):

armada/handlers/armada.py

@@ -307,7 +307,6 @@ class Armada(object):
                     LOG.info("Upgrading release %s", release)
                     # extract the installed chart and installed values from the
                     # latest release so we can compare to the intended state
-                    LOG.info("Checking Pre/Post Actions")
                     apply_chart, apply_values = self.find_release_chart(
                         known_releases, prefix_chart)
 
@@ -329,7 +328,7 @@ class Armada(object):
                     # values
                     # TODO(alanmeadows) account for .files differences
                     # once we support those
-
+                    LOG.info('Checking upgrade chart diffs.')
                     upgrade_diff = self.show_diff(
                         chart, apply_chart, apply_values,
                         chartbuilder.dump(), values, msg)
@@ -407,6 +406,7 @@ class Armada(object):
 
             # TODO(MarshM) does this need release/labels/namespace?
             # TODO(MarshM) consider the tiller_timeout according to above logic
+            LOG.info('Wait after Chartgroup (%s) %ssec', desc, tiller_timeout)
             self.tiller.k8s.wait_until_ready(
                 k8s_wait_attempts=self.k8s_wait_attempts,
                 k8s_wait_attempt_sleep=self.k8s_wait_attempt_sleep,
@@ -449,13 +449,14 @@ class Armada(object):
         chart_release = chart.get('release', None)
 
         if len(chart_diff) > 0:
-            LOG.info("Chart Unified Diff (%s)", chart_release)
             diff_msg = []
             for line in chart_diff:
                 diff_msg.append(line)
-                LOG.debug(line)
-
             msg['diff'].append({'chart': diff_msg})
+            pretty_diff = '\n'.join(diff_msg).replace(
+                '\\n', '\n').replace('\n\n', '\n')
+            LOG.info("Found diff in chart (%s)", chart_release)
+            LOG.debug(pretty_diff)
 
         values_diff = list(
             difflib.unified_diff(
@@ -463,12 +464,14 @@ class Armada(object):
                 yaml.safe_dump(target_values).split('\n')))
 
         if len(values_diff) > 0:
-            LOG.info("Values Unified Diff (%s)", chart_release)
             diff_msg = []
             for line in values_diff:
                 diff_msg.append(line)
-                LOG.debug(line)
+            msg['diff'].append({'values': diff_msg})
-                msg['diff'].append({'values': diff_msg})
+            pretty_diff = '\n'.join(diff_msg).replace(
+                '\\n', '\n').replace('\n\n', '\n')
+            LOG.info("Found diff in chart values (%s)", chart_release)
+            LOG.debug(pretty_diff)
 
         result = (len(chart_diff) > 0) or (len(values_diff) > 0)
 

armada/handlers/k8s.py

@@ -251,13 +251,14 @@ class K8s(object):
                 timeout=deadline_remaining)
 
             if timed_out:
-                LOG.info('Timed out waiting for pods: %s', unready_pods)
+                LOG.info('Timed out waiting for pods: %s',
+                         sorted(unready_pods))
                 return False
 
             if modified_pods:
                 successes = 0
                 LOG.debug('Continuing to wait, found modified pods: %s',
-                          modified_pods)
+                          sorted(modified_pods))
             else:
                 successes += 1
                 LOG.debug('Found no modified pods this attempt. successes=%d',

armada/handlers/tiller.py

@@ -177,7 +177,7 @@ class Tiller(object):
                                          metadata=self.metadata)
 
         for y in release_list:
-            LOG.debug('Found release: %s', y.releases)
+            # LOG.debug('Found release: %s', y.releases
             releases.extend(y.releases)
 
         return releases
@@ -283,7 +283,7 @@ class Tiller(object):
                          latest_release.info.status.code)))
             except IndexError:
                 continue
-        LOG.debug('List of Helm Charts from Latest Releases: %s', charts)
+        # LOG.debug('List of Helm Charts from Latest Releases: %s', charts)
         return charts
 
     def update_release(self, chart, release, namespace,
@@ -324,10 +324,12 @@ class Tiller(object):
                 wait=wait,
                 timeout=timeout)
 
-            stub.UpdateRelease(
+            update_msg = stub.UpdateRelease(
                 release_request, rel_timeout + GRPC_EPSILON,
                 metadata=self.metadata)
+            return update_msg
         except Exception:
+            LOG.exception('Error while updating release %s', release)
             status = self.get_release_status(release)
             raise ex.ReleaseException(release, status, 'Upgrade')
 
@@ -365,10 +367,12 @@ class Tiller(object):
                 wait=wait,
                 timeout=timeout)
 
-            return stub.InstallRelease(
+            install_msg = stub.InstallRelease(
                 release_request, rel_timeout + GRPC_EPSILON,
                 metadata=self.metadata)
+            return install_msg
         except Exception:
+            LOG.exception('Error while installing release %s', release)
             status = self.get_release_status(release)
             raise ex.ReleaseException(release, status, 'Install')
 
@@ -408,6 +412,7 @@ class Tiller(object):
                 return self.get_release_status(release)
 
         except Exception:
+            LOG.exception('Error while testing release %s', release)
             status = self.get_release_status(release)
             raise ex.ReleaseException(release, status, 'Test')
 
@@ -423,7 +428,6 @@ class Tiller(object):
             stub = ReleaseServiceStub(self.channel)
             status_request = GetReleaseStatusRequest(
                 name=release, version=version)
-            LOG.debug('GetReleaseStatusRequest= %s', status_request)
 
             release_status = stub.GetReleaseStatus(
                 status_request, self.timeout, metadata=self.metadata)
@@ -445,7 +449,6 @@ class Tiller(object):
             stub = ReleaseServiceStub(self.channel)
             status_request = GetReleaseContentRequest(
                 name=release, version=version)
-            LOG.debug('GetReleaseContentRequest= %s', status_request)
 
             release_content = stub.GetReleaseContent(
                 status_request, self.timeout, metadata=self.metadata)
@@ -466,7 +469,6 @@ class Tiller(object):
             LOG.debug('Getting Tiller version, with timeout=%s', self.timeout)
             tiller_version = stub.GetVersion(
                 release_request, self.timeout, metadata=self.metadata)
-            LOG.debug('Got Tiller version response: %s', tiller_version)
 
             tiller_version = getattr(tiller_version.Version, 'sem_ver', None)
             LOG.debug('Got Tiller version %s', tiller_version)
@@ -496,6 +498,7 @@ class Tiller(object):
                 release_request, self.timeout, metadata=self.metadata)
 
         except Exception:
+            LOG.exception('Error while uninstalling release %s', release)
             status = self.get_release_status(release)
             raise ex.ReleaseException(release, status, 'Delete')