mollie / magento2

Mollie Payments for Magento 2
https://www.mollie.com
Other
101 stars 53 forks source link

Cronjob 'mollie_send_pending_payment_reminders' gets stuck in 'running' (probably due to it crashing) #367

Closed hostep closed 3 years ago

hostep commented 3 years ago

Describe the bug We've upgraded this module from 1.17.0 to 1.23.0 a week ago. Since a few days we detected that the mollie_send_pending_payment_reminders cronjob gets stuck in the running status in the cron_schedule database table. If a cronjob is set to running it means Magento won't run new scheduled jobs anymore until that job is gone. We have a script to detect these things if a job is in running for more than 24 hours and when that happens we automatically change the status to error. I've now seen this problem happening 3 times on 3 consecutive days, so this appears to be a problem that keeps coming back.

From looking at the mollie.log file, I only find the output: Preparing to send the payment reminder for order ... but never Payment reminder record moved to sent table for order .... This seems to indicate that something is crashing in the method moveReminderFromPendingToSent and this error is not being handled properly by some try catch statement for example and we have no idea from the log file what error this is exactly.

Used versions

To Reproduce Steps to reproduce the behavior: Not sure, hopefully the description above might give some idea

Expected behavior Cronjob shouldn't stay in running state. Exception handling should happen so the cronjob terminates without errors. Also we should preferably find an exception message in some log file. But I don't know if this is the best idea, because this error would then be hidden until somebody inspects the log files. Maybe the cronjob should go into the error status and the exception message could be saved in the messages field of the cron_schedule database? I think Magento does this automatically sometimes, but not sure how it works exactly.

Actual behavior Cronjob stays in running state forever when an exception happens.

Frank-Magmodules commented 3 years ago

Hello @hostep,

Thanks for opening this ticket. First of all: That's the oldest Magento version I've seen in a while. It's a good idea to upgrade it to a more recent version.

That being said: Magento should log all errors that should happen during the cron run. There is only one kind of error that I know of that doesn't get into the Magento logs: When the executing of PHP is stopped for whatever reason. This can be caused by having not enough memory for example.

These kinds of errors should get logged to the main PHP error log under normal circumstances. Could you check if there is enough memory for the cronjob and if there are no errors in the main PHP error log?

hostep commented 3 years ago

Thanks for the feedback @Frank-Magmodules

First of all: That's the oldest Magento version I've seen in a while. It's a good idea to upgrade it to a more recent version.

Yes we are aware, sorry, it's hard to convince our client to upgrade, but one day it will happen, if we complain enough to him ... 🙂

These kinds of errors should get logged to the main PHP error log under normal circumstances.

Unfortunately the hosting didn't enable the error log for php-cli. I'll try talking to them to make that happen.

After quickly trying to simulate this cronjob on my local, I think I might have found the problem. You are using a feature from PHP 7.1 while we run this shop on PHP 7.0, the error we get is:

PHP Fatal error:  Uncaught TypeError: Return value of Mollie\Payment\Service\Order\PaymentReminder::moveReminderFromPendingToSent() must be an instance of Mollie\Payment\Service\Order\void, none returned

Notice that PHP can't find Mollie\Payment\Service\Order\void because PHP 7.0 isn't smart enough yet to understand Void functions which got introduced in PHP 7.1

Since your module claims to be compatible with PHP 7.0 or higher in the composer.json file and the release notes, I would suggest to remove the void return type (it's the only occurrence of this in the entire module, except for some Tests, but those are fine)

That being said: Magento should log all errors that should happen during the cron run. There is only one kind of error that I know of that doesn't get into the Magento logs: When the executing of PHP is stopped for whatever reason. This can be caused by having not enough memory for example.

So PHP Fatal errors seem to also be one of these ones that don't get logged (but that was fixed in Magento 2.2.4 by https://github.com/magento/magento2/commit/5927a75169aa5eb7a978847d22dbde5dbe3cc5a2, damn, just one version too late, otherwise I think we would have found the exact problem earlier 😄 )

Frank-Magmodules commented 3 years ago

Hi @hostep,

We are happy to share that we've just released the new 1.24.0 version that brings back-compatibility for PHP 7.0.

We also added linting to our GitHub Actions flow to prevent these types of issues. Thank you again for the detailed reports and patience. We are closing this issue now but please feel free to reopen the issue if this still occurs.

hostep commented 3 years ago

Hi @Frank-Magmodules, thanks for the quick changes!

But the cronjob mollie_send_pending_payment_reminders still crashes on older Magento versions, with a new error (only Magento versions older then 2.2.9, and Magento 2.3.0 crashes as well):

PHP Fatal error:  Uncaught Error: Call to undefined method Magento\Framework\Mail\Template\TransportBuilder::setFromByScope() in vendor/mollie/magento2/Service/Order/SecondChanceEmail.php:101
Stack trace:
#0 vendor/mollie/magento2/Service/Order/PaymentReminder.php(89): Mollie\Payment\Service\Order\SecondChanceEmail->send(Object(Magento\Sales\Model\Order\Interceptor))
#1 vendor/mollie/magento2/Cron/SendPendingPaymentReminders.php(87): Mollie\Payment\Service\Order\PaymentReminder->send(Object(Mollie\Payment\Model\Data\PendingPaymentReminder))
#2 [internal function]: Mollie\Payment\Cron\SendPendingPaymentReminders->execute(Object(Magento\Cron\Model\Schedule))
#3 vendor/n98/magerun2/src/N98/Magento/Command/System/Cron/RunCommand.php(60): call_user_func(Array, Object(Magento\Cron\Model\Schedule))
#4 in vendor/mollie/magento2/Service/Order/SecondChanceEmail.php on line 101

The setFromByScope method was introduced in Magento 2.2.9 by https://github.com/magento/magento2/pull/18472 and in Magento 2.3.1 by https://github.com/magento/magento2/pull/18471 (Those PR's were created to fix a core Magento email sending bug which existed in Magento 2.2.4 => 2.2.8 and 2.3.0)

So this means this cronjob does not work properly on Magento 2.2.0 => 2.2.8 and 2.3.0

I totally understand that this is a bit tedious to fix and you probably would not like to support those older Magento versions any more, but we assumed based on the composer.json file and the release notes that this module would still work on older versions. Not sure if it makes sense to try to fix this though? Maybe you could just not enable this feature of sending second chance mails on Magento shops if the method setFromByScope does not exists?

What do you think?

I can make a new issue out of this if you want.

Frank-Magmodules commented 3 years ago

HI @hostep ,

Thank you for the extra comment, it seems that you are right, thanks for thinking with us on this. We created a fix for this issue which is implemented in a release later this week. Thanks again!

Frank-Magmodules commented 3 years ago

HI @hostep , we are happy to share that we've just released version 1.2.5 where we have fixed this based on your feedback. Thanks again for your reports, your patience, and for thinking with us!

hostep commented 3 years ago

Thanks @Frank-Magmodules, I can confirm that the second chance email now works perfectly fine on Magento 2.2.3 with version 1.2.5 of the Mollie module!

But when I quickly simulate this by adding 2 orders to the mollie_pending_payment_reminder database table, and running the cronjob, I see 2 mails being sent, but only 1 row being removed from the table, upon running the cronjob again, it sends out another email to the same client as the first time and then the second row is removed from the table, that sounds like another bug? This is only a simulation, I have no idea if this will also happen in the real world though. Have you seen this behavior before or tested with more than one pending payment reminder?

Frank-Magmodules commented 3 years ago

HI @hostep , thanks for your message, I can't reproduce this directly but will check this with the development team and come back to you on this.