Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logs more VM state info in updater #523

Merged
merged 3 commits into from
Apr 10, 2020
Merged

Logs more VM state info in updater #523

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f3ff069
Logs stderr in VM start/stop updater actions
Apr 1, 2020
f8a3b86
Logs running VMs before qvm-start
Apr 2, 2020
6836eb5
Fixes the tests for the updated check_output usage
kushaldas Apr 6, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 12 additions & 3 deletions launcher/sdw_updater_gui/Updater.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -430,10 +430,11 @@ def shutdown_and_start_vms():
sdlog.info("Killing system fedora-based VMs for updates")
for vm in sys_vms_in_order:
try:
subprocess.check_call(["qvm-kill", vm])
subprocess.check_output(["qvm-kill", vm], stderr=subprocess.PIPE)
except subprocess.CalledProcessError as e:
sdlog.error("Error while killing {}".format(vm))
sdlog.error(str(e))
sdlog.error(str(e.stderr))

sdlog.info("Starting system fedora-based VMs after updates")
for vm in reversed(sys_vms_in_order):
Expand All @@ -446,19 +447,27 @@ def shutdown_and_start_vms():

def _safely_shutdown_vm(vm):
try:
subprocess.check_call(["qvm-shutdown", "--wait", vm])
subprocess.check_output(["qvm-shutdown", "--wait", vm], stderr=subprocess.PIPE)
except subprocess.CalledProcessError as e:
sdlog.error("Failed to shut down {}".format(vm))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would adding a log line about information about running VMs here make sense as well? This would help debug situations where a VM can't shutdown due to a VM depending on it being still powered on. In the current workstation case, no VM will be a netVM, but it can be a receiver of qubes-rpc calls, which will cause it to power on again

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point, would rather have the logs than not. Will add momentarily!

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Neglected to add more logging info as suggested. Merging now so devs get the more verbose logs pronto, will continue to look for opportunities to expand logging in follow-ups.

sdlog.error(str(e))
sdlog.error(str(e.stderr))
return UpdateStatus.UPDATES_FAILED


def _safely_start_vm(vm):
try:
subprocess.check_call(["qvm-start", "--skip-if-running", vm])
running_vms = subprocess.check_output(
["qvm-ls", "--running", "--raw-list"], stderr=subprocess.PIPE
)
sdlog.info("VMs running before start of {}: {}".format(vm, running_vms))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will produce logs like:

2020-04-06 15:12:53,712 - sdw_updater_gui.Updater:463(_safely_start_vm) INFO: VMs running before start of sd-app: b'dom0\nsd-gpg\nsd-log\nsd-proxy\nsd-whonix\nsys-firewall\nsys-net\nsys-usb\nsys-whonix\nwork\n'

I would recommend converting the list of VMs to a comma-separated list for readability.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done. New format looks like:

2020-04-06 16:13:37,826 - sdw_updater_gui.Updater:463(_safely_start_vm) INFO: VMs running before start of sd-app: ['dom0', 'fpf-infra', 'fpf-vault', 'fpf-vpn', 'fpf-web', 'sd-dev', 'sd-devices', 'sd-gpg', 'sd-kernel-builder', 'sd-log', 'sd-proxy', 'sd-whonix', 'sys-firewall', 'sys-firewall-inner', 'sys-net', 'sys-usb', 'sys-whonix']

subprocess.check_output(
["qvm-start", "--skip-if-running", vm], stderr=subprocess.PIPE
)
except subprocess.CalledProcessError as e:
sdlog.error("Error while starting {}".format(vm))
sdlog.error(str(e))
sdlog.error(str(e.stderr))


