7.3.2 и потеря мастера

Denis_Lamanov · September 26, 2019, 12:24pm

Наконец-то обновились до 7.3.2 с 6.8.2
Индексы поднялись и при минимальной нагрузке одна нода теряет выбранный мастер и соответственно вылетела из кластера через пару минут присоединившись
При этом проблем с железом и сетью нет
У нас 7 нод и каждая node.master: true

Логи с момента потери: https://gist.github.com/UkrZilla/71d7da7a83c1755e8ec77a9b54baf861

Ещё в процессе нормальной работы вижу в логах на всех нодах через каждую минуту INFO сообщение: waiting for elected master node...

Denis_Lamanov · September 26, 2019, 12:30pm

В логах выбранного мастера вижу как он периодически удаляет ноду, а потом присоединяет:

gist.github.com

https://gist.github.com/UkrZilla/570fad7944ebc3df600a9eca056bb98b

node-left-log

[2019-09-26T12:23:27,701][WARN ][o.e.c.s.MasterService    ] [node-02] cluster state update task [node-left[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} lagging]] took [31s] which is above the warn threshold of 30s
[2019-09-26T12:23:37,775][INFO ][o.e.c.s.MasterService    ] [node-02] node-join[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} join existing leader], term: 3, version: 2169, reason: added {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}
[2019-09-26T12:24:07,928][INFO ][o.e.c.s.ClusterApplierService] [node-02] added {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}, term: 3, version: 2169, reason: Publication{term=3, version=2169}
[2019-09-26T12:24:07,964][WARN ][o.e.c.s.MasterService    ] [node-02] cluster state update task [node-join[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} join existing leader]] took [30.1s] which is above the warn threshold of 30s
[2019-09-26T12:24:08,810][INFO ][o.e.c.s.MasterService    ] [node-02] node-left[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} disconnected], term: 3, version: 2170, reason: removed {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}
[2019-09-26T12:24:35,588][INFO ][o.e.c.s.ClusterApplierService] [node-02] removed {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}, term: 3, version: 2170, reason: Publication{term=3, version=2170}
[2019-09-26T12:24:36,960][INFO ][o.e.c.s.MasterService    ] [node-02] node-join[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} join existing leader], term: 3, version: 2173, reason: added {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}
[2019-09-26T12:25:07,126][INFO ][o.e.c.s.ClusterApplierService] [node-02] added {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}, term: 3, version: 2173, reason: Publication{term=3, version=2173}
[2019-09-26T12:25:07,163][WARN ][o.e.c.s.MasterService    ] [node-02] cluster state update task [node-join[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} join existing leader]] took [30.2s] which is above the warn threshold of 30s
[2019-09-26T12:25:08,036][INFO ][o.e.c.s.MasterService    ] [node-02] node-left[{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} disconnected], term: 3, version: 2174, reason: removed {{node-04}{w5l4kNh_TdiyXDoGN17ovg}{huubuernTCStnU7kc7yTEA}{10.1.3.114}{10.1.3.114:9300}{dim}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}

This file has been truncated. show original

Igor_Motov · September 26, 2019, 1:36pm

Свапимся опять?

Denis_Lamanov · September 26, 2019, 1:38pm

Вы про swapping? Нет. Памяти свободной сейчас 90%

Igor_Motov · September 26, 2019, 1:47pm

Надо разобраться, почему вот это происходит.

[2019-09-26T11:54:31,820][INFO ][o.e.m.j.JvmGcMonitorService] [node-00] [gc][3308] overhead, spent [273ms] collecting in the last [1s]
[2019-09-26T11:54:53,827][INFO ][o.e.m.j.JvmGcMonitorService] [node-00] [gc][3330] overhead, spent [259ms] collecting in the last [1s]
[2019-09-26T11:54:54,828][INFO ][o.e.m.j.JvmGcMonitorService] [node-00] [gc][3331] overhead, spent [362ms] collecting in the last [1s]

Такое обычно бывает, когда процесс elasticsearch уходит в swap, либо когда процессор дросселируется виртуальной машиной или когда у java кучи не хватает. 30% времени в GC - это не здоровая ситуация.

Denis_Lamanov · September 26, 2019, 1:49pm

Кстати, при обновлении я удалил Java 11 и использую бандлед 12 которая идёт в поставке с 7.3.2
Может попробовать вернуть 11?

Denis_Lamanov · September 26, 2019, 2:11pm

Ещё у нас каждая дата нода является и мастером. Есть виртуалка которая не дата и не мастер, для чтения дашбоардов. Виртуалка стабильна. Может сделать мастером только виртуалку и тогда проблемы дата нод не будут влиять на выборы?

