feat(logging): create caluma_logging app for access logging

caluma/caluma_logging/apps.py

@@ -0,0 +1,5 @@
+from django.apps import AppConfig
+
+
+class DefaultConfig(AppConfig):
+    name = "caluma.caluma_logging"

caluma/caluma_logging/factories.py

@@ -0,0 +1,18 @@
+from factory import Faker, django
+
+from . import models
+
+
+class AccessLogFactory(django.DjangoModelFactory):
+    timestamp = None
+    username = Faker("user_name")
+    query = ""
+    operation = "query"
+    operation_name = None
+    selection = None
+    variables = None
+    status_code = 200
+    has_error = False
+
+    class Meta:
+        model = models.AccessLog

caluma/caluma_logging/management/commands/cleanup_access_log.py

@@ -0,0 +1,40 @@
+import dateparser
+from django.core.management.base import BaseCommand
+from django.utils import timezone
+
+from caluma.caluma_logging.models import AccessLog
+
+
+class Command(BaseCommand):
+    """Cleanup access log."""
+
+    help = "Cleanup access log."
+
+    def add_arguments(self, parser):
+        parser.add_argument("--force", dest="force", default=False, action="store_true")
+        parser.add_argument(
+            "-k",
+            "--keep",
+            dest="keep",
+            default="2 weeks",
+            help=(
+                "Duration for which to keep the access log, older entries will be removed."
+            ),
+        )
+
+    def handle(self, *args, **options):
+        force = options["force"]
+        keep = options["keep"]
+        lt = dateparser.parse(options["keep"])
+
+        if lt is not None:
+            lt = timezone.make_aware(lt)
+
+        entries = AccessLog.objects.filter(timestamp__lt=lt)
+
+        self.stdout.write(
+            f"Deleting {entries.count()} access log entries older than {keep}."
+        )
+
+        if force:
+            entries.delete()

caluma/caluma_logging/middleware.py

@@ -0,0 +1,59 @@
+import json
+
+from graphql.error.syntax_error import GraphQLSyntaxError
+from graphql.language import parser, visitor
+
+from caluma.caluma_logging.models import AccessLog
+
+
+class AccessLogMiddleware:
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        response = self.get_response(request)
+        # user is available only after the request was processed
+        try:
+            body = json.loads(request.body.decode("utf-8"))
+        except json.decoder.JSONDecodeError:  # pragma: no cover
+            return response
+
+        vis = AccessLogVisitor()
+        try:
+            doc = parser.parse(body["query"])
+            visitor.visit(doc, vis)
+        except GraphQLSyntaxError:
+            pass
+
+        AccessLog.objects.create(
+            username=request.user.username,
+            query=body.get("query"),
+            variables=body.get("variables"),
+            status_code=response.status_code,
+            has_error=response.status_code >= 400,
+            **vis.values,
+        )
+
+        return response
+
+
+class AccessLogVisitor(visitor.Visitor):
+    def __init__(self):
+        self.values = {}
+
+        super().__init__()
+
+    def enter_OperationDefinition(self, node, *args):
+        # either "query" or "mutation"
+        self.values["operation"] = node.operation
+        try:
+            self.values["operation_name"] = node.name.value
+        except AttributeError:
+            pass
+
+    def enter_SelectionSet(self, node, *args):
+        # grab name of the query, eg. "allCases", which is the first "selection"
+        # thus skip any further selections
+        if self.values.get("selection"):
+            return
+        self.values["selection"] = node.selections[0].name.value

caluma/caluma_logging/migrations/0001_initial.py

@@ -0,0 +1,51 @@
+# Generated by Django 2.2.16 on 2020-09-18 15:59
+
+import django.contrib.postgres.fields.jsonb
+from django.db import migrations, models
+
+
+class Migration(migrations.Migration):
+
+    initial = True
+
+    dependencies = []
+
+    operations = [
+        migrations.CreateModel(
+            name="AccessLog",
+            fields=[
+                (
+                    "id",
+                    models.AutoField(
+                        auto_created=True,
+                        primary_key=True,
+                        serialize=False,
+                        verbose_name="ID",
+                    ),
+                ),
+                ("timestamp", models.DateTimeField(auto_now_add=True)),
+                ("username", models.CharField(blank=True, max_length=100, null=True)),
+                ("query", models.TextField()),
+                (
+                    "variables",
+                    django.contrib.postgres.fields.jsonb.JSONField(
+                        blank=True, null=True
+                    ),
+                ),
+                (
+                    "operation_name",
+                    models.CharField(blank=True, max_length=100, null=True),
+                ),
+                ("status_code", models.PositiveIntegerField()),
+                ("has_error", models.BooleanField(default=False)),
+                (
+                    "operation",
+                    models.CharField(
+                        choices=[("query", "query"), ("mutation", "mutation")],
+                        max_length=20,
+                    ),
+                ),
+                ("selection", models.CharField(blank=True, max_length=100, null=True)),
+            ],
+        )
+    ]

caluma/caluma_logging/models.py

