Create a utility method to compare an orders changed date against the database

Tagging for the Commerce sprint. If this lands, we should target contribs which should use this function and get things straightened up as fast as possible. I think this makes sense.

My only suggestion I had was to wrap this in a static cache based on order ID. On order save we either reset the entire static cache, or remove the one order. Kind of like how drupal_get_title() works.

;) How about we get a test, too?

My only suggestion I had was to wrap this in a static cache based on order ID

Off-topic but related: Do you think a static cache might also help in #1804592: During AJAX form submission in checkout, the $order argument passed by the Form API is incorrect.? I am concerned that multiple calls to commerce_order_load() may cause a bottleneck or deadlocks

Regarding tests... I really need to learn how to write them.

Here's my first attempt at a test for this. Please check my logic because I'm not sure I have it right.

Definitely getting too ambitious. I looked at the commerce entity controller and realized that the changed date gets updated with every call to save() so I've simplified the patch as much as possible. Basically saying, save the order and then check to see if the one we are referencing is stale by using our helper function to check the values in the database. Pretty sure this would cover our use case for Ajax updates, etc.

Whoops, realized I was mixing my functions. createDummyOrder() updates and saves an order, so SAVED_NEW would not be the return value in this case. Changing to just use commerce_order_new() instead (copied from the other CRUD test).

And I was comparing the wrong values in that one test so it's removed. Argh I'm bad at this :)

Hmm. One more try.

I figured it would fail. I think I have it figured out. If this one also fails then I may have another issue and I'm just not thinking it through clearly.

But I think the issue is that I need to load and save another copy of the order, and then compare the original order's changed value. So the issue is I may have just been checking two identical values and expecting them to be different.

Here is the updated version.

Okay, I think I figured it out. REQUEST_TIME is the same in subsequent calls to order_save() and so I've added a sleep(3) to make sure that doesn't cause a failure. Fingers crossed!

