Overpaid orders due to duplicate transactions

[jerome2710]

Description

We have been noticing some overpaid orders in one of our clients Commerce-instances lately. While this wasn't a major issue at the time (albeit being undesirable behavior of course), some orders have now been sent to our fulfillment partner twice, as a result of the Order::EVENT_AFTER_ORDER_PAID.

As seen in the screenshot above, two transactions were recorded for this order. While Mollie both uses the redirect-action and the webhooks in the background, I suspect that both of these are handled as separate transactions. The webhook-processor does actually check if there's already a successful transaction for the order, but it might be that the redirect and webhook are so close to each other, that either request is not finished yet and both get recorded.

Digging through the plugin-code, I recognized the warning-message. We have been receiving quite some of these messages lately. This would confirm my theory, but luckily the redirect and webhook are not always close enough that they will produce this issue.

Orders being marked as "overpaid" in Craft are not a major problem, but when they're sent to the fulfillment partner twice and actually get shipped twice, we start to get nervous. Could we find some sort of solution to prevent this from happening?

Additional info

• Craft version: 3.5.17.1
• PHP version: 7.2.34
• Database driver & version: MySQL 5.5.68
• Plugins & versions: Craft Commerce 3.2.13.2, Mollie for Craft Commerce 2.1.2 and much more

[jerome2710]

Any idea when we could get an update on this matter?

[nfourtythree]

Hi @jerome2710

This is an interesting one, I have been unable to replicate this issue.

As you mentioned there are processes in place to stop this from happening. We use a mutex lock to prevent race conditions issues and (as you pointed out) we check for other successful child transactions to prevent them from being registered more than once.

Looking at the times in the screenshot it appears unlikely that it is a race condition because the are 30 seconds apart.

The only way that it would get past the code is if it couldn't find a successful transaction.

I would be interested to see what the payload is for these requests to be able to determine what was sent to Commerce and when. Is that information you are able to retrieve from your logs or the Mollie dashboard?

Thanks

[jerome2710]

Hi @nfourtythree,

Thank you for your detailed reply. I understand that this might be rather hard to reproduce and fix. The warning-message I mentioned gets logged in our error tracking service a few times a day, of course depending on the amount of orders our client has at that time. This also results in the 'overpaid' issue every once in a while.

Please find the payload for one of these orders below. I have redacted any personal information with .... The payload for both transactions seem to be the same every time.

{
    "resource": "payment",
    "id": "...",
    "mode": "live",
    "createdAt": "2021-03-12T14:59:04+00:00",
    "amount": {
        "value": "35.95",
        "currency": "EUR"
    },
    "description": "Order #542838",
    "method": "creditcard",
    "metadata": {
        "transactionId": "54868....."
    },
    "status": "paid",
    "paidAt": "2021-03-12T15:00:04+00:00",
    "amountRefunded": {
        "value": "0.00",
        "currency": "EUR"
    },
    "amountRemaining": {
        "value": "35.95",
        "currency": "EUR"
    },
    "profileId": "....",
    "sequenceType": "oneoff",
    "redirectUrl": "...",
    "webhookUrl": "...",
    "settlementAmount": {
        "value": "35.95",
        "currency": "EUR"
    },
    "details": {
        "cardFingerprint": "...",
        "cardNumber": "...",
        "cardHolder": "...",
        "cardAudience": "...",
        "cardLabel": "...",
        "cardCountryCode": "...",
        "cardSecurity": "...",
        "feeRegion": "..."
    },
    "_links": {
        "self": {
            "href": "https://api.mollie.com/v2/payments/...",
            "type": "application/hal+json"
        },
        "dashboard": {
            "href": "https://www.mollie.com/dashboard/.../payments/...",
            "type": "text/html"
        },
        "documentation": {
            "href": "https://docs.mollie.com/reference/v2/payments-api/get-payment",
            "type": "text/html"
        }
    }
}

Pleaae do let me know if you need anything else.

[jerome2710]

Hi @nfourtythree, any updates on this issue? :-) We are still receiving errors in our logging daily.

[nfourtythree]

Hi @jerome2710

As I mentioned before I am still unable to replicate the issue of multiple successful child transactions (causing an order to look overpaid).

Seeing this warning appearing in your logs is absolutely fine. This means that the code is doing its job to prevent duplicate transactions from being registered. This is because there is a chance that mollie could be calling back to your application multiple times/ways.

In the screenshot you shared above what are the IDs for each of those lines? When transactions are retrieved they should be in ID ascending sort order, meaning the oldest to newest. If that is the case it would seem strange that the first successful child transaction in that list has a more recent date than the transaction underneath.

Thanks!

[jerome2710]

@nfourtythree, for some reason I missed the notification of your reply. We are however still experiencing this issue with a small portion of our clients orders and manually checking & correcting them.

I am not sure if the warning should be a warning, as it's just a precaution. Our error logging is constantly notifying us, while it's just a fail-safe doing its work. We have now suppressed the message using a regex in our logging, which feels wrong.

The transaction-IDs of the screenshot I shared above are in fact ascending (12203 and 12204). I agree that it is strange that the first successful child transaction in that list has a more recent date than the transaction underneath, which shouldn't happen.

I am actually experiencing a similar case again right now, so it's still an ongoing problem:

[jerome2710]

Hi @nfourtythree, is there any update regarding this issue? We've just had another issue where the customer was refunded more than he actually paid, because of the duplicate transactions and an overpaid order. I would really like to see this issue sorted, as it causes quite some extra administration for our client when it goes wrong.

[nfourtythree]

Hi @jerome2710

Thank you for your message.

We have spent further time this week investigating and testing things related to this issue and we unfortunately still are unable to replicate the issue.

There are two possible things to try here though.

One is adding some log lines to the code (this will involve likely manually editing the files). I would part on in the complete payment method and log out some useful info like the timestamp, microtime, transaction hash, post data etc and also one in the process webhook method. It would then be possible to compare the data to see if there is a discrepancy somehow.

The other one is that I notice you mentioned that you are on MySQL 5.5, looking through the changelog for 5.6 and 5.7 versions there seems to be a number of references to mutex lock changes and fixes. The behaviour you are seeing seems to suggest that the mutex locks are not working as expected and it has not been possible to replicate the issue on 5.7. I am intrigued to know if updating the MySQL version would see this issue resolved.

I will keep the ticket open and please let us know if you have any further information.

Thanks!