Add OrderPayment.fail() to prevent race conditions (#1572)

src/pretix/base/models/orders.py

@@ -1258,6 +1258,36 @@ class OrderPayment(models.Model):
             self.order.log_action('pretix.event.order.overpaid', {}, user=user, auth=auth)
         order_paid.send(self.order.event, order=self.order)
 
+    def fail(self, info=None, user=None, auth=None):
+        """
+        Marks the order as failed and sets info to ``info``, but only if the order is in ``created`` or ``pending``
+        state. This is equivalent to setting ``state`` to ``OrderPayment.PAYMENT_STATE_FAILED`` and logging a failure,
+        but it adds strong database logging since we do not want to report a failure for an order that has just
+        been marked as paid.
+        """
+        with transaction.atomic():
+            locked_instance = OrderPayment.objects.select_for_update().get(pk=self.pk)
+            if locked_instance.state not in (OrderPayment.PAYMENT_STATE_CREATED, OrderPayment.PAYMENT_STATE_PENDING):
+                # Race condition detected, this payment is already confirmed
+                logger.info('Failed payment {} but ignored due to likely race condition.'.format(
+                    self.full_id,
+                ))
+                return
+
+            if isinstance(info, str):
+                locked_instance.info = info
+            elif info:
+                locked_instance.info_data = info
+            locked_instance.state = OrderPayment.PAYMENT_STATE_FAILED
+            locked_instance.save(update_fields=['state', 'info'])
+
+        self.refresh_from_db()
+        self.order.log_action('pretix.event.order.payment.failed', {
+            'local_id': self.local_id,
+            'provider': self.provider,
+            'info': info,
+        }, user=user, auth=auth)
+
     def confirm(self, count_waitinglist=True, send_mail=True, force=False, user=None, auth=None, mail_text='',
                 ignore_date=False, lock=True, payment_date=None):
         """

src/pretix/plugins/paypal/payment.py

@@ -359,12 +359,7 @@ class Paypal(BasePaymentProvider):
             return
 
         if payment.state != 'approved':
-            payment_obj.state = OrderPayment.PAYMENT_STATE_FAILED
+            payment_obj.fail(info=str(payment))
-            payment_obj.save()
-            payment_obj.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-            })
             logger.error('Invalid state: %s' % str(payment))
             raise PaymentException(_('We were unable to process your payment. See below for details on how to '
                                      'proceed.'))

src/pretix/plugins/stripe/payment.py

@@ -375,16 +375,9 @@ class StripeMethod(BasePaymentProvider):
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
             logger.info('Stripe card error: %s' % str(err))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('Stripe reported an error with your card: %s') % err['message'])
 
@@ -395,16 +388,9 @@ class StripeMethod(BasePaymentProvider):
             else:
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('We had trouble communicating with Stripe. Please try again and get in touch '
                                      'with us if this problem persists.'))
@@ -432,14 +418,7 @@ class StripeMethod(BasePaymentProvider):
                 return
             else:
                 logger.info('Charge failed: %s' % str(charge))
-                payment.info = str(charge)
+                payment.fail(info=str(charge))
-                payment.state = OrderPayment.PAYMENT_STATE_FAILED
-                payment.save()
-                payment.order.log_action('pretix.event.order.payment.failed', {
-                    'local_id': payment.local_id,
-                    'provider': payment.provider,
-                    'info': str(charge)
-                })
                 raise PaymentException(_('Stripe reported an error: %s') % charge.failure_message)
 
     def payment_pending_render(self, request, payment) -> str:
@@ -540,16 +519,9 @@ class StripeMethod(BasePaymentProvider):
             else:
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('We had trouble communicating with Stripe. Please try again and get in touch '
                                      'with us if this problem persists.'))
@@ -712,16 +684,9 @@ class StripeCC(StripeMethod):
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
             logger.info('Stripe card error: %s' % str(err))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('Stripe reported an error with your card: %s') % err['message'])
 
@@ -732,16 +697,9 @@ class StripeCC(StripeMethod):
             else:
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('We had trouble communicating with Stripe. Please try again and get in touch '
                                      'with us if this problem persists.'))
@@ -786,20 +744,11 @@ class StripeCC(StripeMethod):
             elif intent.status == 'requires_payment_method':
                 if request:
                     messages.warning(request, _('Your payment failed. Please try again.'))
-                payment.info = str(intent)
+                payment.fail(info=str(intent))
-                payment.state = OrderPayment.PAYMENT_STATE_FAILED
-                payment.save()
                 return
             else:
                 logger.info('Charge failed: %s' % str(intent))
-                payment.info = str(intent)
+                payment.fail(info=str(intent))
-                payment.state = OrderPayment.PAYMENT_STATE_FAILED
-                payment.save()
-                payment.order.log_action('pretix.event.order.payment.failed', {
-                    'local_id': payment.local_id,
-                    'provider': payment.provider,
-                    'info': str(intent)
-                })
                 raise PaymentException(_('Stripe reported an error: %s') % intent.last_payment_error.message)
 
     def _confirm_payment_intent(self, request, payment):
@@ -830,16 +779,9 @@ class StripeCC(StripeMethod):
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
             logger.info('Stripe card error: %s' % str(err))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('Stripe reported an error with your card: %s') % err['message'])
         except stripe.error.InvalidRequestError as e:
@@ -849,16 +791,9 @@ class StripeCC(StripeMethod):
             else:
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('We had trouble communicating with Stripe. Please try again and get in touch '
                                      'with us if this problem persists.'))
@@ -1362,16 +1297,9 @@ class StripeWeChatPay(StripeMethod):
             else:
                 err = {'message': str(e)}
                 logger.exception('Stripe error: %s' % str(e))
-            payment.info_data = {
+            payment.fail(info={
                 'error': True,
                 'message': err['message'],
-            }
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.save()
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'message': err['message']
             })
             raise PaymentException(_('We had trouble communicating with Stripe. Please try again and get in touch '
                                      'with us if this problem persists.'))

src/pretix/plugins/stripe/views.py

@@ -297,14 +297,7 @@ def charge_webhook(event, event_json, charge_id, rso):
         except Quota.QuotaExceededException:
             pass
     elif charge['status'] == 'failed' and payment.state in (OrderPayment.PAYMENT_STATE_PENDING, OrderPayment.PAYMENT_STATE_CREATED):
-        payment.info = str(charge)
+        payment.fail(info=str(charge))
-        payment.state = OrderPayment.PAYMENT_STATE_FAILED
-        payment.save()
-        payment.order.log_action('pretix.event.order.payment.failed', {
-            'local_id': payment.local_id,
-            'provider': payment.provider,
-            'info': str(charge)
-        })
 
     return HttpResponse(status=200)
 
@@ -368,14 +361,7 @@ def source_webhook(event, event_json, source_id, rso):
                 logger.exception('Webhook error')
 
         elif src.status == 'failed':
-            payment.info = str(src)
+            payment.fail(info=str(src))
-            payment.state = OrderPayment.PAYMENT_STATE_FAILED
-            payment.order.log_action('pretix.event.order.payment.failed', {
-                'local_id': payment.local_id,
-                'provider': payment.provider,
-                'info': str(src)
-            })
-            payment.save()
         elif src.status == 'canceled' and payment.state in (OrderPayment.PAYMENT_STATE_PENDING, OrderPayment.PAYMENT_STATE_CREATED):
             payment.info = str(src)
             payment.state = OrderPayment.PAYMENT_STATE_CANCELED
@@ -510,14 +496,7 @@ class ReturnView(StripeOrderView, View):
                 self.payment.info = str(src)
                 self.payment.save()
             else:  # failed or canceled
-                self.payment.state = OrderPayment.PAYMENT_STATE_FAILED
+                self.payment.fail(info=str(src))
-                self.payment.info = str(src)
-                self.payment.save()
-                self.payment.order.log_action('pretix.event.order.payment.failed', {
-                    'local_id': self.payment.local_id,
-                    'provider': self.payment.provider,
-                    'info': str(src)
-                })
                 messages.error(self.request, _('We had trouble authorizing your card payment. Please try again and '
                                                'get in touch with us if this problem persists.'))
         return self._redirect_to_order()