feat(logs): every VM operation writes an audit row the VM's Logs tab finds by UUID

Operations on a VM now write their rows the way the admin audit does: one
row per operation, done or failed with a safe reason, with the user, IP and
host. Each row names the VM ("VM web-1: delete snapshot snap1") and carries
its UUID in the new Logs.instance_uuid column.

- audit_vm and failed_vm wrap audit() and failed() for a VM. A failure the
  view turns into a message is caught outside the block, so its failed row
  is written; busy claims, permission and quota refusals and invalid input
  write nothing. No password, key or XML goes into a row.
- All VM page operations move from addlogmsg to audit_vm, and addlogmsg
  goes. QoS changes and defining a VM from XML are logged now; a gstfsd
  error reply (root password, SSH key) is a failed row, not a done one.
- Partial results are rows of their own: the VM delete, then each disk
  delete; the disk detach, then the volume delete; the migration, then a
  failed autostart restore, NVRAM removal or record on the target.
- Migration rows use the compute name as the host column, as every other
  row does.
- VM job rows (create, clone, snapshots) and their resolutions carry the
  VM's UUID; snapshot job intents now record it. The owner rows of the VM
  page and the accounts pages, and the ownership system rows, carry it too.
- The Logs tab loads vm_logs/<pk>/ and shows the rows with the VM's UUID,
  so a rename keeps the history, two VMs with one name are told apart and
  a VM on two computes is one VM. It gains a Result column. Rows from
  before this change have no UUID and stay on the Logs page only.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

instances/tests/test_audit_rows.py

@@ -33,11 +33,11 @@ class VMOwnerRowTests(TestCase):
         ui = UserInstance.objects.get(user=self.bob)
         self.client.post(reverse("instances:del_owner", args=[self.vm.pk]), {"userinstance": ui.pk})
         self.assertEqual(rows(), [
-            ("VM vm owner bob: add", True),
-            ("VM vm owner carol: add: only one owner is allowed", False),
-            ("VM vm owner bob: remove", True),
+            ("VM vm: add owner bob", True),
+            ("VM vm: add owner carol: only one owner is allowed", False),
+            ("VM vm: remove owner bob", True),
         ])
-        shown = [log["message"] for log in self.client.get(reverse("vm_logs", args=["vm"])).json()]
+        shown = [log["message"] for log in self.client.get(reverse("vm_logs", args=[self.vm.pk])).json()]
         self.assertCountEqual(shown, [m for m, _ in rows()])
 
 

instances/tests/test_create_form_input.py

@@ -289,6 +289,9 @@ class XmlRefusalTests(TestCase):
     def test_a_taken_name(self):
         self.assertIn("already exists", self.post("<domain type='test'><name>test</name></domain>"))
 
+    def test_a_definition_without_a_name(self):
+        self.assertIn("no name", self.post("<domain type='kvm'><memory>1024</memory></domain>"))
+
     def test_malformed_xml(self):
         self.assertIn("not well-formed", self.post("<domain type='test'><name>new</name>"))
 

instances/tests/test_migration_bookkeeping.py

@@ -44,19 +44,19 @@ class MigrationBookkeepingTests(TestCase):
     def test_a_failed_autostart_does_not_stop_the_records(self):
         self.migrate(autostart=True, autostart_error=util.OperationError("no autostart"))
         self.assertEqual(Instance.objects.get(id=self.vm.id).compute, self.dest)
-        self.assertEqual(
-            Logs.objects.get().message,
-            "Instance is migrated(live) to 198.51.100.9; setting its autostart there failed: no autostart",
-        )
+        self.assertEqual(list(Logs.objects.order_by("id").values_list("message", "success")), [
+            ("VM vm: migrate (live) to 198.51.100.9", True),
+            ("VM vm: restore autostart on 198.51.100.9: no autostart", False),
+        ])
 
     def test_a_failed_record_is_logged_as_such(self):
         with patch.object(Instance, "save", side_effect=DatabaseError("locked")), \
              self.assertRaises(DatabaseError):
             self.migrate()
-        self.assertEqual(
-            Logs.objects.get().message,
-            "Instance is migrated(live) to 198.51.100.9, but recording it failed: locked",
-        )
+        self.assertEqual(list(Logs.objects.order_by("id").values_list("message", "success")), [
+            ("VM vm: migrate (live) to 198.51.100.9", True),
+            ("VM vm: record the move to 198.51.100.9: DatabaseError", False),
+        ])
 
     def test_a_record_the_destination_already_has_keeps_template_and_owners(self):
         owner = get_user_model().objects.create_user("mb-owner")

instances/tests/test_migration_log.py

@@ -1,5 +1,6 @@
 """A migration is logged where it runs (migrate_instance, in the job): the
-mode it used on success, the error on failure."""
+mode it used on success, the error on failure, and each later step that
+failed in a row of its own."""
 
 from unittest.mock import MagicMock, patch
 
@@ -14,6 +15,10 @@ from instances.utils import migrate_instance
 from vrtManager import util
 
 
+def rows():
+    return list(Logs.objects.order_by("id").values_list("message", "success"))
+
+
 class MigrationLogTests(TestCase):
     def setUp(self):
         self.admin = get_user_model().objects.create_superuser("ml-admin", "ml@example.com", "pw")
@@ -45,7 +50,7 @@ class MigrationLogTests(TestCase):
         path, destination = self.proxy.remove_nvram.call_args[0]
         self.assertEqual(path, "/var/lib/libvirt/qemu/nvram/vm_VARS.fd")
         self.assertIsNotNone(destination)
-        self.assertEqual(Logs.objects.get().message, "Instance is migrated(live) to 198.51.100.9")
+        self.assertEqual(rows(), [("VM vm: migrate (live) to 198.51.100.9", True)])
 
     def test_a_vm_without_nvram_removes_nothing(self):
         self.migrate("live", live=True)
@@ -54,11 +59,10 @@ class MigrationLogTests(TestCase):
     def test_a_failed_nvram_removal_is_logged_but_the_migration_stands(self):
         self.migrate("live", nvram="/var/lib/libvirt/qemu/nvram/vm_VARS.fd",
                      remove_nvram=libvirtError("cannot delete"), live=True)
-        self.assertEqual(
-            Logs.objects.get().message,
-            "Instance is migrated(live) to 198.51.100.9; removing its NVRAM file "
-            "/var/lib/libvirt/qemu/nvram/vm_VARS.fd on the source failed: cannot delete",
-        )
+        self.assertEqual(rows(), [
+            ("VM vm: migrate (live) to 198.51.100.9", True),
+            ("VM vm: remove NVRAM file /var/lib/libvirt/qemu/nvram/vm_VARS.fd on the source: cannot delete", False),
+        ])
         self.vm.refresh_from_db()
         self.assertEqual(self.vm.compute, self.dest)
 
@@ -67,7 +71,9 @@ class MigrationLogTests(TestCase):
                      remove_nvram=AttributeError("unexpected"), live=True)
         self.vm.refresh_from_db()
         self.assertEqual(self.vm.compute, self.dest)
-        self.assertIn("on the source failed: unexpected", Logs.objects.get().message)
+        # an unknown error gives only its class name
+        self.assertEqual(rows()[-1], ("VM vm: remove NVRAM file /var/lib/libvirt/qemu/nvram/vm_VARS.fd on the source: "
+                                      "AttributeError", False))
 
     def test_a_failed_migration_removes_nothing(self):
         with self.assertRaises(util.OperationError):
@@ -77,23 +83,20 @@ class MigrationLogTests(TestCase):
     def test_success_names_the_mode_used(self):
         self.migrate("non-live, compressed", live=False, compress=True)
         log = Logs.objects.get()
-        self.assertEqual(log.message, "Instance is migrated(non-live, compressed) to 198.51.100.9")
-        self.assertEqual((log.user, log.host, log.instance), ("ml-admin", "198.51.100.8", "vm"))
+        self.assertEqual(log.message, "VM vm: migrate (non-live, compressed) to 198.51.100.9")
+        self.assertEqual((log.user, log.host, log.instance, log.instance_uuid), ("ml-admin", "ml-src", "vm", "u-ml"))
 
     def test_success_names_the_migration_address(self):
         self.dest.migration_address = "203.0.113.9"
         self.migrate("live", live=True)
-        self.assertEqual(Logs.objects.get().message, "Instance is migrated(live) to 198.51.100.9 via 203.0.113.9")
+        self.assertEqual(Logs.objects.get().message, "VM vm: migrate (live) to 198.51.100.9 via 203.0.113.9")
         self.vm.compute = self.source
         self.vm.save()
         self.dest.migration_address = "198.51.100.9"  # the host name itself
         self.migrate("live", live=True)
-        self.assertEqual(Logs.objects.latest("id").message, "Instance is migrated(live) to 198.51.100.9")
+        self.assertEqual(Logs.objects.latest("id").message, "VM vm: migrate (live) to 198.51.100.9")
 
     def test_failure_is_logged_and_raised(self):
         with self.assertRaisesRegex(util.OperationError, "A shut-off VM cannot be migrated live"):
             self.migrate(util.OperationError("A shut-off VM cannot be migrated live"), live=True)
-        self.assertEqual(
-            Logs.objects.get().message,
-            "Instance migration to 198.51.100.9 failed: A shut-off VM cannot be migrated live",
-        )
+        self.assertEqual(rows(), [("VM vm: migrate to 198.51.100.9: A shut-off VM cannot be migrated live", False)])

instances/tests/test_snapshot_delete_job.py

@@ -98,7 +98,8 @@ class SnapshotDeleteJobTestCase(TransactionTestCase):
         self.assertEqual(op.intent["before"]["own"], ["/p/a.one"])
         self.assertEqual(result, {"left_behind": ["/p/a.one"]})
         jobs.finish(op, Outcome(Operation.SUCCEEDED, result=result))
-        self.assertTrue(Logs.objects.filter(message="Delete external snapshot: one").exists())
+        row = Logs.objects.get(message="VM job-vm: delete external snapshot one")
+        self.assertEqual(row.instance_uuid, self.instance.uuid)
 
     def logged(self):
         return list(Logs.objects.values_list("user", "host", "instance", "message"))
@@ -110,17 +111,17 @@ class SnapshotDeleteJobTestCase(TransactionTestCase):
             op = self.submitted()
             jobs.finish(op, Outcome(state, error="x"))
             self.assertEqual(self.logged(), [("job_admin", "job-compute", "job-vm",
-                                              f"Delete external snapshot: one ({state})")])
+                                              f"VM job-vm: delete external snapshot one ({state})")])
         Logs.objects.all().delete()
         Operation.objects.all().delete()
         jobs.cancel(self.submitted().pk, self.admin)
-        self.assertEqual(self.logged(), [("job_admin", "job-compute", "job-vm", "Delete external snapshot: one (cancelled)")])
+        self.assertEqual(self.logged(), [("job_admin", "job-compute", "job-vm", "VM job-vm: delete external snapshot one (cancelled)")])
 
     def test_a_compute_name_with_a_slash_is_logged_whole(self):
         Compute.objects.filter(pk=self.instance.compute_id).update(name="region/job-compute")
         op = self.submitted()
         jobs.finish(op, Outcome(Operation.SUCCEEDED))
-        self.assertEqual(self.logged(), [("job_admin", "region/job-compute", "job-vm", "Delete external snapshot: one")])
+        self.assertEqual(self.logged(), [("job_admin", "region/job-compute", "job-vm", "VM job-vm: delete external snapshot one")])
 
     def test_a_resolved_job_is_logged_on_its_vm(self):
         op = self.submitted()
@@ -129,6 +130,7 @@ class SnapshotDeleteJobTestCase(TransactionTestCase):
         jobs.resolve(op.pk, self.admin, Operation.FAILED, "disks checked")
         self.assertEqual(self.logged(), [("job_admin", "job-compute", "job-vm",
                                           f"Job {op.pk} resolved as failed: disks checked")])
+        self.assertEqual(Logs.objects.get().instance_uuid, self.instance.uuid)
 
     def test_retention_keeps_the_log(self):
         op = self.submitted()
@@ -136,7 +138,7 @@ class SnapshotDeleteJobTestCase(TransactionTestCase):
         Operation.objects.filter(pk=op.pk).update(finished_at=timezone.now() - timedelta(days=400))
         housekeeping()
         self.assertFalse(Operation.objects.filter(pk=op.pk).exists())
-        self.assertEqual([row[3] for row in self.logged()], ["Delete external snapshot: one (failed)"])
+        self.assertEqual([row[3] for row in self.logged()], ["VM job-vm: delete external snapshot one (failed)"])
 
     def test_precheck_refuses_a_moved_vm_and_an_inactive_user(self):
         op = self.submitted()

instances/tests/test_vm_audit_rows.py

@@ -0,0 +1,161 @@
+"""Operations on a VM write one row each: done, or failed with the reason,
+named by the VM and carrying its UUID; refused input writes nothing."""
+
+from unittest.mock import patch
+
+import libvirt
+from computes.models import Compute
+from django.contrib.auth import get_user_model
+from django.test import TestCase
+from django.urls import reverse
+from instances.models import Instance
+from libvirt import libvirtError
+from logs.models import Logs
+from vrtManager.util import OperationError
+
+UUID = "11111111-2222-3333-4444-555555555555"
+
+
+class VMRowTests(TestCase):
+    def setUp(self):
+        self.client.force_login(get_user_model().objects.create_superuser("vm-admin", "vm@example.com", "pw"))
+        self.client.raise_request_exception = False
+        compute = Compute.objects.create(name="c1", hostname="192.0.2.1", login="", password="", type=4)
+        self.vm = Instance.objects.create(compute=compute, name="vm", uuid=UUID)
+        Logs.objects.all().delete()  # the login's row
+        patcher = patch("instances.models.wvmInstance")
+        self.proxy = patcher.start().return_value
+        self.addCleanup(patcher.stop)
+        self.proxy.instance.isActive.return_value = False
+
+    def post(self, view, data=None, args=None):
+        return self.client.post(reverse(f"instances:{view}", args=args or [self.vm.pk]), data or {},
+                                REMOTE_ADDR="192.0.2.50")
+
+    def rows(self):
+        return list(Logs.objects.order_by("id").values_list("message", "success"))
+
+    def test_a_done_row_names_the_vm_and_carries_its_uuid(self):
+        self.post("poweron")
+        row = Logs.objects.get()
+        self.assertEqual((row.message, row.success), ("VM vm: power on", True))
+        self.assertEqual((row.user, row.host, row.instance, row.instance_uuid, row.ip),
+                         ("vm-admin", "c1", "vm", UUID, "192.0.2.50"))
+
+    def test_a_raised_failure_writes_a_failed_row(self):
+        self.proxy.start.side_effect = libvirtError("Requested operation is not valid")
+        self.post("poweron")
+        self.assertEqual(self.rows(), [("VM vm: power on: Requested operation is not valid", False)])
+
+    def test_a_caught_failure_writes_a_failed_row(self):
+        self.proxy.snapshot_delete.side_effect = libvirtError("snapshot not found")
+        self.post("delete_snapshot", {"name": "snap1"})
+        self.proxy.snapshot_delete.side_effect = None
+        self.post("delete_snapshot", {"name": "snap1"})
+        self.assertEqual(self.rows(), [("VM vm: delete snapshot snap1: snapshot not found", False),
+                                       ("VM vm: delete snapshot snap1", True)])
+
+    def test_refused_input_writes_nothing(self):
+        self.post("resizevm_cpu", {"vcpu": "x", "cur_vcpu": "1"})
+        self.post("set_qos", {"qos_direction": "sideways", "net-mac-0": "52:54:00:00:00:01"})
+        Instance.objects.filter(pk=self.vm.pk).update(is_template=True)
+        self.post("poweron")
+        self.assertEqual(self.rows(), [])
+
+    def test_qos_is_logged(self):
+        self.post("set_qos", {"qos_direction": "inbound", "net-mac-0": "52:54:00:00:00:01", "qos_average": "100"})
+        self.post("unset_qos", {"qos_direction": "inbound", "net-mac": "52:54:00:00:00:01"})
+        self.assertEqual(self.rows(), [("VM vm: set inbound QoS on interface 52:54:00:00:00:01", True),
+                                       ("VM vm: remove inbound QoS from interface 52:54:00:00:00:01", True)])
+
+    def test_a_gstfsd_error_reply_is_a_failed_row_without_the_password(self):
+        self.proxy.get_status.return_value = 5
+        with patch("instances.views.gstfsd_request", side_effect=OperationError("gstfsd error: timed out")):
+            self.post("rootpasswd", {"passwd": "S3cret-pass"})
+        with patch("instances.views.gstfsd_request", return_value={"return": "success"}):
+            self.post("rootpasswd", {"passwd": "S3cret-pass"})
+        self.assertEqual(self.rows(), [("VM vm: reset root password: gstfsd error: timed out", False),
+                                       ("VM vm: reset root password", True)])
+
+    def test_console_password_rows_never_hold_the_password(self):
+        self.proxy.get_console_type.return_value = "vnc"
+        self.proxy.console_listens_locally.return_value = True
+        self.proxy.set_console_passwd.return_value = False  # no graphics device
+        form = {"listen_on": "127.0.0.1", "keymap": "auto"}
+        self.post("update_console", {**form, "password": "Vnc-pass-1"})
+        self.proxy.set_console_passwd.return_value = True
+        self.post("update_console", {**form, "password": "Vnc-pass-2"})
+        self.assertNotIn("Vnc-pass", str(self.rows()))
+        rows = [row for row in self.rows() if "password" in row[0]]
+        self.assertEqual(rows, [("VM vm: set console password: The VM has no graphics device", False),
+                                       ("VM vm: set console password", True)])
+
+    def test_a_deleted_vm_and_each_of_its_disks_have_their_own_row(self):
+        self.proxy.split_disk_paths_by_use.return_value = (["/pool/a.qcow2", "/pool/b.qcow2"], [])
+        volume = self.proxy.get_volume_by_path.return_value
+        volume.delete.side_effect = [libvirtError("Permission denied"), None]
+        self.client.post(reverse("instances:destroy", args=[self.vm.pk]), {"delete_disk": "1"})
+        self.assertFalse(Instance.objects.filter(pk=self.vm.pk).exists())
+        self.assertEqual(self.rows(), [("VM vm: delete", True),
+                                       ("VM vm: delete volume /pool/a.qcow2: Permission denied", False),
+                                       ("VM vm: delete volume /pool/b.qcow2", True)])
+        self.assertEqual(set(Logs.objects.values_list("instance_uuid", flat=True)), {UUID})
+
+    def test_a_disk_delete_logs_the_detach_and_the_volume(self):
+        disk = {"dev": "vdb", "path": "/pool/data.qcow2", "storage": "default", "image": "data.qcow2"}
+        self.proxy.get_disk_devices.return_value = [disk]
+        self.proxy.paths_used_by_other_domains.return_value = set()
+        with patch("instances.views.wvmStorage"):
+            self.proxy.wait_disk_detached.return_value = False
+            self.post("delete_vol", {"dev": "vdb"})
+            self.proxy.wait_disk_detached.return_value = True
+            self.post("delete_vol", {"dev": "vdb"})
+        self.assertEqual(self.rows(), [
+            ("VM vm: detach disk vdb", True),
+            ("VM vm: delete volume default/data.qcow2: the guest has not released the disk", False),
+            ("VM vm: detach disk vdb", True),
+            ("VM vm: delete volume default/data.qcow2", True),
+        ])
+
+
+class DefineFromXmlRowTests(TestCase):
+    def post(self, xml):
+        conn = libvirt.open("test:///default")
+        self.addCleanup(conn.close)
+        compute = Compute.objects.create(name="testdrv", hostname="localhost", login="", password="", type=4)
+        self.client.force_login(get_user_model().objects.create_superuser("xml", "xml@example.com", "pw"))
+        Logs.objects.all().delete()
+        with patch("vrtManager.connection.connection_manager.get_connection", return_value=conn):
+            self.client.post(reverse("instances:create_instance_select_type", args=[compute.id]),
+                             {"create_xml": "", "dom_xml": xml})
+        return Logs.objects.get()
+
+    def test_a_defined_vm_has_its_uuid(self):
+        row = self.post("<domain type='test'><name>from-xml</name><memory>1024</memory>"
+                        "<os><type>hvm</type></os></domain>")
+        self.assertEqual((row.message, row.success), ("VM from-xml: define from XML", True))
+        self.assertEqual(row.instance_uuid, Instance.objects.get(name="from-xml").uuid)
+
+    def test_a_refused_definition_is_a_failed_row(self):
+        row = self.post("<domain type='nope'><name>new</name><memory>1024</memory></domain>")
+        self.assertFalse(row.success)
+        self.assertTrue(row.message.startswith("VM new: define from XML: "))
+
+
+class JobRowTests(TestCase):
+    def test_vm_jobs_carry_the_uuid_of_their_vm(self):
+        from operations.jobs import get_kind
+        from operations.models import Operation
+
+        new = {"compute": 1, "uuid": UUID, "name": "web-2"}
+        cases = [
+            ("instance.create", "c1/web-2", {}, new, ("c1", "web-2", UUID, "VM web-2: create")),
+            ("instance.clone", "c1/web-1", {}, new, ("c1", "web-2", UUID, "VM web-2: clone from web-1")),
+            ("snapshot.delete", "c1/web-1", {"name": "s1"}, {"uuid": UUID},
+             ("c1", "web-1", UUID, "VM web-1: delete external snapshot s1 (failed)")),
+        ]
+        for kind, label, params, intent, entry in cases:
+            with self.subTest(kind=kind):
+                op = Operation(kind=kind, resource_label=label, params=params, intent=intent)
+                state = Operation.FAILED if kind == "snapshot.delete" else Operation.SUCCEEDED
+                self.assertEqual(get_kind(kind).log_entry(op, state), entry)

instances/tests/test_xss.py

@@ -96,7 +96,7 @@ class JsonEndpointContentTypeTestCase(TestCase):
                     self.assertJson(self.client.get(url))
 
     def test_vm_logs_is_json(self):
-        self.assertJson(self.client.get(reverse("vm_logs", args=[self.instance.name])))
+        self.assertJson(self.client.get(reverse("vm_logs", args=[self.instance.pk])))
 
 
 class TemplateHtmlConcatenationTestCase(TestCase):