fix(log): stabilize hstore audit snapshots

docker-compose.yml

@@ -18,12 +18,15 @@ services:
       context: .
       args:
           ARG_VERSION: ""
+          POETRY_INSTALL_DEV: "true"
       dockerfile: ./django.Dockerfile
-    command: bash -c "poetry install &&
+    command: bash -c "poetry install --with dev &&
                       poetry run python manage.py compilemessages --ignore \".venv\" &&
                       poetry run python manage.py runserver_plus 0.0.0.0:80"
     volumes:
       - .:/app
+      # Keep container's virtualenv isolated from host .venv so dev deps (pytest) are available
+      - web-venv:/app/.venv
     environment:
       VIRTUAL_HOST: localhost
       DEBUG: 1
@@ -69,7 +72,7 @@ services:
   celery:
     extends:
       service: web
-    command: bash -c "poetry install &&
+    command: bash -c "poetry install --with dev &&
                       poetry run celery -A tapir worker -l info"
     depends_on:
       - redis
@@ -78,7 +81,7 @@ services:
     extends:
       service: web
     # --schedule to avoid polluting the app directory
-    command: bash -c "poetry install &&
+    command: bash -c "poetry install --with dev &&
                       poetry run celery -A tapir beat -l info --schedule /tmp/celerybeat-schedule"
     depends_on:
       - redis
@@ -95,3 +98,4 @@ services:
 
 volumes:
   nginx-certs-volume:
+  web-venv:

pyproject.toml

@@ -40,6 +40,7 @@ dependencies = [
     "slack-sdk (>=3.35.0,<4.0.0)",
     "holidays (>=0.93,<0.94)",
     "drf-spectacular (>=0.29.0,<0.30.0)",
+    "python-ldap (>=3.4.5,<4.0.0)",
 ]
 
 [tool.poetry.group.dev.dependencies]

tapir/accounts/tests/test_update_tapir_user_log_entry.py

@@ -0,0 +1,38 @@
+from tapir.accounts.models import UpdateTapirUserLogEntry
+from tapir.accounts.tests.factories.factories import TapirUserFactory
+from tapir.log.util import freeze_for_log
+from tapir.utils.tests_utils import TapirFactoryTestBase
+
+
+class TestUpdateTapirUserLogEntry(TapirFactoryTestBase):
+    def test_hstore_values_round_trip_as_dict_and_render(self):
+        tapir_user = TapirUserFactory.create()
+
+        UpdateTapirUserLogEntry().populate(
+            actor=tapir_user,
+            tapir_user=tapir_user,
+            old_frozen={"phone_number": "before"},
+            new_frozen={"phone_number": "after"},
+        ).save()
+
+        log_entry = UpdateTapirUserLogEntry.objects.get()
+
+        self.assertIsInstance(log_entry.old_values, dict)
+        self.assertIsInstance(log_entry.new_values, dict)
+        self.assertEqual({"phone_number": "before"}, log_entry.old_values)
+        self.assertEqual({"phone_number": "after"}, log_entry.new_values)
+        self.assertEqual(
+            [("phone_number", "before", "after")],
+            log_entry.get_context_data()["changes"],
+        )
+        self.assertIn(
+            "<strong>phone_number</strong>: before → after",
+            log_entry.render(),
+        )
+
+    def test_freeze_for_log_excludes_password(self):
+        tapir_user = TapirUserFactory.create()
+
+        frozen = freeze_for_log(tapir_user)
+
+        self.assertNotIn("password", frozen)

tapir/log/apps.py

@@ -1,16 +1,60 @@
 from django.apps import AppConfig
+from django.contrib.postgres.signals import get_hstore_oids, register_type_handlers
+from django.core.signals import request_started
+from django.db import connections
+from django.db.backends.base.base import NO_DB_ALIAS
+from django.db.backends.signals import connection_created
 from django.urls import reverse_lazy
 from django.utils.translation import gettext_lazy as _
 
 from tapir.core.config import sidebar_link_groups
 from tapir.settings import PERMISSION_COOP_MANAGE
 
