[ISSUE] Shipments created while another is processing for the same order

[Sental]

Describe the bug If you create a shipment for an order and then while Magento is awaiting a successful response from mollie (or possible while the order is still locked) and a second shipment is sent towards Magento, the order does not fully process correctly. The Order Item does not have it's qty_shipped updated and the order status does not go to complete (in the case of a fully shipped order). I think this could be related to Issue: #655

Used versions

• Magento Version number(eg 2.3.5): 2.4.5-p1
• Open source/Enterprise/B2b: Open Source
• Mollie version number (Check configuration): 2.23.0

To Reproduce Steps to reproduce the behavior:

1. Go to the magento admin, create an order and pay for it.
2. Ship one product on the order
3. Immediately ship the rest of the order
4. The shipment is created.
5. The Shipped : 1 line does not appear in the item details and the qty_ordered column is not updated in the database.

Expected behavior The order & order items are all saved as shipped with the status' updated. The shipment in magento is created.

Actual behavior The shipment in magento is created. The qty_shipped for the order lines in the second shipment are not updated and the order status is not updated.

Screenshots Shipment 1: Shipment 2: Order Line:

Additional context Add any other context about the problem here.

[Frank-Magmodules]

Hello there, @Sental! I appreciate you bringing up this matter. 

I'm unable to replicate it directly, so I have a couple of questions. Firstly, is the "Cadeaubon voor Vivara" a virtual product, or does it come from an external plugin? It's possible that there could be a conflict related to this. Secondly, can you reproduce this issue across all orders, or is it specific to certain ones with a Cadeaubon?

Thanks!

[Sental]

@Frank-Magmodules I'm having it with all types of products. I should have mentioned in the ticket that most of these orders were paid using the payment link email and the shipped via the magento /order/{id}/ship api in quick succession. The cadeaubon product is a mageworx gift card. That doesn't get shipped. The other products are supposed to be shipped and I have shipments that are saved, but hte qty_shipped isn't updated.

[Quazz]

I've also experienced the qty_shipped not updating; though I cannot comment on the exact cause.

I've seen this occur on orders that have multiple items or only a single item with various payment methods, shipments are created at a later date.

The order status ends up on "Completed" so it's not the end of the world, but our RMA module does make use of the value for some logic.

I have tried to discern a pattern (amount of time between creation of the order and shipment, amount of items, payment methods, etc) but ultimately found none.

I actually wanted to make a report about this much earlier, but every time I was writing it up an update related to bugfixing the lock system was released so I tried updating first. As far as I can tell, the frequency has gone down on recent versions; but it still occurs.

[Frank-Magmodules]

Hello, @Quazz and @Sental! We have taken note of your issues and are currently conducting research on them. We will provide you with further updates shortly. It's possible that we may require additional information later, and if that's the case, we'll inform you accordingly.

[Frank-Magmodules]

Hi There! 

We have investigated this again, but we can’t seem to reproduce this. We tried various ways:

• Manually shipping the order items.
• Manually shipping the order items in 2 separate tabs at the same time.
• Shipping the order using the API one after the other (order/{{order_id}}/ship)
• Shipping the order using the API at the same time.

But in all cases, we see the expected behavior. When trying to create two shipments at the same time, we can see in the logs that the second shipment waits on the first shipment to complete, as we expected. 

Could it be that you have some other module that is also invoking the shipment behavior that causes this?

[Quazz]

I've noticed something interesting.

We have an extension that logs changes to order data so we can have an easy overview of the order progress.

First we have "Status changed" event

• When a shipment gets created, the state of the order gets updated to complete from processing (good)
• The qty shipped gets updated to the appropriate quantity (good)
• The last transaction ID (in sales_order_payment) gets updated to the shipping transaction id (good)

Then the "Shipment created" event happens

Here's where things get weird.

Most of the time this goes fine and the shipment is simply created and everything is fine.

But sometimes the following happens

• Changes shipped qty back to the original
• Changes the last trans id (in sales_order_payment) back to the original order transaction id

I don't have that many examples to check at the moment since it only happens sometimes.

