We currently face a problem where some payment with mollie do not properly end the checkout process with the thank you page and generating the order confirmation email. In order to keep track of this one has to enable the email-log function in shopware to see all emails that are generated by the system.
This functionality is crucial in our case, as there are other plugins, created by us, which subscribe to the checkout process, to inject another email adress to the order confirmation email, aswell as saving data for a CRM system.
The problem itself is not a general problem, as we can see that a lot of orders are made and send out emails accordingly. But in some cases it fails to do so. In the shopsystem all orders have to be made via the mollie payment method.
The shop-system is Shopware 5.6.10 running with mollie 1.8.5.
This is what happens here:
A user uses the mollie payment in the checkout process, goes through the mollie process and comes back from the shop. Then somehow the shop stops to go on with the order and does not add the mollie transaction id into the order, as it does normally. In the detail page of the order, we can see the correct transaction, but in the order-list view we only see the mollie id like "mollie_123" and not the "tr_123456" number. When this order is also in the state "open" and "paid" we already can see, which orders might have failed in the checkout process, as normally these order should show their transaction number and not the mollie id. The mollie id is normally only shown for orders which were cancelled, and these will also have the order and payment status shown as cancelled, which is correct.
Sadly we did not yet find any way to reproduce this problem, this only occurs in few cases. We can only find those orders by checking the order-transaction-id and then also looking into the email-log.
Used Plugins:
Deliver Date (https://store.shopware.com/dtgs01537/wunsch-lieferdatum/abhol-termin-datum-uhrzeit.html)
Mollie
Dutch translation
3 custom Plugins
I also found that the deliverydate Plugin is capable of redirecting users.
Suggestions to us:
We were already told, that it might be that the Customer just took too long to fulfill his payment, but i pretty much can rule that out, as we have seen this problem occur for accounts where the user came back at about 40 seconds later. The shop itself, or better the PHP-Info-page, shows that it is set to 7200 seconds (3 hours) and a gc-divisor of 1000 requests, so i doubt that the problem comes from here.
Do not use Session-variables in this step:
Our own plugins also add some variables/info to the session and hopes to read them again in the checkout process. We found that sometimtes these variables are not set, especially when the user came back from a payment provider, so we added a whitelisting for known payment providers and their initial requests-urls when the user is coming back. Nevertheless we are not the only plugin-manufacturers and as we are using the plugin for the delivery-date we can see that this plugin also uses the session variables in the checkout finish action and will also redirect the user to the confirm page, if variables are not set. Currently we are testing if the redirect comes from here, by adding some log-lines to the process parts where it does the forwarding. Yet even if we find, that the problem comes from here, i honestly can not blame the manufacturere here, as the usage of session data in the checkout process should be perfectly viable, and is only messed around in some rare cases. Also it would mean that a lot of other plugins which have to rely on some information in the session and are subscribing to the checkout finish process are prone to fail here.
Session Handling:
It was mentioned that it could be that the users are checking out in one browser, and when switching to the payment page, get another browser opened. When they are coming back they would have no session set and thus the order session is empty and all data is missing.
This problem might be the case here, but this problem was already adresses by shopware in their upgrade guide (see below). Also in mollie version 1.8.0 this problem was adressed.
Related to this issue we also found a ticket in the shopware ticket system:
https://issues.shopware.com/issues/SW-23242
Paypal Payment Token:
custom/plugins/SwagPaymentPayPalUnified/Components/Services/ExpressCheckout/ExpressCheckoutPaymentBuilderService.php
private function getReturnUrl()
{
$routingParameters = [
'module' => 'frontend',
'controller' => 'PaypalUnifiedExpressCheckout',
'action' => 'expressCheckoutReturn',
'forceSecure' => true,
'basketId' => BasketIdWhitelist::WHITELIST_IDS['PayPalExpress'], //PayPal Express Checkout basket Id
];
// Shopware 5.6+ supports session restoring
$token = $this->requestParams->getPaymentToken();
if ($token !== null) {
$routingParameters[PaymentTokenService::TYPE_PAYMENT_TOKEN] = $token;
}
return $this->router->assemble($routingParameters);
}
According to the Shopware Upgrade Guide, the Token should be created, it will later be used by a process to check if the user should be logged in. (https://developers.shopware.com/developers-guide/shopware-5-upgrade-guide-for-developers/#payment-token)
For this reason there is now a service to generate a token, which can be added to the returning url (e.g /payment_paypal/return?paymentId=test123&swPaymentToken=abc123def). This parameter will be resolved in a PreDispatch-event by the \Shopware\Components\Cart\PaymentTokenSubscriber: If the user is not logged in, but the URL contains a valid token, the user will get back his former session and will be redirected to the original URL, but without the token
From what i understand of the mollie plugin, it does not add the payment token, but will search for a user depending on the payment id, thus it might be, that the process is just not going through the shops intended process here and which might be the reason why it sometimtes failes.
Mollie does the session restore on its own:
in the file: custom/plugins/MollieShopware/Components/SessionManager/SessionManager.php
The function that restores the session is: $this->repoCookies->setSessionCookie($transaction->getSessionId());
The Repository is located in the file: custom/plugins/MollieShopware/Components/SessionManager/Services/Cookies/CookieRepository.php
The function setSessionCookie just sets the cookie session id but does not recreate the session as it should.
Logs (logging with mollie debug):
(Note: all logs are changed to remove any data that could be related to the customers that generated these orders. Evere occurence of identifiers have been replaced with some text/numbercombination with search and replace so the internal references are still intact):
Normal Order:
[2021-05-25 01:18:19] Mollie.INFO: Starting checkout for Transaction: 111 with payment: mollie_ideal (Session: qwe1...) {"basket":{"amount":"136,00","quantity":1,"payment":"mollie_ideal","user":"5176"},"tokens":{"creditcard":"","applepay":""},"session":"qwe123rtzui","processors":{"uid":{"uid":"012345"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-05-25 01:18:19] Mollie.DEBUG: Create new Order before payment for Transaction mollie_111 (Session: qwe1...) {"session":"qwe123rtzui","processors":{"uid":{"uid":"012345"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-05-25 01:19:51] Mollie.INFO: Incoming Webhook Notification for transaction: 111 and payment: tr_asdfqwer (Session: qqqw...) {"session":"qqqwwweeerrr111222333","processors":{"uid":{"uid":"121212"},"web":{"url":"/Mollie/notify/transactionNumber/111","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-05-25 01:19:51] Mollie.DEBUG: Webhook Notification successfully processed for transaction: 111 and payment: tr_asdfqwer (Session: qqqw...) {"session":"qqqwwweeerrr111222333","processors":{"uid":{"uid":"121212"},"web":{"url":"/Mollie/notify/transactionNumber/111","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-05-25 01:19:51] Mollie.DEBUG: User is returning from Mollie for Transaction 111 (Session: qwe1...) {"session":"qwe123rtzui","processors":{"uid":{"uid":"09876"},"web":{"url":"/Mollie/return/transactionNumber/111/token/1234567890123456","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://betalen.rabobank.nl/"}}} []
[2021-05-25 01:19:52] Mollie.INFO: Finished checkout for Transaction 111 (Session: qwe1...) {"session":"qwe123rtzui","processors":{"uid":{"uid":"543987"},"web":{"url":"/Mollie/finish/transactionNumber/111","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://betalen.rabobank.nl/"}}} []
Failed Order Type 1:
Here the customer came back from the payment page, the plugin also should see that the customer has the correct session id, yet it thinks thath the session is missing and wants to recreate the session. This seems to be the case more often with the latest version of the plugin:
[2021-05-26 02:53:09] Mollie.INFO: Starting checkout for Transaction: 120 with payment: mollie_ideal (Session: asdf...) {"basket":{"amount":"378,00","quantity":1,"payment":"mollie_ideal","user":"0123"},"tokens":{"creditcard":"","applepay":""},"session":"asdf123qwer","processors":{"uid":{"uid":"112233"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout/confirm"}}} []
[2021-05-26 02:53:09] Mollie.DEBUG: Create new Order before payment for Transaction mollie_120 (Session: asdf...) {"session":"asdf123qwer","processors":{"uid":{"uid":"112233"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout/confirm"}}} []
[2021-05-26 02:53:57] Mollie.INFO: Incoming Webhook Notification for transaction: 120 and payment: tr_abcdef (Session: mmmo...) {"session":"mmmooollliiieee","processors":{"uid":{"uid":"yxcvb"},"web":{"url":"/Mollie/notify/transactionNumber/120","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-05-26 02:53:57] Mollie.DEBUG: Webhook Notification successfully processed for transaction: 120 and payment: tr_abcdef (Session: mmmo...) {"session":"mmmooollliiieee","processors":{"uid":{"uid":"yxcvb"},"web":{"url":"/Mollie/notify/transactionNumber/120","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-05-26 02:53:57] Mollie.DEBUG: User is returning from Mollie for Transaction 120 (Session: asdf...) {"session":"asdf123qwer","processors":{"uid":{"uid":"456123"},"web":{"url":"/Mollie/return/transactionNumber/120/token/asdfghjkl987654321","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://betalen.rabobank.nl/"}}} []
[2021-05-26 02:53:57] Mollie.NOTICE: Missing Session! Restoring Session for Transaction: 120 (Session: asdf...) {"session":"asdf123qwer","processors":{"uid":{"uid":"456123"},"web":{"url":"/Mollie/return/transactionNumber/120/token/asdfghjkl987654321","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://betalen.rabobank.nl/"}}} []
[2021-05-26 02:53:58] Mollie.ERROR: Checkout failed when finishing Order for Transaction: 120 (Session: asdf...) {"error":"Missing Session for Transaction: 120","session":"asdf123qwer","processors":{"uid":{"uid":"000000"},"web":{"url":"/Mollie/finish/transactionNumber/120","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://betalen.rabobank.nl/"},"introspection":{"file":null,"line":null,"class":"Shopware_Controllers_Frontend_Mollie","function":"finishAction"}}} []
Failed Order Type 2:
In these Orders we could see that the session changed between the user checking out and coming back. The Plugin could not find the user back then, could very well be that this is not the case anymore.
[2021-04-20 12:37:17] Mollie.INFO: Starting checkout for Transaction: 090 with payment: mollie_ideal (Session: poiu...) {"basket":{"amount":"136,00","quantity":1,"payment":"mollie_ideal","user":"4567"},"tokens":{"creditcard":"","applepay":""},"session":"poiumnbv1234","processors":{"uid":{"uid":"12asdf12"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-04-20 12:37:17] Mollie.DEBUG: Create new Order before payment for Transaction mollie_090 (Session: poiu...) {"session":"poiumnbv1234","processors":{"uid":{"uid":"12asdf12"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-04-20 12:37:34] Mollie.INFO: Incoming Webhook Notification for transaction: 090 and payment: tr_11223344 (Session: 31d2...) {"session":"789456123","processors":{"uid":{"uid":"654123"},"web":{"url":"/Mollie/notify/transactionNumber/090","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-04-20 12:37:34] Mollie.DEBUG: Webhook Notification successfully processed for transaction: 090 and payment: tr_11223344 (Session: 31d2...) {"session":"789456123","processors":{"uid":{"uid":"654123"},"web":{"url":"/Mollie/notify/transactionNumber/090","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-04-20 12:37:35] Mollie.DEBUG: User is returning from Mollie for Transaction 090 (Session: aaas...) {"session":"aaassssdddfff","processors":{"uid":{"uid":"123456"},"web":{"url":"/Mollie/return/transactionNumber/090/token/01010101010101010101010101010","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":null}}} []
[2021-04-20 12:37:35] Mollie.WARNING: Error when verifying Session for Transaction: 090 (Session: aaas...) {"error":"Pending Order for Session poiumnbv1234 not found!","session":"aaassssdddfff","processors":{"uid":{"uid":"123456"},"web":{"url":"/Mollie/return/transactionNumber/090/token/01010101010101010101010101010","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":null}}} []
[2021-04-20 12:37:35] Mollie.ERROR: Checkout failed when finishing Order for Transaction: 090 (Session: aaas...) {"error":"Missing Session for Transaction: 090","session":"aaassssdddfff","processors":{"uid":{"uid":"987654"},"web":{"url":"/Mollie/finish/transactionNumber/090","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":null},"introspection":{"file":null,"line":null,"class":"Shopware_Controllers_Frontend_Mollie","function":"finishAction"}}} []
Failed Order Type 3:
Order with different Sessions, Mollie does not start the session restoration process here:
[2021-06-01 00:40:03] Mollie.INFO: Starting checkout for Transaction: 123 with payment: mollie_ideal (Session: 1234...) {"basket":{"amount":"206,00","quantity":2,"payment":"mollie_ideal","user":"5432"},"tokens":{"creditcard":"","applepay":""},"session":"1234AAABBB1234","processors":{"uid":{"uid":"******"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-06-01 00:40:03] Mollie.DEBUG: Create new Order before payment for Transaction mollie_123 (Session: 1234...) {"session":"1234AAABBB1234","processors":{"uid":{"uid":"******"},"web":{"url":"/Mollie/direct","ip":"127.0.0.*","http_method":"GET","server":"domain.tld","referrer":"https://domain.tld/checkout"}}} []
[2021-06-01 00:41:22] Mollie.INFO: Incoming Webhook Notification for transaction: 123 and payment: tr_qwertzui (Session: AAAB...) {"session":"AAABBBCCC1234","processors":{"uid":{"uid":"010101010"},"web":{"url":"/Mollie/notify/transactionNumber/123","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
[2021-06-01 00:41:23] Mollie.DEBUG: Webhook Notification successfully processed for transaction: 123 and payment: tr_qwertzui (Session: AAAB...) {"session":"AAABBBCCC1234","processors":{"uid":{"uid":"010101010"},"web":{"url":"/Mollie/notify/transactionNumber/123","ip":"127.0.0.*","http_method":"POST","server":"domain.tld","referrer":null}}} []
Theory:
The user might have closed/stopped the window before it reached the server properly. The order is saved with status paid. When comparing the session ids the plugin should have found out that the session ids are not matching and would have started the proces to recreate the session, which can only mean, that the process was stopped before the plugin could do this, hence we do not see any other entries in the logs after that.
If this is possible, this would also be a problem in the paypal plugin too, as the session/token management could not have taken over yet.
TL;DR:
Suggestion: adding the payment token as described in https://developers.shopware.com/developers-guide/shopware-5-upgrade-guide-for-developers/#payment-token if possible. By the guide it should trigger a service inside shopware which will recreate the session properly. Maybe it will already be enough to simply change the return url from "/Mollie/return/transactionNumber/120/token/asdfghjkl987654321" to "/Mollie/return/transactionNumber/120/swPaymentToken/asdfghjkl987654321" but maybe more configuration is needed here.
Info: it seems that shopware 6 also uses the payment tokens and maybe it needs to be changed there too.
![dependabot[bot] avatar](https://avatars.githubusercontent.com/in/29110?v=4 "dependabot[bot]")
React
Typescript
Django
Laravel
Facebook
Microsoft
Google
Alibaba
D3
Tencent
