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

[Igor_Motov]

А можно ничего не вырезать или хотя бы предупреждать об этом. Эта информация важна, потому что мы думали что в это время вообще ничего не происходило.

[Denis_Lamanov (Denys Lamanov)]

Да, пришлю полный лог

[GreenX]

У вас железное железо или виртуалки?

[Denis_Lamanov (Denys Lamanov)]

Виртуалки, но довольно мощные. Сейчас node-master находится в другом сегменте с остальными нодами и общаются через физический маршрутизатор. Попробуем перевести их в один сегмент сети и посмотрим

[Denis_Lamanov (Denys Lamanov)]

Пока ещё не перевели в один сегмент, но посмотрите что произошло в 16:48:35.
Возможно, действительно, по какой-то причине и разорвалось tcp соединение с мастером(node-00)
Но, почему node-master почти 12 минут не мог нормально присоединиться к кластеру?
По поводу работы сети в эти 12 минут: я сидел в ssh консоли с node-master на node-00 и никаких проблем не было + есть мониториг zabbix который никаких проблем или аномалий не показывает

Полный лог с этого момента с node-master(без обрезаний):

node-master.log

node-00, node-01 - дата ноды
node-master - координатор
роль мастера у всех нод

P.S. Да, мы через node-master пишем логи и соответственно попытки записи в это время падали

[Denis_Lamanov (Denys Lamanov)]

Это повторяется

Новый лог:

node-master_new.log

Кстати, судя по всему тоже самое происходило и на продакшене. Но там я прикрутил таймауты, иначе совсем всё было плохо, ноды отваливались и кластер не работал.

[Denis_Lamanov (Denys Lamanov)]

Для последнего случая лог с node-00(мастер)

node-00.log

Странно, что в это время все FollowerChecker для node-master successful

Разница по времени в логах 3 часа. На node-00 UTC, на node-master UTC+3

[GreenX]

Я насчитал только три ноды: 192.168.11.39, 192.168.11.15, 192.168.100.50.

Раз разные сегменты может быть, что угодно. Вплоть до фаервола.

Еще, посмотри есть ли такое в логах:

grep 'soft lockup' /var/log/messages*

[Igor_Motov]

Показал логи разработчику системы выбора мастера. Он сказал следующее:

I also suspect bad networking. Things started to go wrong here when node-master (not the master) thinks the master disconnected:

[2019-10-26T18:48:44,972][TRACE][o.e.c.c.LeaderChecker    ] [node-master] scheduling next check of {node-00}{cMIMAQ2cQBKx-0W0VqGzrg}{XnVYYzVYRUWLBI5pJ1RVKA}{192.168.11.39}{192.168.11.39:9300}{dim} for [cluster.fault_detection.leader_check.interval] = 1s
[2019-10-26T18:48:45,333][DEBUG][o.e.c.c.LeaderChecker    ] [node-master] leader [{node-00}{cMIMAQ2cQBKx-0W0VqGzrg}{XnVYYzVYRUWLBI5pJ1RVKA}{192.168.11.39}{192.168.11.39:9300}{dim}] disconnected
[2019-10-26T18:48:45,338][INFO ][o.e.c.c.Coordinator      ] [node-master] master node [{node-00}{cMIMAQ2cQBKx-0W0VqGzrg}{XnVYYzVYRUWLBI5pJ1RVKA}{192.168.11.39}{192.168.11.39:9300}{dim}] failed, restarting discovery
org.elasticsearch.transport.NodeDisconnectedException: [node-00][192.168.11.39:9300][disconnected] disconnected
It starts a cycle of trying to rejoin the master. Node node-00 (the master) receives the join requests but cannot validate them due to repeated timeouts, suggestive of connectivity issues:
[2019-10-26T15:48:45,369][TRACE][o.e.c.c.Coordinator      ] [node-00] handleJoinRequest: as LEADER, handling JoinRequest{sourceNode={node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true}, optionalJoin=Optional.empty}
[2019-10-26T15:49:45,369][WARN ][o.e.c.c.Coordinator      ] [node-00] failed to validate incoming join request from node [{node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true}]
org.elasticsearch.transport.ReceiveTimeoutTransportException: [node-master][192.168.100.50:9300][internal:cluster/coordination/join/validate] request_id [3788763] timed out after [60034ms]
        at org.elasticsearch.transport.TransportService$TimeoutHandler.run(TransportService.java:1022) [elasticsearch-7.4.1.jar:7.4.1]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:703) [elasticsearch-7.4.1.jar:7.4.1]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]
[2019-10-26T15:49:45,422][TRACE][o.e.c.c.Coordinator      ] [node-00] handleJoinRequest: as LEADER, handling JoinRequest{sourceNode={node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true}, optionalJoin=Optional.empty}
...
[2019-10-26T16:02:46,428][TRACE][o.e.c.c.Coordinator      ] [node-00] handleJoinRequest: as LEADER, handling JoinRequest{sourceNode={node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true}, optionalJoin=Optional.empty}
[2019-10-26T16:03:46,428][WARN ][o.e.c.c.Coordinator      ] [node-00] failed to validate incoming join request from node [{node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true}]
org.elasticsearch.transport.ReceiveTimeoutTransportException: [node-master][192.168.100.50:9300][internal:cluster/coordination/join/validate] request_id [3832554] timed out after [60035ms]
        at org.elasticsearch.transport.TransportService$TimeoutHandler.run(TransportService.java:1022) [elasticsearch-7.4.1.jar:7.4.1]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:703) [elasticsearch-7.4.1.jar:7.4.1]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]

After around 15 minutes of these attempts node-00 also concludes that the connection is broken:

[2019-10-26T16:04:13,289][INFO ][o.e.c.s.MasterService    ] [node-00] node-left[{node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true} disconnected], term: 135, version: 24862, reason: removed {{node-master}{QMKLhGHiSTWJsFh6IZG0lw}{F6SDojREQtSojw5Kke6RsA}{192.168.100.50}{192.168.100.50:9300}{im}{xpack.installed=true},}

This causes it to drop the broken connection and start again from scratch, at which point the node rejoins the cluster. 15 minutes the default timeout for a TCP connection in Linux - the time between first sending a packet and giving up waiting for it to be acked.

Мы думаем, что, скорее всего, брандмауэр перекрывает долгоживущие соединения между узлами каким-то образом.

[Denis_Lamanov (Denys Lamanov)]

Получается что Elasticsearch использует разные tcp коннекшены для FollowerChecker и выборов мастера?
И если в первом данные бегают каждую секунду, то во втором очень редко(в нормальной ситуации)
В сети маршрутизатор действительно мождет рвать соединения.
Проставил в ОС net.ipv4.tcp_keepalive_time и поставил в конфиге маленький transport.ping_schedule

Игорь, спасибо

[Igor_Motov]

@Denis_Lamanov

Получается что Elasticsearch использует разные tcp коннекшены для FollowerChecker и выборов мастера?

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

[Denis_Lamanov (Denys Lamanov)]

Понял, спасибо. Теперь понятно почему меня смущал successful FollowerChecker.
Всё подкрутили в ОС и конфиге. Также попросили добавить транспортные порты в исключения для разрыва соединений на маршрутизаторе. Наблюдаем. Отпишусь

[Denis_Lamanov (Denys Lamanov)]

Как и обещал: всё полечилось. Всем спасибо)