Page MenuHomePhabricator
Create Task
Maniphest T227136

Reindexing search index wikidatawiki for eqiad fails
Closed, ResolvedPublic
Actions

Description

After launching reindex on wikidatawiki for eqiad, I get this in the logs:

       Task: hCP8oBWATB-ow4_46CiODw:1486068450 Search Retries: 0 Bulk Retries: 0 Indexed: 57280514 / 57735703
        Task: hCP8oBWATB-ow4_46CiODw:1486068450 Search Retries: 0 Bulk Retries: 0 Indexed: 57282714 / 57735703
        Task: hCP8oBWATB-ow4_46CiODw:1486068450 Search Retries: 0 Bulk Retries: 0 Indexed: 57285514 / 57735703
        Task: hCP8oBWATB-ow4_46CiODw:1486068450 Search Retries: 0 Bulk Retries: 0 Indexed: 57288614 / 57735703
        Task: hCP8oBWATB-ow4_46CiODw:1486068450 Search Retries: 0 Bulk Retries: 0 Indexed: 57290132 / 57735703
Reindex task was not successfull: Failed: [{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id
[654279810]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [890751724]"}}]

and new index doesn't seem to be there. Looks like we have some problem in wikidatawiki indexing. codfw indexing went fine, so maybe some timing related things are in play.

Details

SubjectRepoBranchLines +/-
[cirrus] switch search traffic (except completion) to codfwoperations/mediawiki-configmaster+4 -2
[cirrus] Increase elastic master timeout to 5moperations/mediawiki-configmaster+2 -3
Customize query in gerrit

Related Objects

Event Timeline

Smalyshev created this task.Jul 2 2019, 7:43 PM
Restricted Application added subscribers: Liuxinyu970226, Aklapper. · View Herald TranscriptJul 2 2019, 7:43 PM
Smalyshev triaged this task as High priority.Jul 2 2019, 7:43 PM
Smalyshev updated the task description. (Show Details)
Smalyshev added a comment.Jul 3 2019, 6:22 AM

Another error I've got is:

                Validating mapping...different...failed!                                                       
Couldn't update existing mappings. You may need to reindex.       
Here is elasticsearch's error message: process_cluster_event_timeout_exception: failed to process cluster event (put-mapping) within 30s

What is worse, the script does not seem to return error code there so reindex script proceeds on this failure as if nothing happened. This should be fixed too.

gerritbot added a comment.Jul 3 2019, 1:55 PM

Change 520446 had a related patch set uploaded (by DCausse; owner: DCausse):
[operations/mediawiki-config@master] [cirrus] Increase elastic master timeout to 5m

https://gerrit.wikimedia.org/r/520446

gerritbot added a project: Patch-For-Review.Jul 3 2019, 1:55 PM
dcausse added a comment.EditedJul 3 2019, 1:59 PM

The process_cluster_event_timeout_exception is something that can be addressed by increasing the masterTimeout we reverted it back to 30s hoping that the multi-instance cluster setup would help here. Apparently we're still seeing this kind of issue Let's bump this value up to 5m.

As for the SearchContext issue it's hard to do something about it except stabilizing the cluster. Since no nodes went away during the reindex I suspect that a shard rebalance caused a shard holding the scroll to have been moved from a node to another. We experience a lot more rebalances in eqiad because we are a bit more constrained on disk space therefor increasing the chances to have shards being moved (esp. for very large indices like wikidata).
In other words I think we need to stabilize this graph: https://grafana.wikimedia.org/d/JLK3I_siz/elasticsearch-indexing?panelId=34&fullscreen&orgId=1
Hopefully replacing old nodes in this cluster this year will help a lot.

EBernhardson added a comment.Jul 3 2019, 8:08 PM
In T227136#5303679, @dcausse wrote:

As for the SearchContext issue it's hard to do something about it except stabilizing the cluster. Since no nodes went away during the reindex I suspect that a shard rebalance caused a shard holding the scroll to have been moved from a node to another. We experience a lot more rebalances in eqiad because we are a bit more constrained on disk space therefor increasing the chances to have shards being moved (esp. for very large indices like wikidata).
In other words I think we need to stabilize this graph: https://grafana.wikimedia.org/d/JLK3I_siz/elasticsearch-indexing?panelId=34&fullscreen&orgId=1
Hopefully replacing old nodes in this cluster this year will help a lot.

I tested this by starting up a two node elasticsearch 6.5.4 cluster, indexing documents, and then scrolling over the documents. After starting the scroll rerouting index from node A -> B works and doesn't break the scroll. Attempting to reroute the shard from B back to A fails to acquire a lock until the scroll is closed. Once the scroll is closed the shard is free to move back to A again.

It could still have something to do with the shard movement, but i wasn't able to convince elasticsearch to reproduce this error using the cluster reroute api.

gerritbot added a comment.Jul 8 2019, 6:04 PM

Change 520446 merged by jenkins-bot:
[operations/mediawiki-config@master] [cirrus] Increase elastic master timeout to 5m

https://gerrit.wikimedia.org/r/520446

Stashbot added a comment.Jul 8 2019, 6:06 PM

Mentioned in SAL (#wikimedia-operations) [2019-07-08T18:06:37Z] <urbanecm@deploy1001> Synchronized wmf-config/CirrusSearch-production.php: SWAT: [[:gerrit:520446|[cirrus] Increase elastic master timeout to 5m]] (T227136) (duration: 00m 49s)

Smalyshev added a comment.Jul 8 2019, 6:09 PM

OK, process_cluster_event_timeout_exception seems to be gone now, let's see what full reindex brings.

Smalyshev edited projects, added CirrusSearch; removed Patch-For-Review.Jul 8 2019, 6:10 PM
Restricted Application edited projects, added Discovery-Search; removed Discovery-Search (Current work). · View Herald TranscriptJul 8 2019, 6:10 PM
Smalyshev added a comment.Jul 9 2019, 5:25 PM

Reindex failed again with:

        Task: 2RzPRaQORnWFGJZERdgd9A:1072910896 Search Retries: 0 Bulk Retries: 0 Indexed: 47815109 / 57882498
Reindex task was not successfull: Failed: [{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reason":"rejected execution of org.elastics
earch.common.util.concurrent.TimedRunnable@149d19f0 on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-search-eqiad\/search, queue cap
acity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task execution EWMA = 2.9s, adjust
ment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size = 61, active threads = 61, que
ued tasks = 1000, completed tasks = 1736446094]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reason":"rejected execution of org
.elasticsearch.common.util.concurrent.TimedRunnable@376ac7fc on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-search-eqiad\/search,
queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task execution EWMA = 876
.8ms, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size = 61, active threa
ds = 61, queued tasks = 1026, completed tasks = 1739550836]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reason":"rejected exec
ution of org.elasticsearch.common.util.concurrent.TimedRunnable@666bda88 on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-search-eqi
ad\/search, queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task executio
n EWMA = 1.3s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size = 61, act
ive threads = 61, queued tasks = 1002, completed tasks = 1739532977]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reason":"reje
cted execution of org.elasticsearch.common.util.concurrent.TimedRunnable@1509003f on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-s
earch-eqiad\/search, queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task
 execution EWMA = 2.9s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size
= 61, active threads = 61, queued tasks = 1000, completed tasks = 1736446094]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reas
on":"rejected execution of org.elasticsearch.common.util.concurrent.TimedRunnable@1c557685 on QueueResizingEsThreadPoolExecutor[name = elastic1051-pro
duction-search-eqiad\/search, queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate =
 1s, task execution EWMA = 90.4ms, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running,
 pool size = 61, active threads = 61, queued tasks = 1005, completed tasks = 1739514105]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_excep
tion","reason":"rejected execution of org.elasticsearch.common.util.concurrent.TimedRunnable@6d7b5dbb on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-search-eqiad\/search, queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task execution EWMA = 1.1s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size = 61, active threads = 61, queued tasks = 1005, completed tasks = 1739514106]]"}},{"shard":-1,"reason":{"type":"es_rejected_execution_exception","reason":"rejected execution of org.elasticsearch.common.util.concurrent.TimedRunnable@16d8b36b on QueueResizingEsThreadPoolExecutor[name = elastic1051-production-search-eqiad\/search, queue capacity = 1000, min queue capacity = 1000, max queue capacity = 1000, frame size = 2000, targeted response rate = 1s, task execution EWMA = 1.9s, adjustment amount = 50, org.elasticsearch.common.util.concurrent.QueueResizingEsThreadPoolExecutor@6c0d056[Running, pool size = 61, active threads = 61, queued tasks = 1000, completed tasks = 1736446093]]"}}]
Smalyshev moved this task from needs triage to Current work on the Discovery-Search board.Jul 9 2019, 5:27 PM
Smalyshev edited projects, added Discovery-Search (Current work); removed Discovery-Search.
EBernhardson added a comment.EditedJul 9 2019, 5:53 PM

