Improvements in waagent.log (#2558) (#2564)

* Improvements in waagent.log

* fix function call

* update comment

* typo

Co-authored-by: narrieta <narrieta>
(cherry picked from commit fa8e370)

azurelinuxagent/common/protocol/extensions_goal_state_from_vm_settings.py

@@ -289,7 +289,7 @@ def _parse_extensions(self, vm_settings):
         #             "settingsSeqNo": 0,
         #             "settings": [
         #                 {
-        #                     "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+        #                     "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
         #                     "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEFpB/HKM/7evRk+DBz754wUwDQYJKoZIhvcNAQEBBQAEggEADPJwniDeIUXzxNrZCloitFdscQ59Bz1dj9DLBREAiM8jmxM0LLicTJDUv272Qm/4ZQgdqpFYBFjGab/9MX+Ih2x47FkVY1woBkckMaC/QOFv84gbboeQCmJYZC/rZJdh8rCMS+CEPq3uH1PVrvtSdZ9uxnaJ+E4exTPPviIiLIPtqWafNlzdbBt8HZjYaVw+SSe+CGzD2pAQeNttq3Rt/6NjCzrjG8ufKwvRoqnrInMs4x6nnN5/xvobKIBSv4/726usfk8Ug+9Q6Benvfpmre2+1M5PnGTfq78cO3o6mI3cPoBUjp5M0iJjAMGeMt81tyHkimZrEZm6pLa4NQMOEjArBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECC5nVaiJaWt+gAhgeYvxUOYHXw==",
         #                     "publicSettings": "{\"GCS_AUTO_CONFIG\":true}"
         #                 }

azurelinuxagent/common/protocol/goal_state.py

@@ -18,6 +18,7 @@
 import os
 import re
 import time
+import json
 
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
@@ -145,6 +146,7 @@ def update(self):
             return
 
         if vm_settings_updated:
+            logger.info('')
             logger.info("Fetched new vmSettings [HostGAPlugin correlation ID: {0} eTag: {1} source: {2}]", vm_settings.hostga_plugin_correlation_id, vm_settings.etag, vm_settings.source)
         # Ignore the vmSettings if their source is Fabric (processing a Fabric goal state may require the tenant certificate and the vmSettings don't include it.)
         if vm_settings is not None and vm_settings.source == GoalStateSource.Fabric:
@@ -184,6 +186,17 @@ def update(self):
         if self._extensions_goal_state is None or most_recent.created_on_timestamp > self._extensions_goal_state.created_on_timestamp:
             self._extensions_goal_state = most_recent
 
+        # For Fast Track goal states, verify that the required certificates are in the goal state
+        if self.extensions_goal_state.source == GoalStateSource.FastTrack:
+            for extension in self.extensions_goal_state.extensions:
+                for settings in extension.settings:
+                    if settings.protectedSettings is None:
+                        continue
+                    certificates = self.certs.summary
+                    if not any(settings.certificateThumbprint == c['thumbprint'] for c in certificates):
+                        message = "Certificate {0} needed by {1} is missing from the goal state".format(settings.certificateThumbprint, extension.name)
+                        add_event(op=WALAEventOperation.VmSettings, message=message, is_success=False)
+
     def _restore_wire_server_goal_state(self, incarnation, xml_text, xml_doc, vm_settings_support_stopped_error):
         logger.info('The HGAP stopped supporting vmSettings; will fetched the goal state from the WireServer.')
         self._history = GoalStateHistory(timeutil.create_timestamp(), incarnation)
@@ -270,6 +283,7 @@ def _fetch_full_wire_server_goal_state(self, incarnation, xml_doc):
         Returns the value of ExtensionsConfig.
         """
         try:
+            logger.info('')
             logger.info('Fetching full goal state from the WireServer [incarnation {0}]', incarnation)
 
             role_instance = find(xml_doc, "RoleInstance")
@@ -300,9 +314,10 @@ def _fetch_full_wire_server_goal_state(self, incarnation, xml_doc):
             certs = None
             certs_uri = findtext(xml_doc, "Certificates")
             if certs_uri is not None:
-                # Note that we do not save the certificates to the goal state history
                 xml_text = self._wire_client.fetch_config(certs_uri, self._wire_client.get_header_for_cert())
                 certs = Certificates(xml_text)
+                # Save the certificate summary, which includes only the thumbprint but not the certificate itself, to the goal state history
+                self._history.save_certificates(json.dumps(certs.summary))
 
             remote_access = None
             remote_access_uri = findtext(container, "RemoteAccessInfo")
@@ -349,6 +364,7 @@ def __init__(self, xml_text):
 class Certificates(object):
     def __init__(self, xml_text):
         self.cert_list = CertList()
+        self.summary = []  # debugging info
 
         # Save the certificates
         local_file = os.path.join(conf.get_lib_dir(), CERTS_FILE_NAME)
@@ -428,18 +444,15 @@ def __init__(self, xml_text):
                 tmp_file = prvs[pubkey]
                 prv = "{0}.prv".format(thumbprint)
                 os.rename(tmp_file, os.path.join(conf.get_lib_dir(), prv))
-                logger.info("Found private key matching thumbprint {0}".format(thumbprint))
             else:
                 # Since private key has *no* matching certificate,
                 # it will not be named correctly
                 logger.warn("Found NO matching cert/thumbprint for private key!")
 
-        # Log if any certificates were found without matching private keys
-        # This can happen (rarely), and is useful to know for debugging
-        for pubkey in thumbprints:
-            if not pubkey in prvs:
-                msg = "Certificate with thumbprint {0} has no matching private key."
-                logger.info(msg.format(thumbprints[pubkey]))
+        for pubkey, thumbprint in thumbprints.items():
+            has_private_key = pubkey in prvs
+            logger.info("Downloaded certificate with thumbprint {0} (has private key: {1})".format(thumbprint, has_private_key))
+            self.summary.append({"thumbprint": thumbprint, "hasPrivateKey": has_private_key})
 
         for v1_cert in v1_cert_list:
             cert = Cert()

azurelinuxagent/common/utils/archive.py

@@ -42,13 +42,14 @@
 _MAX_ARCHIVED_STATES = 50
 
 _CACHE_PATTERNS = [
-    re.compile(r"^VmSettings.\d+\.json$"),
+    re.compile(r"^VmSettings\.\d+\.json$"),
     re.compile(r"^(.*)\.(\d+)\.(agentsManifest)$", re.IGNORECASE),
     re.compile(r"^(.*)\.(\d+)\.(manifest\.xml)$", re.IGNORECASE),
     re.compile(r"^(.*)\.(\d+)\.(xml)$", re.IGNORECASE),
     re.compile(r"^SharedConfig\.xml$", re.IGNORECASE),
     re.compile(r"^HostingEnvironmentConfig\.xml$", re.IGNORECASE),
-    re.compile(r"^RemoteAccess\.xml$", re.IGNORECASE)
+    re.compile(r"^RemoteAccess\.xml$", re.IGNORECASE),
+    re.compile(r"^waagent_status\.\d+\.json$"),
 ]
 
 #
@@ -69,6 +70,7 @@
 
 _GOAL_STATE_FILE_NAME = "GoalState.xml"
 _VM_SETTINGS_FILE_NAME = "VmSettings.json"
+_CERTIFICATES_FILE_NAME = "Certificates.json"
 _HOSTING_ENV_FILE_NAME = "HostingEnvironmentConfig.xml"
 _SHARED_CONF_FILE_NAME = "SharedConfig.xml"
 _REMOTE_ACCESS_FILE_NAME = "RemoteAccess.xml"
@@ -239,6 +241,9 @@ def save_vm_settings(self, text):
     def save_remote_access(self, text):
         self.save(text, _REMOTE_ACCESS_FILE_NAME)
 
+    def save_certificates(self, text):
+        self.save(text, _CERTIFICATES_FILE_NAME)
+
     def save_hosting_env(self, text):
         self.save(text, _HOSTING_ENV_FILE_NAME)
 

azurelinuxagent/daemon/main.py

@@ -64,7 +64,7 @@ def run(self, child_args=None):
         #
         # Be aware that telemetry events emitted before that will not include the Container ID.
         #
-        logger.info("{0} Version:{1}", AGENT_LONG_NAME, AGENT_VERSION)
+        logger.info("{0} Version: {1}", AGENT_LONG_NAME, AGENT_VERSION)
         logger.info("OS: {0} {1}", DISTRO_NAME, DISTRO_VERSION)
         logger.info("Python: {0}.{1}.{2}", PY_VERSION_MAJOR, PY_VERSION_MINOR, PY_VERSION_MICRO)
 

azurelinuxagent/ga/exthandlers.py

@@ -308,6 +308,7 @@ def run(self):
             error = None
             message = "ProcessExtensionsGoalState started [{0} channel: {1} source: {2} activity: {3} correlation {4} created: {5}]".format(
                 egs.id, egs.channel, egs.source, egs.activity_id, egs.correlation_id, egs.created_on_timestamp)
+            logger.info('')
             logger.info(message)
             add_event(op=WALAEventOperation.ExtensionProcessing, message=message)
 
@@ -319,7 +320,7 @@ def run(self):
             finally:
                 duration = elapsed_milliseconds(utc_start)
                 if error is None:
-                    message = 'ProcessExtensionsGoalState completed [{0} {1} ms]'.format(egs.id, duration)
+                    message = 'ProcessExtensionsGoalState completed [{0} {1} ms]\n'.format(egs.id, duration)
                     logger.info(message)
                 else:
                     message = 'ProcessExtensionsGoalState failed [{0} {1} ms]\n{2}'.format(egs.id, duration, error)

azurelinuxagent/ga/update.py

@@ -54,7 +54,7 @@
 from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.utils.networkutil import AddFirewallRules
 from azurelinuxagent.common.utils.shellutil import CommandError
-from azurelinuxagent.common.version import AGENT_NAME, AGENT_DIR_PATTERN, CURRENT_AGENT, \
+from azurelinuxagent.common.version import AGENT_LONG_NAME, AGENT_NAME, AGENT_DIR_PATTERN, CURRENT_AGENT, \
     CURRENT_VERSION, DISTRO_NAME, DISTRO_VERSION, get_lis_version, \
     has_logrotate, PY_VERSION_MAJOR, PY_VERSION_MINOR, PY_VERSION_MICRO, get_daemon_version
 from azurelinuxagent.ga.collect_logs import get_collect_logs_handler, is_log_collection_allowed
@@ -324,20 +324,11 @@ def run(self, debug=False):
         """
 
         try:
+            logger.info("{0} Version: {1}", AGENT_LONG_NAME, CURRENT_AGENT)
+            logger.info("OS: {0} {1}", DISTRO_NAME, DISTRO_VERSION)
+            logger.info("Python: {0}.{1}.{2}", PY_VERSION_MAJOR, PY_VERSION_MINOR, PY_VERSION_MICRO)
             logger.info(u"Agent {0} is running as the goal state agent", CURRENT_AGENT)
 
-            #
-            # Initialize the goal state; some components depend on information provided by the goal state and this
-            # call ensures the required info is initialized (e.g. telemetry depends on the container ID.)
-            #
-            protocol = self.protocol_util.get_protocol()
-
-            self._initialize_goal_state(protocol)
-
-            # Initialize the common parameters for telemetry events
-            initialize_event_logger_vminfo_common_parameters(protocol)
-
-            # Log OS-specific info.
             os_info_msg = u"Distro: {dist_name}-{dist_ver}; "\
                 u"OSUtil: {util_name}; AgentService: {service_name}; "\
                 u"Python: {py_major}.{py_minor}.{py_micro}; "\
@@ -351,8 +342,20 @@ def run(self, debug=False):
                     py_micro=PY_VERSION_MICRO, systemd=systemd.is_systemd(),
                     lis_ver=get_lis_version(), has_logrotate=has_logrotate()
                 )
