diff --git a/computes/tests/test_cpu_graph.py b/computes/tests/test_cpu_graph.py index 20edc9ce..f9bf14a2 100644 --- a/computes/tests/test_cpu_graph.py +++ b/computes/tests/test_cpu_graph.py @@ -71,7 +71,7 @@ class GraphTestCase(TestCase): self.assertEqual((data["cpudata"], data["memdata"]["total"]), (None, None)) self.assertNotIn("cpu_sample", data) - def test_a_host_that_cannot_be_connected_to_answers_without_values(self): + def test_a_host_that_cannot_be_connected_to_answers_without_values_or_with_its_error(self): down = ConnectionFailed("192.0.2.1 is down") with patch("computes.views.wvmHostDetails", side_effect=down), patch( "computes.models.wvmHostDetails", side_effect=down @@ -79,7 +79,9 @@ class GraphTestCase(TestCase): self.assertIsNone(self.graph()["cpudata"]) for url in (reverse("machines", args=[self.compute.id, "x86_64"]), reverse("buses", args=[self.compute.id, "x86_64", "q35", "disk"])): - self.assertEqual(json.loads(self.client.get(url).content), {}) + # a list the new VM form waits for: the error, not an empty answer + response = self.client.get(url) + self.assertEqual((response.status_code, json.loads(response.content)), (400, {"error": "192.0.2.1 is down"})) @unittest.skipUnless(shutil.which("node"), "node is not installed") diff --git a/computes/tests/test_views.py b/computes/tests/test_views.py index ca3705b3..1fd37286 100644 --- a/computes/tests/test_views.py +++ b/computes/tests/test_views.py @@ -5,6 +5,7 @@ from django.contrib.auth import get_user_model from django.core.exceptions import ObjectDoesNotExist from django.shortcuts import reverse from django.test import TestCase +from libvirt import libvirtError from vrtManager.connection import CONN_SOCKET, connection_manager from computes.models import Compute @@ -190,6 +191,17 @@ class ComputesTestCase(TestCase): ) self.assertEqual(response.status_code, 200) + def test_a_list_the_host_does_not_give_is_an_error_not_an_empty_list(self): + # the new VM form showed nothing and could not go on; the error was nowhere + for url, method in ((reverse("machines", args=[self.compute.id, "x86_64"]), "get_machine_types"), + (reverse("buses", args=[self.compute.id, "x86_64", "q35", "disk"]), "get_disk_device_types")): + with self.subTest(method), patch("computes.models.wvmHostDetails") as conn, \ + self.assertLogs("computes.views", "WARNING") as logs: + getattr(conn.return_value, method).side_effect = libvirtError("Cannot recv data") + response = self.client.get(url) + self.assertEqual((response.status_code, json.loads(response.content)), (400, {"error": "Cannot recv data"})) + self.assertIn(f"of compute {self.compute.name} failed: Cannot recv data", logs.output[0]) + def test_a_disk_is_offered_the_hosts_disk_buses(self): with patch("computes.models.wvmHostDetails") as conn: conn.return_value.get_disk_device_types.return_value = ["disk", "cdrom", "lun"] diff --git a/computes/views.py b/computes/views.py index 99b15830..d74418c8 100644 --- a/computes/views.py +++ b/computes/views.py @@ -1,9 +1,10 @@ import json +import logging from admin.decorators import superuser_only from django.conf import settings from django.core import signing -from django.http import HttpResponse +from django.http import HttpResponse, JsonResponse from django.shortcuts import get_object_or_404, redirect, render from django.urls import reverse from django.utils import timezone @@ -28,6 +29,8 @@ from computes.models import Compute from . import utils +logger = logging.getLogger(__name__) + # The host CPU graph sends back the CPU sample of its previous answer; usage # is taken since then when it is this recent, otherwise over one second. CPU_SAMPLE_MAX_AGE = 15 @@ -227,7 +230,10 @@ def get_compute_disk_buses(request, compute_id, arch, machine, disk): :return: """ comp_mgr = ComputeManager(compute_id) - return HttpResponse(comp_mgr.get_disk_buses(arch, machine, disk), content_type="application/json") + try: + return HttpResponse(comp_mgr.get_disk_buses(arch, machine, disk), content_type="application/json") + except libvirtError as err: + return read_failed(comp_mgr.compute, "disk buses", err) def get_compute_machine_types(request, compute_id, arch): @@ -238,7 +244,17 @@ def get_compute_machine_types(request, compute_id, arch): :return: """ comp_mgr = ComputeManager(compute_id) - return HttpResponse(comp_mgr.get_machine_types(arch), content_type="application/json") + try: + return HttpResponse(comp_mgr.get_machine_types(arch), content_type="application/json") + except libvirtError as err: + return read_failed(comp_mgr.compute, "machine types", err) + + +def read_failed(compute, what, err): + """A list the new VM form loads that the host did not give: not 200 with + an empty list, which the form cannot tell from none.""" + logger.warning("Reading the %s of compute %s failed: %s", what, compute.name, err) + return JsonResponse({"error": str(err)}, status=400) class ComputeManager: @@ -246,30 +262,21 @@ class ComputeManager: self.compute = get_object_or_404(Compute, pk=compute_id) def get_machine_types(self, arch): - data = dict() - try: - data["machines"] = self.compute.proxy.get_machine_types(arch) - except libvirtError: - pass - - return json.dumps(data) + return json.dumps({"machines": self.compute.proxy.get_machine_types(arch)}) def get_disk_buses(self, arch, machine, disk): data = dict() - try: - disk_device_types = self.compute.proxy.get_disk_device_types(arch, machine) + disk_device_types = self.compute.proxy.get_disk_device_types(arch, machine) - if disk in disk_device_types: - if disk == "disk": - data["bus"] = sorted(self.compute.proxy.get_disk_bus_types(arch, machine)) - elif disk == "cdrom": - data["bus"] = ["ide", "sata", "scsi"] - elif disk == "floppy": - data["bus"] = ["fdc"] - elif disk == "lun": - data["bus"] = ["scsi"] - except libvirtError: - pass + if disk in disk_device_types: + if disk == "disk": + data["bus"] = sorted(self.compute.proxy.get_disk_bus_types(arch, machine)) + elif disk == "cdrom": + data["bus"] = ["ide", "sata", "scsi"] + elif disk == "floppy": + data["bus"] = ["fdc"] + elif disk == "lun": + data["bus"] = ["scsi"] return json.dumps(data) diff --git a/console/novncd b/console/novncd index 779016a6..5bd030b4 100755 --- a/console/novncd +++ b/console/novncd @@ -25,6 +25,7 @@ from websockify import ProxyRequestHandler, WebSocketProxy # noqa: E402 from console.sshtunnels import open_tunnel, tunnel_target # noqa: E402 from console.tokens import ACCESS_CHECK, authorize, may_still_open, session_user_id # noqa: E402 from logs.audit import write # noqa: E402 +from operations.utils import safe_text, traceback_of # noqa: E402 from vrtManager.connection import CONN_SOCKET, CONN_SSH, CONNECT_TIMEOUT # noqa: E402 from vrtManager.util import is_loopback # noqa: E402 from webvirtcloud.settings import WS_HOST, WS_PORT # noqa: E402 @@ -120,7 +121,7 @@ class ConsoleClient: logging.warning("Console connection without a token in its websocket URL") return - user = None + instance = user = None try: instance, user = authorize(token, "vnc") # a token read from a log or a URL is no use without its user's session @@ -133,7 +134,9 @@ class ConsoleClient: write(user.username if user else "", "-", "", f"VNC console refused: {e}", False, address) return except Exception as e: - logging.warning("Console connection failed: %s", e) + # the VM and its user, as the refusal above; a fault of the panel with its traceback, without secrets + logging.warning("Console connection to VM %s for %s failed: %s%s", instance.name if instance else "-", + user.username if user else "-", safe_text(e), traceback_of(e)) return logging.debug( "Console of %s@%s (type %s): %s:%s, socket %s", diff --git a/console/tests/test_novncd.py b/console/tests/test_novncd.py index aaa4806c..778daf89 100644 --- a/console/tests/test_novncd.py +++ b/console/tests/test_novncd.py @@ -17,6 +17,7 @@ from django.core.signing import TimestampSigner from django.conf import settings from django.test import TestCase, override_settings from instances.models import Instance +from libvirt import libvirtError from console.tests.daemons import novncd_mod ROOT = Path(__file__).resolve().parent.parent.parent @@ -63,6 +64,31 @@ class NovncdDaemonLogicTestCase(TestCase): self.assertEqual(opts.host, "192.168.1.100") self.assertEqual(opts.port, 7070) + @patch.object(novncd_mod, "get_connection_infos") + def test_a_console_that_cannot_be_reached_is_logged_with_its_vm_and_user(self, mock_get_info): + mock_get_info.side_effect = libvirtError("Domain not found") + self.authorize.return_value[0].name = "vm-alpha" + handler = self.ConsoleClient() + handler.path = "/novncd/?token=1-uuid" + with self.assertLogs(level="WARNING") as logs: + handler._new_client(socket_factory=MagicMock()) + self.assertEqual(logs.output, ["WARNING:root:Console connection to VM vm-alpha for vnc-user failed: Domain not found"]) + + @patch.object(novncd_mod, "get_connection_infos") + def test_a_fault_of_the_panel_is_logged_with_its_traceback_without_secrets(self, mock_get_info): + try: + raise RuntimeError("password=review-dummy-secret") + except RuntimeError as cause: + mock_get_info.side_effect = OSError("console setup failed") + mock_get_info.side_effect.__cause__ = cause + handler = self.ConsoleClient() + handler.path = "/novncd/?token=1-uuid" + with self.assertLogs(level="WARNING") as logs: + handler._new_client(socket_factory=MagicMock()) + self.assertIn("Traceback", logs.output[0]) + self.assertIn("password=***", logs.output[0]) + self.assertNotIn("review-dummy-secret", logs.output[0]) + @patch.object(novncd_mod, "get_connection_infos") def test_a_cookie_does_not_choose_the_console(self, mock_get_info): # another tab's console in a cookie: the URL's own token is used diff --git a/instances/tests/test_create_page_js.py b/instances/tests/test_create_page_js.py index d15280ba..bed58b32 100644 --- a/instances/tests/test_create_page_js.py +++ b/instances/tests/test_create_page_js.py @@ -45,7 +45,8 @@ const field = sel => fields[sel] ??= new El(); const rows = list => field(list).children; const document = {getElementById: id => templates[id], querySelector: field, querySelectorAll: sel => all[sel] ?? []}; const replies = []; -const $ = Object.assign(() => ({ready: f => f()}), {getJSON: (url, f) => { replies.push(f); return {}; }}); +const $ = Object.assign(() => ({ready: f => f()}), {getJSON: (url, f) => { replies.push(f); return {fail() { return this; }}; }}); +const showLoadError = () => {}; const Option = function (text, value) { return {text, value}; }; // TomSelect: records its added options and items, and calls the page's // callbacks as TomSelect does (a silent addItem still calls onItemAdd) @@ -90,7 +91,7 @@ class CreatePageScriptTests(TestCase): compute, page = self.page() buses_url = html.fromstring(page).get_element_by_id("create-vm-form").get("data-buses-url") out = node(f"const document = {{querySelector: () => ({{dataset: {{busesUrl: {json.dumps(buses_url)}}}}})}};" - "let asked; const $ = {getJSON: url => { asked = url; }};" + "let asked; const $ = {getJSON: url => { asked = url; return {fail() {}}; }}; const showLoadError = null;" + functions("form_data", "load_list", "load_buses") + "load_buses({replaceChildren() {}}, 'cdrom'); console.log(JSON.stringify(asked));") self.assertEqual(out, reverse("buses", args=[compute.id, "i686", "pc", "cdrom"])) @@ -98,14 +99,17 @@ class CreatePageScriptTests(TestCase): @unittest.skipUnless(shutil.which("node"), "node is not installed") def test_a_list_is_empty_while_it_loads_and_a_newer_load_aborts_the_older(self): out = node("const document = {querySelector: () => ({dataset: {busesUrl: '/__disk__/'}})}; const requests = [];" - "const $ = {getJSON: (url, fill) => { const r = {fill, abort() { r.aborted = true; }}; requests.push(r); return r; }};" + "const $ = {getJSON: (url, fill) => { const r = {fill, abort() { r.aborted = true; }, fail(f) { r.failed = f; return r; }}; requests.push(r); return r; }};" + "const showLoadError = () => {};" "const Option = function (text) { this.text = text; };" "const bus = {children: ['ide'], replaceChildren(...items) { this.children = items; }};" + functions("form_data", "load_list", "load_buses") + "load_buses(bus, 'disk'); const loading = bus.children; load_buses(bus, 'cdrom');" "requests[1].fill({bus: ['sata']});" - "console.log(JSON.stringify({loading, aborted: requests.map(r => !!r.aborted), filled: bus.children.map(o => o.text)}));") - self.assertEqual(out, {"loading": [], "aborted": [True, False], "filled": ["sata"]}) + "console.log(JSON.stringify({loading, aborted: requests.map(r => !!r.aborted), filled: bus.children.map(o => o.text)," + " reported: requests.every(r => r.failed === showLoadError)}));") + # a load the host refused says why on the page + self.assertEqual(out, {"loading": [], "aborted": [True, False], "filled": ["sata"], "reported": True}) def test_the_form_has_one_mac_field(self): _, page = self.page() diff --git a/instances/tests/test_create_wizard_url.py b/instances/tests/test_create_wizard_url.py index 4d6b4cb2..31064444 100644 --- a/instances/tests/test_create_wizard_url.py +++ b/instances/tests/test_create_wizard_url.py @@ -53,7 +53,8 @@ class CreateWizardUrlTests(TestCase): js = ("const next = {disabled: false}, select = {dataset: {machinesUrl: '/__arch__/'}, replaceChildren() {}};" "const document = {querySelector: sel => sel === '#next' ? next : select};" "const Option = function () {};" - f"const $ = {{getJSON: (url, f) => f({{machines: {machines!r}}})}};" + f"const $ = {{getJSON: (url, f) => {{ f({{machines: {machines!r}}}); return {{fail() {{}}}}; }}}};" + "const showLoadError = null;" f"{load_machines} load_machines('x86_64'); console.log(next.disabled);") out = subprocess.run(["node", "-e", js], capture_output=True, text=True, timeout=30) with self.subTest(machines=machines): @@ -65,7 +66,8 @@ class CreateWizardUrlTests(TestCase): js = ("const next = {}, select = {dataset: {machinesUrl: '/__arch__/'}, children: ['pc'], replaceChildren(...items) { this.children = items; }};" "const document = {querySelector: sel => sel === '#next' ? next : select};" "const Option = function (text) { this.text = text; }; const requests = [];" - "const $ = {getJSON: (url, fill) => { const r = {fill, abort() { r.aborted = true; }}; requests.push(r); return r; }};" + "const $ = {getJSON: (url, fill) => { const r = {fill, abort() { r.aborted = true; }, fail() { return r; }}; requests.push(r); return r; }};" + "const showLoadError = null;" f"{load_machines} load_machines('x86_64'); const loading = select.children; load_machines('aarch64');" "requests[1].fill({machines: ['virt']});" "console.log(JSON.stringify({loading, aborted: requests.map(r => !!r.aborted), filled: select.children.map(o => o.text)}));") diff --git a/operations/tests/test_worker.py b/operations/tests/test_worker.py index 3595e6a9..e53758e8 100644 --- a/operations/tests/test_worker.py +++ b/operations/tests/test_worker.py @@ -21,7 +21,7 @@ from operations.utils import words from operations import jobs from operations.models import Claim, Operation, WorkerLease from operations.tests import fakes -from operations.worker import Worker, data_dir, host_identity, housekeeping, traceback_of +from operations.worker import Worker, _guarded, data_dir, host_identity, housekeeping, traceback_of from vrtManager.util import ConnectionFailed @@ -396,3 +396,28 @@ class HostIdentityTestCase(SimpleTestCase): with patch("operations.worker.socket.gethostname", return_value="wvc-test-b"): self.assertEqual(host_identity(self.dir), first) + + +class CancelHookLogTests(SimpleTestCase): + def test_a_failed_cancel_names_its_job(self): + # every kind's hook is "cancel": the line alone said nothing of which job + op = Operation(kind="instance.clone", resource_label="c1/vm-alpha", username="alice") + + def cancel(op): + raise ConnectionFailed("Connection Failed: %(host)s did not answer within 5 s", host="192.0.2.10") + with self.assertLogs("operations.worker", "ERROR") as logs: + _guarded(cancel, op) + self.assertEqual(logs.output, [f"ERROR:operations.worker:cancel of job {op.pk} (instance.clone, c1/vm-alpha, " + "by alice) failed: Connection Failed: 192.0.2.10 did not answer within 5 s"]) + + def test_housekeeping_runs_as_a_control_task_and_its_failure_is_logged(self): + # the worker submits it without a job + ran = [] + _guarded(lambda: ran.append(True)) + self.assertEqual(ran, [True]) + + def housekeeping(): + raise RuntimeError("disk full") + with self.assertLogs("operations.worker", "ERROR") as logs: + _guarded(housekeeping) + self.assertTrue(logs.output[0].startswith("ERROR:operations.worker:housekeeping failed: disk full\nTraceback")) diff --git a/operations/worker.py b/operations/worker.py index 05113064..e4757946 100644 --- a/operations/worker.py +++ b/operations/worker.py @@ -332,11 +332,16 @@ def hosts_of(op_ids): return {op_id: frozenset(found) for op_id, found in hosts.items()} -def _guarded(fn, *args): +def _guarded(fn, op=None): + """A control task: housekeeping, or a job's cancel hook, which names its job when it fails.""" try: - fn(*args) + if op is None: + fn() + else: + fn(op) except Exception as err: - logger.error("worker task %s failed: %s", getattr(fn, "__name__", fn), utils.safe_text(err)) + job = f" of job {op.pk} ({op.kind}, {op.resource_label}, by {op.username})" if op is not None else "" + logger.error("%s%s failed: %s%s", getattr(fn, "__name__", fn), job, utils.safe_text(err), traceback_of(err)) finally: close_old_connections() diff --git a/static/js/create_instance.js b/static/js/create_instance.js index ba2276ac..1642ffd3 100644 --- a/static/js/create_instance.js +++ b/static/js/create_instance.js @@ -148,7 +148,7 @@ function volumes_url(pool) { // older one: an answer for the previous choice never fills it. function load_list(list, url, fill) { if (list.request) list.request.abort(); - list.request = $.getJSON(url, fill); + list.request = $.getJSON(url, fill).fail(showLoadError); return list.request; } diff --git a/static/js/create_machine.js b/static/js/create_machine.js index fc5fb18a..f8b85cff 100644 --- a/static/js/create_machine.js +++ b/static/js/create_machine.js @@ -13,7 +13,7 @@ function load_machines(arch) { list.replaceChildren(...data['machines'].map( item => new Option(item, item, false, item === list.dataset.default))); next.disabled = !data['machines'].length; - }); + }).fail(showLoadError); } // placeholders, not "x86_64"/"pc": an architecture such as ppc64 contains "pc" diff --git a/static/js/error_focus.js b/static/js/error_focus.js index 6b0efc5c..37b42839 100644 --- a/static/js/error_focus.js +++ b/static/js/error_focus.js @@ -18,3 +18,16 @@ function focusFirstError() { } window.focusFirstError = focusFirstError; if (document.body.dataset.errorFocus !== "manual") focusFirstError(); + +// A list a page loads (jQuery) that the server could not give: its error goes +// with the page's messages. A load a newer one aborted has none. +function showLoadError(xhr) { + const text = (xhr.responseJSON || {}).error; + if (!text) return; + const alert = document.createElement("div"); + alert.className = "alert alert-danger"; + alert.setAttribute("role", "alert"); + alert.textContent = text; + document.querySelector("#messages").append(alert); +} +window.showLoadError = showLoadError; diff --git a/webvirtcloud/settings.py.template b/webvirtcloud/settings.py.template index f0467bc6..3d6615d1 100644 --- a/webvirtcloud/settings.py.template +++ b/webvirtcloud/settings.py.template @@ -285,6 +285,9 @@ LOGGING = { 'level': 'INFO', 'propagate': True }, + # django-axes writes several lines a login; logins and failed logins + # are on the Logs page, a lock is a warning + 'axes': {'level': 'WARNING'}, 'django.request': { "handlers": ["mail_admins"], "level": "ERROR", diff --git a/webvirtcloud/tests/test_error_focus.py b/webvirtcloud/tests/test_error_focus.py index 307fefe0..1adbb90c 100644 --- a/webvirtcloud/tests/test_error_focus.py +++ b/webvirtcloud/tests/test_error_focus.py @@ -57,3 +57,16 @@ class ErrorFocusTests(unittest.TestCase): invalid = {"sel": ".is-invalid", "offsetParent": {}, "name": "field", "field": True} self.assertEqual(self.focused([invalid], {"errorFocus": "manual"}), {"focused": None, "tabIndex": None}) self.assertEqual(self.focused([invalid], {"errorFocus": "manual"}, call=True), {"focused": "field", "tabIndex": None}) + + @unittest.skipUnless(shutil.which("node"), "node is not installed") + def test_a_list_the_server_could_not_give_says_why_with_the_page_s_messages(self): + script = ("const added = []; const messages = {append: e => added.push(e)};" + "const document = {body: {dataset: {errorFocus: 'manual'}}, querySelector: () => messages," + " createElement: () => ({setAttribute(k, v) { this[k] = v; }})}; const window = globalThis;" + + SCRIPT + + "showLoadError({responseJSON: {error: 'Cannot recv data'}}); showLoadError({status: 0});" + "console.log(JSON.stringify(added.map(e => [e.className, e.role, e.textContent])));") + result = subprocess.run(["node", "-e", script], capture_output=True, text=True, timeout=30) + self.assertEqual(result.returncode, 0, result.stderr) + # an aborted load (no answer) adds nothing + self.assertEqual(json.loads(result.stdout), [["alert alert-danger", "alert", "Cannot recv data"]])