Developer forum

Forum » Ecommerce - Standard features » Ecom is sending out multiple order confirmation mails after checkout with quickpay

Ecom is sending out multiple order confirmation mails after checkout with quickpay

Jonas Krarup Dam
Reply

Hi,
We have a site where some orders are resulting in multiple confirmation emails (and the "CheckoutDoneOrderComplete" notification subscriber is hit multiple times. 

When I look at the log for the orders, it looks like quickpay is hitting the callback url multiple times.

Is this a known problem? has it been fixed in newer versions of DW/Ecommerce?

version info:
Dynamicweb version: 9.10.14

Dll versions: 

Dynamicweb.Ecommerce.dll 1.10.96

Dynamicweb.Ecommerce.CheckoutHandlers.QuickPay3.dll 2.0.0
Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.dll 2.0.11


Thanks, Jonas


Replies

 
Nicolai Pedersen
Reply

Not a known problem - but we have fixed some concurrency issues with checkouthandlers, but I believe your version contains those.

We have seen some things in your implementations (Espresso) where some async json-ish is happening as part of the checkout flow that has causes issues before. Might be worth checking in dev tools during checkout what chatter happens on xhr/fetch.

In you order log you can see a thread id of each callback. Can you share that information - will tell if it is the same request doing something twice or if it is two different requests doing something once...

BR Nicolai

 
Jonas Krarup Dam
Reply

here is a partial log for an order that has sent out multiple confirmations. 

looks like seperate threads - there are also 1½-3 minutes between each email being sent.

 

Wed, 12 Jan 2022 11:09:08 Order Going to checkout logic (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Starting checkout logic (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Order is kept in context - getting new order id (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Order is kept in context - new order id (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Before OrderIsPassedToCheckoutHandler notification. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order After OrderIsPassedToCheckoutHandler notification. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Passing order to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Order Before StartCheckout. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:08 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Checkout started (OrderID:ORDER-4037 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:09:08 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Autopost to QuickPay (OrderID:ORDER-4037 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:09:14 Order Cart has an orderID or IsCart=false: ORDER-4037 and is being reloaded 15820 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Getting order from Context.Cart: ORDER-4037 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Order is not complete, next step is the first step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Previous step: 1 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Next step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Render step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:09:14 Order Rendering step 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:114, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Cart has an orderID or IsCart=false: ORDER-4037 and is being reloaded 15820 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Getting order from Context.Cart: ORDER-4037 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Getting next step from submit button: 1 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Saved 25 fields to the order: 'EcomOrderCustomerCompany changed: False', 'EcomOrderCustomerName changed: False', 'EcomOrderCustomerAddress changed: False', 'EcomOrderCustomerAddress2 changed: False', 'EcomOrderCustomerZip changed: False', 'EcomOrderCustomerCity changed: False', 'EcomOrderCustomerCountry changed: False', 'EcomOrderCustomerPhone changed: False', 'EcomOrderCustomerEmail changed: False', 'EcomOrderCustomerComment changed: False', 'EcomOrderDeliveryCompany changed: False', 'EcomOrderDeliveryName changed: False', 'EcomOrderDeliveryAddress changed: False', 'EcomOrderDeliveryAddress2 changed: False', 'EcomOrderDeliveryZip changed: False', 'EcomOrderDeliveryCity changed: False', 'EcomOrderDeliveryCountry changed: False', 'EcomOrderDeliveryPhone changed: False', 'EcomOrderDeliveryEmail changed: False', 'EcomCartShippingmethodId changed: False', 'EcomCartPaymethodId changed: False', 'Custom field: EspressoPostnordSearchQuery changed: False', 'Custom field: EspressoGlsShippingMethodId changed: False', 'Custom field: EspressoPostnordShippingMethodId changed: False', 'EcomOrderCustomerAccepted changed: False' (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Validating order price. (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Going to checkout logic (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Starting checkout logic (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Order is kept in context - getting new order id (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Order is kept in context - new order id (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Before OrderIsPassedToCheckoutHandler notification. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order After OrderIsPassedToCheckoutHandler notification. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Passing order to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Order Before StartCheckout. Order price: 646; IsProcessingCheckout: True (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:49 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Checkout started (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872.)  
Wed, 12 Jan 2022 11:14:49 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Autopost to QuickPay (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:124, HashCode:56631872.)  
Wed, 12 Jan 2022 11:14:55 Order Cart has an orderID or IsCart=false: ORDER-4038 and is being reloaded 15820 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Getting order from Context.Cart: ORDER-4038 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Order is not complete, next step is the first step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Previous step: 1 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Next step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Order saved (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Render step: 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:14:55 Order Rendering step 0 (IsCart:True, Complete:False), (IP:188.228.73.156, Url:/Default.aspx?ID=5699), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.Cart.CheckoutHandler Redirecting to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Callback started (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Response validation started (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Current QuickPay operation is authorize (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Payment succeeded with transaction number 289866379 (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order is kept in context - upgrading to order (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Removing cart from session (CheckoutHandler.SetOrderComplete) (OrderID:ORDER-4038 (IsCart:True, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order was upgraded successfully (OrderID:ORDER-4038 (IsCart:False, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Setting order complete (OrderID:ORDER-4038 (IsCart:False, Complete:False) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Updating order stock (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Saving order (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:06 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow SetOrderComplete done (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:06 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:06 Order Called CheckoutDone (pageID:5699) (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:07 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:07 Order Order is complete (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:07 Order Send notification emails. (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:07 Order Notification mail, To: 'Delivery email ', Subject: 'Tak for din ordre', From: ' Juul's Vin & Spiritus' (IsCart:False, Complete:True), (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:10 Order RedirectToCheckoutHandler callback - CheckoutHandlerOrderId: 'ORDER-4038' (IsCart:False, Complete:True), (IP:188.228.73.156, Url:/Default.aspx?ID=5699&CheckoutHandlerOrderID=ORDER-4038&QuickPayState=Ok), Thread:79, HashCode:56631872)  
Wed, 12 Jan 2022 11:15:10 Dynamicweb.Ecommerce.Common.Context The Context.GetCart() is not a cart and cannot be updated. (Order.IsCart = False, Order.Complete = True, Order.AutoId = 15820, SessionCartKey = EcomCart.'Shopping')  
Wed, 12 Jan 2022 11:15:10 Dynamicweb.Ecommerce.Cart.CheckoutHandler Redirecting to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699&CheckoutHandlerOrderID=ORDER-4038&QuickPayState=Ok), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:15:10 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow State ok (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:188.228.73.156, Url:/Default.aspx?ID=5699&CheckoutHandlerOrderID=ORDER-4038&QuickPayState=Ok), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:36 Dynamicweb.Ecommerce.Cart.CheckoutHandler Redirecting to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Callback completed successfully (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.211, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:59, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 #####hidden#####  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Callback started (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Response validation started (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Current QuickPay operation is authorize (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Payment succeeded with transaction number 289866379 (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order is kept in context - upgrading to order (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:44 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Removing cart from session (CheckoutHandler.SetOrderComplete) (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order was upgraded successfully (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Setting order complete (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Updating order stock (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Saving order (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:45 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow SetOrderComplete done (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:16:45 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:45 Order Called CheckoutDone (pageID:5699) (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:46 Order Order saved (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:46 Order Order is complete (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:46 Order Send notification emails. (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:16:46 Order Notification mail, To: 'Delivery email ', Subject: 'Tak for din ordre', From: ' Juul's Vin & Spiritus' (IsCart:False, Complete:True), (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872)  
Wed, 12 Jan 2022 11:18:06 Dynamicweb.Ecommerce.Cart.CheckoutHandler Redirecting to checkout handler: Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Callback completed successfully (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:119, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Callback started (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Response validation started (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Current QuickPay operation is authorize (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Payment succeeded with transaction number 289866379 (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order is kept in context - upgrading to order (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Removing cart from session (CheckoutHandler.SetOrderComplete) (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Order was upgraded successfully (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Setting order complete (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)  
Wed, 12 Jan 2022 11:18:15 Dynamicweb.Ecommerce.CheckoutHandlers.QuickPayPaymentWindow.QuickPayPaymentWindow Updating order stock (OrderID:ORDER-4038 (IsCart:False, Complete:True) Total:646, orderline total:DKK646,00; Orderlines:4 - Products:4, Discounts:0, Taxes:0, BOM:0, (IP:193.162.142.212, Url:/Admin/Public/Gateways/CheckoutHandler/QuickPay/QuickPayPaymentWindowFormCallBack.aspx), Thread:79, HashCode:56631872.)
 
Jonas Krarup Dam
Reply

The customer has contacted quickpay support, and they say:
 

Jeg kan se at vi sender callback til jer på den pågældende betaling, men at der sker en fejl når i skal modtage callback. Har du evt. en it ansvarlig, så tænker jeg at I skal have kigget på jeres callback endpoint, kig evt. i jeres server logs, der skulle i meget gerne kunne se at vi forsøger at lave callback til jer.

I can't see anything about errors on the callback in the log on the order, or in any of the system/log/ecom logs. 

Should I be checking somewhere else, too?
 
 
 
Nicolai Pedersen
Reply

There is a lot of errors in the monitoring/event viewer:

Seems like sometimes something odd is coming in the callback containing markup. Could be something in the payment form that contains some data send to quickpay and then becomes part of the callback data.

On another note there is a good list of errors that you should look into.

And something we cannot fullyt explain yet is this:

Callback is coming in (and it is slow to execute), then the receipt is coming in. But for some reason the completion of some of your carts are really slow. Maybe export, live integration or something?

But it seems like the callback is 'hanging' and waiting for something causing Quickpay to send another request for callback when no response is coming - timeout something.

...

I have noticed that the site is really slow when navigating around - could also sometimes cause slow responses and then this happens...

But we are not done investigating - but what happens in your end that could cause these delays? CheckoutDoneOrderIsComplete subscribers? Anything integration? Other fancy stuff in the receipt template?

BR Nicolai

 
Jonas Krarup Dam
Reply

There is a live integration running - 99.9% standard integration framework, but an older version.

for the specific request mentioned in the screenshot you included here, the response time from NAV seems to be ok:
1/19/2022 12:14:33 PM: DebugInfo: Request CalculateOrder sent: '<?xml version="1.0" encoding="UTF-8" standalone="yes"?><CalculateOrder><Orders><Order><column columnName="OrderCustomerAccessUserExternalId">Anonymous</column><column columnName="CreateOrder">True</column><column columnName="OrderShopID">SHOP1</column><column columnName="OrderID">ORDER-4147</column>#####SNIP EXTRA######
1/19/2022 12:14:33 PM: DebugInfo: Response CalculateOrder received: '<?xml version="1.0" encoding="utf-8"?><tables><table tableName="EcomOrderLines">##### SNIP ORDERLINES</table><table tableName="EcomOrders"><item table="EcomOrders"><column columnName="OrderCreated"><![CDATA[TRUE]]></column><column columnName="OrderID"><![CDATA[SO422504]]></column>######## SNIP EXTRA COLUMNS </item></table></tables>'.

As far as I know, there shouldn't be anything fancy in the recipt template or the reciept email.

We have written with Quickpay support, and it looks like they get a timeout, which fits with your explanation. 

I will try to deactivate the live integration temporarily, and see if we still get the same problem.

Is there any way we can see the full data that is being sent to/from quickpay? 

Regards, Jonas



 

 

 

You must be logged in to post in the forum