Query count test (#7157)

* Enforce query count middleware for testing

* Cache "DISPLAY_FULL_NAMES" setting

- Much better API performance

* Update unit_test.py

- Add default check for max query count

* Rework unit_test.py

- x-django-query-count header does not get passed through testing framework

* Adjust middleware settings

* Fix debug print

* Refactoring unit_test.py

* Adjust defaults

* Increase default query threshold

- We can work to reduce this further

* Remove outdated comment

* Install django-middleware-global-request

- Makes the request object globally available
- Cache plugin information against it

* Cache "plugins_checked" against global request

- reduce number of times we need to recalculate plugin data

* Cache plugin information to the request

- Prevent duplicate reloads if not required

* Simplify caching of settings

* Revert line

* Allow higher default counts for POST requests

* Remove global request middleware

- Better to implement proper global cache

* increase CI query thresholds

* Fix typo

* API updates

* Unit test updates

* Increase default MAX_QUERY_TIME

* Increase max query time for plugin functions

* Cleanup barcode unit tests

* Fix part test

* Update more tests

* Further unit test updates

* Updates for unit test code

* Fix for unit testing framework

* Fix

* Reduce default query time

* Increase time allowance

src/backend/InvenTree/InvenTree/settings.py

@@ -273,13 +273,14 @@
     'INVENTREE_DEBUG_QUERYCOUNT', 'debug_querycount', False
 ):
     MIDDLEWARE.append('querycount.middleware.QueryCountMiddleware')
