Intermittent Deadlocks on Checkout Success

[perryholden]

On checkout success, when ShipperHQ creates packages (entered into the order comment history), the checkout success page breaks, causing the customer to think that the order did not go through. This is due to a SQL deadlock condition. It only happens intermittently.

Preconditions

1. Magento 2.2.6
2. PHP 7.1
3. shipperhq/module-shipper: 20.20.2

Steps to reproduce

1. Configure ShipperHQ to create packages for the orders automatically on checkout success.
2. Place an order on the frontend.

Expected result

• The customer will be taken to the checkout success screen.

Actual result

• Intermittently, the checkout success screen will be blank due to the following deadlock:

INSERT INTO sales_order_status_history (parent_id, is_customer_notified, is_visible_on_front, comment, status, entity_name) VALUES ...

UPDATE sales_order_item SET order_id = '123456', parent_item_id = NULL, quote_item_id = '123456', store_id = '1', created_at = '2018-12-13 15:06:41', product_id = '1234', product_type = 'simple', product_options = ...

Additional Details

• This extension is unnecessarily calling $order->save() to record order comment history. This conflicts with another $order->save() elsewhere in your extension (\ShipperHQ\Shipper\Observer\AbstractRecordOrder::recordOrder line 145). Both of these "order saves" can cause a deadlock, so it is 100% isolated to this extension.
• The solution is not to rely on $order->save() to save the comment history, but to instead rely on the OrderStatusHistoryRepository.
• This composer patch fixes the issue (I have verified this to resolve it completely):

diff --git a/src/Helper/Package.php b/src/Helper/Package.php
index 41935ca..50b12e2 100644
--- a/src/Helper/Package.php
+++ b/src/Helper/Package.php
@@ -57,6 +57,11 @@ class Package extends \Magento\Framework\App\Helper\AbstractHelper
      */
     private $carrierGroupHelper;
 
+    /**
+     * @var \Magento\Sales\Api\OrderStatusHistoryRepositoryInterface
+     */
+    protected $orderStatusHistoryRepository;
+
     /**
      * Package constructor.
      * @param \Magento\Framework\App\Helper\Context $context
@@ -64,13 +69,15 @@ class Package extends \Magento\Framework\App\Helper\AbstractHelper
      * @param \ShipperHQ\Shipper\Model\Order\PackagesFactory $orderPackageFactory
      * @param Data $shipperDataHelper
      * @param CarrierGroup $carrierGroupHelper
+     * @param \Magento\Sales\Api\OrderStatusHistoryRepositoryInterface $orderStatusHistoryRepository
      */
     public function __construct(
         \Magento\Framework\App\Helper\Context $context,
         \ShipperHQ\Shipper\Model\Quote\PackagesFactory $quotePackageFactory,
         \ShipperHQ\Shipper\Model\Order\PackagesFactory $orderPackageFactory,
         Data $shipperDataHelper,
-        CarrierGroup $carrierGroupHelper
+        CarrierGroup $carrierGroupHelper,
+        \Magento\Sales\Api\OrderStatusHistoryRepositoryInterface $orderStatusHistoryRepository
     ) {
 
         parent::__construct($context);
@@ -78,6 +85,7 @@ class Package extends \Magento\Framework\App\Helper\AbstractHelper
         $this->orderPackageFactory = $orderPackageFactory;
         $this->shipperDataHelper = $shipperDataHelper;
         $this->carrierGroupHelper = $carrierGroupHelper;
+        $this->orderStatusHistoryRepository = $orderStatusHistoryRepository;
     }
 
     /**
@@ -193,11 +201,13 @@ class Package extends \Magento\Framework\App\Helper\AbstractHelper
                                 $carrier_group['name']
                             );
                             $boxText .= __('Transaction ID: ') . $carrier_group['transaction'];
-                            $order->addStatusToHistory($order->getStatus(), $boxText, false);
                         } else {
                             $boxText = __('Transaction ID: ') . $carrier_group['transaction'];
-                            $order->addStatusToHistory($order->getStatus(), $boxText, false);
                         }
+
+                        /** @var \Magento\Sales\Model\Order\Status\History $history */
+                        $history = $order->addCommentToStatusHistory($boxText, $order->getStatus());
+                        $this->orderStatusHistoryRepository->save($history);
                     }
                 }
             } catch (\Exception $e) {
@@ -205,7 +215,6 @@ class Package extends \Magento\Framework\App\Helper\AbstractHelper
                 $this->_logger->critical('ShipperHQ save order package error: ' . $e->getMessage());
             }
         }
