Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BUG: Synchronization Issues #2681

Closed
cbratschi opened this issue Mar 25, 2022 · 21 comments
Closed

BUG: Synchronization Issues #2681

cbratschi opened this issue Mar 25, 2022 · 21 comments
Assignees
Labels
bug Something isn't working

Comments

@cbratschi
Copy link

Describe the bug

Synchronization using the new sync UI did not progress after a while without showing any errors. Using WP-CLI ended in out of memory conditions while indexing posts and failed afterwards in users too. So we split the command to use separate cycles for each indexable. However, this ended in users and terms to contain only 1000 documents.

I saw similar open issues but our issue is probably a little bit different. Therefore creating a new bug report to discuss further details.

Steps to Reproduce

  1. Synchronize
  2. Wait only progress stops
  3. Displays forever the same sync message
Processed users 15400 - 15750 of 277623. Last Object ID: 797854
Processed users 15400 - 15750 of 277623. Last Object ID: 797854
Processed users 15400 - 15750 of 277623. Last Object ID: 797854
Processed users 15400 - 15750 of 277623. Last Object ID: 797854

Expected behavior

Should synchronize all indexables.

Screenshots

Environment information

  • Device:
  • OS:
  • Browser and version:
  • WordPress version:
  • ElasticPress version: 4.0.1
  • Elasticsearch version: 7.9.3
  • Where do you host your Elasticsearch server?
  • What ElasticPress features do you have currently active?
  • Plugins and version:
  • Theme and version:
  • Site Health Info:

Additional context

@cbratschi cbratschi added the bug Something isn't working label Mar 25, 2022
@cbratschi
Copy link
Author

More details about the WP-CLI issue.

Full index runs into out of memory conditions after using more than 1.6 GB of memory.

~/wp-cli/wp-cli.phar elasticpress index --setup --per-page=1000 --show-bulk-errors
Processed posts 61000 - 62000 of 205929. Last Object ID: 550888
Killed

We switched to separate calls. Where posts are resumed:

~/wp-cli/wp-cli.phar option delete ep_index_meta
~/wp-cli/wp-cli.phar elasticpress index --setup --per-page=1000 --show-bulk-errors --indexables=post
Processed posts 50000 - 51000 of 205929. Last Object ID: 597796
Killed

~/wp-cli/wp-cli.phar option delete ep_index_meta
~/wp-cli/wp-cli.phar elasticpress index --per-page=1000 --show-bulk-errors --indexables=post --offset=51000
Processed posts 120000 - 121000 of 205929. Last Object ID: 316790
Killed

~/wp-cli/wp-cli.phar option delete ep_index_meta
~/wp-cli/wp-cli.phar elasticpress index --per-page=1000 --show-bulk-errors --indexables=post --offset=121000
Processed posts 174000 - 175000 of 205929. Last Object ID: 122600
Killed

~/wp-cli/wp-cli.phar option delete ep_index_meta
~/wp-cli/wp-cli.phar elasticpress index --per-page=1000 --show-bulk-errors --indexables=post --offset=175000
Processed posts 205000 - 205929 of 205929. Last Object ID: 22
Success: Done!

Now we see all posts in the index.

Then we continue with the others:

~/wp-cli/wp-cli.phar elasticpress index --setup --per-page=1000 --show-bulk-errors --indexables=user
Success: Number of users indexed: 278000

However, this index only has 1000 users instead of the added 278000 users.

This is our staging environment. Once this issue is solved we will upgrade our production environment to the latest ElasticPress version.

@felipeelia
Copy link
Member

Hey @cbratschi, this is great debugging information, thank you very much.

FWIW, instead of ~/wp-cli/wp-cli.phar option delete ep_index_meta you could run ~/wp-cli/wp-cli.phar elasticpress clear-index that will take the same effect. Also, you'll prefer to use --show-errors instead of --show-bulk-errors, that might bring additional info.