+    logger.debug('Running with debug_querycount middleware enabled')
 
 QUERYCOUNT = {
     'THRESHOLDS': {
         'MEDIUM': 50,
         'HIGH': 200,
-        'MIN_TIME_TO_LOG': 0,
-        'MIN_QUERY_COUNT_TO_LOG': 0,
+        'MIN_TIME_TO_LOG': 0.1,
+        'MIN_QUERY_COUNT_TO_LOG': 25,
     },
     'IGNORE_REQUEST_PATTERNS': ['^(?!\/(api)?(plugin)?\/).*'],
     'IGNORE_SQL_PATTERNS': [],

src/backend/InvenTree/InvenTree/unit_test.py

@@ -4,6 +4,7 @@
 import io
 import json
 import re
+import time
 from contextlib import contextmanager
 from pathlib import Path
 
@@ -228,10 +229,19 @@ class InvenTreeTestCase(ExchangeRateMixin, UserMixin, TestCase):
 class InvenTreeAPITestCase(ExchangeRateMixin, UserMixin, APITestCase):
     """Base class for running InvenTree API tests."""
 
+    # Default query count threshold value
+    # TODO: This value should be reduced
+    MAX_QUERY_COUNT = 250
+
+    WARNING_QUERY_THRESHOLD = 100
+
+    # Default query time threshold value
+    # TODO: This value should be reduced
+    # Note: There is a lot of variability in the query time in unit testing...
+    MAX_QUERY_TIME = 7.5
+
     @contextmanager
-    def assertNumQueriesLessThan(
-        self, value, using='default', verbose=False, debug=False
-    ):
+    def assertNumQueriesLessThan(self, value, using='default', verbose=None, url=None):
         """Context manager to check that the number of queries is less than a certain value.
 
         Example:
@@ -242,41 +252,43 @@ def assertNumQueriesLessThan(
         with CaptureQueriesContext(connections[using]) as context:
             yield  # your test will be run here
 
+        n = len(context.captured_queries)
+
+        if url and n >= value:
+            print(
+                f'Query count exceeded at {url}: Expected < {value} queries, got {n}'
+            )  # pragma: no cover
+
         if verbose:
             msg = '\r\n%s' % json.dumps(
                 context.captured_queries, indent=4
             )  # pragma: no cover
         else:
             msg = None
 
-        n = len(context.captured_queries)
-
-        if debug:
-            print(
-                f'Expected less than {value} queries, got {n} queries'
-            )  # pragma: no cover
+        if url and n > self.WARNING_QUERY_THRESHOLD:
+            print(f'Warning: {n} queries executed at {url}')
 
         self.assertLess(n, value, msg=msg)
 
-    def checkResponse(self, url, method, expected_code, response):
+    def check_response(self, url, response, expected_code=None):
         """Debug output for an unexpected response."""
-        # No expected code, return
-        if expected_code is None:
-            return
+        # Check that the response returned the expected status code
 
-        if expected_code != response.status_code:  # pragma: no cover
-            print(
-                f"Unexpected {method} response at '{url}': status_code = {response.status_code}"
-            )
+        if expected_code is not None:
+            if expected_code != response.status_code:  # pragma: no cover
+                print(
+                    f"Unexpected response at '{url}': status_code = {response.status_code} (expected {expected_code})"
+                )
 
-            if hasattr(response, 'data'):
-                print('data:', response.data)
-            if hasattr(response, 'body'):
-                print('body:', response.body)
-            if hasattr(response, 'content'):
-                print('content:', response.content)
+                if hasattr(response, 'data'):
+                    print('data:', response.data)
+                if hasattr(response, 'body'):
+                    print('body:', response.body)
+                if hasattr(response, 'content'):
+                    print('content:', response.content)
 
-        self.assertEqual(expected_code, response.status_code)
+            self.assertEqual(expected_code, response.status_code)
 
     def getActions(self, url):
         """Return a dict of the 'actions' available at a given endpoint.
@@ -289,72 +301,88 @@ def getActions(self, url):
         actions = response.data.get('actions', {})
         return actions
 
-    def get(self, url, data=None, expected_code=200, format='json', **kwargs):
-        """Issue a GET request."""
-        # Set default - see B006
+    def query(self, url, method, data=None, **kwargs):
+        """Perform a generic API query."""
         if data is None:
             data = {}
 
-        response = self.client.get(url, data, format=format, **kwargs)
+        expected_code = kwargs.pop('expected_code', None)
 
-        self.checkResponse(url, 'GET', expected_code, response)
+        kwargs['format'] = kwargs.get('format', 'json')
 
-        return response
+        max_queries = kwargs.get('max_query_count', self.MAX_QUERY_COUNT)
+        max_query_time = kwargs.get('max_query_time', self.MAX_QUERY_TIME)
 
-    def post(self, url, data=None, expected_code=None, format='json', **kwargs):
-        """Issue a POST request."""
-        # Set default value - see B006
-        if data is None:
-            data = {}
+        t1 = time.time()
 
-        response = self.client.post(url, data=data, format=format, **kwargs)
+        with self.assertNumQueriesLessThan(max_queries, url=url):
+            response = method(url, data, **kwargs)
+        t2 = time.time()
+        dt = t2 - t1
 
-        self.checkResponse(url, 'POST', expected_code, response)
+        self.check_response(url, response, expected_code=expected_code)
+
+        if dt > max_query_time:
+            print(
+                f'Query time exceeded at {url}: Expected {max_query_time}s, got {dt}s'
+            )
+
+        self.assertLessEqual(dt, max_query_time)
 
         return response
 
-    def delete(self, url, data=None, expected_code=None, format='json', **kwargs):
-        """Issue a DELETE request."""
-        if data is None:
-            data = {}
+    def get(self, url, data=None, expected_code=200, **kwargs):
+        """Issue a GET request."""
+        kwargs['data'] = data
 
-        response = self.client.delete(url, data=data, format=format, **kwargs)
+        return self.query(url, self.client.get, expected_code=expected_code, **kwargs)
 
-        self.checkResponse(url, 'DELETE', expected_code, response)
+    def post(self, url, data=None, expected_code=201, **kwargs):
+        """Issue a POST request."""
+        # Default query limit is higher for POST requests, due to extra event processing
+        kwargs['max_query_count'] = kwargs.get(
+            'max_query_count', self.MAX_QUERY_COUNT + 100
+        )
 
-        return response
+        kwargs['data'] = data
 
-    def patch(self, url, data, expected_code=None, format='json', **kwargs):
-        """Issue a PATCH request."""
-        response = self.client.patch(url, data=data, format=format, **kwargs)
+        return self.query(url, self.client.post, expected_code=expected_code, **kwargs)
 
-        self.checkResponse(url, 'PATCH', expected_code, response)
+    def delete(self, url, data=None, expected_code=204, **kwargs):
+        """Issue a DELETE request."""
+        kwargs['data'] = data
 
-        return response
+        return self.query(
+            url, self.client.delete, expected_code=expected_code, **kwargs
+        )
 
-    def put(self, url, data, expected_code=None, format='json', **kwargs):
-        """Issue a PUT request."""
-        response = self.client.put(url, data=data, format=format, **kwargs)
+    def patch(self, url, data, expected_code=200, **kwargs):
+        """Issue a PATCH request."""
+        kwargs['data'] = data
 
-        self.checkResponse(url, 'PUT', expected_code, response)
+        return self.query(url, self.client.patch, expected_code=expected_code, **kwargs)
 
-        return response
+    def put(self, url, data, expected_code=200, **kwargs):
+        """Issue a PUT request."""
+        kwargs['data'] = data
+
+        return self.query(url, self.client.put, expected_code=expected_code, **kwargs)
 
     def options(self, url, expected_code=None, **kwargs):
         """Issue an OPTIONS request."""
-        response = self.client.options(url, format='json', **kwargs)
-
-        self.checkResponse(url, 'OPTIONS', expected_code, response)
+        kwargs['data'] = kwargs.get('data', None)
 
-        return response
+        return self.query(
+            url, self.client.options, expected_code=expected_code, **kwargs
+        )
 
     def download_file(
-        self, url, data, expected_code=None, expected_fn=None, decode=True
+        self, url, data, expected_code=None, expected_fn=None, decode=True, **kwargs
     ):
         """Download a file from the server, and return an in-memory file."""
         response = self.client.get(url, data=data, format='json')
 
-        self.checkResponse(url, 'DOWNLOAD_FILE', expected_code, response)
+        self.check_response(url, response, expected_code=expected_code)
 
         # Check that the response is of the correct type
         if not isinstance(response, StreamingHttpResponse):

src/backend/InvenTree/build/models.py

@@ -567,14 +567,17 @@ def complete_allocations(self, user):
         self.allocated_stock.delete()
 
     @transaction.atomic
-    def complete_build(self, user):
+    def complete_build(self, user, trim_allocated_stock=False):
         """Mark this build as complete."""
 
         import build.tasks
 
         if self.incomplete_count > 0:
             return
 
+        if trim_allocated_stock:
+            self.trim_allocated_stock()
+
         self.completion_date = InvenTree.helpers.current_date()
         self.completed_by = user
         self.status = BuildStatus.COMPLETE.value
@@ -858,6 +861,10 @@ def delete_output(self, output):
     def trim_allocated_stock(self):
         """Called after save to reduce allocated stock if the build order is now overallocated."""
         # Only need to worry about untracked stock here
+
+        items_to_save = []
+        items_to_delete = []
+
         for build_line in self.untracked_line_items:
 
             reduce_by = build_line.allocated_quantity() - build_line.quantity
@@ -875,13 +882,19 @@ def trim_allocated_stock(self):
                 # Easy case - this item can just be reduced.
                 if item.quantity > reduce_by:
                     item.quantity -= reduce_by
-                    item.save()
+                    items_to_save.append(item)
                     break
 
                 # Harder case, this item needs to be deleted, and any remainder
                 # taken from the next items in the list.
                 reduce_by -= item.quantity
-                item.delete()
+                items_to_delete.append(item)
+
+        # Save the updated BuildItem objects
+        BuildItem.objects.bulk_update(items_to_save, ['quantity'])
+
+        # Delete the remaining BuildItem objects
+        BuildItem.objects.filter(pk__in=[item.pk for item in items_to_delete]).delete()
 
     @property
     def allocated_stock(self):
@@ -978,7 +991,10 @@ def complete_build_output(self, output, user, **kwargs):
         # List the allocated BuildItem objects for the given output
         allocated_items = output.items_to_install.all()
 
-        if (common.settings.prevent_build_output_complete_on_incompleted_tests() and output.hasRequiredTests() and not output.passedAllRequiredTests()):
+        required_tests = kwargs.get('required_tests', output.part.getRequiredTests())
+        prevent_on_incomplete = kwargs.get('prevent_on_incomplete', common.settings.prevent_build_output_complete_on_incompleted_tests())
+
+        if (prevent_on_incomplete and not output.passedAllRequiredTests(required_tests=required_tests)):
             serial = output.serial
             raise ValidationError(
                 _(f"Build output {serial} has not passed all required tests"))

src/backend/InvenTree/build/serializers.py

@@ -568,10 +568,13 @@ def save(self):
 
         outputs = data.get('outputs', [])
 
+        # Cache some calculated values which can be passed to each output
+        required_tests = outputs[0]['output'].part.getRequiredTests()
+        prevent_on_incomplete = common.settings.prevent_build_output_complete_on_incompleted_tests()
+
         # Mark the specified build outputs as "complete"
         with transaction.atomic():
             for item in outputs:
-
                 output = item['output']
 
                 build.complete_build_output(
@@ -580,6 +583,8 @@ def save(self):
                     location=location,
                     status=status,
                     notes=notes,
+                    required_tests=required_tests,
+                    prevent_on_incomplete=prevent_on_incomplete,
                 )
 
 
@@ -734,10 +739,11 @@ def save(self):
         build = self.context['build']
 
         data = self.validated_data
-        if data.get('accept_overallocated', OverallocationChoice.REJECT) == OverallocationChoice.TRIM:
-            build.trim_allocated_stock()
 
-        build.complete_build(request.user)
+        build.complete_build(
+            request.user,
+            trim_allocated_stock=data.get('accept_overallocated', OverallocationChoice.REJECT) == OverallocationChoice.TRIM
+        )
 
 
 class BuildUnallocationSerializer(serializers.Serializer):

src/backend/InvenTree/build/test_api.py

@@ -223,6 +223,7 @@ def test_complete(self):
                 "status": 50,  # Item requires attention
             },
             expected_code=201,
