logging: no more cli console logging

lib/reboot_cmds.py

@@ -119,11 +119,10 @@ def main(cfg: config.UAConfig) -> int:
 
 if __name__ == "__main__":
     setup_logging(
-        logging.INFO,
         logging.DEBUG,
         defaults.CONFIG_DEFAULTS["log_file"],
     )
     cfg = config.UAConfig()
-    setup_logging(logging.INFO, logging.DEBUG, log_file=cfg.log_file)
+    setup_logging(logging.DEBUG, log_file=cfg.log_file)
     http.configure_web_proxy(cfg.http_proxy, cfg.https_proxy)
     sys.exit(main(cfg=cfg))

lib/timer.py

@@ -180,7 +180,6 @@ def run_jobs(cfg: UAConfig, current_time: datetime):
 
 if __name__ == "__main__":
     setup_logging(
-        logging.CRITICAL,
         logging.DEBUG,
         defaults.CONFIG_DEFAULTS["timer_log_file"],
         logger=LOG,
@@ -190,15 +189,14 @@ def run_jobs(cfg: UAConfig, current_time: datetime):
 
     # The ua-timer logger should log everything to its file
     setup_logging(
-        logging.CRITICAL,
         logging.DEBUG,
         log_file=cfg.timer_log_file,
         logger=LOG,
     )
     # Make sure the ua-timer logger does not generate double logging
     LOG.propagate = False
     # The root logger should log any error to the timer log file
-    setup_logging(logging.CRITICAL, logging.ERROR, log_file=cfg.timer_log_file)
+    setup_logging(logging.ERROR, log_file=cfg.timer_log_file)
     http.configure_web_proxy(cfg.http_proxy, cfg.https_proxy)
 
     run_jobs(cfg=cfg, current_time=current_time)

uaclient/actions.py

@@ -64,8 +64,7 @@ def attach_with_token(
             contract_token=token, attachment_dt=attached_at
         )
     except exceptions.UrlError as e:
-        with util.disable_log_to_console():
-            LOG.exception(str(e))
+        LOG.exception(str(e))
         raise exceptions.ConnectivityError()
 
     cfg.machine_token_file.write(new_machine_token)

uaclient/cli.py

@@ -1776,8 +1776,7 @@ def _action_refresh_config(args, cfg: config.UAConfig):
     try:
         cfg.process_config()
     except RuntimeError as exc:
-        with util.disable_log_to_console():
-            LOG.exception(exc)
+        LOG.exception(exc)
         raise exceptions.UserFacingError(messages.REFRESH_CONFIG_FAILURE)
     print(messages.REFRESH_CONFIG_SUCCESS)
 
@@ -1787,8 +1786,7 @@ def _action_refresh_contract(_args, cfg: config.UAConfig):
     try:
         contract.refresh(cfg)
     except exceptions.UrlError as exc:
-        with util.disable_log_to_console():
-            LOG.exception(exc)
+        LOG.exception(exc)
         raise exceptions.UserFacingError(messages.REFRESH_CONTRACT_FAILURE)
     print(messages.REFRESH_CONTRACT_SUCCESS)
 
@@ -1803,8 +1801,7 @@ def _action_refresh_messages(_args, cfg: config.UAConfig):
         if cfg.apt_news:
             apt_news.update_apt_news(cfg)
     except Exception as exc:
-        with util.disable_log_to_console():
-            LOG.exception(exc)
+        LOG.exception(exc)
         raise exceptions.UserFacingError(messages.REFRESH_MESSAGES_FAILURE)
     else:
         print(messages.REFRESH_MESSAGES_SUCCESS)
@@ -1885,7 +1882,9 @@ def _warn_about_new_version(cmd_args=None) -> None:
 
     new_version = version.check_for_new_version()
     if new_version:
+        msg = NEW_VERSION_NOTICE.format(version=new_version)
         LOG.warning(NEW_VERSION_NOTICE.format(version=new_version))
+        event.info(msg, file_type=sys.stderr)
 
 
 def _warn_about_output_redirection(cmd_args) -> None:
@@ -1896,14 +1895,14 @@ def _warn_about_output_redirection(cmd_args) -> None:
     ):
         if hasattr(cmd_args, "format") and cmd_args.format in ("json", "yaml"):
             return
