Download certs on FT GS after check_certificates only when missing fr…

…om disk (#2907) (#2913)

* Download certs on FT GS only when missing from disk

* Improve telemetry for inconsistent GS

* Fix string format

(cherry picked from commit c13f750)

azurelinuxagent/common/protocol/goal_state.py

@@ -208,9 +208,15 @@ def update(self, silent=False):
         try:
             self._update(force_update=False)
         except GoalStateInconsistentError as e:
-            self.logger.warn("Detected an inconsistency in the goal state: {0}", ustr(e))
+            message = "Detected an inconsistency in the goal state: {0}".format(ustr(e))
+            self.logger.warn(message)
+            add_event(op=WALAEventOperation.GoalState, is_success=False, message=message)
+
             self._update(force_update=True)
-            self.logger.info("The goal state is consistent")
+
+            message = "The goal state is consistent"
+            self.logger.info(message)
+            add_event(op=WALAEventOperation.GoalState, message=message)
 
     def _update(self, force_update):
         #
@@ -219,7 +225,9 @@ def _update(self, force_update):
         timestamp = datetime.datetime.utcnow()
 
         if force_update:
-            self.logger.info("Refreshing goal state and vmSettings")
+            message = "Refreshing goal state and vmSettings"
+            self.logger.info(message)
+            add_event(op=WALAEventOperation.GoalState, message=message)
 
         incarnation, xml_text, xml_doc = GoalState._fetch_goal_state(self._wire_client)
         goal_state_updated = force_update or incarnation != self._incarnation
@@ -292,11 +300,9 @@ def _update(self, force_update):
         #
         if self._extensions_goal_state.source == GoalStateSource.FastTrack and self._goal_state_properties & GoalStateProperties.Certificates:
             self._check_certificates()
+            self._check_and_download_missing_certs_on_disk()
 
     def _check_certificates(self):
-        # Re-download certificates in case they have been removed from disk since last download
-        if self._certs_uri is not None:
-            self._download_certificates(self._certs_uri)
         # Check that certificates needed by extensions are in goal state certs.summary
         for extension in self.extensions_goal_state.extensions:
             for settings in extension.settings:
@@ -321,6 +327,32 @@ def _download_certificates(self, certs_uri):
         self._history.save_certificates(json.dumps(certs.summary))
         return certs
 
+    def _check_and_download_missing_certs_on_disk(self):
+        # Re-download certificates if any have been removed from disk since last download
+        if self._certs_uri is not None:
+            certificates = self.certs.summary
+            certs_missing_from_disk = False
+
+            for c in certificates:
+                cert_path = os.path.join(conf.get_lib_dir(), c['thumbprint'] + '.crt')
+                if not os.path.isfile(cert_path):
+                    certs_missing_from_disk = True
+                    message = "Certificate required by goal state is not on disk: {0}".format(cert_path)
+                    self.logger.info(message)
+                    add_event(op=WALAEventOperation.GoalState, message=message)
+            if certs_missing_from_disk:
+                # Try to re-download certs. Sometimes download may fail if certs_uri is outdated/contains wrong
+                # container id (for example, when the VM is moved to a new container after resuming from
+                # hibernation). If download fails we should report and continue with goal state processing, as some
+                # extensions in the goal state may succeed.
+                try:
+                    self._download_certificates(self._certs_uri)
+                except Exception as e:
+                    message = "Unable to download certificates. Goal state processing will continue, some " \
+                              "extensions requiring certificates may fail. Error: {0}".format(ustr(e))
+                    self.logger.warn(message)
+                    add_event(op=WALAEventOperation.GoalState, is_success=False, message=message)
+
     def _restore_wire_server_goal_state(self, incarnation, xml_text, xml_doc, vm_settings_support_stopped_error):
         msg = 'The HGAP stopped supporting vmSettings; will fetched the goal state from the WireServer.'
         self.logger.info(msg)

tests/common/protocol/test_goal_state.py

@@ -157,7 +157,7 @@ def http_get_handler(url, *_, **__):
             protocol.set_http_handlers(http_get_handler=None)
             goal_state.update()
             self._assert_directory_contents(
-                self._find_history_subdirectory("234-987"), ["VmSettings.json", "Certificates.json"])
+                self._find_history_subdirectory("234-987"), ["VmSettings.json"])
 
     def test_it_should_redact_the_protected_settings_when_saving_to_the_history_directory(self):
         with mock_wire_protocol(wire_protocol_data.DATA_FILE_VM_SETTINGS) as protocol:
@@ -464,7 +464,7 @@ def http_get_handler(url, *_, **__):
             goal_state = GoalState(protocol.client)
 
             self.assertEqual(2, protocol.mock_wire_data.call_counts['goalstate'], "There should have been exactly 2 requests for the goal state (original + refresh)")
-            self.assertEqual(4, http_get_handler.certificate_requests, "There should have been exactly 4 requests for the goal state certificates (2x original + 2x refresh)")
+            self.assertEqual(2, http_get_handler.certificate_requests, "There should have been exactly 2 requests for the goal state certificates (original + refresh)")
 
             thumbprints = [c.thumbprint for c in goal_state.certs.cert_list.certificates]