diff --git a/src/pretix/base/services/cart.py b/src/pretix/base/services/cart.py index 6382c88de7..425b5da2c9 100644 --- a/src/pretix/base/services/cart.py +++ b/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,)) diff --git a/src/pretix/base/services/locking.py b/src/pretix/base/services/locking.py index 08237c42ca..7aff024baf 100644 --- a/src/pretix/base/services/locking.py +++ b/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 # . # - +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: diff --git a/src/pretix/base/services/orders.py b/src/pretix/base/services/orders.py index 2e08f9316c..906aac4665 100644 --- a/src/pretix/base/services/orders.py +++ b/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() diff --git a/src/pretix/base/services/quotas.py b/src/pretix/base/services/quotas.py index 4511309e7d..89abcad86b 100644 --- a/src/pretix/base/services/quotas.py +++ b/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 # . # +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) diff --git a/src/pretix/settings.py b/src/pretix/settings.py index 49a9db52be..90082c405d 100644 --- a/src/pretix/settings.py +++ b/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,