search

Adyen / adyen-magento2

Adyen Payment plugin for Magento2
MIT License
155 stars 211 forks source link

The order cannot be confirmed even though the notification arrives #610

Closed dbolufer closed 4 years ago

dbolufer commented 4 years ago

Magento version: 2.2.8 Plugin version: 5.0 Description

On the production environment we have an order in payment_review status, this order is payed and Adyen has sent the notification.

When the adyen cron process the notification, it raise a "Unique constraint violation found" because there is a row on the table adyen_order_payment with the same pspreference and the due to UNIQUE KEY restriction the cronjob the raise an exception.

We've solved the error manually:

Please take a look, this is the second time in a month with this bug.

Update We thought we had a couple of bad orders but looking for info we had realized that we had 21 orders payment_review en magento y processing en adyen.

We are using this query to check this missed orders:

SELECT * FROM adyen_notification an 
LEFT JOIN adyen_order_payment aop on aop.pspreference = an.pspreference
LEFT JOIN sales_order_payment sop on aop.payment_id = sop.entity_id
LEFT JOIN sales_order so on so.entity_id = sop.parent_id
 WHERE event_code = "AUTHORISATION" AND  so.status = "payment_review";

This is the log for the error:

[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Array
(
    [entity_id] => 22635
    [pspreference] => XXXX
    [merchant_reference] => XXXX
    [event_code] => AUTHORISATION
    [success] => true
    [payment_method] => mc
    [amount_value] => 15800
    [amount_currency] => EUR
    [reason] => 370529:1014:06/2021
    [live] => true
    [additional_data] => a:6:{s:10:"expiryDate";s:7:"06/2021";s:8:"authCode";s:6:"370529";s:11:"cardSummary";s:4:"1014";s:14:"cardHolderName";s:17:"XXXX";s:24:"recurringProcessingModel";s:10:"CardOnFile";s:13:"hmacSignature";s:44:"XXXX=";}
    [done] => 0
    [processing] => 1
    [created_at] => 2020-01-02 17:18:19
)
 {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Created comment history for this notification {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Updating the Adyen attributes of the order {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Processing the notification {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Authorisation of the order {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: State is changed to  processing {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Order status is changed to Pre-authorised status, status is payment_authorisation {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Prepare invoice for order {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Capture mode is set to auto capture {"is_exception":false} []
[2020-01-07 16:23:04] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Notification 22635 had an error: Unique constraint violation found
 #0 /var/www/www.com/current/vendor/magento/framework/Model/AbstractModel.php(647): Magento\Framework\Model\ResourceModel\Db\AbstractDb->save(Object(Adyen\Payment\Model\Order\Payment))
#1 /var/www/www.com/current/vendor/adyen/module-payment/Model/Cron.php(1356): Magento\Framework\Model\AbstractModel->save()
#2 /var/www/www.com/current/vendor/adyen/module-payment/Model/Cron.php(1217): Adyen\Payment\Model\Cron->_prepareInvoice()
#3 /var/www/www.com/current/vendor/adyen/module-payment/Model/Cron.php(884): Adyen\Payment\Model\Cron->_authorizePayment()
#4 /var/www/www.com/current/vendor/adyen/module-payment/Model/Cron.php(433): Adyen\Payment\Model\Cron->_processNotification()
#5 /var/www/www.com/current/vendor/adyen/module-payment/Model/Cron.php(304): Adyen\Payment\Model\Cron->execute()
#6 [internal function]: Adyen\Payment\Model\Cron->processNotification(Object(Magento\Cron\Model\Schedule))
#7 /var/www/www.com/current/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(314): call_user_func_array(Array, Array)
#8 /var/www/www.com/current/vendor/devopensource/extendcronscheduler/Plugin/Cron/Observer/ProcessCronQueueObserver.php(223): Magento\Cron\Observer\ProcessCronQueueObserver->_runJob(1578414180, 1578414184, Array, Object(Magento\Cron\Model\Schedule), 'adyen_payment')
#9 /var/www/www.com/current/vendor/magento/framework/Interception/Interceptor.php(135): Devopensource\ExtendCronScheduler\Plugin\Cron\Observer\ProcessCronQueueObserver->aroundExecute(Object(Magento\Cron\Observer\ProcessCronQueueObserver\Interceptor), Object(Closure), Object(Magento\Framework\Event\Observer))
#10 /var/www/www.com/current/vendor/magento/framework/Interception/Interceptor.php(153): Magento\Cron\Observer\ProcessCronQueueObserver\Interceptor->Magento\Framework\Interception\{closure}(Object(Magento\Framework\Event\Observer))
#11 /var/www/www.com/current/generated/code/Magento/Cron/Observer/ProcessCronQueueObserver/Interceptor.php(26): Magento\Cron\Observer\ProcessCronQueueObserver\Interceptor->___callPlugins('execute', Array, NULL)
#12 /var/www/www.com/current/vendor/magento/framework/Event/Invoker/InvokerDefault.php(88): Magento\Cron\Observer\ProcessCronQueueObserver\Interceptor->execute(Object(Magento\Framework\Event\Observer))
#13 /var/www/www.com/current/vendor/magento/framework/Event/Invoker/InvokerDefault.php(74): Magento\Framework\Event\Invoker\InvokerDefault->_callObserverMethod(Object(Magento\Cron\Observer\ProcessCronQueueObserver\Interceptor), Object(Magento\Framework\Event\Observer))
#14 /var/www/www.com/current/vendor/magento/framework/Event/Manager.php(66): Magento\Framework\Event\Invoker\InvokerDefault->dispatch(Array, Object(Magento\Framework\Event\Observer))
#15 /var/www/www.com/current/generated/code/Magento/Framework/Event/Manager/Proxy.php(95): Magento\Framework\Event\Manager->dispatch('default', Array)
#16 /var/www/www.com/current/vendor/magento/framework/App/Cron.php(86): Magento\Framework\Event\Manager\Proxy->dispatch('default')
#17 /var/www/www.com/current/vendor/magento/module-cron/Console/Command/CronCommand.php(117): Magento\Framework\App\Cron->launch()
#18 /var/www/www.com/current/vendor/symfony/console/Command/Command.php(245): Magento\Cron\Console\Command\CronCommand->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#19 /var/www/www.com/current/vendor/symfony/console/Application.php(835): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#20 /var/www/www.com/current/vendor/symfony/console/Application.php(185): Symfony\Component\Console\Application->doRunCommand(Object(Magento\Cron\Console\Command\CronCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#21 /var/www/www.com/current/vendor/magento/framework/Console/Cli.php(102): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#22 /var/www/www.com/current/vendor/symfony/console/Application.php(117): Magento\Framework\Console\Cli->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#23 /var/www/www.com/current/bin/magento(23): Symfony\Component\Console\Application->run()
#24 {main} {"is_exception":false} []
cyattilakiss commented 4 years ago

Hi @dbolufer ,

Thank you for raising this issue and for the detailed description. We are going to release a quick fix for this one to prevent the cron job to stop. Meanwhile could you please check your logs regarding your PSP and merchant reference if you can find any errors for the previous cron jobs running? This issue only occurs if the PSP and merchant reference is already in the database and for some reason the notification is reprocessed - most likely because there was an error later in the process caused by the plugin, Magento or another third party plugin. If you could investigate the issue a bit more it would be a great help for us and also for the community to understand this specific issue.

Thank you for your help in advance. Best. Attila Adyen

cyattilakiss commented 4 years ago

Hi @dbolufer ,

Just merged a PR which will introduce a fix for this issue. We are going to release it in the next release cycle.

Best, Attila Adyen

dbolufer commented 4 years ago

Thank you! So far, we have not been able to investigate the origin of the problem. I wish we can take a look next week

dbolufer commented 4 years ago

Hi. The fix should work for adyen_notification.done = 0 but for adyen_notification.done = 1 doesn't work.

Now, we have 20 orders payment_review , 3 of them have adyen_notification.done = 1.

Anyway, we are going to apply the fix via patch and check if 100% of cases will be solved

cyattilakiss commented 4 years ago

Hi @dbolufer ,

Yes for the adyen_notification.done = 1 it won't work because that is the indicator of the notifications that are already processed so we don't touch them anymore. It was an uncaught exception which now in this patch is caught which prevented the process to be finished the correct way.

So after this patch and after cleaning up the rest of the notifications which experienced this issue, it should be fine but please give us feedback when you have the chance to test it :)

Best, Attila Adyen

dbolufer commented 4 years ago

Hi!

At this time, we have one order with adyen_notification.done = 1 and order.state & status = payment_review

This is the results of our investigation.

But the state / status for this order is payment_review

[2020-01-12 21:37:17] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: State is changed to  processing {"is_exception":false} []
[2020-01-12 21:37:17] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Order status is changed to authorised status, status is payment_confirmed {"is
[2020-01-12 21:37:17] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Send orderconfirmation email to shopper {"is_exception":false} []
[2020-01-12 21:37:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Creating new Billing Agreement {"is_exception":false} []
[2020-01-12 21:37:18] AdyenLoggerTest.ADYEN_NOTIFICATION_CRONJOB: Created billing agreement #2815788649299700. {"is_exception":false} []

There is not any other important log :-(

UPDATE: When we change done=1 to done=0, the order has been processed

This is the order comments history

- Jan 13, 2020 7:31:05 PM Payment Confirmed (Adyen asynchronous) Customer Not Notified
Adyen Payment Successfully completed
- Jan 13, 2020 7:31:05 PM Payment Authorisation (Adyen synchronous) Customer Not Notified
Payment is authorised waiting for capture
- Jan 13, 2020 7:31:05 PM Payment Review Customer Not Notified
Adyen HTTP Notification(s):
eventCode: AUTHORISATION
pspReference: XXXX
paymentMethod: visa
success: true
reason:visa
- Jan 12, 2020 10:37:19 PM Payment Review Customer Not Notified
Created billing agreement #2815788649299700.
msilvagarcia commented 4 years ago

Hi @dbolufer ,

Thank you for the feedback. If I understand correctly, the issue is then solved.

I'll close the ticket for now, but feel free to re-open or create a new one if there are any questions remaining.

Cheers! Marcos Adyen

dbolufer commented 4 years ago

No, sorry it didn't. Sorry about my explanation :-) On the last 5 days there was an order with adyen_notification.done = 1 and order.status = 'payment_review'

We have attached all the logs but we didn't find any error

dbolufer commented 4 years ago

UPDATE: Looking for more info, we found this log entry on adyen/error.log

[2020-01-13 18:31:04] AdyenLoggerTest.ERROR: While processing a notification an exception occured. The payment has already been saved in the adyen_order_payment table but something went wrong later. Please check your logs for potential error messages regarding the merchant reference (order id): "XXXXX" and PSP reference: "YYYY" {"is_exception":false} []

Can you help us in which logs can we looking for the error message?

cyattilakiss commented 4 years ago

Hi @dbolufer ,

Usually another module or Magento throws the error and stops our process. You can check in the root exception.log and also in the payment or invoicing related modules log folders as well.

I see that you tried to reprocess the notification itself and for the second time everything went well so I assume that other plugin couldn't reach an API endpoint or another temporary issue occurred which has been resolved for the second try.

I hope this will help.

Best, Attila

danslo commented 4 years ago

@dbolufer did you ever get to the bottom of this? We're running into something very similar (Unique constraint violation), but it's quite hard to reproduce.

For us it doesn't happen in cron, but during order placement. And only in very specific circumstances.

dbolufer commented 4 years ago

No, sorry. We didn't find the reason of the error, with the patch the problem was minimized but not resolved

danslo commented 4 years ago

@dbolufer Okay I think I found the error in our case, I'm currently doing a write up of the issue and probably will send a PR soon. Not sure if it also fixes your issue, but it seems likely.

If you have a test environment and want to try to reproduce it, try doing two orders: Place order with 5555 4444 3333 1111 10/20 737 Place order with 5555 4444 3333 1111 03/30 737 (notice the difference in expiration dates)

Bigger write up of the issue is coming, but for us it boils down to the fact that vault_payment_token table has UNIQUE indexes for:

But in Vault code, duplicate token check is only done for public_hash. Even though Adyen can return the same gateway_token for different public_hash (when user updates their expiration date etc).

danslo commented 4 years ago

@dbolufer I've written up the issue here: https://github.com/Adyen/adyen-magento2/issues/678

AntonEvers commented 4 years ago

@danslo a way to replicate this is by forcing or faking a deadlock failure on the sales_invoice_grid table. In my case this always started with:

Notification xxxxxx had an error: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction, query was: INSERT INTO `sales_invoice_grid` ...

This happens during $this->_createInvoice:

        if ($this->_isTotalAmount($paymentObj->getEntityId(), $orderCurrencyCode)) {
            $this->_createInvoice();
        } else {
            $this->_adyenLogger->addAdyenNotificationCronjob(
                'This is a partial AUTHORISATION and the full amount is not reached'
            );
        }

Because there is no error handling that rolls back the payment creation around $this->_createInvoice(); the code stops there and will arrive at $this->_adyenOrderPaymentFactory->create()...->save() a minute later, causing the constraint violation.

The code in https://github.com/Adyen/adyen-magento2/commit/f2d13c2576186e0a6362aa446ad3c6e970751d3b helps to get past the constraint violation, but it would be even better if the notification handling would be able to cope with a deadlock on the invoice grid table and roll back the entire procedure somehow to try again later.

othuress commented 1 year ago

Please reopen we are facing this issue at the moment @cyattilakiss Adyen ticet #(#3765581)

[2023-04-04 16:21:57] AdyenLoggerTest.ERROR: While processing a notification an exception occured. The payment has already been saved in the adyen_order_payment table but something went wrong later. Please check your logs for potential error messages regarding the merchant reference (order id): 5000032315 and PSP reference: W9RW3LLKJC2DPK52. Exception message: Unique constraint violation found [] {"uid":"2ef29d1"}

[2023-04-04 17:39:06] AdyenLoggerTest.ADYEN_DEBUG: There are no verified Adyen IP addresses in cache. Updating IP records. [] {"uid":"803b01e"}

also adyen thinks that Rabbit MQ is enabled eventhough it has been disabled [2023-04-04 13:00:10] AdyenLoggerTest.WARNING: Unknown connection name amqp

0 /var/www/public/vendor/magento/framework-message-queue/PublisherPool.php(143): Magento\Framework\MessageQueue\ConnectionTypeResolver->getConnectionType()

1 /var/www/public/vendor/magento/framework-message-queue/PublisherPool.php(88): Magento\Framework\MessageQueue\PublisherPool->getPublisherForConnectionNameAndType()

2 /var/www/public/vendor/adyen/module-payment/Model/Queue/Notification/Publisher.php(29): Magento\Framework\MessageQueue\PublisherPool->publish()

3 /var/www/public/vendor/adyen/module-payment/Cron/WebhookProcessor.php(130): Adyen\Payment\Model\Queue\Notification\Publisher->execute()

4 /var/www/public/vendor/adyen/module-payment/Cron/WebhookProcessor.php(84): Adyen\Payment\Cron\WebhookProcessor->doProcessWebhook()

5 [internal function]: Adyen\Payment\Cron\WebhookProcessor->execute()

6 /var/www/public/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(356): call_user_func_array()

7 /var/www/public/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(858): Magento\Cron\Observer\ProcessCronQueueObserver->_runJob()

8 /var/www/public/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(825): Magento\Cron\Observer\ProcessCronQueueObserver->tryRunJob()

9 /var/www/public/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(273): Magento\Cron\Observer\ProcessCronQueueObserver->processPendingJobs()

10 /var/www/public/vendor/magento/framework/Event/Invoker/InvokerDefault.php(88): Magento\Cron\Observer\ProcessCronQueueObserver->execute()

11 /var/www/public/vendor/magento/framework/Event/Invoker/InvokerDefault.php(74): Magento\Framework\Event\Invoker\InvokerDefault->_callObserverMethod()

12 /var/www/public/vendor/magento/framework/Event/Manager.php(66): Magento\Framework\Event\Invoker\InvokerDefault->dispatch()

13 /var/www/public/generated/code/Magento/Framework/Event/Manager/Proxy.php(95): Magento\Framework\Event\Manager->dispatch()

14 /var/www/public/vendor/magento/framework/App/Cron.php(86): Magento\Framework\Event\Manager\Proxy->dispatch()

15 /var/www/public/vendor/magento/module-cron/Console/Command/CronCommand.php(117): Magento\Framework\App\Cron->launch()

16 /var/www/public/vendor/symfony/console/Command/Command.php(255): Magento\Cron\Console\Command\CronCommand->execute()

17 /var/www/public/vendor/magento/framework/Interception/Interceptor.php(58): Symfony\Component\Console\Command\Command->run()

18 /var/www/public/vendor/magento/framework/Interception/Interceptor.php(138): Magento\Cron\Console\Command\CronCommand\Interceptor->___callParent()

19 /var/www/public/vendor/magento/framework/Interception/Interceptor.php(153): Magento\Cron\Console\Command\CronCommand\Interceptor->Magento\Framework\Interception{closure}()

20 /var/www/public/generated/code/Magento/Cron/Console/Command/CronCommand/Interceptor.php(23): Magento\Cron\Console\Command\CronCommand\Interceptor->___callPlugins()

21 /var/www/public/vendor/symfony/console/Application.php(1021): Magento\Cron\Console\Command\CronCommand\Interceptor->run()

22 /var/www/public/vendor/symfony/console/Application.php(275): Symfony\Component\Console\Application->doRunCommand()

23 /var/www/public/vendor/magento/framework/Console/Cli.php(115): Symfony\Component\Console\Application->doRun()

24 /var/www/public/vendor/symfony/console/Application.php(149): Magento\Framework\Console\Cli->doRun()

25 /var/www/public/bin/magento(23): Symfony\Component\Console\Application->run()

26 {main} [] {"uid":"862988f"}

Solution is the manually reprocess each transaction in adyen notications overview, that is alott of clicking

image