From 86daea43b4a0963b9a2d5c0ffa3a6decdb87b7c1 Mon Sep 17 00:00:00 2001 From: Brett Holman Date: Mon, 2 Sep 2024 14:44:06 -0600 Subject: [PATCH] chore: add timer to io and string manipulation code refactors existing code to utilize timer codepaths: - replace manual timer implementations in subp.py and sockets.py - replace open() / read() calls with util.load_text_file() where appropriate --- cloudinit/atomic_helper.py | 58 +++++---- cloudinit/cmd/main.py | 15 +-- cloudinit/config/cc_growpart.py | 4 +- cloudinit/config/modules.py | 14 ++- cloudinit/config/schema.py | 23 +++- cloudinit/dmi.py | 6 +- cloudinit/log/log_util.py | 4 +- cloudinit/net/eni.py | 12 +- cloudinit/reporting/events.py | 5 +- cloudinit/reporting/handlers.py | 6 +- cloudinit/safeyaml.py | 37 +++--- cloudinit/socket.py | 9 +- cloudinit/sources/DataSourceAzure.py | 4 +- cloudinit/sources/DataSourceVMware.py | 7 +- cloudinit/sources/helpers/azure.py | 4 +- .../helpers/vmware/imc/guestcust_util.py | 6 +- cloudinit/ssh_util.py | 7 +- cloudinit/subp.py | 32 +++-- cloudinit/templater.py | 26 ++-- cloudinit/url_helper.py | 10 +- cloudinit/util.py | 118 +++++++++--------- tests/unittests/config/test_schema.py | 6 +- 22 files changed, 241 insertions(+), 172 deletions(-) diff --git a/cloudinit/atomic_helper.py b/cloudinit/atomic_helper.py index 8d355b3c243..91c0dbabfae 100644 --- a/cloudinit/atomic_helper.py +++ b/cloudinit/atomic_helper.py @@ -7,35 +7,50 @@ import tempfile from base64 import b64decode, b64encode -from cloudinit import util +from cloudinit import log, util _DEF_PERMS = 0o644 LOG = logging.getLogger(__name__) def b64d(source): - # Base64 decode some data, accepting bytes or unicode/str, and returning - # str/unicode if the result is utf-8 compatible, otherwise returning bytes. - decoded = b64decode(source) - try: - return decoded.decode("utf-8") - except UnicodeDecodeError: - return decoded + """base64 decode data + + :param source: a bytes or str to decode + :return: base64 as a decoded str if utf-8 encoded, otherwise bytes + """ + with log.log_time("Base64 decoding"): + decoded = b64decode(source) + try: + return decoded.decode("utf-8") + except UnicodeDecodeError: + return decoded def b64e(source): - # Base64 encode some data, accepting bytes or unicode/str, and returning - # str/unicode if the result is utf-8 compatible, otherwise returning bytes. - if not isinstance(source, bytes): - source = source.encode("utf-8") - return b64encode(source).decode("utf-8") + """base64 encode data + + :param source: a bytes or str to decode + :return: base64 encoded str + """ + with log.log_time("Base64 encodeing"): + if not isinstance(source, bytes): + source = source.encode("utf-8") + return b64encode(source).decode("utf-8") def write_file( filename, content, mode=_DEF_PERMS, omode="wb", preserve_mode=False ): - # open filename in mode 'omode', write content, set permissions to 'mode' + """open filename in mode omode, write content, set permissions to mode""" + + with log.log_time(f"Writing {filename}"): + return _write_file(filename, content, mode, omode, preserve_mode) + +def _write_file( + filename, content, mode=_DEF_PERMS, omode="wb", preserve_mode=False +): if preserve_mode: try: file_stat = os.stat(filename) @@ -77,13 +92,14 @@ def json_serialize_default(_obj): def json_dumps(data): """Return data in nicely formatted json.""" - return json.dumps( - data, - indent=1, - sort_keys=True, - separators=(",", ": "), - default=json_serialize_default, - ) + with log.log_time("Dumping json"): + return json.dumps( + data, + indent=1, + sort_keys=True, + separators=(",", ": "), + default=json_serialize_default, + ) def write_json(filename, data, mode=_DEF_PERMS): diff --git a/cloudinit/cmd/main.py b/cloudinit/cmd/main.py index e5964883e7e..466c897e74f 100644 --- a/cloudinit/cmd/main.py +++ b/cloudinit/cmd/main.py @@ -134,12 +134,13 @@ def close_stdin(logger: Callable[[str], None] = LOG.debug): logger: a function for logging messages """ - if not os.isatty(sys.stdin.fileno()): - logger("Closing stdin") - with open(os.devnull) as fp: - os.dup2(fp.fileno(), sys.stdin.fileno()) - else: - logger("Not closing stdin, stdin is a tty.") + with log.log_time("Closing stdin"): + if not os.isatty(sys.stdin.fileno()): + logger("Closing stdin") + with open(os.devnull) as fp: + os.dup2(fp.fileno(), sys.stdin.fileno()) + else: + logger("Not closing stdin, stdin is a tty.") def extract_fns(args): @@ -310,7 +311,7 @@ def purge_cache_on_python_version_change(init): init.paths.get_cpath("data"), "python-version" ) if os.path.exists(python_version_path): - cached_python_version = open(python_version_path).read() + cached_python_version = util.load_text_file(python_version_path) # The Python version has changed out from under us, anything that was # pickled previously is likely useless due to API changes. if cached_python_version != current_python_version: diff --git a/cloudinit/config/cc_growpart.py b/cloudinit/config/cc_growpart.py index 6eee11b7c48..1cedb7bbc26 100644 --- a/cloudinit/config/cc_growpart.py +++ b/cloudinit/config/cc_growpart.py @@ -20,7 +20,7 @@ from pathlib import Path from typing import Optional, Tuple -from cloudinit import lifecycle, subp, temp_utils, util +from cloudinit import lifecycle, log, subp, temp_utils, util from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema @@ -318,7 +318,7 @@ def resize_encrypted(blockdev, partition) -> Tuple[str, str]: if not KEYDATA_PATH.exists(): return (RESIZE.SKIPPED, "No encryption keyfile found") try: - with KEYDATA_PATH.open() as f: + with log.log_time(f"Reading {KEYDATA_PATH}"), KEYDATA_PATH.open() as f: keydata = json.load(f) key = keydata["key"] decoded_key = base64.b64decode(key) diff --git a/cloudinit/config/modules.py b/cloudinit/config/modules.py index a82e1ff8e8e..c55bfbc55f1 100644 --- a/cloudinit/config/modules.py +++ b/cloudinit/config/modules.py @@ -12,7 +12,7 @@ from types import ModuleType from typing import Dict, List, NamedTuple, Optional -from cloudinit import config, importer, lifecycle, type_utils, util +from cloudinit import config, importer, lifecycle, log, type_utils, util from cloudinit.distros import ALL_DISTROS from cloudinit.helpers import ConfigMerger from cloudinit.reporting.events import ReportEventStack @@ -283,11 +283,15 @@ def _run_modules(self, mostly_mods: List[ModuleDetails]): deprecated_version="23.2", ) func_args.update({"log": LOG}) - ran, _r = cc.run( - run_name, mod.handle, func_args, freq=freq - ) + + timer = log.log_time("and", skip_log=True) + with timer: + ran, _r = cc.run( + run_name, mod.handle, func_args, freq=freq + ) if ran: - myrep.message = "%s ran successfully" % run_name + time = f" {timer.output}" if timer.output else "" + myrep.message = f"{run_name} ran successfully {time}" else: myrep.message = "%s previously ran" % run_name diff --git a/cloudinit/config/schema.py b/cloudinit/config/schema.py index 27caa0bd306..2530257be4e 100644 --- a/cloudinit/config/schema.py +++ b/cloudinit/config/schema.py @@ -31,7 +31,7 @@ import yaml -from cloudinit import features, importer, lifecycle, safeyaml +from cloudinit import features, importer, lifecycle, log, safeyaml from cloudinit.cmd.devel import read_cfg_paths from cloudinit.handlers import INCLUSION_TYPES_MAP, type_from_starts_with from cloudinit.helpers import Paths @@ -732,6 +732,27 @@ def validate_cloudconfig_schema( @raises: ValueError on invalid schema_type not in CLOUD_CONFIG or NETWORK_CONFIG_V1 or NETWORK_CONFIG_V2 """ + with log.log_time(f"Validating {schema_type}"): + return _validate_cloudconfig_schema( + config, + schema, + schema_type, + strict, + strict_metaschema, + log_details, + log_deprecations, + ) + + +def _validate_cloudconfig_schema( + config: dict, + schema: Optional[dict] = None, + schema_type: SchemaType = SchemaType.CLOUD_CONFIG, + strict: bool = False, + strict_metaschema: bool = False, + log_details: bool = True, + log_deprecations: bool = False, +) -> bool: from cloudinit.net.netplan import available as netplan_available if schema_type == SchemaType.NETWORK_CONFIG: diff --git a/cloudinit/dmi.py b/cloudinit/dmi.py index 453e8510ab4..9de7ab2a433 100644 --- a/cloudinit/dmi.py +++ b/cloudinit/dmi.py @@ -5,7 +5,7 @@ from collections import namedtuple from typing import Optional -from cloudinit import subp +from cloudinit import log, subp from cloudinit.util import ( is_container, is_DragonFlyBSD, @@ -91,7 +91,9 @@ def _read_dmi_syspath(key: str) -> Optional[str]: return None try: - with open(dmi_key_path, "rb") as fp: + with log.log_time(f"Reading {dmi_key_path}"), open( + dmi_key_path, "rb" + ) as fp: key_data = fp.read() except PermissionError: LOG.debug("Could not read %s", dmi_key_path) diff --git a/cloudinit/log/log_util.py b/cloudinit/log/log_util.py index 0d01f8eb20a..d87a13b34a1 100644 --- a/cloudinit/log/log_util.py +++ b/cloudinit/log/log_util.py @@ -3,6 +3,8 @@ import sys import time +LOG = logging.getLogger(__name__) + def logexc( log, msg, *args, log_level: int = logging.WARNING, exc_info=True @@ -57,7 +59,7 @@ def __exit__(self, exc_type, exc_val, exc_tb): def write_to_console(conpath, text): - with open(conpath, "w") as wfh: + with log_time(f"Writing to {conpath}"), open(conpath, "w") as wfh: wfh.write(text) wfh.flush() diff --git a/cloudinit/net/eni.py b/cloudinit/net/eni.py index 59dc395f922..44ac80af05c 100644 --- a/cloudinit/net/eni.py +++ b/cloudinit/net/eni.py @@ -7,7 +7,7 @@ import re from typing import Optional -from cloudinit import subp, util +from cloudinit import log, subp, util from cloudinit.net import ParserError, renderer, subnet_is_ipv6 from cloudinit.net.network_state import NetworkState @@ -208,8 +208,7 @@ def _parse_deb_config_data(ifaces, contents, src_dir, src_path): ) ] for entry in dir_contents: - with open(entry, "r") as fp: - src_data = fp.read().strip() + src_data = util.load_text_file(entry).strip() abs_entry = os.path.abspath(entry) _parse_deb_config_data( ifaces, src_data, os.path.dirname(abs_entry), abs_entry @@ -310,9 +309,10 @@ def _parse_deb_config_data(ifaces, contents, src_dir, src_path): def convert_eni_data(eni_data): # return a network config representation of what is in eni_data - ifaces = {} - _parse_deb_config_data(ifaces, eni_data, src_dir=None, src_path=None) - return _ifaces_to_net_config_data(ifaces) + with log.log_time("Converting eni data"): + ifaces = {} + _parse_deb_config_data(ifaces, eni_data, src_dir=None, src_path=None) + return _ifaces_to_net_config_data(ifaces) def _ifaces_to_net_config_data(ifaces): diff --git a/cloudinit/reporting/events.py b/cloudinit/reporting/events.py index fac77435be0..05d6d840e45 100644 --- a/cloudinit/reporting/events.py +++ b/cloudinit/reporting/events.py @@ -9,10 +9,12 @@ They can be published to registered handlers with report_event. """ import base64 +import logging import os.path import time from typing import List +from cloudinit import log from cloudinit.reporting import ( available_handlers, instantiated_handler_registry, @@ -23,6 +25,7 @@ START_EVENT_TYPE = "start" DEFAULT_EVENT_ORIGIN = "cloudinit" +LOG = logging.getLogger(__name__) class _nameset(set): @@ -301,7 +304,7 @@ def _collect_file_info(files): if not os.path.isfile(fname): content = None else: - with open(fname, "rb") as fp: + with log.log_time(f"Reading {fname}"), open(fname, "rb") as fp: content = base64.b64encode(fp.read()).decode() ret.append({"path": fname, "content": content, "encoding": "base64"}) return ret diff --git a/cloudinit/reporting/handlers.py b/cloudinit/reporting/handlers.py index 80258f3e932..3ea80f827de 100644 --- a/cloudinit/reporting/handlers.py +++ b/cloudinit/reporting/handlers.py @@ -14,7 +14,7 @@ from threading import Event from typing import Union -from cloudinit import url_helper, util +from cloudinit import log, url_helper, util from cloudinit.registry import DictRegistry LOG = logging.getLogger(__name__) @@ -310,7 +310,9 @@ def _decode_kvp_item(self, record_data): return {"key": k, "value": v} def _append_kvp_item(self, record_data): - with open(self._kvp_file_path, "ab") as f: + with log.log_time(f"Appending {self._kvp_file_path}"), open( + self._kvp_file_path, "ab" + ) as f: fcntl.flock(f, fcntl.LOCK_EX) for data in record_data: f.write(data) diff --git a/cloudinit/safeyaml.py b/cloudinit/safeyaml.py index a4328068f66..b448c40abda 100644 --- a/cloudinit/safeyaml.py +++ b/cloudinit/safeyaml.py @@ -4,12 +4,17 @@ # # This file is part of cloud-init. See LICENSE file for license information. +import logging from collections import defaultdict from itertools import chain from typing import Any, Dict, List, Tuple import yaml +from cloudinit import log + +LOG = logging.getLogger(__name__) + # SchemaPathMarks track the path to an element within a loaded YAML file. # The start_mark and end_mark contain the row and column indicators @@ -250,23 +255,25 @@ def load_with_marks(blob) -> Tuple[Any, Dict[str, int]]: """ - result = yaml.load(blob, Loader=_CustomSafeLoaderWithMarks) - if not isinstance(result, dict): - schemamarks = {} - else: - schemamarks = result.pop("schemamarks") - return result, schemamarks + with log.log_time("Loading yaml"): + result = yaml.load(blob, Loader=_CustomSafeLoaderWithMarks) + if not isinstance(result, dict): + schemamarks = {} + else: + schemamarks = result.pop("schemamarks") + return result, schemamarks def dumps(obj, explicit_start=True, explicit_end=True, noalias=False): """Return data in nicely formatted yaml.""" - return yaml.dump( - obj, - line_break="\n", - indent=4, - explicit_start=explicit_start, - explicit_end=explicit_end, - default_flow_style=False, - Dumper=(NoAliasSafeDumper if noalias else yaml.dumper.SafeDumper), - ) + with log.log_time("Dumping yaml"): + return yaml.dump( + obj, + line_break="\n", + indent=4, + explicit_start=explicit_start, + explicit_end=explicit_end, + default_flow_style=False, + Dumper=(NoAliasSafeDumper if noalias else yaml.dumper.SafeDumper), + ) diff --git a/cloudinit/socket.py b/cloudinit/socket.py index 7ef19f43798..cdcb0c2adb8 100644 --- a/cloudinit/socket.py +++ b/cloudinit/socket.py @@ -4,9 +4,9 @@ import os import socket import sys -import time from contextlib import suppress +from cloudinit import log from cloudinit.settings import DEFAULT_RUN_DIR LOG = logging.getLogger(__name__) @@ -109,14 +109,14 @@ def __enter__(self): "STATUS=Waiting on external services to " f"complete before starting the {self.stage} stage." ) - start_time = time.monotonic() # block until init system sends us data # the first value returned contains a message from the init system # (should be "start") # the second value contains the path to a unix socket on which to # reply, which is expected to be /path/to/{self.stage}-return.sock sock = self.sockets[self.stage] - chunk, self.remote = sock.recvfrom(5) + with log.log_time(f"Waiting to start stage {self.stage}"): + chunk, self.remote = sock.recvfrom(5) if b"start" != chunk: # The protocol expects to receive a command "start" @@ -130,10 +130,7 @@ def __enter__(self): self.__exit__(None, None, None) raise ValueError(f"Unexpected path to unix socket: {self.remote}") - total = time.monotonic() - start_time - time_msg = f"took {total: .3f}s to " if total > 0.01 else "" sd_notify(f"STATUS=Running ({self.stage} stage)") - LOG.debug("sync(%s): synchronization %scomplete", self.stage, time_msg) return self def __exit__(self, exc_type, exc_val, exc_tb): diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py index 149bb7545d4..9e6e3707a8d 100644 --- a/cloudinit/sources/DataSourceAzure.py +++ b/cloudinit/sources/DataSourceAzure.py @@ -19,7 +19,7 @@ import requests -from cloudinit import net, sources, ssh_util, subp, util +from cloudinit import log, net, sources, ssh_util, subp, util from cloudinit.event import EventScope, EventType from cloudinit.net import device_driver from cloudinit.net.dhcp import ( @@ -1995,7 +1995,7 @@ def load_azure_ds_dir(source_dir): if not os.path.isfile(ovf_file): raise NonAzureDataSource("No ovf-env file found") - with open(ovf_file, "rb") as fp: + with log.log_time("Reading ovf-env.xml"), open(ovf_file, "rb") as fp: contents = fp.read() md, ud, cfg = read_azure_ovf(contents) diff --git a/cloudinit/sources/DataSourceVMware.py b/cloudinit/sources/DataSourceVMware.py index 888060c9bd9..b4fdd24403e 100644 --- a/cloudinit/sources/DataSourceVMware.py +++ b/cloudinit/sources/DataSourceVMware.py @@ -266,9 +266,10 @@ def get_instance_id(self): # read the file /sys/class/dmi/id/product_uuid for the instance ID. if self.metadata and "instance-id" in self.metadata: return self.metadata["instance-id"] - with open(PRODUCT_UUID_FILE_PATH, "r") as id_file: - self.metadata["instance-id"] = str(id_file.read()).rstrip().lower() - return self.metadata["instance-id"] + self.metadata["instance-id"] = ( + util.load_text_file(PRODUCT_UUID_FILE_PATH).rstrip().lower() + ) + return self.metadata["instance-id"] def check_if_fallback_is_allowed(self): if ( diff --git a/cloudinit/sources/helpers/azure.py b/cloudinit/sources/helpers/azure.py index 1493afc5195..ae6eea1b4fb 100644 --- a/cloudinit/sources/helpers/azure.py +++ b/cloudinit/sources/helpers/azure.py @@ -457,7 +457,9 @@ def generate_certificate(self): ] ) certificate = "" - for line in open(self.certificate_names["certificate"]): + for line in util.load_text_file( + self.certificate_names["certificate"] + ).split("\n"): if "CERTIFICATE" not in line: certificate += line.rstrip() self.certificate = certificate diff --git a/cloudinit/sources/helpers/vmware/imc/guestcust_util.py b/cloudinit/sources/helpers/vmware/imc/guestcust_util.py index b7fa5e4a85e..4a78cbc17d3 100644 --- a/cloudinit/sources/helpers/vmware/imc/guestcust_util.py +++ b/cloudinit/sources/helpers/vmware/imc/guestcust_util.py @@ -13,7 +13,7 @@ import yaml -from cloudinit import subp, util +from cloudinit import log, subp, util from .config import Config from .config_custom_script import PostCustomScript, PreCustomScript @@ -87,7 +87,9 @@ def get_nics_to_enable(nicsfilepath): if not os.path.exists(nicsfilepath): return None - with open(nicsfilepath, "r") as fp: + with log.log_time(f"Reading {nicsfilepath}"), open( + nicsfilepath, "r" + ) as fp: nics = fp.read(NICS_SIZE) return nics diff --git a/cloudinit/ssh_util.py b/cloudinit/ssh_util.py index f7661929e49..4ecbd0a587f 100644 --- a/cloudinit/ssh_util.py +++ b/cloudinit/ssh_util.py @@ -546,10 +546,9 @@ def parse_ssh_config_map(fname): def _includes_dconf(fname: str) -> bool: if not os.path.isfile(fname): return False - with open(fname, "r") as f: - for line in f: - if line.startswith(f"Include {fname}.d/*.conf"): - return True + for line in util.load_text_file(fname).split("\n"): + if line.startswith(f"Include {fname}.d/*.conf"): + return True return False diff --git a/cloudinit/subp.py b/cloudinit/subp.py index 44307343937..199970ac52e 100644 --- a/cloudinit/subp.py +++ b/cloudinit/subp.py @@ -5,11 +5,12 @@ import logging import os import subprocess -import time from errno import ENOEXEC from io import TextIOWrapper from typing import List, Optional, Union +from cloudinit import log + LOG = logging.getLogger(__name__) SubpResult = collections.namedtuple("SubpResult", ["stdout", "stderr"]) @@ -256,24 +257,19 @@ def subp( x if isinstance(x, bytes) else x.encode("utf-8") for x in args ] try: - before = time.monotonic() - sp = subprocess.Popen( - bytes_args, - stdout=stdout, - stderr=stderr, - stdin=stdin, - env=env, - shell=shell, - cwd=cwd, - ) - out, err = sp.communicate(data, timeout=timeout) - total = time.monotonic() - before - if total > 0.1: - LOG.debug( - "%s took %.3ss to run", - logstring if logstring else args, - total, + with log.log_time( + "Running {}".format(logstring if logstring else args) + ): + sp = subprocess.Popen( + bytes_args, + stdout=stdout, + stderr=stderr, + stdin=stdin, + env=env, + shell=shell, + cwd=cwd, ) + out, err = sp.communicate(data, timeout=timeout) except OSError as e: raise ProcessExecutionError( cmd=args, diff --git a/cloudinit/templater.py b/cloudinit/templater.py index 8d83345fbac..4b70a78a924 100644 --- a/cloudinit/templater.py +++ b/cloudinit/templater.py @@ -20,6 +20,7 @@ from jinja2 import TemplateSyntaxError +from cloudinit import log from cloudinit import type_utils as tu from cloudinit import util from cloudinit.atomic_helper import write_file @@ -138,7 +139,8 @@ def replacer(match): ) return str(selected_params[key]) - return BASIC_MATCHER.sub(replacer, content) + with log.log_time("Rendering basic"): + return BASIC_MATCHER.sub(replacer, content) def detect_template(text): @@ -146,15 +148,16 @@ def jinja_render(content, params): # keep_trailing_newline is in jinja2 2.7+, not 2.6 add = "\n" if content.endswith("\n") else "" try: - return ( - JTemplate( - content, - undefined=UndefinedJinjaVariable, - trim_blocks=True, - extensions=["jinja2.ext.do"], - ).render(**params) - + add - ) + with log.log_time("Rendering jinja2"): + return ( + JTemplate( + content, + undefined=UndefinedJinjaVariable, + trim_blocks=True, + extensions=["jinja2.ext.do"], + ).render(**params) + + add + ) except TemplateSyntaxError as template_syntax_error: template_syntax_error.lineno += 1 raise JinjaSyntaxParsingException( @@ -212,8 +215,7 @@ def render_string(content, params): def render_template(variant, template, output, is_yaml, prefix=None): - with open(template, "r") as fh: - contents = fh.read() + contents = util.load_text_file(template) tpl_params = {"variant": variant, "prefix": prefix} contents = (render_string(contents, tpl_params)).rstrip() + "\n" if is_yaml: diff --git a/cloudinit/url_helper.py b/cloudinit/url_helper.py index f404d1130bd..a674fe8a795 100644 --- a/cloudinit/url_helper.py +++ b/cloudinit/url_helper.py @@ -28,7 +28,7 @@ import requests from requests import exceptions -from cloudinit import util, version +from cloudinit import log, util, version LOG = logging.getLogger(__name__) @@ -894,7 +894,9 @@ def __init__( def read_skew_file(self): if self.skew_data_file and os.path.isfile(self.skew_data_file): - with open(self.skew_data_file, mode="r") as fp: + with log.log_time(f"Reading {self.skew_data_file}"), open( + self.skew_data_file, mode="r" + ) as fp: return json.load(fp) return None @@ -906,7 +908,9 @@ def update_skew_file(self, host, value): if cur is None: cur = {} cur[host] = value - with open(self.skew_data_file, mode="w") as fp: + with log.log_time(f"Writing {self.skew_data_file}"), open( + self.skew_data_file, mode="w" + ) as fp: fp.write(json.dumps(cur)) def exception_cb(self, msg, exception): diff --git a/cloudinit/util.py b/cloudinit/util.py index 3846e01e302..eccd54f2db5 100644 --- a/cloudinit/util.py +++ b/cloudinit/util.py @@ -62,6 +62,7 @@ from cloudinit import ( features, importer, + log, mergers, net, settings, @@ -154,12 +155,13 @@ def maybe_b64decode(data: bytes) -> bytes: @param data: data as bytes. TypeError is raised if not bytes. """ - if not isinstance(data, bytes): - raise TypeError("data is '%s', expected bytes" % type(data)) - try: - return b64decode(data, validate=True) - except binascii.Error: - return data + with log.log_time("Base64 decoding"): + if not isinstance(data, bytes): + raise TypeError("data is '%s', expected bytes" % type(data)) + try: + return b64decode(data, validate=True) + except binascii.Error: + return data def fully_decoded_payload(part): @@ -1558,16 +1560,18 @@ def load_binary_file( read_cb: Optional[Callable[[int], None]] = None, quiet: bool = False, ) -> bytes: - LOG.debug("Reading from %s (quiet=%s)", fname, quiet) - with io.BytesIO() as ofh: - try: - with open(fname, "rb") as ifh: - pipe_in_out(ifh, ofh, chunk_cb=read_cb) - except FileNotFoundError: - if not quiet: - raise - contents = ofh.getvalue() - LOG.debug("Read %s bytes from %s", len(contents), fname) + timer = log.log_time("", skip_log=True) + with timer: + LOG.debug("Reading from %s (quiet=%s)", fname, quiet) + with io.BytesIO() as ofh: + try: + with open(fname, "rb") as ifh: + pipe_in_out(ifh, ofh, chunk_cb=read_cb) + except FileNotFoundError: + if not quiet: + raise + contents = ofh.getvalue() + LOG.debug("Reading %s bytes from %s%s", len(contents), fname, timer.output) return contents @@ -1849,14 +1853,15 @@ def ensure_dirs(dirlist, mode=0o755): def load_json(text, root_types=(dict,)): - decoded = json.loads(decode_binary(text)) - if not isinstance(decoded, tuple(root_types)): - expected_types = ", ".join([str(t) for t in root_types]) - raise TypeError( - "(%s) root types expected, got %s instead" - % (expected_types, type(decoded)) - ) - return decoded + with log.log_time("Loading json"): + decoded = json.loads(decode_binary(text)) + if not isinstance(decoded, tuple(root_types)): + expected_types = ", ".join([str(t) for t in root_types]) + raise TypeError( + "(%s) root types expected, got %s instead" + % (expected_types, type(decoded)) + ) + return decoded def get_non_exist_parent_dir(path): @@ -2242,9 +2247,9 @@ def write_file( content, mode=0o644, omode="wb", - preserve_mode=False, + preserve_mode: bool = False, *, - ensure_dir_exists=True, + ensure_dir_exists: bool = True, user=None, group=None, ): @@ -2265,37 +2270,38 @@ def write_file( @param group: The group to set on the file. """ - if preserve_mode: - try: - mode = get_permissions(filename) - except OSError: - pass + with log.log_time(f"Writing file {filename}"): + if preserve_mode: + try: + mode = get_permissions(filename) + except OSError: + pass - if ensure_dir_exists: - ensure_dir(os.path.dirname(filename), user=user, group=group) - if "b" in omode.lower(): - content = encode_text(content) - write_type = "bytes" - else: - content = decode_binary(content) - write_type = "characters" - try: - mode_r = "%o" % mode - except TypeError: - mode_r = "%r" % mode - LOG.debug( - "Writing to %s - %s: [%s] %s %s", - filename, - omode, - mode_r, - len(content), - write_type, - ) - with SeLinuxGuard(path=filename): - with open(filename, omode) as fh: - fh.write(content) - fh.flush() - chmod(filename, mode) + if ensure_dir_exists: + ensure_dir(os.path.dirname(filename), user=user, group=group) + if "b" in omode.lower(): + content = encode_text(content) + write_type = "bytes" + else: + content = decode_binary(content) + write_type = "characters" + try: + mode_r = "%o" % mode + except TypeError: + mode_r = "%r" % mode + LOG.debug( + "Writing to %s - %s: [%s] %s %s", + filename, + omode, + mode_r, + len(content), + write_type, + ) + with SeLinuxGuard(path=filename): + with open(filename, omode) as fh: + fh.write(content) + fh.flush() + chmod(filename, mode) def delete_dir_contents(dirname): diff --git a/tests/unittests/config/test_schema.py b/tests/unittests/config/test_schema.py index 590e0899d54..df5692fa4f7 100644 --- a/tests/unittests/config/test_schema.py +++ b/tests/unittests/config/test_schema.py @@ -20,7 +20,7 @@ import pytest import yaml -from cloudinit import features +from cloudinit import features, log from cloudinit.config.schema import ( VERSIONED_USERDATA_SCHEMA_FILE, MetaSchema, @@ -815,7 +815,9 @@ def test_validateconfig_strict_metaschema_do_not_raise_exception( def test_validateconfig_logs_deprecations( self, schema, config, expected_msg, log_deprecations, caplog ): - with mock.patch.object(features, "DEPRECATION_INFO_BOUNDARY", "devel"): + with mock.patch.object( + features, "DEPRECATION_INFO_BOUNDARY", "devel" + ), mock.patch.object(log, "log_time"): validate_cloudconfig_schema( config, schema=schema,