+            max_query_count=450,  # TODO: Try to optimize this
         )
 
         self.assertEqual(self.build.incomplete_outputs.count(), 0)
@@ -992,6 +993,7 @@ def test_overallocated_requires_acceptance(self):
                 'accept_overallocated': 'accept',
             },
             expected_code=201,
+            max_query_count=550,  # TODO: Come back and refactor this
         )
 
         self.build.refresh_from_db()
@@ -1012,6 +1014,7 @@ def test_overallocated_can_trim(self):
                 'accept_overallocated': 'trim',
             },
             expected_code=201,
+            max_query_count=550,  # TODO: Come back and refactor this
         )
 
         self.build.refresh_from_db()

src/backend/InvenTree/common/models.py

@@ -749,6 +749,7 @@ def set_setting(cls, key, value, change_user=None, create=True, **kwargs):
                     attempts=attempts - 1,
                     **kwargs,
                 )
+
         except (OperationalError, ProgrammingError):
             logger.warning("Database is locked, cannot set setting '%s'", key)
             # Likely the DB is locked - not much we can do here

src/backend/InvenTree/common/tests.py

@@ -1093,7 +1093,7 @@ def test_refresh_endpoint(self):
 
         # Updating via the external exchange may not work every time
         for _idx in range(5):
-            self.post(reverse('api-currency-refresh'))
+            self.post(reverse('api-currency-refresh'), expected_code=200)
 
             # There should be some new exchange rate objects now
             if Rate.objects.all().exists():

src/backend/InvenTree/order/test_api.py

@@ -1108,7 +1108,7 @@ def test_serial_numbers(self):
 
         n = StockItem.objects.count()
 
-        self.post(self.url, data, expected_code=201)
+        self.post(self.url, data, expected_code=201, max_query_count=400)
 
         # Check that the expected number of stock items has been created
         self.assertEqual(n + 11, StockItem.objects.count())