Repository: Azure/WALinuxAgent
Pull request #2332 (2021-08-18 19:35:16)

Implement InitialGoalStatePeriod parameter + improvements in logging goal state processing
Implementation of Extensions.InitialGoalStatePeriod in /etc/waagent.conf.

In order to implement this parameter, I need to keep track of the convergence of the first goal state so I took this as an opportunity to improve the logging of the status of the goal state,

codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) Report
> Merging [#2332](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (c037cae) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/ee1318736ede216b13d6bb000da879907e148a6a?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) (ee13187) will **increase** coverage by `0.08%`.
> The diff coverage is `92.22%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332/graphs/tree.svg?width=650&height=150&src=pr&token=ae90E2KYCw&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)

```diff
@@             Coverage Diff             @@
##           develop    #2332      +/-   ##
===========================================
+ Coverage    70.79%   70.88%   +0.08%     
===========================================
  Files           97       97              
  Lines        14034    14105      +71     
  Branches      2013     2029      +16     
===========================================
+ Hits          9936     9998      +62     
- Misses        3656     3660       +4     
- Partials       442      447       +5     
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/ga/update.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL3VwZGF0ZS5weQ==) | `87.96% <91.89%> (+0.34%)` | :arrow_up: |
| [azurelinuxagent/common/conf.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9jb25mLnB5) | `78.44% <92.85%> (+0.71%)` | :arrow_up: |
| [azurelinuxagent/ga/exthandlers.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2V4dGhhbmRsZXJzLnB5) | `86.24% <100.00%> (+0.02%)` | :arrow_up: |
| [azurelinuxagent/ga/collect\_telemetry\_events.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#diff-YXp1cmVsaW51eGFnZW50L2dhL2NvbGxlY3RfdGVsZW1ldHJ5X2V2ZW50cy5weQ==) | `89.72% <0.00%> (-1.37%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure). Last update [ee13187...c037cae](https://codecov.io/gh/Azure/WALinuxAgent/pull/2332?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).


Patch:
diff --git a/azurelinuxagent/common/conf.py b/azurelinuxagent/common/conf.py
index 848c175d..b3f4c20d 100644
--- a/azurelinuxagent/common/conf.py
+++ b/azurelinuxagent/common/conf.py
@@ -49,25 +49,43 @@ class ConfigurationProvider(object):
                 value = parts[1].split('#')[0].strip("\" ").strip()
                 self.values[key] = value if value != "None" else None
 
-    def get(self, key, default_val):
+    @staticmethod
+    def _get_default(default):
+        if hasattr(default, '__call__'):
+            return default()
+        return default
+
+    def get(self, key, default_value):
+        """
+        Retrieves a string parameter by key and returns its value. If not found returns the default value,
+        or if the default value is a callable returns the result of invoking the callable.
+        """
         val = self.values.get(key)
-        return val if val is not None else default_val
+        return val if val is not None else self._get_default(default_value)
 
-    def get_switch(self, key, default_val):
+    def get_switch(self, key, default_value):
+        """
+        Retrieves a switch parameter by key and returns its value as a boolean. If not found returns the default value,
+        or if the default value is a callable returns the result of invoking the callable.
+        """
         val = self.values.get(key)
         if val is not None and val.lower() == 'y':
             return True
         elif val is not None and val.lower() == 'n':
             return False
-        return default_val
+        return self._get_default(default_value)
 
-    def get_int(self, key, default_val):
+    def get_int(self, key, default_value):
+        """
+        Retrieves an int parameter by key and returns its value. If not found returns the default value,
+        or if the default value is a callable returns the result of invoking the callable.
+        """
         try:
             return int(self.values.get(key))
         except TypeError:
-            return default_val
+            return self._get_default(default_value)
         except ValueError:
-            return default_val
+            return self._get_default(default_value)
 
 
 __conf__ = ConfigurationProvider()
@@ -146,6 +164,7 @@ __STRING_OPTIONS__ = {
 
 __INTEGER_OPTIONS__ = {
     "Extensions.GoalStatePeriod": 6,
+    "Extensions.InitialGoalStatePeriod": 6,
     "Extensions.GoalStateHistoryCleanupPeriod": 1800,
     "OS.EnableFirewallPeriod": 30,
     "OS.RemovePersistentNetRulesPeriod": 30,
@@ -346,6 +365,10 @@ def get_goal_state_period(conf=__conf__):
     return conf.get_int("Extensions.GoalStatePeriod", 6)
 
 
+def get_initial_goal_state_period(conf=__conf__):
+    return conf.get_int("Extensions.InitialGoalStatePeriod", default_value=lambda: get_goal_state_period(conf=conf))
+
+
 def get_goal_state_history_cleanup_period(conf=__conf__):
     return conf.get_int("Extensions.GoalStateHistoryCleanupPeriod", 1800)
 
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index a902891c..54a100bb 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -899,7 +899,8 @@ class ExtHandlersHandler(object):
 
     def report_ext_handlers_status(self, incarnation_changed=False):
         """
-        Go through handler_state dir, collect and report status
+        Go through handler_state dir, collect and report status.
+        Returns the status it reported, or None if an error occurred.
         """
         try:
             vm_status = VMStatus(status="Ready", message="Guest Agent is running",
@@ -953,6 +954,8 @@ class ExtHandlersHandler(object):
 
             self.write_ext_handlers_status_to_info_file(vm_status)
 
+            return vm_status
+
         except Exception as error:
             msg = u"Failed to report status: {0}".format(textutil.format_exception(error))
             logger.warn(msg)
@@ -961,6 +964,7 @@ class ExtHandlersHandler(object):
                       op=WALAEventOperation.ReportStatus,
                       is_success=False,
                       message=msg)
+            return None
 
     def write_ext_handlers_status_to_info_file(self, vm_status):
         status_path = os.path.join(conf.get_lib_dir(), AGENT_STATUS_FILE.format(self.protocol.get_incarnation()))
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index 2c660c81..6d54d067 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -56,7 +56,7 @@ from azurelinuxagent.ga.collect_logs import get_collect_logs_handler, is_log_col
 from azurelinuxagent.ga.env import get_env_handler
 from azurelinuxagent.ga.collect_telemetry_events import get_collect_telemetry_events_handler
 
-from azurelinuxagent.ga.exthandlers import HandlerManifest, ExtHandlersHandler, list_agent_lib_directory
+from azurelinuxagent.ga.exthandlers import HandlerManifest, ExtHandlersHandler, list_agent_lib_directory, ValidHandlerStatus
 from azurelinuxagent.ga.monitor import get_monitor_handler
 
 from azurelinuxagent.ga.send_telemetry_events import get_send_telemetry_events_handler
@@ -72,13 +72,18 @@ CHILD_POLL_INTERVAL = 60
 
 MAX_FAILURE = 3  # Max failure allowed for agent before blacklisted
 
-GOAL_STATE_INTERVAL_DISABLED = 5 * 60
+GOAL_STATE_PERIOD_EXTENSIONS_DISABLED = 5 * 60
 
 ORPHAN_POLL_INTERVAL = 3
 ORPHAN_WAIT_INTERVAL = 15 * 60
 
 AGENT_SENTINEL_FILE = "current_version"
 
+# This file marks that the first goal state (after provisioning) has been completed, either because it converged or because we received another goal
+# state before it converged. The contents will be an instance of ExtensionsSummary. If the file does not exist then we have not finished processing
+# the goal state.
+INITIAL_GOAL_STATE_FILE = "initial_goal_state"
+
 READONLY_FILE_GLOBS = [
     "*.crt",
     "*.p7m",
@@ -88,6 +93,29 @@ READONLY_FILE_GLOBS = [
 ]
 
 
+class ExtensionsSummary(object):
+    """
+    The extensions summary is a list of (extension name, extension status) tuples for the current goal state; it is
+    used to report changes in the status of extensions and to keep track of when the goal state converges (i.e. when
+    all extensions in the goal state reach a terminal state: success or error.)
+    The summary is computed from the VmStatus reported to blob storage.
+    """
+    def __init__(self, vm_status=None):
+        if vm_status is None:
+            self.summary = []
+            self.converged = True
+        else:
+            self.summary = [(h.extension_status.name, h.extension_status.status) for h in vm_status.vmAgent.extensionHandlers]
+            self.summary.sort(key=lambda s: s[0])  # sort by extension name to make comparisons easier
+            self.converged = all(status in (ValidHandlerStatus.success, ValidHandlerStatus.error) for _, status in self.summary)
+
+    def __eq__(self, other):
+        return self.summary == other.summary
+
+    def __str__(self):
+        return ustr(self.summary)
+
+
 def get_update_handler():
     return UpdateHandler()
 
@@ -114,11 +142,26 @@ class UpdateHandler(object):
         self._last_telemetry_heartbeat = None
         self._heartbeat_id = str(uuid.uuid4()).upper()
         self._heartbeat_counter = 0
+
+        # these members are used to avoid reporting errors too frequently
         self._heartbeat_update_goal_state_error_count = 0
         self._last_try_update_goal_state_failed = False
+        self._report_status_last_failed_incarnation = -1
 
         self.last_incarnation = None
 
+        self._extensions_summary = ExtensionsSummary()
+
+        self._is_initial_goal_state = not os.path.exists(self._initial_goal_state_file_path())
+
+        if not conf.get_extensions_enabled():
+            self._goal_state_period = GOAL_STATE_PERIOD_EXTENSIONS_DISABLED
+        else:
+            if self._is_initial_goal_state:
+                self._goal_state_period = conf.get_initial_goal_state_period()
+            else:
+                self._goal_state_period = conf.get_goal_state_period()
+
     def run_latest(self, child_args=None):
         """
         This method is called from the daemon to find and launch the most
@@ -316,14 +359,14 @@ class UpdateHandler(object):
             for thread_handler in all_thread_handlers:
                 thread_handler.run()
 
-            goal_state_interval = conf.get_goal_state_period() if conf.get_extensions_enabled() else GOAL_STATE_INTERVAL_DISABLED
+            logger.info("Goal State Period: {0} sec. This indicates how often the agent checks for new goal states and reports status.", self._goal_state_period)
 
             while self.is_running:
                 self._check_daemon_running(debug)
                 self._check_threads_running(all_thread_handlers)
-                self._process_goal_state(protocol, exthandlers_handler, remote_access_handler)
+                self._process_goal_state(exthandlers_handler, remote_access_handler)
                 self._send_heartbeat_telemetry(protocol)
-                time.sleep(goal_state_interval)
+                time.sleep(self._goal_state_period)
 
         except ExitException as exitException:
             logger.info(exitException.reason)
@@ -375,7 +418,8 @@ class UpdateHandler(object):
             return False
         return True
 
-    def _process_goal_state(self, protocol, exthandlers_handler, remote_access_handler):
+    def _process_goal_state(self, exthandlers_handler, remote_access_handler):
+        protocol = exthandlers_handler.protocol
         if not self._try_update_goal_state(protocol):
             self._heartbeat_update_goal_state_error_count += 1
             return
@@ -392,17 +436,58 @@ class UpdateHandler(object):
 
         try:
             if incarnation != self.last_incarnation:  # TODO: This check should be based in the etag for the extensions goal state
-                exthandlers_handler.run()  # TODO: The info for the extensions within run() should be based on the extensions goal state
+                if not self._extensions_summary.converged:
+                    message = "A new goal state was received, but not all the extensions in the previous goal state have completed: {0}".format(self._extensions_summary)
+                    logger.warn(message)
+                    add_event(op=WALAEventOperation.GoalState, message=message, is_success=False, log_event=False)
+                    if self._is_initial_goal_state:
+                        self._on_initial_goal_state_completed(self._extensions_summary)
+                self._extensions_summary = ExtensionsSummary()
+                exthandlers_handler.run()
 
             # report status always, even if the goal state did not change
             # do it before processing the remote access, since that operation can take a long time
-            exthandlers_handler.report_ext_handlers_status(incarnation_changed=incarnation != self.last_incarnation)
+            self._report_status(exthandlers_handler, incarnation_changed=incarnation != self.last_incarnation)
 
             if incarnation != self.last_incarnation:
                 remote_access_handler.run()
         finally:
             self.last_incarnation = incarnation
 
+    def _report_status(self, exthandlers_handler, incarnation_changed):
+        # report_ext_handlers_status does its own error handling and returns None if an error occurred
+        vm_status = exthandlers_handler.report_ext_handlers_status(incarnation_changed=incarnation_changed)
+        if vm_status is None:
+            return
+
+        try:
+            extensions_summary = ExtensionsSummary(vm_status)
+            if self._extensions_summary != extensions_summary:
+                self._extensions_summary = extensions_summary
+                message = "Extension status: {0}".format(self._extensions_summary)
+                logger.info(message)
+                add_event(op=WALAEventOperation.GoalState, message=message)
+                if self._extensions_summary.converged:
+                    message = "All extensions in the goal state have reached a terminal state: {0}".format(extensions_summary)
+                    logger.info(message)
+                    add_event(op=WALAEventOperation.GoalState, message=message)
+                    if self._is_initial_goal_state:
+                        self._on_initial_goal_state_completed(self._extensions_summary)
+        except Exception as error:
+            # report errors only once per incarnation
+            if self._report_status_last_failed_incarnation != exthandlers_handler.protocol.get_incarnation():
+                self._report_status_last_failed_incarnation = exthandlers_handler.protocol.get_incarnation()
+                msg = u"Error logging the goal state summary: {0}".format(textutil.format_exception(error))
+                logger.warn(msg)
+                add_event(op=WALAEventOperation.GoalState, is_success=False, message=msg)
+
+    def _on_initial_goal_state_completed(self, extensions_summary):
+        fileutil.write_file(self._initial_goal_state_file_path(), ustr(extensions_summary))
+        if conf.get_extensions_enabled() and self._goal_state_period != conf.get_goal_state_period():
+            self._goal_state_period = conf.get_goal_state_period()
+            logger.info("Initial goal state completed, switched the goal state period to {0}", self._goal_state_period)
+        self._is_initial_goal_state = False
+
     def forward_signal(self, signum, frame):
         if signum == signal.SIGTERM:
             self._shutdown()
@@ -464,19 +549,22 @@ class UpdateHandler(object):
     def _emit_changes_in_default_configuration():
         try:
             def log_event(msg):
-                logger.info(msg)
+                logger.info("******** {0} ********", msg)
                 add_event(AGENT_NAME, op=WALAEventOperation.ConfigurationChange, message=msg)
 
-            def log_if_int_changed_from_default(name, current):
+            def log_if_int_changed_from_default(name, current, message=""):
                 default = conf.get_int_default_value(name)
                 if default != current:
-                    log_event("{0} changed from its default: {1}. New value: {2}".format(name, default, current))
+                    log_event("{0} changed from its default: {1}. New value: {2}. {3}".format(name, default, current, message))
 
             def log_if_op_disabled(name, value):
                 if not value:
                     log_event("{0} is set to False, not processing the operation".format(name))
 
-            log_if_int_changed_from_default("Extensions.GoalStatePeriod", conf.get_goal_state_period())
+            log_if_int_changed_from_default("Extensions.GoalStatePeriod", conf.get_goal_state_period(),
+                "Changing this value affects how often extensions are processed and status for the VM is reported. Too small a value may report the VM as unresponsive")
+            log_if_int_changed_from_default("Extensions.InitialGoalStatePeriod", conf.get_initial_goal_state_period(),
+                "Changing this value affects how often extensions are processed and status for the VM is reported. Too small a value may report the VM as unresponsive")
             log_if_op_disabled("OS.EnableFirewall", conf.enable_firewall())
             log_if_op_disabled("Extensions.Enabled", conf.get_extensions_enabled())
 
@@ -699,6 +787,10 @@ class UpdateHandler(object):
     def _sentinel_file_path(self):
         return os.path.join(conf.get_lib_dir(), AGENT_SENTINEL_FILE)
 
+    @staticmethod
+    def _initial_goal_state_file_path():
+        return os.path.join(conf.get_lib_dir(), INITIAL_GOAL_STATE_FILE)
+
     def _shutdown(self):
         # Todo: Ensure all threads stopped when shutting down the main extension handler to ensure that the state of
         # all threads is clean.


Test patch:
diff --git a/tests/common/test_conf.py b/tests/common/test_conf.py
index 8f98f3d7..ebc57ffe 100644
--- a/tests/common/test_conf.py
+++ b/tests/common/test_conf.py
@@ -75,6 +75,18 @@ class TestConf(AgentTestCase):
                 os.path.join(data_dir, "test_waagent.conf"),
                 self.conf)
 
+    def test_get_should_return_default_when_key_is_not_found(self):
+        self.assertEqual("The Default Value", self.conf.get("this-key-does-not-exist", "The Default Value"))
+        self.assertEqual("The Default Value", self.conf.get("this-key-does-not-exist", lambda: "The Default Value"))
+
+    def test_get_switch_should_return_default_when_key_is_not_found(self):
+        self.assertEqual(True, self.conf.get_switch("this-key-does-not-exist", True))
+        self.assertEqual(True, self.conf.get_switch("this-key-does-not-exist", lambda: True))
+
+    def test_get_int_should_return_default_when_key_is_not_found(self):
+        self.assertEqual(123456789, self.conf.get_int("this-key-does-not-exist", 123456789))
+        self.assertEqual(123456789, self.conf.get_int("this-key-does-not-exist", lambda: 123456789))
+
     def test_key_value_handling(self):
         self.assertEqual("Value1", self.conf.get("FauxKey1", "Bad"))
         self.assertEqual("Value2 Value2", self.conf.get("FauxKey2", "Bad"))
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index 19148860..b729a4c2 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -30,7 +30,7 @@ from azurelinuxagent.common.protocol.goal_state import ExtensionsConfig
 from azurelinuxagent.common.protocol.hostplugin import URI_FORMAT_GET_API_VERSIONS, HOST_PLUGIN_PORT, \
     URI_FORMAT_GET_EXTENSION_ARTIFACT, HostPluginProtocol
 from azurelinuxagent.common.protocol.restapi import ExtHandlerPackageUri, VMAgentManifest, VMAgentManifestUri, \
-    VMAgentManifestList, ExtHandlerPackage, ExtHandlerPackageList, ExtHandler
+    VMAgentManifestList, ExtHandlerPackage, ExtHandlerPackageList, ExtHandler, VMStatus, ExtHandlerStatus, ExtensionStatus
 from azurelinuxagent.common.protocol.util import ProtocolUtil
 from azurelinuxagent.common.protocol.wire import WireProtocol
 from azurelinuxagent.common.utils import fileutil, restutil, textutil
@@ -38,10 +38,10 @@ from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
 from azurelinuxagent.common.utils.networkutil import FirewallCmdDirectCommands
 from azurelinuxagent.common.version import AGENT_PKG_GLOB, AGENT_DIR_GLOB, AGENT_NAME, AGENT_DIR_PATTERN, \
     AGENT_VERSION, CURRENT_AGENT, CURRENT_VERSION
-from azurelinuxagent.ga.exthandlers import ExtHandlerInstance, HandlerEnvironment
+from azurelinuxagent.ga.exthandlers import ExtHandlersHandler, ExtHandlerInstance, HandlerEnvironment, ValidHandlerStatus
 from azurelinuxagent.ga.update import GuestAgent, GuestAgentError, MAX_FAILURE, AGENT_MANIFEST_FILE, \
     get_update_handler, ORPHAN_POLL_INTERVAL, AGENT_PARTITION_FILE, AGENT_ERROR_FILE, ORPHAN_WAIT_INTERVAL, \
-    CHILD_LAUNCH_RESTART_MAX, CHILD_HEALTH_INTERVAL, UpdateHandler
+    CHILD_LAUNCH_RESTART_MAX, CHILD_HEALTH_INTERVAL, GOAL_STATE_PERIOD_EXTENSIONS_DISABLED, UpdateHandler
 from tests.protocol.mocks import mock_wire_protocol
 from tests.protocol.mockwiredata import DATA_FILE, DATA_FILE_MULTIPLE_EXT
 from tests.tools import AgentTestCase, data_dir, DEFAULT, patch, load_bin_data, load_data, Mock, MagicMock, \
@@ -1501,14 +1501,6 @@ class TestUpdate(UpdateTestCase):
         self.update_handler._upgrade_available = Mock(return_value=True)
         self._test_run(invocations=0, calls=0, enable_updates=True, sleep_interval=(300,))
 
-    @patch('azurelinuxagent.common.conf.get_extensions_enabled', return_value=False)
-    def test_interval_changes_when_extensions_disabled(self, _):
-        """
-        When extension processing is disabled, the goal state interval should be larger.
-        """
-        self.update_handler._upgrade_available = Mock(return_value=False)
-        self._test_run(invocations=1, calls=1, sleep_interval=(300,))
-
     @patch("azurelinuxagent.common.logger.info")
     @patch("azurelinuxagent.ga.update.add_event")
     def test_telemetry_heartbeat_creates_event(self, patch_add_event, patch_info, *_):
@@ -2025,40 +2017,160 @@ class TryUpdateGoalStateTestCase(HttpRequestPredicates, AgentTestCase):
                 gs = goal_state_events()
                 self.assertTrue(len(gs) == 1 and 'is_success=True' in gs[0], "Recovering after failures should produce a telemetry event (success=true): [{0}]".format(gs))
 
+def _create_update_handler():
+    """
+    Creates an UpdateHandler in which agent updates are mocked as a no-op.
+    """
+    update_handler = get_update_handler()
+    update_handler._upgrade_available = Mock(return_value=False)
+    return update_handler
 
-class TestProcessGoalState(AgentTestCase):
+@contextlib.contextmanager
+def _mock_exthandlers_handler(extension_statuses=None):
+    """
+    Creates an ExtHandlersHandler that doesn't actually handle any extensions, but that returns status for 1 extension.
+    The returned ExtHandlersHandler uses a mock WireProtocol, and both the run() and report_ext_handlers_status() are
+    mocked. The mock run() is a no-op. If a list of extension_statuses is given, successive calls to the mock
+    report_ext_handlers_status() returns a single extension with each of the statuses in the list. If extension_statuses
+    is ommitted all calls to report_ext_handlers_status() return a single extension with a success status.
+    """
+    def create_vm_status(extension_status):
+        vm_status = VMStatus(status="Ready", message="Ready")
+        vm_status.vmAgent.extensionHandlers = [ExtHandlerStatus()]
+        vm_status.vmAgent.extensionHandlers[0].extension_status = ExtensionStatus(name="TestExtension")
+        vm_status.vmAgent.extensionHandlers[0].extension_status.status = extension_status
+        return vm_status
+
+    with mock_wire_protocol(DATA_FILE) as protocol:
+        exthandlers_handler = ExtHandlersHandler(protocol)
+        exthandlers_handler.run = Mock()
+        if extension_statuses is None:
+            exthandlers_handler.report_ext_handlers_status = Mock(return_value=create_vm_status(ValidHandlerStatus.success))
+        else:
+            exthandlers_handler.report_ext_handlers_status = Mock(side_effect=[create_vm_status(s) for s in extension_statuses])
+        yield exthandlers_handler
+
+
+class ProcessGoalStateTestCase(AgentTestCase):
     """
-    Tests for UpdateHandler._process_goal_state
+    Tests for UpdateHandler._process_goal_state()
     """
     def test_it_should_process_goal_state_only_on_new_goal_state(self):
-        with mock_wire_protocol(DATA_FILE) as protocol:
+        with _mock_exthandlers_handler() as exthandlers_handler:
+            update_handler = _create_update_handler()
+            remote_access_handler = Mock()
+            remote_access_handler.run = Mock()
+
+            # process a goal state
+            update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+            self.assertEqual(1, exthandlers_handler.run.call_count, "exthandlers_handler.run() should have been called on the first goal state")
+            self.assertEqual(1, exthandlers_handler.report_ext_handlers_status.call_count, "exthandlers_handler.report_ext_handlers_status() should have been called on the first goal state")
+            self.assertEqual(1, remote_access_handler.run.call_count, "remote_access_handler.run() should have been called on the first goal state")
+
+            # process the same goal state
+            update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+            self.assertEqual(1, exthandlers_handler.run.call_count, "exthandlers_handler.run() should have not been called on the same goal state")
+            self.assertEqual(2, exthandlers_handler.report_ext_handlers_status.call_count, "exthandlers_handler.report_ext_handlers_status() should have been called on the same goal state")
+            self.assertEqual(1, remote_access_handler.run.call_count, "remote_access_handler.run() should not have been called on the same goal state")
+
+            # process a new goal state
+            exthandlers_handler.protocol.mock_wire_data.set_incarnation(999)
+            exthandlers_handler.protocol.client.update_goal_state()
+            update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+            self.assertEqual(2, exthandlers_handler.run.call_count, "exthandlers_handler.run() should have been called on a new goal state")
+            self.assertEqual(3, exthandlers_handler.report_ext_handlers_status.call_count, "exthandlers_handler.report_ext_handlers_status() should have been called on a new goal state")
+            self.assertEqual(2, remote_access_handler.run.call_count, "remote_access_handler.run() should have been called on a new goal state")
+
+
+class ReportStatusTestCase(AgentTestCase):
+    """
+    Tests for UpdateHandler._report_status()
+    """
+    def test_report_status_should_log_errors_only_once_per_goal_state(self):
+        update_handler = _create_update_handler()
+        with _mock_exthandlers_handler() as exthandlers_handler:
+            with patch("azurelinuxagent.ga.update.logger.warn") as logger_warn:
+                update_handler._report_status(exthandlers_handler, False)
+                self.assertEqual(0, logger_warn.call_count, "UpdateHandler._report_status() should not report WARNINGS when there are no errors")
+
+                with patch("azurelinuxagent.ga.update.ExtensionsSummary.__init__", return_value=Exception("TEST EXCEPTION")):  # simulate an error during _report_status()
+                    update_handler._report_status(exthandlers_handler, False)
+                    update_handler._report_status(exthandlers_handler, False)
+                    update_handler._report_status(exthandlers_handler, False)
+                    self.assertEqual(1, logger_warn.call_count, "UpdateHandler._report_status() should report only 1 WARNING when there are multiple errors within the same goal state")
+
+                    exthandlers_handler.protocol.mock_wire_data.set_incarnation(999)
+                    update_handler._try_update_goal_state(exthandlers_handler.protocol)
+                    update_handler._report_status(exthandlers_handler, True)
+                    self.assertEqual(2, logger_warn.call_count, "UpdateHandler._report_status() should continue reporting errors after a new goal state")
+
+
+class GoalStateIntervalTestCase(AgentTestCase):
+    def test_initial_goal_state_period_should_default_to_goal_state_period(self):
+        configuration_provider = conf.ConfigurationProvider()
+        test_file = os.path.join(self.tmp_dir, "waagent.conf")
+        with open(test_file, "w") as file_:
+            file_.write("Extensions.GoalStatePeriod=987654321\n")
+        conf.load_conf_from_file(test_file, configuration_provider)
+
+        self.assertEqual(987654321, conf.get_initial_goal_state_period(conf=configuration_provider))
+
+    def test_update_handler_should_use_the_default_goal_state_period(self):
+        update_handler = get_update_handler()
+        default = conf.get_int_default_value("Extensions.GoalStatePeriod")
+        self.assertEqual(default, update_handler._goal_state_period, "The UpdateHanlder is not using the default goal state period")
+
+    def test_update_handler_should_not_use_the_default_goal_state_period_when_extensions_are_disabled(self):
+        with patch('azurelinuxagent.common.conf.get_extensions_enabled', return_value=False):
+            update_handler = get_update_handler()
+            self.assertEqual(GOAL_STATE_PERIOD_EXTENSIONS_DISABLED, update_handler._goal_state_period, "Incorrect goal state period when extensions are disabled")
+
+    def test_the_default_goal_state_period_and_initial_goal_state_period_should_be_the_same(self):
+        update_handler = get_update_handler()
+        default = conf.get_int_default_value("Extensions.GoalStatePeriod")
+        self.assertEqual(default, update_handler._goal_state_period, "The UpdateHanlder is not using the default goal state period")
+
+    def test_update_handler_should_use_the_initial_goal_state_period_when_it_is_different_to_the_goal_state_period(self):
+        with patch('azurelinuxagent.common.conf.get_initial_goal_state_period', return_value=99999):
             update_handler = get_update_handler()
-            with patch.object(update_handler, "_upgrade_available", return_value=False):  # skip the upgrade logic
-                exthandlers_handler = Mock()
-                remote_access_handler = Mock()
-
-                def get_method_calls(mock, method):
-                    return [call[0] for call in mock.method_calls if call[0] == method]
-
-                # process a goal state
-                update_handler._process_goal_state(protocol, exthandlers_handler, remote_access_handler)
-                self.assertEqual(1, len(get_method_calls(exthandlers_handler, 'run')), "exthandlers_handler.run() should have been called on the first goal state")
-                self.assertEqual(1, len(get_method_calls(exthandlers_handler, 'report_ext_handlers_status')), "exthandlers_handler.report_ext_handlers_status() should have been called on the first goal state")
-                self.assertEqual(1, len(get_method_calls(remote_access_handler, 'run')), "remote_access_handler.run() should have been called on the first goal state")
-
-                # process the same goal state
-                update_handler._process_goal_state(protocol, exthandlers_handler, remote_access_handler)
-                self.assertEqual(1, len(get_method_calls(exthandlers_handler, 'run')), "exthandlers_handler.run() should have not been called on the same goal state")
-                self.assertEqual(2, len(get_method_calls(exthandlers_handler, 'report_ext_handlers_status')), "exthandlers_handler.report_ext_handlers_status() should have been called on the same goal state")
-                self.assertEqual(1, len(get_method_calls(remote_access_handler, 'run')), "remote_access_handler.run() should not have been called on the same goal state")
-
-                # process a new goal state
-                protocol.mock_wire_data.set_incarnation(999)
-                protocol.client.update_goal_state()
-                update_handler._process_goal_state(protocol, exthandlers_handler, remote_access_handler)
-                self.assertEqual(2, len(get_method_calls(exthandlers_handler, 'run')), "exthandlers_handler.run() should have been called on a new goal state")
-                self.assertEqual(3, len(get_method_calls(exthandlers_handler, 'report_ext_handlers_status')), "exthandlers_handler.report_ext_handlers_status() should have been called on a new goal state")
-                self.assertEqual(2, len(get_method_calls(remote_access_handler, 'run')), "remote_access_handler.run() should have been called on a new goal state")
+            self.assertEqual(99999, update_handler._goal_state_period, "Expected the initial goal state period")
+
+    def test_update_handler_should_use_the_initial_goal_state_period_until_the_goal_state_converges(self):
+        initial_goal_state_period, goal_state_period = 11111, 22222
+        with patch('azurelinuxagent.common.conf.get_initial_goal_state_period', return_value=initial_goal_state_period):
+            with patch('azurelinuxagent.common.conf.get_goal_state_period', return_value=goal_state_period):
+                with _mock_exthandlers_handler([ValidHandlerStatus.transitioning, ValidHandlerStatus.success]) as exthandlers_handler:
+                    remote_access_handler = Mock()
+
+                    update_handler = _create_update_handler()
+                    self.assertEqual(initial_goal_state_period, update_handler._goal_state_period, "Expected the initial goal state period")
+
+                    # the extension is transisioning, so we should still be using the initial goal state period
+                    update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+                    self.assertEqual(initial_goal_state_period, update_handler._goal_state_period, "Expected the initial goal state period when the extension is transitioning")
+
+                    # the goal state converged (the extension succeeded), so we should switch to the regular goal state period
+                    update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+                    self.assertEqual(goal_state_period, update_handler._goal_state_period, "Expected the regular goal state period after the goal state converged")
+
+    def test_update_handler_should_switch_to_the_regular_goal_state_period_when_the_goal_state_does_not_converges(self):
+        initial_goal_state_period, goal_state_period = 11111, 22222
+        with patch('azurelinuxagent.common.conf.get_initial_goal_state_period', return_value=initial_goal_state_period):
+            with patch('azurelinuxagent.common.conf.get_goal_state_period', return_value=goal_state_period):
+                with _mock_exthandlers_handler([ValidHandlerStatus.transitioning, ValidHandlerStatus.transitioning]) as exthandlers_handler:
+                    remote_access_handler = Mock()
+
+                    update_handler = _create_update_handler()
+                    self.assertEqual(initial_goal_state_period, update_handler._goal_state_period, "Expected the initial goal state period")
+
+                    # the extension is transisioning, so we should still be using the initial goal state period
+                    update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+                    self.assertEqual(initial_goal_state_period, update_handler._goal_state_period, "Expected the initial goal state period when the extension is transitioning")
+
+                    # a new goal state arrives before the current goal state converged (the extension is transitioning), so we should switch to the regular goal state period
+                    exthandlers_handler.protocol.mock_wire_data.set_incarnation(100)
+                    update_handler._process_goal_state(exthandlers_handler, remote_access_handler)
+                    self.assertEqual(goal_state_period, update_handler._goal_state_period, "Expected the regular goal state period when the goal state does not converge")
 
 
 if __name__ == '__main__':
diff --git a/tests/test_agent.py b/tests/test_agent.py
index 58ed8bf1..ee36061b 100644
--- a/tests/test_agent.py
+++ b/tests/test_agent.py
@@ -40,6 +40,7 @@ Extension.LogDir = /var/log/azure
 Extensions.Enabled = True
 Extensions.GoalStateHistoryCleanupPeriod = 1800
 Extensions.GoalStatePeriod = 6
+Extensions.InitialGoalStatePeriod = 6
 HttpProxy.Host = None
 HttpProxy.Port = None
 Lib.Dir = /var/lib/waagent