Locking for ensuring unique order numbers is not locked enough

I'm having the same issue, I've tried your patch but when I receive a high amount of orders the wait time of 5 seconds still seems to be too low, so it doesn't place the orders. I'm going to do some more tests on why the standard locking isn't working properly and see if I can find the cause.

I think either that or with this method it is still the same issue with the locking, except that it would now result in the timeout.

At least there's no duplicate order numbers anymore, and now I can just manually place the orders that failed :)

Are you using Redis/or a different lock backend? Did you define additional number patterns (for the same entity type)? How can I reproduce this?

Also, it feels weird to me that we're copying the core pattern for claiming queue items while at the same time keep using the lock mechanism?

By the way, the sequence is unique per store, but you could have the same generated sequential number for different stores... Is that what you're experiencing? Or are you getting the same sequential numbers, for the same store?

I think however we should step back and think more generally about the current approach. Does make it possible to create duplicate numbers? Yes. Should it? No.

Well core uses the same pattern when rebuilding menu links, cron, and when importing config... etc, I'm just wondering why is not a problem there?

Is this occurring when the server is under heavy load?

It could also be that we're incorrectly using the locking API? (Nobody uses a while loop and most of the implementations put the operation to protect under the if ($this->lock->acquire()) { condition.

RE: #13

Using a while is basically the same as setting a high timeout, but without aborting. See cron

    // Try to acquire cron lock.
    if (!$this->lock->acquire('cron', 900.0)) {
      // Cron is still running normally.
      $this->logger->warning('Attempting to re-run cron while it is already running.');
    }
    else {

So what seems to be happening is we are getting a race condition on threads waiting for the lock to become available, correct? Locking is working, but things go sideways when enough orders complete and are waiting for their order number sequence to generate.

I don't know if I like the while loop that lasts 5 seconds. Especially since this is blocking the user from seeing the next page, correct? It seems like the most appropriate action is to put each order into a queue and process it that, way.

* Insert into the queue that the sequence needs to be generated.
* Flag that the queue needs to be processed
* Processor picks the first item.

Technically each request should flag a queue item to be worked. The problem is you may want to show the order number to the user on the order complete page.

What concerns me is #7

I've tried your patch but when I receive a high amount of orders the wait time of 5 seconds still seems to be too low, so it doesn't place the orders.

Five seconds is too low, meaning it takes 5+ seconds to go from order_information -> payment -> complete.

Of course, once I submitted my comment I thought of a way to test this.

We can leverage a Nightwatch test for this. JavaScript is asynchronous, which means we can simulate multiple requests at once fairly easily. We need an endpoint that the test can ping which generates a number pattern for a test content entity. The endpoint returns the generated number as a string. The test verifies there are no duplicates.

I haven't had much time to do proper testing yet, but I can at least provide some information that I currently have.
We are using Redis for locking, and only one number pattern. Our orders usually come in at a high rate (20+ in ~ 5 minutes) which results in this issue occurring a few times (I would say about 20% of the orders).

For testing purposes I've increased the timeout from #6 to two minutes (the order is placed in a callback from the payment provider, so customer won't be affected), but the same thing still happened. When the issue does not occur the callback is executed in a few 100 milliseconds, so to me it seems like the the timeout does not really matter because it somehow won't get the lock anyways.

A queue would be nice, but it is indeed problematic if you need to wait for the queue to be processed to continue with the order process.\

Also, we're running on a single node, so there are no time differences. I'm still wondering how the locking API still allows for duplicate numbers, so this might be a core issue?

Another datapoint for this issue - I've experienced it during a period of moderate load where the payment return requests happened about 1 second apart but appear to have taken 4-5 seconds to complete, so would've had considerable overlap. Both requested handled by the same server. Single store, single order number sequence. It seems clear that something is bad with the core DatabaseLockBackend, but I can't see what. I feel that the best approach to solving this is diagnosing that problem and solving upstream rather than trying to layer some extra measures on top.

Further update on how bad this is: we're getting about 2-3 occurrences out of 1000-1200 orders placed per month. Given that the vast majority of our orders are placed in ideal scenarios it does seem that the core database lock mechanism is either highly unreliable or just completely broken for the small number of order being placed in race condition scenarios

Additional data point:

