logging: standardize logging callsite conventions

This commit standardizes our logging calls in a couple ways:
 - log messages should be inline strings at the callsite
 - log string formatting should use lazy % style
 - logs shouldn't share strings with printed messages

In the places where log and print calls shared a string, I separated
them and attempted to make the log string more "log-like" and the
printed string more user-friendly. I also moved the printed string
to the messages module.

Fixes: #2632

lib/patch_status_json.py

@@ -30,7 +30,7 @@ def patch_status_json_schema_0_1(status_file: str):
     try:
         status = json.loads(content, cls=util.DatetimeAwareJSONDecoder)
     except ValueError as e:
-        LOG.debug(
+        LOG.warning(
             "Unable to patch /var/lib/ubuntu-advantage/status.json: %s", str(e)
         )
         return
@@ -57,10 +57,8 @@ def patch_status_json_schema_0_1(status_file: str):
             new_status, cls=util.DatetimeAwareJSONEncoder
         )
     except ValueError as e:
-        LOG.debug(
-            "Unable to patch /var/lib/ubuntu-advantage/status.json: {}".format(
-                str(e)
-            )
+        LOG.warning(
+            "Unable to patch /var/lib/ubuntu-advantage/status.json: %s", str(e)
         )
     system.write_file(status_file, status_content)
 

lib/reboot_cmds.py

@@ -24,7 +24,6 @@
     exceptions,
     http,
     lock,
-    messages,
     upgrade_lts_contract,
 )
 from uaclient.api.u.pro.status.is_attached.v1 import _is_attached
@@ -60,19 +59,15 @@ def fix_pro_pkg_holds(cfg: config.UAConfig):
     try:
         fips.install_packages(cleanup_on_failure=False)
     except exceptions.UserFacingError:
-        LOG.warning(
-            "Failed to install packages at boot: {}".format(
-                ", ".join(fips.packages)
-            )
-        )
+        LOG.warning("Failed to install packages at boot: %r", fips.packages)
         raise
 
 
 def refresh_contract(cfg: config.UAConfig):
     try:
         contract.refresh(cfg)
     except exceptions.UrlError:
-        LOG.warning(messages.REFRESH_CONTRACT_FAILURE)
+        LOG.warning("Failed to refresh contract")
         raise
 
 

lib/timer.py

@@ -64,11 +64,11 @@ def run_interval_seconds(self, cfg: UAConfig) -> int:
         if configured_interval is None:
             return self._default_interval_seconds
         if not isinstance(configured_interval, int) or configured_interval < 0:
-            warning_msg = (
-                "Invalid value for {} interval found in config. "
-                "Default value will be used."
-            ).format(self.name)
-            LOG.warning(warning_msg)
+            LOG.warning(
+                "Invalid value for %s interval found in config. "
+                "Default value will be used.",
+                self.name,
+            )
             return self._default_interval_seconds
         return configured_interval
 
@@ -157,9 +157,10 @@ def run_jobs(cfg: UAConfig, current_time: datetime):
         try:
             timer_jobs_state_file.delete()
         except (OSError, PermissionError) as exception:
-            msg = "Error trying to delete invalid jobs-status.json file: {}"
-            msg = msg.format(str(exception))
-            LOG.warning(msg)
+            LOG.warning(
+                "Error trying to delete invalid jobs-status.json file: %s",
+                str(exception),
+            )
             return
 
     if jobs_status_obj is None:

uaclient/apt.py