Igor_Motov · September 26, 2019, 2:33pm

Надо разобраться почему ваша виртуалка не дает процессу java нормально работать, все остальное - временные решения.

Denis_Lamanov · September 26, 2019, 4:22pm

Так, похоже проблема найдена: во всех случаях удаления ноды от мастера была причина: reason: ApplyCommitRequest
Насколько я понял по форуму это повреждённый индекс или transaction log.
После установки 7.3 я увидел старые индексы за март, которые 6.8 не показывал.
Удалив их всё нормализовалось и ноды перестали отлетать. Объясняет ли это проблему в GC?

Igor_Motov · September 26, 2019, 6:21pm

Вы, скорее всего, прочитали про flush, он же Lucene commit. ApplyCommitRequest - это часть процесса публикации состояния кластера на все ноды. В результате длинных пауз в результате блокировки во время сборки мусора, ноды не подтверждали во время новое состояние кластера, что и вызывало сбои.

Индексы, которые появились - это так называемые dangling indices. Они могли вызывать дополнительную нагрузку на кластер. Если у вас сообщения про GC после этого исчезли - то все нормально, если они все еще появляются - то ваше спокойствие временное и проблемы вернутся как только вы увеличите нагрузку на кластер.

Denis_Lamanov · September 29, 2019, 5:40pm

Всё нормализовалось. Больше такого не наблюдали

Denis_Lamanov · October 11, 2019, 6:31pm

Обновились на 7.4. В плане производительности стало лучше. Но мастер всё таки раз в 2-3 дня отваливается. При этом никакой резкой нагрузки, всплеска или видимых причин не видно.

Вот что в этот момент в логах дата нод которые с ролью мастера, но не были в этот момент мастером:

gist.github.com

https://gist.github.com/UkrZilla/5e63d2c80c4299f59bfbd5a2a6334473

notMaster

[2019-10-11T17:06:10,195][INFO ][o.e.c.c.Coordinator      ] [node-02] master node [{node-01}{wGMNopDRRLOX-CePJLFv_g}{_I8Nh-z1TiSpweOkLuK2Kw}{10.1.3.111}{10.1.3.111:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}] failed, restarting discovery
org.elasticsearch.ElasticsearchException: node [{node-01}{wGMNopDRRLOX-CePJLFv_g}{_I8Nh-z1TiSpweOkLuK2Kw}{10.1.3.111}{10.1.3.111:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}] failed [3] consecutive checks
	at org.elasticsearch.cluster.coordination.LeaderChecker$CheckScheduler$1.handleException(LeaderChecker.java:278) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1120) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.InboundHandler.lambda$handleException$2(InboundHandler.java:243) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:225) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.InboundHandler.handleException(InboundHandler.java:241) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.InboundHandler.handlerResponseError(InboundHandler.java:233) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:136) ~[elasticsearch-7.4.0.jar:7.4.0]
	at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:102) ~[elasticsearch-7.4.0.jar:7.4.0]

This file has been truncated. show original

В этот момент в логах избранного мастера:

gist.github.com

https://gist.github.com/UkrZilla/9c116e5fbb006b20e2640eddeec32754

Master