14 order number duplications out of 4844 completed orders (0.29%)

But: only 207 orders have been placed within 10 seconds of another order, so failure rate rises to 6.8%. I've not tried to work out how many of these 207 orders have happened in genuinely overlapping time frames, but I strongly suspect the locking mechanism is completely broken where the requests placing the orders actually overlap.

Now, I have run into this problem. The last monday, we launched a new version of a web commerce moved from D7 to D8. We are getting about 200 orders placed per day, and I get four to six order numbers duplicates per day. I've never notice this issue with commerce 1.x version. It is a very big problem, especially for commerce's owner due to manage duplicate order numbers. The locking system is not working at all. I think it's a very low number of placed orders to get duplicate numbers. I have switched all displayed references to use internal order_id , that seems to be unique. Although I don't get a sequencial number without holes, It's preferebal to duplicate order numbers.

Experiencing this issue with only 200 orders placed per day makes me wonder if the locking is working at all... Or whether it's actually properly implemented.

I've been attempting to recreate this problem in a controlled environment with a simple controller that gets a number pattern plugin and returns the values of getCurrentSequence and getNextSequence, along with some analysis of both the commerce_number_pattern implementation and the core DatabaseLockBackend implementation, and have found one reproducible way in which the lock implementation can allow an order number duplication to occur.

The core lock implementation acquires a lock by attempting to insert a row into the semaphore table keyed by the lock name: if the lock is already held by another process then a row with the same name already exists and the insert fails with a IntegrityConstraintViolationException. The acquire function handles this by calling lockMayBeAvailable and then retrying the insert one more time. Locks are recorded with an expiry time, and competing processes can delete stale locks, which is what lockMayBeAvailable does. So the failure mode looks like this:

1. Customer A completes an order in process A: This process acquires the commerce_number_pattern.plugin.[config_entity_id] lock in getNextSequence. This process then spends longer than the timeout period in the subsequent code between the acquisition of the lock and the update query being committed in the merge call.
2. Customer B completes an order in process B: This process attempts to acquire the lock, and discovers the existing lock hold from process A, so proceeds to wait. The while loop calls into wait (and by extension of how that function is implemented repeatedly calls into lockMayBeAvailable), which ensures process B will eventually gain control of the lock either by naturally acquiring it after it becomes free or by deletion of an expired lock. In this failure mode, it's the latter.
3. Process B now calls into getCurrentSequence, which returns the same value as was returned when process A made the same call, as process A has yet to commit the update with the new value.
4. Process B then proceeds to generate the same next sequence value as process A. Both are eventually committed to the database (with whichever of the merge updates which happens second essentially being a no-op), and both processes release the lock.

I was able to artificially induce this scenario by acquiring the lock with a low timeout value and then adding a sleep before the merge call, but I'm not convinced this is necessarily the cause of all problem seen in production, because IRL the lock is acquired with the default timeout, which is thirty seconds. On my site the last five occurences of this problem occurred in a three minute window during which a total of 21 orders were placed (so 10 of the 21 orders affected), and while logging indicates affected requests do seem to have taken multiple seconds to complete in overlapping time frames, there isn't any evidence they took more than 30 seconds (SAR data for the time window suggest neither the application server or the database server for the site were particularly heavily loaded at the time despite there being a bit of a spike in online shop activity).

Increasing the timeout value from the default 30s might be beneficial, but on the basis of evidence from IRL occurences it would seem to be dubious.

For the moment I'm going to add some logging to see if the expired lock code path does ever get hit in real usage.

Also worth noting there are a few ways this expiry timing problem can surface which could be problematic for some people but don't appear to be applicable in my case:

• Time drift between servers: If competing requests are handled by different servers whose clocks are substantially adrift from each other then one could steal the lock from the other even if both requests are executing in timely fashion
• Clock changes on a single server: If a time synchronisation service (e.g. ntpd, chrony, etc) updated the clock at an inopportune moment it could allow a lock to be falsely expired.

OK I've had another bout of order number duplications, and this time have been able to study some binlogs to see whats happening at the database level. My conclusion is that because transactions aren't being used, the database is essentially optimising away the lock acquisition and release without guaranteeing the work inbetween has been done.

Here's a snippet from one of my bin logs:

SET TIMESTAMP=1621192744/*!*/;
INSERT INTO semaphore (name, value, expire) VALUES ('commerce_number_pattern.plugin.order_default', '190185750560a170282df777.94506854', '1621192774.1883')
/*!*/;
--
SET TIMESTAMP=1621192744/*!*/;
UPDATE commerce_number_pattern_sequence SET entity_id='order_default', store_id='1', number='1006595', "generated"='1621192743'
WHERE (entity_id = 'order_default') AND (store_id = '1')
--
SET TIMESTAMP=1621192744/*!*/;
DELETE FROM semaphore
WHERE (name = 'commerce_number_pattern.plugin.order_default') AND (value = '190185750560a170282df777.94506854')
/*!*/;
--
SET TIMESTAMP=1621192748/*!*/;
...
--
SET TIMESTAMP=1621192744/*!*/;
INSERT INTO semaphore (name, value, expire) VALUES ('commerce_number_pattern.plugin.order_default', '170685206960a17028492be6.29092966', '1621192774.2997')
/*!*/;
--
SET TIMESTAMP=1621192747/*!*/;
UPDATE commerce_number_pattern_sequence SET entity_id='order_default', store_id='1', number='1006595', "generated"='1621192743'
WHERE (entity_id = 'order_default') AND (store_id = '1')
--
SET TIMESTAMP=1621192747/*!*/;
DELETE FROM semaphore
WHERE (name = 'commerce_number_pattern.plugin.order_default') AND (value = '170685206960a17028492be6.29092966')
/*!*/;

Note the SET TIMESTAMP before the second insert: it's the same time as the first INSERT even though some other stuff has happened inbetween. My hypothesis is this:

1. Process 1 performs semaphore insert to acquire the lock. Mysql returns OK, but hasn't yet completely committed the work as we're not in a transaction.
2. Process 2 attempts to insert into semaphore, and the corresponding mysql thread blocks as the table is being worked on elsewhere
3. Process 1 selects from commerce_number_pattern and sends update query. Mysql again returns OK but hasn't yet completed the work. Process 2 continues to block pending the outcomt of the step 1 insert
4. Process 1 now performs semaphore delete to release the lock. Mysql returns OK, notes that the delete query cancels out the insert query so releases lock on this table. It still hasn't fnished work on commerce_number_pattern update.
5. Process 2 insert now completes as the mysql thread is no longer blocked. Process 2 now selects from commerce_number_pattern and very quickly gets an answer back from the query cache as the update hasn't invalidated it yet.
6. Process 2 now has the wrong current sequence number and proceeds to do the same update as process 1

My thinking is that the whole Drupal database locking idea can't be guaranteed to work unless used with transactions to guarantee work is done in the correct sequence by the database.

In our case though I think a better idea is to bypass the Drupal locking mechanism entirely and just use a transaction in combination with a SELECT FOR UPDATE, which is a much more reliable pattern for the work we need to do here.

I'm on annual leave this week, but will certainly have a go at a patch on my return next week.

OK here's a new patch which replaces the previous core locking approach with a transaction and SELECT FOR UPDATE row locking. Artificial testing with an added sleep just before the merge demonstrated correct behaviour (second process blocks on select until first process commits the transaction), and order number assignment worked as expected on a full test order. I'm going to deploy this patch into my production site and will report back if there are any issues.

I wonder if this isn't going to cause performance issues..But don't really know which other alternative we could try, considering the application locking didn't work as expected.

Also, it'd be great if we could write a failing test, so we can be 100% sure your approach is fixing the issue.

#26: I'm not convinced we should change the signature of the method... Since calling the method without the $for_update parameter set to TRUE will potentially cause duplicate numbers, and there's no alternative, so it should probably simply be the default.

We've had issues in Commerce 1.x with forUpdate queries for orders... But this was probably caused by the fact that orders were locked without being necessarily saved, so it might be different this time.

Re-uploading the same patch, without the extra parameter. Let's see if the tests pass.

Same patch, minus the coding standard issues.

Looks good - I was about to submit an almost idenitcal updated patch. Will try this one out now.

Regarding tests, we could try copying core functional javascript test for CSRF tokens (CsrfTokenRaceTest::testCsrfRace()).

Writing a failing test is definitely the way to go here and that is probably the only way we can commit this safely.