@@ -417,7 +417,7 @@ def add_auth_apt_repo(
             continue  # Only enable suites matching this current series
         maybe_comment = ""
         if "-updates" in suite and not updates_enabled:
-            LOG.debug(
+            LOG.warning(
                 'Not enabling apt suite "%s" because "%s-updates" is not'
                 " enabled",
                 suite,

uaclient/cli.py

@@ -89,16 +89,6 @@
 
 UA_COLLECT_LOGS_FILE = "ua_logs.tar.gz"
 
-NEW_VERSION_NOTICE = (
-    "\n"
-    + messages.BLUE_INFO
-    + """\
- A new version is available: {version}
-Please run:
-    sudo apt-get install ubuntu-advantage-tools
-to get the latest version with new features and bug fixes."""
-)
-
 event = event_logger.get_event_logger()
 LOG = logging.getLogger(util.replace_top_level_logger_name(__name__))
 
@@ -1299,7 +1289,7 @@ def action_enable(args, *, cfg, **kwargs):
         contract.refresh(cfg)
     except (exceptions.UrlError, exceptions.UserFacingError):
         # Inability to refresh is not a critical issue during enable
-        LOG.debug(messages.REFRESH_CONTRACT_FAILURE, exc_info=True)
+        LOG.warning("Failed to refresh contract", exc_info=True)
         event.warning(warning_msg=messages.REFRESH_CONTRACT_FAILURE)
 
     names = getattr(args, "service", [])
@@ -1882,9 +1872,13 @@ 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)
+        LOG.warning("New version available: %s", new_version)
+        event.info(
+            messages.WARN_NEW_VERSION_AVAILABLE_CLI.format(
+                version=new_version
+            ),
+            file_type=sys.stderr,
+        )
 
 
 def _warn_about_output_redirection(cmd_args) -> None:
@@ -1895,11 +1889,13 @@ def _warn_about_output_redirection(cmd_args) -> None:
     ):
         if hasattr(cmd_args, "format") and cmd_args.format in ("json", "yaml"):
             return
-        msg = messages.WARNING_HUMAN_READABLE_OUTPUT.format(
-            command=cmd_args.command
+        LOG.warning("Not in a tty and human-readable command called")
+        event.info(
+            messages.WARNING_HUMAN_READABLE_OUTPUT.format(
+                command=cmd_args.command
+            ),
+            file_type=sys.stderr,
         )
-        LOG.warning(msg)
-        event.info(msg, file_type=sys.stderr)
 
 
 def setup_logging(log_level, log_file=None, logger=None):
@@ -1968,12 +1964,9 @@ 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:
-                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))
+                LOG.exception(
+                    "Failed to access URL: %s", exc.url, exc_info=exc
+                )
 
                 msg = messages.CONNECTIVITY_ERROR
                 event.error(error_msg=msg.msg, error_code=msg.name)

uaclient/clouds/aws.py

@@ -48,13 +48,11 @@ def _request_imds_v2_token_headers(self):
             try:
                 headers = self._get_imds_v2_token_headers(ip_address=address)
             except Exception as e:
