Repository: Azure/WALinuxAgent

Issue:
Track Boot Time in Provision Event
To better understand and break down the provision process please include the boot time in the provision event, or emit a boot event with an appropriate duration.

Discussion:

Patch:
diff --git a/azurelinuxagent/pa/provision/cloudinit.py b/azurelinuxagent/pa/provision/cloudinit.py
index 60d42fd2..de07ea93 100644
--- a/azurelinuxagent/pa/provision/cloudinit.py
+++ b/azurelinuxagent/pa/provision/cloudinit.py
@@ -64,7 +64,7 @@ class CloudInitProvisionHandler(ProvisionHandler):
             logger.info("Finished provisioning")
 
             self.report_ready(thumbprint)
-            self.report_event("Provisioning with cloud-init succeeded",
+            self.report_event("Provisioning with cloud-init succeeded ({0})".format(self._get_uptime_seconds()),
                 is_success=True,
                 duration=elapsed_milliseconds(utc_start))
 
diff --git a/azurelinuxagent/pa/provision/default.py b/azurelinuxagent/pa/provision/default.py
index 5d07fdf4..5df572cb 100644
--- a/azurelinuxagent/pa/provision/default.py
+++ b/azurelinuxagent/pa/provision/default.py
@@ -88,7 +88,7 @@ class ProvisionHandler(object):
 
             self.write_provisioned()
 
-            self.report_event("Provisioning succeeded",
+            self.report_event("Provisioning succeeded ({0})".format(self._get_uptime_seconds()),
                 is_success=True,
                 duration=elapsed_milliseconds(utc_start))
 
@@ -125,6 +125,15 @@ class ProvisionHandler(object):
                 continue
         return is_running == is_expected
 
+    @staticmethod
+    def _get_uptime_seconds():
+        try:
+            with open('/proc/uptime') as fh:
+                uptime, _ = fh.readline().split()
+                return uptime
+        except:
+            return 0
+
     def reg_ssh_host_key(self):
         keypair_type = conf.get_ssh_host_keypair_type()
         if conf.get_regenerate_ssh_host_key():


Test patch:
diff --git a/tests/pa/test_provision.py b/tests/pa/test_provision.py
index 1004547b..52098f2f 100644
--- a/tests/pa/test_provision.py
+++ b/tests/pa/test_provision.py
@@ -146,8 +146,12 @@ class TestProvision(AgentTestCase):
 
         ph.run()
 
-        call1 = call("Provisioning succeeded", duration=ANY, is_success=True)
-        ph.report_event.assert_has_calls([call1])
+        self.assertEqual(1, ph.report_event.call_count)
+        positional_args, kw_args = ph.report_event.call_args
+        # [call('Provisioning succeeded (146473.68)', duration=65, is_success=True)]
+        self.assertTrue(re.match(r'Provisioning succeeded \(\d+\.\d+\)', positional_args[0]) is not None)
+        self.assertTrue(isinstance(kw_args['duration'], int))
+        self.assertTrue(kw_args['is_success'])
 
     @distros()
     @patch(