Problem with syncing data

[derringer]

When pressing sync, or delete data it seems to get stuck in a loop

1. Go to Elasticpress -> Sync
2. Click on 'Delete all data and start a fresh sync'
3. The sync will get stuck in a loop on one post

Log

Log on the sync page shows:

Deleting data…
2
Indexing posts...
3
Mapping sent
4
Processed posts 0 - 100 of 14154. Last Object ID: 63268
5
Processed posts 100 - 200 of 14154. Last Object ID: 62660
6
Processed posts 200 - 300 of 14154. Last Object ID: 61872
7
Processed posts 300 - 400 of 14154. Last Object ID: 61178
8
Processed posts 400 - 500 of 14154. Last Object ID: 60579
9
Processed posts 500 - 600 of 14154. Last Object ID: 60001
10
Processed posts 600 - 700 of 14154. Last Object ID: 59216
11
Processed posts 700 - 800 of 14154. Last Object ID: 58622
12
Processed posts 800 - 900 of 14154. Last Object ID: 57904
13
Processed posts 900 - 1000 of 14154. Last Object ID: 57122
14
Processed posts 1000 - 1100 of 14154. Last Object ID: 57060
15
Processed posts 1100 - 1200 of 14154. Last Object ID: 56040
16
Processed posts 1200 - 1300 of 14154. Last Object ID: 55169
17
Processed posts 1300 - 1400 of 14154. Last Object ID: 54425
18
Processed posts 1400 - 1500 of 14154. Last Object ID: 53493
19
Processed posts 1500 - 1600 of 14154. Last Object ID: 52466
20
Processed posts 1600 - 1700 of 14154. Last Object ID: 51780
21
Processed posts 1700 - 1800 of 14154. Last Object ID: 51081
22
Processed posts 1800 - 1900 of 14154. Last Object ID: 50235
23
Processed posts 1900 - 2000 of 14154. Last Object ID: 49377
24
Processed posts 2000 - 2100 of 14154. Last Object ID: 48887
25
Processed posts 2100 - 2200 of 14154. Last Object ID: 48399
26
Processed posts 2200 - 2300 of 14154. Last Object ID: 47812
27
Processed posts 2300 - 2400 of 14154. Last Object ID: 47020
28
Processed posts 2400 - 2500 of 14154. Last Object ID: 46253
29
Processed posts 2500 - 2600 of 14154. Last Object ID: 45513
30
Processed posts 2600 - 2700 of 14154. Last Object ID: 44990
31
Processed posts 2700 - 2800 of 14154. Last Object ID: 44468
32
Processed posts 2800 - 2900 of 14154. Last Object ID: 43931
33
Processed posts 2900 - 3000 of 14154. Last Object ID: 43467
34
Processed posts 3000 - 3100 of 14154. Last Object ID: 42724
35
Processed posts 3100 - 3200 of 14154. Last Object ID: 42098
36
Processed posts 3200 - 3300 of 14154. Last Object ID: 41464
37
Processed posts 3300 - 3400 of 14154. Last Object ID: 40970
38
Processed posts 3400 - 3500 of 14154. Last Object ID: 40503
39
Processed posts 3500 - 3600 of 14154. Last Object ID: 40195
40
Processed posts 3600 - 3700 of 14154. Last Object ID: 39785
41
Processed posts 3700 - 3800 of 14154. Last Object ID: 39310
42
Processed posts 3800 - 3900 of 14154. Last Object ID: 38876
43
Processed posts 3900 - 4000 of 14154. Last Object ID: 38401
44
Processed posts 4000 - 4100 of 14154. Last Object ID: 37779
45
Processed posts 4100 - 4200 of 14154. Last Object ID: 37098
46
Processed posts 4200 - 4300 of 14154. Last Object ID: 36240
47
Processed posts 4300 - 4400 of 14154. Last Object ID: 35803
48
Processed posts 4400 - 4500 of 14154. Last Object ID: 35405
49
Processed posts 4500 - 4600 of 14154. Last Object ID: 34696
50
Processed posts 4600 - 4700 of 14154. Last Object ID: 34319
51
Processed posts 4700 - 4800 of 14154. Last Object ID: 34051
52
Processed posts 4800 - 4900 of 14154. Last Object ID: 33666
53
Processed posts 4900 - 5000 of 14154. Last Object ID: 33259
54
Processed posts 5000 - 5100 of 14154. Last Object ID: 32901
55
Processed posts 5100 - 5200 of 14154. Last Object ID: 32558
56
Processed posts 5200 - 5300 of 14154. Last Object ID: 32139
57
Processed posts 5300 - 5400 of 14154. Last Object ID: 31088
58
Processed posts 5400 - 5500 of 14154. Last Object ID: 30717
59
Processed posts 5500 - 5600 of 14154. Last Object ID: 30426
60
Processed posts 5600 - 5700 of 14154. Last Object ID: 29881
61
Processed posts 5700 - 5800 of 14154. Last Object ID: 29582
62
Processed posts 5800 - 5900 of 14154. Last Object ID: 29395
63
Processed posts 5900 - 6000 of 14154. Last Object ID: 29154
64
Processed posts 6000 - 6100 of 14154. Last Object ID: 28800
65
Processed posts 6100 - 6200 of 14154. Last Object ID: 28584
66
Processed posts 6200 - 6300 of 14154. Last Object ID: 28325
67
Processed posts 6300 - 6400 of 14154. Last Object ID: 28196
68
Processed posts 6400 - 6500 of 14154. Last Object ID: 27992
69
Processed posts 6500 - 6600 of 14154. Last Object ID: 27909
70
Processed posts 6600 - 6700 of 14154. Last Object ID: 27816
71
Processed posts 6700 - 6800 of 14154. Last Object ID: 27708
72
Processed posts 6800 - 6900 of 14154. Last Object ID: 27581
73
Processed posts 6900 - 7000 of 14154. Last Object ID: 27474
74
Processed posts 7000 - 7100 of 14154. Last Object ID: 27381
75
Processed posts 7100 - 7200 of 14154. Last Object ID: 27280
76
Processed posts 7200 - 7300 of 14154. Last Object ID: 27191
77
Processed posts 7300 - 7400 of 14154. Last Object ID: 27070
78
Processed posts 7400 - 7500 of 14154. Last Object ID: 26961
79
Processed posts 7500 - 7600 of 14154. Last Object ID: 26789
80
Processed posts 7600 - 7700 of 14154. Last Object ID: 26696
81
Processed posts 7700 - 7800 of 14154. Last Object ID: 26604
82
Processed posts 7800 - 7900 of 14154. Last Object ID: 26277
83
Processed posts 7900 - 8000 of 14154. Last Object ID: 25995
84
Processed posts 8000 - 8100 of 14154. Last Object ID: 25956
85
Processed posts 8100 - 8200 of 14154. Last Object ID: 25886
86
Processed posts 8200 - 8300 of 14154. Last Object ID: 25862
87
Processed posts 8300 - 8400 of 14154. Last Object ID: 25824
88
Processed posts 8400 - 8500 of 14154. Last Object ID: 25800
89
Processed posts 8500 - 8600 of 14154. Last Object ID: 25754
90
Processed posts 8600 - 8700 of 14154. Last Object ID: 25682
91
Processed posts 8700 - 8800 of 14154. Last Object ID: 25653
92
Processed posts 8800 - 8900 of 14154. Last Object ID: 25606
93
Processed posts 8900 - 9000 of 14154. Last Object ID: 25575
94
Processed posts 9000 - 9100 of 14154. Last Object ID: 25517
95
Processed posts 9100 - 9200 of 14154. Last Object ID: 25443
96
Processed posts 9200 - 9300 of 14154. Last Object ID: 25410
97
Processed posts 9300 - 9400 of 14154. Last Object ID: 25337
98
Processed posts 9400 - 9500 of 14154. Last Object ID: 25281
99
Processed posts 9500 - 9600 of 14154. Last Object ID: 25025
100
Processed posts 9600 - 9700 of 14154. Last Object ID: 24776
101
Processed posts 9700 - 9800 of 14154. Last Object ID: 24638
102
Processed posts 9800 - 9900 of 14154. Last Object ID: 24564
103
Processed posts 9900 - 10000 of 14154. Last Object ID: 24490
104
Processed posts 10000 - 10100 of 14154. Last Object ID: 24441
105
Processed posts 10100 - 10200 of 14154. Last Object ID: 24386
106
Processed posts 10200 - 10300 of 14154. Last Object ID: 24336
107
Processed posts 10300 - 10400 of 14154. Last Object ID: 24305
108
Processed posts 10400 - 10500 of 14154. Last Object ID: 24197
109
Processed posts 10500 - 10600 of 14154. Last Object ID: 5838
110
Processed posts 10600 - 10700 of 14154. Last Object ID: 984
111
Processed posts 10700 - 10800 of 14154. Last Object ID: 623
112
Processed posts 10800 - 10900 of 14154. Last Object ID: 614
113
Processed posts 10900 - 11000 of 14154. Last Object ID: 602
114
Processed posts 11000 - 11100 of 14154. Last Object ID: 591
115
Processed posts 11100 - 11200 of 14154. Last Object ID: 577
116
Processed posts 11200 - 11300 of 14154. Last Object ID: 559
117
Processed posts 11300 - 11400 of 14154. Last Object ID: 535
118
Processed posts 11400 - 11500 of 14154. Last Object ID: 512
119
Processed posts 11500 - 11600 of 14154. Last Object ID: 480
120
Processed posts 11600 - 11700 of 14154. Last Object ID: 444
121
Processed posts 11700 - 11800 of 14154. Last Object ID: 397
122
Processed posts 11800 - 11900 of 14154. Last Object ID: 342
123
Processed posts 11900 - 12000 of 14154. Last Object ID: 273
124
Processed posts 12000 - 12100 of 14154. Last Object ID: 173
125
Processed posts 12100 - 12200 of 14154. Last Object ID: 59
126
Processed posts 12200 - 12243 of 14154. Last Object ID: 3
127
Processed posts 12243 - 12244 of 14154. Last Object ID: 2
128
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
129
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
130
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
131
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
132
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
133
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
134
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
135
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
136
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
137
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
138
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
139
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
140
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
141
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
142
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
143
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
144
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
145
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
146
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
147
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
148
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
149
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
150
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
151
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
152
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
153
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
154
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
155
Processed posts 12244 - 12244 of 14154. Last Object ID: 2
156
Sync paused
157
Processed posts 12244 - 12244 of 14154. Last Object ID: 2