-        LOG.warning(
-            messages.WARNING_HUMAN_READABLE_OUTPUT.format(
-                command=cmd_args.command
-            )
+        msg = messages.WARNING_HUMAN_READABLE_OUTPUT.format(
+            command=cmd_args.command
         )
+        LOG.warning(msg)
+        event.info(msg, file_type=sys.stderr)
 
 
-def setup_logging(console_level, log_level, log_file=None, logger=None):
+def setup_logging(log_level, log_file=None, logger=None):
     """Setup console logging and debug logging to log_file
 
     It configures the pro client logger.
@@ -1920,7 +1919,6 @@ def setup_logging(console_level, log_level, log_file=None, logger=None):
     if isinstance(log_level, str):
         log_level = log_level.upper()
 
-    console_formatter = util.LogFormatter()
     if not logger:
         logger = logging.getLogger("ubuntupro")
     logger.setLevel(log_level)
@@ -1929,20 +1927,11 @@ def setup_logging(console_level, log_level, log_file=None, logger=None):
     # Clear all handlers, so they are replaced for this logger
     logger.handlers = []
 
-    # Setup console logging
-    console_handler = logging.StreamHandler(sys.stderr)
-    console_handler.setFormatter(console_formatter)
-    console_handler.setLevel(console_level)
-    console_handler.set_name("upro-console")  # Used to disable console logging
-    logger.addHandler(console_handler)
-
+    # Setup file logging
     log_file_path = pathlib.Path(log_file)
-
     if not log_file_path.exists():
         log_file_path.parent.mkdir(parents=True, exist_ok=True)
         log_file_path.touch(mode=0o640)
-    # Setup file logging
-
     file_handler = logging.FileHandler(log_file)
     file_handler.setFormatter(JsonArrayFormatter())
     file_handler.setLevel(log_level)
@@ -1966,8 +1955,7 @@ def wrapper(*args, **kwargs):
         try:
             return func(*args, **kwargs)
         except KeyboardInterrupt:
-            with util.disable_log_to_console():
-                LOG.error("KeyboardInterrupt")
+            LOG.error("KeyboardInterrupt")
             print("Interrupt received; exiting.", file=sys.stderr)
             lock.clear_lock_file_if_present()
             sys.exit(1)
@@ -1980,15 +1968,12 @@ def wrapper(*args, **kwargs):
                 event.error(error_msg=msg.msg, error_code=msg.name)
                 event.info(info_msg=msg.msg, file_type=sys.stderr)
             else:
-                with util.disable_log_to_console():
-                    msg_args = {"url": exc.url, "error": exc}
-                    if exc.url:
-                        msg_tmpl = (
-                            messages.LOG_CONNECTIVITY_ERROR_WITH_URL_TMPL
-                        )
-                    else:
-                        msg_tmpl = messages.LOG_CONNECTIVITY_ERROR_TMPL
-                    LOG.exception(msg_tmpl.format(**msg_args))
+                msg_args = {"url": exc.url, "error": exc}
+                if exc.url:
+                    msg_tmpl = messages.LOG_CONNECTIVITY_ERROR_WITH_URL_TMPL
+                else:
+                    msg_tmpl = messages.LOG_CONNECTIVITY_ERROR_TMPL
+                LOG.exception(msg_tmpl.format(**msg_args))
 
                 msg = messages.CONNECTIVITY_ERROR
                 event.error(error_msg=msg.msg, error_code=msg.name)
@@ -2001,8 +1986,7 @@ def wrapper(*args, **kwargs):
 
             sys.exit(1)
         except exceptions.UserFacingError as exc:
-            with util.disable_log_to_console():
-                LOG.error(exc.msg)
+            LOG.error(exc.msg)
 
             event.error(
                 error_msg=exc.msg,
@@ -2019,8 +2003,7 @@ def wrapper(*args, **kwargs):
 
             sys.exit(exc.exit_code)
         except Exception as e:
-            with util.disable_log_to_console():
-                LOG.exception("Unhandled exception, please file a bug")
+            LOG.exception("Unhandled exception, please file a bug")
             lock.clear_lock_file_if_present()
             event.info(
                 info_msg=messages.UNEXPECTED_ERROR.msg, file_type=sys.stderr
@@ -2040,13 +2023,15 @@ def wrapper(*args, **kwargs):
 @main_error_handler
 def main(sys_argv=None):
     setup_logging(
-        logging.INFO,
         defaults.CONFIG_DEFAULTS["log_level"],
         defaults.CONFIG_DEFAULTS["log_file"],
     )
+    cfg = config.UAConfig()
+    setup_logging(cfg.log_level, cfg.log_file)
+
     if not sys_argv:
         sys_argv = sys.argv
-    cfg = config.UAConfig()
+
     parser = get_parser(cfg=cfg)
     cli_arguments = sys_argv[1:]
     if not cli_arguments:
@@ -2064,20 +2049,20 @@ def main(sys_argv=None):
         extra_args = []
 
     args = parser.parse_args(args=pro_cli_args)
+    if args.debug:
+        console_handler = logging.StreamHandler(sys.stderr)
+        console_handler.setLevel(logging.DEBUG)
+        logging.getLogger("ubuntupro").addHandler(console_handler)
+
     set_event_mode(args)
 
     http_proxy = cfg.http_proxy
     https_proxy = cfg.https_proxy
     http.configure_web_proxy(http_proxy=http_proxy, https_proxy=https_proxy)
 
-    log_level = cfg.log_level
-    console_level = logging.DEBUG if args.debug else logging.INFO
-    setup_logging(console_level, log_level, cfg.log_file)
-
     LOG.debug("Executed with sys.argv: %r" % sys_argv)
 
-    with util.disable_log_to_console():
-        cfg.warn_about_invalid_keys()
+    cfg.warn_about_invalid_keys()
 
     pro_environment = [
         "{}={}".format(k, v)

uaclient/config.py

@@ -128,9 +128,8 @@ def __init__(
                     or state_files.UserConfigData()
                 )
             except Exception as e:
-                with util.disable_log_to_console():
-                    LOG.warning("Error loading user config: {}".format(e))
-                    LOG.warning("Using default config values")
+                LOG.warning("Error loading user config: {}".format(e))
+                LOG.warning("Using default config values")
                 self.user_config = state_files.UserConfigData()
 
         # support old ua_config values in uaclient.conf as user-config.json

uaclient/contract.py

@@ -517,19 +517,17 @@ def process_entitlements_delta(
         except exceptions.UserFacingError:
             delta_error = True
             failed_services.append(name)
-            with util.disable_log_to_console():
-                LOG.error(
-                    "Failed to process contract delta for {name}:"
-                    " {delta}".format(name=name, delta=new_entitlement)
-                )
+            LOG.error(
+                "Failed to process contract delta for {name}:"
+                " {delta}".format(name=name, delta=new_entitlement)
+            )
         except Exception:
             unexpected_error = True
             failed_services.append(name)
-            with util.disable_log_to_console():
-                LOG.exception(
-                    "Unexpected error processing contract delta for {name}:"
-                    " {delta}".format(name=name, delta=new_entitlement)
-                )
+            LOG.exception(
+                "Unexpected error processing contract delta for {name}:"
+                " {delta}".format(name=name, delta=new_entitlement)
+            )
         else:
             # If we have any deltas to process and we were able to process
             # them, then we will mark that service as successfully enabled

uaclient/entitlements/base.py

@@ -1179,17 +1179,19 @@ def process_contract_deltas(
             if application_status != ApplicationStatus.DISABLED:
                 if self.can_disable():
                     self.disable()
-                    LOG.info(
-                        "Due to contract refresh, '%s' is now disabled.",
-                        self.name,
-                    )
+                    msg = (
+                        "Due to contract refresh, " "'{}' is now disabled."
+                    ).format(self.name)
+                    LOG.info(msg)
+                    event.info(msg)
                 else:
-                    LOG.warning(
-                        "Unable to disable '%s' as recommended during contract"
+                    msg = (
+                        "Unable to disable '{}' as recommended during contract"
                         " refresh. Service is still active. See"
-                        " `pro status`",
-                        self.name,
-                    )
+                        " `pro status`"
+                    ).format(self.name)
+                    LOG.warning(msg)
+                    event.info(msg)
             # Clean up former entitled machine-access-<name> response cache
             # file because uaclient doesn't access machine-access-* routes or
             # responses on unentitled services.

uaclient/entitlements/fips.py

@@ -450,10 +450,12 @@ def messaging(self) -> MessagingOperationsDict:
     def _perform_enable(self, silent: bool = False) -> bool:
         cloud_type, error = get_cloud_type()
         if cloud_type is None and error == NoCloudTypeReason.CLOUD_ID_ERROR:
-            LOG.warning(
+            msg = (
                 "Could not determine cloud, "
                 "defaulting to generic FIPS package."
             )
+            LOG.warning(msg)
+            event.info(msg)
         if super()._perform_enable(silent=silent):
             notices.remove(
                 Notice.FIPS_INSTALL_OUT_OF_DATE,

uaclient/entitlements/landscape.py

@@ -65,8 +65,7 @@ def _perform_disable(self, silent: bool = False) -> bool:
         try:
             system.subp(cmd)
         except exceptions.ProcessExecutionError as e:
-            with util.disable_log_to_console():
-                LOG.error(e)
+            LOG.error(e)
             event.info(str(e).strip())
             event.warning(str(e), self.name)
 
@@ -82,8 +81,7 @@ def _perform_disable(self, silent: bool = False) -> bool:
                 LANDSCAPE_CLIENT_CONFIG_PATH_DISABLE_BACKUP,
             )
         except FileNotFoundError as e:
-            with util.disable_log_to_console():
-                LOG.error(e)
+            LOG.error(e)
             event.info(str(e))
             event.warning(str(e), self.name)
 

uaclient/entitlements/livepatch.py

@@ -147,10 +147,11 @@ def setup_livepatch_config(
                 livepatch_token = self.cfg.machine_token["machineToken"]
             application_status, _details = self.application_status()
             if application_status != ApplicationStatus.DISABLED:
-                LOG.info(
-                    "Disabling %s prior to re-attach with new token",
-                    self.title,
+                msg = "Disabling {} prior to re-attach with new token".format(
+                    self.title
                 )
+                LOG.info(msg)
+                event.info(msg)
                 try:
                     system.subp([livepatch.LIVEPATCH_CMD, "disable"])
                 except exceptions.ProcessExecutionError as e:
@@ -280,7 +281,9 @@ def process_contract_deltas(
         )
         process_token = bool(deltas.get("resourceToken", False))
         if any([process_directives, process_token]):
-            LOG.info("Updating '%s' on changed directives.", self.name)
+            msg = "Updating '{}' on changed directives.".format(self.name)
+            LOG.info(msg)
+            event.info(msg)
             return self.setup_livepatch_config(
                 process_directives=process_directives,
                 process_token=process_token,

uaclient/entitlements/repo.py

@@ -202,10 +202,14 @@ def process_contract_deltas(
             return False
 
         if not self._check_apt_url_is_applied(delta_apt_url):
-            LOG.info(
-                "Updating '%s' apt sources list on changed directives.",
-                self.name,
+
+            msg = (
+                "Updating '{}' apt sources list on changed directives.".format(
+                    self.name
+                )
             )
+            LOG.info(msg)
+            event.info(msg)
 
             orig_entitlement = orig_access.get("entitlement", {})
             old_url = orig_entitlement.get("directives", {}).get("aptURL")
@@ -218,11 +222,11 @@ def process_contract_deltas(
             self.setup_apt_config()
 
         if delta_packages:
-            LOG.info(
-                "Installing packages on changed directives: {}".format(
-                    ", ".join(delta_packages)
-                )
+            msg = "Installing packages on changed directives: {}".format(
+                ", ".join(delta_packages)
             )
+            LOG.info(msg)
+            event.info(msg)
             self.install_packages(package_list=delta_packages)
 
         return True