From c86283f0d9fe8a2634dc3c47727e6218fdaf25e2 Mon Sep 17 00:00:00 2001 From: Moustafa Moustafa Date: Wed, 4 Nov 2020 11:51:16 -0800 Subject: azure: enable pushing the log to KVP from the last pushed byte (#614) This allows the cloud-init log to be pushed multiple times during boot, with the latest lines being pushed each time. --- cloudinit/sources/helpers/azure.py | 44 +++++++++++++++++++++++--------- tests/unittests/test_reporting_hyperv.py | 7 ++--- 2 files changed, 36 insertions(+), 15 deletions(-) diff --git a/cloudinit/sources/helpers/azure.py b/cloudinit/sources/helpers/azure.py index 560cadba..4071a50e 100755 --- a/cloudinit/sources/helpers/azure.py +++ b/cloudinit/sources/helpers/azure.py @@ -9,6 +9,7 @@ import struct import time import textwrap import zlib +from errno import ENOENT from cloudinit.settings import CFG_BUILTIN from cloudinit.net import dhcp @@ -41,8 +42,9 @@ COMPRESSED_EVENT_TYPE = 'compressed' # cloud-init.log files where the P95 of the file sizes was 537KB and the time # consumed to dump 500KB file was (P95:76, P99:233, P99.9:1170) in ms MAX_LOG_TO_KVP_LENGTH = 512000 -# Marker file to indicate whether cloud-init.log is pushed to KVP -LOG_PUSHED_TO_KVP_MARKER_FILE = '/var/lib/cloud/data/log_pushed_to_kvp' +# File to store the last byte of cloud-init.log that was pushed to KVP. This +# file will be deleted with every VM reboot. +LOG_PUSHED_TO_KVP_INDEX_FILE = '/run/cloud-init/log_pushed_to_kvp_index' azure_ds_reporter = events.ReportEventStack( name="azure-ds", description="initialize reporter for azure ds", @@ -214,32 +216,50 @@ def report_compressed_event(event_name, event_content): def push_log_to_kvp(file_name=CFG_BUILTIN['def_log_file']): """Push a portion of cloud-init.log file or the whole file to KVP based on the file size. - If called more than once, it skips pushing the log file to KVP again.""" + The first time this function is called after VM boot, It will push the last + n bytes of the log file such that n < MAX_LOG_TO_KVP_LENGTH + If called again on the same boot, it continues from where it left off.""" - log_pushed_to_kvp = bool(os.path.isfile(LOG_PUSHED_TO_KVP_MARKER_FILE)) - if log_pushed_to_kvp: - report_diagnostic_event( - "cloud-init.log is already pushed to KVP", logger_func=LOG.debug) - return + start_index = get_last_log_byte_pushed_to_kvp_index() LOG.debug("Dumping cloud-init.log file to KVP") try: with open(file_name, "rb") as f: f.seek(0, os.SEEK_END) - seek_index = max(f.tell() - MAX_LOG_TO_KVP_LENGTH, 0) + seek_index = max(f.tell() - MAX_LOG_TO_KVP_LENGTH, start_index) report_diagnostic_event( - "Dumping last {} bytes of cloud-init.log file to KVP".format( - f.tell() - seek_index), + "Dumping last {0} bytes of cloud-init.log file to KVP starting" + " from index: {1}".format(f.tell() - seek_index, seek_index), logger_func=LOG.debug) f.seek(seek_index, os.SEEK_SET) report_compressed_event("cloud-init.log", f.read()) - util.write_file(LOG_PUSHED_TO_KVP_MARKER_FILE, '') + util.write_file(LOG_PUSHED_TO_KVP_INDEX_FILE, str(f.tell())) except Exception as ex: report_diagnostic_event( "Exception when dumping log file: %s" % repr(ex), logger_func=LOG.warning) +@azure_ds_telemetry_reporter +def get_last_log_byte_pushed_to_kvp_index(): + try: + with open(LOG_PUSHED_TO_KVP_INDEX_FILE, "r") as f: + return int(f.read()) + except IOError as e: + if e.errno != ENOENT: + report_diagnostic_event("Reading LOG_PUSHED_TO_KVP_INDEX_FILE" + " failed: %s." % repr(e), + logger_func=LOG.warning) + except ValueError as e: + report_diagnostic_event("Invalid value in LOG_PUSHED_TO_KVP_INDEX_FILE" + ": %s." % repr(e), + logger_func=LOG.warning) + except Exception as e: + report_diagnostic_event("Failed to get the last log byte pushed to KVP" + ": %s." % repr(e), logger_func=LOG.warning) + return 0 + + @contextmanager def cd(newdir): prevdir = os.getcwd() diff --git a/tests/unittests/test_reporting_hyperv.py b/tests/unittests/test_reporting_hyperv.py index 3f63a60e..8f7b3694 100644 --- a/tests/unittests/test_reporting_hyperv.py +++ b/tests/unittests/test_reporting_hyperv.py @@ -237,7 +237,7 @@ class TextKvpReporter(CiTestCase): instantiated_handler_registry.register_item("telemetry", reporter) log_file = self.tmp_path("cloud-init.log") azure.MAX_LOG_TO_KVP_LENGTH = 100 - azure.LOG_PUSHED_TO_KVP_MARKER_FILE = self.tmp_path( + azure.LOG_PUSHED_TO_KVP_INDEX_FILE = self.tmp_path( 'log_pushed_to_kvp') with open(log_file, "w") as f: log_content = "A" * 50 + "B" * 100 @@ -254,8 +254,9 @@ class TextKvpReporter(CiTestCase): self.assertNotEqual( event.event_type, azure.COMPRESSED_EVENT_TYPE) self.validate_compressed_kvps( - reporter, 1, - [log_content[-azure.MAX_LOG_TO_KVP_LENGTH:].encode()]) + reporter, 2, + [log_content[-azure.MAX_LOG_TO_KVP_LENGTH:].encode(), + extra_content.encode()]) finally: instantiated_handler_registry.unregister_item("telemetry", force=False) -- cgit v1.2.3