Enhance payment processing with additional logging and error handling in CreateTransactionView and ConfirmTransactionView

Author: tobiascadee

webapp/finance/views.py

@@ -4,7 +4,7 @@
 from django.contrib import messages
 from django.urls import reverse
 from django.http import HttpResponse, HttpResponseRedirect, Http404
-from django.shortcuts import redirect, get_object_or_404
+from django.shortcuts import redirect
 from django.views.decorators.csrf import csrf_exempt
 from django.views.generic import TemplateView, FormView, View
 from finance.models import Payment
@@ -71,6 +71,27 @@ def post(self, request, *args, **kwargs):
                   "and amount %f" %
                   (order_to_pay.id, amount_to_pay), user=order_to_pay.user)
 
+        # Extra context for debugging before starting external call
+        try:
+            has_succeeded_payment = order_to_pay.payments.filter(succeeded=True).exists()
+        except Exception:
+            has_succeeded_payment = False
+        log_event(
+            event=(
+                "[DEBUG] Payment pre-checks for order %s" % order_to_pay.id
+            ),
+            user=order_to_pay.user,
+            extra=(
+                "finalized=%s, paid=%s, succeeded_payment_exists=%s, round_is_open=%s"
+                % (
+                    order_to_pay.finalized,
+                    order_to_pay.paid,
+                    has_succeeded_payment,
+                    order_to_pay.order_round.is_open,
+                )
+            ),
+        )
+
         if amount_to_pay == 0:
             log_event(
                 event="Payment for order %d not necessary because order total "
@@ -84,8 +105,8 @@ def post(self, request, *args, **kwargs):
             order_to_pay.complete_after_payment()
             return redirect(reverse('order_summary', args=(order_to_pay.pk,)))
 
-        # Sanity checks. If one of these fails, it's very likely that someone
-        # is tampering.
+    # Sanity checks. If one of these fails, it's very likely that someone
+    # is tampering.
         assert order_to_pay.user == request.user
         assert order_to_pay.finalized is True
         assert order_to_pay.paid is False
@@ -103,18 +124,55 @@ def post(self, request, *args, **kwargs):
             return redirect(reverse('finish_order', args=(order_to_pay.id,)))
 
         # Start the payment
-        results = self.create_payment(
-            amount=float(amount_to_pay),
-            description="VOKO Utrecht %d"
-                        % order_to_pay.id,
-            order_id=order_to_pay.id,
+        try:
+            results = self.create_payment(
+                amount=float(amount_to_pay),
+                description="VOKO Utrecht %d" % order_to_pay.id,
+                order_id=order_to_pay.id,
+            )
+            try:
+                mollie_id = results["id"]
+            except Exception:
+                mollie_id = getattr(results, "id", None)
+            checkout_url = getattr(results, "checkout_url", None)
+            status = getattr(results, "status", None)
+            log_event(
+                event=("[DEBUG] Mollie payment created for order %s") % order_to_pay.id,
+                user=order_to_pay.user,
+                extra=("mollie_id=%s, status=%s, checkout_url=%s") % (mollie_id, status, checkout_url),
             )
+        except Exception as e:
+            # Log and surface a friendly error to the user
+            log_event(
+                event=(
+                    "[ERROR] Failed to create Mollie payment for order %s: %s"
+                ) % (order_to_pay.id, e),
+                user=order_to_pay.user,
+            )
+            messages.error(request, "Het aanmaken van de betaling is mislukt. Probeer het later opnieuw.")
+            # Un-freeze order so user can retry
+            order_to_pay.finalized = False
+            order_to_pay.save()
+            return redirect(reverse('finish_order', args=(order_to_pay.id,)))
 
-        Payment.objects.create(amount=amount_to_pay,
-                               order=order_to_pay,
-                               mollie_id=results["id"])
+        Payment.objects.create(
+            amount=amount_to_pay,
+            order=order_to_pay,
+            mollie_id=mollie_id,
+        )
+        log_event(
+            event=(
+                "[DEBUG] Stored local Payment for order %s with mollie_id=%s"
+            ) % (order_to_pay.id, mollie_id),
+            user=order_to_pay.user,
+        )
 
         redirect_url = results.checkout_url
+        log_event(
+            event=("[DEBUG] Redirecting user to Mollie checkout for order %s") % (order_to_pay.id),
+            user=order_to_pay.user,
+            extra=("checkout_url=%s") % redirect_url,
+        )
         return redirect(redirect_url)
 
     def _message_payment_unnecessary(self):
@@ -141,13 +199,29 @@ def get_context_data(self, **kwargs):
 
         order_id = self.request.GET.get('order')
 
+        log_event(
+            event="[DEBUG] ConfirmTransactionView called",
+            user=self.request.user,
+            extra=("user_id=%s, order_id=%s") % (self.request.user.id, order_id),
+        )
+
         # Payment may already be confirmed by the webhook
         try:
             order = Order.objects.get(id=order_id, user=self.request.user)
         except Order.DoesNotExist:
+            log_event(
+                event=("[WARN] ConfirmTransactionView: Order not found"),
+                user=self.request.user,
+                extra=("user_id=%s, order_id=%s") % (self.request.user.id, order_id),
+            )
             raise Http404
 
         if order.paid is True:
+            log_event(
+                event=("[DEBUG] ConfirmTransactionView: order already paid"),
+                user=order.user,
+                extra=("order_id=%s") % order.id,
+            )
             context['payment_succeeded'] = True
             return context
 
@@ -156,10 +230,35 @@ def get_context_data(self, **kwargs):
             .order_by('id').last()
 
         if payment is None:
+            log_event(
+                event=("[WARN] ConfirmTransactionView: No pending Payment found"),
+                user=order.user,
+                extra=("order_id=%s") % order_id,
+            )
             raise Http404
 
-        mollie_payment = self.get_payment(payment.mollie_id)
+        log_event(
+            event=("[DEBUG] ConfirmTransactionView: Fetching Mollie payment status"),
+            user=order.user,
+            extra=("mollie_id=%s, order_id=%s") % (payment.mollie_id, order_id),
+        )
+        try:
+            mollie_payment = self.get_payment(payment.mollie_id)
+        except Exception as e:
+            log_event(
+                event=("[ERROR] ConfirmTransactionView: Failed to fetch Mollie payment"),
+                user=order.user,
+                extra=("mollie_id=%s, order_id=%s, error=%s") % (payment.mollie_id, order_id, e),
+            )
+            context['payment_succeeded'] = False
+            return context
         success = mollie_payment.is_paid()
+        status = getattr(mollie_payment, 'status', None)
+        log_event(
+            event=("[DEBUG] ConfirmTransactionView: Mollie payment status fetched"),
+            user=order.user,
+            extra=("mollie_id=%s, status=%s, is_paid=%s") % (payment.mollie_id, status, success),
+        )
 
         if success:
             if (payment.order.finalized is True
@@ -182,9 +281,11 @@ def get_context_data(self, **kwargs):
                           user=payment.order.user)
 
         else:
-            log_event(event="Payment %s for order %s and amount %f failed" %
-                            (payment.id, payment.order.id, payment.amount),
-                      user=payment.order.user)
+            log_event(
+                event=("Payment failed in confirm view"),
+                user=payment.order.user,
+                extra=("payment_id=%s, order_id=%s, amount=%s, status=%s") % (payment.id, payment.order.id, payment.amount, status),
+            )
 
         context['payment_succeeded'] = success
         return context
@@ -198,15 +299,45 @@ def dispatch(self, request, *args, **kwargs):
     def post(self, request, *args, **kwargs):
         mollie_id = request.POST.get('id')
 
-        payment = get_object_or_404(Payment, mollie_id=mollie_id)
-        mollie_payment = self.get_payment(payment.mollie_id)
+        if not mollie_id:
+            log_event(event="[WARN] Webhook called without Mollie id", user=None)
+            return HttpResponse("", status=404)
+
+        remote = request.META.get('HTTP_X_FORWARDED_FOR') or request.META.get('REMOTE_ADDR')
+        log_event(
+            event=("[DEBUG] Webhook received"),
+            user=None,
+            extra=("mollie_id=%s, remote=%s") % (mollie_id, remote),
+        )
+
+        try:
+            payment = Payment.objects.get(mollie_id=mollie_id)
+        except Payment.DoesNotExist:
+            log_event(event=("[WARN] Webhook for unknown mollie_id"), user=None, extra=("mollie_id=%s") % mollie_id)
+            return HttpResponse("unknown id", status=404)
+
+        try:
+            mollie_payment = self.get_payment(payment.mollie_id)
+        except Exception as e:
+            log_event(
+                event=("[ERROR] Webhook: Failed to fetch Mollie payment"),
+                user=payment.order.user,
+                extra=("mollie_id=%s, order_id=%s, error=%s") % (payment.mollie_id, payment.order.id, e),
+            )
+            return HttpResponse("error", status=500)
         success = mollie_payment.is_paid()
+        status = getattr(mollie_payment, 'status', None)
+        log_event(
+            event=("[DEBUG] Webhook Mollie status fetched"),
+            user=payment.order.user,
+            extra=("mollie_id=%s, status=%s, is_paid=%s, order_id=%s") % (payment.mollie_id, status, success, payment.order.id),
+        )
 
         if not success:
             log_event(
                 event="Payment %s for order %s and amount %f "
-                      "failed via callback" %
-                      (payment.id, payment.order.id, payment.amount),
+                      "failed via callback (Mollie status=%s)" %
+                      (payment.id, payment.order.id, payment.amount, status),
                 user=payment.order.user)
             return HttpResponse("")