-                msg = (
-                    "Could not reach AWS IMDS at http://{endpoint}:"
-                    " {reason}\n".format(
-                        endpoint=address, reason=getattr(e, "reason", "")
-                    )
+                LOG.warning(
+                    "Could not reach AWS IMDS at http://%s: %s\n",
+                    address,
+                    getattr(e, "reason", ""),
                 )
-                LOG.debug(msg)
             else:
                 self._ip_address = address
                 break

uaclient/clouds/tests/test_aws.py

@@ -112,9 +112,9 @@ def fake_someurlerrors(url, method=None, headers=None, timeout=1):
         expected_sleep_calls = [mock.call(1), mock.call(2), mock.call(5)]
         assert expected_sleep_calls == sleep.call_args_list
         expected_logs = [
-            "(701, 'funky error msg') Retrying 3 more times.",
-            "(702, 'funky error msg') Retrying 2 more times.",
-            "(703, 'funky error msg') Retrying 1 more times.",
+            "(701, 'funky error msg'): Retrying 3 more times.",
+            "(702, 'funky error msg'): Retrying 2 more times.",
+            "(703, 'funky error msg'): Retrying 1 more times.",
         ]
         logs = caplog_text()
         for log in expected_logs:
@@ -193,9 +193,9 @@ def fake_someurlerrors(url, method=None, headers=None, timeout=1):
         expected_sleep_calls = [mock.call(0.5), mock.call(1), mock.call(1)]
         assert expected_sleep_calls == sleep.call_args_list
         expected_logs = [
-            "(702, 'funky error msg') Retrying 3 more times.",
-            "(703, 'funky error msg') Retrying 2 more times.",
-            "(704, 'funky error msg') Retrying 1 more times.",
+            "(702, 'funky error msg'): Retrying 3 more times.",
+            "(703, 'funky error msg'): Retrying 2 more times.",
+            "(704, 'funky error msg'): Retrying 1 more times.",
         ]
         logs = caplog_text()
         for log in expected_logs:

uaclient/clouds/tests/test_azure.py

@@ -102,9 +102,9 @@ def fake_someurlerrors(url, headers, timeout):
         expected_sleep_calls = [mock.call(1), mock.call(1), mock.call(1)]
         assert expected_sleep_calls == sleep.call_args_list
         expected_logs = [
-            "(701, 'funky error msg') Retrying 3 more times.",
-            "(702, 'funky error msg') Retrying 2 more times.",
-            "(703, 'funky error msg') Retrying 1 more times.",
+            "(701, 'funky error msg'): Retrying 3 more times.",
+            "(702, 'funky error msg'): Retrying 2 more times.",
+            "(703, 'funky error msg'): Retrying 1 more times.",
         ]
         logs = caplog_text()
         for log in expected_logs:

uaclient/clouds/tests/test_gcp.py

@@ -83,11 +83,11 @@ def fake_someurlerrors(url, headers, timeout):
 
         expected_logs = [
             "GCPProServiceAccount Error 701: "
-            + "funky error msg Retrying 3 more times.",
+            + "funky error msg: Retrying 3 more times.",
             "GCPProServiceAccount Error 702: "
-            + "funky error msg Retrying 2 more times.",
+            + "funky error msg: Retrying 2 more times.",
             "GCPProServiceAccount Error 703: "
-            + "funky error msg Retrying 1 more times.",
+            + "funky error msg: Retrying 1 more times.",
         ]
         logs = caplog_text()
         for log in expected_logs:

uaclient/config.py

@@ -128,7 +128,7 @@ def __init__(
                     or state_files.UserConfigData()
                 )
             except Exception as e:
-                LOG.warning("Error loading user config: {}".format(e))
+                LOG.warning("Error loading user config", exc_info=e)
                 LOG.warning("Using default config values")
                 self.user_config = state_files.UserConfigData()
 
@@ -491,7 +491,9 @@ def process_config(self):
         ):
             value = getattr(self, prop)
             if value is None:
-                LOG.debug("No config set for {}, default value will be used.")
+                LOG.debug(
+                    "No config set for %s, default value will be used.", prop
+                )
             elif not isinstance(value, int) or value < 0:
                 error_msg = (
                     "Value for the {} interval must be a positive integer. "

uaclient/contract.py

@@ -264,7 +264,7 @@ def get_magic_attach_token_info(self, magic_token: str) -> Dict[str, Any]:
                 API_V1_GET_MAGIC_ATTACH_TOKEN_INFO, headers=headers
             )
         except exceptions.UrlError as e:
-            LOG.exception(str(e))
+            LOG.exception(e)
             raise exceptions.ConnectivityError()
         if response.code == 401:
             raise exceptions.MagicAttachTokenError()
@@ -290,7 +290,7 @@ def new_magic_attach_token(self) -> Dict[str, Any]:
                 method="POST",
             )
         except exceptions.UrlError as e:
-            LOG.exception(str(e))
+            LOG.exception(e)
             raise exceptions.ConnectivityError()
         if response.code == 503:
             raise exceptions.MagicAttachUnavailable()
@@ -313,7 +313,7 @@ def revoke_magic_attach_token(self, magic_token: str):
                 method="DELETE",
             )
         except exceptions.UrlError as e:
-            LOG.exception(str(e))
+            LOG.exception(e)
             raise exceptions.ConnectivityError()
         if response.code == 400:
             raise exceptions.MagicAttachTokenAlreadyActivated()
@@ -514,19 +514,23 @@ def process_entitlements_delta(
                 allow_enable=allow_enable,
                 series_overrides=series_overrides,
             )
-        except exceptions.UserFacingError:
+        except exceptions.UserFacingError as e:
+            LOG.exception(e)
             delta_error = True
             failed_services.append(name)
             LOG.error(
-                "Failed to process contract delta for {name}:"
-                " {delta}".format(name=name, delta=new_entitlement)
+                "Failed to process contract delta for %s: %r",
+                name,
+                new_entitlement,
             )
