Logging improvements

* formatted logging related code using black
* removed deprecated logzero.setup_default_logger
  * broken down into logzero.formatter, logzero.loglevel and logzero.logfile
* fixed broken logging in ipython console with %autoreload 2 turned on
  * _old_factory is None by default and is set to
    `broker_record_factory` only if _old_factory was not set to
`broker_record_factory` yet.

broker/binds/containers.py

@@ -1,6 +1,6 @@
 class ContainerBind:
     _sensitive_attrs = ["password", "host_password"]
-    
+
     def __init__(self, host=None, username=None, password=None, port=22, timeout=None):
         self.host = host
         self.username = username

broker/broker.py

@@ -111,7 +111,9 @@ def _act(self, provider, method, checkout=False):
             }
         )
         method_obj = getattr(provider_inst, method)
-        logger.debug(f"On {provider_inst=} executing {method_obj=} with params {self._kwargs=}.")
+        logger.debug(
+            f"On {provider_inst=} executing {method_obj=} with params {self._kwargs=}."
+        )
         result = method_obj(**self._kwargs)
         logger.debug(f"Action {result=}")
         if result and checkout:

broker/commands.py

@@ -14,15 +14,21 @@
 
 def loggedcli(*cli_args, **cli_kwargs):
     """Updates the cli.command wrapper function in order to add logging"""
+
     def decorator(func):
         @cli.command(*cli_args, **cli_kwargs)
         @wraps(func)
         def wrapper(*args, **kwargs):
             logger.log(LOG_LEVEL.TRACE.value, f"Calling {func=}(*{args=} **{kwargs=}")
             retval = func(*args, **kwargs)
-            logger.log(LOG_LEVEL.TRACE.value, f"Finished {func=}(*{args=} **{kwargs=}) {retval=}")
+            logger.log(
+                LOG_LEVEL.TRACE.value,
+                f"Finished {func=}(*{args=} **{kwargs=}) {retval=}",
+            )
             return retval
+
         return wrapper
+
     return decorator
 
 
@@ -135,9 +141,7 @@ def cli(version):
         click.echo(f"Log File: {broker_directory}/logs/broker.log")
 
 
-@loggedcli(
-    context_settings={"allow_extra_args": True, "ignore_unknown_options": True}
-)
+@loggedcli(context_settings={"allow_extra_args": True, "ignore_unknown_options": True})
 @click.option("-b", "--background", is_flag=True, help="Run checkout in the background")
 @click.option("-n", "--nick", type=str, help="Use a nickname defined in your settings")
 @click.option(
@@ -193,6 +197,7 @@ def providers():
 
 populate_providers(providers)
 
+
 @loggedcli()
 @click.argument("vm", type=str, nargs=-1)
 @click.option("-b", "--background", is_flag=True, help="Run checkin in the background")
@@ -261,6 +266,7 @@ def inventory(details, sync, filter):
             logger.info(f"{num}: {display_name}")
     helpers.emit({"inventory": emit_data})
 
+
 @loggedcli()
 @click.argument("vm", type=str, nargs=-1)
 @click.option("-b", "--background", is_flag=True, help="Run extend in the background")
@@ -340,9 +346,7 @@ def duplicate(vm, background, count, all_, filter):
                 )
 
 
-@loggedcli(
-    context_settings={"allow_extra_args": True, "ignore_unknown_options": True}
-)
+@loggedcli(context_settings={"allow_extra_args": True, "ignore_unknown_options": True})
 @click.option("-b", "--background", is_flag=True, help="Run execute in the background")
 @click.option("--nick", type=str, help="Use a nickname defined in your settings")
 @click.option(

broker/logger.py

@@ -20,8 +20,8 @@ class LOG_LEVEL(IntEnum):
     ERROR = logging.ERROR
 
 
-_sensitive = ['password', 'pword', 'token']
-_old_factory = logging.getLogRecordFactory()
+_sensitive = ["password", "pword", "token", "host_password"]
+_old_factory = None
 logging.addLevelName("TRACE", LOG_LEVEL.TRACE)
 logzero.DEFAULT_COLORS[LOG_LEVEL.TRACE.value] = logzero.colors.Fore.MAGENTA
 
@@ -71,7 +71,8 @@ def formatter_factory(log_level, color=True):
     )
     return formatter
 