-        $order->save();
 
         //record without carrier group details?
     }

[TravisBernard]

Hi @dewayneholden I'm familiar with this issue. I know we've done some improvements here in the last few months. Have you reproduced this issue on the most recent release (20.22.1)?

[perryholden]

@TravisBernard - I have not. However, in examining the code, the conditions (two calls to $order->save()) are still present, so I would assume that the issue still applies (it is due to those calls happening at the same time). The thing is, it being intermittent on production, I cannot install the latest version, remove my patch, and verify that the issue happens, as that will introduce risk for customers to continue to deal with the issue.

Honestly, I recommend following my recommended fix using the order history repository in the Helper/Package.php class, regardless, as that invalidates the need for call to the save method on the order object, which shouldn't be done anyhow.

Thanks.

[TravisBernard]

@dewayneholden Thanks for the feedback. I'll bring the patch to the team and see what the consensus is and if/when we can get it worked into the source. We appreciate your diligence tracking this down and submitting a fix.

[almuete]

Hi Guys,

Any idea about this issue?

#39 /app/server/vendor/magento/framework/Interception/Interceptor.php(74): Magento\Checkout\Model\ShippingInformationManagement->saveAddressInformation('1706619', Object(Magento\Checkout\Model\ShippingInformation))
#40 /app/server/vendor/magento/framework/Interception/Chain/Chain.php(70): Magento\Checkout\Model\ShippingInformationManagement\Interceptor->___callParent('saveAddressInfo...', Array)
#41 /app/server/vendor/magento/framework/Interception/Interceptor.php(138): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\Checkou...', 'saveAddressInfo...', Object(Magento\Checkout\Model\ShippingInformationManagement\Interceptor), Array, 'shipperhq_shipp...')
#42 /app/server/vendor/shipperhq/module-shipper/src/Plugin/Checkout/ShippingInformationPlugin.php(177): Magento\Checkout\Model\ShippingInformationManagement\Interceptor->Magento\Framework\Interception{closure}('1706619', Object(Magento\Checkout\Model\ShippingInformation))
#43 /app/server/vendor/magento/framework/Interception/Interceptor.php(142): ShipperHQ\Shipper\Plugin\Checkout\ShippingInformationPlugin->aroundSaveAddressInformation(Object(Magento\Checkout\Model\ShippingInformationManagement\Interceptor), Object(Closure), '1706619', Object(Magento\Checkout\Model\ShippingInformation))
#44 /app/server/var/generation/Magento/Checkout/Model/ShippingInformationManagement/Interceptor.php(26): Magento\Checkout\Model\ShippingInformationManagement\Interceptor->___callPlugins('saveAddressInfo...', Array, Array)
#45 /app/server/vendor/magento/module-checkout/Model/GuestShippingInformationManagement.php(44): Magento\Checkout\Model\ShippingInformationManagement\Interceptor->saveAddressInformation('1706619', Object(Magento\Checkout\Model\ShippingInformation))
#46 [internal function]: Magento\Checkout\Model\GuestShippingInformationManagement->saveAddressInformation('cdaba6534fd3c51...', Object(Magento\Checkout\Model\ShippingInformation))

[2019-03-14 23:40:48] report.CRITICAL: PDOException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction in /vendor/magento/zendframework1/library/Zend/Db/Statement/Pdo.php:228

Its happening when I'm creating order in the admin and I'm selecting shipprtHQ fo my shipping.

Warm Regards
Armin

[wsajosh]

Hi @almuete It sounds like the same issue. We've got this scheduled in to be looked at next week. There's a patch file above submitted by another user, it would be worth taking a look at that if this issue is causing you immediate troubles

[wsajosh]

@dewayneholden Thanks for the code submission. I've had to make a slight change so this is compatible with 2.1 still but otherwise looks good! This is currently in QA and if approved will be in the next extension update

[wsajosh]

This is addressed in 20.24.1. Thanks for raising this.