@@ -0,0 +1,16 @@
+from django.contrib.postgres.fields import JSONField
+from django.db import models
+
+
+class AccessLog(models.Model):
+    OPERATIONS = (("query", "query"), ("mutation", "mutation"))
+
+    timestamp = models.DateTimeField(auto_now_add=True)
+    username = models.CharField(max_length=100, blank=True, null=True)
+    query = models.TextField()
+    operation = models.CharField(choices=OPERATIONS, max_length=20)
+    operation_name = models.CharField(max_length=100, blank=True, null=True)
+    selection = models.CharField(max_length=100, blank=True, null=True)
+    variables = JSONField(blank=True, null=True)
+    status_code = models.PositiveIntegerField()
+    has_error = models.BooleanField(default=False)

caluma/caluma_logging/tests/test_command.py

@@ -0,0 +1,39 @@
+from datetime import timedelta
+
+import pytest
+from django.core.management import call_command
+from django.utils import timezone
+
+from caluma.caluma_logging.models import AccessLog
+
+
+@pytest.mark.parametrize("force", [True, False])
+@pytest.mark.parametrize(
+    "keep,exist",
+    [
+        (None, 10),
+        ("2 weeks", 10),
+        ("1 month", 10),
+        ("1 day", 1),
+        ("7 days", 7),
+        ("0 days", 0),
+    ],
+)
+def test_cleanup_access_log(db, access_log_factory, force, keep, exist):
+    for i in range(10):
+        entry = access_log_factory()
+        entry.timestamp = timezone.now() - timedelta(days=i)
+        entry.save()
+
+    kwargs = {"force": force}
+    if keep:
+        kwargs["keep"] = keep
+
+    call_command("cleanup_access_log", **kwargs)
+
+    count = AccessLog.objects.all().count()
+
+    if force:
+        assert count == exist
+    else:
+        count == 10

caluma/caluma_logging/tests/test_logging_middleware.py

@@ -0,0 +1,116 @@
+import pytest
+from django.urls import reverse
+
+from .. import models
+
+
+@pytest.mark.parametrize(
+    "query,variables,operation,operation_name,selection,status_code",
+    [
+        (
+            """
+            query foo {
+              allCases {
+                edges {
+                  node {
+                    id
+            }}}}
+            """,
+            "",
+            "query",
+            "foo",
+            "allCases",
+            200,
+        ),
+        (
+            """
+            query {
+              allCases {
+                edges {
+                  node {
+                    id
+            }}}}
+            """,
+            "",
+            "query",
+            None,
+            "allCases",
+            200,
+        ),
+        (
+            """
+            query {
+              foo {
+                bar
+            }}
+            """,
+            "",
+            "query",
+            None,
+            "foo",
+            400,
+        ),
+        (
+            """
+            mutation SaveTextQuestion($input: SaveTextQuestionInput!) {
+              saveTextQuestion(input: $input) {
+                question {
+                  id
+                  }
+                }
+            }
+            """,
+            {"input": {"slug": "some-text-question", "label": "some text question"}},
+            "mutation",
+            "SaveTextQuestion",
+            "saveTextQuestion",
+            200,
+        ),
+        (
+            """
+            {
+            }""",
+            "",
+            "",
+            None,
+            None,
+            400,
+        ),
+    ],
+)
+def test_access_log(
+    db,
+    snapshot,
+    client,
+    schema_executor,
+    query,
+    variables,
+    operation,
+    operation_name,
+    selection,
+    status_code,
+):
+    url = reverse("graphql")
+    res = schema_executor(query, variable_values=variables)
+
+    result = client.post(
+        url, {"query": query, "variables": variables}, content_type="application/json"
+    )
+
+    # schema executor and actual api call should get both success / errors
+    assert (
+        result.status_code < 400
+        and not res.errors
+        or result.status_code >= 400
+        and res.errors
+    )
+
+    assert models.AccessLog.objects.all().count() == 1
+    log_entry = models.AccessLog.objects.get()
+
+    assert log_entry.query == query
+    assert log_entry.variables == variables
+    assert log_entry.operation_name == operation_name
+    assert log_entry.operation == operation
+    assert log_entry.selection == selection
+    assert log_entry.status_code == status_code == result.status_code

caluma/conftest.py

@@ -15,6 +15,7 @@
 from .caluma_core.faker import MultilangProvider
 from .caluma_core.models import HistoricalRecords
 from .caluma_form import factories as form_factories
+from .caluma_logging import factories as logging_factories
 from .caluma_user.models import AnonymousUser, OIDCUser
 from .caluma_workflow import factories as workflow_factories
 from .schema import schema
@@ -29,6 +30,7 @@ def register_module(module):
 
 
 register_module(form_factories)
+register_module(logging_factories)
 register_module(workflow_factories)
 
 

caluma/settings/django.py

@@ -28,6 +28,7 @@
     "caluma.caluma_form.apps.DefaultConfig",
     "caluma.caluma_workflow.apps.DefaultConfig",
     "caluma.caluma_data_source.apps.DefaultConfig",
+    "caluma.caluma_logging.apps.DefaultConfig",
 ]
 
 if DEBUG:
@@ -156,3 +157,10 @@ def parse_admins(admins):  # pragma: no cover
 # GraphQL
 if DEBUG:
     GRAPHENE["MIDDLEWARE"].append("graphene_django.debug.DjangoDebugMiddleware")
+
+
+# caluma access log
+ENABLE_ACCESS_LOG = env.bool("ENABLE_ACCESS_LOG", default=False)
+
+if ENABLE_ACCESS_LOG:
+    MIDDLEWARE.append("caluma.caluma_logging.middleware.AccessLogMiddleware")