Still haven't found a common factor between them, perhaps there isn't one, it does make it impossible to reproduce.

It's possible it's not caused by Mollie, but it's hard to track down due to its seemingly random nature.

edit: Can't believe I didn't think of this previosuly, but the random nature can easily be explained if it's being caused in an Observer since their order of exeuction is random... (well technically not entirely random, based on the merge order of configuration files)

It's worth noting that if you use MSI (Magento 2 Inventory module) it uses the shipment event, so this module should add a depend for it in module.xml so it goes later in execution order. (it's safe to have modules in there that aren't present on the system, for installations that dont have MSI)

[Frank-Magmodules]

Hello @quazz, As this is super hard for us to reproduce, would it be possible for you to test if that fixes the issue for you? Thanks a lot!

[Quazz]

Hello @Quazz, As this is super hard for us to reproduce, would it be possible for you to test if that fixes the issue for you? Thanks a lot!

@Frank-Magmodules thanks for working on this. I've deployed the new version; now we have to wait and see.

[Frank-Magmodules]

Thanks @Quazz , keep me posted.

[Frank-Magmodules]

Hi @Quazz , do you have some good news here? ;-)

[Quazz]

@Frank-Magmodules Unfortunately, it doesn't appear to have resolved the issue.

It's possible that the issue isn't caused by Mollie directly, it's hard to say based on the available data.

As far as I can tell, it's a race condition of sorts. When a shipment gets created, the order status also gets updated, I'm guessing that the order gets saved twice seperately with different data, one overwriting the other. Though as far as I understand it, the lock service should prevent this.

That said, the following kind of logging can be observed in Mollie log when a shipment is created that causes this issue:

[2023-07-20T14:44:20.850732+00:00] Mollie.INFO: info: Locking: mollie.order.4203 [] []
[2023-07-20T14:44:22.234729+00:00] Mollie.INFO: info: Lock for "mollie.order.4203" is already active, attempt 0 (sleep for: 0.5) [] []
[2023-07-20T14:44:22.498621+00:00] Mollie.INFO: info: Unlocking: mollie.order.4203 [] []

The weird thing is that it shouldn't be locked at all at this point, the last lock action was an unlock for this order.

edit:

Ok, after looking at the code, I think it has to do with observers.

CreateMollieShipment hooks on 'sales_order_shipment_save_before' and so does LockUnlockOrder

The issue is, Observers dont respect order. Their execution order is not guaranteed.

This means that the CreateMollieShipment can trigger before the order gets locked.

Do not rely on invocation order Your observer should not make assumptions about the order in which it will be invoked nor should it rely on the execution of another observer. Observers listening to the same event may be invoked in any order when that event is dispatched. https://devdocs.magento.com/guides/v2.3/ext-best-practices/extension-coding/observers-bp.html

[Frank-Magmodules]

HI There @Quazz ,

It’s hard to say if that is the issue, but we can try to see if that is the cause. Can you install this patch to see if that resolves the issue?

This calls the CreateMollieShipment from within the LockUnlockOrder observer.

Please note: If this fixes the issue there needs to be a better solution in place, but for the purpose to pinpoint the root cause of this issue, this should be fine.

[Quazz]

@Frank-Magmodules

I have applied to patch. We'll see how it goes.

[Quazz]

@Frank-Magmodules

Sadly it did not solve the issue (aside from the locking message of course)

[Quazz]

The observer gets triggered on sales_order_shipment_save_before

Eventually the observer reaches https://github.com/mollie/magento2/blob/5636a71c077059e8b4a4d53da133cd5ddc572618/Model/Client/Orders.php#L566 where it saves the order.

https://github.com/magento/magento2/blob/727560d82199f6b938d1906e9d923e2dd40b490a/app/code/Magento/Shipping/Controller/Adminhtml/Order/Shipment/Save.php#L85 controller function plays a role too.

It passes the Order as it is assigned to the shipment by Magento. This means before Mollie modifies it, since the save event for shipment will only get triggered when it reaches save

This explains why there's an orderrepository->save action during an observer event; however this is also potentially why weird problems can arise.

