Add special logging

src/pretix/base/services/cart.py

@@ -31,6 +31,8 @@
 # Unless required by applicable law or agreed to in writing, software distributed under the Apache License 2.0 is
 # distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
 # License for the specific language governing permissions and limitations under the License.
+import json
+import logging
 import re
 import uuid
 from collections import Counter, defaultdict, namedtuple
@@ -80,6 +82,8 @@ from pretix.presale.signals import (
 )
 from pretix.testutils.middleware import debugflags_var
 
+quota_logger = logging.getLogger("pretix_quota")
+
 
 class CartError(Exception):
     def __init__(self, *args):
@@ -1123,6 +1127,11 @@ class CartManager:
             )
         vouchers_ok = self._get_voucher_availability()
         quotas_ok = _get_quota_availability(self._quota_diff, self.real_now_dt)
+        quota_logger.debug(json.dumps({
+            "op": "CartManager._perform_operations",
+            "quota_diff": {q.name: d for q, d in self._quota_diff.items()},
+            "quotas_ok": {q.name: d for q, d in quotas_ok.items()},
+        }))
         err = None
         new_cart_positions = []
         deleted_positions = set()
@@ -1408,6 +1417,16 @@ class CartManager:
         return diff
 
     def commit(self):
+        quota_logger.debug(json.dumps({
+            "op": "CartManager.commit start",
+        }))
+        for op in self._operations:
+            quota_logger.debug(json.dumps({
+                "op": "CartManager.commit operation",
+                "operation_type": str(type(op)),
+                "count": getattr(op, "count", 1) if isinstance(op, (self.AddOperation, self.ExtendOperation)) else None,
+                "repr": repr(op),
+            }))
         self._check_presale_dates()
         self._check_max_cart_size()
         self._calculate_expiry()
@@ -1424,6 +1443,16 @@ class CartManager:
 
         if err:
             raise CartError(err)
+        for op in self._operations:
+            quota_logger.debug(json.dumps({
+                "op": "CartManager.commit operation done",
+                "operation_type": str(type(op)),
+                "count": getattr(op, "count", 1) if isinstance(op, (self.AddOperation, self.ExtendOperation)) else None,
+                "repr": repr(op),
+            }))
+        quota_logger.debug(json.dumps({
+            "op": "CartManager.commit done",
+        }))
 
 
 def add_payment_to_cart(request, provider, min_value: Decimal=None, max_value: Decimal=None, info_data: dict=None):
