From 8c0fbff8f753236016929d8530acdb85bd1886b6 Mon Sep 17 00:00:00 2001 From: catborise Date: Fri, 23 Oct 2026 09:46:36 +0300 Subject: [PATCH] feat(logs): admin changes and logins are recorded on the Logs page The Logs page shows who added, changed or deleted a compute, from web or API, and every login, failed login, lockout and logout, with the client address and a Result column (Done, Failed, Unknown for older rows). A failed change is recorded with its reason and the error still reaches the user; a refused one is recorded too. - logs.audit.write saves each row in its own savepoint and never raises, so a log write cannot break or undo the action it records. The audit() context manager writes one row when the change ends. - Logs gains success and ip; user, host and instance are wider and date is indexed. The page orders by date then id. - A compute edit names the changed fields; an edit that changes nothing writes no row, and an empty password field is no change. - A compute's VMs leaving the panel get a system row each: owners kept on the Removed VMs page, moved to another compute, restored, left without owners, or the removed record expired. - Job rows carry the result. A job's log entry that cannot be computed is logged and skipped instead of rolling back the finish (test_service.py changes this on purpose). - Logins are recorded by signal receivers; CustomLoginView is removed and the plain LoginView is used. A wrong OTP code is a failed login, counted by django-axes toward the lockout. Panel records and host-side objects follow in the next layers. --- README.md | 1 + accounts/otp.py | 9 +- accounts/tests/test_otp_login.py | 25 ++++ accounts/urls.py | 3 +- accounts/views.py | 19 +-- admin/templates/admin/logs.html | 4 + admin/tests/test_views.py | 28 ++++ admin/views.py | 6 +- computes/api/viewsets.py | 20 +++ computes/tests/test_audit_rows.py | 69 +++++++++ computes/tests/test_ownership.py | 20 +++ computes/utils.py | 17 ++- computes/views.py | 16 ++- instances/tests/test_missing_fields.py | 1 + instances/tests/test_snapshot_delete_job.py | 1 + logs/apps.py | 32 +++++ logs/audit.py | 104 ++++++++++++++ logs/migrations/0004_audit_fields.py | 48 +++++++ logs/models.py | 14 +- logs/tests/test_audit.py | 146 ++++++++++++++++++++ logs/tests/test_login_rows.py | 51 +++++++ logs/views.py | 4 +- operations/jobs.py | 30 ++-- operations/tests/test_service.py | 26 +++- 24 files changed, 639 insertions(+), 55 deletions(-) create mode 100644 computes/tests/test_audit_rows.py create mode 100644 logs/audit.py create mode 100644 logs/migrations/0004_audit_fields.py create mode 100644 logs/tests/test_audit.py create mode 100644 logs/tests/test_login_rows.py diff --git a/README.md b/README.md index 2deb8abb..8f715f2d 100644 --- a/README.md +++ b/README.md @@ -583,6 +583,7 @@ A version from before v3.0.0 has no worker: `systemctl disable --now webvirt-wor - A disk can be grown while its VM runs or is paused, not only when it is shut off. A disk on an LVM pool cannot be grown (libvirt cannot resize its volumes): the resize says so instead of failing, and the VM's other disks still grow. - Enabling vCPU hot plug keeps the VM's current vCPU count (it enabled all of them up to the maximum). - A host's CPU graph shows the average since its previous point (normally 5 s) instead of a 1 s sample taken while a worker waits. +- The Logs page records who added, changed or deleted a compute, and every login, failed login, lockout and logout, with the address it came from and whether it worked (Result: Done, Failed, Unknown for older rows); a compute's VMs leaving the panel get a row each. Other admin and host changes follow. - The CPU usage in the new-VM dialog is the current load (over 1 s), read when the dialog opens; it was the average since the host booted. - A VM's stats are polled every 5 s like the host graph, the first point as soon as the tab opens; each point is the average since the previous one, disk rates in MB/s (they were MiB/s labelled Mb/s); a counter the host does not report shows a gap instead of 0. - An ISO uploads to an SSH compute about 3.5 times faster (SFTP writes no longer wait for each 32 KiB); a failed write still fails the upload. diff --git a/accounts/otp.py b/accounts/otp.py index 585f2b30..34ae3f35 100644 --- a/accounts/otp.py +++ b/accounts/otp.py @@ -10,6 +10,8 @@ django-otp does not check for confirmed status or ownership-by-type) is ignored. """ +from django.contrib.auth.signals import user_login_failed +from django.core.exceptions import ValidationError from django_otp.forms import OTPAuthenticationForm from django_otp.plugins.otp_totp.models import TOTPDevice @@ -33,4 +35,9 @@ class SingleDeviceOTPForm(OTPAuthenticationForm): def clean_otp(self, user): if user is not None and self._confirmed_totp(user) is None: return # no confirmed device: the password is the only factor - return super().clean_otp(user) + try: + return super().clean_otp(user) + except ValidationError: + # a wrong code is a failed login: counted by django-axes and logged + user_login_failed.send(sender=__name__, credentials={"username": user.get_username()}, request=self.request) + raise diff --git a/accounts/tests/test_otp_login.py b/accounts/tests/test_otp_login.py index c072350b..7ec48bf9 100644 --- a/accounts/tests/test_otp_login.py +++ b/accounts/tests/test_otp_login.py @@ -142,6 +142,31 @@ class OTPLoginHTTPTestCase(TestCase): response = self._post(otp_token=wrong_token(device)) self.assertEqual(response.status_code, 200) + def messages(self): + from logs.models import Logs + return list(Logs.objects.order_by("id").values_list("message", flat=True)) + + def test_a_wrong_otp_code_is_a_failed_login(self): + from axes.models import AccessAttempt + device = TOTPDevice.objects.create(user=self.user, confirmed=True) + self._post(otp_token=wrong_token(device)) + self.assertEqual(self.messages(), ["Login failed"]) + self.assertEqual(AccessAttempt.objects.get(username="bob").failures_since_start, 1) + + def test_wrong_otp_codes_reach_the_lockout(self): + from appsettings.models import AppSettings + AppSettings.objects.filter(key="LOGIN_FAILURE_LIMIT").update(value="3") + device = TOTPDevice.objects.create(user=self.user, confirmed=True) + self._post(otp_token=wrong_token(device)) + self._post(otp_token=wrong_token(device)) + self.assertEqual(self._post(otp_token=wrong_token(device)).status_code, 429) + self.assertEqual(self.messages(), ["Login failed", "Login failed", "Locked out", "Login failed"]) + + def test_a_right_code_logs_in(self): + device = TOTPDevice.objects.create(user=self.user, confirmed=True) + self._post(otp_token=token_for(device)) + self.assertEqual(self.messages(), ["Login"]) + def test_a_signed_in_user_is_sent_on_from_the_login_page(self): from django.urls import reverse self.client.force_login(self.user) diff --git a/accounts/urls.py b/accounts/urls.py index 90801c2e..55024737 100644 --- a/accounts/urls.py +++ b/accounts/urls.py @@ -4,7 +4,6 @@ from django.urls import path from . import views from .otp import SingleDeviceOTPForm -from .views import CustomLoginView app_name = "accounts" @@ -52,5 +51,5 @@ if settings.OTP_ENABLED: ] else: urlpatterns += ( - path("login/", CustomLoginView.as_view(template_name="login.html"), name="login"), + path("login/", LoginView.as_view(template_name="login.html", redirect_authenticated_user=True), name="login"), ) diff --git a/accounts/views.py b/accounts/views.py index c2340a1b..c903f840 100644 --- a/accounts/views.py +++ b/accounts/views.py @@ -4,7 +4,7 @@ import os from admin.decorators import superuser_only from django.conf import settings from django.contrib import messages -from django.contrib.auth import get_user_model, update_session_auth_hash, login as auth_login +from django.contrib.auth import get_user_model, update_session_auth_hash from django.contrib.auth.decorators import login_not_required, login_required from django.contrib.auth.forms import PasswordChangeForm from django.core.exceptions import PermissionDenied @@ -12,7 +12,7 @@ from django.db import transaction from django.shortcuts import get_object_or_404, redirect, render from django.urls import reverse from django.core.cache import cache -from django.http import Http404, HttpResponseRedirect +from django.http import Http404 from django.utils.http import url_has_allowed_host_and_scheme from django.utils.translation import gettext_lazy as _ from django.views.decorators.http import require_POST @@ -25,22 +25,7 @@ from accounts.models import User, UserAttributes, UserInstance, UserSSHKey from . import forms from .utils import get_existing_totp_device, get_user_totp_device, send_email_with_otp -from django.contrib.auth.views import LoginView -from logs.views import addlogmsg -class CustomLoginView(LoginView): - redirect_authenticated_user = True - - def form_valid(self, form): - username = form.cleaned_data['username'] - addlogmsg(username, "-", "-", "Logged In") - auth_login(self.request, form.get_user()) - return HttpResponseRedirect(self.get_success_url()) - - def form_invalid(self, form): - username = form.cleaned_data['username'] - addlogmsg(username, "-", "-", "Failed Login Attempt") - return self.render_to_response(self.get_context_data(form=form)) def profile(request): publickeys = UserSSHKey.objects.filter(user_id=request.user.id) diff --git a/admin/templates/admin/logs.html b/admin/templates/admin/logs.html index 74fc05b2..0252fc4b 100644 --- a/admin/templates/admin/logs.html +++ b/admin/templates/admin/logs.html @@ -33,6 +33,8 @@ {% trans "Host" %} {% trans "Instance" %} {% trans "Message" %} + {% trans "Result" %} + {% trans "IP" %} @@ -44,6 +46,8 @@ {{ log.host }} {{ log.instance }} {{ log.message }} + {% if log.success is None %}{% trans "Unknown" %}{% elif log.success %}{% trans "Done" %}{% else %}{% trans "Failed" %}{% endif %} + {{ log.ip|default:"" }} {% endfor %} diff --git a/admin/tests/test_views.py b/admin/tests/test_views.py index aea83835..6b9c2d75 100644 --- a/admin/tests/test_views.py +++ b/admin/tests/test_views.py @@ -4,11 +4,13 @@ from django.shortcuts import reverse from django.test import RequestFactory, TestCase from accounts.models import UserAttributes +from logs.models import Logs class AdminTestCase(TestCase): def setUp(self): self.client.login(request=RequestFactory().get("/"), username="admin", password="admin") + Logs.objects.all().delete() # the login's row def test_group_list(self): response = self.client.get(reverse("admin:group_list")) @@ -134,3 +136,29 @@ class AdminTestCase(TestCase): def test_logs(self): response = self.client.get(reverse("admin:logs")) self.assertEqual(response.status_code, 200) + + def test_logs_show_result_and_ip(self): + Logs.objects.create(message="first", success=True, ip="192.0.2.7") + Logs.objects.create(message="second", success=False) + Logs.objects.create(message="third") + response = self.client.get(reverse("admin:logs")) + self.assertContains(response, "Done") + self.assertContains(response, "Failed") + self.assertContains(response, "Unknown") + self.assertContains(response, "192.0.2.7") + + def test_logs_order_ties_by_id(self): + first = Logs.objects.create(message="first") + second = Logs.objects.create(message="second") + Logs.objects.filter(id__in=[first.id, second.id]).update(date=first.date) + response = self.client.get(reverse("admin:logs")) + self.assertEqual([log.id for log in response.context["logs"]], [second.id, first.id]) + + def test_logs_bad_page_numbers(self): + Logs.objects.create(message="entry") + response = self.client.get(reverse("admin:logs"), {"page": "abc"}) + self.assertEqual(response.status_code, 200) + self.assertEqual(response.context["logs"].number, 1) + response = self.client.get(reverse("admin:logs"), {"page": "999"}) + self.assertEqual(response.status_code, 200) + self.assertEqual(response.context["logs"].number, response.context["logs"].paginator.num_pages) diff --git a/admin/views.py b/admin/views.py index 44791e29..1424f588 100644 --- a/admin/views.py +++ b/admin/views.py @@ -207,10 +207,8 @@ def user_unblock(request, pk): @superuser_only def logs(request): - l = Logs.objects.order_by("-date") - paginator = Paginator(l, int(app_settings.LOGS_PER_PAGE)) - page = request.GET.get("page", 1) - logs = paginator.page(page) + paginator = Paginator(Logs.objects.order_by("-date", "-id"), int(app_settings.LOGS_PER_PAGE)) + logs = paginator.get_page(request.GET.get("page")) return render(request, "admin/logs.html", {"logs": logs}) diff --git a/computes/api/viewsets.py b/computes/api/viewsets.py index 17bfe165..8b86960d 100644 --- a/computes/api/viewsets.py +++ b/computes/api/viewsets.py @@ -2,6 +2,7 @@ from admin.permissions import IsSuperUser from computes.models import Compute from drf_spectacular.types import OpenApiTypes from drf_spectacular.utils import extend_schema +from logs.audit import audit, changed_fields, snapshot from rest_framework import viewsets from rest_framework.response import Response from vrtManager.create import wvmCreate @@ -19,6 +20,25 @@ class ComputeViewSet(viewsets.ModelViewSet): serializer_class = ComputeSerializer permission_classes = [IsSuperUser] + def perform_create(self, serializer): + data = serializer.validated_data + with audit(self.request, data["name"], f"Compute {data['name']} ({data['hostname']})", "add"): + serializer.save() + + def perform_update(self, serializer): + compute = serializer.instance + subject = f"Compute {compute.name} ({compute.hostname})" + before = snapshot(compute) + with audit(self.request, compute, subject, "change") as entry: + serializer.save() + fields = changed_fields(before, snapshot(compute)) + entry.action = "change " + ", ".join(fields) + entry.skip = not fields + + def perform_destroy(self, instance): + with audit(self.request, instance, f"Compute {instance.name} ({instance.hostname})", "delete"): + instance.delete() + class ComputeArchitecturesView(viewsets.ViewSet): permission_classes = [IsSuperUser] diff --git a/computes/tests/test_audit_rows.py b/computes/tests/test_audit_rows.py new file mode 100644 index 00000000..63501348 --- /dev/null +++ b/computes/tests/test_audit_rows.py @@ -0,0 +1,69 @@ +"""Adding, changing and deleting a compute, on the web and on the API, each write one audit row.""" + +from django.contrib.auth import get_user_model +from django.test import TestCase +from django.urls import reverse +from logs.models import Logs +from operations import claims +from operations.models import Claim +from operations.utils import busy_message + +from computes.models import Compute + + +class ComputeAuditRowTests(TestCase): + def setUp(self): + self.admin = get_user_model().objects.create_superuser("audit-admin", "audit@example.com", "pw") + self.client.force_login(self.admin) + Logs.objects.all().delete() # the login's row + + def messages(self): + return list(Logs.objects.order_by("id").values_list("message", flat=True)) + + def form_data(self, hostname): + return {"name": "c1", "hostname": hostname, "login": "admin", "password": "", "details": "", "type": 1} + + def test_add_change_delete_write_rows(self): + self.client.post(reverse("add_tcp_host"), {**self.form_data("192.0.2.5"), "password": "secret"}) + row = Logs.objects.get() + self.assertEqual( + (row.message, row.success, row.host, row.ip, row.user), + ("Compute c1 (192.0.2.5): add", True, "c1", "127.0.0.1", "audit-admin"), + ) + + compute = Compute.objects.get() + self.client.post(reverse("compute_update", args=[compute.id]), self.form_data("192.0.2.6")) + self.assertEqual(self.messages()[1], "Compute c1 (192.0.2.5): change hostname") + + self.client.post(reverse("compute_delete", args=[compute.id])) + self.assertEqual(self.messages()[2], "Compute c1 (192.0.2.6): delete") + self.assertFalse(Compute.objects.exists()) + + def test_an_edit_that_changes_nothing_writes_nothing(self): + compute = Compute.objects.create(name="c1", hostname="192.0.2.5", login="admin", password="secret", type=1) + self.client.post(reverse("compute_update", args=[compute.id]), self.form_data("192.0.2.5")) + self.assertFalse(Logs.objects.exists()) + + def test_a_busy_delete_writes_a_failed_row(self): + compute = Compute.objects.create(name="c1", hostname="192.0.2.5", login="admin", password="secret", type=1) + busy = claims.Busy(None) + claims.admit({claims.compute_key(compute.id): Claim.SHARED}, holder="192.0.2.30:1:1") + self.client.post(reverse("compute_delete", args=[compute.id])) + row = Logs.objects.get() + self.assertEqual(row.message, f"Compute c1 (192.0.2.5): delete: {busy_message(busy, self.admin)}") + self.assertFalse(row.success) + self.assertTrue(Compute.objects.exists()) + + def test_the_api_writes_the_same_rows(self): + data = {"name": "c1", "hostname": "192.0.2.5", "login": "admin", "password": "secret", "type": 1} + res = self.client.post("/api/v1/computes/", data, content_type="application/json") + self.assertEqual(res.status_code, 201) + pk = res.json()["id"] + res = self.client.patch(f"/api/v1/computes/{pk}/", {"hostname": "192.0.2.6"}, content_type="application/json") + self.assertEqual(res.status_code, 200) + res = self.client.delete(f"/api/v1/computes/{pk}/") + self.assertEqual(res.status_code, 204) + self.assertEqual( + self.messages(), + ["Compute c1 (192.0.2.5): add", "Compute c1 (192.0.2.5): change hostname", "Compute c1 (192.0.2.6): delete"], + ) diff --git a/computes/tests/test_ownership.py b/computes/tests/test_ownership.py index 2d7bc53b..849c0f8a 100644 --- a/computes/tests/test_ownership.py +++ b/computes/tests/test_ownership.py @@ -11,6 +11,7 @@ from django.test import TestCase, override_settings from django.urls import reverse from django.utils import timezone from instances.models import Instance, InstanceTombstone +from logs.models import Logs from operations import claims from operations.models import Claim from rest_framework.test import APIClient @@ -54,6 +55,9 @@ class OwnershipTestCase(TestCase): vm = Instance.objects.get(compute=compute, uuid=UUID) return vm.is_template, [(ui.user, ui.is_change, ui.is_delete, ui.is_vnc) for ui in vm.userinstance_set.all()] + def rows(self): + return list(Logs.objects.order_by("id").values_list("user", "host", "message")) + def test_vm_that_disappears_and_returns_keeps_its_owners(self): self.owned_vm(self.host_a) refresh_instance_database(self.host_a) # undefined for a while @@ -64,6 +68,15 @@ class OwnershipTestCase(TestCase): self.assertEqual(self.ownership(self.host_a), (True, [(self.owner, True, False, True)])) self.assertFalse(InstanceTombstone.objects.exists()) + self.assertEqual(self.rows(), [ + ("-", "host-a", f"VM vm ({UUID}): owners kept on the Removed VMs page"), + ("-", "host-a", f"VM vm ({UUID}): owners restored"), + ]) + + def test_an_ownerless_vm_leaves_a_row(self): + Instance.objects.create(compute=self.host_a, name="vm", uuid=UUID) + refresh_instance_database(self.host_a) + self.assertEqual(self.rows(), [("-", "host-a", f"VM vm ({UUID}): left the panel (no owners)")]) def test_move_seen_on_the_new_host_first(self): self.owned_vm(self.host_a) @@ -75,6 +88,7 @@ class OwnershipTestCase(TestCase): self.assertEqual(self.ownership(self.host_b), (True, [(self.owner, True, False, True)])) self.assertFalse(Instance.objects.filter(compute=self.host_a).exists()) + self.assertEqual(self.rows(), [("-", "host-a", f"VM vm ({UUID}): owners moved to host-b")]) def test_move_seen_on_the_old_host_first(self): self.owned_vm(self.host_a) @@ -105,6 +119,7 @@ class OwnershipTestCase(TestCase): self.assertEqual(self.ownership(self.host_a), (False, [])) self.assertFalse(InstanceTombstone.objects.exists()) + self.assertIn(("-", "-", f"VM vm ({UUID}): removed record expired"), self.rows()) def test_deleted_users_are_skipped(self): self.owned_vm(self.host_a) @@ -128,6 +143,11 @@ class OwnershipTestCase(TestCase): self.owned_vm(self.host_a) self.delete(self.host_a) self.assertEqual(InstanceTombstone.objects.get().owners[0]["user"], self.owner.id) + self.assertEqual(self.rows(), [ + ("cd-admin", "-", "Login"), + ("-", "host-a", f"VM vm ({UUID}): owners kept on the Removed VMs page"), + ("cd-admin", "host-a", "Compute host-a (host-a.example): delete"), + ]) again = self.compute("host-a-again") self.on(again, [("vm", UUID)]) diff --git a/computes/utils.py b/computes/utils.py index eb86d862..76c7638d 100644 --- a/computes/utils.py +++ b/computes/utils.py @@ -9,6 +9,7 @@ from django.db import transaction from django.utils import timezone from computes.models import Compute from instances.models import Instance, InstanceTombstone +from logs.audit import write from operations import claims from operations.models import Claim @@ -45,6 +46,10 @@ def libvirt_instance_lock(instance): yield +def _log(inst, what): + write("-", inst.compute.name, "", f"VM {inst.name} ({inst.uuid}): {what}", True) + + def _move_ownership(source, target): """Give target the owners and template flag of source; a user's rights are merged.""" for ui in UserInstance.objects.filter(instance=source): @@ -70,6 +75,7 @@ def forget(inst): elsewhere = Instance.objects.filter(uuid=inst.uuid).exclude(compute_id=inst.compute_id).first() if elsewhere: _move_ownership(inst, elsewhere) + _log(inst, f"owners moved to {elsewhere.compute.name}") else: _bury(inst) inst.delete() @@ -82,7 +88,9 @@ def _bury(inst): ] if owners or inst.is_template: InstanceTombstone.objects.create(uuid=inst.uuid, name=inst.name, is_template=inst.is_template, owners=owners) - logger.info("Instance %s (%s) disappeared; ownership kept", inst.name, inst.uuid) + _log(inst, "owners kept on the Removed VMs page") + else: + _log(inst, "left the panel (no owners)") def _restore(inst): @@ -103,7 +111,7 @@ def _restore(inst): inst.is_template = True inst.save(update_fields=["is_template"]) InstanceTombstone.objects.filter(uuid=inst.uuid).delete() - logger.info("Instance %s (%s) is back; ownership restored", inst.name, inst.uuid) + _log(inst, "owners restored") def refresh_instance_database(compute): @@ -187,7 +195,10 @@ def refresh_instance_database(compute): # compute is a copy and gets no owners; otherwise a tombstone's # ownership is restored. retention = getattr(settings, "INSTANCE_OWNERSHIP_RETENTION_DAYS", 30) - InstanceTombstone.objects.filter(removed__lt=timezone.now() - timedelta(days=retention)).delete() + expired = InstanceTombstone.objects.filter(removed__lt=timezone.now() - timedelta(days=retention)) + for t in expired: + write("-", "-", "", f"VM {t.name} ({t.uuid}): removed record expired", True) + expired.delete() for uuid, name in host_domains.items(): if uuid not in db_uuids: inst, created = Instance.objects.get_or_create( diff --git a/computes/views.py b/computes/views.py index 7d4b6c87..223cd35c 100644 --- a/computes/views.py +++ b/computes/views.py @@ -10,6 +10,7 @@ from django.utils import timezone from django.utils.translation import gettext_lazy as _ from instances.models import Instance from libvirt import libvirtError +from logs.audit import audit, changed_fields, snapshot from operations import claims from vrtManager.connection import wvmConnect from vrtManager.hostdetails import wvmHostDetails @@ -92,7 +93,9 @@ def instances(request, compute_id): def compute_create(request, FormClass): form = FormClass(request.POST or None) if form.is_valid(): - form.save() + compute = form.instance + with audit(request, compute, f"Compute {compute.name} ({compute.hostname})", "add"): + form.save() return redirect(reverse("computes")) return render(request, "computes/form.html", {"form": form}) @@ -111,9 +114,15 @@ def compute_update(request, compute_id): elif compute.type == 4: FormClass = SocketComputeForm + subject = f"Compute {compute.name} ({compute.hostname})" + before = snapshot(compute) form = FormClass(request.POST or None, instance=compute) if form.is_valid(): - form.save() + with audit(request, compute, subject, "change") as entry: + form.save() + fields = changed_fields(before, snapshot(compute)) + entry.action = "change " + ", ".join(fields) + entry.skip = not fields return redirect(reverse("computes")) return render(request, "computes/form.html", {"form": form}) @@ -123,7 +132,8 @@ def compute_update(request, compute_id): def compute_delete(request, compute_id): compute = get_object_or_404(Compute, pk=compute_id) if request.method == "POST": - compute.delete() + with audit(request, compute, f"Compute {compute.name} ({compute.hostname})", "delete"): + compute.delete() return redirect("computes") return render( diff --git a/instances/tests/test_missing_fields.py b/instances/tests/test_missing_fields.py index d94ad3fd..cb5705b3 100644 --- a/instances/tests/test_missing_fields.py +++ b/instances/tests/test_missing_fields.py @@ -17,6 +17,7 @@ from logs.models import Logs class MissingFieldTestCase(TestCase): def setUp(self): self.client.force_login(get_user_model().objects.create_superuser("mf", "mf@example.com", "pw")) + Logs.objects.all().delete() # the login's row self.compute = Compute.objects.create(name="mf-c", hostname="127.0.0.1", login="", password="", type=4) self.instance = Instance.objects.create( compute=self.compute, name="mf-vm", uuid="11111111-2222-3333-4444-555555555555" diff --git a/instances/tests/test_snapshot_delete_job.py b/instances/tests/test_snapshot_delete_job.py index 90a92d9c..00e19269 100644 --- a/instances/tests/test_snapshot_delete_job.py +++ b/instances/tests/test_snapshot_delete_job.py @@ -39,6 +39,7 @@ class SnapshotDeleteJobTestCase(TransactionTestCase): uuid="11111111-2222-3333-4444-555555555555") self.admin = get_user_model().objects.create_superuser("job_admin", "a@example.com", "pw") self.client.force_login(self.admin) + Logs.objects.all().delete() # the login's row patcher = patch("instances.jobs.wvmInstance", return_value=proxy()) self.wvm = patcher.start() self.addCleanup(patcher.stop) diff --git a/logs/apps.py b/logs/apps.py index 26cf6d68..9f417e3b 100644 --- a/logs/apps.py +++ b/logs/apps.py @@ -1,6 +1,38 @@ from django.apps import AppConfig +def _login_row(request, user, message, success): + from logs.audit import request_ip, write + + write(user, "-", "", message, success, request_ip(request) if request is not None else None) + + +def logged_in(sender, request, user, **kwargs): + _login_row(request, user.get_username(), "Login", True) + + +def login_failed(sender, credentials, request=None, **kwargs): + _login_row(request, credentials.get("username", ""), "Login failed", False) + + +def locked_out(sender, request, username, ip_address, **kwargs): + _login_row(request, username or "", "Locked out", False) + + +def logged_out(sender, request, user, **kwargs): + if user is not None: + _login_row(request, user.get_username(), "Logout", True) + + class LogsConfig(AppConfig): name = "logs" default_auto_field = "django.db.models.AutoField" + + def ready(self): + from axes.signals import user_locked_out + from django.contrib.auth.signals import user_logged_in, user_logged_out, user_login_failed + + user_logged_in.connect(logged_in, dispatch_uid="logs.login") + user_login_failed.connect(login_failed, dispatch_uid="logs.login_failed") + user_locked_out.connect(locked_out, dispatch_uid="logs.locked_out") + user_logged_out.connect(logged_out, dispatch_uid="logs.logout") diff --git a/logs/audit.py b/logs/audit.py new file mode 100644 index 00000000..d000be00 --- /dev/null +++ b/logs/audit.py @@ -0,0 +1,104 @@ +import ipaddress +import logging +from contextlib import contextmanager +from dataclasses import dataclass + +import libvirt +from django.db import transaction + +from accounts.lockout import client_ip +from logs.models import Logs + +logger = logging.getLogger("logs.audit") + + +def write(user, host, instance, message, success=None, ip=None): + """ + Save one Logs row. A failure is written to the log file instead and never + raised, so an audit write cannot break the action it records. + """ + user, host, instance = user[:150], host[:255], instance[:120] + try: + with transaction.atomic(): + Logs.objects.create(user=user, host=host, instance=instance, message=message, success=success, ip=ip) + except Exception as e: + try: + line = f"audit row not saved ({e!r}): {user} {host} {instance} success={success} ip={ip} {message}" + logger.warning(line.replace("\n", "\\n")) + except Exception: + pass + + +def request_ip(request): + """The client address of the request, or None if it is empty or not a plain IP address.""" + value = client_ip(request) + try: + ipaddress.ip_address(value) + except ValueError: + return None + # a scoped IPv6 address (fe80::1%eth0) is valid for ipaddress but not for GenericIPAddressField + return None if "%" in value else value + + +@dataclass +class Entry: + action: str + skip: bool = False + + +def host_of(compute): + """The host column for a Compute, or for a host name already at hand.""" + if compute is None: + return "-" + return compute if isinstance(compute, str) else compute.name + + +def reason(exc, user): + """Why an action failed, as text for the audit row; unknown errors give only their class name.""" + from operations import claims + from operations.utils import busy_message, safe_text + from vrtManager.util import OperationError + + if isinstance(exc, claims.Busy): + return busy_message(exc, user) + if isinstance(exc, OperationError): + return str(exc) + if isinstance(exc, libvirt.libvirtError): + return safe_text(exc.get_error_message() or str(exc))[:500] + return type(exc).__name__ + + +@contextmanager +def audit(request, compute, subject, action, instance=""): + """ + Write one row when the block ends: done, or failed with the reason when it + raises (the exception goes on). The block may set entry.action, or + entry.skip when nothing was done. + """ + entry = Entry(action) + user, host, ip = request.user.get_username(), host_of(compute), request_ip(request) + try: + yield entry + except Exception as exc: + write(user, host, instance, f"{subject}: {entry.action}: {reason(exc, request.user)}", False, ip) + raise + if not entry.skip: + write(user, host, instance, f"{subject}: {entry.action}", True, ip) + + +def failed(request, compute, subject, action, why, instance=""): + """Write the failure row of an action that was refused before it started.""" + write(request.user.get_username(), host_of(compute), instance, f"{subject}: {action}: {why}", False, request_ip(request)) + + +def snapshot(obj): + """The field values of a model object, for changed_fields; a many-to-many field gives its related pks.""" + values = {f.attname: getattr(obj, f.attname) for f in obj._meta.concrete_fields} + for f in obj._meta.many_to_many: + values[f.name] = frozenset(o.pk for o in getattr(obj, f.name).all()) if obj.pk else frozenset() + return values + + +def changed_fields(before, after): + """The sorted names of the fields whose values differ between two snapshots.""" + return sorted(key.removesuffix("_id") for key in before if before[key] != after[key]) diff --git a/logs/migrations/0004_audit_fields.py b/logs/migrations/0004_audit_fields.py new file mode 100644 index 00000000..b01d462e --- /dev/null +++ b/logs/migrations/0004_audit_fields.py @@ -0,0 +1,48 @@ +# Generated by Django 5.2.18 on 2026-10-22 13:01 + +from django.db import migrations, models + + +class Migration(migrations.Migration): + + dependencies = [ + ('logs', '0003_logs_host'), + ] + + operations = [ + migrations.AddField( + model_name='logs', + name='ip', + field=models.GenericIPAddressField(null=True, verbose_name='IP address'), + ), + migrations.AddField( + model_name='logs', + name='success', + field=models.BooleanField(null=True, verbose_name='success'), + ), + migrations.AlterField( + model_name='logs', + name='date', + field=models.DateTimeField(auto_now_add=True, db_index=True, verbose_name='date'), + ), + migrations.AlterField( + model_name='logs', + name='host', + field=models.CharField(default='-', max_length=255, verbose_name='host'), + ), + migrations.AlterField( + model_name='logs', + name='instance', + field=models.CharField(max_length=120, verbose_name='instance'), + ), + migrations.AlterField( + model_name='logs', + name='message', + field=models.TextField(verbose_name='message'), + ), + migrations.AlterField( + model_name='logs', + name='user', + field=models.CharField(max_length=150, verbose_name='user'), + ), + ] diff --git a/logs/models.py b/logs/models.py index bcbb7338..1300bcf1 100644 --- a/logs/models.py +++ b/logs/models.py @@ -1,12 +1,14 @@ -from django.db.models import CharField, DateTimeField, Model +from django.db.models import BooleanField, CharField, DateTimeField, GenericIPAddressField, Model, TextField from django.utils.translation import gettext_lazy as _ class Logs(Model): - user = CharField(_("user"), max_length=50) - host = CharField(_("host"), max_length=50, default="-") - instance = CharField(_("instance"), max_length=50) - message = CharField(_("message"), max_length=255) - date = DateTimeField(_("date"), auto_now=True) + user = CharField(_("user"), max_length=150) + host = CharField(_("host"), max_length=255, default="-") + instance = CharField(_("instance"), max_length=120) + message = TextField(_("message")) + date = DateTimeField(_("date"), auto_now_add=True, db_index=True) + success = BooleanField(_("success"), null=True) + ip = GenericIPAddressField(_("IP address"), null=True) def __str__(self): return self.instance diff --git a/logs/tests/test_audit.py b/logs/tests/test_audit.py new file mode 100644 index 00000000..34735a4c --- /dev/null +++ b/logs/tests/test_audit.py @@ -0,0 +1,146 @@ +from unittest import mock + +import libvirt + +from django.contrib.auth import get_user_model +from django.contrib.auth.models import Group +from django.db import IntegrityError, transaction +from django.test import RequestFactory, TestCase + +from computes.models import Compute +from logs.audit import audit, changed_fields, failed, request_ip, snapshot, write +from logs.models import Logs +from logs.views import addlogmsg +from operations import claims +from vrtManager.util import OperationError + + +class WriteTests(TestCase): + def test_a_row_has_its_fields(self): + write("bob", "host1", "", "Compute c: delete", True, "192.0.2.7") + row = Logs.objects.get() + self.assertEqual((row.user, row.host, row.instance), ("bob", "host1", "")) + self.assertEqual(row.message, "Compute c: delete") + self.assertIs(row.success, True) + self.assertEqual(row.ip, "192.0.2.7") + + def test_long_values_are_cut(self): + write("u" * 200, "h" * 300, "i" * 200, "m" * 5000) + row = Logs.objects.get() + self.assertEqual(len(row.user), 150) + self.assertEqual(len(row.host), 255) + self.assertEqual(len(row.instance), 120) + self.assertEqual(len(row.message), 5000) + + def test_a_failed_write_inside_a_transaction_leaves_it_usable(self): + with self.assertLogs("logs.audit", "WARNING") as logs: + with transaction.atomic(): + with mock.patch.object(Logs.objects, "create", side_effect=IntegrityError): + write("bob", "-", "", "msg") + get_user_model().objects.create_user("after") + self.assertEqual(len(logs.output), 1) + self.assertTrue(get_user_model().objects.filter(username="after").exists()) + + def test_the_file_line_keeps_one_line(self): + with self.assertLogs("logs.audit", "WARNING") as logs: + with mock.patch.object(Logs.objects, "create", side_effect=IntegrityError): + write("bob", "-", "", "a\nb") + self.assertNotIn("\n", logs.records[0].getMessage()) + self.assertIn("a\\nb", logs.records[0].getMessage()) + + def test_a_failing_file_logger_raises_nothing(self): + with mock.patch.object(Logs.objects, "create", side_effect=IntegrityError), mock.patch( + "logs.audit.logger.warning", side_effect=OSError + ): + self.assertIsNone(write("bob", "-", "", "msg")) + + def test_ips(self): + rf = RequestFactory() + self.assertEqual(request_ip(rf.get("/", REMOTE_ADDR="192.0.2.7")), "192.0.2.7") + self.assertIsNone(request_ip(rf.get("/", REMOTE_ADDR="127.0.0.1", HTTP_X_REAL_IP="not-an-ip"))) + self.assertEqual(request_ip(rf.get("/", REMOTE_ADDR="127.0.0.1", HTTP_X_REAL_IP="")), "127.0.0.1") + self.assertIsNone(request_ip(rf.get("/", REMOTE_ADDR="127.0.0.1", HTTP_X_REAL_IP="fe80::1%eth0"))) + self.assertIsNone(request_ip(rf.get("/", REMOTE_ADDR=""))) + + def test_addlogmsg_still_writes(self): + addlogmsg("u", "h", "vm", "Destroy") + row = Logs.objects.get() + self.assertEqual((row.user, row.host, row.instance, row.message), ("u", "h", "vm", "Destroy")) + self.assertIsNone(row.success) + self.assertIsNone(row.ip) + + +class AuditTests(TestCase): + def setUp(self): + self.user = get_user_model().objects.create_user("bob") + self.request = RequestFactory().get("/", REMOTE_ADDR="192.0.2.7") + self.request.user = self.user + self.compute = Compute(name="c", hostname="192.0.2.5", type=1) + + def row(self): + return Logs.objects.get() + + def test_a_block_that_ends_writes_done(self): + with audit(self.request, self.compute, "Compute c (192.0.2.5)", "delete"): + pass + row = self.row() + self.assertEqual(row.message, "Compute c (192.0.2.5): delete") + self.assertIs(row.success, True) + self.assertEqual((row.host, row.user, row.ip), ("c", "bob", "192.0.2.7")) + + def test_a_block_that_raises_writes_failed_and_reraises(self): + error = OperationError("in use") + with self.assertRaises(OperationError) as caught: + with audit(self.request, self.compute, "Compute c", "delete"): + raise error + self.assertIs(caught.exception, error) + row = self.row() + self.assertEqual(row.message, "Compute c: delete: in use") + self.assertIs(row.success, False) + + def reason_row(self, exc): + Logs.objects.all().delete() + with self.assertRaises(type(exc)): + with audit(self.request, None, "Compute c", "delete"): + raise exc + return self.row().message + + def test_reasons(self): + self.assertEqual( + self.reason_row(claims.Busy(None)), + "Compute c: delete: A short operation is in progress on this resource; try again in a moment.", + ) + self.assertNotIn("secret", self.reason_row(libvirt.libvirtError("password=secret"))) + self.assertEqual(self.reason_row(ValueError("")), "Compute c: delete: ValueError") + + def test_the_block_sets_the_action_or_skips(self): + with audit(self.request, self.compute, "Compute c", "edit") as entry: + entry.action = "change hostname" + self.assertEqual(self.row().message, "Compute c: change hostname") + Logs.objects.all().delete() + with audit(self.request, self.compute, "Compute c", "edit") as entry: + entry.skip = True + self.assertFalse(Logs.objects.exists()) + with self.assertRaises(ValueError): + with audit(self.request, self.compute, "Compute c", "edit") as entry: + entry.skip = True + raise ValueError + self.assertEqual(self.row().message, "Compute c: edit: ValueError") + self.assertIs(self.row().success, False) + + def test_failed_writes_a_refusal(self): + failed(self.request, None, "Network lab", "create", "Name in use") + row = self.row() + self.assertEqual(row.message, "Network lab: create: Name in use") + self.assertEqual(row.host, "-") + self.assertIs(row.success, False) + + def test_changed_fields(self): + compute = Compute.objects.create(name="c", hostname="192.0.2.5", type=1, password="pw") + before = snapshot(compute) + self.assertEqual(changed_fields(before, snapshot(compute)), []) + compute.hostname = "192.0.2.6" + self.assertEqual(changed_fields(before, snapshot(compute)), ["hostname"]) + before = snapshot(self.user) + self.user.groups.add(Group.objects.create(name="g")) + self.assertEqual(changed_fields(before, snapshot(self.user)), ["groups"]) diff --git a/logs/tests/test_login_rows.py b/logs/tests/test_login_rows.py new file mode 100644 index 00000000..556af810 --- /dev/null +++ b/logs/tests/test_login_rows.py @@ -0,0 +1,51 @@ +"""Logins, failed logins, lockouts and logouts write rows on the Logs page.""" + +from appsettings.models import AppSettings +from django.contrib.auth import get_user_model +from django.test import TestCase, override_settings +from django.urls import reverse + +from logs.models import Logs + + +def rows(): + return list(Logs.objects.order_by("id").values_list("user", "host", "message", "success", "ip")) + + +@override_settings(OTP_ENABLED=False) +class LoginRowsTests(TestCase): + def setUp(self): + get_user_model().objects.create_user("bob", password="right-pass-1") + AppSettings.objects.filter(key="LOGIN_FAILURE_LIMIT").update(value="3") + + def login(self, password, username="bob"): + return self.client.post(reverse("accounts:login"), {"username": username, "password": password}) + + def test_a_login_and_a_logout_write_rows(self): + self.assertEqual(self.login("right-pass-1").status_code, 302) + self.client.post(reverse("accounts:logout")) + self.assertEqual(rows(), [ + ("bob", "-", "Login", True, "127.0.0.1"), + ("bob", "-", "Logout", True, "127.0.0.1"), + ]) + + def test_a_failed_login_writes_the_typed_username(self): + self.assertEqual(self.login("wrong").status_code, 200) + self.assertEqual(rows(), [("bob", "-", "Login failed", False, "127.0.0.1")]) + + def test_an_empty_username_is_no_attempt(self): + # the form stops it before authentication: no row and no error + self.assertEqual(self.login("wrong", username="").status_code, 200) + self.assertEqual(rows(), []) + + def test_the_attempt_at_the_limit_and_one_while_locked(self): + self.login("wrong") + self.login("wrong") + self.assertEqual(self.login("wrong").status_code, 429) + # django-axes sends the lockout from its own failure receiver, before ours + messages = [r[2] for r in rows()] + self.assertEqual(messages, ["Login failed", "Login failed", "Locked out", "Login failed"]) + + self.assertEqual(self.login("right-pass-1").status_code, 429) + self.assertEqual([r[2] for r in rows()][4:], ["Locked out", "Login failed"]) + self.assertTrue(all(r[0] == "bob" and r[3] is False for r in rows())) diff --git a/logs/views.py b/logs/views.py index 2671cdfe..0e63603d 100644 --- a/logs/views.py +++ b/logs/views.py @@ -4,6 +4,7 @@ from django.http import JsonResponse from admin.decorators import superuser_only from instances.models import Instance +from logs.audit import write from logs.models import Logs @@ -15,8 +16,7 @@ def addlogmsg(user, host, instance, message): :param message: :return: """ - add_log_msg = Logs(user=user, host=host, instance=instance, message=str(message)) - add_log_msg.save() + write(user, host, instance, str(message)) logger = logging.getLogger("") logger.info(f"{user} {host} {instance} {message}") diff --git a/operations/jobs.py b/operations/jobs.py index 9d019f24..1e4462a2 100644 --- a/operations/jobs.py +++ b/operations/jobs.py @@ -14,7 +14,7 @@ from django.db.models import F, Value from django.db.models.functions import Coalesce from django.utils import timezone -from logs.models import Logs +from logs.audit import write from vrtManager.util import OperationError from . import claims, utils @@ -195,8 +195,8 @@ def cancel(op_id, user): if op.state == Operation.QUEUED: Operation.objects.filter(pk=op.pk).update(state=Operation.CANCELLED, finished_at=timezone.now()) Claim.objects.filter(operation=op).delete() - if (entry := get_kind(op.kind).log_entry(op, Operation.CANCELLED)) is not None: - _log(op.username, *entry) + if (entry := _entry(op, Operation.CANCELLED)) is not None: + _log(op.username, *entry, None) elif op.state == Operation.RUNNING: if not get_kind(op.kind).cancellable: raise OperationError("This job cannot be cancelled once it has started") @@ -210,15 +210,22 @@ def cancel(op_id, user): return op -def _log(user, host, instance, message): - Logs.objects.create(user=str(user)[:50], host=str(host)[:50], instance=str(instance)[:50], - message=utils.safe_text(message)[:255]) +def _entry(op, state): + """The kind's log entry; one that cannot be computed is logged and skipped, so it never undoes the job.""" + try: + return get_kind(op.kind).log_entry(op, state) + except Exception: + logging.getLogger("logs.audit").exception("log entry of job %s not computed", op.pk) + return None + + +def _log(user, host, instance, message, success): + write(str(user), str(host), str(instance), utils.safe_text(message), success) def finish(op, outcome, *, worker=None): """Terminal state, claims and history together, once. With a worker, only while it holds the lease and owns the job. Uncertain keeps the claims.""" - kind = get_kind(op.kind) error = utils.safe_text(outcome.error) with fenced(worker.identity) if worker is not None else transaction.atomic(): q = Operation.objects.filter(pk=op.pk, state__in=Operation.ACTIVE) @@ -233,8 +240,8 @@ def finish(op, outcome, *, worker=None): return False if outcome.state != Operation.UNCERTAIN: Claim.objects.filter(operation=op).delete() - if (entry := kind.log_entry(op, outcome.state)) is not None: - _log(op.username, *entry) + if (entry := _entry(op, outcome.state)) is not None: + _log(op.username, *entry, {Operation.SUCCEEDED: True, Operation.FAILED: False}.get(outcome.state)) logger.info("job %s %s: %s", op.pk, op.kind, outcome.state) op.refresh_from_db() return True @@ -256,9 +263,10 @@ def resolve(op_id, user, outcome_state, note): resolution_note=note, resolved_by=user, resolved_at=timezone.now()) Claim.objects.filter(operation=op).delete() # the host and VM columns of the kind's own entries, so the VM's log shows it - entry = get_kind(op.kind).log_entry(op, outcome_state) + entry = _entry(op, outcome_state) host, instance = entry[:2] if entry is not None else ("-", op.resource_label) - _log(user.username, host, instance, f"Job {op.pk} resolved as {outcome_state}: {note}") + _log(user.username, host, instance, f"Job {op.pk} resolved as {outcome_state}: {note}", + outcome_state == Operation.SUCCEEDED) op.refresh_from_db() return op diff --git a/operations/tests/test_service.py b/operations/tests/test_service.py index 00ccb60a..daaa6226 100644 --- a/operations/tests/test_service.py +++ b/operations/tests/test_service.py @@ -90,12 +90,26 @@ class CancelFinishResolveTestCase(TransactionTestCase): self.assertFalse(Claim.objects.exists()) self.assertEqual(list(Logs.objects.values_list("message", flat=True)), ["No-op cancelled"]) - def test_the_log_entry_is_written_inside_the_finishing_transaction(self): + def test_a_failing_log_entry_does_not_undo_the_finish(self): op = jobs.submit("test.noop", self.user, {}, KEY) - with patch.object(fakes.NoopKind, "log_entry", side_effect=RuntimeError("x")), self.assertRaises(RuntimeError): - jobs.finish(op, Outcome(Operation.SUCCEEDED)) - self.assertEqual(Operation.objects.get(pk=op.pk).state, Operation.QUEUED) # rolled back - self.assertTrue(Claim.objects.exists()) + with patch.object(fakes.NoopKind, "log_entry", side_effect=RuntimeError("x")), \ + self.assertLogs("logs.audit", "ERROR"): + self.assertTrue(jobs.finish(op, Outcome(Operation.SUCCEEDED))) + self.assertEqual(Operation.objects.get(pk=op.pk).state, Operation.SUCCEEDED) + self.assertFalse(Claim.objects.exists()) + self.assertFalse(Logs.objects.exists()) + + def test_job_rows_carry_the_result(self): + for key, state, success in (("key-00000002", Operation.SUCCEEDED, True), ("key-00000003", Operation.FAILED, False)): + jobs.finish(jobs.submit("test.noop", self.user, {}, key), Outcome(state)) + self.assertIs(Logs.objects.latest("pk").success, success) + jobs.cancel(jobs.submit("test.noop", self.user, {}, "key-00000004").pk, self.user) + self.assertIsNone(Logs.objects.latest("pk").success) + op = jobs.submit("test.noop", self.user, {}, "key-00000005") + jobs.finish(op, Outcome(Operation.UNCERTAIN)) + self.assertIsNone(Logs.objects.latest("pk").success) + jobs.resolve(op.pk, self.admin, Operation.FAILED, "checked") + self.assertIs(Logs.objects.latest("pk").success, False) def test_cancel_decides_from_the_current_state(self): op = jobs.submit("test.scripted", self.user, {}, KEY) @@ -176,7 +190,7 @@ class CancelFinishResolveTestCase(TransactionTestCase): jobs.finish(op, Outcome(Operation.FAILED, error="qemu+tcp://admin:s3cret@192.0.2.5/system failed")) op.refresh_from_db() self.assertNotIn("s3cret", op.error) - self.assertLessEqual(len(Logs.objects.get().user), 50) + self.assertLessEqual(len(Logs.objects.get().user), 150) def test_an_uncertain_job_keeps_its_claims_until_resolved(self): op = jobs.submit("test.noop", self.user, {}, KEY)