-
             logger.info(os_info_msg)
+
+            #
+            # Initialize the goal state; some components depend on information provided by the goal state and this
+            # call ensures the required info is initialized (e.g. telemetry depends on the container ID.)
+            #
+            protocol = self.protocol_util.get_protocol()
+
+            self._initialize_goal_state(protocol)
+
+            # Initialize the common parameters for telemetry events
+            initialize_event_logger_vminfo_common_parameters(protocol)
+
+            # Send telemetry for the OS-specific info.
             add_event(AGENT_NAME, op=WALAEventOperation.OSInfo, message=os_info_msg)
 
             #
@@ -738,7 +741,7 @@ def forward_signal(self, signum, frame):
             return
 
         logger.info(
-            u"Agent {0} forwarding signal {1} to {2}",
+            u"Agent {0} forwarding signal {1} to {2}\n",
             CURRENT_AGENT,
             signum,
             self.child_agent.name if self.child_agent is not None else CURRENT_AGENT)
@@ -827,6 +830,9 @@ def log_if_op_disabled(name, value):
             if conf.get_autoupdate_enabled():
                 log_if_int_changed_from_default("Autoupdate.Frequency", conf.get_autoupdate_frequency())
 
+            if conf.get_enable_fast_track():
+                log_if_op_disabled("Debug.EnableFastTrack", conf.get_enable_fast_track())
+
             if conf.get_lib_dir() != "/var/lib/waagent":
                 log_event("lib dir is in an unexpected location: {0}".format(conf.get_lib_dir()))
 