-def record_factory(*args, **kwargs):
+
+def broker_record_factory(*args, **kwargs):
     """Factory to create a redacted logging.LogRecord"""
     record = _old_factory(*args, **kwargs)
     args_new = []
@@ -83,6 +84,7 @@ def record_factory(*args, **kwargs):
     record.args = tuple(args_new)
     return record
 
+
 def redact_dynaconf(data):
     if isinstance(data, (list, tuple)):
         data_copy = [redact_dynaconf(item) for item in data]
@@ -92,28 +94,28 @@ def redact_dynaconf(data):
             if isinstance(v, (dict, list)):
                 data_copy[k] = redact_dynaconf(v)
             elif k in _sensitive and v:
-                data_copy[k] = '*' * 6
+                data_copy[k] = "*" * 6
     else:
         data_copy = data
     return data_copy
 
 
 def set_log_level(level=settings.logging.console_level):
-    silent = False
     if level == "silent":
-        silent = True
         log_level = LOG_LEVEL.INFO
     else:
         log_level = resolve_log_level(level)
-    logzero.setup_default_logger(
-        level=log_level,
-        formatter=formatter_factory(log_level),
-        disableStderrLogger=silent,
-    )
+    logzero.formatter(formatter=formatter_factory(log_level))
+    logzero.loglevel(level=log_level)
 
 
 def set_file_logging(level=settings.logging.file_level, path="logs/broker.log"):
-    log_level = resolve_log_level(level)
+    silent = False
+    if level == "silent":
+        silent = True
+        log_level = LOG_LEVEL.INFO
+    else:
+        log_level = resolve_log_level(level)
     path = BROKER_DIRECTORY.joinpath(path)
     path.parent.mkdir(parents=True, exist_ok=True)
     logzero.logfile(
@@ -122,6 +124,7 @@ def set_file_logging(level=settings.logging.file_level, path="logs/broker.log"):
         maxBytes=1e9,
         backupCount=3,
         formatter=formatter_factory(log_level, color=False),
+        disableStderrLogger=silent,
     )
 
 
@@ -134,7 +137,11 @@ def setup_logzero(
     patch_awx_for_verbosity(awxkit.api)
     set_log_level(level)
     set_file_logging(file_level, path)
-    logging.setLogRecordFactory(record_factory)
+    global _old_factory
+    lrf = logging.getLogRecordFactory()
+    if lrf.__name__ is not broker_record_factory.__name__:
+        _old_factory = lrf
+        logging.setLogRecordFactory(broker_record_factory)
 
 
 setup_logzero()

broker/providers/ansible_tower.py

@@ -127,7 +127,7 @@ class AnsibleTower(Provider):
         ),
     ]
 
-    _sensitive_attrs = ['pword', 'password', 'token']
+    _sensitive_attrs = ["pword", "password", "token"]
 
     def __init__(self, **kwargs):
         super().__init__(**kwargs)

broker/settings.py

@@ -22,8 +22,16 @@
     Validator("HOST_SSH_PORT", default=22),
     Validator("HOST_SSH_KEY_FILENAME", default=None),
     Validator("LOGGING", is_type_of=dict),
-    Validator("LOGGING.LEVEL", is_in=["error", "warning", "info", "debug", "trace", "silent"], default="info"),
-    Validator("LOGGING.FILE_LEVEL", is_in=["error", "warning", "info", "debug", "trace", "silent"], default="debug"),
+    Validator(
+        "LOGGING.CONSOLE_LEVEL",
+        is_in=["error", "warning", "info", "debug", "trace", "silent"],
+        default="info",
+    ),
+    Validator(
+        "LOGGING.FILE_LEVEL",
+        is_in=["error", "warning", "info", "debug", "trace", "silent"],
+        default="debug",
+    ),
 ]
 
 # temporary fix for dynaconf #751