+++ b/modules/order/tests/commerce_order.test
@@ -120,4 +120,38 @@ class CommerceOrderCRUDTestCase extends CommerceBaseTestCase {
+    // Sleep for 3 seconds to make sure REQUEST_TIME in commerce_order_save() is different.
+    sleep(3);
...
+    // Update the order and save it again.
+    $loaded->data['testing'] = REQUEST_TIME;
+    commerce_order_save($loaded);

YOu can't trust REQUEST_TIME. The test bot runs on CLI so request time is from the first process. Use time().

Yeah what I've discovered is that the test order itself after saving still isn't being seen as "needing a changed timestamp". I'm working on a revised test, running it on my test environment first so I can see if my fixes help.

My new test involves changing a line item's price amount, then saving it, and then comparing the values. Almost done and will post soon.

Touching base on my comment in #22, discussing with torgosPizza in IRC we are realizing the issue is the fact the controller uses REQUEST_TIME during save for the changed property. That means that every order save in an API call stack will have same changed timestamp.

I get the feeling that using REQUEST_TIME probably affects other areas of Commerce where modules check to see if the order has changed. Not positive though and I'm not sure if it's better to keep everything REQUEST_TIME for consistency or something else I haven't thought of yet.

Yeah, no matter what I do, I can't get it to return TRUE in testing. No matter what, the value of $order->changed is always the same. (I even tried removing REQUEST_TIME from the controller as @mglaman suggested.) My guess is it's due to the way the thread runner in Simpletest works. I'd suggest we just not worry about a test for this particular function, since its main purpose / benefit will be in examining orders that are stored in an Ajaxified $form array.

My only other suggestion would be to change the field to use a db_query() directly, rather than rely on EFQ, because it's possible that there could be a cached entity value getting returned rather than the latest database values.

Just to be sure... when calling commerce_order_load() doesn't it return the same object from the static cache even it was changed in the database by http://www.drupalcontrib.org/api/drupal/drupal!includes!entity.inc/funct...?

I know this is not part of the function directly, but I saw implementations like this: https://www.drupal.org/files/issues/commerce_order-refresh_order_object_... where that could be a problem if the cache was not reset?
Or am I missing an important point?

I'm going to take a stab at this, finally. Thanks Anybody for pointing out static cache in #27.

It doesn't seem that entity cache is the issue, as the Commerce entity controller updates the entity cache.

// \DrupalCommerceEntityController::save();

      // Update the static cache so that the next entity_load() will return this
      // newly saved entity.
      $this->entityCache[$entity->{$this->idKey}] = $entity;

I lied :P Static cache was at play. Here is a patch which uses time() because REQUEST_TIME isn't granular enough for how much we save orders. I've also added a $reset flag to commerce_order_load so we can reset caches, like many other entity load functions do. These two items combined let tests pass for me and prove the utility function works.

Thank you very much, mglaman,

I think the static cache is really really important here, just like a proper locking.
To add some thoughts to your patch and tests:

Concurrency is also dangerous here:
I'm having huge issues with current Drupal Commerce when using external payment providers. These providers make a second call while leading the user back to the checkout complete pane. The second call triggers some rules and this is concurrency at its best... sometimes the call comes before the user is being redirected, sometimes after and sometimes even while the other process is still in execution... again and again this leads to hardly reproducable order status fails...

So this is not just theory but we have to care a lot about concurrency when handling orders and especially checkout panes... sadly... we should keep that in mind.

@Anybody: Is it possible to write a test case for this scenario? it seems like you have at least some kind of grasp on the cause, but it does seem like some kind of corner case that might be hard to reproduce, based on what you're saying here.

But I think the static cache in this case is a double-edged sword. The order shouldn't be loaded more times than it has to, but it should also be the most recent (changed) version if that is applicable.

From my understanding the entity API itself does have "static caching" in the function level, using drupal_static(), which is different from the static entitycache, which stores a (sometimes outdated) version of the entity, which is where the problem lies.

I think @mglaman's utility function will help cut down both concurrency as well as stale entities being held in the checkout pane/form.

While this function is doing doesn't "change" the issues with concurrency you are seeing on its own, I think it is a step towards fixing the problems in Commerce.

This specific patch doesn't solve problems but gives us solutions to. It allows us to have more granular changed attributes, so we can identify actual changes. It also allows us to bypass the entity cache when we need to. If we can get this in, it'll help identify edge cases and implement fixes in contributed modules.

Also, keep in mind we're dancing around issues of stale order's within a serialized form cache. AJAX requests do not rebuild orders and can make this moot, as the issue most likely in #1804592: During AJAX form submission in checkout, the $order argument passed by the Form API is incorrect.

Looks like it has tests. Any chance you'd need an alter hook there incase someone needs to check on other conditions?

Maybe not? I feel like if another module makes a change to an order and saves it, since that timestamp gets changed as well, this function should just work. I could be mistaken though, but I'm not sure we need the alter.

@mglaman would there be a problem where a record could be saved within the same second? though I love this, I wonder...

Should we use microsecond instead?

A second is a long time in concurrency situations... I'm not sure how locking is involved here... but it should be 100% safe.

This patch works for me... we're using it in production (along with the patch at #1804592: During AJAX form submission in checkout, the $order argument passed by the Form API is incorrect.) and so far I don't see any issues.

On second thought: Having a function tell if an order has changed based on time sounds like a load of problems waiting to happen.

If you rely on that as an indicator that the order has changed, and try to use that and it's reporting no change, even though it has in the last second you will not trigger the condition.

As much as I want this, I can't see how it's a good idea.

@joelpittet: I had seen another patch from a user a while back who basically took the order and its database counterpart and compared them line item by line item. Would that work better?

I think if we enforced that in all places in Commerce core and contrib, that anytime an order gets modified it must be saved, we should be okay, since the changed timestamp gets updated at the entity controller level. To me this makes sense, but I'm not as familiar with the inner guts. Can you elaborate? Are there any use cases you can see that your scenario above would definitely make this feature problematic?

+++ b/modules/order/tests/commerce_order.test
@@ -120,4 +120,34 @@ class CommerceOrderCRUDTestCase extends CommerceBaseTestCase {
+    // Sleep for 3 seconds to make sure time() in commerce_order_save() is different.
+    sleep(3);

Remove this line from the test and it will fail even though the order has changed.

I'm am idiot. We need microtime not time. Milliseconds are important here in the orders API cycle. I'll reroll later.

joelpittet, currently shipping and others check this to see if the order was modified via AJAX. What about the changes to the controller and bypasses static cache, using miliseconds for changed? This grew into a bit more than the helper utility, to be honest. But it's one that it wasn't discovered until we wrote the test and utility.

+++ b/modules/order/commerce_order.module
@@ -746,9 +746,17 @@ function commerce_order_save($order) {
+ * @param $reset
+ *    Whether to reset the internal order loading cache. Useful if checking
+ *    if order has been updated and you cannot rely on static cache.
...
+function commerce_order_load($order_id, $reset = FALSE) {
+  $orders = commerce_order_load_multiple(array($order_id), array(), $reset);

+++ b/modules/order/includes/commerce_order.controller.inc
@@ -90,9 +90,14 @@ class CommerceOrderEntityController extends DrupalCommerceEntityController {
+      // We have to use time() here as the REQUEST_TIME constant will remain
+      // the same value throughout a single request. That means each save
+      // operation in a single request will have same timestamp.
+      $time = round(microtime(true) * 1000);
...
+      $order->changed = $time;
...
+      $order->revision_timestamp = $time;

If the utility function isn't on point. I think we need to get this change into the order's controller. REQUEST_TIME can't be trusted within a request, as its constant. I don't think seconds is good enough, as a typical request shouldn't take more than a second.

I give up. We would need to bump it to bigint for storage.

I think this would alleviate the symptoms that people are having and for that I'm thankful but time as a measure of change is only as good as long as the lag between checks.

Hashing the order and its line items could be expensive but maybe not if they are already loaded...

Still a bit sketched and racking my head on this.