Azure: Record boot timestamps, system information, and diagnostic events

Collect and record the following information through KVP:
 + timestamps related to kernel initialization and systemd activation
   of cloud-init services
 + system information including cloud-init version, kernel version,
   distro version, and python version
 + diagnostic events for the most common provisioning error issues
   such as empty dhcp lease, corrupted ovf-env.xml, etc.
 + increasing the log frequency of polling IMDS during reprovision.

2 files changed, 75 insertions, 5 deletions

diff --git a/tests/unittests/test_datasource/test_azure.py b/tests/unittests/test_datasource/test_azure.py
index 4d57cebc..3547dd94 100644
--- a/tests/unittests/test_datasource/test_azure.py
+++ b/tests/unittests/test_datasource/test_azure.py
@@ -181,7 +181,7 @@ class TestGetMetadataFromIMDS(HttprettyTestCase):
             self.logs.getvalue())
 
     @mock.patch(MOCKPATH + 'readurl')
-    @mock.patch(MOCKPATH + 'EphemeralDHCPv4')
+    @mock.patch(MOCKPATH + 'EphemeralDHCPv4WithReporting')
     @mock.patch(MOCKPATH + 'net.is_up')
     def test_get_metadata_performs_dhcp_when_network_is_down(
             self, m_net_is_up, m_dhcp, m_readurl):
@@ -195,7 +195,7 @@ class TestGetMetadataFromIMDS(HttprettyTestCase):
             dsaz.get_metadata_from_imds('eth9', retries=2))
 
         m_net_is_up.assert_called_with('eth9')
-        m_dhcp.assert_called_with('eth9')
+        m_dhcp.assert_called_with(mock.ANY, 'eth9')
         self.assertIn(
             "Crawl of Azure Instance Metadata Service (IMDS) took",  # log_time
             self.logs.getvalue())
@@ -552,7 +552,8 @@ scbus-1 on xpt0 bus 0
             dsrc.crawl_metadata()
         self.assertEqual(str(cm.exception), error_msg)
 
-    @mock.patch('cloudinit.sources.DataSourceAzure.EphemeralDHCPv4')
+    @mock.patch(
+        'cloudinit.sources.DataSourceAzure.EphemeralDHCPv4WithReporting')
     @mock.patch('cloudinit.sources.DataSourceAzure.util.write_file')
     @mock.patch(
         'cloudinit.sources.DataSourceAzure.DataSourceAzure._report_ready')
@@ -1308,7 +1309,9 @@ class TestAzureBounce(CiTestCase):
         self.assertEqual(initial_host_name,
                          self.set_hostname.call_args_list[-1][0][0])
 
-    def test_environment_correct_for_bounce_command(self):
+    @mock.patch.object(dsaz, 'get_boot_telemetry')
+    def test_environment_correct_for_bounce_command(
+            self, mock_get_boot_telemetry):
         interface = 'int0'
         hostname = 'my-new-host'
         old_hostname = 'my-old-host'
@@ -1324,7 +1327,9 @@ class TestAzureBounce(CiTestCase):
         self.assertEqual(hostname, bounce_env['hostname'])
         self.assertEqual(old_hostname, bounce_env['old_hostname'])
 
-    def test_default_bounce_command_ifup_used_by_default(self):
+    @mock.patch.object(dsaz, 'get_boot_telemetry')
+    def test_default_bounce_command_ifup_used_by_default(
+            self, mock_get_boot_telemetry):
         cfg = {'hostname_bounce': {'policy': 'force'}}
         data = self.get_ovf_env_with_dscfg('some-hostname', cfg)
         dsrc = self._get_ds(data, agent_command=['not', '__builtin__'])
diff --git a/tests/unittests/test_reporting_hyperv.py b/tests/unittests/test_reporting_hyperv.py
index d01ed5b3..640895a4 100755..100644
--- a/tests/unittests/test_reporting_hyperv.py
+++ b/tests/unittests/test_reporting_hyperv.py
@@ -7,9 +7,12 @@ import json
 import os
 import struct
 import time
+import re
+import mock
 
 from cloudinit import util
 from cloudinit.tests.helpers import CiTestCase
+from cloudinit.sources.helpers import azure
 
 
 class TestKvpEncoding(CiTestCase):
@@ -126,3 +129,65 @@ class TextKvpReporter(CiTestCase):
         reporter = HyperVKvpReportingHandler(kvp_file_path=self.tmp_file_path)
         kvps = list(reporter._iterate_kvps(0))
         self.assertEqual(0, len(kvps))
+
+    @mock.patch('cloudinit.distros.uses_systemd')
+    @mock.patch('cloudinit.util.subp')
+    def test_get_boot_telemetry(self, m_subp, m_sysd):
+        reporter = HyperVKvpReportingHandler(kvp_file_path=self.tmp_file_path)
+        datetime_pattern = r"\d{4}-[01]\d-[0-3]\dT[0-2]\d:[0-5]"
+        r"\d:[0-5]\d\.\d+([+-][0-2]\d:[0-5]\d|Z)"
+
+        # get_boot_telemetry makes two subp calls to systemctl. We provide
+        # a list of values that the subp calls should return
+        m_subp.side_effect = [
+            ('UserspaceTimestampMonotonic=1844838', ''),
+            ('InactiveExitTimestampMonotonic=3068203', '')]
+        m_sysd.return_value = True
+
+        reporter.publish_event(azure.get_boot_telemetry())
+        reporter.q.join()
+        kvps = list(reporter._iterate_kvps(0))
+        self.assertEqual(1, len(kvps))
+
+        evt_msg = kvps[0]['value']
+        if not re.search("kernel_start=" + datetime_pattern, evt_msg):
+            raise AssertionError("missing kernel_start timestamp")
+        if not re.search("user_start=" + datetime_pattern, evt_msg):
+            raise AssertionError("missing user_start timestamp")
+        if not re.search("cloudinit_activation=" + datetime_pattern,
+                         evt_msg):
+            raise AssertionError(
+                "missing cloudinit_activation timestamp")
+
+    def test_get_system_info(self):
+        reporter = HyperVKvpReportingHandler(kvp_file_path=self.tmp_file_path)
+        pattern = r"[^=\s]+"
+
+        reporter.publish_event(azure.get_system_info())
+        reporter.q.join()
+        kvps = list(reporter._iterate_kvps(0))
+        self.assertEqual(1, len(kvps))
+        evt_msg = kvps[0]['value']
+
+        # the most important information is cloudinit version,
+        # kernel_version, and the distro variant. It is ok if
+        # if the rest is not available
+        if not re.search("cloudinit_version=" + pattern, evt_msg):
+            raise AssertionError("missing cloudinit_version string")
+        if not re.search("kernel_version=" + pattern, evt_msg):
+            raise AssertionError("missing kernel_version string")
+        if not re.search("variant=" + pattern, evt_msg):
+            raise AssertionError("missing distro variant string")
+
+    def test_report_diagnostic_event(self):
+        reporter = HyperVKvpReportingHandler(kvp_file_path=self.tmp_file_path)
+
+        reporter.publish_event(
+            azure.report_diagnostic_event("test_diagnostic"))
+        reporter.q.join()
+        kvps = list(reporter._iterate_kvps(0))
+        self.assertEqual(1, len(kvps))
+        evt_msg = kvps[0]['value']
+
+        if "test_diagnostic" not in evt_msg:
+            raise AssertionError("missing expected diagnostic message")