From 604c65b10593621665e26de8c7ddfb27db0f1945 Mon Sep 17 00:00:00 2001 From: Brett Holman Date: Tue, 27 Aug 2024 16:45:38 -0600 Subject: [PATCH] feat: add log package and performance module The logic in Timed() has defaults which are designed to avoid low-value log messages. A log is only emitted when the threshold is exceeded. Additionally, the log_mode parameter allows the caller to prevent Timed() logs, so that the caller may coalesce the message into another log. - Make timer helper into a context manager. - Add new decorator for timing functions. - Simplify timer helper function, eliminate obsolete logic. - Eliminate redundant logs and timer calls. --- cloudinit/cmd/clean.py | 8 +- cloudinit/cmd/cloud_id.py | 6 +- cloudinit/cmd/devel/hotplug_hook.py | 5 +- cloudinit/cmd/devel/logs.py | 8 +- cloudinit/cmd/devel/net_convert.py | 7 +- cloudinit/cmd/main.py | 38 +++-- cloudinit/config/cc_disk_setup.py | 24 +--- cloudinit/config/cc_final_message.py | 3 +- cloudinit/config/cc_growpart.py | 8 +- cloudinit/config/cc_keys_to_console.py | 5 +- cloudinit/config/cc_mounts.py | 10 +- .../cc_package_update_upgrade_install.py | 2 +- cloudinit/config/cc_resizefs.py | 15 +- cloudinit/config/cc_rsyslog.py | 7 +- cloudinit/config/cc_set_passwords.py | 3 +- .../config/cc_ssh_authkey_fingerprints.py | 5 +- cloudinit/config/cc_ubuntu_pro.py | 20 ++- cloudinit/config/schema.py | 2 +- cloudinit/distros/networking.py | 10 +- cloudinit/distros/package_management/apt.py | 9 +- cloudinit/lifecycle.py | 5 +- cloudinit/log/__init__.py | 1 + cloudinit/log/log_util.py | 76 ++++++++++ cloudinit/{log.py => log/loggers.py} | 0 cloudinit/net/__init__.py | 3 +- cloudinit/performance.py | 107 ++++++++++++++ cloudinit/signal_handler.py | 4 +- cloudinit/sources/DataSourceAzure.py | 6 +- cloudinit/sources/DataSourceCloudCIX.py | 6 +- cloudinit/sources/DataSourceEc2.py | 15 +- cloudinit/sources/DataSourceExoscale.py | 12 +- cloudinit/sources/DataSourceGCE.py | 21 +-- cloudinit/sources/DataSourceLXD.py | 6 +- cloudinit/sources/DataSourceOpenStack.py | 21 +-- cloudinit/sources/DataSourceScaleway.py | 36 ++--- cloudinit/sources/DataSourceUpCloud.py | 12 +- cloudinit/sources/DataSourceVMware.py | 5 +- cloudinit/sources/__init__.py | 11 +- .../helpers/vmware/imc/guestcust_util.py | 10 +- cloudinit/util.py | 132 +----------------- tests/unittests/cmd/devel/test_net_convert.py | 2 +- tests/unittests/cmd/test_main.py | 2 +- .../config/test_cc_keys_to_console.py | 2 +- .../unittests/config/test_cc_set_passwords.py | 4 +- tests/unittests/config/test_cc_ubuntu_pro.py | 11 +- .../config/test_cc_zypper_add_repo.py | 4 +- tests/unittests/conftest.py | 9 +- tests/unittests/sources/test_ec2.py | 1 - tests/unittests/sources/test_gce.py | 2 +- tests/unittests/test_cli.py | 4 +- tests/unittests/test_log.py | 13 +- tests/unittests/test_util.py | 45 +++--- 52 files changed, 372 insertions(+), 411 deletions(-) create mode 100644 cloudinit/log/__init__.py create mode 100644 cloudinit/log/log_util.py rename cloudinit/{log.py => log/loggers.py} (100%) create mode 100644 cloudinit/performance.py diff --git a/cloudinit/cmd/clean.py b/cloudinit/cmd/clean.py index d852ab711cc..1d61c11d2b8 100755 --- a/cloudinit/cmd/clean.py +++ b/cloudinit/cmd/clean.py @@ -13,13 +13,13 @@ from cloudinit import settings from cloudinit.distros import uses_systemd +from cloudinit.log import log_util from cloudinit.net.netplan import CLOUDINIT_NETPLAN_FILE from cloudinit.stages import Init from cloudinit.subp import ProcessExecutionError, runparts, subp from cloudinit.util import ( del_dir, del_file, - error, get_config_logfiles, is_link, write_file, @@ -144,12 +144,12 @@ def remove_artifacts(init, remove_logs, remove_seed=False, remove_config=None): else: del_file(path) except OSError as e: - error("Could not remove {0}: {1}".format(path, str(e))) + log_util.error("Could not remove {0}: {1}".format(path, str(e))) return 1 try: runparts(settings.CLEAN_RUNPARTS_DIR) except Exception as e: - error( + log_util.error( f"Failure during run-parts of {settings.CLEAN_RUNPARTS_DIR}: {e}" ) return 1 @@ -176,7 +176,7 @@ def handle_clean_args(name, args): try: subp(cmd, capture=False) except ProcessExecutionError as e: - error( + log_util.error( 'Could not reboot this system using "{0}": {1}'.format( cmd, str(e) ) diff --git a/cloudinit/cmd/cloud_id.py b/cloudinit/cmd/cloud_id.py index 4a856fe28b5..650e53cdc00 100644 --- a/cloudinit/cmd/cloud_id.py +++ b/cloudinit/cmd/cloud_id.py @@ -10,8 +10,8 @@ from cloudinit.cmd.devel import read_cfg_paths from cloudinit.cmd.status import RunningStatus, get_status_details +from cloudinit.log import log_util from cloudinit.sources import METADATA_UNKNOWN, canonical_cloud_id -from cloudinit.util import error NAME = "cloud-id" @@ -77,12 +77,12 @@ def handle_args(name, args): with open(args.instance_data) as file: instance_data = json.load(file) except IOError: - return error( + return log_util.error( "File not found '%s'. Provide a path to instance data json file" " using --instance-data" % args.instance_data ) except ValueError as e: - return error( + return log_util.error( "File '%s' is not valid json. %s" % (args.instance_data, e) ) v1 = instance_data.get("v1", {}) diff --git a/cloudinit/cmd/devel/hotplug_hook.py b/cloudinit/cmd/devel/hotplug_hook.py index 6e909caaa55..8e839cb1617 100755 --- a/cloudinit/cmd/devel/hotplug_hook.py +++ b/cloudinit/cmd/devel/hotplug_hook.py @@ -10,9 +10,10 @@ import sys import time -from cloudinit import log, reporting, stages, util +from cloudinit import reporting, stages, util from cloudinit.config.cc_install_hotplug import install_hotplug from cloudinit.event import EventScope, EventType +from cloudinit.log import loggers from cloudinit.net import read_sys_net_safe from cloudinit.net.network_state import parse_net_config_data from cloudinit.reporting import events @@ -288,7 +289,7 @@ def handle_args(name, args): hotplug_init = Init(ds_deps=[], reporter=hotplug_reporter) hotplug_init.read_cfg() - log.setup_logging(hotplug_init.cfg) + loggers.setup_logging(hotplug_init.cfg) if "reporting" in hotplug_init.cfg: reporting.update_configuration(hotplug_init.cfg.get("reporting")) # Logging isn't going to be setup until now diff --git a/cloudinit/cmd/devel/logs.py b/cloudinit/cmd/devel/logs.py index f18bfbed6ab..17be2c1d54d 100755 --- a/cloudinit/cmd/devel/logs.py +++ b/cloudinit/cmd/devel/logs.py @@ -17,13 +17,13 @@ from datetime import datetime, timezone from typing import Any, Dict, Iterator, List, NamedTuple, Optional, cast -from cloudinit import log +from cloudinit.log import loggers from cloudinit.stages import Init from cloudinit.subp import ProcessExecutionError, subp from cloudinit.temp_utils import tempdir from cloudinit.util import copy, get_config_logfiles, write_file -LOG = cast(log.CustomLoggerType, logging.getLogger(__name__)) +LOG = cast(loggers.CustomLoggerType, logging.getLogger(__name__)) class ApportFile(NamedTuple): @@ -378,13 +378,13 @@ def _setup_logger(verbosity: int) -> None: The verbosity controls which level gets printed to stderr. By default, DEBUG and TRACE are hidden. """ - log.reset_logging() + loggers.reset_logging() if verbosity == 0: level = logging.INFO elif verbosity == 1: level = logging.DEBUG else: - level = log.TRACE + level = loggers.TRACE LOG.setLevel(level) handler = logging.StreamHandler() handler.setFormatter(logging.Formatter("%(message)s")) diff --git a/cloudinit/cmd/devel/net_convert.py b/cloudinit/cmd/devel/net_convert.py index 4b7c27ae49e..b3c2fa7c513 100755 --- a/cloudinit/cmd/devel/net_convert.py +++ b/cloudinit/cmd/devel/net_convert.py @@ -10,7 +10,8 @@ import yaml -from cloudinit import distros, log, safeyaml +from cloudinit import distros, safeyaml +from cloudinit.log import loggers from cloudinit.net import ( eni, netplan, @@ -100,9 +101,9 @@ def handle_args(name, args): os.makedirs(args.directory) if args.debug: - log.setup_basic_logging(level=logging.DEBUG) + loggers.setup_basic_logging(level=logging.DEBUG) else: - log.setup_basic_logging(level=logging.WARN) + loggers.setup_basic_logging(level=logging.WARN) if args.mac: known_macs = {} for item in args.mac: diff --git a/cloudinit/cmd/main.py b/cloudinit/cmd/main.py index 88bab1d2fdd..89e46d02f33 100644 --- a/cloudinit/cmd/main.py +++ b/cloudinit/cmd/main.py @@ -28,16 +28,17 @@ from cloudinit import stages from cloudinit import url_helper from cloudinit import util +from cloudinit import performance from cloudinit import version from cloudinit import warnings from cloudinit import reporting from cloudinit import atomic_helper from cloudinit import lifecycle +from cloudinit.log import log_util, loggers from cloudinit.cmd.devel import read_cfg_paths from cloudinit.config import cc_set_hostname from cloudinit.config.modules import Modules from cloudinit.config.schema import validate_cloudconfig_schema -from cloudinit import log from cloudinit.reporting import events from cloudinit.settings import ( PER_INSTANCE, @@ -115,7 +116,7 @@ def log_ppid(distro, bootstage_name): def welcome(action, msg=None): if not msg: msg = welcome_format(action) - util.multi_log("%s\n" % (msg), console=False, stderr=True, log=LOG) + log_util.multi_log("%s\n" % (msg), console=False, stderr=True, log=LOG) return msg @@ -383,9 +384,9 @@ def main_init(name, args): LOG.debug( "Logging being reset, this logger may no longer be active shortly" ) - log.reset_logging() + loggers.reset_logging() if not args.skip_log_setup: - log.setup_logging(init.cfg) + loggers.setup_logging(init.cfg) apply_reporting_cfg(init.cfg) # Any log usage prior to setup_logging above did not have local user log @@ -547,7 +548,7 @@ def main_init(name, args): (outfmt, errfmt) = util.fixup_output(mods.cfg, name) except Exception: util.logexc(LOG, "Failed to re-adjust output redirection!") - log.setup_logging(mods.cfg) + loggers.setup_logging(mods.cfg) # give the activated datasource a chance to adjust init.activate_datasource() @@ -653,9 +654,9 @@ def main_modules(action_name, args): LOG.debug( "Logging being reset, this logger may no longer be active shortly" ) - log.reset_logging() + loggers.reset_logging() if not args.skip_log_setup: - log.setup_logging(mods.cfg) + loggers.setup_logging(mods.cfg) apply_reporting_cfg(init.cfg) # now that logging is setup and stdout redirected, send welcome @@ -723,8 +724,8 @@ def main_single(name, args): LOG.debug( "Logging being reset, this logger may no longer be active shortly" ) - log.reset_logging() - log.setup_logging(mods.cfg) + loggers.reset_logging() + loggers.setup_logging(mods.cfg) apply_reporting_cfg(init.cfg) # now that logging is setup and stdout redirected, send welcome @@ -817,7 +818,9 @@ def status_wrapper(name, args): v1[mode]["start"] = float(util.uptime()) handler = next( - filter(lambda h: isinstance(h, log.LogExporter), root_logger.handlers) + filter( + lambda h: isinstance(h, loggers.LogExporter), root_logger.handlers + ) ) preexisting_recoverable_errors = handler.export_logs() @@ -932,7 +935,7 @@ def main_features(name, args): def main(sysv_args=None): - log.configure_root_logger() + loggers.configure_root_logger() if not sysv_args: sysv_args = sys.argv parser = argparse.ArgumentParser(prog=sysv_args.pop(0)) @@ -1254,11 +1257,11 @@ def sub_main(args): # - if --debug is passed, logging.DEBUG # - if --debug is not passed, logging.WARNING if name not in ("init", "modules"): - log.setup_basic_logging( + loggers.setup_basic_logging( logging.DEBUG if args.debug else logging.WARNING ) elif args.debug: - log.setup_basic_logging() + loggers.setup_basic_logging() # Setup signal handlers before running signal_handler.attach_handlers() @@ -1300,13 +1303,8 @@ def sub_main(args): ) with args.reporter: - retval = util.log_time( - logfunc=LOG.debug, - msg="cloud-init mode '%s'" % name, - get_uptime=True, - func=functor, - args=(name, args), - ) + with performance.Timed(f"cloud-init stage: '{rname}'"): + retval = functor(name, args) reporting.flush_events() # handle return code for main_modules, as it is not wrapped by diff --git a/cloudinit/config/cc_disk_setup.py b/cloudinit/config/cc_disk_setup.py index ba3106a4188..cff5ee6654f 100644 --- a/cloudinit/config/cc_disk_setup.py +++ b/cloudinit/config/cc_disk_setup.py @@ -12,7 +12,7 @@ import shlex from pathlib import Path -from cloudinit import subp, util +from cloudinit import performance, subp, util from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema @@ -51,13 +51,10 @@ def alias_to_device(cand): continue try: - LOG.debug("Creating new partition table/disk") - util.log_time( - logfunc=LOG.debug, - msg="Creating partition on %s" % disk, - func=mkpart, - args=(disk, definition), - ) + with performance.Timed( + f"Creating partition on {disk}", + ): + mkpart(disk, definition) except Exception as e: util.logexc(LOG, "Failed partitioning operation\n%s" % e) @@ -71,14 +68,8 @@ def alias_to_device(cand): continue try: - LOG.debug("Creating new filesystem.") - device = definition.get("device") - util.log_time( - logfunc=LOG.debug, - msg="Creating fs for %s" % device, - func=mkfs, - args=(definition,), - ) + with performance.Timed("Creating new filesystem"): + mkfs(definition) except Exception as e: util.logexc(LOG, "Failed during filesystem operation\n%s" % e) @@ -983,7 +974,6 @@ def mkfs(fs_cfg): fs_cmd.append(device) LOG.debug("Creating file system %s on %s", label, device) - LOG.debug(" Using cmd: %s", str(fs_cmd)) try: subp.subp(fs_cmd, shell=shell) except Exception as e: diff --git a/cloudinit/config/cc_final_message.py b/cloudinit/config/cc_final_message.py index dc263ee2d3d..3615bf44a54 100644 --- a/cloudinit/config/cc_final_message.py +++ b/cloudinit/config/cc_final_message.py @@ -14,6 +14,7 @@ from cloudinit.config import Config from cloudinit.config.schema import MetaSchema from cloudinit.distros import ALL_DISTROS +from cloudinit.log import log_util from cloudinit.settings import PER_ALWAYS frequency = PER_ALWAYS @@ -57,7 +58,7 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: "datasource": str(cloud.datasource), } subs.update(dict([(k.upper(), v) for k, v in subs.items()])) - util.multi_log( + log_util.multi_log( "%s\n" % (templater.render_string(msg_in, subs)), console=False, stderr=True, diff --git a/cloudinit/config/cc_growpart.py b/cloudinit/config/cc_growpart.py index 8f2978b0579..b646be1cdec 100644 --- a/cloudinit/config/cc_growpart.py +++ b/cloudinit/config/cc_growpart.py @@ -567,12 +567,8 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: raise e return - resized = util.log_time( - logfunc=LOG.debug, - msg="resize_devices", - func=resize_devices, - args=(resizer, devices, cloud.distro), - ) + with performance.Timed("Resizing devices"): + resized = resize_devices(resizer, devices, cloud.distro) for entry, action, msg in resized: if action == RESIZE.CHANGED: LOG.info("'%s' resized: %s", entry, msg) diff --git a/cloudinit/config/cc_keys_to_console.py b/cloudinit/config/cc_keys_to_console.py index 3ca2c088261..de29a81a8c2 100644 --- a/cloudinit/config/cc_keys_to_console.py +++ b/cloudinit/config/cc_keys_to_console.py @@ -15,6 +15,7 @@ from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema +from cloudinit.log import log_util from cloudinit.settings import PER_INSTANCE # This is a tool that cloud init provides @@ -64,7 +65,9 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: try: cmd = [helper_path, ",".join(fp_blacklist), ",".join(key_blacklist)] (stdout, _stderr) = subp.subp(cmd) - util.multi_log("%s\n" % (stdout.strip()), stderr=False, console=True) + log_util.multi_log( + "%s\n" % (stdout.strip()), stderr=False, console=True + ) except Exception: LOG.warning("Writing keys to the system console failed!") raise diff --git a/cloudinit/config/cc_mounts.py b/cloudinit/config/cc_mounts.py index 20e23296a4f..54c99f43ec2 100644 --- a/cloudinit/config/cc_mounts.py +++ b/cloudinit/config/cc_mounts.py @@ -16,7 +16,7 @@ import re from typing import Dict, List, Optional, Tuple, cast -from cloudinit import subp, util +from cloudinit import performance, subp, util from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema @@ -296,12 +296,8 @@ def setup_swapfile(fname, size=None, maxsize=None): LOG.debug("Not creating swap: suggested size was 0") return - util.log_time( - LOG.debug, - msg="Setting up swap file", - func=create_swapfile, - args=[fname, mibsize], - ) + with performance.Timed("Setting up swap file"): + create_swapfile(fname, mibsize) return fname diff --git a/cloudinit/config/cc_package_update_upgrade_install.py b/cloudinit/config/cc_package_update_upgrade_install.py index 4edba27e7bb..61728b0ac5a 100644 --- a/cloudinit/config/cc_package_update_upgrade_install.py +++ b/cloudinit/config/cc_package_update_upgrade_install.py @@ -15,7 +15,7 @@ from cloudinit.config import Config from cloudinit.config.schema import MetaSchema from cloudinit.distros import ALL_DISTROS -from cloudinit.log import flush_loggers +from cloudinit.log.loggers import flush_loggers from cloudinit.settings import PER_INSTANCE REBOOT_FILES = ("/var/run/reboot-required", "/run/reboot-needed") diff --git a/cloudinit/config/cc_resizefs.py b/cloudinit/config/cc_resizefs.py index 70bd4e17f3b..8a983653af7 100644 --- a/cloudinit/config/cc_resizefs.py +++ b/cloudinit/config/cc_resizefs.py @@ -315,20 +315,11 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: # Fork to a child that will run # the resize command util.fork_cb( - util.log_time, - logfunc=LOG.debug, - msg="backgrounded Resizing", - func=do_resize, - args=(resize_cmd,), + do_resize, + resize_cmd, ) else: - util.log_time( - logfunc=LOG.debug, - msg="Resizing", - func=do_resize, - args=(resize_cmd,), - ) - + do_resize(resize_cmd) action = "Resized" if resize_root == NOBLOCK: action = "Resizing (via forking)" diff --git a/cloudinit/config/cc_rsyslog.py b/cloudinit/config/cc_rsyslog.py index 88ec1c4f3a1..fa3b7164fca 100644 --- a/cloudinit/config/cc_rsyslog.py +++ b/cloudinit/config/cc_rsyslog.py @@ -17,11 +17,12 @@ import re from textwrap import dedent -from cloudinit import lifecycle, log, subp, util +from cloudinit import lifecycle, subp, util from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema from cloudinit.distros import ALL_DISTROS, Distro +from cloudinit.log import loggers from cloudinit.settings import PER_INSTANCE meta: MetaSchema = { @@ -431,8 +432,8 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: if restarted: # This only needs to run if we *actually* restarted # syslog above. - log.reset_logging() - log.setup_logging(cloud.cfg) + loggers.reset_logging() + loggers.setup_logging(cloud.cfg) # This should now use rsyslog if # the logging was setup to use it... LOG.debug("%s configured %s files", name, changes) diff --git a/cloudinit/config/cc_set_passwords.py b/cloudinit/config/cc_set_passwords.py index 224ae6b85fe..6fa5852de6e 100644 --- a/cloudinit/config/cc_set_passwords.py +++ b/cloudinit/config/cc_set_passwords.py @@ -17,6 +17,7 @@ from cloudinit.config import Config from cloudinit.config.schema import MetaSchema from cloudinit.distros import ALL_DISTROS, Distro, ug_util +from cloudinit.log import log_util from cloudinit.settings import PER_INSTANCE from cloudinit.ssh_util import update_ssh_config @@ -220,7 +221,7 @@ def handle(name: str, cfg: Config, cloud: Cloud, args: list) -> None: "Set the following 'random' passwords\n", "\n".join(randlist), ) - util.multi_log( + log_util.multi_log( "%s\n%s\n" % blurb, stderr=False, fallback_to_stdout=False ) diff --git a/cloudinit/config/cc_ssh_authkey_fingerprints.py b/cloudinit/config/cc_ssh_authkey_fingerprints.py index 8b02789b739..083559ec026 100644 --- a/cloudinit/config/cc_ssh_authkey_fingerprints.py +++ b/cloudinit/config/cc_ssh_authkey_fingerprints.py @@ -14,6 +14,7 @@ from cloudinit.config import Config from cloudinit.config.schema import MetaSchema from cloudinit.distros import ALL_DISTROS, ug_util +from cloudinit.log import log_util from cloudinit.settings import PER_INSTANCE from cloudinit.simpletable import SimpleTable @@ -67,7 +68,7 @@ def _pprint_key_entries( "%sno authorized SSH keys fingerprints found for user %s.\n" % (prefix, user) ) - util.multi_log(message, console=True, stderr=False) + log_util.multi_log(message, console=True, stderr=False) return tbl_fields = [ "Keytype", @@ -97,7 +98,7 @@ def _pprint_key_entries( ] lines.extend(authtbl_lines) for line in lines: - util.multi_log( + log_util.multi_log( text="%s%s\n" % (prefix, line), stderr=False, console=True ) diff --git a/cloudinit/config/cc_ubuntu_pro.py b/cloudinit/config/cc_ubuntu_pro.py index a82c1b8d538..0fbc864c8d8 100644 --- a/cloudinit/config/cc_ubuntu_pro.py +++ b/cloudinit/config/cc_ubuntu_pro.py @@ -8,7 +8,7 @@ from typing import Any, List from urllib.parse import urlparse -from cloudinit import subp, util +from cloudinit import performance, subp, util from cloudinit.cloud import Cloud from cloudinit.config import Config from cloudinit.config.schema import MetaSchema @@ -282,11 +282,11 @@ def _should_auto_attach(pro_section: dict) -> bool: # pylint: enable=import-error try: - result = util.log_time( - logfunc=LOG.debug, - msg="Checking if the instance can be attached to Ubuntu Pro", - func=should_auto_attach, - ) + with performance.Timed( + "Checking if the instance can be attached to Ubuntu Pro", + log_mode="always", + ): + result = should_auto_attach() except UserFacingError as ex: LOG.debug("Error during `should_auto_attach`: %s", ex) LOG.warning(ERROR_MSG_SHOULD_AUTO_ATTACH) @@ -327,12 +327,8 @@ def _auto_attach(pro_section: dict): enable_beta=enable_beta, ) try: - util.log_time( - logfunc=LOG.debug, - msg="Attaching to Ubuntu Pro", - func=full_auto_attach, - kwargs={"options": options}, - ) + with performance.Timed("Attaching to Ubuntu Pro", log_mode="always"): + full_auto_attach(options=options) except AlreadyAttachedError: if enable_beta is not None or enable is not None: # Only warn if the user defined some service to enable/disable. diff --git a/cloudinit/config/schema.py b/cloudinit/config/schema.py index de9547b987c..e9bc3d4fbfb 100644 --- a/cloudinit/config/schema.py +++ b/cloudinit/config/schema.py @@ -35,10 +35,10 @@ from cloudinit.cmd.devel import read_cfg_paths from cloudinit.handlers import INCLUSION_TYPES_MAP, type_from_starts_with from cloudinit.helpers import Paths +from cloudinit.log.log_util import error from cloudinit.sources import DataSourceNotFoundException from cloudinit.temp_utils import mkdtemp from cloudinit.util import ( - error, get_modules_from_dir, load_text_file, load_yaml, diff --git a/cloudinit/distros/networking.py b/cloudinit/distros/networking.py index 67f10f4fbcf..c3973c9a6bf 100644 --- a/cloudinit/distros/networking.py +++ b/cloudinit/distros/networking.py @@ -2,7 +2,7 @@ import logging import os -from cloudinit import net, subp, util +from cloudinit import net, performance, subp, util from cloudinit.distros.parsers import ifconfig from cloudinit.net.netops.iproute2 import Iproute2 @@ -154,12 +154,8 @@ def wait_for_physdevs( # trigger a settle, unless this interface exists devname = expected_ifaces[mac] msg = "Waiting for settle or {} exists".format(devname) - util.log_time( - LOG.debug, - msg, - func=self.settle, - kwargs={"exists": devname}, - ) + with performance.Timed(msg, log_mode="always"): + self.settle(exists=devname) # update present_macs after settles present_macs = self.get_interfaces_by_mac().keys() diff --git a/cloudinit/distros/package_management/apt.py b/cloudinit/distros/package_management/apt.py index e8b8a459024..11742797646 100644 --- a/cloudinit/distros/package_management/apt.py +++ b/cloudinit/distros/package_management/apt.py @@ -214,14 +214,7 @@ def _wait_for_apt_command( continue LOG.debug("APT lock available") try: - # Allow the output of this to flow outwards (not be captured) - log_msg = f'apt-{short_cmd} [{" ".join(subp_kwargs["args"])}]' - return util.log_time( - logfunc=LOG.debug, - msg=log_msg, - func=subp.subp, - kwargs=subp_kwargs, - ) + return subp.subp(**subp_kwargs) except subp.ProcessExecutionError: # Even though we have already waited for the apt lock to be # available, it is possible that the lock was acquired by diff --git a/cloudinit/lifecycle.py b/cloudinit/lifecycle.py index 87e0f8f42fd..2102d03da32 100644 --- a/cloudinit/lifecycle.py +++ b/cloudinit/lifecycle.py @@ -4,7 +4,8 @@ import logging from typing import NamedTuple, Optional -from cloudinit import features, log +from cloudinit import features +from cloudinit.log import loggers LOG = logging.getLogger(__name__) @@ -195,7 +196,7 @@ def deprecate( ): level = logging.INFO elif hasattr(LOG, "deprecated"): - level = log.DEPRECATED + level = loggers.DEPRECATED else: level = logging.WARN log_cache = getattr(deprecate, "log") diff --git a/cloudinit/log/__init__.py b/cloudinit/log/__init__.py new file mode 100644 index 00000000000..da6365a5941 --- /dev/null +++ b/cloudinit/log/__init__.py @@ -0,0 +1 @@ +# This file is part of cloud-init. See LICENSE file for license information. diff --git a/cloudinit/log/log_util.py b/cloudinit/log/log_util.py new file mode 100644 index 00000000000..ec8438ade6c --- /dev/null +++ b/cloudinit/log/log_util.py @@ -0,0 +1,76 @@ +import logging +import os +import sys + +from cloudinit.performance import Timed + + +def logexc( + log, msg, *args, log_level: int = logging.WARNING, exc_info=True +) -> None: + log.log(log_level, msg, *args) + log.debug(msg, exc_info=exc_info, *args) + + +def write_to_console(conpath, text): + with open(conpath, "w") as wfh: + wfh.write(text) + wfh.flush() + + +def multi_log( + text, + console=True, + stderr=True, + log=None, + log_level=logging.DEBUG, + fallback_to_stdout=True, +): + if stderr: + sys.stderr.write(text) + if console: + conpath = "/dev/console" + writing_to_console_worked = False + if os.path.exists(conpath): + try: + write_to_console(conpath, text) + writing_to_console_worked = True + except OSError: + console_error = "Failed to write to /dev/console" + sys.stdout.write(f"{console_error}\n") + if log: + log.log(logging.WARNING, console_error) + + if fallback_to_stdout and not writing_to_console_worked: + # A container may lack /dev/console (arguably a container bug). + # Additionally, /dev/console may not be writable to on a VM (again + # likely a VM bug or virtualization bug). + # + # If either of these is the case, then write output to stdout. + # This will result in duplicate stderr and stdout messages if + # stderr was True. + # + # even though systemd might have set up output to go to + # /dev/console, the user may have configured elsewhere via + # cloud-config 'output'. If there is /dev/console, messages will + # still get there. + sys.stdout.write(text) + if log: + if text[-1] == "\n": + log.log(log_level, text[:-1]) + else: + log.log(log_level, text) + + +def error(msg, rc=1, fmt="Error:\n{}", sys_exit=False): + r"""Print error to stderr and return or exit + + @param msg: message to print + @param rc: return code (default: 1) + @param fmt: format string for putting message in (default: 'Error:\n {}') + @param sys_exit: exit when called (default: false) + """ + print(fmt.format(msg), file=sys.stderr) + if sys_exit: + sys.exit(rc) + return rc diff --git a/cloudinit/log.py b/cloudinit/log/loggers.py similarity index 100% rename from cloudinit/log.py rename to cloudinit/log/loggers.py diff --git a/cloudinit/net/__init__.py b/cloudinit/net/__init__.py index 28ac814b6e9..592a91540ed 100644 --- a/cloudinit/net/__init__.py +++ b/cloudinit/net/__init__.py @@ -488,8 +488,7 @@ def find_candidate_nics_on_linux() -> List[str]: "Found unstable nic names: %s; calling udevadm settle", unstable, ) - msg = "Waiting for udev events to settle" - util.log_time(LOG.debug, msg, func=util.udevadm_settle) + util.udevadm_settle() # sort into interfaces with carrier, interfaces which could have carrier, # and ignore interfaces that are definitely disconnected diff --git a/cloudinit/performance.py b/cloudinit/performance.py new file mode 100644 index 00000000000..171f45c3c65 --- /dev/null +++ b/cloudinit/performance.py @@ -0,0 +1,107 @@ +import functools +import logging +import time + +LOG = logging.getLogger(__name__) + + +class Timed: + """ + A context manager which measures and optionally logs context run time. + + :param msg: A message that describes the thing that is being measured + :param threshold: Threshold, in seconds. When the context exceeds this + threshold, a log will be made. + :param log_mode: Control whether to log. Defaults to "threshold". Possible + values include: + "always" - Always log 'msg', even when 'threshold' is not reached. + "threshold" - Log when context time exceeds 'threshold'. + "skip" - Do not log. Context time and message are stored in the + 'output' and 'delta' attributes, respectively. Used to manually + coalesce with other logs at the call site. + + usage: + + this call: + ``` + with Timed("Configuring the network"): + run_configure() + ``` + + might produce this log: + ``` + Configuring the network took 0.100 seconds + ``` + """ + + def __init__( + self, + msg: str, + *, + threshold: float = 0.01, + log_mode: str = "threshold", + ): + self.msg = msg + self.threshold = threshold + self.log_mode = log_mode + self.output = "" + self.start = 0.0 + self.delta = 0.0 + + def __enter__(self): + self.start = time.monotonic() + return self + + def __exit__(self, exc_type, exc_val, exc_tb): + self.delta = time.monotonic() - self.start + suffix = f"took {self.delta:.3f} seconds" + if "always" == self.log_mode: + LOG.debug("%s %s", self.msg, suffix) + elif "skip" == self.log_mode: + return + elif "threshold" == self.log_mode: + if self.delta > self.threshold: + LOG.debug("%s %s", self.msg, suffix) + self.output = f"{self.msg} {suffix}" + else: + raise ValueError( + f"Invalid Timed log_mode value: '{self.log_mode}'." + ) + + +def timed(msg: str, *, threshold: float = 0.01, log_mode: str = "threshold"): + """ + A decorator which measures and optionally logs context run time. + + :param msg: A message that describes the thing that is being measured + :param threshold: Threshold, in seconds. When the context exceeds this + threshold, a log will be made. + :param log_mode: Control whether to log. Defaults to "threshold". Possible + values include: + "always" - Always log 'msg', even when 'threshold' is not reached. + "threshold" - Log when context time exceeds 'threshold'. + + usage: + + this call: + ``` + @timed("Configuring the network") + def run_configure(): + ... + ``` + + might produce this log: + ``` + Configuring the network took 0.100 seconds + ``` + """ + + def wrapper(func): + @functools.wraps(func) + def decorator(*args, **kwargs): + with Timed(msg, threshold=threshold, log_mode=log_mode): + return func(*args, **kwargs) + + return decorator + + return wrapper diff --git a/cloudinit/signal_handler.py b/cloudinit/signal_handler.py index 00eb4f4af05..c5e490bb6b0 100644 --- a/cloudinit/signal_handler.py +++ b/cloudinit/signal_handler.py @@ -11,8 +11,8 @@ import sys from io import StringIO -from cloudinit import util from cloudinit import version as vr +from cloudinit.log import log_util LOG = logging.getLogger(__name__) @@ -44,7 +44,7 @@ def _handle_exit(signum, frame): contents = StringIO() contents.write("%s\n" % (msg)) _pprint_frame(frame, 1, BACK_FRAME_TRACE_DEPTH, contents) - util.multi_log(contents.getvalue(), log=LOG, log_level=logging.ERROR) + log_util.multi_log(contents.getvalue(), log=LOG, log_level=logging.ERROR) sys.exit(rc) diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py index 77a5f46f100..149bb7545d4 100644 --- a/cloudinit/sources/DataSourceAzure.py +++ b/cloudinit/sources/DataSourceAzure.py @@ -909,11 +909,7 @@ def _get_data(self): LOG.warning("Failed to get system information: %s", e) try: - crawled_data = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self.crawl_metadata, - ) + crawled_data = self.crawl_metadata() except errors.ReportableError as error: self._report_failure(error) return False diff --git a/cloudinit/sources/DataSourceCloudCIX.py b/cloudinit/sources/DataSourceCloudCIX.py index 8f6ef4a1b6f..4e62648e603 100644 --- a/cloudinit/sources/DataSourceCloudCIX.py +++ b/cloudinit/sources/DataSourceCloudCIX.py @@ -32,11 +32,7 @@ def _get_data(self): Fetch the user data and the metadata """ try: - crawled_data = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self.crawl_metadata_service, - ) + crawled_data = self.crawl_metadata_service() except sources.InvalidMetaDataException as error: LOG.error( "Failed to read data from CloudCIX datasource: %s", error diff --git a/cloudinit/sources/DataSourceEc2.py b/cloudinit/sources/DataSourceEc2.py index bf3b84850ec..4289e65e209 100644 --- a/cloudinit/sources/DataSourceEc2.py +++ b/cloudinit/sources/DataSourceEc2.py @@ -159,22 +159,13 @@ def _get_data(self): self.distro.fallback_interface, ipv4=True, ipv6=True, - ) as netw: - state_msg = f" {netw.state_msg}" if netw.state_msg else "" - self._crawled_metadata = util.log_time( - logfunc=LOG.debug, - msg=f"Crawl of metadata service{state_msg}", - func=self.crawl_metadata, - ) + ): + self._crawled_metadata = self.crawl_metadata() except NoDHCPLeaseError: return False else: - self._crawled_metadata = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self.crawl_metadata, - ) + self._crawled_metadata = self.crawl_metadata() if not self._crawled_metadata: return False self.metadata = self._crawled_metadata.get("meta-data", None) diff --git a/cloudinit/sources/DataSourceExoscale.py b/cloudinit/sources/DataSourceExoscale.py index 82e4621dab8..38e00cacdfc 100644 --- a/cloudinit/sources/DataSourceExoscale.py +++ b/cloudinit/sources/DataSourceExoscale.py @@ -76,11 +76,7 @@ def crawl_metadata(self): @returns: Dictionary of crawled metadata content. """ - metadata_ready = util.log_time( - logfunc=LOG.info, - msg="waiting for the metadata service", - func=self.wait_for_metadata_service, - ) + metadata_ready = self.wait_for_metadata_service() if not metadata_ready: return {} @@ -100,11 +96,7 @@ def _get_data(self): Please refer to the datasource documentation for details on how the metadata server and password server are crawled. """ - data = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self.crawl_metadata, - ) + data = self.crawl_metadata() if not data: return False diff --git a/cloudinit/sources/DataSourceGCE.py b/cloudinit/sources/DataSourceGCE.py index f3bcd5315a2..949580d8bce 100644 --- a/cloudinit/sources/DataSourceGCE.py +++ b/cloudinit/sources/DataSourceGCE.py @@ -104,14 +104,9 @@ def _get_data(self): try: with network_context: try: - ret = util.log_time( - LOG.debug, - "Crawl of GCE metadata service", - read_md, - kwargs={ - "address": self.metadata_address, - "url_params": url_params, - }, + ret = read_md( + address=self.metadata_address, + url_params=url_params, ) except Exception as e: LOG.debug( @@ -131,15 +126,7 @@ def _get_data(self): "Did not find a fallback interface on %s.", self.cloud_name ) else: - ret = util.log_time( - LOG.debug, - "Crawl of GCE metadata service", - read_md, - kwargs={ - "address": self.metadata_address, - "url_params": url_params, - }, - ) + ret = read_md(address=self.metadata_address, url_params=url_params) if not ret["success"]: if ret["platform_reports_gce"]: diff --git a/cloudinit/sources/DataSourceLXD.py b/cloudinit/sources/DataSourceLXD.py index cb3f5ece009..b23eae97a19 100644 --- a/cloudinit/sources/DataSourceLXD.py +++ b/cloudinit/sources/DataSourceLXD.py @@ -200,11 +200,7 @@ def ds_detect() -> bool: def _get_data(self) -> bool: """Crawl LXD socket API instance data and return True on success""" - self._crawled_metadata = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=read_metadata, - ) + self._crawled_metadata = read_metadata() self.metadata = _raw_instance_data_to_dict( "meta-data", self._crawled_metadata.get("meta-data") ) diff --git a/cloudinit/sources/DataSourceOpenStack.py b/cloudinit/sources/DataSourceOpenStack.py index 2c8a2b7bbc8..019a0a122c5 100644 --- a/cloudinit/sources/DataSourceOpenStack.py +++ b/cloudinit/sources/DataSourceOpenStack.py @@ -161,11 +161,7 @@ def _get_data(self): with EphemeralDHCPv4( self.distro, self.distro.fallback_interface ): - results = util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self._crawl_metadata, - ) + results = self._crawl_metadata() except (NoDHCPLeaseError, sources.InvalidMetaDataException) as e: util.logexc(LOG, str(e)) return False @@ -226,16 +222,11 @@ def _crawl_metadata(self): url_params = self.get_url_params() try: - result = util.log_time( - LOG.debug, - "Crawl of openstack metadata service", - read_metadata_service, - args=[self.metadata_address], - kwargs={ - "ssl_details": self.ssl_details, - "retries": url_params.num_retries, - "timeout": url_params.timeout_seconds, - }, + result = read_metadata_service( + self.metadata_address, + ssl_details=self.ssl_details, + retries=url_params.num_retries, + timeout=url_params.timeout_seconds, ) except openstack.NonReadable as e: raise sources.InvalidMetaDataException(str(e)) diff --git a/cloudinit/sources/DataSourceScaleway.py b/cloudinit/sources/DataSourceScaleway.py index ae018fe4908..4952e314edd 100644 --- a/cloudinit/sources/DataSourceScaleway.py +++ b/cloudinit/sources/DataSourceScaleway.py @@ -19,7 +19,7 @@ from urllib3.connection import HTTPConnection from urllib3.poolmanager import PoolManager -from cloudinit import dmi, sources, url_helper, util +from cloudinit import dmi, performance, sources, url_helper, util from cloudinit.event import EventScope, EventType from cloudinit.net.dhcp import NoDHCPLeaseError from cloudinit.net.ephemeral import EphemeralDHCPv4, EphemeralIPv6Network @@ -293,18 +293,12 @@ def _get_data(self): self.distro, self.distro.fallback_interface, ) as ipv4: - util.log_time( - logfunc=LOG.debug, - msg="Set api-metadata URL depending on " - "IPv4 availability", - func=self._set_metadata_url, - args=(self.metadata_urls,), - ) - util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self._crawl_metadata, - ) + with performance.Timed( + "Setting api-metadata URL " + "depending on IPv4 availability" + ): + self._set_metadata_url(self.metadata_urls) + self._crawl_metadata() self.ephemeral_fixed_address = ipv4["fixed-address"] self.metadata["net_in_use"] = "ipv4" except ( @@ -324,18 +318,12 @@ def _get_data(self): self.distro, self.distro.fallback_interface, ): - util.log_time( - logfunc=LOG.debug, - msg="Set api-metadata URL depending on " + with performance.Timed( + "Setting api-metadata URL depending on " "IPv6 availability", - func=self._set_metadata_url, - args=(self.metadata_urls,), - ) - util.log_time( - logfunc=LOG.debug, - msg="Crawl of metadata service", - func=self._crawl_metadata, - ) + ): + self._set_metadata_url(self.metadata_urls) + self._crawl_metadata() self.metadata["net_in_use"] = "ipv6" except ConnectionError: return False diff --git a/cloudinit/sources/DataSourceUpCloud.py b/cloudinit/sources/DataSourceUpCloud.py index c69678378e7..463996c325e 100644 --- a/cloudinit/sources/DataSourceUpCloud.py +++ b/cloudinit/sources/DataSourceUpCloud.py @@ -74,11 +74,7 @@ def _get_data(self): nic = cloudnet.find_fallback_nic() LOG.debug("Discovering metadata via DHCP interface %s", nic) with EphemeralDHCPv4(self.distro, nic): - md = util.log_time( - logfunc=LOG.debug, - msg="Reading from metadata service", - func=self._read_metadata, - ) + md = self._read_metadata() except (NoDHCPLeaseError, sources.InvalidMetaDataException) as e: util.logexc(LOG, str(e)) return False @@ -87,11 +83,7 @@ def _get_data(self): LOG.debug( "Discovering metadata without DHCP-configured networking" ) - md = util.log_time( - logfunc=LOG.debug, - msg="Reading from metadata service", - func=self._read_metadata, - ) + md = self._read_metadata() except sources.InvalidMetaDataException as e: util.logexc(LOG, str(e)) LOG.info( diff --git a/cloudinit/sources/DataSourceVMware.py b/cloudinit/sources/DataSourceVMware.py index 888060c9bd9..9ff88cea009 100644 --- a/cloudinit/sources/DataSourceVMware.py +++ b/cloudinit/sources/DataSourceVMware.py @@ -27,7 +27,8 @@ import socket import time -from cloudinit import atomic_helper, dmi, log, net, netinfo, sources, util +from cloudinit import atomic_helper, dmi, net, netinfo, sources, util +from cloudinit.log import loggers from cloudinit.sources.helpers.vmware.imc import guestcust_util from cloudinit.subp import ProcessExecutionError, subp, which @@ -1061,7 +1062,7 @@ def main(): Executed when this file is used as a program. """ try: - log.setup_basic_logging() + loggers.setup_basic_logging() except Exception: pass metadata = { diff --git a/cloudinit/sources/__init__.py b/cloudinit/sources/__init__.py index 6d906ec403b..d2b4f619bd4 100644 --- a/cloudinit/sources/__init__.py +++ b/cloudinit/sources/__init__.py @@ -19,7 +19,15 @@ from enum import Enum, unique from typing import Any, Dict, List, Optional, Tuple, Union -from cloudinit import atomic_helper, dmi, importer, lifecycle, net, type_utils +from cloudinit import ( + atomic_helper, + dmi, + importer, + lifecycle, + net, + performance, + type_utils, +) from cloudinit import user_data as ud from cloudinit import util from cloudinit.atomic_helper import write_json @@ -475,6 +483,7 @@ def clear_cached_attrs(self, attr_defaults=()): if not attr_defaults: self._dirty_cache = False + @performance.timed("Getting metadata", log_mode="always") def get_data(self) -> bool: """Datasources implement _get_data to setup metadata and userdata_raw. diff --git a/cloudinit/sources/helpers/vmware/imc/guestcust_util.py b/cloudinit/sources/helpers/vmware/imc/guestcust_util.py index b0b12ba5c0f..66d1fa1c9a1 100644 --- a/cloudinit/sources/helpers/vmware/imc/guestcust_util.py +++ b/cloudinit/sources/helpers/vmware/imc/guestcust_util.py @@ -367,12 +367,10 @@ def get_cust_cfg_file(ds_cfg): # that required metadata and userdata files are now # present. max_wait = get_max_wait_from_cfg(ds_cfg) - cust_cfg_file_path = util.log_time( - logfunc=logger.debug, - msg="Waiting for VMware customization configuration file", - func=wait_for_cust_cfg_file, - args=("cust.cfg", max_wait), - ) + with performance.Timed( + "Waiting for VMware customization configuration file" + ): + cust_cfg_file_path = wait_for_cust_cfg_file("cust.cfg", max_wait) if cust_cfg_file_path: logger.debug( "Found VMware customization configuration file at %s", diff --git a/cloudinit/util.py b/cloudinit/util.py index 9c90e35f5ee..d4efefa23ed 100644 --- a/cloudinit/util.py +++ b/cloudinit/util.py @@ -52,7 +52,6 @@ Mapping, Optional, Sequence, - TypeVar, Union, cast, ) @@ -65,6 +64,7 @@ importer, mergers, net, + performance, settings, subp, temp_utils, @@ -72,6 +72,7 @@ url_helper, version, ) +from cloudinit.log.log_util import logexc from cloudinit.settings import CFG_BUILTIN, PER_ONCE if TYPE_CHECKING: @@ -439,56 +440,6 @@ def get_modules_from_dir(root_dir: str) -> dict: return entries -def write_to_console(conpath, text): - with open(conpath, "w") as wfh: - wfh.write(text) - wfh.flush() - - -def multi_log( - text, - console=True, - stderr=True, - log=None, - log_level=logging.DEBUG, - fallback_to_stdout=True, -): - if stderr: - sys.stderr.write(text) - if console: - conpath = "/dev/console" - writing_to_console_worked = False - if os.path.exists(conpath): - try: - write_to_console(conpath, text) - writing_to_console_worked = True - except OSError: - console_error = "Failed to write to /dev/console" - sys.stdout.write(f"{console_error}\n") - if log: - log.log(logging.WARNING, console_error) - - if fallback_to_stdout and not writing_to_console_worked: - # A container may lack /dev/console (arguably a container bug). - # Additionally, /dev/console may not be writable to on a VM (again - # likely a VM bug or virtualization bug). - # - # If either of these is the case, then write output to stdout. - # This will result in duplicate stderr and stdout messages if - # stderr was True. - # - # even though systemd might have set up output to go to - # /dev/console, the user may have configured elsewhere via - # cloud-config 'output'. If there is /dev/console, messages will - # still get there. - sys.stdout.write(text) - if log: - if text[-1] == "\n": - log.log(log_level, text[:-1]) - else: - log.log(log_level, text) - - @lru_cache() def is_Linux(): """deprecated: prefer Distro object's `is_linux` property @@ -1325,6 +1276,7 @@ def get_fqdn_from_hosts(hostname, filename="/etc/hosts"): return fqdn +@performance.timed("Resolving URL") def is_resolvable(url) -> bool: """determine if a url's network address is resolvable, return a boolean This also attempts to be resilent against dns redirection. @@ -1390,12 +1342,7 @@ def gethostbyaddr(ip): def is_resolvable_url(url): """determine if this url is resolvable (existing or ip).""" - return log_time( - logfunc=LOG.debug, - msg="Resolving URL: " + url, - func=is_resolvable, - args=(url,), - ) + return is_resolvable(url) def search_for_mirror(candidates): @@ -1850,13 +1797,6 @@ def get_config_logfiles(cfg: Dict[str, Any]): return list(set(logs + rotated_logs)) -def logexc( - log, msg, *args, log_level: int = logging.WARNING, exc_info=True -) -> None: - log.log(log_level, msg, *args) - log.debug(msg, exc_info=exc_info, *args) - - def hash_blob(blob, routine: str, mlen=None) -> str: hasher = hashlib.new(routine) hasher.update(encode_text(blob)) @@ -2845,55 +2785,6 @@ def has_mount_opt(path, opt: str) -> bool: return opt in mnt_opts.split(",") -T = TypeVar("T") - - -def log_time( - logfunc, - msg, - func: Callable[..., T], - args=None, - kwargs=None, - get_uptime=False, -) -> T: - if args is None: - args = [] - if kwargs is None: - kwargs = {} - - start = time.monotonic() - - ustart = None - if get_uptime: - try: - ustart = float(uptime()) - except ValueError: - pass - - try: - ret = func(*args, **kwargs) - finally: - delta = time.monotonic() - start - udelta = None - if ustart is not None: - try: - udelta = float(uptime()) - ustart - except ValueError: - pass - - tmsg = " took %0.3f seconds" % delta - if get_uptime: - if isinstance(udelta, (float)): - tmsg += " (%0.2f)" % udelta - else: - tmsg += " (N/A)" - try: - logfunc(msg + tmsg) - except Exception: - pass - return ret - - def expand_dotted_devname(dotted): toks = dotted.rsplit(".", 1) if len(toks) > 1: @@ -3165,21 +3056,6 @@ def udevadm_settle(exists=None, timeout=None): return subp.subp(settle_cmd) -def error(msg, rc=1, fmt="Error:\n{}", sys_exit=False): - r""" - Print error to stderr and return or exit - - @param msg: message to print - @param rc: return code (default: 1) - @param fmt: format string for putting message in (default: 'Error:\n {}') - @param sys_exit: exit when called (default: false) - """ - print(fmt.format(msg), file=sys.stderr) - if sys_exit: - sys.exit(rc) - return rc - - def read_hotplug_enabled_file(paths: "Paths") -> dict: content: dict = {"scopes": []} try: diff --git a/tests/unittests/cmd/devel/test_net_convert.py b/tests/unittests/cmd/devel/test_net_convert.py index b59caed16dc..39e049227b5 100644 --- a/tests/unittests/cmd/devel/test_net_convert.py +++ b/tests/unittests/cmd/devel/test_net_convert.py @@ -97,7 +97,7 @@ def mock_setup_logging(): WARNING level, which would be a side-effect for future tests. It's behavior isn't checked in these tests, so mock it out. """ - with mock.patch(f"{M_PATH}log.setup_basic_logging"): + with mock.patch(f"{M_PATH}loggers.setup_basic_logging"): yield diff --git a/tests/unittests/cmd/test_main.py b/tests/unittests/cmd/test_main.py index bad728f2a72..e85fcdd4021 100644 --- a/tests/unittests/cmd/test_main.py +++ b/tests/unittests/cmd/test_main.py @@ -184,7 +184,7 @@ def set_hostname(name, cfg, cloud, args): @mock.patch("cloudinit.cmd.clean.get_parser") @mock.patch("cloudinit.cmd.clean.handle_clean_args") - @mock.patch("cloudinit.log.configure_root_logger") + @mock.patch("cloudinit.log.loggers.configure_root_logger") def test_main_sys_argv( self, _m_configure_root_logger, diff --git a/tests/unittests/config/test_cc_keys_to_console.py b/tests/unittests/config/test_cc_keys_to_console.py index f77e6234acd..caa2fa7bba1 100644 --- a/tests/unittests/config/test_cc_keys_to_console.py +++ b/tests/unittests/config/test_cc_keys_to_console.py @@ -20,7 +20,7 @@ class TestHandle: should be expanded to cover the full functionality. """ - @mock.patch("cloudinit.config.cc_keys_to_console.util.multi_log") + @mock.patch("cloudinit.config.cc_keys_to_console.log_util.multi_log") @mock.patch("cloudinit.config.cc_keys_to_console.os.path.exists") @mock.patch("cloudinit.config.cc_keys_to_console.subp.subp") @pytest.mark.parametrize( diff --git a/tests/unittests/config/test_cc_set_passwords.py b/tests/unittests/config/test_cc_set_passwords.py index d37faedd4c6..bc6f4cbda30 100644 --- a/tests/unittests/config/test_cc_set_passwords.py +++ b/tests/unittests/config/test_cc_set_passwords.py @@ -36,7 +36,7 @@ @pytest.fixture(autouse=True) def common_fixtures(mocker): mocker.patch("cloudinit.distros.uses_systemd", return_value=True) - mocker.patch("cloudinit.util.write_to_console") + mocker.patch("cloudinit.log.log_util.write_to_console") class TestHandleSSHPwauth: @@ -268,7 +268,7 @@ def test_bsd_calls_custom_pw_cmds_to_set_and_expire_passwords( ) def test_random_passwords(self, user_cfg, mocker, caplog): """handle parses command set random passwords.""" - m_multi_log = mocker.patch(f"{MODPATH}util.multi_log") + m_multi_log = mocker.patch(f"{MODPATH}log_util.multi_log") mocker.patch(f"{MODPATH}subp.subp") cloud = get_cloud() diff --git a/tests/unittests/config/test_cc_ubuntu_pro.py b/tests/unittests/config/test_cc_ubuntu_pro.py index 25794c70c64..aa347330587 100644 --- a/tests/unittests/config/test_cc_ubuntu_pro.py +++ b/tests/unittests/config/test_cc_ubuntu_pro.py @@ -1154,13 +1154,11 @@ def test_happy_path( m_should_auto_attach.should_auto_attach.return_value.should_auto_attach = ( # noqa: E501 should_auto_attach_value ) - if expected_result is None: # Pro API does respond + if expected_result is None: + # Pro API does respond assert should_auto_attach_value == _should_auto_attach(ua_section) - assert ( - "Checking if the instance can be attached to Ubuntu Pro took" - in caplog.text - ) - else: # cloud-init does respond + else: + # cloud-init does respond assert expected_result == _should_auto_attach(ua_section) assert not caplog.text @@ -1191,7 +1189,6 @@ def test_happy_path(self, caplog, mocker, fake_uaclient): mock.Mock() ) _auto_attach(self.ua_section) - assert "Attaching to Ubuntu Pro took" in caplog.text class TestAttach: diff --git a/tests/unittests/config/test_cc_zypper_add_repo.py b/tests/unittests/config/test_cc_zypper_add_repo.py index 772d132ffdf..21f033afd8a 100644 --- a/tests/unittests/config/test_cc_zypper_add_repo.py +++ b/tests/unittests/config/test_cc_zypper_add_repo.py @@ -8,7 +8,6 @@ from cloudinit import util from cloudinit.config import cc_zypper_add_repo from tests.unittests import helpers -from tests.unittests.helpers import mock LOG = logging.getLogger(__name__) @@ -98,8 +97,7 @@ def test_config_write(self): if item not in expected: self.assertIsNone(item) - @mock.patch("cloudinit.log.logging") - def test_config_write_skip_configdir(self, mock_logging): + def test_config_write_skip_configdir(self): """Write configuration but skip writing 'configdir' setting""" cfg = { "config": { diff --git a/tests/unittests/conftest.py b/tests/unittests/conftest.py index 60f2b675358..3042dee1288 100644 --- a/tests/unittests/conftest.py +++ b/tests/unittests/conftest.py @@ -7,8 +7,9 @@ import pytest -from cloudinit import atomic_helper, lifecycle, log, util +from cloudinit import atomic_helper, lifecycle, util from cloudinit.gpg import GPG +from cloudinit.log import loggers from tests.hypothesis import HAS_HYPOTHESIS from tests.unittests.helpers import example_netdev, retarget_many_wrapper @@ -135,12 +136,14 @@ def dhclient_exists(): yield -log.configure_root_logger() +loggers.configure_root_logger() @pytest.fixture(autouse=True, scope="session") def disable_root_logger_setup(): - with mock.patch("cloudinit.log.configure_root_logger", autospec=True): + with mock.patch( + "cloudinit.log.loggers.configure_root_logger", autospec=True + ): yield diff --git a/tests/unittests/sources/test_ec2.py b/tests/unittests/sources/test_ec2.py index 5cf2c38d543..b28afc52fe0 100644 --- a/tests/unittests/sources/test_ec2.py +++ b/tests/unittests/sources/test_ec2.py @@ -945,7 +945,6 @@ def test_ec2_local_performs_dhcp_on_non_bsd( router="192.168.2.1", static_routes=None, ) - assert "Crawl of metadata service " in caplog.text @responses.activate def test_get_instance_tags(self, mocker, tmpdir): diff --git a/tests/unittests/sources/test_gce.py b/tests/unittests/sources/test_gce.py index 1617f69430e..38935e05de5 100644 --- a/tests/unittests/sources/test_gce.py +++ b/tests/unittests/sources/test_gce.py @@ -418,7 +418,7 @@ def test_local_datasource_uses_ephemeral_dhcp( ds._get_data() assert m_dhcp.call_count == 1 - @mock.patch(M_PATH + "util.log_time") + @mock.patch(M_PATH + "read_md") @mock.patch( M_PATH + "EphemeralDHCPv4", autospec=True, diff --git a/tests/unittests/test_cli.py b/tests/unittests/test_cli.py index 58f003eb70f..bf42bd06a94 100644 --- a/tests/unittests/test_cli.py +++ b/tests/unittests/test_cli.py @@ -25,7 +25,7 @@ def disable_setup_logging(): # setup_basic_logging can change the logging level to WARNING, so # ensure it is always mocked - with mock.patch(f"{M_PATH}log.setup_basic_logging", autospec=True): + with mock.patch(f"{M_PATH}loggers.setup_basic_logging", autospec=True): yield @@ -205,7 +205,7 @@ def test_all_subcommands_represented_in_help(self, capsys): ), ), ) - @mock.patch("cloudinit.cmd.main.log.setup_basic_logging") + @mock.patch("cloudinit.cmd.main.loggers.setup_basic_logging") def test_subcommands_log_to_stderr_via_setup_basic_logging( self, setup_basic_logging, subcommand, log_to_stderr, mocks ): diff --git a/tests/unittests/test_log.py b/tests/unittests/test_log.py index d67c3552157..c3e83143165 100644 --- a/tests/unittests/test_log.py +++ b/tests/unittests/test_log.py @@ -10,8 +10,9 @@ import pytest -from cloudinit import lifecycle, log, util +from cloudinit import lifecycle, util from cloudinit.analyze.dump import CLOUD_INIT_ASCTIME_FMT +from cloudinit.log import loggers from tests.unittests.helpers import CiTestCase @@ -24,7 +25,7 @@ def setUp(self): self.ci_logs = io.StringIO() self.ci_root = logging.getLogger() console = logging.StreamHandler(self.ci_logs) - console.setFormatter(logging.Formatter(log.DEFAULT_LOG_FORMAT)) + console.setFormatter(logging.Formatter(loggers.DEFAULT_LOG_FORMAT)) console.setLevel(logging.DEBUG) self.ci_root.addHandler(console) self.ci_root.setLevel(logging.DEBUG) @@ -64,13 +65,13 @@ def test_logger_uses_gmtime(self): class TestDeprecatedLogs: def test_deprecated_log_level(self, caplog): - logger = cast(log.CustomLoggerType, logging.getLogger()) + logger = cast(loggers.CustomLoggerType, logging.getLogger()) logger.deprecated("deprecated message") assert "DEPRECATED" == caplog.records[0].levelname assert "deprecated message" in caplog.text def test_trace_log_level(self, caplog): - logger = cast(log.CustomLoggerType, logging.getLogger()) + logger = cast(loggers.CustomLoggerType, logging.getLogger()) logger.setLevel(logging.NOTSET) logger.trace("trace message") assert "TRACE" == caplog.records[0].levelname @@ -124,7 +125,7 @@ def test_deprecate_log_level_based_on_features( ) def test_log_deduplication(self, caplog): - log.define_extra_loggers() + loggers.define_extra_loggers() lifecycle.deprecate( deprecated="stuff", deprecated_version="19.1", @@ -146,6 +147,6 @@ def test_log_deduplication(self, caplog): def test_logger_prints_to_stderr(capsys): message = "to stdout" - log.setup_basic_logging() + loggers.setup_basic_logging() logging.getLogger().warning(message) assert message in capsys.readouterr().err diff --git a/tests/unittests/test_util.py b/tests/unittests/test_util.py index 190eca7610e..221e21de5c2 100644 --- a/tests/unittests/test_util.py +++ b/tests/unittests/test_util.py @@ -33,6 +33,7 @@ ) from cloudinit.distros import Distro from cloudinit.helpers import Paths +from cloudinit.log import log_util from cloudinit.sources import DataSourceHostname from cloudinit.subp import SubpResult from tests.unittests import helpers @@ -2369,85 +2370,85 @@ def setUp(self): def test_stderr_used_by_default(self): logged_string = "test stderr output" - util.multi_log(logged_string) + log_util.multi_log(logged_string) self.assertEqual(logged_string, self.stderr.getvalue()) def test_stderr_not_used_if_false(self): - util.multi_log("should not see this", stderr=False) + log_util.multi_log("should not see this", stderr=False) self.assertEqual("", self.stderr.getvalue()) def test_logs_go_to_console_by_default(self): self._createConsole(self.root) logged_string = "something very important" - util.multi_log(logged_string) + log_util.multi_log(logged_string) with open("/dev/console") as f: self.assertEqual(logged_string, f.read()) def test_logs_dont_go_to_stdout_if_console_exists(self): self._createConsole(self.root) - util.multi_log("something") + log_util.multi_log("something") self.assertEqual("", self.stdout.getvalue()) def test_logs_go_to_stdout_if_console_does_not_exist(self): logged_string = "something very important" - util.multi_log(logged_string) + log_util.multi_log(logged_string) self.assertEqual(logged_string, self.stdout.getvalue()) def test_logs_dont_go_to_stdout_if_fallback_to_stdout_is_false(self): - util.multi_log("something", fallback_to_stdout=False) + log_util.multi_log("something", fallback_to_stdout=False) self.assertEqual("", self.stdout.getvalue()) @mock.patch( - M_PATH + "write_to_console", + "cloudinit.log.log_util.write_to_console", mock.Mock(side_effect=OSError("Failed to write to console")), ) def test_logs_go_to_stdout_if_writing_to_console_fails_and_fallback_true( self, ): self._createConsole(self.root) - util.multi_log("something", fallback_to_stdout=True) + log_util.multi_log("something", fallback_to_stdout=True) self.assertEqual( "Failed to write to /dev/console\nsomething", self.stdout.getvalue(), ) @mock.patch( - M_PATH + "write_to_console", + "cloudinit.log.log_util.write_to_console", mock.Mock(side_effect=OSError("Failed to write to console")), ) def test_logs_go_nowhere_if_writing_to_console_fails_and_fallback_false( self, ): self._createConsole(self.root) - util.multi_log("something", fallback_to_stdout=False) + log_util.multi_log("something", fallback_to_stdout=False) self.assertEqual( "Failed to write to /dev/console\n", self.stdout.getvalue() ) def test_logs_go_to_log_if_given(self): - log = mock.MagicMock() + logger = mock.MagicMock() logged_string = "something very important" - util.multi_log(logged_string, log=log) + log_util.multi_log(logged_string, log=logger) self.assertEqual( - [((mock.ANY, logged_string), {})], log.log.call_args_list + [((mock.ANY, logged_string), {})], logger.log.call_args_list ) def test_newlines_stripped_from_log_call(self): - log = mock.MagicMock() + logger = mock.MagicMock() expected_string = "something very important" - util.multi_log("{0}\n".format(expected_string), log=log) - self.assertEqual((mock.ANY, expected_string), log.log.call_args[0]) + log_util.multi_log("{0}\n".format(expected_string), log=logger) + self.assertEqual((mock.ANY, expected_string), logger.log.call_args[0]) def test_log_level_defaults_to_debug(self): - log = mock.MagicMock() - util.multi_log("message", log=log) - self.assertEqual((logging.DEBUG, mock.ANY), log.log.call_args[0]) + logger = mock.MagicMock() + log_util.multi_log("message", log=logger) + self.assertEqual((logging.DEBUG, mock.ANY), logger.log.call_args[0]) def test_given_log_level_used(self): - log = mock.MagicMock() + logger = mock.MagicMock() log_level = mock.Mock() - util.multi_log("message", log=log, log_level=log_level) - self.assertEqual((log_level, mock.ANY), log.log.call_args[0]) + log_util.multi_log("message", log=logger, log_level=log_level) + self.assertEqual((log_level, mock.ANY), logger.log.call_args[0]) class TestMessageFromString(helpers.TestCase):