liquidweb / woocommerce-custom-orders-table

Store WooCommerce order data in a custom table for improved performance.
GNU General Public License v3.0
476 stars 51 forks source link

Error: Infinite loop detected, aborting. #174

Closed robwatson-intechra closed 2 years ago

robwatson-intechra commented 4 years ago

Describe the bug On a WooCommerce site with 30,360 orders to migrate, I'm getting the error "Error: Infinite loop detected, aborting." at the point where the very last 586 orders are being processed. I'm hosted on Pantheon.io and using their Terminus CLI to run the WP-CLI commands to perform the orders table migration.

To Reproduce Steps to reproduce the behavior:

  1. Start from a Bash prompt. (I'm using Bash on Ubuntu on Windows)
  2. Enter the command terminus wp site.dev -- wc orders-table migrate --save-post-meta
  3. Up to 2,509 orders are migrated and then it times out with 27,851 left to go.
  4. Enter the command terminus wp site.dev -- wc orders-table migrate --save-post-meta --batch-size=0
  5. All but 586 orders are processed with the error Error: Infinite loop detected, aborting. when it terminates. I checked the database with SELECT count(*) FROM pantheon.wp_woocommerce_orders; and got a total up to but not including that last 586, so I conclude they were not migrated.
  6. Enter the command terminus wp site.dev -- wc orders-table migrate --save-post-meta and get the same error. Can't get past it.

Expected behavior I had expected through the command, with or without the --batch-size specified, that I'd eventually get to 100% of the records migrated. I'm unclear on why it's detecting an infinite loop. Nor do I know whether the infinite loop detection is happening in Terminus or in the WooCommerce Custom Orders Table plugin.

Versions

Additional context Add any other context about the problem here.

robwatson-intechra commented 4 years ago

Just now I found the "Infinite loop detected" error message in the code (line 187 of woocommerce-custom-orders-table/includes/class-woocommerce-custom-orders-table-cli.php) and decided to try setting the --batch-size to exactly the number of orders I had left to migrate. Unfortunately, that still resulted in the same error. Then I tried setting -batch-size to the number of orders minus one. Same result. Something about the comparison on line 187 is causing it to detect an infinite loop even when it seems it shouldn't match such a condition

So I added some debugging statements to the error message at line 187 to detect if the type (Array) and number were truly equal in value and type according to the === comparison operator. They are coming out like this when the default of 100 for the batch size is the setting:

There are 586 orders to be migrated. Order Data Migration 17 % [======> ] 0:14 / 1:23Error: $order_data =100 and $next_batch =100--> Infinite loop detected, aborting.

and like this when I set batch size to equal how many orders are left to process:

There are 586 orders to be migrated. Order Data Migration 100% [=======================================] 0:56 / 0:58Error: $order_data =586 and $next_batch =586--> Infinite loop detected, aborting.

and, finally, like this when I set the batch size to just one less (585) than the number of orders left to process (586):

There are 586 orders to be migrated. Order Data Migration 99 % [======================================>] 1:18 / 1:16Error: $order_data =585 and $next_batch =585--> Infinite loop detected, aborting.

Not sure what this means in practice. I'm not a full time PHP developer. I just know enough to debug and rearrange code as needed.

bswatson commented 4 years ago

@robwatson-intechra

We really appreciate the detailed error report. I'm not sure what may be causing the issue, but you've given us enough info to start tracking it down.

If you haven't already could you attempt to run the command again using the --debug flag and copy the output here?

terminus wp site.dev -- wc orders-table migrate --save-post-meta --debug

That should give us an indication of whether it's tripping up on line 158. If you've already run that, and there's no debug or warning statements, then we're likely dealing with an issue from the query on line 109.

Thanks!

robwatson-intechra commented 4 years ago

Here it is attached as a .log file. orders-table-migrate-debug.log

bswatson commented 4 years ago

Digging into this a little more, and have a few theories, but it's going to take some time to reproduce and debug.

The failure appears related to get_migration_query.

As it's looping around, it's using the same offset (0) / limit (100) because no failures were reported in the previous batch. However, when it retrieves the next batch from the database, it's getting the exact same list of order IDs. Based on the last clause in the query AND o.order_id IS NULL, that means none of the previous IDs were stored in the new Orders table.

Following that through to how orders are migrated, my best guess is there's an issue when trying to insert orders or refunds, but instead of throwing an error, it's returning an unexpected response, and the process just bails.

Picking that back up in the CLI command, we're only checking for a WP_Error and not handling the potential NULL response. Because of that, the order isn't marked as skipped, and there is no additional offset added to the next query.

Since this is handled individually for each one of these orders, it's likely the same issue exists for all 586 orders. The crux is going to be identifying what's causing the insertion failure.

We might be able to figure out specifically what is causing this on your site in particular, if you'd be able to drop a little debugging code around these two areas:

https://github.com/liquidweb/woocommerce-custom-orders-table/blob/6d329d62b192c5a6cd92881eb36df6b0ca639afd/includes/class-wc-order-refund-data-store-custom-table.php#L99

and

https://github.com/liquidweb/woocommerce-custom-orders-table/blob/0a6d40e816f3c700d5f047693aa4e1c4aaa57b1f/includes/class-wc-order-data-store-custom-table.php#L193

That being said, there's definitely some cleanup work we can do here to handle these errors better so we don't force ourselves into an infinite loop when we hit this situation.

Thanks!

robwatson-intechra commented 4 years ago

Thanks. Before I read your response, I decided to re-clone the live site to the dev site and retry with a different batch size, this time of 400, hoping beyond hope that it would "jar" something lose with the loop. It didn't.

$ terminus wp site.dev -- wc orders-table migrate --save-post-meta --batch-size=400 There are 30399 orders to be migrated. Order Data Migration 28 % [==========> ] 12:10 / 40:31Error: $order_data = 400 and $next_batch = 400--> Infinite loop detected, aborting.

After looking through your response, I'm not quite clear on what debug statements would be helpful around the lines you designated. Can you give me more guidance on that? As noted earlier, I'm more of a casual coder in that I can move stuff around and do basic debugging, but my mastery of PHP is lacking to figure out what is needed here.

I did give it a try, though, and for the refund script, I inserted

echo '$inserted = '.$inserted.'\n'; echo '$table = '.$table.'\n'; echo '$refund_data = '.$refund_data.'\n';

after line 99

and for the order script, I inserted

echo '$inserted = '.$inserted.'\n'; echo '$table = '.$table.'\n'; echo '$order_data = '.$order_data.'\n';

after line 193.

All that ended up doing when running the script in Terminus was this

$ terminus wp site.dev -- wc orders-table migrate --save-post-meta --batch-size=400 There are 23745 orders to be migrated. Order Data Migration 1 % [> ] 0:36 / 34:51Error: $order_data = 400 and $next_batch = 400--> Infinite loop detected, aborting.

followed by a long repetition of the following:

$inserted = \n$table = wp_woocommerce_orders\n$order_data = Array\n$inserted = \n$table = wp_woocommerce_orders\n$order_data = Array\n$inserted = \n$table = wp_woocommerce_orders\n$order_data = Array\n$inserted = \n$table = wp_woocommerce_orders\n$order_data = Array\n ...

So, obviously I'm not understanding the context of the debugging and what is useful to display, nor how.

Thanks.

bswatson commented 4 years ago

@robwatson-intechra -

Thanks for being patient as I had to attend to a few other things in the last couple of days.

It does look like my suspicions were correct based on your debug statement. We've got order data ($order_data = Array\n), which is being inserted into the correct table (wp_woocommerce_orders), but the insertion is failing as it's returning either false or empty ($inserted = \n).

Next step would be to try and understand why the insertion is failing.

It appears there are only two returns from $wpdb->insert(), but I'd suspect this is the culprit:

// https://core.trac.wordpress.org/browser/tags/5.5.1/src/wp-includes/wp-db.php#L2236

$data = $this->process_fields( $table, $data, $format );
if ( false === $data ) {
    return false;
}

The function process_fields could return false if any inserted content has a problem with:

  1. Formatting to a valid string
  2. Using the defined character set for the DB
  3. Content length is too long for the DB field
  4. Fails at stripping invalid text

Now, if I had to make a guess - the most likely cause is going to be #3. It's very possible that data fine in a non-size-restricted wp_post_meta table is running into an issue with some of the limits we've set for the Orders Table. Those limits are in place for performance, but that doesn't always mean they work for everyone quite yet.

Right near the insert statement, could you make the following changes:

// https://github.com/liquidweb/woocommerce-custom-orders-table/blob/develop/includes/class-wc-order-data-store-custom-table.php#L192-L197

        // Insert or update the database record.
        if ( ! wc_custom_order_table()->row_exists( $order_data['order_id'] ) ) {
            foreach ( $order_data as $key => $value ) {
                WP_CLI::debug(
                    sprintf(
                        '%1$s: %2$d',
                        $key,
                        strlen($value)
                    )
                );
            }
            $inserted = $wpdb->insert( $table, $order_data ); // WPCS: DB call OK.

Run it with a batch size of 1 to 5 items so it doesn't flood your terminal.

You can then either review the output of each of those against the DB definition, or post an example of one and I'll take a quick review.

Thanks again!

robwatson-intechra commented 4 years ago

Thanks. I had to adjust the code by adding a comma after '%1$s: %2$d' because otherwise it gives a segmentation fault and won't run. Once that was in place and I ran it I got

$ terminus wp site.dev -- wc orders-table migrate --save-post-meta --batch-size=5 There are 23745 orders to be migrated. Order Data Migration 0 % [> ] 0:00 / 0:00Error: $order_data = 5 and $next_batch = 5--> Infinite loop detected, aborting.

with no debug output. Here's my full code:

// Insert or update the database record. if ( ! wc_custom_order_table()->row_exists( $order_data['order_id'] ) ) { foreach ( $order_data as $key => $value ) { WP_CLI::debug( sprintf( '%1$s: %2$d', $key, strlen($value) ) ); } $inserted = $wpdb->insert( $table, $order_data ); // WPCS: DB call OK.

bswatson commented 4 years ago

Oh, should have mentioned you'll need to run it with the --debug flag again for the output to show.

robwatson-intechra commented 4 years ago

Thanks. I added --debug and attached is the output. debug-log.txt

bswatson commented 4 years ago

Appears there are 3 potential issues with these orders. They all seem to have the following in common.

Debug: transaction_id: 0 (2.042s) Debug: billing_country: 3 (2.042s) Debug: shipping_country: 3 (2.042s)

Transaction ID is a required field, so if it's empty or null, it's going to have an issue. We also have the assumption that Billing and Shipping are using a 2 character code, but it appears for these orders at least, your site has set a few with 3 characters.

Would you be able to get the data for one of the failing orders and grab those 3 fields? (I need to step away, but can provide more details on how if you need it later tonight)

robwatson-intechra commented 4 years ago

Thanks. I'm afraid I'm in need of more details on how to specifically target these criteria in a SQL query such that all three criteria are met. The best I could come up with was:

SELECT * FROM pantheon.wp_woocommerce_orders where LENGTH(transaction_id)=0;

Which produces 1311 results.

That was the only query that produced results. The others:

SELECT * FROM pantheon.wp_woocommerce_orders where LENGTH(billing_country)>2; SELECT * FROM pantheon.wp_woocommerce_orders where LENGTH(shipping_country)>2;

Produce zero results each. So I guess I'm not seeing how it's failing upon seeing 3 characters in the billing_country and shipping_country fields when no records in the database exist with that condition.

robwatson-intechra commented 4 years ago

Hi Brian. Just wanted to see if there's anything else I can try here. Thanks for all your help.

bswatson commented 4 years ago

In place of the previous debugging code, swap it out for:

            foreach ( $order_data as $key => $value ) {
                if ( in_array( $key, ['transaction_id', 'billing_country', 'shipping_country'] ) ) {
                    WP_CLI::debug(
                        sprintf(
                            '%1$s: %2$s',
                            $key,
                            $value
                        )
                    );
                }
            }

That should show us the values that are kicking up a failure so we can do a better evaluation.

robwatson-intechra commented 4 years ago

Ok, thanks. Here's the output. debug.log

bswatson commented 4 years ago

Still need to figure out the transaction being null, but it appears your billing_country is incorrectly set as a currency. Instead of it being US or even USA, it's set to the USD currency.

This is likely an issue with a plugin, as it should be set properly by WooCommerce.

Would you mind dropping a list of plugins and versions so we can review?

robwatson-intechra commented 4 years ago

Sure. Is there someone I can send it to so that private information about our setup isn't exposed in a public forum?

bswatson commented 4 years ago

Sure! You could put it in to a private gist (http://gist.github.com/) and then email the link to me.

robwatson-intechra commented 4 years ago

Ok, that's sent to you now.

bswatson commented 4 years ago

Confirming that I received it. Reviewing it now, but may take a couple of days to walk through each of the plugins listed.

bswatson commented 4 years ago

One other thing to do while I'm tracking it down on this angle is to take a look at a handful of the orders in the system and confirm they are valid and/or there isn't some other pattern that jumps out. Use the numbers printed with the following to track down orders:

            foreach ( $order_data as $key => $value ) {
                if ( in_array( $key, ['order_id', 'order_key'] ) ) {
                    WP_CLI::debug(
                        sprintf(
                            '%1$s: %2$s',
                            $key,
                            $value
                        )
                    );
                }
            }
robwatson-intechra commented 4 years ago

Hmm. Something isn't right about the foreach code you gave me a few days ago. At first I thought it was something wrong with my dev site's DB so I re-cloned it from the live site. But the error I'm getting is about the code. Here's the code:

           `// Insert or update the database record.
    if ( ! wc_custom_order_table()->row_exists( $order_data['order_id'] ) ) {
        foreach ( $order_data as $key => $value ) {
            if ( in_array( $key, ['order_id', 'order_key'] ) ) {
                WP_CLI::debug( 
                    sprintf(
                        '%1$s: %2$s',
                        $key,
                        $value
                    )
                );
            }
        }
        $inserted = $wpdb->insert( $table, $order_data ); // WPCS: DB call OK.`

And here's the error:

Line 195 Message Uncaught Error: Class 'WP_CLI' not found in /code/wp-content/plugins/woocommerce-custom-orders-table-develop/includes/class-wc-order-data-store-custom-table.php:195 Stack trace: #0 /code/wp-content/plugins/woocommerce-custom-orders-table-develop/includes/class-wc-order-data-store-custom-table.php(421): WC_Order_Data_Store_Custom_Table->update_post_meta(Object(Automattic\WooCommerce\Admin\Overrides\Order)) #1 /code/wp-content/plugins/woocommerce-custom-orders-table-develop/includes/class-wc-order-data-store-custom-table.php(76): WC_Order_Data_Store_Custom_Table->populate_from_meta(Object(Automattic\WooCommerce\Admin\Overrides\Order)) #2 /code/wp-content/plugins/woocommerce/includes/data-stores/abstract-wc-order-data-store-cpt.php(117): WC_Order_Data_Store_Custom_Table->read_order_data(Object(Automattic\WooCommerce\Admin\Overrides\Order), Object(WP_Post)) #3 /code/wp-content/plugins/woocommerce/includes/class-wc-data-store.php(159): Abstract_WC_Order_Data_Store_CPT->read(Object(Automattic\WooCommerce\Admin\Over File /code/wp-content/plugins/woocommerce-custom-orders-table-develop/includes/class-wc-order-data-store-custom-table.php

When I compared the code above to other versions you gave me before that were working, I couldn't find a discrepancy. Not sure what's going on here with that WP_CLI class.

robwatson-intechra commented 4 years ago

Never mind the error above. The --debug code works. I just needed to disable the plugin after running the migrate command with the --debug flag to get the site to not throw that error when browsing in the WP Dashboard.

I figured out what was jamming up the migration. It was a bunch of orders injected into WooCommerce from our integration with Jet.com (defunct now). When I deleted those orders on the Dev site, the migration completed to 100%.

In looking at the pattern of things, everything hummed along nicely until I get done with order_id: 212697. Then it attempted the same migration twice in sequence for 4 orders between 212699 through 212702 (see repetition below) at which point it terminated with the error upon migrating 212703 (the fifth one).

Debug: Order ID 212697 has been migrated. (585.464s) Debug: order_id: 212699 (585.495s) Debug: order_key: wc_order_5a4b9e517d9cf (585.495s) Order Data Migration 21 % [========> ] 9:42 / 44:46Debug: order_id: 212699 (585.522s) Debug: order_key: wc_order_5a4b9e517d9cf (585.522s) Debug: Order ID 212699 has been migrated. (585.523s) Debug: Order ID 212699 has been migrated. (585.523s) Debug: order_id: 212700 (585.558s) Debug: order_key: wc_order_5a4b9e54ee704 (585.558s) Debug: order_id: 212700 (585.597s) Debug: order_key: wc_order_5a4b9e54ee704 (585.597s) Debug: Order ID 212700 has been migrated. (585.598s) Debug: Order ID 212700 has been migrated. (585.598s) Debug: order_id: 212701 (585.63s) Debug: order_key: wc_order_5a4b9e5826dd7 (585.631s) Order Data Migration 21 % [========> ] 9:42 / 44:46Debug: order_id: 212701 (585.656s) Debug: order_key: wc_order_5a4b9e5826dd7 (585.656s) Debug: Order ID 212701 has been migrated. (585.656s) Debug: Order ID 212701 has been migrated. (585.656s) Debug: order_id: 212702 (585.686s) Debug: order_key: wc_order_5a4b9e5b57974 (585.686s) Debug: order_id: 212702 (585.713s) Debug: order_key: wc_order_5a4b9e5b57974 (585.713s) Debug: Order ID 212702 has been migrated. (585.718s) Debug: Order ID 212702 has been migrated. (585.718s) Debug: Beginning batch #1323 (5 orders/batch). (585.738s) Debug: order_id: 212699 (585.761s) Debug: order_key: wc_order_5a4b9e517d9cf (585.761s) Order Data Migration 21 % [========> ] 9:42 / 44:46Debug: order_id: 212699 (585.786s) Debug: order_key: wc_order_5a4b9e517d9cf (585.786s) Debug: Order ID 212699 has been migrated. (585.786s) Debug: Order ID 212699 has been migrated. (585.786s) Debug: order_id: 212700 (585.813s) Debug: order_key: wc_order_5a4b9e54ee704 (585.813s) Debug: order_id: 212700 (585.836s) Debug: order_key: wc_order_5a4b9e54ee704 (585.836s) Debug: Order ID 212700 has been migrated. (585.837s) Debug: Order ID 212700 has been migrated. (585.837s) Debug: order_id: 212701 (585.861s) Debug: order_key: wc_order_5a4b9e5826dd7 (585.861s) Debug: order_id: 212701 (585.884s) Debug: order_key: wc_order_5a4b9e5826dd7 (585.884s) Debug: Order ID 212701 has been migrated. (585.885s) Debug: Order ID 212701 has been migrated. (585.885s) Debug: order_id: 212702 (585.907s) Debug: order_key: wc_order_5a4b9e5b57974 (585.907s) Debug: order_id: 212702 (585.931s) Debug: order_key: wc_order_5a4b9e5b57974 (585.931s) Debug: Order ID 212702 has been migrated. (585.932s) Debug: Order ID 212702 has been migrated. (585.932s) Order Data Migration 21 % [========> ] 9:42 / 44:46Debug: order_id: 212703 (585.961s) Debug: order_key: wc_order_5a4b9e5e56409 (585.961s) Debug: order_id: 212703 (585.986s) Debug: order_key: wc_order_5a4b9e5e56409 (585.986s) Debug: Order ID 212703 has been migrated. (585.986s) Debug: Order ID 212703 has been migrated. (585.986s) Error: Infinite loop detected, aborting.

Looking at each of those five order IDs in that repeated set, it's clear that they were orders that were injected into WooCommerce from a past integration we had just begun right on those order dates with Jet.com (now part of Walmart.com). In fact, none of those orders were shipped via our main fulfillment company. They went out through Jet.com's fulfillment, which means no shipping status was ever added to the order in WooCommerce. It was just marked as Order status changed from Pending payment to Completed. Could it be the somewhat irregular <idnumber>@customer.jet.com email address that Jet assigned to each customer is tripping up the plugin's algorithm?

The problem could just "go away" by deleting nearly 600 orders. However, that would leave a hole in our reporting and, if it came to it, being able to look up a customer's old order (not terribly likely). What do you think could be done to preserve our Jet.com data and still complete the migration, if anything? I can send over a subset of that data as a SQL dump if you need to see a pattern of what's defined and how in each order.

bswatson commented 4 years ago

Those orders via jet.com are very likely the source of the issue. If they didn't properly create transaction ids and incorrectly set the billing and shipping country codes, then those orders would fail on import.

Unfortunately, there isn't much within the plugin itself that we can do, since we don't want to manipulate data, so this will need to be something fixed within your database.

You can run a query against the order ids that are failing and switch the billing_country and shipping_country to US when it's set to USD. For the transaction ID, that may be a little trickier as I'm not 100% certain where that data is used throughout all of WooCommerce and if changing it may affect any other plugins you have installed.

robwatson-intechra commented 4 years ago

Thanks, Brian. I think we're just going to export and archive those Jet.com customers and then delete them from our database. When querying the customer reports in WooCommerce, none of these Jet.com customers are in any of the search results. And the fake @customer.jet.com email addresses make follow-up impossible with those customers either for marketing or customer service purposes. So they've never shown up in any of our reporting to begin with.

Just in case this is helpful to future inquirers, Jet.com had its own separate tables for storing its order data and only tied them loosely to WooCommerce by referencing an order ID in WooCommerce. The wp_jet_order_detail table contains the order info stored as a json string in the order_all_item column. It was never stored in the WooCommerce native tables except for order IDs and a bit of metadata. All the "useful" data is in the Jet tables.

bswatson commented 4 years ago

@robwatson-intechra Appreciate the follow-up and let us know if you are still seeing issues even after removing those customers / orders or importing that info from the Jet tables to the native tables.

I'm going to leave this ticket open to address the issues identified in a previous comment:

The failure appears related to get_migration_query.

As it's looping around, it's using the same offset (0) / limit (100) because no failures were reported in the previous batch. However, when it retrieves the next batch from the database, it's getting the exact same list of order IDs. Based on the last clause in the query AND o.order_id IS NULL, that means none of the previous IDs were stored in the new Orders table.

Following that through to how orders are migrated, my best guess is there's an issue when trying to insert orders or refunds, but instead of throwing an error, it's returning an unexpected response, and the process just bails.

Picking that back up in the CLI command, we're only checking for a WP_Error and not handling the potential NULL response. Because of that, the order isn't marked as skipped, and there is no additional offset added to the next query.

robwatson-intechra commented 4 years ago

Thanks. One quick question: If I migrate orders to the new tables but without the --save-post-meta switch, and later I want to revert back to using the postmeta table because of some unforeseen problem with the new tables, will running it with the --backfill switch still work in terms of moving the data back to postmeta? I tested it on my staging server and it seems to do just that, but I wanted to check with you to be sure.

lukecav commented 4 years ago

Yep, that is exactly what using that command will do for backfilling postmeta. wp wc orders-table backfill https://github.com/liquidweb/woocommerce-custom-orders-table#copying-data-from-the-orders-table-into-post-meta

robwatson-intechra commented 3 years ago

Thanks again for all the help. We've migrated and tested on our live site and all seems to be in order. We did see one anomaly in the tables, particularly in intechra_woocommerce_orders. As you can see in the screenshot, for each of the test orders that we then canceled and sent to trash, there seems to be a counterpart row filled with null values in every column. Even if I delete permanently from trash, the null rows remain. canceled-orders Any idea whether this is normal and for what purpose? Is there a way that kind of thing can be done away with to avoid storing empty/null rows for canceled orders? The query shown in the screenshot is SELECT * FROM pantheon.intechra_woocommerce_orders order by order_id desc;