+HSTORE_CONNECTION_MARKER = "_tapir_hstore_registered_connection"
+
+
+def ensure_hstore_type_handlers(connection) -> bool:
+    """Register HStore adapters for the current raw PostgreSQL connection.
+
+    A web process can open its connection before the migration that creates the
+    HStore extension runs in another process. Django then caches the empty OID
+    lookup. Retry the lookup until the extension exists and remember successful
+    registration for the lifetime of the raw connection.
+    """
+    if connection.vendor != "postgresql" or connection.alias == NO_DB_ALIAS:
+        return False
+
+    raw_connection = connection.connection
+    if raw_connection is None:
+        return False
+    if getattr(connection, HSTORE_CONNECTION_MARKER, None) is raw_connection:
+        return True
+
+    get_hstore_oids.cache_clear()
+    oids, _ = get_hstore_oids(connection.alias)
+    if not oids:
+        return False
+
+    register_type_handlers(connection)
+    setattr(connection, HSTORE_CONNECTION_MARKER, raw_connection)
+    return True
+
+
+def ensure_hstore_on_connection_created(sender, connection, **kwargs):
+    ensure_hstore_type_handlers(connection)
+
+
+def ensure_hstore_for_open_connections(**kwargs):
+    for connection in connections.all(initialized_only=True):
+        ensure_hstore_type_handlers(connection)
+
 
 class LogConfig(AppConfig):
     name = "tapir.log"
 
     def ready(self):
         self.register_sidebar_link_groups()
+        self._register_db_signal_handlers()
 
     @staticmethod
     def register_sidebar_link_groups():
@@ -21,3 +65,17 @@ def register_sidebar_link_groups():
             ordering=1,
             required_permissions=[PERMISSION_COOP_MANAGE],
         )
+
+    @staticmethod
+    def _register_db_signal_handlers():
+        connection_created.connect(
+            ensure_hstore_on_connection_created,
+            dispatch_uid="tapir.log.ensure_hstore_on_connection_created",
+            weak=False,
+        )
+        request_started.connect(
+            ensure_hstore_for_open_connections,
+            dispatch_uid="tapir.log.ensure_hstore_for_open_connections",
+            weak=False,
+        )
+        ensure_hstore_for_open_connections()

tapir/log/models.py

@@ -244,9 +244,12 @@ def populate_base(
     ):
         frozen = freeze_for_log(model) if model else frozen
 