Some questions for you:

  • Do you mind sharing the list of active plugins you have? Recently we saw some problems related to cache plugins preventing ElasticPress from correctly advancing in posts pagination.
  • Due to Problem with syncing data #2649, the pagination of other Indexables (terms, users, and comments) are not working properly. Code in Only use advanced pagination for supported indexables #2665 fixes that and will be shipped in our next release (it would be great if you could give that a try, by the way.)

If you can add the content of this gist to your codebase, run a sync and then share your logs with us, that may give us some additional ideas of what could be the root cause of the problem.

@github-actions
Copy link

github-actions bot commented Apr 1, 2022

This issue has been automatically closed because there has been no response to our request for more information. With only the information that is currently in the issue, we don't have enough information to take action. Please reach out if you have or find the answers we need so that we can investigate further. See this blog post on bug reports and the importance of repro steps for more information about the kind of information that may be helpful.

@github-actions github-actions bot closed this as completed Apr 1, 2022
@cbratschi
Copy link
Author

We are using these plugins:

  • ACF Pro
  • EWWW Image Optimizer
  • GAinWP
  • LiteSpeed Cache
  • Yoast SEO Premium

LiteSpeed Cache uses an Object Cache.

I will share the debug logs later.

Please reopen. I will wait for the next release to try WP-CLI again.

@cbratschi
Copy link
Author

This is the log of this endless sync cycle:

