laravel / cashier-mollie

MIT License
375 stars 63 forks source link

Mollie payment status for order not updated after incoming payment webhook #100

Closed DevyDalton closed 5 years ago

DevyDalton commented 5 years ago

It appears that the mollie payment status in the order table is not updated with an incoming payment webhook.

I checked the WebhookController and it looks like the Order::findByPaymentId method is not returning the order.

// Laravel\Cashier\Http\Controllers\WebhookController

class WebhookController extends BaseWebhookController
{
    /**
     * @param Request $request
     * @return Response
     * @throws \Mollie\Api\Exceptions\ApiException Only in debug mode
     */
    public function handleWebhook(Request $request)
    {
        $payment = $this->getPaymentById($request->get('id'));

        if($payment) {
            $order = Order::findByPaymentId($payment->id);
            if ($order && $order->status !== $payment->status) {
                switch ($payment->status) {
                    case PaymentStatus::STATUS_PAID:
                        $order->handlePaymentPaid();
                        break;
                    case PaymentStatus::STATUS_FAILED:
                        $order->handlePaymentFailed();
                        break;
                    default:
                        break;
                }
            }
        }

        return new Response(null, 200);
    }
}

I checked the method in Plan model class and tested it outside the WebhookController with the same payment id. Then the Order is returned so the method seems to work. I also tested it in a new Laravel installation but there i have te same problem, mollie payment status is not updated. Does anyone have the same problem?

// Laravel\Cashier\Order\Order

/**
* Retrieve an Order by the Mollie Payment id.
*
* @param $id
* @return self
*/
public static function findByPaymentId($id)
{
       return self::whereMolliePaymentId($id)->first();
}
sandervanhooft commented 5 years ago

Hi @DevyDalton ,

I can't reproduce the problem.

  1. Can Mollie call your webhooks? You can check this in the Mollie dashboard for each Payment.
  2. Is this about the First Payment (via the Mollie checkout), subsequent premandated payments, or both? Each flow has its own route, controller etc. .
DevyDalton commented 5 years ago

Hi @sandervanhooft

Thanks for your awnser. Mollie can call my webhooks. The Mollie dashboard also shows that the webhooks be called successfull. It only concerns the subsequent premandated payments, first payment goes well.

In the WebhookController I do receive the payment response from Mollie (with status paid). Only the retrieval of the order (findByPaymentId) returns null. If i check the database there is an Order with the same Mollie payment id as i receive in the payment response from Mollie in the WebhookController.

P.s. I am very grateful for this package. Awesome job!

sandervanhooft commented 5 years ago

Hi @DevyDalton,

Thank you for the kind words :).

I've just written and run this test, seems to work ok, so I'm not sure what's going on:

/** @test */
    public function findByMolliePaymentIdWorks()
    {
        $order = factory(Order::class)->create(['mollie_payment_id' => 'tr_xxxxx1234dummy']);
        $otherOrder = factory(Order::class)->create(['mollie_payment_id' => 'tr_wrong_order']);

        $found = Order::findByPaymentId('tr_xxxxx1234dummy');

        $this->assertTrue($found->is($order));
        $this->assertTrue($found->isNot($otherOrder));
    }
sandervanhooft commented 5 years ago

Modified it a bit further, but it can be found here now.

DevyDalton commented 5 years ago

@sandervanhooft I did the same thing and for me it worked as well. But if I test it with "real" mollie payment it doesn't update the payment status for the order.

I also tested it with a new Laravel installation but there i have the same problem. I already spent a couple of hours(learned a few nice new things exploring this package) to find the problemen but I can't figure it out.

sandervanhooft commented 5 years ago

I hacked a bit into the WebhookController to debug the problem:

class WebhookController extends BaseWebhookController
{
    /**
     * @param Request $request
     * @return Response
     * @throws \Mollie\Api\Exceptions\ApiException Only in debug mode
     */
    public function handleWebhook(Request $request)
    {
        Log::info('Webhook called with id', [$request->get('id')]);
        $payment = $this->getPaymentById($request->get('id'));
        Log::info('Get payment ' . $payment->id, [$payment]);

        if($payment) {
            $order = Order::findByPaymentId($payment->id);
            Log::info('Retrieved order', [$order]);

            if ($order && $order->mollie_payment_status !== $payment->status) {
                switch ($payment->status) {
                    case PaymentStatus::STATUS_PAID:
                        $order->handlePaymentPaid();
                        Log::info('Handled payment paid', [$order->refresh()]);
                        break;
                    case PaymentStatus::STATUS_FAILED:
                        $order->handlePaymentFailed();
                        Log::info('Handled payment failed', [$order->refresh()]);
                        break;
                    default:
                        Log::info('Did nothing', [$order->refresh()]);
                        break;
                }
            }
        }

        return new Response(null, 200);
    }
}
sandervanhooft commented 5 years ago