[2019-10-11T17:04:51,446][WARN ][o.e.c.InternalClusterInfoService] [node-01] Failed to update shard information for ClusterInfoUpdateJob within 15s timeout
[2019-10-11T17:05:06,714][WARN ][o.e.t.TransportService   ] [node-01] Received response for a request that has timed out, sent [36000ms] ago, timed out [25982ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{_1VDIvOpSvq6hkhBbBwcVw}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [31282225]
[2019-10-11T17:05:06,970][WARN ][o.e.t.TransportService   ] [node-01] Received response for a request that has timed out, sent [25666ms] ago, timed out [15455ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{_1VDIvOpSvq6hkhBbBwcVw}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [31284663]
[2019-10-11T17:05:06,971][WARN ][o.e.t.TransportService   ] [node-01] Received response for a request that has timed out, sent [14442ms] ago, timed out [4554ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{_1VDIvOpSvq6hkhBbBwcVw}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [31284917]
[2019-10-11T17:05:07,991][INFO ][o.e.m.j.JvmGcMonitorService] [node-01] [gc][282144] overhead, spent [255ms] collecting in the last [1s]
[2019-10-11T17:05:09,680][INFO ][o.e.c.s.MasterService    ] [node-01] node-left[{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{_1VDIvOpSvq6hkhBbBwcVw}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} followers check retry count exceeded], term: 13, version: 36719, reason: removed {{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{_1VDIvOpSvq6hkhBbBwcVw}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},}
[2019-10-11T17:05:16,766][INFO ][o.e.m.j.JvmGcMonitorService] [node-01] [gc][282152] overhead, spent [310ms] collecting in the last [1.1s]
[2019-10-11T17:05:17,827][INFO ][o.e.m.j.JvmGcMonitorService] [node-01] [gc][282153] overhead, spent [319ms] collecting in the last [1.1s]
[2019-10-11T17:05:36,992][DEBUG][o.e.a.a.i.t.p.TransportPutIndexTemplateAction] [node-01] failed to put template [.management-beats]
org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (create-index-template [.management-beats], cause [api]) within 30s

This file has been truncated. show original

Что можете посоветовать? На версиях до 7-ки такого не было

Denis_Lamanov · October 12, 2019, 4:09pm

Судя по логам т.к. у нас не SSD диски, то обновление мета-информации о каждоом индексе(которых у нас больше чем 1000 на ноду) на диске иногда превышает cluster.publish.timeout (Rolling upgrade problem from 6.8 to 7.1.1)
Собственно этот механизм, судя по документации, ввели в 7-ке
https://www.elastic.co/guide/en/elasticsearch/reference/7.4/cluster-state-publishing.html

Igor_Motov · October 13, 2019, 9:47am

У вас ноду залипают не только на state publishing, но и не очень легких запросов вроде internal:coordination/fault_detection/follower_check. Другими словами, некоторые ноды перестают отвечать на любые запросы по 15-40 секунд. Отсюда и все проблемы. Почему это происходит, я сказать затрудняюсь. Может VM глючит, может сеть. Когда такие проблемы происходит, вы можете попробовать на машину залогиниться и посмотреть - а машина то сама отзывается, или все остальное тоже тормозит.

Denis_Lamanov · October 13, 2019, 9:51am

Да, логинился в это время на проблемную ноду - ничего не тормозит. Всё в нормальном режиме: сеть не пропадала, диск и процессор не нагружены

Пока что подкрутил так:

cluster.join.timeout: 180s
cluster.publish.timeout: 180s
cluster.follower_lag.timeout: 180s

Но ещё заметил, что бывает часто когда нода отваливается от мастера и в вечном цикле подключается и сразу же отключается пока не перезагрузишь её

Denis_Lamanov · October 15, 2019, 7:56am

Действительно, одна нода отваливается по internal:coordination/fault_detection/follower_check

Какие можно включить trace в логировании чтобы посмотреть более детально?
Параллельно смотрим на железо, но предварительно там всё хорошо и сеть не пропадает в это время

Igor_Motov · October 15, 2019, 8:11am

У Вас для этого кластера мониторинг настроен?

Denis_Lamanov · October 15, 2019, 8:13am

Мониторинг через Zabbix и ещё снимаем раз в минуту статистику по Heap Size и Open descriptors

Denis_Lamanov · October 15, 2019, 8:16am

Интересно, что после того как мастер отключил ноду по таймауту, то чуть позже приходят запоздалые ответы на респонсы (лог с мастера):

[2019-10-15T06:40:51,152][INFO ][o.e.c.s.MasterService ] [node-01] node-left[{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{zkM7E5SdSmG6MdvxLMPiRQ}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true} followers check retry count exceeded], term: 24, version: 110637, reason: removed {{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{zkM7E5SdSmG6MdvxLMPiRQ}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true},} [2019-10-15T06:40:53,929][WARN ][o.e.t.TransportService ] [node-01] Received response for a request that has timed out, sent [38172ms] ago, timed out [28069ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{zkM7E5SdSmG6MdvxLMPiRQ}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [8400909] [2019-10-15T06:40:53,997][WARN ][o.e.t.TransportService ] [node-01] Received response for a request that has timed out, sent [27268ms] ago, timed out [17312ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{zkM7E5SdSmG6MdvxLMPiRQ}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [8403538] [2019-10-15T06:40:54,000][WARN ][o.e.t.TransportService ] [node-01] Received response for a request that has timed out, sent [16311ms] ago, timed out [6340ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node-00}{A9AdXLb5QA-ZMcicCn26OQ}{zkM7E5SdSmG6MdvxLMPiRQ}{10.1.3.110}{10.1.3.110:9300}{dilm}{ml.machine_memory=134928560128, ml.max_open_jobs=20, xpack.installed=true}], id [8405154]

Denis_Lamanov · October 15, 2019, 8:20am

Вот история Heap Size по нодам(инцидент произошел в 6:40)