def should_launch_updater(interval):
Expand Down
104 changes: 69 additions & 35 deletions launcher/tests/test_updater.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -98,11 +98,12 @@ def test_check_updates_dom0_needs_updates(
assert not mocked_info.called


@mock.patch("subprocess.check_output", return_value="0")
@mock.patch("subprocess.check_call", return_value=0)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_check_debian_updates_up_to_date(
mocked_info, mocked_error, mocked_call, capsys
mocked_info, mocked_error, mocked_call, mocked_output, capsys
):
status = updater._check_updates_debian("sd-app")
assert status == UpdateStatus.UPDATES_OK
Expand All @@ -114,14 +115,17 @@ def test_check_debian_updates_up_to_date(
assert not mocked_error.called


@mock.patch(
"subprocess.check_output", side_effect=["0", "0"],
)
@mock.patch(
"subprocess.check_call",
side_effect=[subprocess.CalledProcessError(1, "check_call"), "0"],
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_check_updates_debian_updates_required(
mocked_info, mocked_error, mocked_call, capsys
mocked_info, mocked_error, mocked_call, mocked_output, capsys
):
status = updater._check_updates_debian("sd-app")
assert status == UpdateStatus.UPDATES_REQUIRED
Expand All @@ -140,12 +144,18 @@ def test_check_updates_debian_updates_required(
mocked_info.assert_has_calls(info_log)


@mock.patch(
"subprocess.check_output",
side_effect=subprocess.CalledProcessError(1, "check_output",),
)
@mock.patch(
"subprocess.check_call", side_effect=subprocess.CalledProcessError(1, "check_call")
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_check_debian_updates_failed(mocked_info, mocked_error, mocked_call, capsys):
def test_check_debian_updates_failed(
mocked_info, mocked_error, mocked_call, mocked_output, capsys
):
status = updater._check_updates_debian("sd-app")
assert status == UpdateStatus.UPDATES_FAILED
error_log = [
Expand All @@ -156,7 +166,7 @@ def test_check_debian_updates_failed(mocked_info, mocked_error, mocked_call, cap
),
call("Command 'check_call' returned non-zero exit status 1."),
call("Failed to shut down {}".format("sd-app-buster-template")),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
]
info_log = [
call("Checking for updates {}:{}".format("sd-app", "sd-app-buster-template"))
Expand All @@ -165,13 +175,18 @@ def test_check_debian_updates_failed(mocked_info, mocked_error, mocked_call, cap
mocked_info.assert_has_calls(info_log)


@mock.patch(
"subprocess.check_output", side_effect="0",
)
@mock.patch(
"subprocess.check_call",
side_effect=[subprocess.CalledProcessError(1, "check_call"), "0", "0"],
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_check_debian_has_updates(mocked_info, mocked_error, mocked_call, capsys):
def test_check_debian_has_updates(
mocked_info, mocked_error, mocked_call, mocked_output, capsys
):
error_log = [
call(
"Updates required for {} or cannot check for updates".format(
Expand Down Expand Up @@ -199,11 +214,12 @@ def test_check_updates_fedora_calls_fedora(mocked_info, mocked_error):


@pytest.mark.parametrize("vm", current_templates.keys())
@mock.patch("subprocess.check_output")
@mock.patch("subprocess.check_call")
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_check_updates_calls_correct_commands(
mocked_info, mocked_error, mocked_call, vm
mocked_info, mocked_error, mocked_call, mocked_output, vm
):
status = updater.check_updates(vm)
if vm == "fedora":
Expand All @@ -221,16 +237,21 @@ def test_check_updates_calls_correct_commands(
"[[ $(apt list --upgradable | wc -l) -eq 1 ]]",
]
),
call(["qvm-shutdown", "--wait", current_templates[vm]]),
]
check_output_call_list = [
call(["qvm-shutdown", "--wait", current_templates[vm]], stderr=-1),
]
elif vm == "dom0":
subprocess_call_list = [call(["sudo", "qubes-dom0-update", "--check-only"])]
check_output_call_list = []
elif vm == "fedora":
subprocess_call_list = []
check_output_call_list = []
else:
pytest.fail("Unupported VM: {}".format(vm))

mocked_call.assert_has_calls(subprocess_call_list)
mocked_output.assert_has_calls(check_output_call_list)
assert not mocked_error.called


Expand Down Expand Up @@ -443,6 +464,7 @@ def test_write_last_updated_flags_dom0_folder_creation_fail(
mocked_error.assert_has_calls(error_log)


@mock.patch("subprocess.check_output")
@mock.patch("subprocess.check_call")
@mock.patch("Updater._write_updates_status_flag_to_disk")
@mock.patch("Updater._write_last_updated_flags_to_disk")
Expand All @@ -458,6 +480,7 @@ def test_apply_updates_dom0_success(
write_updated,
write_status,
mocked_call,
mocked_output,
):
result = updater._apply_updates_dom0()
assert result == UpdateStatus.REBOOT_REQUIRED
Expand Down Expand Up @@ -580,39 +603,45 @@ def test_overall_update_status_reboot_not_done_previously(


@pytest.mark.parametrize("vm", current_templates.keys())
@mock.patch("subprocess.check_call")
@mock.patch("subprocess.check_output")
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_safely_shutdown(mocked_info, mocked_error, mocked_call, vm):
call_list = [call(["qvm-shutdown", "--wait", "{}".format(vm)])]
def test_safely_shutdown(mocked_info, mocked_error, mocked_output, vm):
call_list = [call(["qvm-shutdown", "--wait", "{}".format(vm)], stderr=-1)]

updater._safely_shutdown_vm(vm)
mocked_call.assert_has_calls(call_list)
mocked_output.assert_has_calls(call_list)
assert not mocked_error.called


@pytest.mark.parametrize("vm", current_templates.keys())
@mock.patch("subprocess.check_call")
@mock.patch(
"subprocess.check_output", side_effect=["0", "0", "0"],
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_safely_start(mocked_info, mocked_error, mocked_call, vm):
call_list = [call(["qvm-start", "--skip-if-running", "{}".format(vm)])]
def test_safely_start(mocked_info, mocked_error, mocked_output, vm):
call_list = [
call(["qvm-ls", "--running", "--raw-list"], stderr=-1),
call(["qvm-start", "--skip-if-running", vm], stderr=-1),
]

updater._safely_start_vm(vm)
mocked_call.assert_has_calls(call_list)
mocked_output.assert_has_calls(call_list)
assert not mocked_error.called


@pytest.mark.parametrize("vm", current_templates.keys())
@mock.patch(
"subprocess.check_call", side_effect=subprocess.CalledProcessError(1, "check_call")
"subprocess.check_output",
side_effect=subprocess.CalledProcessError(1, "check_output"),
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_safely_start_fails(mocked_info, mocked_error, mocked_call, vm):
def test_safely_start_fails(mocked_info, mocked_error, mocked_output, vm):
call_list = [
call("Error while starting {}".format(vm)),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
]

updater._safely_start_vm(vm)
Expand All @@ -621,32 +650,33 @@ def test_safely_start_fails(mocked_info, mocked_error, mocked_call, vm):

@pytest.mark.parametrize("vm", current_templates.keys())
@mock.patch(
"subprocess.check_call", side_effect=subprocess.CalledProcessError(1, "check_call")
"subprocess.check_output",
side_effect=subprocess.CalledProcessError(1, "check_output"),
)
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_safely_shutdown_fails(mocked_info, mocked_error, mocked_call, vm):
call_list = [
call("Failed to shut down {}".format(vm)),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
]

updater._safely_shutdown_vm(vm)
mocked_error.assert_has_calls(call_list)


@mock.patch("subprocess.check_call")
@mock.patch("subprocess.check_output")
@mock.patch("Updater._safely_start_vm")
@mock.patch("Updater._safely_shutdown_vm")
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_shutdown_and_start_vms(
mocked_info, mocked_error, mocked_shutdown, mocked_start, mocked_call
mocked_info, mocked_error, mocked_shutdown, mocked_start, mocked_output
):
sys_vm_kill_calls = [
call(["qvm-kill", "sys-firewall"]),
call(["qvm-kill", "sys-net"]),
call(["qvm-kill", "sys-usb"]),
call(["qvm-kill", "sys-firewall"], stderr=-1),
call(["qvm-kill", "sys-net"], stderr=-1),
call(["qvm-kill", "sys-usb"], stderr=-1),
]
sys_vm_start_calls = [
call("sys-usb"),
Expand All @@ -672,27 +702,28 @@ def test_shutdown_and_start_vms(
call("sd-log"),
]
updater.shutdown_and_start_vms()
mocked_call.assert_has_calls(sys_vm_kill_calls)
mocked_output.assert_has_calls(sys_vm_kill_calls)
mocked_shutdown.assert_has_calls(template_vm_calls + app_vm_calls)
app_vm_calls_reversed = list(reversed(app_vm_calls))
mocked_start.assert_has_calls(sys_vm_start_calls + app_vm_calls_reversed)
assert not mocked_error.called


@mock.patch(
"subprocess.check_call", side_effect=subprocess.CalledProcessError(1, "check_call")
"subprocess.check_output",
side_effect=subprocess.CalledProcessError(1, "check_output"),
)
@mock.patch("Updater._safely_start_vm")
@mock.patch("Updater._safely_shutdown_vm")
@mock.patch("Updater.sdlog.error")
@mock.patch("Updater.sdlog.info")
def test_shutdown_and_start_vms_sysvm_fail(
mocked_info, mocked_error, mocked_shutdown, mocked_start, mocked_call
mocked_info, mocked_error, mocked_shutdown, mocked_start, mocked_output
):
sys_vm_kill_calls = [
call(["qvm-kill", "sys-firewall"]),
call(["qvm-kill", "sys-net"]),
call(["qvm-kill", "sys-usb"]),
call(["qvm-kill", "sys-firewall"], stderr=-1),
call(["qvm-kill", "sys-net"], stderr=-1),
call(["qvm-kill", "sys-usb"], stderr=-1),
]
sys_vm_start_calls = [
call("sys-usb"),
Expand All @@ -719,14 +750,17 @@ def test_shutdown_and_start_vms_sysvm_fail(
]
error_calls = [
call("Error while killing sys-firewall"),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
call("None"),
call("Error while killing sys-net"),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
call("None"),
call("Error while killing sys-usb"),
call("Command 'check_call' returned non-zero exit status 1."),
call("Command 'check_output' returned non-zero exit status 1."),
call("None"),
]
updater.shutdown_and_start_vms()
mocked_call.assert_has_calls(sys_vm_kill_calls)
mocked_output.assert_has_calls(sys_vm_kill_calls)
mocked_shutdown.assert_has_calls(template_vm_calls + app_vm_calls)
app_vm_calls_reversed = list(reversed(app_vm_calls))
mocked_start.assert_has_calls(sys_vm_start_calls + app_vm_calls_reversed)
Expand Down