I think adapting the CSRF race test is a good approach, however it is tricky to artificially trigger the correct conditions that allow the core locking mechanism to fail. I have a simple module with a single router and controller which I've been using to try this in browser which could be adapted into a dedicted test module as per the CSRF race test, but so far haven't been able to manually trigger the duplication (although I just realised my dev VM only has a single core so would never actually be running the two php processes simultaneously, which obviously doesn't help). I'll continue to work on this to try and get a reliable test failure as time allows.

In the meantime I've been running #32 in production since Monday without issue (over 80 orders placed). The problem tends to happen for us when one of our student groups puts a product on sale and then contacts their membership to let them know it's on sale, generating a spike of 10+ customers coming on to the site at the same time to buy it. I have no way of knowing when this will happen, but I'll continue to monitor - we'll probably get at least one more of these events in the next few weeks before our summer term ends.

I also tried producing a failing test with no success as well.... Attaching it anyway so that it gives us a base, and who knows, perhaps it'll fail on d.org.

I do have 6 cores where this is running. I managed to break it by adding a sleep after we acquire the lock, longer than the lock timeout (i.e 31 seconds), but this isn't a real world scenario, so wondering if we'll simply just have to commit this without additional tests coverage.

The test is doing 1000 Ajax requests to a test route that simply calls the number pattern plugin generate() method and each time it returns a different number.

@pstewart: Have you been encountering issues with the patch since it was applied to your project?

+++ b/modules/number_pattern/tests/src/FunctionalJavascript/NumberPatternTest.php
@@ -159,4 +159,53 @@ class NumberPatternTest extends CommerceWebDriverTestBase {
+    $numbers = range(0, 1000);
+    foreach ($numbers as $i) {
+      $script .= <<<EOT
+      jQuery.ajax({
+        url: "$this->baseUrl/number_pattern_race/generate",
+        method: "GET",
+        headers: {
+          "Content-Type": "application/json"
+        },
+        success: function(response) {
+          jQuery('body').append("<p class='number$i'></p>");
+          jQuery('.number$i').html(response);
+        },
+        error: function() {
+          jQuery('body').append('Nothing');
+        }
+      });

I think getting a Nightwatch test to run the code might be better, as we could throw a 500 error on a lock, which would kill fetch and catch the error more easily.

I'll try and work on one.

Note that the test failure doesn't actually demonstrate the problem, there's a timeout occurring after waiting for one of the generated numbers to appear. It's probably because 1000 requests is too high.

@jsacksick adding a sleep after lock acquisition has been the only way I've been able to trigger this artifically so far. I think the problem is very sensitive to database load and configuration - maybe there's a way of artificially generating database load in requests to try and better simulate real world activity where other unrelated requests are also putting work on to the database (cache misses from pages views etc).

Another possibility is the role the Mysql query cache plays, as I suspect part of the problem with the race relates to the second process being able to get a read from the query cache after the semaphore lock is defeated before the first process's update has progressed far enough to invalidate the query cache. I don't know if that's something you can control in the test environment, but probably worth trying the test with both with query cache enabled and disabled if possible (FWIW the Mysql query cache does not seem to be recommended these days and I've recently disabled it in production with no appreciable impact in performance so far).

Regarding the patch deployment, we've had around 450 orders placed since deploying with no problems, however we've not had any major traffic spikes in that time either so we're yet to see any orders placed in conditions where competing requests overlap and the duplication could be triggered.

Sorry didn't intend to change the status there

Good news! One of our student groups put an in-demand product on sale at 5pm last Friday which resulted in a small order spike with five orders placed in a 2 minute window, and no order number duplication occurred. Two of these orders were placed in requests that started just under 1.2s apart with both requests taking over 3s to complete, so were definitely overlapping. It's hard to be certain these two would've resulted in order number duplication without the patch, but they're a very strong candidate: based on previous experience I'd say there's a 70-80% chance they would've contended the lock and duplicated an order number.

I will continue to monitor to try and get more datapoints, but it looks very promising that #32 resolves the issue in real world usage.

I decided to go ahead and commit the patch from #32 as I believe this is the right approach.

Simulating concurrency in tests isn't trivial, if one manages to do that properly, adding tests coverage in the future would be great.