tests/data/hostgaplugin/ext_conf-requested_version.xml

@@ -60,7 +60,7 @@
   "runtimeSettings": [
     {
       "handlerSettings": {
-        "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+        "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
         "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEFpB/HKM/7evRk+DBz754wUwDQYJKoZIhvcNAQEBBQAEggEADPJwniDeIUXzxNrZCloitFdscQ59Bz1dj9DLBREAiM8jmxM0LLicTJDUv272Qm/4ZQgdqpFYBFjGab/9MX+Ih2x47FkVY1woBkckMaC/QOFv84gbboeQCmJYZC/rZJdh8rCMS+CEPq3uH1PVrvtSdZ9uxnaJ+E4exTPPviIiLIPtqWafNlzdbBt8HZjYaVw+SSe+CGzD2pAQeNttq3Rt/6NjCzrjG8ufKwvRoqnrInMs4x6nnN5/xvobKIBSv4/726usfk8Ug+9Q6Benvfpmre2+1M5PnGTfq78cO3o6mI3cPoBUjp5M0iJjAMGeMt81tyHkimZrEZm6pLa4NQMOEjArBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECC5nVaiJaWt+gAhgeYvxUOYHXw==",
         "publicSettings": {"GCS_AUTO_CONFIG":true}
       }
@@ -73,7 +73,7 @@
   "runtimeSettings": [
     {
       "handlerSettings": {
-        "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+        "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
         "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEFpB/HKM/7evRk+DBz754wUwDQYJKoZIhvcNAQEBBQAEggEADPJwniDeIUXzxNrZCloitFdscQ59Bz1dj9DLBREAiM8jmxM0LLicTJDUv272Qm/4ZQgdqpFYBFjGab/9MX+Ih2x47FkVY1woBkckMaC/QOFv84gbboeQCmJYZC/rZJdh8rCMS+CEPq3uH1PVrvtSdZ9uxnaJ+E4exTPPviIiLIPtqWafNlzdbBt8HZjYaVw+SSe+CGzD2pAQeNttq3Rt/6NjCzrjG8ufKwvRoqnrInMs4x6nnN5/xvobKIBSv4/726usfk8Ug+9Q6Benvfpmre2+1M5PnGTfq78cO3o6mI3cPoBUjp5M0iJjAMGeMt81tyHkimZrEZm6pLa4NQMOEjArBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECC5nVaiJaWt+gAhgeYvxUOYHXw==",
         "publicSettings": {"enableGenevaUpload":true}
       }

tests/data/hostgaplugin/ext_conf.xml

@@ -58,7 +58,7 @@
   "runtimeSettings": [
     {
       "handlerSettings": {
-        "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+        "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
         "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent==",
         "publicSettings": {"GCS_AUTO_CONFIG":true}
       }
@@ -71,7 +71,7 @@
   "runtimeSettings": [
     {
       "handlerSettings": {
-        "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+        "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
         "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/Microsoft.Azure.Security.Monitoring.AzureSecurityLinuxAgent==",
         "publicSettings": {"enableGenevaUpload":true}
       }

tests/data/hostgaplugin/vm_settings-difference_in_required_features.json

@@ -56,7 +56,7 @@
             "settingsSeqNo": 0,
             "settings": [
                 {
-                    "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+                    "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
                     "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEFpB/HKM/7evRk+DBz754wUwDQYJKoZIhvcNAQEBBQAEggEADPJwniDeIUXzxNrZCloitFdscQ59Bz1dj9DLBREAiM8jmxM0LLicTJDUv272Qm/4ZQgdqpFYBFjGab/9MX+Ih2x47FkVY1woBkckMaC/QOFv84gbboeQCmJYZC/rZJdh8rCMS+CEPq3uH1PVrvtSdZ9uxnaJ+E4exTPPviIiLIPtqWafNlzdbBt8HZjYaVw+SSe+CGzD2pAQeNttq3Rt/6NjCzrjG8ufKwvRoqnrInMs4x6nnN5/xvobKIBSv4/726usfk8Ug+9Q6Benvfpmre2+1M5PnGTfq78cO3o6mI3cPoBUjp5M0iJjAMGeMt81tyHkimZrEZm6pLa4NQMOEjArBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECC5nVaiJaWt+gAhgeYvxUOYHXw==",
                     "publicSettings": "{\"GCS_AUTO_CONFIG\":true}"
                 }
@@ -76,7 +76,7 @@
             "settingsSeqNo": 0,
             "settings": [
                 {
-                    "protectedSettingsCertThumbprint": "4C4F304667711036E64AF4894B76EB208A863BD4",
+                    "protectedSettingsCertThumbprint": "4037FBF5F1F3014F99B5D6C7799E9B20E6871CB3",
                     "protectedSettings": "MIIBsAYJKoZIhvcNAQcDoIIBoTCCAZ0CAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEFpB/HKM/7evRk+DBz754wUwDQYJKoZIhvcNAQEBBQAEggEADPJwniDeIUXzxNrZCloitFdscQ59Bz1dj9DLBREAiM8jmxM0LLicTJDUv272Qm/4ZQgdqpFYBFjGab/9MX+Ih2x47FkVY1woBkckMaC/QOFv84gbboeQCmJYZC/rZJdh8rCMS+CEPq3uH1PVrvtSdZ9uxnaJ+E4exTPPviIiLIPtqWafNlzdbBt8HZjYaVw+SSe+CGzD2pAQeNttq3Rt/6NjCzrjG8ufKwvRoqnrInMs4x6nnN5/xvobKIBSv4/726usfk8Ug+9Q6Benvfpmre2+1M5PnGTfq78cO3o6mI3cPoBUjp5M0iJjAMGeMt81tyHkimZrEZm6pLa4NQMOEjArBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECC5nVaiJaWt+gAhgeYvxUOYHXw==",
                     "publicSettings": "{\"enableGenevaUpload\":true}"
                 }