Hmm, that is quite unexpected. Basically the error that is being returned is that the search queue on a single node filled up and rejected a search. Reindex is supposed to handle retries natively, and we can see from the status line it reports 0 retries so far.

This could be related to: https://github.com/elastic/elasticsearch/issues/26153

It's not 100% the same situation, but it seems close.

Summary:

When a scroll fails on some shards and returns partial results, there's no current way to rewind so that the reader makes sure to  get those missing documents. In the context of the reindex API, losing documents is clearly very incorrect behavior, so the right thing to do is fail when this happens, even though it's unfortunately very inconvenient.

One option is we can simply restart the same reindex into the same target index. Anything previously imported (and not updated since) will get a noop and speed along the reindex task. I don't think our scripts currently have an option to reindex into an existing index though. Not sure what else we can do from outside elasticsearch on this one. The summary of the bug seems to imply even if we managed the scroll ourselves it's the scroll that fails, and we can't rewind or resume a scroll.

Smalyshev added a comment.Jul 9 2019, 8:54 PM

One option is we can simply restart the same reindex into the same target index.

Can we make the script to do this if reindex fails? Or that's too hard to detect? If it is, we should at least produce a failure code I think...

Smalyshev mentioned this in T206613: Search of wikidata string property values using haswbstatement is case sensitive.Jul 10 2019, 9:23 PM
Smalyshev mentioned this in T224611: Implement match for any-language label (haslabel:*).Jul 10 2019, 9:44 PM
EBernhardson added a comment.Jul 15 2019, 3:12 PM
In T227136#5319281, @Smalyshev wrote:

