Pushing cloud-init log to the KVP (#529)

Push the cloud-init.log file (Up to 500KB at once) to the KVP before reporting ready to the Azure platform.
Based on the analysis done on a large sample of cloud-init.log files, Here's the statistics collected on the log file size:
P50 	P90 	P95 	P99 	P99.9 	P99.99
137K 	423K 	537K 	3.5MB 	6MB 	16MB

This change limits the size of cloud-init.log file data that gets dumped to KVP to 500KB. So for ~95% of the cases, the whole log file will be dumped and for the remaining ~5%, we will get the last 500KB of the cloud-init.log file.
To asses the performance of the 500KB limit, 250 VM were deployed with a 500KB cloud-init.log file and the time taken to compress, encode and dump the entries to KVP was measured. Here's the time in milliseconds percentiles:
P50 	P99 	P999
75.705 	232.701 	1169.636

Another 250 VMs were deployed with this logic dumping their normal cloud-init.log file to KVP, the same timing was measured as above. Here's the time in milliseconds percentiles:
P50 	P99 	P999
1.88 	5.277 	6.992

Added excluded_handlers to the report_event function to be able to opt-out from reporting the events of the compressed cloud-init.log file to the cloud-init.log file.

The KVP break_down logic had a bug, where it will reuse the same key for all the split chunks of KVP which results in overwriting the split KVPs by the last one when consumed by Hyper-V. I added the split chunk index as a differentiator to the KVP key.

The Hyper-V consumes the KVPs from the KVP file as chunks whose key is 512KB and value is 2048KB but the Azure platform expects the value to be 1024KB, thus I introduced the Azure value limit.

2 files changed, 27 insertions, 8 deletions

diff --git a/cloudinit/reporting/events.py b/cloudinit/reporting/events.py
index e5dfab33..b8677c8b 100644
--- a/cloudinit/reporting/events.py
+++ b/cloudinit/reporting/events.py
@@ -12,7 +12,7 @@ import base64
 import os.path
 import time
 
-from . import instantiated_handler_registry
+from . import instantiated_handler_registry, available_handlers
 
 FINISH_EVENT_TYPE = 'finish'
 START_EVENT_TYPE = 'start'
@@ -81,17 +81,32 @@ class FinishReportingEvent(ReportingEvent):
         return data
 
 
-def report_event(event):
-    """Report an event to all registered event handlers.
+def report_event(event, excluded_handler_types=None):
+    """Report an event to all registered event handlers
+    except those whose type is in excluded_handler_types.
 
     This should generally be called via one of the other functions in
     the reporting module.
 
+    :param excluded_handler_types:
+         List of handlers types to exclude from reporting the event to.
     :param event_type:
         The type of the event; this should be a constant from the
         reporting module.
     """
-    for _, handler in instantiated_handler_registry.registered_items.items():
+
+    if not excluded_handler_types:
+        excluded_handler_types = {}
+    excluded_handler_classes = {
+        hndl_cls
+        for hndl_type, hndl_cls in available_handlers.registered_items.items()
+        if hndl_type in excluded_handler_types
+    }
+
+    handlers = instantiated_handler_registry.registered_items.items()
+    for _, handler in handlers:
+        if type(handler) in excluded_handler_classes:
+            continue  # skip this excluded handler
         handler.publish_event(event)
 
 
diff --git a/cloudinit/reporting/handlers.py b/cloudinit/reporting/handlers.py
index 1986ebdd..0a8c7af3 100755
--- a/cloudinit/reporting/handlers.py
+++ b/cloudinit/reporting/handlers.py
@@ -113,6 +113,8 @@ class HyperVKvpReportingHandler(ReportingHandler):
     https://technet.microsoft.com/en-us/library/dn798287.aspx#Linux%20guests
     """
     HV_KVP_EXCHANGE_MAX_VALUE_SIZE = 2048
+    # The maximum value size expected in Azure
+    HV_KVP_AZURE_MAX_VALUE_SIZE = 1024
     HV_KVP_EXCHANGE_MAX_KEY_SIZE = 512
     HV_KVP_RECORD_SIZE = (HV_KVP_EXCHANGE_MAX_KEY_SIZE +
                           HV_KVP_EXCHANGE_MAX_VALUE_SIZE)
@@ -195,7 +197,8 @@ class HyperVKvpReportingHandler(ReportingHandler):
     def _event_key(self, event):
         """
         the event key format is:
-        CLOUD_INIT|<incarnation number>|<event_type>|<event_name>|<time>
+        CLOUD_INIT|<incarnation number>|<event_type>|<event_name>|<uuid>
+        [|subevent_index]
         """
         return u"{0}|{1}|{2}|{3}".format(self.event_key_prefix,
                                          event.event_type, event.name,
@@ -249,13 +252,14 @@ class HyperVKvpReportingHandler(ReportingHandler):
             data_without_desc = json.dumps(meta_data,
                                            separators=self.JSON_SEPARATORS)
             room_for_desc = (
-                self.HV_KVP_EXCHANGE_MAX_VALUE_SIZE -
+                self.HV_KVP_AZURE_MAX_VALUE_SIZE -
                 len(data_without_desc) - 8)
             value = data_without_desc.replace(
                 message_place_holder,
                 '"{key}":"{desc}"'.format(
                     key=self.MSG_KEY, desc=des_in_json[:room_for_desc]))
-            result_array.append(self._encode_kvp_item(key, value))
+            subkey = "{}|{}".format(key, i)
+            result_array.append(self._encode_kvp_item(subkey, value))
             i += 1
             des_in_json = des_in_json[room_for_desc:]
             if len(des_in_json) == 0:
@@ -282,7 +286,7 @@ class HyperVKvpReportingHandler(ReportingHandler):
         # if it reaches the maximum length of kvp value,
         # break it down to slices.
         # this should be very corner case.
-        if len(value) > self.HV_KVP_EXCHANGE_MAX_VALUE_SIZE:
+        if len(value) > self.HV_KVP_AZURE_MAX_VALUE_SIZE:
             return self._break_down(key, meta_data, event.description)
         else:
             data = self._encode_kvp_item(key, value)