Checkout Process stops in some Cases

[danielDigitalArt]

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.

[boxblinkracer]

Hi

thanks for this detailed log.

So the thing with the payment token is, that it is only available starting from a specific shopware version. Thats why a custom implementation has been done. The important thing, it does basically the same.

The reason why it only sets a cookie, is because the payment token behaviour does also do it in that way. After a redirect, the user should be automatically logged in by Shopware standard (because of that cookie)

There are indeed a few Cypress tests about lost sessions that cover the functionality in the mollie plugin. so like starting checkout....going to mollie payment page, then removing the session and coming back, which triggers the restoring of the session.

Still, I'm currently investigating, what could happen and why its not working in some rare scenarios.

What I see from the log is, that Mollie recognizes that a session needs to be restored. Then theres NO error when setting the cookie and processing anything, but after the next redirect, when checking the session, it was not restored by Shopware.....but that would also be tested with Cypress....so very weird

do you see any problems or anything in the core logs of Shopware?

i also hope it explains it a bit more :)

thank you

[danielDigitalArt]

Hi @boxblinkracer,

i looked into the core production log of one of the failed attempts. Sadly there is nothing in here for that time.

I also found an order which went fine, but also logged the session error. here are the first log entries that it saved:

``` 09:26:10] Mollie.DEBUG: User is returning from Mollie for Transaction 111 09:26:10] Mollie.ERROR: Checkout failed when finishing Order for Transaction: 111 09:27:45] Mollie.INFO: Starting checkout for Transaction: 111 09:27:45] Mollie.DEBUG: Create new Order before payment for Transaction mollie_111 ```

A failed transaction logged this:

``` 19:53:57] Mollie.DEBUG: User is returning from Mollie for Transaction 123 19:53:57] Mollie.NOTICE: Missing Session! Restoring Session for Transaction: 123 19:53:58] Mollie.ERROR: Checkout failed when finishing Order for Transaction: 123 ```

From what i could see in the plugin file, the "directAction" function is calling the Session Management here, but when is the direct action being done? Maybe it is already too late in the process. When doing this for compatibility reasons, would it still not a good idea to try to let shopware resolve the paymenttoken session before the plugin will try to do it on its own? For this it only needs to set the return parameter with a different name (swPaymentToken), then shopware should resolve this (at least according to the upgrade guide). When this functionality is not available in older shopware versions, it might just get ignored, and then the mollie plugin can handle it.

In general it would also be questionable wheather one has to support older shopware versions anymore, i could not find an official php support table, but i found this here: https://stackoverflow.com/questions/62953186/shopware-5-which-shopware-version-uses-which-min-php-version

If it is correct shopware < 5.6 only support php versions which also went out of support last year.

[boxblinkracer]

Hi

the directAction is called when starting the checkout process, then the mollie payment page is being displayed afterwards the returnAction is used to verify the session, and then a redirect is done to the finishAction

people are using older shopware versions with mollie which also requires PHP 5.6, theres no way at the moment, we already thought about that, but its not possible at the moment

regarding the payment token. we also have to support "lost sessions" in older versions that do not have the payment token. and if you take a look at the image i've attached, you see that its the same what is happening. Shopware does only set a cookie and starts a redirect...its the same. the only difference is how the cookie is created, because the Cookie class is not existing in earlier versions, and setCookie isnt too, thats why setcookie() is used. and it ends in the same cookie, and als already mentioned, its basically working and proven to work.

I'm not saying that a paymentToken will never be added...but that cannot be the problem here. it has to be something special.... do you know if it might only affect special sub shops?

also in your upper samples...why do you think transaction 111 has to do with sessions?

[boxblinkracer]

Hi

i'm currently thinking......what if everything is working with session restoring, but only the checks fail....

Mollie checks for payment variables, if they are existing in the session. but what if we change that to simply check "sUserId" (i know this is the general approach and also the payment token subscriber uses it).....it had a reason....because if those params are not correct, then a payment cannot be finished correctly.

so either a) its working with that change, because in some edge cases those are not valid even though they should, or b) without these checks the payment fails, but its skipped anyway at the moment...

[danielDigitalArt]

The Transaction 111 indeed has nothing to do with session, i found this wrong, this was a cancelled order.

Your idea about the false check of sOrderVariables might be a possibility here, but this can only be the case if shopware or another Plugin somehow removes the sOrderVariables when going into the finish action. I checked our plugins, aswell as the delivery date plugin, none of them do anything with it in the checkout finish process. But i somehow doupt that this would solve it, because that would also destroy the normal process for a customer if something in the checkout finish process stops the function here and redirects to the confirm page, because then the orderVariables would be missing, right? Also the problem would then occur always, as the mollie plugin would never see the orderVariables here.

For the Token: What do you think would happen if you rename the Token in the return url to the one that shopware checks for? I would think that a newer shopware version would see it and handle sessions. When it is an older Version which does not handle paymentTokens it might very well do nothing with it and we would then have separate parts of the process handling the paymenttoken according to their respective Shop-Version-Numbers. Im just asking this, because i know of another shop, where one of our plugins also would check for a specific session-info, and so far we never faced a problem there. This shop only uses payment methods like paypal or amazon pay, so i think they would have these problems too if it fails.

[boxblinkracer]

hi

i think we need a phone call for this do you have a number? are you in the slack of shopware, can you contact me?

[boxblinkracer]

i think i can reproduce it

can you tell me the time when the order is started, and when the user got back?

i talked to shopware, the restoring process from shopware is just the s_core_sessions table (if database handler is used) so depending on the cookie, that session is then "restored".

so we could confirm that the process of the mollie plugin is totally fine and it does the same thing as the payment token, which is great

the problem is, that the s_core_session seems to not have data, thats why the restoring did not really work. i can reproduce it, if i just set the "expiry" to "0", then its not working anymore

so either the s_core_session is expired, or there is a mismatch in the ids when restoring setting the cookie

ill continue debugging...but maybe this helps for now

[danielDigitalArt]

The Process of the order 123 started at: 19:53:09, then the webhook came back at 19:53:57

I looked into the session table and extracted 2 sessions here: first-modified: 1625054921 = 30-06-2021 - 14:08:41 first-expiry: 1625056361 = 30-06-2021 - 14:32:41

second-modified: 1625053028 = 30-06-2021 - 13:37:08 second-expiry: 1625054468 = 30-06-2021 - 14:01:08

When im not mistaken, shopware will update the timestamps when the user loads a page in the shop, so if he is continiously reloading the page he will not get logged out.

[boxblinkracer]

hi the webhook doesnt matter

how can i reach you?

[boxblinkracer]

Hi so 1.8.8 has been released today. that one extends the session expiration time. so we now have 2 things in the mollie plugin

• browser switch does work
• session restoring also works if the time expired, because the plugin increases it

what would however not work (there will be a wiki page on that) is, that restoring of sessions works if data is not even existing anymore in shopware

so there is still the thought about adding our separate backups, but that would lead to a drastic amount of additional database data. so for now we will stick with shopware standard.

but the second with with the time extension from above would now work.

let me know if we can close this issue for now

cheers christian

[boxblinkracer]

I havent heard back, it is also improved now, so i would now close this issue until we might face it again, thanks for your help on that