One option is we can simply restart the same reindex into the same target index.

Can we make the script to do this if reindex fails? Or that's too hard to detect? If it is, we should at least produce a failure code I think...

I don't see why not, we might want to try and define what a retry-able error is, but likely even retrying something that doesn't work a few times will only lead to some extra log spam?

Stashbot added a comment.Jul 16 2019, 12:42 PM

Mentioned in SAL (#wikimedia-operations) [2019-07-16T12:42:40Z] <dcausse> deleting stale wikidata indices (elastic@eqiad) T227136

Stashbot added a comment.Jul 16 2019, 4:28 PM

Mentioned in SAL (#wikimedia-operations) [2019-07-16T16:28:07Z] <dcausse> reindexing wikidata (elastic@eqiad) T227136

dcausse added a comment.Jul 17 2019, 6:59 AM

Failed again (56850851 / 58244355) with:

Reindex task was not successfull: Failed: [{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [803795624]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [854883345]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [562256487]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [894521381]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [825290081]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [894521383]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [825290085]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [894521384]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [854883344]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [854883343]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [803795626]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [803795625]"}},{"shard":-1,"reason":{"type":"search_context_missing_exception","reason":"No search context found for id [825290078]"}}]

I'll switch everything but completion to codfw and test again.

gerritbot added a comment.Jul 17 2019, 7:51 AM

Change 523860 had a related patch set uploaded (by DCausse; owner: DCausse):
[operations/mediawiki-config@master] [cirrus] switch search traffic (except completion) to codfw

https://gerrit.wikimedia.org/r/523860

gerritbot added a project: Patch-For-Review.Jul 17 2019, 7:51 AM
Mvolz subscribed.Jul 17 2019, 9:07 AM
gerritbot added a comment.Jul 17 2019, 11:03 AM

Change 523860 merged by jenkins-bot:
[operations/mediawiki-config@master] [cirrus] switch search traffic (except completion) to codfw

https://gerrit.wikimedia.org/r/523860

Stashbot added a comment.Jul 17 2019, 11:08 AM

Mentioned in SAL (#wikimedia-operations) [2019-07-17T11:08:29Z] <dcausse@deploy1001> Synchronized wmf-config/InitialiseSettings.php: T227136: [cirrus] switch search traffic (except completion) to codfw (duration: 00m 54s)

Stashbot added a comment.Jul 17 2019, 11:16 AM

Mentioned in SAL (#wikimedia-operations) [2019-07-17T11:16:24Z] <dcausse> reindexing wikidata (elastic@eqiad) T227136

dcausse moved this task from Incoming to Needs Reporting on the Discovery-Search (Current work) board.Jul 18 2019, 1:47 PM
dcausse mentioned this in T228430: Improve resiliency of the reindexing process.Jul 18 2019, 3:00 PM
debt closed this task as Resolved.Jul 19 2019, 3:43 PM
debt claimed this task.
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL