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

@@ -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)
                 )

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", {})

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

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"))

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:

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

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:

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,

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)

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

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
 

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")