Merge ~dojordan/cloud-init:azuretimeouts into cloud-init:master

[Douglas Jordan]

Reduce AzurePreprovisioning HTTP timeouts.

Reducing timeout to 1 second as IMDS responds within a handful
of milliseconds. Also get rid of max_retries to prevent exiting
out of polling loop early due to IMDS outage / upgrade.

Reduce Azure PreProvisioning HTTP timeouts during polling to
avoid waiting an extra minute.

LP: #1752977

During Azure preprovisioning, the platform owned VM gets into a polling loop while we are waiting for the reprovsioning data file (the customer's ovf_env.xml). If the VM moves from one vnet to another, we will get a timeout exception on the request to IMDS and thus need to re-dhcp to get the new IP and network configuration. Currently, that timeout is 60seconds, and upon further testing IMDS responds within 5-20 milliseconds so we propose moving the timeout to 1 second in order to speed up the total deployment time for the customer.

In addition, due to IMDS server updates there is a chance it will be unreachable. If it is, then we could be re-dhcping multiple times, and it is possible to hit the current limit (5) especially with a max retry of 5. That would put the VM in an effectively useless state where it would not be possible to recover. We propose removing the max dhcp retry count for preprovisioning.

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

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

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

review: Approve (continuous-integration)

[Chad Smith (chad.smith)]

Thanks for this Douglas.

   Now that timeouts are 1 second instead of 1 minute, let's drop that logging on exception as this will generate a high-frequency of these logs where the only real value is to see how long we were in the polling stage.

Let's instead add bookend comments for entrance into IMDS polling and exit from that Polling loop.
Then we'll easily see how long we waited in that preprovisioning state once instances do finally provision.

[Douglas Jordan (dojordan)]

Hmm, is there a log level we can use that is disabled by default like verbose? Or is verbose logged too?
> Thanks for this Douglas.
>
> Now that timeouts are 1 second instead of 1 minute, let's drop that logging
> on exception as this will generate a high-frequency of these logs where the
> only real value is to see how long we were in the polling stage.
>
>
> Let's instead add bookend comments for entrance into IMDS polling and exit
> from that Polling loop.
> Then we'll easily see how long we waited in that preprovisioning state once
> instances do finally provision.

83c2198... by Douglas Jordan on 2018-03-05

Fix logging

764b1f3... by Douglas Jordan on 2018-03-05

Fix logging

832f67f... by Douglas Jordan on 2018-03-05

Fix logging

24c4467... by Douglas Jordan on 2018-03-05

Fix string formatting

ec66fe8... by Douglas Jordan on 2018-03-05

Fix string formatting

64f90cc... by Douglas Jordan on 2018-03-05

Fix string formatting

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

FAILED: Continuous integration, rev:24c4467b491ce71c520247c129a8c12f376e5a8a
https://jenkins.ubuntu.com/server/job/cloud-init-ci/816/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    FAILED: Ubuntu LTS: Integration

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

review: Needs Fixing (continuous-integration)

7e1cded... by Douglas Jordan on 2018-03-06

Removing all debug logs

b2384b5... by Douglas Jordan on 2018-03-06

Fix merge

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

FAILED: Continuous integration, rev:b2384b57fb998cde2916059b62907c025ed1d9ce
https://jenkins.ubuntu.com/server/job/cloud-init-ci/817/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    FAILED: Ubuntu LTS: Integration

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

review: Needs Fixing (continuous-integration)

9cbfb4b... by Douglas Jordan on 2018-03-06

Fix merge

e875718... by Douglas Jordan on 2018-03-06

Bouncing C-I with new log message

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

FAILED: Continuous integration, rev:e875718ce26e25d3999faaa3f4176bcce5cfa0a2
https://jenkins.ubuntu.com/server/job/cloud-init-ci/818/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    FAILED: Ubuntu LTS: Integration

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

review: Needs Fixing (continuous-integration)

df7c764... by Douglas Jordan on 2018-03-07

Only catch UrlError and bring back log

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

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

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

review: Approve (continuous-integration)

580798c... by Douglas Jordan on 2018-03-14

Moving to readurl in preprovisioning case

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

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

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

review: Approve (continuous-integration)

196550e... by Douglas Jordan on 2018-03-19

Fixing UTs

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

FAILED: Continuous integration, rev:196550eae86c00b025d6a4b464da877e95d8bd0e
https://jenkins.ubuntu.com/server/job/cloud-init-ci/881/
Executed test runs:
    SUCCESS: Checkout
    FAILED: Unit & Style Tests

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

review: Needs Fixing (continuous-integration)

3e98773... by Douglas Jordan on 2018-03-19

Style fix

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

FAILED: Continuous integration, rev:3e9877373627e08fbfce9ee9ad9f5180eb4bcc29
https://jenkins.ubuntu.com/server/job/cloud-init-ci/882/
Executed test runs:
    SUCCESS: Checkout
    FAILED: Unit & Style Tests

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

review: Needs Fixing (continuous-integration)

fb27875... by Douglas Jordan on 2018-03-19

Merge branch 'master' into azuretimeouts

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

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

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

review: Approve (continuous-integration)

ed5a580... by Douglas Jordan on 2018-03-23

Merge branch 'master' into azuretimeouts

dd1023f... by Douglas Jordan on 2018-03-23

Fixing exception_cb to match new contract

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

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

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

review: Approve (continuous-integration)

[Chad Smith (chad.smith)]

Approved this latest round with exception_cb updates. Ran through a battery of test on Azure with _poll_imds when IMDS service is not present, and 404s vs 200s. Looping and retries make sense here.

Thanks!

review: Approve

[Chad Smith (chad.smith)]

An upstream commit landed for this bug.

To view that commit see the following URL:
https://git.launchpad.net/cloud-init/commit/?id=2d618e27

diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py
index 0bb7fad..0ee622e 100644
--- a/cloudinit/sources/DataSourceAzure.py
+++ b/cloudinit/sources/DataSourceAzure.py
@@ -20,7 +20,7 @@ from cloudinit import net
 from cloudinit.net.dhcp import EphemeralDHCPv4
 from cloudinit import sources
 from cloudinit.sources.helpers.azure import get_metadata_from_fabric
-from cloudinit.url_helper import readurl, wait_for_url, UrlError
+from cloudinit.url_helper import readurl, UrlError
 from cloudinit import util
 
 LOG = logging.getLogger(__name__)
@@ -49,7 +49,6 @@ DEFAULT_FS = 'ext4'
 AZURE_CHASSIS_ASSET_TAG = '7783-7084-3265-9085-8269-3286-77'
 REPROVISION_MARKER_FILE = "/var/lib/cloud/data/poll_imds"
 IMDS_URL = "http://169.254.169.254/metadata/reprovisiondata"
-IMDS_RETRIES = 5
 
 
 def find_storvscid_from_sysctl_pnpinfo(sysctl_out, deviceid):
@@ -451,36 +450,24 @@ class DataSourceAzure(sources.DataSource):
         headers = {"Metadata": "true"}
         LOG.debug("Start polling IMDS")
 
-        def sleep_cb(response, loop_n):
-            return 1
-
-        def exception_cb(msg, exception):
+        def exc_cb(msg, exception):
             if isinstance(exception, UrlError) and exception.code == 404:
-                return
-            LOG.warning("Exception during polling. Will try DHCP.",
-                        exc_info=True)
-
+                return True
             # If we get an exception while trying to call IMDS, we
             # call DHCP and setup the ephemeral network to acquire the new IP.
-            raise exception
+            return False
 
         need_report = report_ready
-        for i in range(IMDS_RETRIES):
+        while True:
             try:
                 with EphemeralDHCPv4() as lease:
                     if need_report:
                         self._report_ready(lease=lease)
                         need_report = False
-                    wait_for_url([url], max_wait=None, timeout=60,
-                                 status_cb=LOG.info,
-                                 headers_cb=lambda url: headers, sleep_time=1,
-                                 exception_cb=exception_cb,
-                                 sleep_time_cb=sleep_cb)
-                    return str(readurl(url, headers=headers))
-            except Exception:
-                LOG.debug("Exception during polling-retrying dhcp" +
-                          " %d more time(s).", (IMDS_RETRIES - i),
-                          exc_info=True)
+                    return readurl(url, timeout=1, headers=headers,
+                                   exception_cb=exc_cb, infinite=True).contents
+            except UrlError:
+                pass
 
     def _report_ready(self, lease):
         """Tells the fabric provisioning has completed
diff --git a/cloudinit/url_helper.py b/cloudinit/url_helper.py
index 36289af..03a573a 100644
--- a/cloudinit/url_helper.py
+++ b/cloudinit/url_helper.py
@@ -16,7 +16,7 @@ import time
 
 from email.utils import parsedate
 from functools import partial
-
+from itertools import count
 from requests import exceptions
 
 from six.moves.urllib.parse import (
@@ -172,7 +172,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):
+            session=None, infinite=False):
     url = _cleanurl(url)
     req_args = {
         'url': url,
@@ -220,7 +220,8 @@ def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
     excps = []
     # Handle retrying ourselves since the built-in support
     # doesn't handle sleeping between tries...
-    for i in range(0, manual_tries):
+    # Infinitely retry if infinite is True
+    for i in count() if infinite else range(0, manual_tries):
         req_args['headers'] = headers_cb(url)
         filtered_req_args = {}
         for (k, v) in req_args.items():
@@ -229,7 +230,8 @@ def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
             filtered_req_args[k] = v
         try:
             LOG.debug("[%s/%s] open '%s' with %s configuration", i,
-                      manual_tries, url, filtered_req_args)
+                      "infinite" if infinite else manual_tries, url,
+                      filtered_req_args)
 
             if session is None:
                 session = requests.Session()
@@ -263,7 +265,8 @@ def readurl(url, data=None, timeout=None, retries=0, sec_between=1,
                 # to continue retrying and False to break and re-raise the
                 # exception
                 break
-            if i + 1 < manual_tries and sec_between > 0:
+            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)
                 time.sleep(sec_between)
diff --git a/tests/unittests/test_datasource/test_azure.py b/tests/unittests/test_datasource/test_azure.py
index da7da0c..3e8b791 100644
--- a/tests/unittests/test_datasource/test_azure.py
+++ b/tests/unittests/test_datasource/test_azure.py
@@ -1177,7 +1177,8 @@ class TestAzureDataSourcePreprovisioning(CiTestCase):
         url = 'http://{0}/metadata/reprovisiondata?api-version=2017-04-02'
         host = "169.254.169.254"
         full_url = url.format(host)
-        fake_resp.return_value = mock.MagicMock(status_code=200, text="ovf")
+        fake_resp.return_value = mock.MagicMock(status_code=200, text="ovf",
+                                                content="ovf")
         dsa = dsaz.DataSourceAzure({}, distro=None, paths=self.paths)
         self.assertTrue(len(dsa._poll_imds()) > 0)
         self.assertEqual(fake_resp.call_args_list,
@@ -1185,13 +1186,8 @@ class TestAzureDataSourcePreprovisioning(CiTestCase):
                                     headers={'Metadata': 'true',
                                              'User-Agent':
                                              'Cloud-Init/%s' % vs()
-                                             }, method='GET', timeout=60.0,
-                                    url=full_url),
-                          mock.call(allow_redirects=True,
-                                    headers={'Metadata': 'true',
-                                             'User-Agent':
-                                             'Cloud-Init/%s' % vs()
-                                             }, method='GET', url=full_url)])
+                                             }, method='GET', timeout=1,
+                                    url=full_url)])
         self.assertEqual(m_dhcp.call_count, 1)
         m_net.assert_any_call(
             broadcast='192.168.2.255', interface='eth9', ip='192.168.2.9',
@@ -1217,7 +1213,8 @@ class TestAzureDataSourcePreprovisioning(CiTestCase):
         username = "myuser"
         odata = {'HostName': hostname, 'UserName': username}
         content = construct_valid_ovf_env(data=odata)
-        fake_resp.return_value = mock.MagicMock(status_code=200, text=content)
+        fake_resp.return_value = mock.MagicMock(status_code=200, text=content,
+                                                content=content)
         dsa = dsaz.DataSourceAzure({}, distro=None, paths=self.paths)
         md, ud, cfg, d = dsa._reprovision()
         self.assertEqual(md['local-hostname'], hostname)
@@ -1227,12 +1224,7 @@ class TestAzureDataSourcePreprovisioning(CiTestCase):
                                     headers={'Metadata': 'true',
                                              'User-Agent':
                                              'Cloud-Init/%s' % vs()},
-                                    method='GET', timeout=60.0, url=full_url),
-                          mock.call(allow_redirects=True,
-                                    headers={'Metadata': 'true',
-                                             'User-Agent':
-                                             'Cloud-Init/%s' % vs()},
-                                    method='GET', url=full_url)])
+                                    method='GET', timeout=1, url=full_url)])
         self.assertEqual(m_dhcp.call_count, 1)
         m_net.assert_any_call(
             broadcast='192.168.2.255', interface='eth9', ip='192.168.2.9',