And tested the call with curl:

(updated)


curl -d "id=tr_fuA2z24GD9" -X POST https://7cd8ac31.ngrok.io/webhooks/mollie```
sandervanhooft commented 5 years ago

Found 1 bug:

if ($order && $order->status !== $payment->status) {

should be

if ($order && $order->mollie_payment_status !== $payment->status) {
sandervanhooft commented 5 years ago

Next, it's also good to know that Mollie does not automatically update the payment status to paid when it's in test mode AND it's a premandated payment. You can fetch an url to do so manually from the payment object.

sandervanhooft commented 5 years ago

I'll fix the bug now, let's go from there.

sandervanhooft commented 5 years ago

BTW, this was the log

[2019-10-25 13:40:21] local.INFO: Webhook called with id ["tr_fuA2z24GD9"] 
[2019-10-25 13:40:21] local.INFO: Get payment tr_fuA2z24GD9 ["[object] (Mollie\\Api\\Resources\\Payment: {\"resource\":\"payment\",\"id\":\"tr_fuA2z24GD9\",\"mode\":\"test\",\"amount\":{\"value\":\"7.10\",\"currency\":\"EUR\"},\"settlementAmount\":{\"value\":\"7.10\",\"currency\":\"EUR\"},\"amountRefunded\":{\"value\":\"0.00\",\"currency\":\"EUR\"},\"amountRemaining\":{\"value\":\"32.10\",\"currency\":\"EUR\"},\"description\":\"Order 2019-0000-0002\",\"method\":\"directdebit\",\"status\":\"paid\",\"createdAt\":\"2019-10-25T13:32:40+00:00\",\"paidAt\":\"2019-10-25T13:40:20+00:00\",\"canceledAt\":null,\"expiresAt\":null,\"failedAt\":null,\"profileId\":\"pfl_HbC2MJ3mGj\",\"sequenceType\":\"recurring\",\"redirectUrl\":null,\"webhookUrl\":\"https://7cd8ac31.ngrok.io/webhooks/mollie\",\"mandateId\":\"mdt_j4xUfucgKj\",\"subscriptionId\":null,\"orderId\":null,\"settlementId\":null,\"locale\":\"nl_NL\",\"metadata\":null,\"details\":{\"transferReference\":\"SD06-4858-7045-6085\",\"creditorIdentifier\":\"NL08ZZZ502057730000\",\"consumerName\":\"T. TEST\",\"consumerAccount\":\"NL17RABO0213698412\",\"consumerBic\":\"ABNANL2A\",\"dueDate\":\"2019-10-29\",\"signatureDate\":\"2019-10-24\"},\"_links\":{\"self\":{\"href\":\"https://api.mollie.com/v2/payments/tr_fuA2z24GD9\",\"type\":\"application/hal+json\"},\"changePaymentState\":{\"href\":\"https://www.mollie.com/paymentscreen/testmode/?method=directdebit&token=1.njjigm\",\"type\":\"text/html\"},\"customer\":{\"href\":\"https://api.mollie.com/v2/customers/cst_UnNueWufh5\",\"type\":\"application/hal+json\"},\"mandate\":{\"href\":\"https://api.mollie.com/v2/customers/cst_UnNueWufh5/mandates/mdt_j4xUfucgKj\",\"type\":\"application/hal+json\"},\"documentation\":{\"href\":\"https://docs.mollie.com/reference/v2/payments-api/get-payment\",\"type\":\"text/html\"}},\"_embedded\":null,\"isCancelable\":null,\"countryCode\":\"NL\",\"customerId\":\"cst_UnNueWufh5\"})"] 
[2019-10-25 13:40:21] local.INFO: Retrieved order ["[object] (Laravel\\Cashier\\Order\\Order: {\"id\":2,\"owner_type\":\"App\\\\User\",\"owner_id\":1,\"number\":\"2019-0000-0002\",\"currency\":\"EUR\",\"subtotal\":500,\"tax\":210,\"total\":710,\"balance_before\":0,\"credit_used\":0,\"total_due\":710,\"mollie_payment_id\":\"tr_fuA2z24GD9\",\"mollie_payment_status\":\"open\",\"processed_at\":\"2019-10-25 13:32:41\",\"created_at\":\"2019-10-25 13:32:38\",\"updated_at\":\"2019-10-25 13:32:41\"})"] 
[2019-10-25 13:40:21] local.INFO: Handled payment paid ["[object] (Laravel\\Cashier\\Order\\Order: {\"id\":2,\"owner_type\":\"App\\\\User\",\"owner_id\":1,\"number\":\"2019-0000-0002\",\"currency\":\"EUR\",\"subtotal\":500,\"tax\":210,\"total\":710,\"balance_before\":0,\"credit_used\":0,\"total_due\":710,\"mollie_payment_id\":\"tr_fuA2z24GD9\",\"mollie_payment_status\":\"paid\",\"processed_at\":\"2019-10-25 13:32:41\",\"created_at\":\"2019-10-25 13:32:38\",\"updated_at\":\"2019-10-25 13:40:21\",\"items\":[{\"id\":1,\"process_at\":\"2019-10-24 14:55:30\",\"orderable_type\":\"Laravel\\\\Spark\\\\Subscription\",\"orderable_id\":1,\"owner_type\":\"App\\\\User\",\"owner_id\":1,\"description\":\"Monthly payment\",\"description_extra_lines\":[\"From 2019-11-24 to 2019-12-24\"],\"currency\":\"EUR\",\"quantity\":1,\"unit_price\":1000,\"tax_percentage\":\"21.0000\",\"order_id\":2,\"created_at\":\"2019-10-24 14:55:30\",\"updated_at\":\"2019-10-25 13:32:38\"},{\"id\":4,\"process_at\":\"2019-10-25 13:32:38\",\"orderable_type\":\"Laravel\\\\Cashier\\\\Coupon\\\\AppliedCoupon\",\"orderable_id\":2,\"owner_type\":\"App\\\\User\",\"owner_id\":1,\"description\":\"Welcome to Spark Mollie Test\",\"description_extra_lines\":null,\"currency\":\"EUR\",\"quantity\":1,\"unit_price\":-500,\"tax_percentage\":\"0.0000\",\"order_id\":2,\"created_at\":\"2019-10-25 13:32:38\",\"updated_at\":\"2019-10-25 13:32:38\"}]})"]
DevyDalton commented 5 years ago

@sandervanhooft Thanks for your input. I updated the WebhookController as well. I did a test payment with Mollie. This is my log. I don't understand why the findByPaymentId returns null.

[2019-10-25 15:52:45] local.INFO: Webhook called with id ["tr_wB6NmgjwfW"] 
[2019-10-25 15:52:45] local.INFO: Get payment tr_wB6NmgjwfW ["[object] (Mollie\\Api\\Resources\\Payment: {\"resource\":\"payment\",\"id\":\"tr_wB6NmgjwfW\",\"mode\":\"test\",\"amount\":{\"value\":\"10.89\",\"currency\":\"EUR\"},\"settlementAmount\":{\"value\":\"10.89\",\"currency\":\"EUR\"},\"amountRefunded\":{\"value\":\"0.00\",\"currency\":\"EUR\"},\"amountRemaining\":{\"value\":\"10.89\",\"currency\":\"EUR\"},\"description\":\"Order 2019-0000-0296\",\"method\":\"creditcard\",\"status\":\"paid\",\"createdAt\":\"2019-10-25T13:52:40+00:00\",\"paidAt\":\"2019-10-25T13:52:40+00:00\",\"canceledAt\":null,\"expiresAt\":null,\"failedAt\":null,\"profileId\":\"pfl_HpgP5aT7mP\",\"sequenceType\":\"recurring\",\"redirectUrl\":null,\"webhookUrl\":\"https://6454af.eu.ngrok.io/webhooks/mollie\",\"mandateId\":\"mdt_bSGqVGt8N7\",\"subscriptionId\":null,\"orderId\":null,\"settlementId\":null,\"locale\":\"nl_NL\",\"metadata\":null,\"details\":{\"cardNumber\":\"6787\",\"cardHolder\":\"T. TEST\",\"cardAudience\":\"consumer\",\"cardLabel\":\"Mastercard\",\"cardCountryCode\":\"NL\",\"cardSecurity\":\"normal\",\"feeRegion\":\"other\"},\"_links\":{\"self\":{\"href\":\"https://api.mollie.com/v2/payments/tr_wB6NmgjwfW\",\"type\":\"application/hal+json\"},\"changePaymentState\":{\"href\":\"https://www.mollie.com/paymentscreen/testmode/?method=creditcard&token=1.ycia04\",\"type\":\"text/html\"},\"customer\":{\"href\":\"https://api.mollie.com/v2/customers/cst_MGy7FeqtNv\",\"type\":\"application/hal+json\"},\"mandate\":{\"href\":\"https://api.mollie.com/v2/customers/cst_MGy7FeqtNv/mandates/mdt_bSGqVGt8N7\",\"type\":\"application/hal+json\"},\"documentation\":{\"href\":\"https://docs.mollie.com/reference/v2/payments-api/get-payment\",\"type\":\"text/html\"}},\"_embedded\":null,\"isCancelable\":null,\"customerId\":\"cst_MGy7FeqtNv\"})"] 
[2019-10-25 15:52:45] local.INFO: Retrieved order [null] 
sandervanhooft commented 5 years ago

Me neither... πŸ€·β€β™‚ πŸ˜…

sandervanhooft commented 5 years ago

Did you make any webhook-related changes to the configs?

sandervanhooft commented 5 years ago

or in the create_orders_table migration?

DevyDalton commented 5 years ago

I fetch the plans from the database as discussed in this issue: #69. I didn't changed anything in the orders migration.

But like I sad before I also experienced it on a fresh Laravel installation with the default settings. So I think its unlikely that has something to do with the database plans config. But I will investigate a bit more in the fresh Laravel setup with the default settings.

sandervanhooft commented 5 years ago

I've added a findPaymentByIdOrFail method for your convenience. It's on the develop branch now.

sandervanhooft commented 5 years ago

And I've simplified the findPaymentById and findPaymentByIdOrFail methods just now. It's also on the develop branch.

sandervanhooft commented 5 years ago

What Laravel version are you on? What db are you using? It's a strange issue...

DevyDalton commented 5 years ago

Our app uses Laravel 5.8, and the fresh Laravel installation is 6.3. MySQL database on InnoDB engine with utf8mb4_unicode_ci collation.

But its a very strange issue πŸ˜…

sandervanhooft commented 5 years ago

Hm nothing exotic in that setup...

sandervanhooft commented 5 years ago

The other way around... Can you fetch the payment like this? (by heart, not tested)

$order = \Laravel\Cashier\Order\Order::processed()->firstOrFail();
$payment = mollie()->payments()->get($order->mollie_payment_id);
dd($payment);
DevyDalton commented 5 years ago

Yes I can fetch the payment like that. The same payment that I receive in the WebhookController, only with that payment id, the order can not be found. If I try to find the order like this then the order is returned.

$order = \Laravel\Cashier\Order\Order::processed()->firstOrFail();
$payment = mollie()->payments()->get($order->mollie_payment_id);

$ord = \Laravel\Cashier\Order\Order::findByPaymentId($payment->id);

dd($ord);
sandervanhooft commented 5 years ago

Works here πŸ€·β€β™‚

DevyDalton commented 5 years ago

I found the problem. Mollie is to fast with calling the webhook(or my Homestead setup to slow πŸ˜…). The query to save the mollie_payment_id which is created with the create payment call is not finished yet. So when the webhook is called the mollie_payment_id is not filled for the order.

Now I use the findByPaymentIdOrFail method instead of the findByPaymentId. Now the first webhook call from Mollie always fails but the second will update the payment status.

Later I will test this in an other environment to see if only occurs on my local machine.

DevyDalton commented 5 years ago

I tested this on my development(small $10 digital ocean) server and I experienced the same problem.

sandervanhooft commented 5 years ago

I'm not convinced yet concurrency is the problem here.

sandervanhooft commented 5 years ago

It's possible though. But it would mean that Mollie's webhook call is faster than processing this.

sandervanhooft commented 5 years ago

Maybe we could:

  1. create a UUID
  2. store it in the $order->mollie_payment_id (before creating the payment)
  3. store it in the payment's metadata
  4. then update the $order->mollie_payment_id as usual
  5. in the WebhookController, use the UUID (from the payment metadata) as fallback for retrieving the right Order
sandervanhooft commented 5 years ago

This would solve the concurrency issue (if that's the case)

DevyDalton commented 5 years ago

Ok I will play around a little bit with this solution(maybe not today) but I will let you know the results.

sandervanhooft commented 5 years ago

Modified WebhookController:

<?php

namespace Laravel\Cashier\Http\Controllers;

use Illuminate\Http\Request;
use Laravel\Cashier\Order\Order;
use Mollie\Api\Resources\Payment;
use Mollie\Api\Types\PaymentStatus;
use Symfony\Component\HttpFoundation\Response;

class WebhookController extends BaseWebhookController
{
    /**
     * @param Request $request
     * @return Response
     * @throws \Mollie\Api\Exceptions\ApiException Only in debug mode
     */
    public function handleWebhook(Request $request)
    {
        $payment = $this->getPaymentById($request->get('id'));

        if($payment) {
            $order = $this->getOrder($payment);

            if ($order && $order->mollie_payment_status !== $payment->status) {
                switch ($payment->status) {
                    case PaymentStatus::STATUS_PAID:
                        $order->handlePaymentPaid();
                        break;
                    case PaymentStatus::STATUS_FAILED:
                        $order->handlePaymentFailed();
                        break;
                    default:
                        break;
                }
            }
        }

        return new Response(null, 200);
    }

    /**
     * @param \Mollie\Api\Resources\Payment $payment
     * @return \Laravel\Cashier\Order\Order|null
     */
    protected function getOrder(Payment $payment)
    {
        $order = Order::findByPaymentId($payment->id);

        if(!$order) {
            if(isset($payment->metadata, $payment->metadata->temporary_mollie_payment_id)) {
                $uuid = $payment->metadata->temporary_payment_id;
                $order = Order::findByPaymentId($uuid);
            }
        }

        return $order;
    }
}
sandervanhooft commented 5 years ago

Modified Order.processPayment():

/**
     * Processes the Order into Credit, Refund or Mollie Payment - whichever is appropriate.
     *
     * @return $this
     * @throws \Laravel\Cashier\Exceptions\InvalidMandateException
     */
    public function processPayment()
    {
        $mandate = $this->owner->mollieMandate();
        $this->guardMandate($mandate);
        $minimumPaymentAmount = app(MinimumPayment::class)::forMollieMandate($mandate, $this->getCurrency());
        $this->update(['mollie_payment_id' => Str::uuid()]); //new

        DB::transaction(function () use ($minimumPaymentAmount) {
            $owner = $this->owner;

            // Process user balance, if any
            if($owner->hasCredit($this->currency)) {
                $total = $this->getTotal();
                $this->balance_before = $owner->credit($this->currency)->value;

                $creditUsed = $owner->maxOutCredit($total);
                $this->credit_used = (int) $creditUsed->getAmount();
                $this->total_due = $total->subtract($creditUsed)->getAmount();
            }

            $totalDue = money($this->total_due, $this->currency);

            switch(true) {
                case $totalDue->isZero():
                    break; // No payment processing required

                case $totalDue->lessThan($minimumPaymentAmount):

                    // Add credit to the owner's balance
                    $credit = Credit::addAmountForOwner($owner, money(-($this->total_due), $this->currency));

                    if (! $owner->hasActiveSubscriptionWithCurrency($this->currency)) {
                        Event::dispatch(new BalanceTurnedStale($credit));
                    }
                    break;

                case $totalDue->greaterThanOrEqual($minimumPaymentAmount):

                    // Create Mollie payment
                    $payment = (new MandatedPaymentBuilder(
                        $owner,
                        "Order " . $this->number,
                        $totalDue,
                        url(config('cashier.webhook_url')),
                        ['temporary_mollie_payment_id' => $this->mollie_payment_id] //new
                    ))->create();

                    $this->mollie_payment_id = $payment->id;
                    $this->mollie_payment_status = 'open';
                    break;

                default:
                    break;
            }

            $this->processed_at = now();
            $this->save();
        });

        Event::dispatch(new OrderProcessed($this));

        return $this;
    }
sandervanhooft commented 5 years ago

Haven't tested it, feel free to give it a spin when you can.

sandervanhooft commented 5 years ago

If this does not resolve the issue, keep an eye on DB::transactionLevel() while setting the uuid. The DB transaction may be delaying the db writes here.

sandervanhooft commented 5 years ago

Hi @DevyDalton any news on this?

sandervanhooft commented 5 years ago

I've included a fix in the development branch. Plan on releasing Monday / Tuesday. See #106