-        except Exception:
+        except Exception as e:
+            LOG.exception(e)
             unexpected_error = True
             failed_services.append(name)
             LOG.exception(
-                "Unexpected error processing contract delta for {name}:"
-                " {delta}".format(name=name, delta=new_entitlement)
+                "Unexpected error processing contract delta for %s: %r",
+                name,
+                new_entitlement,
             )
         else:
             # If we have any deltas to process and we were able to process

uaclient/daemon/__init__.py

@@ -23,7 +23,7 @@ def start():
             ["systemctl", "start", "ubuntu-advantage.service"], timeout=2.0
         )
     except (exceptions.ProcessExecutionError, TimeoutExpired) as e:
-        LOG.warning(e)
+        LOG.warning(e, exc_info=e)
 
 
 def stop():
@@ -32,7 +32,7 @@ def stop():
             ["systemctl", "stop", "ubuntu-advantage.service"], timeout=2.0
         )
     except (exceptions.ProcessExecutionError, TimeoutExpired) as e:
-        LOG.warning(e)
+        LOG.warning(e, exc_info=e)
 
 
 def cleanup(cfg: UAConfig):

uaclient/daemon/poll_for_pro_license.py

@@ -106,9 +106,8 @@ def poll_for_pro_license(cfg: UAConfig):
             if end - start < 10:
                 LOG.debug(
                     "wait_for_change returned quickly and no pro license"
-                    " present. Waiting {} seconds before polling again".format(
-                        cfg.polling_error_retry_delay
-                    )
+                    " present. Waiting %d seconds before polling again",
+                    cfg.polling_error_retry_delay,
                 )
                 time.sleep(cfg.polling_error_retry_delay)
                 continue

uaclient/daemon/retry_auto_attach.py

@@ -58,7 +58,7 @@ def full_auto_attach_exception_to_failure_reason(e: Exception) -> str:
     elif isinstance(e, api_exceptions.UserFacingError):
         return '"{}"'.format(e.msg)
     else:
-        LOG.error("Unexpected exception: {}".format(e))
+        LOG.error("Unexpected exception", exc_info=e)
         return str(e) or messages.RETRY_ERROR_DETAIL_UNKNOWN
 
 

uaclient/daemon/tests/test_daemon.py

@@ -35,7 +35,7 @@ def test_start_warning(self, m_log_warning, m_subp, err):
                 ["systemctl", "start", "ubuntu-advantage.service"], timeout=2.0
             )
         ] == m_subp.call_args_list
-        assert [mock.call(err)] == m_log_warning.call_args_list
+        assert [mock.call(err, exc_info=err)] == m_log_warning.call_args_list
 
 
 @mock.patch(M_PATH + "system.subp")
@@ -64,4 +64,4 @@ def test_stop_warning(self, m_log_warning, m_subp, err):
                 ["systemctl", "stop", "ubuntu-advantage.service"], timeout=2.0
             )
         ] == m_subp.call_args_list
-        assert [mock.call(err)] == m_log_warning.call_args_list
+        assert [mock.call(err, exc_info=err)] == m_log_warning.call_args_list

uaclient/daemon/tests/test_poll_for_pro_license.py

@@ -325,7 +325,8 @@ def test_before_polling_loop_checks(
                 [
                     mock.call(
                         "wait_for_change returned quickly and no pro license"
-                        " present. Waiting 123 seconds before polling again"
+                        " present. Waiting %d seconds before polling again",
+                        123,
                     )
                 ],
                 [mock.call(123)],
@@ -343,10 +344,10 @@ def test_before_polling_loop_checks(
                 ],
                 [mock.call(mock.ANY, mock.ANY)],
                 [
-                    mock.call(mock.ANY),
-                    mock.call(mock.ANY),
-                    mock.call(mock.ANY),
-                    mock.call(mock.ANY),
+                    mock.call(mock.ANY, mock.ANY),
+                    mock.call(mock.ANY, mock.ANY),
+                    mock.call(mock.ANY, mock.ANY),
+                    mock.call(mock.ANY, mock.ANY),
                 ],
                 [
                     mock.call(123),