Environment information

• WordPress version: 5.9.2
• ElasticPress version: 4.0.0
• Elasticsearch version: 7.10.0
• Where do you host your Elasticsearch server? Locally
• What ElasticPress features do you have currently active? Post Search, Terms

Additional context
Rolling back to 3.6.6 works perfectly and all posts and terms are indexed.
Is there any additional logging that can be done - I presume it will be some sort of data issue with the content?
I tried removing all the additional metadata fields using the filter hook, but there is was no difference (other than the mapping was much smaller).
What other information can help?

[felipeelia]

Hi @derringer,

Thanks for opening the issue. One of the changes we made in version 4.0.0 was to introduce a dynamic index process, so, let's say, you use 1,000 posts per page, ElasticPress will get 1,000 from the database but won't send them all in one request but send them in small bulks until all of them are processed. The main goal of this feature is to avoid having several failures due to "Request too big" requests.

People wanting to index without this feature can use the WP-CLI command with the static-bulk flag:
wp elasticpress index --setup --yes --show-errors --static-bulk

I presume it will be some sort of data issue with the content?
Probably your post with ID #2 has some particularity that is preventing it to be properly indexed.

Is there any additional logging that can be done?
Yes. Running the command above (with that --show-errors) will probably display why post-ID 2 is not being indexed.