@@ -1516,6 +1545,11 @@ def add_items_to_cart(self, event: int, items: List[dict], cart_id: str=None, lo
     :param cart_id: Session ID of a guest
     :raises CartError: On any error that occurred
     """
+    quota_logger.debug(json.dumps({
+        "op": "add_items_to_cart start",
+        "cart_id": cart_id,
+        "items": items,
+    }))
     with language(locale), time_machine_now_assigned(override_now_dt):
         ia = False
         if invoice_address:
@@ -1540,6 +1574,10 @@ def add_items_to_cart(self, event: int, items: List[dict], cart_id: str=None, lo
                 self.retry()
         except (MaxRetriesExceededError, LockTimeoutException):
             raise CartError(error_messages['busy'])
+    quota_logger.debug(json.dumps({
+        "op": "add_items_to_cart end",
+        "cart_id": cart_id,
+    }))
 
 
 @app.task(base=ProfiledEventTask, bind=True, max_retries=5, default_retry_delay=1, throws=(CartError,))
@@ -1549,6 +1587,10 @@ def apply_voucher(self, event: Event, voucher: str, cart_id: str=None, locale='e
     :param voucher: A voucher code
     :param cart_id: The cart ID of the cart to modify
     """
+    quota_logger.debug(json.dumps({
+        "op": "apply_voucher start",
+        "cart_id": cart_id,
+    }))
     with language(locale), time_machine_now_assigned(override_now_dt):
         try:
             sales_channel = event.organizer.sales_channels.get(identifier=sales_channel)
@@ -1563,6 +1605,10 @@ def apply_voucher(self, event: Event, voucher: str, cart_id: str=None, locale='e
                 self.retry()
         except (MaxRetriesExceededError, LockTimeoutException):
             raise CartError(error_messages['busy'])
+    quota_logger.debug(json.dumps({
+        "op": "apply_voucher end",
+        "cart_id": cart_id,
+    }))
 
 
 @app.task(base=ProfiledEventTask, bind=True, max_retries=5, default_retry_delay=1, throws=(CartError,))
@@ -1573,6 +1619,11 @@ def remove_cart_position(self, event: Event, position: int, cart_id: str=None, l
     :param position: A cart position ID
     :param cart_id: The cart ID of the cart to modify
     """
+    quota_logger.debug(json.dumps({
+        "op": "remove_cart_position start",
+        "cart_id": cart_id,
+        "position": position,
+    }))
     with language(locale), time_machine_now_assigned(override_now_dt):
         try:
             sales_channel = event.organizer.sales_channels.get(identifier=sales_channel)
@@ -1587,6 +1638,11 @@ def remove_cart_position(self, event: Event, position: int, cart_id: str=None, l
                 self.retry()
         except (MaxRetriesExceededError, LockTimeoutException):
             raise CartError(error_messages['busy'])
+    quota_logger.debug(json.dumps({
+        "op": "remove_cart_position end",
+        "cart_id": cart_id,
+        "position": position,
+    }))
 
 
 @app.task(base=ProfiledEventTask, bind=True, max_retries=5, default_retry_delay=1, throws=(CartError,))
@@ -1596,6 +1652,10 @@ def clear_cart(self, event: Event, cart_id: str=None, locale='en', sales_channel
     :param event: The event ID in question
     :param cart_id: The cart ID of the cart to modify
     """
+    quota_logger.debug(json.dumps({
+        "op": "clear_cart start",
+        "cart_id": cart_id,
+    }))
     with language(locale), time_machine_now_assigned(override_now_dt):
         try:
             sales_channel = event.organizer.sales_channels.get(identifier=sales_channel)
@@ -1610,6 +1670,10 @@ def clear_cart(self, event: Event, cart_id: str=None, locale='en', sales_channel
                 self.retry()
         except (MaxRetriesExceededError, LockTimeoutException):
             raise CartError(error_messages['busy'])
+    quota_logger.debug(json.dumps({
+        "op": "clear_cart end",
+        "cart_id": cart_id,
+    }))
 
 
 @app.task(base=ProfiledEventTask, bind=True, max_retries=5, default_retry_delay=1, throws=(CartError,))

src/pretix/base/services/locking.py

@@ -19,18 +19,19 @@
 # You should have received a copy of the GNU Affero General Public License along with this program.  If not, see
 # <https://www.gnu.org/licenses/>.
 #
-
+import json
 import logging
 from itertools import groupby
 
 from django.conf import settings
-from django.db import DatabaseError, connection
+from django.db import DatabaseError, connection, transaction
 from django.utils.timezone import now
 
 from pretix.base.models import Event, Membership, Quota, Seat, Voucher
 from pretix.testutils.middleware import debugflags_var
 
 logger = logging.getLogger('pretix.base.locking')
+quota_logger = logging.getLogger("pretix_quota")
 
 # A lock acquisition is aborted if it takes longer than LOCK_ACQUISITION_TIMEOUT to prevent connection starvation
 LOCK_ACQUISITION_TIMEOUT = 3
@@ -97,6 +98,10 @@ def lock_objects(objects, *, shared_lock_objects=None, replace_exclusive_with_sh
             "You cannot create locks outside of an transaction"
         )
 
+    quota_logger.debug(json.dumps({
+        "op": "lock_objects",
+        "objects": [{"type": str(type(o)), "pk": o.pk, "str": str(o)} for o in objects],
+    }))
     if 'postgresql' in settings.DATABASES['default']['ENGINE']:
         shared_keys = set(pg_lock_key(obj) for obj in shared_lock_objects) if shared_lock_objects else set()
         exclusive_keys = set(pg_lock_key(obj) for obj in objects)
@@ -120,6 +125,14 @@ def lock_objects(objects, *, shared_lock_objects=None, replace_exclusive_with_sh
     else:
         for model, instances in groupby(objects, key=lambda o: type(o)):
             model.objects.select_for_update().filter(pk__in=[o.pk for o in instances])
+    quota_logger.debug(json.dumps({
+        "op": "lock_objects acquired",
+        "objects": [{"type": str(type(o)), "pk": o.pk, "str": str(o)} for o in objects],
+    }))
+    transaction.on_commit(lambda: quota_logger.debug(json.dumps({
+        "op": "lock_objects released",
+        "reason": "transaction.on_commit",
+    })))
 
 
 class NoLockManager:

src/pretix/base/services/orders.py

@@ -203,6 +203,7 @@ error_messages = {
 }
 
 logger = logging.getLogger(__name__)
+quota_logger = logging.getLogger("pretix_quota")
 
 
 def mark_order_paid(*args, **kwargs):
@@ -694,6 +695,10 @@ def _check_positions(event: Event, now_dt: datetime, time_machine_now_dt: dateti
                 [op.seat for op in sorted_positions if op.seat],
                 shared_lock_objects=[event]
             )
+    else:
+        quota_logger.debug(json.dumps({
+            "op": "_check_items lock skipped due to trust window",
+        }))
 
     # Check availability
     for i, cp in enumerate(sorted_positions):
@@ -811,6 +816,10 @@ def _check_positions(event: Event, now_dt: datetime, time_machine_now_dt: dateti
                 cp.voucher.allow_ignore_quota or (cp.voucher.block_quota and cp.voucher.quota is None)
             )
         )
+        if ignore_all_quotas:
+            quota_logger.debug(json.dumps({
+                "op": "quotas skipped due to trust window or voucher",
+            }))
 
         if not ignore_all_quotas:
             for quota in quotas:
@@ -827,7 +836,15 @@ def _check_positions(event: Event, now_dt: datetime, time_machine_now_dt: dateti
 
         if not quota_ok:
             # Sorry, can't let you keep that!
+            quota_logger.debug(json.dumps({
+                "op": "_check_items quota not ok",
+            }))
             delete(cp)
+        else:
+            quota_logger.debug(json.dumps({
+                "op": "_check_items ok",
+                "q_avail_after": [{"id": q.pk, "str": q.name, "avail": v} for q, v in q_avail.items()]
+            }))
 
     for voucher, cnt in v_usages.items():
         if 0 < cnt < voucher.min_usages_remaining:
@@ -1135,6 +1152,18 @@ def _perform_order(event: Event, payment_requests: List[dict], position_ids: Lis
     ).filter(
         id__in=position_ids, event=event
     )
+    quota_logger.debug(json.dumps({
+        "op": "perform_order positions",
+        "positions": [
+            {
+                "item_id": p.item_id,
+                "variation_id": p.variation_id,
+                "id": p.pk,
+                "addon_to": p.addon_to_id,
+                "expires": p.expires.isoformat(),
+            } for p in positions
+        ]
+    }))
 
     if shown_total is not None and Decimal(shown_total) > Decimal("0.00") and event.currency == "XXX":
         raise OrderError(error_messages['currency_XXX'])
@@ -2806,6 +2835,16 @@ class OrderChangeManager:
             # Do nothing
             return
 
+        quota_logger.debug(json.dumps({
+            "op": "OrderChangeManager.commit start",
+        }))
+        for op in self._operations:
+            quota_logger.debug(json.dumps({
+                "op": "OrderChangeManager.commit operation",
+                "operation_type": str(type(op)),
+                "repr": repr(op),
+            }))
+
         # Clear prefetched objects cache of order. We're going to modify the positions and fees and we have no guarantee
         # that every operation tuple points to a position/fee instance that has been fetched from the same object cache,
         # so it's dangerous to keep the cache around.
@@ -2854,6 +2893,15 @@ class OrderChangeManager:
                 )
 
         order_changed.send(self.order.event, order=self.order)
+        for op in self._operations:
+            quota_logger.debug(json.dumps({
+                "op": "OrderChangeManager.commit operation done",
+                "operation_type": str(type(op)),
+                "repr": repr(op),
+            }))
+        quota_logger.debug(json.dumps({
+            "op": "OrderChangeManager.commit end",
+        }))
 
     def _clear_tickets_cache(self):
         tickets.invalidate_cache.apply_async(kwargs={'event': self.event.pk,
@@ -2877,11 +2925,18 @@ def perform_order(self, event: Event, payments: List[dict], positions: List[str]
                   email: str=None, locale: str=None, address: int=None, meta_info: dict=None,
                   sales_channel: str='web', shown_total=None, customer=None, override_now_dt: datetime=None,
                   api_meta: dict=None):
+    quota_logger.debug(json.dumps({
+        "op": "perform_order start",
+    }))
     with language(locale), time_machine_now_assigned(override_now_dt):
         try:
             try:
-                return _perform_order(event, payments, positions, email, locale, address, meta_info,
-                                      sales_channel, shown_total, customer, api_meta)
+                r = _perform_order(event, payments, positions, email, locale, address, meta_info,
+                                   sales_channel, shown_total, customer, api_meta)
+                quota_logger.debug(json.dumps({
+                    "op": "perform_order end",
+                }))
+                return r
             except LockTimeoutException:
                 self.retry()
         except (MaxRetriesExceededError, LockTimeoutException):
@@ -3012,6 +3067,9 @@ def _try_auto_refund(order, auto_refund=True, manual_refund=False, allow_partial
 def cancel_order(self, order: int, user: int=None, send_mail: bool=True, api_token=None, oauth_application=None,
                  device=None, cancellation_fee=None, try_auto_refund=False, refund_as_giftcard=False,
                  email_comment=None, refund_comment=None, cancel_invoice=True):
+    quota_logger.debug(json.dumps({
+        "op": "cancel_order start",
+    }))
     try:
         try:
             ret = _cancel_order(order, user, send_mail, api_token, device, oauth_application,
@@ -3019,6 +3077,9 @@ def cancel_order(self, order: int, user: int=None, send_mail: bool=True, api_tok
             if try_auto_refund:
                 _try_auto_refund(order, refund_as_giftcard=refund_as_giftcard,
                                  comment=refund_comment)
+            quota_logger.debug(json.dumps({
+                "op": "cancel_order end",
+            }))
             return ret
         except LockTimeoutException:
             self.retry()

src/pretix/base/services/quotas.py

@@ -19,6 +19,8 @@
 # You should have received a copy of the GNU Affero General Public License along with this program.  If not, see
 # <https://www.gnu.org/licenses/>.
 #
+import json
+import logging
 import sys
 import time
 from collections import Counter, defaultdict
@@ -40,6 +42,8 @@ from pretix.base.models import (
 
 from ..signals import quota_availability
 
+quota_logger = logging.getLogger("pretix_quota")
+
 
 class QuotaAvailability:
     """
@@ -146,6 +150,10 @@ class QuotaAvailability:
                                     self.results[q] = int(data[0]), None
                                 else:
                                     self.results[q] = int(data[0]), int(data[1])
+                quota_logger.debug(json.dumps({
+                    "op": "quota_from_cache",
+                    "objects": [{"pk": q.pk, "str": str(q), "result": r} for q, r in self.results.items()],
+                }))
 
         if not quota_ids_set:
             return
@@ -161,6 +169,11 @@ class QuotaAvailability:
                                                       count_waitinglist=self.count_waitinglist):
                 self.results[q] = resp
 
+        quota_logger.debug(json.dumps({
+            "op": "quota_results",
+            "objects": [{"pk": q.pk, "str": str(q), "result": r} for q, r in self.results.items()],
+        }))
+
         self._close(quotas)
         self._write_cache(quotas, now_dt)
 

src/pretix/settings.py

@@ -556,6 +556,13 @@ LOGGING = {
                 else '%(levelname)s %(asctime)s %(name)s %(module)s %(message)s'
             )
         },
+        'quota_default': {
+            'format': (
+                '%(levelname)s %(asctime)s %(thread)d %(threadName)s RequestId=%(request_id)s %(name)s %(module)s %(message)s'
+                if REQUEST_ID_HEADER
+                else '%(levelname)s %(asctime)s %(thread)d %(threadName)s %(name)s %(module)s %(message)s'
+            )
+        },
     },
     'filters': {
         'require_admin_enabled': {
@@ -586,6 +593,13 @@ LOGGING = {
             'formatter': 'default',
             'filters': ['request_id'],
         },
+        'quota_file': {
+            'level': logging.DEBUG,
+            'class': 'logging.FileHandler',
+            'filename': os.path.join(LOG_DIR, 'quota.log'),
+            'formatter': 'quota_default',
+            'filters': ['request_id'],
+        },
         'mail_admins': {
             'level': 'ERROR',
             'class': 'django.utils.log.AdminEmailHandler',
@@ -601,6 +615,11 @@ LOGGING = {
             'level': loglevel,
             'propagate': True,
         },
+        'pretix_quota': {
+            'handlers': ['quota_file'],
+            'level': logging.DEBUG,
+            'propagate': True,
+        },
         'django.request': {
             'handlers': ['file', 'console', 'mail_admins'],
             'level': loglevel,