diff --git a/packages/serveradmin/serveradmin/api/views.py b/packages/serveradmin/serveradmin/api/views.py index 73ed7719..8d084427 100644 --- a/packages/serveradmin/serveradmin/api/views.py +++ b/packages/serveradmin/serveradmin/api/views.py @@ -3,6 +3,8 @@ Copyright (c) 2019 InnoGames GmbH """ +from time import monotonic + from django.core.exceptions import ( SuspiciousOperation, PermissionDenied, @@ -14,6 +16,8 @@ from adminapi.filters import BaseFilter, FilterValueError from serveradmin.api import ApiError, AVAILABLE_API_FUNCTIONS from serveradmin.api.decorators import api_view +from serveradmin.dataset import Query +from serveradmin.querylog.utils import log_query from serveradmin.serverdb.models import Attribute from serveradmin.serverdb.query_committer import commit_query from serveradmin.serverdb.query_executer import execute_query @@ -62,9 +66,28 @@ def dataset_query(request, app, data): order_by = data.get('order_by') + start = monotonic() + result = execute_query(filters, restrict, order_by) + duration_seconds = monotonic() - start + + # Query(...) is instantiated here only for its repr(); it is never + # iterated, since that would trigger a second, redundant execution of + # the same query. + log_query( + application=app, + user=app.owner, + source='api', + filters=filters, + restrict=restrict, + order_by=order_by, + duration_seconds=duration_seconds, + query_text=repr(Query(filters, restrict, order_by)), + num_results=len(result), + ) + return { 'status': 'success', - 'result': execute_query(filters, restrict, order_by), + 'result': result, } diff --git a/packages/serveradmin/serveradmin/querylog/__init__.py b/packages/serveradmin/serveradmin/querylog/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/packages/serveradmin/serveradmin/querylog/admin.py b/packages/serveradmin/serveradmin/querylog/admin.py new file mode 100644 index 00000000..15953156 --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/admin.py @@ -0,0 +1,109 @@ +"""Serveradmin - Ad-hoc Query Logging + +Copyright (c) 2026 InnoGames GmbH +""" + +from django import forms +from django.contrib import admin +from django.contrib.admin.widgets import FilteredSelectMultiple + +from serveradmin.querylog.models import QueryLog, QueryLoggingRule +from serveradmin.serverdb.models import Attribute + + +def _attribute_choices(): + """(value, label) choices for the trigger_attributes widget + + Computed on demand (called from QueryLoggingRuleForm.__init__, not at + class-definition time) so newly added Attribute rows show up without + restarting the process, and so importing this module never queries + the DB. + """ + real_ids = Attribute.objects.values_list('attribute_id', flat=True) + all_ids = set(real_ids) | set(Attribute.specials.keys()) + return sorted((attribute_id, attribute_id) for attribute_id in all_ids) + + +class QueryLoggingRuleForm(forms.ModelForm): + trigger_attributes = forms.MultipleChoiceField( + required=False, + choices=(), + widget=FilteredSelectMultiple('attributes', is_stacked=False), + ) + + class Meta: + model = QueryLoggingRule + fields = '__all__' + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.fields['trigger_attributes'].choices = _attribute_choices() + + +@admin.register(QueryLoggingRule) +class QueryLoggingRuleAdmin(admin.ModelAdmin): + form = QueryLoggingRuleForm + list_display = [ + 'application', 'user', 'is_active', 'enabled_until', + 'short_trigger_query', 'short_trigger_attributes', 'note', + 'created_by', 'created_at', + ] + list_filter = ['is_active', 'application'] + search_fields = ['application__name', 'user__username', 'note'] + autocomplete_fields = ['application', 'user'] + readonly_fields = ['created_at', 'created_by'] + list_select_related = ['application', 'user', 'created_by'] + + @admin.display(description='Trigger query') + def short_trigger_query(self, obj): + if len(obj.trigger_query) <= 60: + return obj.trigger_query + return obj.trigger_query[:57] + '...' + + @admin.display(description='Trigger attributes') + def short_trigger_attributes(self, obj): + joined = ', '.join(obj.trigger_attributes) + if len(joined) <= 60: + return joined + return joined[:57] + '...' + + def save_model(self, request, obj, form, change): + if not change: + obj.created_by = request.user + obj.full_clean() + super().save_model(request, obj, form, change) + + +@admin.register(QueryLog) +class QueryLogAdmin(admin.ModelAdmin): + list_display = [ + 'created_at', 'source', 'application', 'user', + 'duration_ms', 'num_results', 'short_query_text', + ] + list_filter = ['source', 'application', 'user'] + search_fields = ['query_text'] + date_hierarchy = 'created_at' + list_select_related = ['application', 'user', 'rule'] + + # This table has no automated retention/cleanup (see the plan this + # feature was built from), so it can grow unbounded. Avoid a slow + # exact COUNT(*) on every paginated list view - same motivation as + # the custom NoCountPaginator used for the (much larger) ChangeCommit + # log in serverdb/views.py. + show_full_result_count = False + + @admin.display(description='Query') + def short_query_text(self, obj): + if len(obj.query_text) <= 120: + return obj.query_text + return obj.query_text[:117] + '...' + + def has_add_permission(self, request): + return False + + def has_change_permission(self, request, obj=None): + return False + + # has_delete_permission is left at the ModelAdmin default (True): + # deleting old rows via the admin is the only housekeeping mechanism + # since there is no automated retention job in this version. diff --git a/packages/serveradmin/serveradmin/querylog/migrations/0001_initial.py b/packages/serveradmin/serveradmin/querylog/migrations/0001_initial.py new file mode 100644 index 00000000..9c740025 --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/migrations/0001_initial.py @@ -0,0 +1,61 @@ +# Generated by Django 5.2.16 on 2026-08-28 11:35 + +import django.db.models.deletion +import django.utils.timezone +from django.conf import settings +from django.db import migrations, models + + +class Migration(migrations.Migration): + + initial = True + + dependencies = [ + ('apps', '0004_application_last_login'), + migrations.swappable_dependency(settings.AUTH_USER_MODEL), + ] + + operations = [ + migrations.CreateModel( + name='QueryLoggingRule', + fields=[ + ('id', models.AutoField(auto_created=True, primary_key=True, serialize=False, verbose_name='ID')), + ('is_active', models.BooleanField(default=True, help_text='Uncheck to disable this rule immediately without losing its configured expiry.')), + ('enabled_until', models.DateTimeField(help_text='Logging stops matching automatically after this time.')), + ('note', models.TextField(blank=True, help_text='Reason for enabling logging, e.g. a ticket link.')), + ('created_at', models.DateTimeField(default=django.utils.timezone.now, editable=False)), + ('application', models.ForeignKey(blank=True, null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='query_logging_rules', to='apps.application')), + ('created_by', models.ForeignKey(editable=False, null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='created_query_logging_rules', to=settings.AUTH_USER_MODEL)), + ('user', models.ForeignKey(blank=True, null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='query_logging_rules', to=settings.AUTH_USER_MODEL)), + ], + ), + migrations.CreateModel( + name='QueryLog', + fields=[ + ('id', models.AutoField(auto_created=True, primary_key=True, serialize=False, verbose_name='ID')), + ('source', models.CharField(choices=[('api', 'API'), ('servershell', 'Servershell')], max_length=16)), + ('query_text', models.TextField()), + ('filters', models.JSONField(blank=True, null=True)), + ('restrict', models.JSONField(blank=True, null=True)), + ('order_by', models.JSONField(blank=True, null=True)), + ('duration_ms', models.FloatField()), + ('num_results', models.IntegerField(blank=True, null=True)), + ('created_at', models.DateTimeField(db_index=True, default=django.utils.timezone.now)), + ('application', models.ForeignKey(null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='query_logs', to='apps.application')), + ('user', models.ForeignKey(null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='query_logs', to=settings.AUTH_USER_MODEL)), + ('rule', models.ForeignKey(null=True, on_delete=django.db.models.deletion.SET_NULL, related_name='logs', to='querylog.queryloggingrule')), + ], + ), + migrations.AddIndex( + model_name='queryloggingrule', + index=models.Index(fields=['is_active', 'enabled_until'], name='querylog_qu_is_acti_acce8b_idx'), + ), + migrations.AddConstraint( + model_name='queryloggingrule', + constraint=models.CheckConstraint(condition=models.Q(('application__isnull', False), ('user__isnull', False), _connector='OR'), name='querylog_rule_application_or_user_required'), + ), + migrations.AddIndex( + model_name='querylog', + index=models.Index(fields=['source', 'created_at'], name='querylog_qu_source_714e77_idx'), + ), + ] diff --git a/packages/serveradmin/serveradmin/querylog/migrations/0002_queryloggingrule_trigger_query.py b/packages/serveradmin/serveradmin/querylog/migrations/0002_queryloggingrule_trigger_query.py new file mode 100644 index 00000000..2fedbe9f --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/migrations/0002_queryloggingrule_trigger_query.py @@ -0,0 +1,18 @@ +# Generated by Django 5.2.16 on 2026-08-28 13:21 + +from django.db import migrations, models + + +class Migration(migrations.Migration): + + dependencies = [ + ('querylog', '0001_initial'), + ] + + operations = [ + migrations.AddField( + model_name='queryloggingrule', + name='trigger_query', + field=models.CharField(blank=True, help_text='Optional. Only log a query if its filters satisfy this condition, e.g. "hostname=Regexp(\'web.*\') environment=prod". Leave blank to log every query matched by application/user above. Use attr=All() to match any query that references "attr" at all, regardless of its value.', max_length=1000), + ), + ] diff --git a/packages/serveradmin/serveradmin/querylog/migrations/0003_queryloggingrule_trigger_attributes.py b/packages/serveradmin/serveradmin/querylog/migrations/0003_queryloggingrule_trigger_attributes.py new file mode 100644 index 00000000..f55b5ddb --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/migrations/0003_queryloggingrule_trigger_attributes.py @@ -0,0 +1,18 @@ +# Generated by Django 5.2.16 on 2026-08-28 13:42 + +from django.db import migrations, models + + +class Migration(migrations.Migration): + + dependencies = [ + ('querylog', '0002_queryloggingrule_trigger_query'), + ] + + operations = [ + migrations.AddField( + model_name='queryloggingrule', + name='trigger_attributes', + field=models.JSONField(blank=True, default=list, help_text='Optional. Only log a query if its "restrict" (the list of attributes it asked to have returned) includes at least one of the attributes selected here. Leave empty to log every query matched by application/user/trigger_query above. Includes the special attributes object_id, hostname, servertype and intern_ip, which are not real serverdb attributes but are valid values for "restrict".'), + ), + ] diff --git a/packages/serveradmin/serveradmin/querylog/migrations/__init__.py b/packages/serveradmin/serveradmin/querylog/migrations/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/packages/serveradmin/serveradmin/querylog/models.py b/packages/serveradmin/serveradmin/querylog/models.py new file mode 100644 index 00000000..a77ce73e --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/models.py @@ -0,0 +1,259 @@ +"""Serveradmin - Ad-hoc Query Logging + +Copyright (c) 2026 InnoGames GmbH +""" + +from django.contrib.auth.models import User +from django.core.exceptions import ValidationError +from django.db import models +from django.db.models import Q +from django.utils.timezone import now + +from adminapi.exceptions import DatatypeError +from adminapi.filters import Any, BaseFilter +from adminapi.parse import parse_query +from serveradmin.apps.models import Application +from serveradmin.serverdb.models import Attribute + + +def _extract_candidate_values(filter_obj): + """Best-effort extraction of concrete values from an incoming filter + + Used to evaluate a QueryLoggingRule.trigger_query condition against + the actual filter object a query used for one attribute. Only two + incoming filter shapes are considered safely decidable; anything + else (Regexp, All, Not, GreaterThan, Contains, ...) conservatively + yields no candidates, meaning the trigger condition for that + attribute cannot be satisfied. This is a known, intentional + limitation - comparing two filter expressions isn't well-defined. + """ + if type(filter_obj) is BaseFilter: + return [filter_obj.value] + if type(filter_obj) is Any: + return [v.value for v in filter_obj.values if type(v) is BaseFilter] + return [] + + +class QueryLoggingRuleManager(models.Manager): + def matching(self, application, user): + """Return the currently active rules that apply + + A rule with only "application" set matches any user of that + application. A rule with only "user" set matches that user + regardless of application (this is the only way Servershell + queries, which have no application, can ever be logged). A rule + with both set requires both to match. + + "application" may be None (Servershell has no Application). + """ + clauses = Q(pk__in=[]) + if application is not None and user is not None: + clauses |= Q(application=application, user=user) + if application is not None: + clauses |= Q(application=application, user__isnull=True) + if user is not None: + clauses |= Q(user=user, application__isnull=True) + + return self.filter( + is_active=True, enabled_until__gt=now(), + ).filter(clauses).order_by('pk') + + +class QueryLoggingRule(models.Model): + """Admin-configured rule enabling ad-hoc query logging + + Logging for serveradmin.api.views.dataset_query and + serveradmin.servershell.views.get_results is off by default. It is + only turned on for the application and/or user targeted by an active + rule, and only until "enabled_until". + """ + + application = models.ForeignKey( + Application, null=True, blank=True, on_delete=models.SET_NULL, + related_name='query_logging_rules', + ) + user = models.ForeignKey( + User, null=True, blank=True, on_delete=models.SET_NULL, + related_name='query_logging_rules', + ) + is_active = models.BooleanField( + default=True, + help_text=( + 'Uncheck to disable this rule immediately without losing its ' + 'configured expiry.' + ), + ) + enabled_until = models.DateTimeField( + help_text='Logging stops matching automatically after this time.', + ) + note = models.TextField( + blank=True, + help_text='Reason for enabling logging, e.g. a ticket link.', + ) + trigger_query = models.CharField( + max_length=1000, + blank=True, + help_text=( + 'Optional. Only log a query if its filters satisfy this ' + 'condition, e.g. "hostname=Regexp(\'web.*\') ' + 'environment=prod". Leave blank to log every query matched ' + 'by application/user above. Use attr=All() to match any ' + 'query that references "attr" at all, regardless of its ' + 'value.' + ), + ) + trigger_attributes = models.JSONField( + default=list, + blank=True, + help_text=( + 'Optional. Only log a query if its "restrict" (the list of ' + 'attributes it asked to have returned) includes at least one ' + 'of the attributes selected here. Leave empty to log every ' + 'query matched by application/user/trigger_query above. ' + 'Includes the special attributes object_id, hostname, ' + 'servertype and intern_ip, which are not real serverdb ' + 'attributes but are valid values for "restrict".' + ), + ) + created_at = models.DateTimeField(default=now, editable=False) + created_by = models.ForeignKey( + User, null=True, on_delete=models.SET_NULL, editable=False, + related_name='created_query_logging_rules', + ) + + objects = QueryLoggingRuleManager() + + class Meta: + constraints = [ + models.CheckConstraint( + condition=( + Q(application__isnull=False) | Q(user__isnull=False) + ), + name='querylog_rule_application_or_user_required', + ), + ] + indexes = [ + models.Index(fields=['is_active', 'enabled_until']), + ] + + def clean(self): + if self.application_id is None and self.user_id is None: + raise ValidationError( + 'At least one of application or user must be set.' + ) + if self.trigger_query: + try: + parse_query(self.trigger_query) + except DatatypeError as error: + raise ValidationError({ + 'trigger_query': 'Invalid query syntax: {}'.format( + error + ), + }) + if self.trigger_attributes: + valid_ids = set( + Attribute.objects.values_list('attribute_id', flat=True) + ) | set(Attribute.specials.keys()) + invalid_ids = sorted(set(self.trigger_attributes) - valid_ids) + if invalid_ids: + raise ValidationError({ + 'trigger_attributes': 'Unknown attribute id(s): {}' + .format(', '.join(invalid_ids)), + }) + + def matches_query(self, filters): + """Does the actual query's filters dict satisfy trigger_query? + + filters is the {attribute_id: BaseFilter-or-subclass} dict of the + actual ad-hoc query being considered for logging. Returns True + unconditionally if trigger_query is blank (unrestricted, the + default). + """ + if not self.trigger_query: + return True + + trigger_filters = parse_query(self.trigger_query) + for attribute_id, trigger_filter in trigger_filters.items(): + destiny = trigger_filter.destiny() + if destiny is True: + # e.g. attr=All(): matches unconditionally, so only the + # attribute's presence in the query matters. + if attribute_id not in filters: + return False + continue + if destiny is False: + # e.g. the degenerate attr=Any(): never matches. + return False + + if attribute_id not in filters: + return False + + candidates = _extract_candidate_values(filters[attribute_id]) + if not any(trigger_filter.matches(v) for v in candidates): + return False + + return True + + def matches_restrict(self, restrict): + """Does the actual query's restrict list satisfy trigger_attributes? + + restrict is either None (the query asked to have every attribute + returned) or a list of attribute_id strings the actual ad-hoc + query asked to have returned. Returns True unconditionally if + trigger_attributes is empty (unrestricted, the default). When + trigger_attributes is non-empty, restrict=None is treated as + satisfying it too, since "return everything" implicitly includes + any attribute this rule is watching for. Otherwise matches if + restrict contains at least one of the selected attributes (OR + semantics across the selection). + """ + if not self.trigger_attributes: + return True + if restrict is None: + return True + return bool(set(self.trigger_attributes) & set(restrict)) + + def __str__(self): + target = self.application or self.user or 'nobody' + return '{} until {}'.format(target, self.enabled_until) + + +class QueryLog(models.Model): + """A single logged ad-hoc query + + Only created when a matching, active QueryLoggingRule exists at the + time the query ran. See serveradmin.querylog.utils.log_query(). + """ + + class Source(models.TextChoices): + API = 'api', 'API' + SERVERSHELL = 'servershell', 'Servershell' + + rule = models.ForeignKey( + QueryLoggingRule, null=True, on_delete=models.SET_NULL, + related_name='logs', + ) + application = models.ForeignKey( + Application, null=True, on_delete=models.SET_NULL, + related_name='query_logs', + ) + user = models.ForeignKey( + User, null=True, on_delete=models.SET_NULL, + related_name='query_logs', + ) + source = models.CharField(max_length=16, choices=Source.choices) + query_text = models.TextField() + filters = models.JSONField(null=True, blank=True) + restrict = models.JSONField(null=True, blank=True) + order_by = models.JSONField(null=True, blank=True) + duration_ms = models.FloatField() + num_results = models.IntegerField(null=True, blank=True) + created_at = models.DateTimeField(default=now, db_index=True) + + class Meta: + indexes = [ + models.Index(fields=['source', 'created_at']), + ] + + def __str__(self): + return '{} query at {}'.format(self.source, self.created_at) diff --git a/packages/serveradmin/serveradmin/querylog/tests/__init__.py b/packages/serveradmin/serveradmin/querylog/tests/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/packages/serveradmin/serveradmin/querylog/tests/test_logging.py b/packages/serveradmin/serveradmin/querylog/tests/test_logging.py new file mode 100644 index 00000000..a74b9142 --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/tests/test_logging.py @@ -0,0 +1,254 @@ +from datetime import timedelta +from unittest.mock import patch + +from django.contrib.auth.models import User +from django.core.exceptions import ObjectDoesNotExist +from django.test import TransactionTestCase +from django.utils.timezone import now + +from adminapi.filters import Any, BaseFilter, Regexp +from serveradmin.api.views import dataset_query +from serveradmin.apps.models import Application +from serveradmin.querylog.models import QueryLog, QueryLoggingRule +from serveradmin.querylog.utils import log_query + + +class LogQueryTest(TransactionTestCase): + fixtures = ['test_dataset.json'] + + def setUp(self): + self.user = User.objects.create_user('alice') + self.app = Application.objects.create( + name='app-a', owner=self.user, location='', + ) + + def _log(self, **overrides): + kwargs = dict( + application=self.app, + user=self.user, + source=QueryLog.Source.API, + filters={'hostname': BaseFilter('test0')}, + restrict=['hostname'], + order_by=None, + duration_seconds=0.05, + query_text="Query({'hostname': BaseFilter('test0')})", + num_results=1, + ) + kwargs.update(overrides) + return log_query(**kwargs) + + def test_no_rule_no_log(self): + self.assertFalse(self._log()) + self.assertEqual(0, QueryLog.objects.count()) + + def test_matching_rule_creates_log_row(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + ) + + self.assertTrue(self._log()) + + log = QueryLog.objects.get() + self.assertEqual(self.app, log.application) + self.assertEqual(self.user, log.user) + self.assertEqual(QueryLog.Source.API, log.source) + self.assertEqual(50.0, log.duration_ms) + self.assertEqual(1, log.num_results) + self.assertEqual({'hostname': 'test0'}, log.filters) + + def test_filters_round_trip_regexp_and_any(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + ) + + self._log(filters={ + 'hostname': Regexp('test.*'), + 'servertype': Any('test0', 'test1'), + }) + + log = QueryLog.objects.get() + self.assertEqual( + Regexp('test.*').serialize(), log.filters['hostname'], + ) + reconstructed = BaseFilter.deserialize(log.filters['servertype']) + self.assertIsInstance(reconstructed, Any) + + def test_log_query_never_raises_on_internal_error(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + ) + + with patch.object( + QueryLog.objects, 'create', side_effect=Exception('boom'), + ): + with self.assertLogs('serveradmin', level='WARNING'): + result = self._log() + + self.assertFalse(result) + self.assertEqual(0, QueryLog.objects.count()) + + def test_content_mismatched_trigger_does_not_log(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query="hostname=Regexp('nomatch.*')", + ) + + self.assertFalse(self._log()) + self.assertEqual(0, QueryLog.objects.count()) + + def test_content_matched_trigger_logs(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query='hostname=test0', + ) + + self.assertTrue(self._log()) + self.assertEqual(1, QueryLog.objects.count()) + + def test_and_combination_filters_match_but_restrict_does_not(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query='hostname=test0', + trigger_attributes=['environment'], + ) + + # _log()'s default restrict is ['hostname'], which does not + # intersect ['environment']. + self.assertFalse(self._log()) + self.assertEqual(0, QueryLog.objects.count()) + + def test_and_combination_restrict_matches_but_filters_do_not(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query="hostname=Regexp('nomatch.*')", + trigger_attributes=['hostname'], + ) + + self.assertFalse(self._log()) + self.assertEqual(0, QueryLog.objects.count()) + + def test_and_combination_both_match_logs(self): + QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query='hostname=test0', + trigger_attributes=['hostname'], + ) + + self.assertTrue(self._log()) + self.assertEqual(1, QueryLog.objects.count()) + + def test_second_candidate_rule_matches_when_first_does_not(self): + non_matching = QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + trigger_query="hostname=Regexp('nomatch.*')", + ) + matching = QueryLoggingRule.objects.create( + application=self.app, enabled_until=now() + timedelta(hours=1), + ) + self.assertLess(non_matching.pk, matching.pk) + + self.assertTrue(self._log()) + + log = QueryLog.objects.get() + self.assertEqual(matching.pk, log.rule_id) + + +class DatasetQueryLoggingTest(TransactionTestCase): + fixtures = ['test_dataset.json'] + + def setUp(self): + self.alice = User.objects.create_user('alice') + self.app_a = Application.objects.create( + name='app-a', owner=self.alice, location='', + ) + self.bob = User.objects.create_user('bob') + self.app_b = Application.objects.create( + name='app-b', owner=self.bob, location='', + ) + + def _call(self, app): + data = { + 'filters': {'hostname': 'test0'}, + 'restrict': ['hostname'], + } + return dataset_query.__wrapped__(None, app, data) + + def test_logs_when_app_rule_active(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=now() + timedelta(hours=1), + ) + + result = self._call(self.app_a) + + self.assertEqual('success', result['status']) + log = QueryLog.objects.get() + self.assertEqual('api', log.source) + self.assertEqual(self.app_a, log.application) + self.assertEqual(self.alice, log.user) + self.assertGreaterEqual(log.duration_ms, 0) + self.assertEqual(1, log.num_results) + + def test_no_log_for_unrelated_app(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=now() + timedelta(hours=1), + ) + + self._call(self.app_b) + + self.assertEqual(0, QueryLog.objects.count()) + + def test_no_log_on_error(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=now() + timedelta(hours=1), + ) + + with self.assertRaises(ObjectDoesNotExist): + dataset_query.__wrapped__(None, self.app_a, { + 'filters': {'no_such_attribute': 'test0'}, + }) + + self.assertEqual(0, QueryLog.objects.count()) + + +class ServershellQueryLoggingTest(TransactionTestCase): + fixtures = ['test_dataset.json'] + + def setUp(self): + self.user = User.objects.create_user('alice', password='alice') + self.client.force_login(self.user) + + def test_logs_when_user_rule_active(self): + QueryLoggingRule.objects.create( + user=self.user, enabled_until=now() + timedelta(hours=1), + ) + + response = self.client.get( + '/servershell/results', {'term': 'hostname=test0'}, + ) + + self.assertEqual(200, response.status_code) + log = QueryLog.objects.get() + self.assertEqual('servershell', log.source) + self.assertIsNone(log.application) + self.assertEqual(self.user, log.user) + self.assertEqual(1, log.num_results) + + def test_no_log_without_rule(self): + response = self.client.get( + '/servershell/results', {'term': 'hostname=test0'}, + ) + + self.assertEqual(200, response.status_code) + self.assertEqual(0, QueryLog.objects.count()) + + def test_no_log_on_parse_error(self): + QueryLoggingRule.objects.create( + user=self.user, enabled_until=now() + timedelta(hours=1), + ) + + response = self.client.get( + '/servershell/results', {'term': "hostname=Regexp('[')"}, + ) + + self.assertEqual(200, response.status_code) + self.assertEqual(0, QueryLog.objects.count()) diff --git a/packages/serveradmin/serveradmin/querylog/tests/test_rules.py b/packages/serveradmin/serveradmin/querylog/tests/test_rules.py new file mode 100644 index 00000000..dfb6f6fb --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/tests/test_rules.py @@ -0,0 +1,256 @@ +from datetime import timedelta + +from django.contrib.auth.models import User +from django.core.exceptions import ValidationError +from django.db import IntegrityError, transaction +from django.test import TestCase, TransactionTestCase +from django.utils.timezone import now + +from adminapi.filters import All, Any, BaseFilter, Regexp +from serveradmin.apps.models import Application +from serveradmin.querylog.models import QueryLoggingRule +from serveradmin.serverdb.models import Attribute + + +class QueryLoggingRuleManagerTest(TransactionTestCase): + def setUp(self): + self.alice = User.objects.create_user('alice') + self.bob = User.objects.create_user('bob') + self.app_a = Application.objects.create( + name='app-a', owner=self.alice, location='', + ) + self.app_b = Application.objects.create( + name='app-b', owner=self.bob, location='', + ) + self.future = now() + timedelta(hours=1) + self.past = now() - timedelta(hours=1) + + def test_application_only_rule_matches_any_user_of_that_application(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=self.future, + ) + + self.assertTrue( + QueryLoggingRule.objects.matching(self.app_a, self.bob).exists() + ) + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_b, self.alice).exists() + ) + + def test_user_only_rule_matches_any_application_including_none(self): + QueryLoggingRule.objects.create( + user=self.alice, enabled_until=self.future, + ) + + self.assertTrue( + QueryLoggingRule.objects.matching(self.app_a, self.alice).exists() + ) + self.assertTrue( + QueryLoggingRule.objects.matching(None, self.alice).exists() + ) + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_a, self.bob).exists() + ) + + def test_rule_with_both_requires_both_to_match(self): + QueryLoggingRule.objects.create( + application=self.app_a, user=self.alice, + enabled_until=self.future, + ) + + self.assertTrue( + QueryLoggingRule.objects + .matching(self.app_a, self.alice).exists() + ) + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_a, self.bob).exists() + ) + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_b, self.alice).exists() + ) + + def test_expired_rule_does_not_match(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=self.past, + ) + + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_a, self.alice).exists() + ) + + def test_inactive_rule_does_not_match(self): + QueryLoggingRule.objects.create( + application=self.app_a, enabled_until=self.future, + is_active=False, + ) + + self.assertFalse( + QueryLoggingRule.objects.matching(self.app_a, self.alice).exists() + ) + + def test_clean_requires_application_or_user(self): + rule = QueryLoggingRule(enabled_until=self.future) + with self.assertRaises(ValidationError): + rule.full_clean() + + def test_check_constraint_rejects_bare_insert(self): + with self.assertRaises(IntegrityError): + with transaction.atomic(): + QueryLoggingRule.objects.create(enabled_until=self.future) + + +class QueryLoggingRuleMatchesQueryTest(TestCase): + def setUp(self): + self.future = now() + timedelta(hours=1) + self.user = User.objects.create_user('alice') + + def _rule(self, trigger_query): + return QueryLoggingRule( + user=self.user, enabled_until=self.future, + trigger_query=trigger_query, + ) + + def test_blank_trigger_query_always_matches(self): + rule = self._rule('') + self.assertTrue(rule.matches_query({})) + self.assertTrue(rule.matches_query({'hostname': BaseFilter('x')})) + + def test_all_wildcard_matches_presence_regardless_of_value(self): + rule = self._rule('hostname=All()') + + self.assertTrue(rule.matches_query({'hostname': Regexp('web.*')})) + self.assertTrue(rule.matches_query({'hostname': Any('a', 'b')})) + self.assertFalse( + rule.matches_query({'environment': BaseFilter('prod')}) + ) + + def test_any_wildcard_never_matches(self): + rule = self._rule('hostname=Any()') + + self.assertFalse(rule.matches_query({'hostname': BaseFilter('x')})) + self.assertFalse(rule.matches_query({})) + + def test_concrete_value_trigger_matches_equal_plain_value(self): + rule = self._rule('environment=prod') + + self.assertTrue( + rule.matches_query({'environment': BaseFilter('prod')}) + ) + + def test_concrete_value_trigger_rejects_different_plain_value(self): + rule = self._rule('environment=prod') + + self.assertFalse( + rule.matches_query({'environment': BaseFilter('staging')}) + ) + + def test_concrete_value_trigger_matches_inside_incoming_any(self): + rule = self._rule('environment=prod') + + self.assertTrue(rule.matches_query({ + 'environment': Any('staging', 'prod'), + })) + + def test_concrete_value_trigger_rejects_incoming_regexp(self): + rule = self._rule('environment=prod') + + self.assertFalse(rule.matches_query({ + 'environment': Regexp('pro.*'), + })) + + def test_concrete_value_trigger_rejects_incoming_all(self): + rule = self._rule('environment=prod') + + self.assertFalse(rule.matches_query({'environment': All()})) + + def test_missing_attribute_does_not_match(self): + rule = self._rule('environment=prod') + + self.assertFalse(rule.matches_query({})) + + def test_multiple_attributes_require_all_to_match(self): + rule = self._rule('hostname=All() environment=prod') + + self.assertTrue(rule.matches_query({ + 'hostname': BaseFilter('web1'), + 'environment': BaseFilter('prod'), + })) + self.assertFalse(rule.matches_query({ + 'hostname': BaseFilter('web1'), + 'environment': BaseFilter('staging'), + })) + self.assertFalse(rule.matches_query({ + 'environment': BaseFilter('prod'), + })) + + def test_invalid_trigger_query_syntax_raises_validation_error(self): + rule = self._rule("hostname=Regexp('[')") + + with self.assertRaises(ValidationError): + rule.full_clean() + + +class QueryLoggingRuleMatchesRestrictTest(TestCase): + def setUp(self): + self.future = now() + timedelta(hours=1) + self.user = User.objects.create_user('alice') + + def _rule(self, trigger_attributes): + return QueryLoggingRule( + user=self.user, enabled_until=self.future, + trigger_attributes=trigger_attributes, + ) + + def test_empty_trigger_attributes_always_matches(self): + rule = self._rule([]) + + self.assertTrue(rule.matches_restrict(None)) + self.assertTrue(rule.matches_restrict([])) + self.assertTrue(rule.matches_restrict(['hostname'])) + + def test_restrict_none_matches_any_non_empty_selection(self): + rule = self._rule(['hostname']) + + self.assertTrue(rule.matches_restrict(None)) + + def test_intersecting_restrict_matches(self): + rule = self._rule(['hostname', 'object_id']) + + self.assertTrue(rule.matches_restrict(['object_id'])) + + def test_non_intersecting_restrict_does_not_match(self): + rule = self._rule(['hostname']) + + self.assertFalse(rule.matches_restrict(['environment'])) + + def test_or_semantics_across_multiple_selected_attributes(self): + rule = self._rule(['hostname', 'environment']) + + self.assertTrue(rule.matches_restrict(['environment', 'object_id'])) + + +class QueryLoggingRuleCleanTriggerAttributesTest(TestCase): + def setUp(self): + self.future = now() + timedelta(hours=1) + self.user = User.objects.create_user('alice') + Attribute.objects.create( + attribute_id='test_attr', type='string', regexp=r'\A.*\Z', + ) + + def _rule(self, trigger_attributes): + return QueryLoggingRule( + user=self.user, enabled_until=self.future, + trigger_attributes=trigger_attributes, + ) + + def test_valid_mix_of_real_and_special_attributes_passes(self): + rule = self._rule(['test_attr', 'hostname', 'object_id']) + + rule.full_clean() # must not raise + + def test_unknown_attribute_id_raises_field_scoped_error(self): + rule = self._rule(['not_a_real_attribute']) + + with self.assertRaises(ValidationError) as ctx: + rule.full_clean() + self.assertIn('trigger_attributes', ctx.exception.message_dict) diff --git a/packages/serveradmin/serveradmin/querylog/utils.py b/packages/serveradmin/serveradmin/querylog/utils.py new file mode 100644 index 00000000..269780ce --- /dev/null +++ b/packages/serveradmin/serveradmin/querylog/utils.py @@ -0,0 +1,77 @@ +"""Serveradmin - Ad-hoc Query Logging + +Copyright (c) 2026 InnoGames GmbH +""" + +from logging import getLogger + +from serveradmin.querylog.models import QueryLog, QueryLoggingRule + +logger = getLogger('serveradmin') + + +def log_query( + *, + application, + user, + source, + filters, + restrict, + order_by, + duration_seconds, + query_text, + num_results=None, +): + """Persist a QueryLog row if an active QueryLoggingRule matches + + This is a no-op (no DB write) when nothing is configured to log the + given application/user, which is the default and common case. Also + skips rules whose trigger_query does not match the query's actual + filters, or whose trigger_attributes does not intersect the query's + actual restrict list. + + Must never raise: a bug or outage in logging must not break the + actual query response. Returns True if a row was written, else False. + """ + try: + rule = None + for candidate in QueryLoggingRule.objects.matching(application, user): + content_matches = ( + candidate.matches_query(filters) and + candidate.matches_restrict(restrict) + ) + if content_matches: + rule = candidate + break + if rule is None: + return False + + QueryLog.objects.create( + rule=rule, + application=application, + user=user, + source=source, + query_text=query_text, + filters=_serialize_filters(filters), + restrict=restrict, + order_by=order_by, + duration_ms=duration_seconds * 1000.0, + num_results=num_results, + ) + return True + except Exception: + logger.warning( + 'querylog: Failed to record query log for source=%s ' + 'application=%s user=%s', source, application, user, + exc_info=True, + ) + return False + + +def _serialize_filters(filters): + if not filters: + return None + return { + attribute_id: filt.serialize() + for attribute_id, filt in filters.items() + } diff --git a/packages/serveradmin/serveradmin/servershell/views.py b/packages/serveradmin/serveradmin/servershell/views.py index b86e3e0b..c92be20b 100644 --- a/packages/serveradmin/serveradmin/servershell/views.py +++ b/packages/serveradmin/serveradmin/servershell/views.py @@ -6,6 +6,7 @@ import json from ipaddress import IPv6Address, IPv4Address, ip_interface from itertools import islice, chain +from time import monotonic from django.conf import settings as django_settings from django.contrib import messages @@ -36,6 +37,7 @@ from adminapi.parse import parse_query from adminapi.request import json_encode_extra from serveradmin.dataset import Query +from serveradmin.querylog.utils import log_query from serveradmin.serverdb.models import ( Servertype, Attribute, @@ -161,7 +163,8 @@ def get_results(request): restrict = shown_attributes.copy() if 'servertype' not in restrict: restrict.append('servertype') - main_query = Query(parse_query(term), restrict, order_by) + parsed_filters = parse_query(term) + main_query = Query(parsed_filters, restrict, order_by) merged_query = MergedQuery([ Query({'object_id': Any(*pinned)}, restrict), @@ -171,13 +174,27 @@ def get_results(request): # TODO: Using len is terribly slow for large datasets because it has # to query all objects but we cannot use count which is available on # Django QuerySet + start = monotonic() num_servers = len(list(merged_query)) + duration_seconds = monotonic() - start except (DatatypeError, ObjectDoesNotExist, ValidationError) as error: return HttpResponse(json.dumps({ 'status': 'error', 'message': str(error) })) + log_query( + application=None, + user=request.user, + source='servershell', + filters=parsed_filters, + restrict=restrict, + order_by=order_by, + duration_seconds=duration_seconds, + query_text=repr(main_query), + num_results=num_servers, + ) + # Query successful term must be valid here, so we can save it safely now. request.session['term'] = term diff --git a/packages/serveradmin/serveradmin/settings.py b/packages/serveradmin/serveradmin/settings.py index 1f4369c3..6c401334 100644 --- a/packages/serveradmin/serveradmin/settings.py +++ b/packages/serveradmin/serveradmin/settings.py @@ -70,6 +70,7 @@ 'serveradmin.apps', 'serveradmin.common', 'serveradmin.graphite', + 'serveradmin.querylog', 'serveradmin.resources', 'serveradmin.serverdb', 'serveradmin.servershell',