You can also use the code in this gist to log all the requests made and their characteristics. Would it be possible for you to

1. Enable WordPress logging
2. Use the content of that gist in your theme's functions.php or a mu-plugin
3. Paste the content of your debug.log file in a pastebin
4. Share it with us here?

Thanks!

[github-actions]

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.

[derringer]

Hi @felipeelia ,

Sorry for the delay. Now we are running 4.0.1 on the development server to test this now.

I have enabled all those things and the log in the webpage gets stuck on many repeated lines of:
Processed posts 6304 - 6304 of 14154. Last Object ID: 2

And wp elasticpress index --setup --yes --show-errors --static-bulk gives no extra information.

Here is the wp-debug.log (https://pastebin.com/GDESh62D).

I deleted post ID 2...

Now it stops and repeats:
Processed posts 6575 - 6575 of 14153. Last Object ID: 3

[felipeelia]

Hi @derringer,

First of all, thank you for getting back to us. Looking at your log, it doesn't seem it is stuck where I thought it would be. Here are a few things that could help us to identify the root of the problem:

1. While you have it stuck in one terminal, would it be possible for you to run wp elasticpress get-indexing-status and share the output?
2. Do you happen to have any custom code that would interfere with WP_Query calls?
3. Would it be possible for you to disable all the other plugins, enable a default WP theme and try again?

Thanks!

[derringer]

1. wp elasticpress get-indexing-status
   {"method":"cli","put_mapping":true,"offset":6575,"pagination_method":"id_range","start":true,"sync_stack":[{"url":"https:\/\/redacted.com","blog_id":1,"indexable":"term","put_mapping":true,"found_items":9656}],"network_alias":[],"start_time":1647536515.707427,"start_date_time":"2022-03-17T17:01:55+00:00","totals":{"total":0,"synced":0,"skipped":0,"failed":0,"total_time":0,"errors":[]},"current_sync_item":{"url":"https:\/\/redacted.com","blog_id":1,"indexable":"post","put_mapping":false,"found_items":14153,"total":14153,"synced":6575,"skipped":0,"failed":0,"errors":[],"last_processed_object_id":3},"from":6575,"found_items":14153,"indexing":true,"items_indexed":6575,"url":"https:\/\/redacted.com","total_items":14153,"slug":"post"}

2. No, but...

3. We do have Advanced Post Types Order 4.5 by NSP code installed. I have disabled this and it now works!

[derringer]

So disabling this plugin or actually, working around it with this filter (the ignore_custom_sort attribute turns off the AutoSort behaviour in the plugin):

add_filter( 'ep_post_query_db_args', function( $args ) {  
    $args["ignore_custom_sort"]=true;
    return $args; 
} ); 

fixed the posts. But there is still a problem now with the terms indexing. It only seems to index the number in "Content Items per Index Cycle".
Log of terms index: https://pastebin.com/thPcHvm4

[felipeelia]

That is an excellent discovery, @derringer. Thank you very much!

For the problems with terms, does it work if you run: wp elasticpress index --indexables=term --show-errors --static-bulk? (this command will only index terms, without touching any posts.)

[derringer]

No, so that is what I ran (without the --static-bulk) in the paste above, but with that I just get the same and there are only 350 items in ES:

vendor/wp-cli/wp-cli/bin/wp elasticpress index --indexables=term --show-errors --static-bulk
Success: Indexing terms...
Processed terms 0 - 350 of 9656. Last Object ID: 46153
Processed terms 350 - 700 of 9656. Last Object ID: 46153
Processed terms 700 - 1050 of 9656. Last Object ID: 46153
Processed terms 1050 - 1400 of 9656. Last Object ID: 46153
Processed terms 1400 - 1750 of 9656. Last Object ID: 46153
Processed terms 1750 - 2100 of 9656. Last Object ID: 46153
Processed terms 2100 - 2450 of 9656. Last Object ID: 46153
Processed terms 2450 - 2800 of 9656. Last Object ID: 46153
Processed terms 2800 - 3150 of 9656. Last Object ID: 46153
Processed terms 3150 - 3500 of 9656. Last Object ID: 46153
Time elapsed: 5.00
Memory Usage: 97.16mb (Peak: 114.98mb)
Processed terms 3500 - 3850 of 9656. Last Object ID: 46153
Processed terms 3850 - 4200 of 9656. Last Object ID: 46153
Processed terms 4200 - 4550 of 9656. Last Object ID: 46153
Processed terms 4550 - 4900 of 9656. Last Object ID: 46153
Processed terms 4900 - 5250 of 9656. Last Object ID: 46153
Processed terms 5250 - 5600 of 9656. Last Object ID: 46153
Processed terms 5600 - 5950 of 9656. Last Object ID: 46153
Processed terms 5950 - 6300 of 9656. Last Object ID: 46153
Processed terms 6300 - 6650 of 9656. Last Object ID: 46153
Processed terms 6650 - 7000 of 9656. Last Object ID: 46153
Time elapsed: 10.23 (+5.23)
Memory Usage: 100.42mb (Peak: 118.24mb)
Processed terms 7000 - 7350 of 9656. Last Object ID: 46153
Processed terms 7350 - 7700 of 9656. Last Object ID: 46153
Processed terms 7700 - 8050 of 9656. Last Object ID: 46153
Processed terms 8050 - 8400 of 9656. Last Object ID: 46153
Processed terms 8400 - 8750 of 9656. Last Object ID: 46153
Processed terms 8750 - 9100 of 9656. Last Object ID: 46153
Processed terms 9100 - 9450 of 9656. Last Object ID: 46153
Processed terms 9450 - 9800 of 9656. Last Object ID: 46153
Success: Number of terms indexed: 9800
Success: Sync complete
Total time elapsed: 14.658
Success: Done!

On the live with with the old plugin (3.6.6) there are about 1400 terms indexed.

[felipeelia]

Hi @derringer, that looks like a bug in the plugin. While running the current codebase, can you please run wp elasticpress index --indexables=term --show-errors --offset=1 and let me know the output and how many terms you have indexed in Elasticsearch?

I've opened #2665 to fix the problem, would it be possible for you to test it? If you can't let me know and I can create a zip file for you. Thanks!

[derringer]

Hi @felipeelia, Using that command works fine and there are 9656 items in ES:
wp elasticpress index --indexables=term --show-errors --static-bulk --offset=1

Success: Indexing terms...
Skipping 1 terms...
Processed terms 1 - 351 of 9656. Last Object ID: 46152
Processed terms 351 - 701 of 9656. Last Object ID: 45795
Processed terms 701 - 1051 of 9656. Last Object ID: 41462
Processed terms 1051 - 1401 of 9656. Last Object ID: 36598
Processed terms 1401 - 1751 of 9656. Last Object ID: 33215
Processed terms 1751 - 2101 of 9656. Last Object ID: 29220
Processed terms 2101 - 2451 of 9656. Last Object ID: 24331
Processed terms 2451 - 2801 of 9656. Last Object ID: 20575
Processed terms 2801 - 3151 of 9656. Last Object ID: 16705
Processed terms 3151 - 3501 of 9656. Last Object ID: 11632
Time elapsed: 6.03
Memory Usage: 97.33mb (Peak: 115.01mb)
Processed terms 3501 - 3851 of 9656. Last Object ID: 6389
Processed terms 3851 - 4201 of 9656. Last Object ID: 5996
Processed terms 4201 - 4551 of 9656. Last Object ID: 5547
Processed terms 4551 - 4901 of 9656. Last Object ID: 5112
Processed terms 4901 - 5251 of 9656. Last Object ID: 4749
Processed terms 5251 - 5601 of 9656. Last Object ID: 4389
Processed terms 5601 - 5951 of 9656. Last Object ID: 4030
Processed terms 5951 - 6301 of 9656. Last Object ID: 3662
Processed terms 6301 - 6651 of 9656. Last Object ID: 3307
Processed terms 6651 - 7001 of 9656. Last Object ID: 2946
Time elapsed: 12.01 (+5.98)
Memory Usage: 100.77mb (Peak: 118.6mb)
Processed terms 7001 - 7351 of 9656. Last Object ID: 2585
Processed terms 7351 - 7701 of 9656. Last Object ID: 2225
Processed terms 7701 - 8051 of 9656. Last Object ID: 1865
Processed terms 8051 - 8401 of 9656. Last Object ID: 1498
Processed terms 8401 - 8751 of 9656. Last Object ID: 1128
Processed terms 8751 - 9101 of 9656. Last Object ID: 743
Processed terms 9101 - 9451 of 9656. Last Object ID: 316
Processed terms 9451 - 9656 of 9656. Last Object ID: 1
Success: Number of terms indexed: 9655
Success: Sync complete
Total time elapsed: 16.487
Success: Done!

Will test the patch now.

[derringer]

I have patched my version with #2665 and can confirm that it works as expected indexing 9656 terms.

Thanks @felipeelia