As a result, I will try to put the observer on the _after event instead, this way it should get the updated Magento data without getting in the way of the original save event.

What do you think?

Note: It's still very strange because the shipping qty should be correct when it reaches observer no matter what.

[Frank-Magmodules]

Hello @Quazz and @Sental, are you currently experiencing this problem? If so, kindly get in touch with us directly so that we can exchange environment details and discuss this issue more efficiently.

[Frank-Magmodules]

Good morning, @Quazz and @Sental,

I haven't received any updates on this issue. Would it be possible for us to explore this together, or should we consider closing the matter for the time being?

[Frank-Magmodules]

Hi There @Quazz and @Sental ,

Because of inactivity, I am closing this matter for the time being. If you have any further questions or concerns regarding this issue, please don't hesitate to reopen this ticket or reach out to us directly.

[mokadev]

Hi @Frank-Magmodules

I have the same problem and this patch https://gist.github.com/Frank-Magmodules/896e4aac3c4f7c2cbb475f0c570510c8 didn't work. (I installed the last version of the module)

The problem happened when the invoice is created by Mollie, I have an observer on "sales_order_invoice_register" event which create a shipment and a shipping label.

It seems that the lock placed by mollie prevent throw an exception "Mollie.ERROR: error: Rolled back transaction has not been completed correctly":

[2024-04-30T20:32:36.124848+00:00] Mollie.INFO: info: Locking: mollie.order.220180 [] [] [2024-04-30T20:32:36.428620+00:00] Mollie.INFO: webhook: {"resource":"payment","id":"tr_yneoRi5E6x","mode":"test","amount":{"value":"87.40","currency":"EUR"},"settlementAmount":{"value":"87.40","currency":"EUR"},"amountRefunded":{"value":"0.00","currency":"EUR"},"amountRemaining":{"value":"87.40","currency":"EUR"},"amountChargedBack":null,"description":"100287787","method":"creditcard","status":"paid","createdAt":"2024-04-30T20:28:58+00:00","paidAt":"2024-04-30T20:29:03+00:00",[...],"countryCode":"FR"} [] [] [2024-04-30T20:32:36.490369+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 0 (sleep for: 0.5) [] [] [2024-04-30T20:32:36.990884+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 1 (sleep for: 1.0) [] [] [2024-04-30T20:32:37.991415+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 2 (sleep for: 1.5) [] [] [2024-04-30T20:32:39.491950+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 3 (sleep for: 2.0) [] [] [2024-04-30T20:32:41.492487+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 4 (sleep for: 2.5) [] [] [2024-04-30T20:32:43.992980+00:00] Mollie.INFO: info: Lock for "mollie.order.220180" is already active, attempt 5 (sleep for: 3.0) [] [] [2024-04-30T20:32:46.998544+00:00] Mollie.INFO: info: Unlocking: mollie.order.220180 [] [] [2024-04-30T20:32:46.998743+00:00] Mollie.INFO: info: Key "mollie.order.220180" unlocked [] [] [2024-04-30T20:32:46.998797+00:00] Mollie.ERROR: error: Rolled back transaction has not been completed correctly. [] []

It seems that we can't create a shipment just after the invoice is created.

[Frank-Magmodules]

Hello @mokadev (and others in this issue),

The error indicates that there was an exception somewhere down the line. It’s very unfortunate that it didn’t get logged in these logs though. Would it be possible to check if it’s the exception.log of your webshop or any other log file? That might give some information about why this error is occurring.

If there are no errors, could you describe or share what kind of mutations you are doing on the order and/or shipping objects? This might help us reproduce this issue.

[Frank-Magmodules]

@mokadev and @Quazz, just checking if you've seen my previous comment :)

[mokadev]

Hi @Frank-Magmodules no exception found .

For now to work around the bug i removed my shipping label generation after invoice creation. So the problem is still there (weird that the module lock the order even if Mollie is not enabled) but it doesn't block me anymore.

Thanks

[Frank-Magmodules]

Great @mokadev , thanks for your response. I'm closing this for now. If you have a specific issue or request, please open a new issue with a more detailed description so we can address it more effectively.