-        if hasattr(self, "exclude_fields"):
-            for k in self.exclude_fields:
-                del frozen[k]
+        fields_to_exclude = [
+            *getattr(self, "excluded_fields", ()),
+            *getattr(self, "exclude_fields", ()),
+        ]
+        for k in fields_to_exclude:
+            frozen.pop(k, None)
 
         self.values = frozen
         return super().populate_base(

tapir/log/tests/__init__.py

@@ -0,0 +1 @@
+"""Tests for the audit log application."""

tapir/log/tests/test_apps.py

@@ -0,0 +1,114 @@
+from types import SimpleNamespace
+from unittest.mock import call, patch
+
+from django.db import OperationalError
+from django.db.backends.base.base import NO_DB_ALIAS
+from django.test import SimpleTestCase
+
+from tapir.log.apps import (
+    HSTORE_CONNECTION_MARKER,
+    ensure_hstore_for_open_connections,
+    ensure_hstore_type_handlers,
+)
+
+
+def postgres_connection():
+    return SimpleNamespace(
+        alias="default",
+        connection=object(),
+        vendor="postgresql",
+    )
+
+
+class TestEnsureHstoreTypeHandlers(SimpleTestCase):
+    @patch("tapir.log.apps.register_type_handlers")
+    @patch("tapir.log.apps.get_hstore_oids")
+    def test_ignores_non_postgresql_connections(
+        self, get_hstore_oids, register_type_handlers
+    ):
+        connection = SimpleNamespace(connection=object(), vendor="sqlite")
+
+        self.assertFalse(ensure_hstore_type_handlers(connection))
+
+        get_hstore_oids.cache_clear.assert_not_called()
+        get_hstore_oids.assert_not_called()
+        register_type_handlers.assert_not_called()
+
+    @patch("tapir.log.apps.register_type_handlers")
+    @patch("tapir.log.apps.get_hstore_oids")
+    def test_ignores_django_no_database_connection(
+        self, get_hstore_oids, register_type_handlers
+    ):
+        connection = postgres_connection()
+        connection.alias = NO_DB_ALIAS
+
+        self.assertFalse(ensure_hstore_type_handlers(connection))
+
+        get_hstore_oids.cache_clear.assert_not_called()
+        get_hstore_oids.assert_not_called()
+        register_type_handlers.assert_not_called()
+
+    @patch("tapir.log.apps.register_type_handlers")
+    @patch("tapir.log.apps.get_hstore_oids")
+    def test_retries_after_hstore_extension_becomes_available(
+        self, get_hstore_oids, register_type_handlers
+    ):
+        connection = postgres_connection()
+        get_hstore_oids.side_effect = [((), ()), ((1234,), (1235,))]
+
+        self.assertFalse(ensure_hstore_type_handlers(connection))
+        self.assertTrue(ensure_hstore_type_handlers(connection))
+        self.assertTrue(ensure_hstore_type_handlers(connection))
+
+        self.assertIs(
+            connection.connection,
+            getattr(connection, HSTORE_CONNECTION_MARKER),
+        )
+        self.assertEqual(2, get_hstore_oids.cache_clear.call_count)
+        self.assertEqual(2, get_hstore_oids.call_count)
+        register_type_handlers.assert_called_once_with(connection)
+
+    @patch("tapir.log.apps.register_type_handlers")
+    @patch("tapir.log.apps.get_hstore_oids", return_value=((1234,), (1235,)))
+    def test_registers_again_for_a_reopened_raw_connection(
+        self, get_hstore_oids, register_type_handlers
+    ):
+        connection = postgres_connection()
+
+        self.assertTrue(ensure_hstore_type_handlers(connection))
+        connection.connection = object()
+        self.assertTrue(ensure_hstore_type_handlers(connection))
+
+        self.assertEqual(2, get_hstore_oids.cache_clear.call_count)
+        self.assertEqual(2, get_hstore_oids.call_count)
+        self.assertEqual(
+            [call(connection), call(connection)],
+            register_type_handlers.call_args_list,
+        )
+
+    @patch("tapir.log.apps.register_type_handlers")
+    @patch("tapir.log.apps.get_hstore_oids")
+    def test_does_not_hide_database_errors(
+        self, get_hstore_oids, register_type_handlers
+    ):
+        connection = postgres_connection()
+        get_hstore_oids.side_effect = OperationalError("database unavailable")
+
+        with self.assertRaises(OperationalError):
+            ensure_hstore_type_handlers(connection)
+
+        register_type_handlers.assert_not_called()
+
+    @patch("tapir.log.apps.ensure_hstore_type_handlers")
+    @patch("tapir.log.apps.connections.all")
+    def test_rechecks_all_initialized_connections(self, all_connections, ensure_hstore):
+        connections = [postgres_connection(), postgres_connection()]
+        all_connections.return_value = connections
+
+        ensure_hstore_for_open_connections()
+
+        all_connections.assert_called_once_with(initialized_only=True)
+        self.assertEqual(
+            [call(connections[0]), call(connections[1])],
+            ensure_hstore.call_args_list,
+        )

tapir/log/util.py

@@ -9,7 +9,6 @@ def freeze_for_log(instance) -> dict:
         data[field.name] = field.value_from_object(instance)
     for field in opts.many_to_many:
         data[field.name] = [i.id for i in field.value_from_object(instance)]
-    if hasattr(instance, "excluded_fields"):
-        for field in instance.excluded_fields_for_logs:
-            del data[field]
+    for field in getattr(instance, "excluded_fields_for_logs", ()):
+        data.pop(field, None)
     return data