Order cancellation - possible race condition

[aligent-lturner]

Describe the bug
A scenario has been found where an initial payment failure has resulted in an order being incorrectly cancelled. This is seemingly either a race condition or a bug with how the failure notification is handled.

To Reproduce
Steps to reproduce the behavior:

1. Attempt to place an order, but supply invalid card details. Order is not created in Magento
2. Supply correct card details and place order. Order is created in Magento at this time (in payment_review status).
3. Notification is received for the initial failure with the following information:

{
    "entity_id": "redacted",
    "pspreference": "redacted",
    "merchant_reference": "redacted",
    "event_code": "AUTHORISATION",
    "success": "false",
    "payment_method": "unknowncard",
    "amount_value": "redacted",
    "amount_currency": "redacted",
    "reason": "101 Invalid card number",
    "live": "true",
    "additional_data": "redacted",
    "done": "0",
    "processing": true,
    "error_count": "0",
    "created_at": "2022-07-20 03:35:39"
}

4. Cron job processing results in the cancellation of the order.

[2022-07-20 03:46:19] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification XYZ will be processed 
{
    "orderId": "redacted",
    "orderIncrementId": "redacted",
    "orderState": "payment_review",
    "orderStatus": "payment_review",
    "is_exception": false
}
 []
[2022-07-20 03:46:19] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Created comment history for this notification 
{
    "is_exception": false
}
 []
[2022-07-20 03:46:19] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Updating the Adyen attributes of the order 
{
    "is_exception": false
}
 []
[2022-07-20 03:46:19] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Going to cancel the order 
{
    "is_exception": false
}
[2022-07-20 03:46:23] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification XYZ was processed 
{
    "orderId": "redacted",
    "orderIncrementId": "redacted",
    "orderState": "canceled",
    "orderStatus": "canceled",
    "is_exception": false
}
 []

5. Notification is received for successful payment:

{
    "entity_id": "redacted",
    "pspreference": "redacted",
    "merchant_reference": "redacted",
    "event_code": "AUTHORISATION",
    "success": "true",
    "payment_method": "redacted",
    "amount_value": "redacted",
    "amount_currency": "redacted",
    "reason": "redacted",
    "live": "true",
    "additional_data": "redacted",
    "done": "0",
    "processing": true,
    "error_count": "0",
    "created_at": "2022-07-20 03:45:30"
}

6. Cron job processes the notification, but invoice creation fails, resulting order ending in closed status instead of processing

[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification ABC will be processed 
{
    "orderId": "redacted",
    "orderIncrementId": "redacted",
    "orderState": "canceled",
    "orderStatus": "canceled",
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Created comment history for this notification 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Updating the Adyen attributes of the order 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Processing the notification 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Authorisation of the order 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Capture mode is set to auto capture 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: State is changed to  new 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Order status is changed to Pre-authorised status, status is pending 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Prepare invoice for order 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Creating invoice for order 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Unable to create invoice when handling Notification ABC 
{
    "orderId": "redacted",
    "orderIncrementId": "redacted",
    "orderState": "new",
    "orderStatus": "pending",
    "canUnhold": false,
    "isPaymentReview": false,
    "isCancelled": false,
    "invoiceActionFlag": null,
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Set order to authorised 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification w/amount redacted has completed the capturing of order redacted w/amount redacted 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: State is changed to  processing 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Order status was changed to authorised status: processing 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Send orderconfirmation email to shopper 
{
    "is_exception": false
}
 []
[2022-07-20 03:47:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification ABC was processed 
{
    "orderId": "redacted",
    "orderIncrementId": "redacted",
    "orderState": "closed",
    "orderStatus": "closed",
    "is_exception": false
}
 []

Expected behavior
The initial payment failure should not result in the order being cancelled, as the order was not yet created.

Magento version
2.3.4

Plugin version
7.3.7

Screenshots
If applicable, add screenshots to help explain your problem.

Desktop (please complete the following information):

• OS: Ubuntu
• Browser - chrome
• Version - latest

Additional context
Note that this is happening in an environment with a custom checkout, but in any case, the order should not be created in the case of an invalid card number, so why is it attempting to cancel the order?

[RokPopov]

Hi @aligent-lturner,

Thank you for reporting this issue with us.

The reason why we delay the processing of the AUTHORISATION notification with success=false is to cover the scenario when the successful authorisation would follow, Magento would process that one first.

I can see that the initial notification was created at 03:35, and the successful one was created at 3:45. Delaying the first one for 10 minutes didn't do the trick here and the initial notification seemed to be processed first. This seems to have caused the issue.

Could you please further clarify whether this is a standalone case or have you experienced more of these?
We may have to delay the processing of the unsuccessful authorisations for longer.

Looking forward to your reply,

Kind regards,
Rok,
Adyen

[aligent-lturner]

@RokPopov at this stage we're not sure if this is the only case, but we've definitely seen failure notifications turn up after successful ones before, which has been confusing, as the comments get added to the order out of sequence, so it looks like the order was successful, and then later unsuccessful.

I guess I have a few queries:

• Why is there a notification being processed for the first failure at all? There's no order created, so there's not anything to do here. Under what circumstances would we expect an order to exist (and rightfully be cancelled)?
• I can't see how any arbitrary delay in processing will work, as it's going to be wholly dependent on how long the customer waits between the unsuccessful attempt and the successful one. e.g. if the delay was changed to 20 minutes, it's just moving the edge case along by 10 minutes, rather than eliminating it.
  • Would it be possible to have the PSP reference for a successful authorisation stored on the order when it's created (it may already be). Then, when processing a failed authorisation, it would only try to cancel it if the PSP reference matched (or the "original PSP reference")?
• As an aside, I think it would be useful to include the notification time in the comment that's added to the order, so that anything out of sequence can be seen without looking elsewhere.

[Nuranto]

We juste saw a similar case, unfortunately we don't have the corresponding logs, but it looks like this in the Magento's backend :

And the payment has SettledBulk status.

[WilcoOppoSuits]

We got the exact same issue on our website, so far 7 cases this happend.
Weirdly so far all 7 in the US and not on our EU storefront.

[Morerice]

Hi guys,

Are you also seeing the Order has been cancelled by adyen_cc (or adyen_hpp) message in Magento's backend, just like the screenshot posted by @Nuranto?

Thanks,
Jean
Adyen

[WilcoOppoSuits]

Yes!

[Morerice]

In that case both adyen_cc or adyen_hpp issues should not be present anymore after v8.9.0.

• adyen_cc issue was solved in [PW-7189] - Disable cross button and ESC key on action modal #1731
• adyen_hpp issue was solved in [PW-7276] - Remove X-cross button from payment action modal #1802

I will close this issue for now. However, if the problem persists feel free to leave a message in this issue which we will check, to verify if the issue should be re-opened or not.

Thanks,
Jean
Adyen