def test_no_duplicate_ua_handlers(self, m_getuid, m_config,
logging_sandbox, tmpdir, FakeConfig):
log_file = tmpdir.join("file.log")
cfg = FakeConfig({"log_file": log_file.strpath})
m_config.return_value = cfg
root_logger = logging.getLogger()
setup_logging(logging.INFO, logging.DEBUG)
stream_handlers = [
h for h in root_logger.handlers
if h.level == logging.INFO and isinstance(h, logging.StreamHandler)
]
file_handlers = [
h for h in root_logger.handlers
if h.level == logging.DEBUG and isinstance(h, logging.FileHandler)
and h.stream.name == log_file
]
assert len(root_logger.handlers) == 2
assert len(stream_handlers) == 1
assert len(file_handlers) == 1
setup_logging(logging.INFO, logging.DEBUG)
stream_handlers = [
h for h in root_logger.handlers
if h.level == logging.INFO and isinstance(h, logging.StreamHandler)
]
file_handlers = [
h for h in root_logger.handlers
if h.level == logging.DEBUG and isinstance(h, logging.FileHandler)
and h.stream.name == log_file
]
assert len(root_logger.handlers) == 2
assert len(stream_handlers) == 1
assert len(file_handlers) == 1
def test_file_log_not_configured_if_not_root(self, m_getuid, tmpdir,
logging_sandbox):
log_file = tmpdir.join("log_file")
setup_logging(logging.INFO, logging.INFO, log_file=log_file.strpath)
logging.info("after setup")
assert not log_file.exists()
def test_console_log_configured_if_not_present(self, level, capsys,
logging_sandbox):
setup_logging(level, logging.INFO)
logging.log(level, "after setup")
logging.log(level - 1, "not present")
_, err = capsys.readouterr()
assert "after setup" in err
assert "not present" not in err
def test_disable_log_to_console_does_nothing_at_debug_level(
self, logging_sandbox, capsys):
cli.setup_logging(logging.DEBUG, logging.DEBUG)
with util.disable_log_to_console():
logging.error("test error")
logging.info("test info")
out, err = capsys.readouterr()
combined_output = out + err
assert "test error" in combined_output
assert "test info" in combined_output
def test_console_log_configured_if_already_present(self, capsys,
logging_sandbox):
logging.getLogger().addHandler(logging.StreamHandler(sys.stderr))
logging.error("before setup")
setup_logging(logging.INFO, logging.INFO)
logging.error("after setup")
# 'before setup' will be in stderr, so check that setup_logging
# configures the format
_, err = capsys.readouterr()
assert "ERROR: before setup" not in err
assert "ERROR: after setup" in err
def test_file_log_configured_if_root(self, m_config, _m_getuid,
log_filename, logging_sandbox,
tmpdir):
if log_filename is None:
log_filename = "default.log"
log_file = tmpdir.join(log_filename)
m_config.CONFIG_DEFAULTS = {"log_file": log_file.strpath}
else:
log_file = tmpdir.join(log_filename)
setup_logging(logging.INFO, logging.INFO, log_file=log_file.strpath)
logging.info("after setup")
assert "after setup" in log_file.read()
def test_custom_logger_configuration(self, m_getuid, m_config,
logging_sandbox, tmpdir, FakeConfig):
log_file = tmpdir.join("file.log")
cfg = FakeConfig({"log_file": log_file.strpath})
m_config.return_value = cfg
custom_logger = logging.getLogger("for-my-special-module")
root_logger = logging.getLogger()
n_root_handlers = len(root_logger.handlers)
setup_logging(logging.INFO, logging.INFO, logger=custom_logger)
assert len(custom_logger.handlers) == 2
assert len(root_logger.handlers) == n_root_handlers
def process_contract_delta_after_apt_lock() -> None:
setup_logging(logging.INFO, logging.DEBUG)
logging.debug("Check whether to upgrade-lts-contract")
if not UAConfig().is_attached:
logging.debug("Skiping upgrade-lts-contract. Machine is unattached")
return
out, _err = 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)
logging.debug(msg)
current_version = parse_os_release()["VERSION_ID"]
current_release = version_to_codename[current_version]
if current_release == "trusty":
msg = "Unable to execute upgrade-lts-contract.py on trusty"
print(msg)
logging.warning(msg)
sys.exit(1)
past_release = current_codename_to_past_codename[current_release]
past_entitlements = UAConfig(series=past_release).entitlements
new_entitlements = UAConfig(series=current_release).entitlements
retry_count = 0
while out:
# Loop until that apt hold is released (at the end of the do-release-upgrade operation
# when a reboot is suggested)
time.sleep(10)
out, _err = 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)
print(msg)
logging.debug(msg)
process_entitlements_delta(
past_entitlements=past_entitlements,
new_entitlements=new_entitlements,
allow_enable=True,
series_overrides=False,
)
msg = "upgrade-lts-contract succeeded after {} retries".format(retry_count)
print(msg)
logging.debug(msg)
def test_file_log_configured_if_already_present(self, m_config, _m_getuid,
logging_sandbox, tmpdir,
FakeConfig):
some_file = log_file = tmpdir.join("default.log")
logging.getLogger().addHandler(logging.FileHandler(some_file.strpath))
log_file = tmpdir.join("file.log")
cfg = FakeConfig({"log_file": log_file.strpath})
m_config.return_value = cfg
logging.error("before setup")
setup_logging(logging.INFO, logging.INFO)
logging.error("after setup")
content = log_file.read()
assert "[ERROR]: before setup" not in content
assert "[ERROR]: after setup" in content
def test_file_log_only_readable_by_root(self, m_config, _m_getuid,
logging_sandbox, tmpdir,
pre_existing):
log_file = tmpdir.join("root-only.log")
log_path = log_file.strpath
if pre_existing:
log_file.write("existing content\n")
assert 0o600 != stat.S_IMODE(os.lstat(log_path).st_mode)
setup_logging(logging.INFO, logging.INFO, log_file=log_path)
logging.info("after setup")
assert 0o600 == stat.S_IMODE(os.lstat(log_path).st_mode)
log_content = log_file.read()
assert "after setup" in log_content
if pre_existing:
assert "existing content" in log_content
def test_file_log_is_world_readable(self, m_config, _m_getuid,
logging_sandbox, tmpdir, pre_existing):
log_file = tmpdir.join("root-only.log")
log_path = log_file.strpath
expected_mode = 0o644
if pre_existing:
expected_mode = 0o640
log_file.write("existing content\n")
os.chmod(log_path, expected_mode)
assert 0o644 != stat.S_IMODE(os.lstat(log_path).st_mode)
setup_logging(logging.INFO, logging.INFO, log_file=log_path)
logging.info("after setup")
assert expected_mode == stat.S_IMODE(os.lstat(log_path).st_mode)
log_content = log_file.read()
assert "after setup" in log_content
if pre_existing:
assert "existing content" in log_content
def test_disable_log_to_console(self, logging_sandbox, capsys,
disable_log):
# This test is parameterised so that we are sure that the context
# manager is suppressing the output, not some other config change
cli.setup_logging(logging.INFO, logging.INFO)
if disable_log:
context_manager = util.disable_log_to_console
else:
context_manager = mock.MagicMock
with context_manager():
logging.error("test error")
logging.info("test info")
out, err = capsys.readouterr()
combined_output = out + err
if disable_log:
assert not combined_output
else:
assert "test error" in combined_output
assert "test info" in combined_output
return # Already have version 0.1 from daily PPA
logging.debug("Patching /var/lib/ubuntu-advantage/status.json schema")
new_status["_schema_version"] = "0.1"
new_status["account"] = {
"name": new_status.pop("account", ""),
"id": new_status.pop("account-id", ""),
}
new_status["contract"] = {
"tech_support_level": new_status.pop("techSupportLevel", "n/a"),
"name": new_status.pop("subscription", ""),
"id": new_status.pop("subscription-id", ""),
}
if "configStatus" in new_status:
new_status["execution_status"] = new_status.pop("configStatus")
if "configStatusDetails" in new_status:
new_status["execution_details"] = new_status.pop("configStatusDetails")
try:
status_content = json.dumps(new_status,
cls=util.DatetimeAwareJSONEncoder)
except ValueError as e:
logging.debug(
"Unable to patch /var/lib/ubuntu-advantage/status.json: {}".format(
str(e)))
util.write_file(status_file, status_content)
if __name__ == "__main__":
setup_logging(logging.INFO, logging.DEBUG)
patch_status_json_schema_0_1(
status_file="/var/lib/ubuntu-advantage/status.json")
continue # Skip job as expected next_run hasn't yet passed
if job.run(cfg):
# Persist last_run and next_run UTC-based times on job success.
jobs_status[job.name] = {
"last_run":
current_time,
"next_run":
current_time +
timedelta(seconds=job.run_interval_seconds(cfg)),
}
cfg.write_cache(key="jobs-status", content=jobs_status)
if __name__ == "__main__":
cfg = UAConfig()
current_time = datetime.now(timezone.utc)
# 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)
run_jobs(cfg=cfg, current_time=current_time)
except Exception as e:
msg = "Failed running commands on reboot."
msg += str(e)
logging.error(msg)
cfg.add_notice("", messages.REBOOT_SCRIPT_FAILED)
def main(cfg):
"""Retry running process_reboot_operations on LockHeldError
:raises: LockHeldError when lock still held by auto-attach after retries.
UserFacingError for all other errors
"""
try:
with lock.SpinLock(
cfg=cfg,
lock_holder="ua-reboot-cmds",
sleep_time=SLEEP_ON_LOCK_HELD,
max_retries=MAX_RETRIES_ON_LOCK_HELD,
):
process_reboot_operations(cfg=cfg)
except exceptions.LockHeldError as e:
logging.warning("Lock not released. %s", str(e.msg))
sys.exit(1)
if __name__ == "__main__":
cfg = config.UAConfig()
setup_logging(logging.INFO, logging.DEBUG, log_file=cfg.log_file)
main(cfg=cfg)
