Merge ~asakkurr/cloud-init:azure_report_ready into cloud-init:master

[Aswin Rajamannar]

azure: report ready to fabric after reprovision and reduce logging

When reusing a preprovisioned VM, report ready to Azure fabric as soon as
we get the reprovision data and the goal state so that we are not delayed
by the cloud-init stage switch, saving 2-3 seconds. Also reduce logging
when polling IMDS for reprovision data.

LP: #1799594

When reusing a preprovisioned VM, report ready to Azure fabric as soon as we get the reprovision data and the goal state so that we are not delayed by the cloud-init stage switch, saving 2-3 seconds. Also reduce logging when polling IMDS for reprovision data.

[Paul Meyer (paul-meyer)]

LGTM, but if you want to shave off some more time, it might be time to stop depending on get_metadata_from_fabric to report ready, because that does a bunch more (retrieve goalstate and maybe certificates).
cloudinit.helpers.azure._report_ready(...) needs only the goalstate incarnation, container_id and instance_id. I bet we already have those from the data we read from IMDS?

[Aswin Rajamannar (asakkurr)]

> LGTM, but if you want to shave off some more time, it might be time to stop
> depending on get_metadata_from_fabric to report ready, because that does a
> bunch more (retrieve goalstate and maybe certificates).
> cloudinit.helpers.azure._report_ready(...) needs only the goalstate
> incarnation, container_id and instance_id. I bet we already have those from
> the data we read from IMDS?

IMDS gives us just the ovf-env.xml content. We still need to depend on the wireserver to get the goalstate info. I guess that can be done by the waagent as well, but I think it makes sense to report ready after getting the goalstate info once the vm gets reused, so that it serves as an indication that we have everything needed to proceed further.

[Paul Meyer (paul-meyer)]

review: Approve

[Chad Smith (chad.smith)]

Thanks for this, and tuning down the noise in readurl where possible.

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:ccd13677c9659b493452872228f39bda666ea0b6
https://jenkins.ubuntu.com/server/job/cloud-init-ci/422/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/422/rebuild

review: Approve (continuous-integration)

diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py
index d0358e9..8642915 100644
--- a/cloudinit/sources/DataSourceAzure.py
+++ b/cloudinit/sources/DataSourceAzure.py
@@ -267,6 +267,7 @@ class DataSourceAzure(sources.DataSource):
     dsname = 'Azure'
     _negotiated = False
     _metadata_imds = sources.UNSET
+    lease_info = None
 
     def __init__(self, sys_cfg, distro, paths):
         sources.DataSource.__init__(self, sys_cfg, distro, paths)
@@ -406,8 +407,10 @@ class DataSourceAzure(sources.DataSource):
                 LOG.warning("%s was not mountable", cdev)
                 continue
 
+            should_report_ready_after_reprovision = False
             if reprovision or self._should_reprovision(ret):
                 ret = self._reprovision()
+                should_report_ready_after_reprovision = True
             imds_md = get_metadata_from_imds(
                 self.fallback_interface, retries=3)
             (md, userdata_raw, cfg, files) = ret
@@ -434,6 +437,11 @@ class DataSourceAzure(sources.DataSource):
             crawled_data['metadata']['random_seed'] = seed
         crawled_data['metadata']['instance-id'] = util.read_dmi_data(
             'system-uuid')
+
+        if should_report_ready_after_reprovision:
+            LOG.info("Reporting ready to Azure after getting ReprovisionData")
+            self._report_ready(lease=self.lease_info)
+
         return crawled_data
 
     def _is_platform_viable(self):
@@ -522,6 +530,7 @@ class DataSourceAzure(sources.DataSource):
         while True:
             try:
                 with EphemeralDHCPv4() as lease:
+                    self.lease_info = lease
                     if report_ready:
                         path = REPORTED_READY_MARKER_FILE
                         LOG.info(
@@ -531,13 +540,13 @@ class DataSourceAzure(sources.DataSource):
                         self._report_ready(lease=lease)
                         report_ready = False
                     return readurl(url, timeout=1, headers=headers,
-                                   exception_cb=exc_cb, infinite=True).contents
+                                   exception_cb=exc_cb, infinite=True,
+                                   log_req_resp=False).contents
             except UrlError:
                 pass
 
     def _report_ready(self, lease):
-        """Tells the fabric provisioning has completed
-           before we go into our polling loop."""
+        """Tells the fabric provisioning has completed """
         try:
             get_metadata_from_fabric(None, lease['unknown-245'])
         except Exception:
diff --git a/cloudinit/url_helper.py b/cloudinit/url_helper.py
index 8067979..cf57dbd 100644
--- a/cloudinit/url_helper.py
+++ b/cloudinit/url_helper.py
@@ -199,7 +199,7 @@ def _get_ssl_args(url, ssl_details):
 def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
             headers=None, headers_cb=None, ssl_details=None,
             check_status=True, allow_redirects=True, exception_cb=None,
-            session=None, infinite=False):
+            session=None, infinite=False, log_req_resp=True):
     url = _cleanurl(url)
     req_args = {
         'url': url,
@@ -256,9 +256,11 @@ def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
                 continue
             filtered_req_args[k] = v
         try:
-            LOG.debug("[%s/%s] open '%s' with %s configuration", i,
-                      "infinite" if infinite else manual_tries, url,
-                      filtered_req_args)
+
+            if log_req_resp:
+                LOG.debug("[%s/%s] open '%s' with %s configuration", i,
+                          "infinite" if infinite else manual_tries, url,
+                          filtered_req_args)
 
             if session is None:
                 session = requests.Session()
@@ -294,8 +296,11 @@ def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
                 break
             if (infinite and sec_between > 0) or \
                (i + 1 < manual_tries and sec_between > 0):
-                LOG.debug("Please wait %s seconds while we wait to try again",
-                          sec_between)
+
+                if log_req_resp:
+                    LOG.debug(
+                        "Please wait %s seconds while we wait to try again",
+                        sec_between)
                 time.sleep(sec_between)
     if excps:
         raise excps[-1]
diff --git a/tests/unittests/test_datasource/test_azure.py b/tests/unittests/test_datasource/test_azure.py
index cd6e7e7..4c5c6c1 100644
--- a/tests/unittests/test_datasource/test_azure.py
+++ b/tests/unittests/test_datasource/test_azure.py
@@ -513,6 +513,57 @@ fdescfs            /dev/fd          fdescfs rw              0 0
             dsrc.crawl_metadata()
         self.assertEqual(str(cm.exception), error_msg)
 
+    @mock.patch('cloudinit.sources.DataSourceAzure.util.write_file')
+    @mock.patch(
+        'cloudinit.sources.DataSourceAzure.DataSourceAzure._report_ready')
+    @mock.patch('cloudinit.sources.DataSourceAzure.DataSourceAzure._poll_imds')
+    def test_crawl_metadata_on_reprovision_reports_ready(
+                            self, poll_imds_func,
+                            report_ready_func,
+                            m_write):
+        """If reprovisioning, report ready at the end"""
+        ovfenv = construct_valid_ovf_env(
+                            platform_settings={"PreprovisionedVm": "True"})
+
+        data = {'ovfcontent': ovfenv,
+                'sys_cfg': {}}
+        dsrc = self._get_ds(data)
+        poll_imds_func.return_value = ovfenv
+        dsrc.crawl_metadata()
+        self.assertEqual(1, report_ready_func.call_count)
+
+    @mock.patch('cloudinit.sources.DataSourceAzure.util.write_file')
+    @mock.patch(
+        'cloudinit.sources.DataSourceAzure.DataSourceAzure._report_ready')
+    @mock.patch('cloudinit.net.dhcp.EphemeralIPv4Network')
+    @mock.patch('cloudinit.net.dhcp.maybe_perform_dhcp_discovery')
+    @mock.patch('cloudinit.sources.DataSourceAzure.readurl')
+    def test_crawl_metadata_on_reprovision_reports_ready_using_lease(
+                            self, m_readurl, m_dhcp,
+                            m_net, report_ready_func,
+                            m_write):
+        """If reprovisioning, report ready using the obtained lease"""
+        ovfenv = construct_valid_ovf_env(
+                            platform_settings={"PreprovisionedVm": "True"})
+
+        data = {'ovfcontent': ovfenv,
+                'sys_cfg': {}}
+        dsrc = self._get_ds(data)
+
+        lease = {
+            'interface': 'eth9', 'fixed-address': '192.168.2.9',
+            'routers': '192.168.2.1', 'subnet-mask': '255.255.255.0',
+            'unknown-245': '624c3620'}
+        m_dhcp.return_value = [lease]
+
+        reprovision_ovfenv = construct_valid_ovf_env()
+        m_readurl.return_value = url_helper.StringResponse(
+            reprovision_ovfenv.encode('utf-8'))
+
+        dsrc.crawl_metadata()
+        self.assertEqual(2, report_ready_func.call_count)
+        report_ready_func.assert_called_with(lease=lease)
+
     def test_waagent_d_has_0700_perms(self):
         # we expect /var/lib/waagent to be created 0700
         dsrc = self._get_ds({'ovfcontent': construct_valid_ovf_env()})