From 6abea495f1f1124a9704cce4f331acd6edb1adfe Mon Sep 17 00:00:00 2001 From: catborise Date: Fri, 6 Nov 2026 23:14:08 +0300 Subject: [PATCH] fix(logs): failures name their job, VM and user; the new VM form shows a list it could not load - A failed cancel hook logged "worker task cancel failed": it now names the job, its kind, resource and user, with the traceback for a fault of the panel. - novncd logged "Console connection failed" without the VM or the user. - django-axes wrote four INFO lines a login ("Reset 0 access attempts"...); logins are on the Logs page, so it logs warnings only. - The new VM form's machine types and disk buses answered 200 with an empty object when libvirt failed, and nothing was logged: the list stayed empty, the form could not go on and said nothing. They answer 400 with the error, as the pool's volume list does, the warning is logged with the compute, and the form's lists show an error they get with the page's messages. --- computes/tests/test_cpu_graph.py | 6 ++- computes/tests/test_views.py | 12 +++++ computes/views.py | 53 +++++++++++++---------- console/novncd | 7 ++- console/tests/test_novncd.py | 26 +++++++++++ instances/tests/test_create_page_js.py | 14 +++--- instances/tests/test_create_wizard_url.py | 6 ++- operations/tests/test_worker.py | 27 +++++++++++- operations/worker.py | 11 +++-- static/js/create_instance.js | 2 +- static/js/create_machine.js | 2 +- static/js/error_focus.js | 13 ++++++ webvirtcloud/settings.py.template | 3 ++ webvirtcloud/tests/test_error_focus.py | 13 ++++++ 14 files changed, 155 insertions(+), 40 deletions(-) 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"]])