From da68cb618e890fb08b44fd0a4548700a65743f16 Mon Sep 17 00:00:00 2001
From: Raphael Michel <mail@raphaelmichel.de>
Date: Wed, 5 Feb 2020 12:02:02 +0100
Subject: [PATCH] Improved logging and transaction handling around payment
 confirmations

---
 src/pretix/base/models/orders.py   |  7 +++++
 src/pretix/base/payment.py         |  2 +-
 src/pretix/base/services/orders.py | 44 ++++++++++++++++--------------
 3 files changed, 31 insertions(+), 22 deletions(-)

diff --git a/src/pretix/base/models/orders.py b/src/pretix/base/models/orders.py
index 95ae8e5333..9935dbc4dc 100644
--- a/src/pretix/base/models/orders.py
+++ b/src/pretix/base/models/orders.py
@@ -1285,6 +1285,9 @@ class OrderPayment(models.Model):
             locked_instance = OrderPayment.objects.select_for_update().get(pk=self.pk)
             if locked_instance.state == self.PAYMENT_STATE_CONFIRMED:
                 # Race condition detected, this payment is already confirmed
+                logger.info('Confirmed payment {} but ignored due to likely race condition.'.format(
+                    self.full_id,
+                ))
                 return
 
             locked_instance.state = self.PAYMENT_STATE_CONFIRMED
@@ -1305,6 +1308,7 @@ class OrderPayment(models.Model):
         }, user=user, auth=auth)
 
         if self.order.status in (Order.STATUS_PAID, Order.STATUS_CANCELED):
+            logger.info('Confirmed payment {} but order is in status {}.'.format(self.full_id, self.order.status))
             return
 
         payment_sum = self.order.payments.filter(
@@ -1315,6 +1319,9 @@ class OrderPayment(models.Model):
                        OrderRefund.REFUND_STATE_CREATED)
         ).aggregate(s=Sum('amount'))['s'] or Decimal('0.00')
         if payment_sum - refund_sum < self.order.total:
+            logger.info('Confirmed payment {} but payment sum is {} and refund sum is.'.format(
+                self.full_id, payment_sum, refund_sum
+            ))
             return
 
         if (self.order.status == Order.STATUS_PENDING and self.order.expires > now() + timedelta(hours=12)) or not lock:
diff --git a/src/pretix/base/payment.py b/src/pretix/base/payment.py
index d28a95fe86..7bfe692e2e 100644
--- a/src/pretix/base/payment.py
+++ b/src/pretix/base/payment.py
@@ -687,7 +687,7 @@ class BasePaymentProvider:
         On failure, you should raise a PaymentException.
         """
         payment.state = OrderPayment.PAYMENT_STATE_CANCELED
-        payment.save()
+        payment.save(update_fields=['state'])
 
     def execute_refund(self, refund: OrderRefund):
         """
diff --git a/src/pretix/base/services/orders.py b/src/pretix/base/services/orders.py
index 673d399018..519f72138a 100644
--- a/src/pretix/base/services/orders.py
+++ b/src/pretix/base/services/orders.py
@@ -11,6 +11,7 @@ from django.core.cache import cache
 from django.db import transaction
 from django.db.models import Exists, F, Max, Min, OuterRef, Q, Sum
 from django.db.models.functions import Coalesce, Greatest
+from django.db.transaction import get_connection
 from django.dispatch import receiver
 from django.utils.functional import cached_property
 from django.utils.timezone import make_aware, now
@@ -1863,6 +1864,9 @@ def cancel_order(self, order: int, user: int=None, send_mail: bool=True, api_tok
 
 def change_payment_provider(order: Order, payment_provider, amount=None, new_payment=None, create_log=True,
                             recreate_invoices=True):
+    if not get_connection().in_atomic_block:
+        raise Exception('change_payment_provider should only be called in atomic transaction!')
+
     oldtotal = order.total
     e = OrderPayment.objects.filter(fee=OuterRef('pk'), state__in=(OrderPayment.PAYMENT_STATE_CONFIRMED,
                                                                    OrderPayment.PAYMENT_STATE_REFUNDED))
@@ -1883,34 +1887,32 @@ def change_payment_provider(order: Order, payment_provider, amount=None, new_pay
     new_fee = payment_provider.calculate_fee(
         order.pending_sum - old_fee if amount is None else amount
     )
-    with transaction.atomic():
-        if new_fee:
-            fee.value = new_fee
-            fee.internal_type = payment_provider.identifier
-            fee._calculate_tax()
-            fee.save()
-        else:
-            if fee.pk:
-                fee.delete()
-            fee = None
+    if new_fee:
+        fee.value = new_fee
+        fee.internal_type = payment_provider.identifier
+        fee._calculate_tax()
+        fee.save()
+    else:
+        if fee.pk:
+            fee.delete()
+        fee = None
 
     open_payment = None
     if new_payment:
-        lp = order.payments.exclude(pk=new_payment.pk).last()
+        lp = order.payments.select_for_update().exclude(pk=new_payment.pk).last()
     else:
-        lp = order.payments.last()
-    if lp and lp.state not in (OrderPayment.PAYMENT_STATE_CONFIRMED, OrderPayment.PAYMENT_STATE_REFUNDED):
+        lp = order.payments.select_for_update().last()
+
+    if lp and lp.state in (OrderPayment.PAYMENT_STATE_PENDING, OrderPayment.PAYMENT_STATE_CREATED):
         open_payment = lp
 
-    if open_payment and open_payment.state in (OrderPayment.PAYMENT_STATE_PENDING,
-                                               OrderPayment.PAYMENT_STATE_CREATED):
+    if open_payment:
         try:
-            with transaction.atomic():
-                open_payment.payment_provider.cancel_payment(open_payment)
-                order.log_action('pretix.event.order.payment.canceled', {
-                    'local_id': open_payment.local_id,
-                    'provider': open_payment.provider,
-                })
+            open_payment.payment_provider.cancel_payment(open_payment)
+            order.log_action('pretix.event.order.payment.canceled', {
+                'local_id': open_payment.local_id,
+                'provider': open_payment.provider,
+            })
         except PaymentException as e:
             order.log_action(
                 'pretix.event.order.payment.canceled.failed',