Processed posts 19950 - 20300 of 205929. Last Object ID: 723736
120
Processed posts 19950 - 20300 of 205929. Last Object ID: 723736
121
Processed posts 19950 - 20300 of 205929. Last Object ID: 723736
...
[06-Apr-2022 14:14:15 UTC] ==============================================
[06-Apr-2022 14:14:15 UTC] ============ STARTING A NEW BATCH ============
[06-Apr-2022 14:14:15 UTC] ==============================================
[06-Apr-2022 14:14:15 UTC] 
[06-Apr-2022 14:14:15 UTC] 
[06-Apr-2022 14:14:15 UTC] Documents count: 350
[06-Apr-2022 14:14:15 UTC] Documents avg size: 9280.8914285714
[06-Apr-2022 14:14:15 UTC] 
[06-Apr-2022 14:14:15 UTC] ==============================================
[06-Apr-2022 14:14:15 UTC] 
[06-Apr-2022 14:14:16 UTC] count( $body ): 75
[06-Apr-2022 14:14:16 UTC] count( $documents ): 275
[06-Apr-2022 14:14:16 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:16 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:16 UTC] $current_buffer_size: 524288
[06-Apr-2022 14:14:16 UTC] Current request size: 527760
[06-Apr-2022 14:14:16 UTC] ES Time: 0.095
[06-Apr-2022 14:14:16 UTC] Request Time: 0.231
[06-Apr-2022 14:14:16 UTC] ==============================================
[06-Apr-2022 14:14:16 UTC] count( $body ): 139
[06-Apr-2022 14:14:16 UTC] count( $documents ): 136
[06-Apr-2022 14:14:16 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:16 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:16 UTC] $current_buffer_size: 1048576
[06-Apr-2022 14:14:16 UTC] Current request size: 1227306
[06-Apr-2022 14:14:16 UTC] ES Time: 0.296
[06-Apr-2022 14:14:16 UTC] Request Time: 0.499
[06-Apr-2022 14:14:16 UTC] ==============================================
[06-Apr-2022 14:14:17 UTC] count( $body ): 136
[06-Apr-2022 14:14:17 UTC] count( $documents ): 0
[06-Apr-2022 14:14:17 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:17 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:17 UTC] $current_buffer_size: 1572864
[06-Apr-2022 14:14:17 UTC] Current request size: 1493246
[06-Apr-2022 14:14:17 UTC] ES Time: 0.228
[06-Apr-2022 14:14:17 UTC] Request Time: 0.435
[06-Apr-2022 14:14:17 UTC] ==============================================
[06-Apr-2022 14:14:17 UTC] 
[06-Apr-2022 14:14:17 UTC] # of requests: 3
[06-Apr-2022 14:14:17 UTC] ==============================================
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] ==============================================
[06-Apr-2022 14:14:19 UTC] ============ STARTING A NEW BATCH ============
[06-Apr-2022 14:14:19 UTC] ==============================================
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] Documents count: 350
[06-Apr-2022 14:14:19 UTC] Documents avg size: 9280.8914285714
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:19 UTC] ==============================================
[06-Apr-2022 14:14:19 UTC] 
[06-Apr-2022 14:14:20 UTC] count( $body ): 75
[06-Apr-2022 14:14:20 UTC] count( $documents ): 275
[06-Apr-2022 14:14:20 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:20 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:20 UTC] $current_buffer_size: 524288
[06-Apr-2022 14:14:20 UTC] Current request size: 527760
[06-Apr-2022 14:14:20 UTC] ES Time: 0.12
[06-Apr-2022 14:14:20 UTC] Request Time: 0.255
[06-Apr-2022 14:14:20 UTC] ==============================================
[06-Apr-2022 14:14:20 UTC] count( $body ): 139
[06-Apr-2022 14:14:20 UTC] count( $documents ): 136
[06-Apr-2022 14:14:20 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:20 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:20 UTC] $current_buffer_size: 1048576
[06-Apr-2022 14:14:20 UTC] Current request size: 1227306
[06-Apr-2022 14:14:20 UTC] ES Time: 0.229
[06-Apr-2022 14:14:20 UTC] Request Time: 0.401
[06-Apr-2022 14:14:20 UTC] ==============================================
[06-Apr-2022 14:14:21 UTC] count( $body ): 136
[06-Apr-2022 14:14:21 UTC] count( $documents ): 0
[06-Apr-2022 14:14:21 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:21 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:21 UTC] $current_buffer_size: 1572864
[06-Apr-2022 14:14:21 UTC] Current request size: 1493246
[06-Apr-2022 14:14:21 UTC] ES Time: 0.321
[06-Apr-2022 14:14:21 UTC] Request Time: 0.525
[06-Apr-2022 14:14:21 UTC] ==============================================
[06-Apr-2022 14:14:21 UTC] 
[06-Apr-2022 14:14:21 UTC] # of requests: 3
[06-Apr-2022 14:14:21 UTC] ==============================================
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] ==============================================
[06-Apr-2022 14:14:23 UTC] ============ STARTING A NEW BATCH ============
[06-Apr-2022 14:14:23 UTC] ==============================================
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] Documents count: 350
[06-Apr-2022 14:14:23 UTC] Documents avg size: 9280.8914285714
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:23 UTC] ==============================================
[06-Apr-2022 14:14:23 UTC] 
[06-Apr-2022 14:14:24 UTC] count( $body ): 75
[06-Apr-2022 14:14:24 UTC] count( $documents ): 275
[06-Apr-2022 14:14:24 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:24 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:24 UTC] $current_buffer_size: 524288
[06-Apr-2022 14:14:24 UTC] Current request size: 527760
[06-Apr-2022 14:14:24 UTC] ES Time: 0.093
[06-Apr-2022 14:14:24 UTC] Request Time: 0.282
[06-Apr-2022 14:14:24 UTC] ==============================================
[06-Apr-2022 14:14:24 UTC] count( $body ): 139
[06-Apr-2022 14:14:24 UTC] count( $documents ): 136
[06-Apr-2022 14:14:24 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:24 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:24 UTC] $current_buffer_size: 1048576
[06-Apr-2022 14:14:24 UTC] Current request size: 1227306
[06-Apr-2022 14:14:24 UTC] ES Time: 0.195
[06-Apr-2022 14:14:24 UTC] Request Time: 0.361
[06-Apr-2022 14:14:24 UTC] ==============================================
[06-Apr-2022 14:14:25 UTC] count( $body ): 136
[06-Apr-2022 14:14:25 UTC] count( $documents ): 0
[06-Apr-2022 14:14:25 UTC] $min_buffer_size: 524288
[06-Apr-2022 14:14:25 UTC] $max_buffer_size: 157286400
[06-Apr-2022 14:14:25 UTC] $current_buffer_size: 1572864
[06-Apr-2022 14:14:25 UTC] Current request size: 1493246
[06-Apr-2022 14:14:25 UTC] ES Time: 0.299
[06-Apr-2022 14:14:25 UTC] Request Time: 0.470
[06-Apr-2022 14:14:25 UTC] ==============================================
[06-Apr-2022 14:14:25 UTC] 
[06-Apr-2022 14:14:25 UTC] # of requests: 3
[06-Apr-2022 14:14:25 UTC] ==============================================

