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)