From 881f9767f402c5699a64cf50e1ad68549f47a3a5 Mon Sep 17 00:00:00 2001 From: Grant Orndorff Date: Fri, 18 Aug 2023 10:45:41 -0400 Subject: [PATCH] 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 | 8 +- lib/reboot_cmds.py | 9 +-- lib/timer.py | 17 +++-- uaclient/apt.py | 2 +- uaclient/cli.py | 41 +++++------ uaclient/clouds/aws.py | 10 +-- uaclient/clouds/tests/test_aws.py | 12 +-- uaclient/clouds/tests/test_azure.py | 6 +- uaclient/clouds/tests/test_gcp.py | 6 +- uaclient/config.py | 6 +- uaclient/contract.py | 22 +++--- uaclient/daemon/__init__.py | 4 +- uaclient/daemon/poll_for_pro_license.py | 5 +- uaclient/daemon/retry_auto_attach.py | 2 +- uaclient/daemon/tests/test_daemon.py | 4 +- .../daemon/tests/test_poll_for_pro_license.py | 11 +-- uaclient/entitlements/base.py | 38 ++++++---- uaclient/entitlements/fips.py | 5 +- uaclient/entitlements/landscape.py | 17 +++-- uaclient/entitlements/livepatch.py | 26 ++++--- uaclient/entitlements/repo.py | 21 +++--- uaclient/entitlements/tests/test_livepatch.py | 6 +- uaclient/files/files.py | 2 +- uaclient/files/notices.py | 15 ++-- uaclient/files/tests/test_notices.py | 6 +- uaclient/http/__init__.py | 18 ++--- uaclient/http/tests/test_http.py | 10 +-- uaclient/livepatch.py | 13 ++-- uaclient/lock.py | 6 +- uaclient/messages.py | 59 ++++++++++----- uaclient/snap.py | 16 ++-- uaclient/status.py | 6 +- uaclient/system.py | 19 +++-- uaclient/tests/test_cli.py | 73 +++++++++++-------- uaclient/tests/test_system.py | 9 ++- uaclient/tests/test_upgrade_lts_contract.py | 32 ++++---- uaclient/timer/__init__.py | 4 +- uaclient/timer/update_contract_info.py | 9 ++- uaclient/upgrade_lts_contract.py | 32 ++++---- uaclient/util.py | 16 ++-- uaclient/yaml.py | 22 +++--- 41 files changed, 348 insertions(+), 297 deletions(-) diff --git a/lib/patch_status_json.py b/lib/patch_status_json.py index 481b039973..c45b85b44d 100755 --- a/lib/patch_status_json.py +++ b/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) diff --git a/lib/reboot_cmds.py b/lib/reboot_cmds.py index f50777c9d9..fb514e2a12 100644 --- a/lib/reboot_cmds.py +++ b/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,11 +59,7 @@ 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 @@ -72,7 +67,7 @@ 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 diff --git a/lib/timer.py b/lib/timer.py index 037a6aa7ff..e6b481f887 100644 --- a/lib/timer.py +++ b/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: diff --git a/uaclient/apt.py b/uaclient/apt.py index 5645744cd5..a5e8f60352 100644 --- a/uaclient/apt.py +++ b/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, diff --git a/uaclient/cli.py b/uaclient/cli.py index 3a50a7bbb8..612c553086 100644 --- a/uaclient/cli.py +++ b/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) diff --git a/uaclient/clouds/aws.py b/uaclient/clouds/aws.py index b492ddce97..22be14d5f2 100644 --- a/uaclient/clouds/aws.py +++ b/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 diff --git a/uaclient/clouds/tests/test_aws.py b/uaclient/clouds/tests/test_aws.py index 7a00efb6e4..df912a741a 100644 --- a/uaclient/clouds/tests/test_aws.py +++ b/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: diff --git a/uaclient/clouds/tests/test_azure.py b/uaclient/clouds/tests/test_azure.py index 2bea631802..802e3550ba 100644 --- a/uaclient/clouds/tests/test_azure.py +++ b/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: diff --git a/uaclient/clouds/tests/test_gcp.py b/uaclient/clouds/tests/test_gcp.py index c11cc5c3bb..b669ba310e 100644 --- a/uaclient/clouds/tests/test_gcp.py +++ b/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: diff --git a/uaclient/config.py b/uaclient/config.py index c3129787f1..2e4cde583e 100644 --- a/uaclient/config.py +++ b/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. " diff --git a/uaclient/contract.py b/uaclient/contract.py index bfb30503aa..5af0ed6f6b 100644 --- a/uaclient/contract.py +++ b/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 diff --git a/uaclient/daemon/__init__.py b/uaclient/daemon/__init__.py index 3cb85e8c13..ee64ef9832 100644 --- a/uaclient/daemon/__init__.py +++ b/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): diff --git a/uaclient/daemon/poll_for_pro_license.py b/uaclient/daemon/poll_for_pro_license.py index 15873391b7..e6b5d0c347 100644 --- a/uaclient/daemon/poll_for_pro_license.py +++ b/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 diff --git a/uaclient/daemon/retry_auto_attach.py b/uaclient/daemon/retry_auto_attach.py index 5247cc5558..fe20694ced 100644 --- a/uaclient/daemon/retry_auto_attach.py +++ b/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 diff --git a/uaclient/daemon/tests/test_daemon.py b/uaclient/daemon/tests/test_daemon.py index 2157204749..44b1ec7aaf 100644 --- a/uaclient/daemon/tests/test_daemon.py +++ b/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 diff --git a/uaclient/daemon/tests/test_poll_for_pro_license.py b/uaclient/daemon/tests/test_poll_for_pro_license.py index 247eeafb8d..3882825a33 100644 --- a/uaclient/daemon/tests/test_poll_for_pro_license.py +++ b/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), diff --git a/uaclient/entitlements/base.py b/uaclient/entitlements/base.py index e972bde7f1..d78519e6f1 100644 --- a/uaclient/entitlements/base.py +++ b/uaclient/entitlements/base.py @@ -544,9 +544,10 @@ def handle_required_packages(self) -> bool: apt.run_apt_update_command() package_names = [package["name"] for package in required_packages] - msg = messages.INSTALLING_PACKAGES.format(" ".join(package_names)) - LOG.debug(msg) - event.info(msg) + LOG.debug("Installing packages %r", package_names) + event.info( + messages.INSTALLING_PACKAGES.format(" ".join(package_names)) + ) apt.run_apt_install_command(package_names) return True @@ -569,10 +570,9 @@ def handle_removing_required_packages(self) -> bool: for package in required_packages if package.get("removeOnDisable", False) ] + LOG.debug("Uninstalling packages %r", package_names) package_names_str = " ".join(package_names) - msg = messages.UNINSTALLING_PACKAGES.format(package_names_str) - LOG.debug(msg) - event.info(msg) + event.info(messages.UNINSTALLING_PACKAGES.format(package_names_str)) apt.remove_packages( package_names, messages.UNINSTALLING_PACKAGES_FAILED.format(package_names_str), @@ -1168,20 +1168,28 @@ def process_contract_deltas( if application_status != ApplicationStatus.DISABLED: if self.can_disable(): + LOG.info( + "Disabling %s after refresh transition to unentitled" + ) self.disable() msg = ( "Due to contract refresh, " "'{}' is now disabled." ).format(self.name) - LOG.info(msg) - event.info(msg) + event.info( + messages.DISABLE_DURING_CONTRACT_REFRESH.format( + self.name + ) + ) else: - msg = ( - "Unable to disable '{}' as recommended during contract" - " refresh. Service is still active. See" - " `pro status`" - ).format(self.name) - LOG.warning(msg) - event.info(msg) + LOG.warning( + "Cannot disable %s after refresh transition to " + "unentitled" + ) + event.info( + messages.UNABLE_TO_DISABLE_DURING_CONTRACT_REFRESH.format( # noqa: E501 + self.name + ) + ) # Clean up former entitled machine-access- response cache # file because uaclient doesn't access machine-access-* routes or # responses on unentitled services. diff --git a/uaclient/entitlements/fips.py b/uaclient/entitlements/fips.py index 75b9c670a7..2f579cdf14 100644 --- a/uaclient/entitlements/fips.py +++ b/uaclient/entitlements/fips.py @@ -457,12 +457,11 @@ 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: - msg = ( + LOG.warning( "Could not determine cloud, " "defaulting to generic FIPS package." ) - LOG.warning(msg) - event.info(msg) + event.info(messages.FIPS_COULD_NOT_DETERMINE_CLOUD_DEFAULT_PACKAGE) if super()._perform_enable(silent=silent): notices.remove( Notice.FIPS_INSTALL_OUT_OF_DATE, diff --git a/uaclient/entitlements/landscape.py b/uaclient/entitlements/landscape.py index 5e1a9a7e1a..f269c1342f 100644 --- a/uaclient/entitlements/landscape.py +++ b/uaclient/entitlements/landscape.py @@ -34,7 +34,7 @@ def _perform_enable(self, silent: bool = False) -> bool: if self.assume_yes and "--silent" not in cmd: cmd += ["--silent"] - LOG.debug(messages.EXECUTING_COMMAND.format(" ".join(cmd))) + LOG.debug("Executing: %r", cmd) event.info( util.redact_sensitive_logs( messages.EXECUTING_COMMAND.format(" ".join(cmd)) @@ -76,12 +76,17 @@ def _perform_disable(self, silent: bool = False) -> bool: event.info(str(e).strip()) event.warning(str(e), self.name) - msg = messages.BACKING_UP_FILE.format( - original=LANDSCAPE_CLIENT_CONFIG_PATH, - backup=LANDSCAPE_CLIENT_CONFIG_PATH_DISABLE_BACKUP, + LOG.debug( + "Backing up %s as %s", + LANDSCAPE_CLIENT_CONFIG_PATH, + LANDSCAPE_CLIENT_CONFIG_PATH_DISABLE_BACKUP, + ) + event.info( + messages.BACKING_UP_FILE.format( + original=LANDSCAPE_CLIENT_CONFIG_PATH, + backup=LANDSCAPE_CLIENT_CONFIG_PATH_DISABLE_BACKUP, + ) ) - LOG.debug(msg) - event.info(msg) try: os.rename( LANDSCAPE_CLIENT_CONFIG_PATH, diff --git a/uaclient/entitlements/livepatch.py b/uaclient/entitlements/livepatch.py index 50dc5943b1..7cfc6e4e6c 100644 --- a/uaclient/entitlements/livepatch.py +++ b/uaclient/entitlements/livepatch.py @@ -139,9 +139,8 @@ def setup_livepatch_config( try: process_config_directives(entitlement_cfg) except exceptions.ProcessExecutionError as e: - msg = "Unable to configure Livepatch: " + str(e) - event.info(msg) - LOG.error(msg) + LOG.error(str(e), exc_info=e) + event.info("Unable to configure livepatch: %s", str(e)) return False if process_token: livepatch_token = entitlement_cfg.get("resourceToken") @@ -154,15 +153,16 @@ def setup_livepatch_config( livepatch_token = self.cfg.machine_token["machineToken"] application_status, _details = self.application_status() if application_status != ApplicationStatus.DISABLED: - msg = "Disabling {} prior to re-attach with new token".format( - self.title + LOG.info("Disabling livepatch before re-enabling") + event.info( + "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: - LOG.error(str(e)) + LOG.error(str(e), exc_info=e) return False try: system.subp( @@ -288,9 +288,13 @@ def process_contract_deltas( ) process_token = bool(deltas.get("resourceToken", False)) if any([process_directives, process_token]): - msg = "Updating '{}' on changed directives.".format(self.name) - LOG.info(msg) - event.info(msg) + LOG.info( + "New livepatch directives or token. running " + "setup_livepatch_config" + ) + event.info( + "Updating '{}' on changed directives.".format(self.name) + ) return self.setup_livepatch_config( process_directives=process_directives, process_token=process_token, diff --git a/uaclient/entitlements/repo.py b/uaclient/entitlements/repo.py index 873d2bf241..1347746dda 100644 --- a/uaclient/entitlements/repo.py +++ b/uaclient/entitlements/repo.py @@ -202,14 +202,12 @@ def process_contract_deltas( return False if not self._check_apt_url_is_applied(delta_apt_url): - - msg = ( - "Updating '{}' apt sources list on changed directives.".format( - self.name - ) + LOG.info( + "New aptURL, updating %s apt sources list to %s", + self.name, + delta_apt_url, ) - LOG.info(msg) - event.info(msg) + event.info(messages.REPO_UPDATING_APT_SOURCES.format(self.name)) orig_entitlement = orig_access.get("entitlement", {}) old_url = orig_entitlement.get("directives", {}).get("aptURL") @@ -222,11 +220,12 @@ def process_contract_deltas( self.setup_apt_config() if delta_packages: - msg = "Installing packages on changed directives: {}".format( - ", ".join(delta_packages) + LOG.info("New additionalPackages, installing %r", delta_packages) + event.info( + messages.REPO_REFRESH_INSTALLING_PACKAGES.format( + ", ".join(delta_packages) + ) ) - LOG.info(msg) - event.info(msg) self.install_packages(package_list=delta_packages) return True diff --git a/uaclient/entitlements/tests/test_livepatch.py b/uaclient/entitlements/tests/test_livepatch.py index d5baf73e85..5a5e2f8d71 100644 --- a/uaclient/entitlements/tests/test_livepatch.py +++ b/uaclient/entitlements/tests/test_livepatch.py @@ -734,8 +734,10 @@ def test_enable_alerts_user_that_snapd_does_not_wait_command( in fake_stdout.getvalue().strip() ) - for msg in messages.SNAPD_DOES_NOT_HAVE_WAIT_CMD.split("\n"): - assert msg in caplog_text() + assert ( + "Detected version of snapd that does not have wait command" + in caplog_text() + ) assert m_validate_proxy.call_count == 2 assert m_snap_proxy.call_count == 1 diff --git a/uaclient/files/files.py b/uaclient/files/files.py index 3df34d48e9..df5287640e 100644 --- a/uaclient/files/files.py +++ b/uaclient/files/files.py @@ -52,7 +52,7 @@ def read(self) -> Optional[str]: try: content = system.load_file(self.path) except FileNotFoundError: - LOG.debug("File does not exist: {}".format(self.path)) + LOG.debug("Tried to load %s but file does not exist", self.path) return content def delete(self): diff --git a/uaclient/files/notices.py b/uaclient/files/notices.py index 7df3af7d8d..38877b55d7 100644 --- a/uaclient/files/notices.py +++ b/uaclient/files/notices.py @@ -119,7 +119,10 @@ def add( :param description: The content to be written to the notice file. """ if not util.we_are_currently_root(): - LOG.warning("Trying to add a notice as non-root user") + LOG.warning( + "NoticesManager.add(%s) called as non-root user", + notice_details.value.label, + ) return directory = ( @@ -141,7 +144,10 @@ def remove(self, notice_details: Notice): :param notice_details: Holds details concerning the notice file. """ if not util.we_are_currently_root(): - LOG.warning("Trying to remove a notice as non-root user") + LOG.warning( + "NoticesManager.remove(%s) called as non-root user", + notice_details.value.label, + ) return directory = ( @@ -193,9 +199,8 @@ def list(self) -> List[str]: except Exception: LOG.warning( "Something went wrong while processing" - " notice: {}.".format( - notice_file_name, - ) + " notice: %s.", + notice_file_name, ) notices.sort() return notices diff --git a/uaclient/files/tests/test_notices.py b/uaclient/files/tests/test_notices.py index 9267cdd9ea..f336cfdfaf 100644 --- a/uaclient/files/tests/test_notices.py +++ b/uaclient/files/tests/test_notices.py @@ -46,7 +46,7 @@ def test_add_non_root( notice = NoticesManager() notice.add(FakeNotice.a, "content") assert [] == m_sys_write_file.call_args_list - assert "Trying to add a notice as non-root user" in caplog_text() + assert "NoticesManager.add(a) called as non-root user" in caplog_text() @pytest.mark.parametrize( "label,content", @@ -106,7 +106,9 @@ def test_remove_non_root( notice = NoticesManager() notice.remove(FakeNotice.a) assert [] == m_sys_file_absent.call_args_list - assert "Trying to remove a notice as non-root user" in caplog_text() + assert ( + "NoticesManager.remove(a) called as non-root user" in caplog_text() + ) @mock.patch("uaclient.files.notices.NoticesManager.list") @mock.patch("uaclient.files.notices.NoticesManager.remove") diff --git a/uaclient/http/__init__.py b/uaclient/http/__init__.py index 8a76fddc66..cc3fd63641 100644 --- a/uaclient/http/__init__.py +++ b/uaclient/http/__init__.py @@ -7,7 +7,7 @@ from urllib import error, request from urllib.parse import ParseResult, urlparse -from uaclient import defaults, exceptions, messages, util +from uaclient import defaults, exceptions, util UA_NO_PROXY_URLS = ("169.254.169.254", "metadata", "[fd00:ec2::254]") PROXY_VALIDATION_APT_HTTP_URL = "http://archive.ubuntu.com" @@ -73,11 +73,11 @@ def validate_proxy( except exceptions.ProxyAuthenticationFailed: raise except Exception as e: - msg = getattr(e, "reason", str(e)) LOG.error( - messages.ERROR_USING_PROXY.format( - proxy=proxy, test_url=test_url, error=msg - ) + 'Error trying to use "%s" as pycurl proxy to reach "%s": %s', + proxy, + test_url, + str(e), ) raise exceptions.ProxyNotWorkingError(proxy) @@ -93,11 +93,11 @@ def validate_proxy( opener.open(req) return proxy except (socket.timeout, error.URLError) as e: - msg = getattr(e, "reason", str(e)) LOG.error( - messages.ERROR_USING_PROXY.format( - proxy=proxy, test_url=test_url, error=msg - ) + 'Error trying to use "%s" as urllib proxy to reach "%s": %s', + proxy, + test_url, + getattr(e, "reason", str(e)), ) raise exceptions.ProxyNotWorkingError(proxy) diff --git a/uaclient/http/tests/test_http.py b/uaclient/http/tests/test_http.py index 9b00c30de6..91c400cfad 100644 --- a/uaclient/http/tests/test_http.py +++ b/uaclient/http/tests/test_http.py @@ -120,13 +120,9 @@ def test_fails_when_open_fails( ) assert ( - messages.ERROR_USING_PROXY.format( - proxy="http://localhost:1234", - test_url="http://example.com", - error=expected_message, - ) - in caplog_text() - ) + 'Error trying to use "http://localhost:1234" as urllib proxy ' + 'to reach "http://example.com": {}' + ).format(expected_message) in caplog_text() class TestConfigureWebProxy: diff --git a/uaclient/livepatch.py b/uaclient/livepatch.py index 1c2d6d86e3..df84666287 100644 --- a/uaclient/livepatch.py +++ b/uaclient/livepatch.py @@ -136,11 +136,12 @@ def status() -> Optional[LivepatchStatusStatus]: try: status_json = json.loads(out) - except json.JSONDecodeError: + except json.JSONDecodeError as e: LOG.warning( - messages.JSON_PARSER_ERROR.format( - source="canonical-livepatch status", out=out - ).msg + "JSONDecodeError while parsing livepatch status, returning None. " + 'output was: "%s"', + out, + exc_info=e, ) return None @@ -148,8 +149,8 @@ def status() -> Optional[LivepatchStatusStatus]: status_root = LivepatchStatus.from_dict(status_json) except IncorrectTypeError: LOG.warning( - "canonical-livepatch status returned unexpected " - "structure: {}".format(out) + "canonical-livepatch status returned unexpected structure: %s", + out, ) return None diff --git a/uaclient/lock.py b/uaclient/lock.py index 8eeb0d1f3b..cd36e726e2 100644 --- a/uaclient/lock.py +++ b/uaclient/lock.py @@ -91,7 +91,7 @@ def __init__( self.max_retries = max_retries def __enter__(self): - LOG.debug("spin lock starting for {}".format(self.lock_holder)) + LOG.debug("spin lock starting for %s", self.lock_holder) tries = 0 while True: try: @@ -99,9 +99,7 @@ def __enter__(self): break except exceptions.LockHeldError as e: LOG.debug( - "SpinLock Attempt {}. {}. Spinning...".format( - tries + 1, e.msg - ) + "SpinLock Attempt %d. %s. Spinning...", tries + 1, e.msg ) tries += 1 if tries >= self.max_retries: diff --git a/uaclient/messages.py b/uaclient/messages.py index 8078762090..cfc64f68ba 100644 --- a/uaclient/messages.py +++ b/uaclient/messages.py @@ -265,10 +265,6 @@ class TxtColor: "Unable to update Ubuntu Pro related APT and MOTD messages." ) -UPDATE_CHECK_CONTRACT_FAILURE = ( - """Failed to check for change in machine contract. Reason: {reason}""" -) - INCOMPATIBLE_SERVICE = """\ {service_being_enabled} cannot be enabled with {incompatible_service}. Disable {incompatible_service} and proceed to enable {service_being_enabled}? \ @@ -352,9 +348,6 @@ class TxtColor: """ SETTING_SERVICE_PROXY = "Setting {service} proxy" -ERROR_USING_PROXY = ( - 'Error trying to use "{proxy}" as proxy to reach "{test_url}": {error}' -) PROXY_DETECTED_BUT_NOT_CONFIGURED = """\ No proxy set in config; however, proxy is configured for: {{services}}. @@ -838,11 +831,6 @@ class TxtColor: "see https://cloud.google.com/iam/docs/service-accounts", ) -LOG_CONNECTIVITY_ERROR_TMPL = CONNECTIVITY_ERROR.msg + " {error}" -LOG_CONNECTIVITY_ERROR_WITH_URL_TMPL = ( - CONNECTIVITY_ERROR.msg + " Failed to access URL: {url}. {error}" -) - SETTING_SERVICE_PROXY_SCOPE = "Setting {scope} APT proxy" WARNING_APT_PROXY_SETUP = """\ Warning: apt_{protocol_type}_proxy has been renamed to global_apt_{protocol_type}_proxy.""" # noqa: E501 @@ -865,10 +853,6 @@ class TxtColor: Cancelling config process operation. """ -AVAILABILITY_FROM_UNKNOWN_SERVICE = """\ -Ignoring availability of unknown service {service} from contract server -""" - NOTICE_FIPS_MANUAL_DISABLE_URL = """\ FIPS kernel is running in a disabled state. To manually remove fips kernel: https://discourse.ubuntu.com/t/20738 @@ -948,14 +932,21 @@ class TxtColor: name="invalid-file-format", msg="{file_name} is not valid {file_format}" ) -KERNEL_PARSE_ERROR = "Failed to parse kernel: {kernel}" - WARN_NEW_VERSION_AVAILABLE = FormattedNamedMessage( name="new-version-available", msg="A new version of the client is available: {version}. \ Please upgrade to the latest version to get the new features \ and bug fixes.", ) +WARN_NEW_VERSION_AVAILABLE_CLI = ( + "\n" + + 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.""" +) INVALID_PRO_IMAGE = FormattedNamedMessage( name="invalid-pro-image", msg="Error on Pro Image:\n{msg}" @@ -1380,3 +1371,35 @@ class TxtColor: "security-fix-not-found-issue", "Error: {issue_id} not found.", ) + +DISABLE_DURING_CONTRACT_REFRESH = ( + "Due to contract refresh, " "'{}' is now disabled." +) +UNABLE_TO_DISABLE_DURING_CONTRACT_REFRESH = ( + "Unable to disable '{}' as recommended during contract" + " refresh. Service is still active. See" + " `pro status`" +) + +FIPS_COULD_NOT_DETERMINE_CLOUD_DEFAULT_PACKAGE = ( + "Could not determine cloud, defaulting to generic FIPS package." +) + + +REPO_UPDATING_APT_SOURCES = ( + "Updating '{}' apt sources list on changed directives." +) +REPO_REFRESH_INSTALLING_PACKAGES = ( + "Installing packages on changed directives: {}" +) + +RELEASE_UPGRADE_APT_LOCK_HELD_WILL_WAIT = ( + "APT lock is held. Ubuntu Pro configuration will wait until it is released" +) +RELEASE_UPGRADE_NO_PAST_RELEASE = "Could not find past release for {}" +RELEASE_UPGRADE_STARTING = ( + "Starting upgrade of Ubuntu Pro service configuration" +) +RELEASE_UPGRADE_SUCCESS = ( + "Finished upgrade of Ubuntu Pro service configuration" +) diff --git a/uaclient/snap.py b/uaclient/snap.py index dae0b5178b..ff06c53480 100644 --- a/uaclient/snap.py +++ b/uaclient/snap.py @@ -143,7 +143,10 @@ def run_snapd_wait_cmd(): system.subp([SNAP_CMD, "wait", "system", "seed.loaded"], capture=True) except exceptions.ProcessExecutionError as e: if re.search(r"unknown command .*wait", str(e).lower()): - LOG.warning(messages.SNAPD_DOES_NOT_HAVE_WAIT_CMD) + LOG.warning( + "Detected version of snapd that does not have wait command" + ) + event.info(messages.SNAPD_DOES_NOT_HAVE_WAIT_CMD) else: raise @@ -183,12 +186,13 @@ def get_snap_info(snap: str) -> SnapPackage: try: data = json.loads(out) - except json.JSONDecodeError: + except json.JSONDecodeError as e: LOG.warning( - messages.JSON_PARSER_ERROR.format( - source="SNAPD API {}".format(url), - out=out, - ).msg + "JSONDecodeError while parsing result of snap api call to %s, " + 'returning None. output was: "%s"', + url, + out, + exc_info=e, ) raise exceptions.SnapdInvalidJson(url=url, out=out) diff --git a/uaclient/status.py b/uaclient/status.py index 0c6dcbb984..a607a05e47 100644 --- a/uaclient/status.py +++ b/uaclient/status.py @@ -279,9 +279,9 @@ def _unattached_status(cfg: UAConfig) -> Dict[str, Any]: except exceptions.EntitlementNotFoundError: LOG.debug( - messages.AVAILABILITY_FROM_UNKNOWN_SERVICE.format( - service=resource.get("name", "without a 'name' key") - ) + "Ignoring availability of unknown service %s from contract " + "server", + resource.get("name", "without a 'name' key"), ) continue diff --git a/uaclient/system.py b/uaclient/system.py index de62dcc357..70aed49c7b 100644 --- a/uaclient/system.py +++ b/uaclient/system.py @@ -152,7 +152,7 @@ def get_kernel_info() -> KernelInfo: uname_release = uname.release.strip() uname_match = re.match(RE_KERNEL_UNAME, uname_release) if uname_match is None: - LOG.warning(messages.KERNEL_PARSE_ERROR.format(kernel=uname_release)) + LOG.warning("Failed to parse kernel: %s", uname_release) return KernelInfo( uname_machine_arch=uname_machine_arch, uname_release=uname_release, @@ -477,8 +477,8 @@ def is_exe(path: str) -> bool: def load_file(filename: str, decode: bool = True) -> str: """Read filename and decode content.""" - LOG.debug("Reading file: %s", filename) with open(filename, "rb") as stream: + LOG.debug("Reading file: %s", filename) content = stream.read() return content.decode("utf-8") @@ -536,10 +536,10 @@ def write_file( def ensure_file_absent(file_path: str) -> None: """Remove a file if it exists, logging a message about removal.""" try: - LOG.debug("Removing file: %s", file_path) os.unlink(file_path) + LOG.debug("Removed file: %s", file_path) except FileNotFoundError: - LOG.debug("File does not exist: %s", file_path) + LOG.debug("Tried to remove %s but file does not exist", file_path) def _subp( @@ -676,22 +676,21 @@ def subp( except exceptions.ProcessExecutionError as e: if capture: LOG.debug(str(e)) - msg = "Stderr: {}\nStdout: {}".format(e.stderr, e.stdout) - LOG.warning(msg) + LOG.warning("Stderr: %s\nStdout: %s", e.stderr, e.stdout) if not retry_sleeps: raise - retry_msg = " Retrying %d more times." % len(retry_sleeps) - LOG.debug(str(e) + retry_msg) + LOG.debug(str(e)) + LOG.debug("Retrying %d more times.", len(retry_sleeps)) time.sleep(retry_sleeps.pop(0)) return out, err def ensure_folder_absent(folder_path: str) -> None: try: - LOG.debug("Removing folder: %s", folder_path) rmtree(folder_path) + LOG.debug("Removed folder: %s", folder_path) except FileNotFoundError: - LOG.debug("Folder does not exist: %s", folder_path) + LOG.debug("Tried to remove %s but folder does not exist", folder_path) def is_systemd_unit_active(service_name: str) -> bool: diff --git a/uaclient/tests/test_cli.py b/uaclient/tests/test_cli.py index f016bfbbb3..ddec7b9f14 100644 --- a/uaclient/tests/test_cli.py +++ b/uaclient/tests/test_cli.py @@ -2,7 +2,6 @@ import io import json import logging -import re import socket import sys import textwrap @@ -620,20 +619,15 @@ def test_user_facing_error_handled_gracefully( assert [mock.call(expected_msg)] == m_log_error.call_args_list @pytest.mark.parametrize( - "error_url,expected_log", + ["error_url", "expected_log_call"], ( - ( - None, - "Failed to connect to authentication server\n" - "Check your Internet connection and try again." - " [Errno -2] Name or service not known", - ), ( "http://nowhere.com", - "Failed to connect to authentication server\n" - "Check your Internet connection and try again." - " Failed to access URL: http://nowhere.com." - " [Errno -2] Name or service not known", + mock.call( + "Failed to access URL: %s", + "http://nowhere.com", + exc_info=mock.ANY, + ), ), ), ) @@ -648,7 +642,7 @@ def test_url_error_handled_gracefully( m_log_exception, m_event_info, error_url, - expected_log, + expected_log_call, ): m_args = m_get_parser.return_value.parse_args.return_value m_args.action.side_effect = exceptions.UrlError( @@ -666,7 +660,7 @@ def test_url_error_handled_gracefully( info_msg=messages.CONNECTIVITY_ERROR.msg, file_type=mock.ANY ) ] == m_event_info.call_args_list - assert [mock.call(expected_log)] == m_log_exception.call_args_list + assert [expected_log_call] == m_log_exception.call_args_list @pytest.mark.parametrize("caplog_text", [logging.DEBUG], indirect=True) @mock.patch("uaclient.cli.setup_logging") @@ -760,7 +754,6 @@ def test_argparse_errors_well_formatted( == str(err) ) - @pytest.mark.parametrize("caplog_text", [logging.DEBUG], indirect=True) @pytest.mark.parametrize( "cli_args,is_tty,should_warn", ( @@ -776,6 +769,7 @@ def test_argparse_errors_well_formatted( (["pro", "security-status", "--format", "json"], False, False), ), ) + @mock.patch("uaclient.cli.event.info") @mock.patch("uaclient.cli.action_status") @mock.patch("uaclient.cli.action_security_status") @mock.patch("uaclient.cli.setup_logging") @@ -786,13 +780,12 @@ def test_status_human_readable_warning( _m_setup_logging, _m_action_security_status, _m_action_status, - caplog_text, + m_event_info, cli_args, is_tty, should_warn, FakeConfig, ): - check_text = "WARNING: this output is intended to be human readable" m_tty.return_value = is_tty with mock.patch("sys.argv", cli_args): with mock.patch( @@ -801,11 +794,17 @@ def test_status_human_readable_warning( ): main() - logs = caplog_text() if should_warn: - assert check_text in logs + assert [ + mock.call( + messages.WARNING_HUMAN_READABLE_OUTPUT.format( + command=cli_args[1] + ), + file_type=mock.ANY, + ) + ] == m_event_info.call_args_list else: - assert check_text not in logs + assert [] == m_event_info.call_args_list class TestSetupLogging: @@ -872,13 +871,13 @@ def test_get_valid_entitlements(self, _m_valid_services, FakeConfig): # the reference for the fixture to test it. class TestWarnAboutNewVersion: @pytest.mark.parametrize("new_version", (None, "1.2.3")) - @pytest.mark.parametrize("caplog_text", [logging.WARNING], indirect=True) + @mock.patch("uaclient.cli.event.info") @mock.patch("uaclient.cli.version.check_for_new_version") def test_warn_about_new_version( self, m_check_version, + m_event_info, new_version, - caplog_text, _warn_about_new_version, ): m_check_version.return_value = new_version @@ -886,24 +885,33 @@ def test_warn_about_new_version( _warn_about_new_version() if new_version: - assert re.search(expected_notice, caplog_text()) + assert [ + mock.call( + messages.WARN_NEW_VERSION_AVAILABLE_CLI.format( + version=new_version + ), + file_type=mock.ANY, + ) + ] == m_event_info.call_args_list else: - assert not re.search(expected_notice, caplog_text()) + assert [] == m_event_info.call_args_list @pytest.mark.parametrize("command", ("api", "status")) @pytest.mark.parametrize("out_format", (None, "tabular", "json")) - @pytest.mark.parametrize("caplog_text", [logging.WARNING], indirect=True) + @mock.patch("uaclient.cli.event.info") @mock.patch( "uaclient.cli.version.check_for_new_version", return_value="1.2.3" ) def test_dont_show_for_api_calls( self, - _m_check_version, - caplog_text, + m_check_version, + m_event_info, command, out_format, _warn_about_new_version, ): + m_check_version.return_value = "1" + args = mock.MagicMock() args.command = command args.format = out_format @@ -914,6 +922,13 @@ def test_dont_show_for_api_calls( _warn_about_new_version(args) if command != "api" and out_format != "json": - assert re.search(expected_notice, caplog_text()) + assert [ + mock.call( + messages.WARN_NEW_VERSION_AVAILABLE_CLI.format( + version="1" + ), + file_type=mock.ANY, + ) + ] == m_event_info.call_args_list else: - assert not re.search(expected_notice, caplog_text()) + assert [] == m_event_info.call_args_list diff --git a/uaclient/tests/test_system.py b/uaclient/tests/test_system.py index e6bd1e5e2f..99b9f679e1 100644 --- a/uaclient/tests/test_system.py +++ b/uaclient/tests/test_system.py @@ -1214,9 +1214,12 @@ def test_retry_logs_remaining_retries(self, m_sleep, m_subp, caplog_text): logs = caplog_text() expected_logs = [ - "'Funky apt %d error'. Retrying 3 more times.", - "'Funky apt %d error'. Retrying 2 more times.", - "'Funky apt %d error'. Retrying 1 more times.", + "Invalid command specified 'Funky apt %d error'.", + "Retrying 3 more times.", + "Invalid command specified 'Funky apt %d error'.", + "Retrying 2 more times.", + "Invalid command specified 'Funky apt %d error'.", + "Retrying 1 more times.", ] for log in expected_logs: assert log in logs diff --git a/uaclient/tests/test_upgrade_lts_contract.py b/uaclient/tests/test_upgrade_lts_contract.py index 7ca3dfda77..81fbb68c9e 100644 --- a/uaclient/tests/test_upgrade_lts_contract.py +++ b/uaclient/tests/test_upgrade_lts_contract.py @@ -44,10 +44,12 @@ def test_upgrade_cancel_when_past_version_not_supported( m_subp.return_value = ("", "") expected_msgs = [ - "Starting upgrade-lts-contract.", - "Could not find past release for: groovy", + "Could not find past release for groovy", + ] + expected_logs = [ + "Could not find past release for groovy", + "Check whether to upgrade-lts-contract", ] - expected_logs = ["Check whether to upgrade-lts-contract"] with pytest.raises(SystemExit) as execinfo: process_contract_delta_after_apt_lock(FakeConfig()) @@ -58,7 +60,7 @@ def test_upgrade_cancel_when_past_version_not_supported( out, _err = capsys.readouterr() assert out == "\n".join(expected_msgs) + "\n" debug_logs = caplog_text() - for log in expected_msgs + expected_logs: + for log in expected_logs: assert log in debug_logs @mock.patch("uaclient.upgrade_lts_contract._is_attached") @@ -92,21 +94,16 @@ def test_upgrade_contract_when_apt_lock_is_held( m_process_delta.return_value = True m_sleep.return_value = True - base_msg = "".join( + expected_stdout = "\n".join( [ - "Starting upgrade-lts-contract.", - " Retrying every 10 seconds waiting on released apt lock", + "APT lock is held. Ubuntu Pro configuration will wait until " + "it is released", + "Starting upgrade of Ubuntu Pro service configuration", + "Finished upgrade of Ubuntu Pro service configuration", + "", ] ) - expected_msgs = [ - base_msg, - "upgrade-lts-contract processing contract deltas: {}".format( - "bionic -> focal" - ), - "upgrade-lts-contract succeeded after 3 retries", - ] - with mock.patch( "uaclient.upgrade_lts_contract.UAConfig", return_value=FakeConfig(), @@ -118,7 +115,4 @@ def test_upgrade_contract_when_apt_lock_is_held( assert 4 == m_subp.call_count assert 1 == m_process_delta.call_count out, _err = capsys.readouterr() - assert out == "\n".join(expected_msgs) + "\n" - debug_logs = caplog_text() - for log in expected_msgs + ["Check whether to upgrade-lts-contract"]: - assert log in debug_logs + assert out == expected_stdout diff --git a/uaclient/timer/__init__.py b/uaclient/timer/__init__.py index 3eb78134cd..f1140dd387 100644 --- a/uaclient/timer/__init__.py +++ b/uaclient/timer/__init__.py @@ -10,11 +10,11 @@ def start(): try: system.subp(["systemctl", "start", "ua-timer.timer"], timeout=2.0) except (exceptions.ProcessExecutionError, TimeoutExpired) as e: - LOG.warning(e) + LOG.warning(e, exc_info=e) def stop(): try: system.subp(["systemctl", "stop", "ua-timer.timer"], timeout=2.0) except (exceptions.ProcessExecutionError, TimeoutExpired) as e: - LOG.warning(e) + LOG.warning(e, exc_info=e) diff --git a/uaclient/timer/update_contract_info.py b/uaclient/timer/update_contract_info.py index 7b621edd1f..88555a6f9b 100644 --- a/uaclient/timer/update_contract_info.py +++ b/uaclient/timer/update_contract_info.py @@ -1,6 +1,6 @@ import logging -from uaclient import contract, messages, util +from uaclient import contract, util from uaclient.api.u.pro.status.is_attached.v1 import _is_attached from uaclient.config import UAConfig from uaclient.files import notices @@ -21,9 +21,10 @@ def update_contract_info(cfg: UAConfig) -> bool: Notice.CONTRACT_REFRESH_WARNING, ) except Exception as e: - err_msg = messages.UPDATE_CHECK_CONTRACT_FAILURE.format( - reason=str(e) + LOG.warning( + "Failed to check for change in machine contract. Reason: %s", + str(e), + exc_info=e, ) - LOG.warning(err_msg) return False return True diff --git a/uaclient/upgrade_lts_contract.py b/uaclient/upgrade_lts_contract.py index 420f49ee5e..6434168b5d 100755 --- a/uaclient/upgrade_lts_contract.py +++ b/uaclient/upgrade_lts_contract.py @@ -27,7 +27,7 @@ import sys import time -from uaclient import contract, defaults, system, util +from uaclient import contract, defaults, messages, system, util from uaclient.api.u.pro.status.is_attached.v1 import _is_attached from uaclient.config import UAConfig @@ -53,20 +53,21 @@ def process_contract_delta_after_apt_lock(cfg: UAConfig) -> None: if not _is_attached(cfg).is_attached: LOG.debug("Skipping upgrade-lts-contract. Machine is unattached") return + LOG.debug("Starting upgrade-lts-contract.") out, _err = system.subp(["lsof", "/var/lib/apt/lists/lock"], rcs=[0, 1]) - msg = "Starting upgrade-lts-contract." if out: - msg += " Retrying every 10 seconds waiting on released apt lock" - print(msg) - LOG.debug(msg) + print(messages.RELEASE_UPGRADE_APT_LOCK_HELD_WILL_WAIT) current_release = system.get_release_info().series past_release = current_codename_to_past_codename.get(current_release) if past_release is None: - msg = "Could not find past release for: {}".format(current_release) - print(msg) - LOG.warning(msg) + print(messages.RELEASE_UPGRADE_NO_PAST_RELEASE.format(current_release)) + LOG.warning( + "Could not find past release for %s. Current known releases: %r.", + current_release, + current_codename_to_past_codename, + ) sys.exit(1) past_entitlements = UAConfig( @@ -79,17 +80,19 @@ def process_contract_delta_after_apt_lock(cfg: UAConfig) -> None: retry_count = 0 while out: # Loop until apt hold is released at the end of `do-release-upgrade` + LOG.debug("Detected that apt lock is held. Sleeping 10 seconds.") time.sleep(10) out, _err = system.subp( ["lsof", "/var/lib/apt/lists/lock"], rcs=[0, 1] ) retry_count += 1 - msg = "upgrade-lts-contract processing contract deltas: {} -> {}".format( - past_release, current_release + LOG.debug( + "upgrade-lts-contract processing contract deltas: %s -> %s", + past_release, + current_release, ) - print(msg) - LOG.debug(msg) + print(messages.RELEASE_UPGRADE_STARTING) contract.process_entitlements_delta( cfg=cfg, @@ -98,9 +101,8 @@ def process_contract_delta_after_apt_lock(cfg: UAConfig) -> None: allow_enable=True, series_overrides=False, ) - msg = "upgrade-lts-contract succeeded after {} retries".format(retry_count) - print(msg) - LOG.debug(msg) + LOG.debug("upgrade-lts-contract succeeded after %s retries", retry_count) + print(messages.RELEASE_UPGRADE_SUCCESS) def remove_private_esm_apt_cache(): diff --git a/uaclient/util.py b/uaclient/util.py index 107fe5d8fa..c9d0becc86 100644 --- a/uaclient/util.py +++ b/uaclient/util.py @@ -92,8 +92,9 @@ def decorator(*args, **kwargs): except exception as e: if not sleeps: raise e - retry_msg = " Retrying %d more times." % len(sleeps) - LOG.debug(str(e) + retry_msg) + LOG.debug( + "%s: Retrying %d more times.", str(e), len(sleeps) + ) time.sleep(sleeps.pop(0)) return decorator @@ -119,14 +120,11 @@ def get_dict_deltas( else: deltas[key] = DROPPED_KEY elif value != new_value: - log = ( - "Contract value for '" - + key_path - + "' changed to '" - + str(new_value) - + "'" + LOG.debug( + "Contract value for '%s' changed to '%s'", + key_path, + str(new_value), ) - LOG.debug(log) deltas[key] = new_value for key, value in new_dict.items(): if key not in orig_dict: diff --git a/uaclient/yaml.py b/uaclient/yaml.py index 6c74b4ca11..ea9390d0ee 100644 --- a/uaclient/yaml.py +++ b/uaclient/yaml.py @@ -8,8 +8,8 @@ try: import yaml -except ImportError: - LOG.error(MISSING_YAML_MODULE.msg) +except ImportError as e: + LOG.exception(e) print(MISSING_YAML_MODULE.msg, file=sys.stderr) sys.exit(1) @@ -17,20 +17,22 @@ def safe_load(stream): try: return yaml.safe_load(stream) - except AttributeError: - msg = BROKEN_YAML_MODULE.format(path=yaml.__path__).msg - LOG.error(msg) - print(msg, file=sys.stderr) + except AttributeError as e: + LOG.exception(e) + print( + BROKEN_YAML_MODULE.format(path=yaml.__path__).msg, file=sys.stderr + ) sys.exit(1) def safe_dump(data, stream=None, **kwargs): try: return yaml.safe_dump(data, stream, **kwargs) - except AttributeError: - msg = BROKEN_YAML_MODULE.format(path=yaml.__path__).msg - LOG.error(msg) - print(msg, file=sys.stderr) + except AttributeError as e: + LOG.exception(e) + print( + BROKEN_YAML_MODULE.format(path=yaml.__path__).msg, file=sys.stderr + ) sys.exit(1)