@felipeelia
Copy link
Member

Yeah, @cbratschi, that log indicates it is sending the same things over and over again. Did you already try to sync while having LiteSpeed Cache disabled?

ps.: Issues marked as "reporter feedback" here in our repository are automatically closed after 3 days without a response from the creator but it'll automatically reopen if you come back after that time.

@cbratschi
Copy link
Author

@felipeelia did not yet try without LiteSpeed Cache but will run a sync soon again.

@cbratschi
Copy link
Author

@felipeelia I disabled LiteSpeed Cache and tried to sync it again. Several attempts failed without any output in the debug log. After reloading the sync page I got a full sync done.

So it seems to be related to LiteSpeed Cache. What do you suggest? We could patch the LiteSpeed Cache plugin code to temporarily be disabled if a REST API call is ongoing. However, LiteSpeed Cache is very critical to our setup and we need a way to keep it running while performing a sync.

@felipeelia
Copy link
Member

@cbratschi, I tried to reproduce the problem in a local installation but I couldn't. Would it be possible for you to send us an export of your LiteSpeed settings? In the WP Dashboard that is available under LiteSpeed Cache -> Toolbox -> Export Settings. You can send it to us via the form at https://www.elasticpress.io/request-a-demo/.

Here are some of the suggestions you may already try:

  • Under Cache -> [4] Excludes -> Do Not Cache URIs, add the ajax URL (Sync is done via ajax calls, not via REST API)
  • Under the same section, you may prefer to use the Do Not Cache Roles section and target your user role (probably Administrator?)

Can you give those a try and let us know, please? Thanks in advance!

@felipeelia felipeelia self-assigned this Apr 11, 2022
@cbratschi
Copy link
Author

I just sent you the settings. Will try excluding AJAX now. Admins are already in the do not cache settings.

@cbratschi
Copy link
Author

Disable AJAX caching did not improve anything.

@felipeelia
Copy link
Member

Hey @cbratschi,

I've tried locally with those settings and I'm still unable to reproduce the problem. While we keep investigating it, can you let me know if you have any other cache layer like Cloudflare or Varnish, for example?

@cbratschi
Copy link
Author

Hi @felipeelia,

No, this is the only cache plugin running.

@thomasdiesenreiter
Copy link

We have the same issue. Endless the same message:
Processed posts 126199 - 126199 of 126200. Last Object ID: 1
Processed posts 126199 - 126199 of 126200. Last Object ID: 1
Processed posts 126199 - 126199 of 126200. Last Object ID: 1

We have no cache plugins available (we did use redis object cache before, but already deactivated it, because it would prevent elasticpress from working).
It would be great if ep would be compatible to popular caching plugins.

@felipeelia
Copy link
Member

Hi @thomasdiesenreiter,

The repeated message is something we are handling in #2737. Did you try via WP-CLI with the --show-errors flag? Any additional details help us to reproduce and fix the problem. Thanks.

@thomasdiesenreiter
Copy link

I got the same behaviour as well with the gui and the wp-cli tools. Sorry, didn't try it with the --show-errors flag. After multiple attempts (with deleting settings and the index in between, partly manually in the filesystem and phpmyadmin, because it sometimes wouldn't properly reset the index) it finally ran through without errors.

We have a rather large website with 130.000 posts in production. I don't want to risk it again to reset it, but if it should occur again anytime I'll report back again.

@archon810
Copy link

archon810 commented May 13, 2022

Same issue here on version 4.1.0 of the plugin and no caching plugins used.
image

The indexing ran to 99% and got stuck somewhere toward the very end... doh, so close.

What's weird is the indexing worked without issues before, but we've been making some changes and reindexed several times, until today when it got stuck.

Edit: I tried to start and stop (ctrl-C) an index with wp cli, then loaded the web UI and saw this repeating several times a second. Looks like a buggy behavior:
image

There should really be a way to stop wp-cli indexing properly without clearing the index. #2227. Update: Wait, clear-index doesn't actually wipe the index but only stops the indexer? Wow, I thought it cleared the index the whole time, talk about a confusingly named command!

@felipeelia
Copy link
Member

Hey @archon810, thanks for the detailed report! We've recently changed a bit that error handling, the code for that is already merged and planned to be released in our next version. I've also just created a PR addressing a problem that might be affecting you as well.
Would it be possible for you to test the zip attached in #2761? Thanks!

@archon810
Copy link

archon810 commented May 13, 2022

Sorry, this is a production env, and I'll wait for the official update with the fixes.

Btw, I also wanted to point out the "Last Object ID: 5" in my first screenshot. That doesn't sound right. Edit: Is this what your new PR is addressing?

@archon810
Copy link

I ran a full resync with wp cli and it finished this time.

Here's the final output.

Processed posts 2259000 - 2260000 of 2282384. Last Object ID: 65007
Time elapsed: 0.21 (+-0.05)
Memory Usage: 9799.86mb (Peak: 9811.24mb)
Processed posts 2260000 - 2261000 of 2282384. Last Object ID: 62061
Processed posts 2261000 - 2262000 of 2282384. Last Object ID: 58897
Processed posts 2262000 - 2263000 of 2282384. Last Object ID: 55889
Processed posts 2263000 - 2264000 of 2282384. Last Object ID: 52712
Processed posts 2264000 - 2265000 of 2282384. Last Object ID: 49923
Processed posts 2265000 - 2266000 of 2282384. Last Object ID: 47078
Processed posts 2266000 - 2267000 of 2282384. Last Object ID: 44233
Processed posts 2267000 - 2268000 of 2282384. Last Object ID: 41443
Processed posts 2268000 - 2269000 of 2282384. Last Object ID: 39066
Processed posts 2269000 - 2270000 of 2282384. Last Object ID: 37619
Time elapsed: 0.12 (+-0.09)
Memory Usage: 9845.28mb (Peak: 9859.43mb)
Processed posts 2270000 - 2271000 of 2282384. Last Object ID: 30289
Processed posts 2271000 - 2272000 of 2282384. Last Object ID: 28707
Processed posts 2272000 - 2273000 of 2282384. Last Object ID: 26786
Processed posts 2273000 - 2274000 of 2282384. Last Object ID: 23621
Processed posts 2274000 - 2275000 of 2282384. Last Object ID: 20266
Processed posts 2275000 - 2276000 of 2282384. Last Object ID: 17248
Processed posts 2276000 - 2277000 of 2282384. Last Object ID: 14697
Processed posts 2277000 - 2278000 of 2282384. Last Object ID: 12249
Processed posts 2278000 - 2279000 of 2282384. Last Object ID: 9587
Processed posts 2279000 - 2280000 of 2282384. Last Object ID: 7031
Time elapsed: 0.13 (+0.01)
Memory Usage: 9879.91mb (Peak: 9890.14mb)
Processed posts 2280000 - 2281000 of 2282384. Last Object ID: 4132
Processed posts 2281000 - 2282000 of 2282384. Last Object ID: 842
Processed posts 2282000 - 2282384 of 2282384. Last Object ID: 5
Success: Number of posts indexed: 2282384
Success: Sync complete
Total time elapsed: 0.092
Success: Done!

This explains where ID 5 came from previously.

Time elapsed doesn't seem to make any sense (as well as total time elapsed). This process ran for hours.

@felipeelia
Copy link
Member

Hi there! As the issues listed here were fixed by ElasticPress 4.2.0 I'm going ahead and closing this one out. If any of you face any issues with the latest release please open a new issue linking to this one. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants