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

@@ -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")

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"]

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)
 

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",

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

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()

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)}));")

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"))

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()
 

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;
 }
 

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"

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;

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",

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"]])