diff --git a/webapp/finance/views.py b/webapp/finance/views.py index b42cf235..4b2f037e 100644 --- a/webapp/finance/views.py +++ b/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,12 @@ 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 +300,46 @@ 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("")