Elasticsearch 7.4 неправильно жалуется, что моментальный снимок уже запущен

После решения Что-то внутри Elasticsearch 7.4 кластер становится все медленнее и медленнее с тайм-аутом чтения время от времени в моем кластере все еще что-то не так. Всякий раз, когда я запускаю команду снимка, она дает мне 503, когда я запускаю ее еще один или два раза, она внезапно запускается и создает снимок. Онлайн-инструмент opster.com предлагает кое-что о том, что моментальные снимки не настраиваются, однако, когда я запускаю предложенную им команду verify, все выглядит нормально.

$ curl -s -X POST 'http://127.0.0.1:9201/_snapshot/elastic_backup/_verify?pretty'
{
  "nodes" : {
    "JZHgYyCKRyiMESiaGlkITA" : {
      "name" : "elastic7-1"
    },
    "jllZ8mmTRQmsh8Sxm8eDYg" : {
      "name" : "elastic7-4"
    },
    "TJJ_eHLIRk6qKq_qRWmd3w" : {
      "name" : "elastic7-3"
    },
    "cI-cn4V3RP65qvE3ZR8MXQ" : {
      "name" : "elastic7-2"
    }
  }
}

Но потом:

curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'
{
  "error" : {
    "root_cause" : [
      {
        "type" : "concurrent_snapshot_execution_exception",
        "reason" : "[elastic_backup:snapshot-2020.11.27]  a snapshot is already running"
      }
    ],
    "type" : "concurrent_snapshot_execution_exception",
    "reason" : "[elastic_backup:snapshot-2020.11.27]  a snapshot is already running"
  },
  "status" : 503
}

Может быть, один из 4 узлов полагает, что моментальный снимок уже запущен, и что эта задача случайным образом назначается одному из узлов, так что при запуске несколько раз в конечном итоге он сделает моментальный снимок? Если да, то как я могу выяснить, какой из узлов сообщает, что моментальный снимок уже запущен?

Кроме того, я заметил, что на одном из узлов куча намного выше, каково нормальное использование кучи?

$ curl -s http://127.0.0.1:9201/_cat/nodes?v
ip         heap.percent ram.percent cpu load_1m load_5m load_15m node.role master name
10.0.1.215           59          99   7    0.38    0.38     0.36 dilm      -      elastic7-1
10.0.1.218           32          99   1    0.02    0.17     0.22 dilm      *      elastic7-4
10.0.1.212           11          99   1    0.04    0.17     0.21 dilm      -      elastic7-3
10.0.1.209           36          99   3    0.42    0.40     0.36 dilm      -      elastic7-2

Прошлой ночью это произошло снова, хотя я уверен, что снимок еще не производился, поэтому теперь я выполнил следующие команды, чтобы подтвердить странный ответ, по крайней мере, я не ожидал получить эту ошибку в этот момент.

$ curl http://127.0.0.1:9201/_snapshot/elastic_backup/_current?pretty
{
  "snapshots" : [ ]
}

$ curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'
{
  "error" : {
    "root_cause" : [
      {
        "type" : "concurrent_snapshot_execution_exception",
        "reason" : "[elastic_backup:snapshot-2020.12.03]  a snapshot is already running"
      }
    ],
    "type" : "concurrent_snapshot_execution_exception",
    "reason" : "[elastic_backup:snapshot-2020.12.03]  a snapshot is already running"
  },
  "status" : 503
}

Когда я запускаю его второй (а иногда и третий) раз, он внезапно создает снимок.

И обратите внимание, что когда я его не запускаю, второй или третий раз моментальный снимок никогда не появится, поэтому я на 100% уверен, что в момент возникновения этой ошибки моментальный снимок не запущен.

Насколько мне известно, SLM не настроен:

{ }

Репо настроено правильно AFAICT:

$ curl http://127.0.0.1:9201/_snapshot/elastic_backup?pretty
{
  "elastic_backup" : {
    "type" : "fs",
    "settings" : {
      "compress" : "true",
      "location" : "elastic_backup"
    }
  }
}

Также в конфигурации он сопоставлен с той же папкой, которая является монтированием NFS Amazon EFS. Он доступен и доступен, а на удачных снимках показывает новые данные.

В рамках задания cron я добавил в запрос _cat/tasks?v, так что, надеюсь, сегодня вечером мы увидим больше. Потому что сейчас, когда я запускал команду вручную, она выполнялась без проблем:

$ curl localhost:9201/_cat/tasks?v ; curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty' ; curl localhost:9201/_cat/tasks?v     
action                         task_id                         parent_task_id                  type      start_time    timestamp running_time ip         node                                                        
cluster:monitor/tasks/lists    JZHgYyCKRyiMESiaGlkITA:15885091 -                               transport 1607068277045 07:51:17  209.6micros  10.0.1.215 elastic7-1                                                  
cluster:monitor/tasks/lists[n] TJJ_eHLIRk6qKq_qRWmd3w:24278976 JZHgYyCKRyiMESiaGlkITA:15885091 transport 1607068277044 07:51:17  62.7micros   10.0.1.212 elastic7-3
cluster:monitor/tasks/lists[n] JZHgYyCKRyiMESiaGlkITA:15885092 JZHgYyCKRyiMESiaGlkITA:15885091 direct    1607068277045 07:51:17  57.4micros   10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] jllZ8mmTRQmsh8Sxm8eDYg:23773565 JZHgYyCKRyiMESiaGlkITA:15885091 transport 1607068277045 07:51:17  84.7micros   10.0.1.218 elastic7-4
cluster:monitor/tasks/lists[n] cI-cn4V3RP65qvE3ZR8MXQ:3418325  JZHgYyCKRyiMESiaGlkITA:15885091 transport 1607068277046 07:51:17  56.9micros   10.0.1.209 elastic7-2                                               
{                                                                                                                                                                  
  "snapshot" : {                                                                                                                                                   
    "snapshot" : "snapshot-2020.12.04",                                                                                                                            
    "uuid" : "u2yQB40sTCa8t9BqXfj_Hg",                                                                                                                                                                          
    "version_id" : 7040099,                                                                                                                                        
    "version" : "7.4.0",                                                                                                                                           
    "indices" : [                                                                                                                                                  
        "log-db-1-2020.06.18-000003",
        "log-db-2-2020.02.19-000002",
        "log-db-1-2019.10.25-000001",
        "log-db-3-2020.11.23-000002",
        "log-db-3-2019.10.25-000001",
        "log-db-2-2019.10.25-000001",
        "log-db-1-2019.10.27-000002"                                                                                                                              
    ],                                                                                                                                                             
    "include_global_state" : true,                                                                                                                                                                              
    "state" : "SUCCESS",                                                                                                                                           
    "start_time" : "2020-12-04T07:51:17.085Z",                                                                                                                                                                  
    "start_time_in_millis" : 1607068277085,                                                                                                                        
    "end_time" : "2020-12-04T07:51:48.537Z",                                                                                                                        
    "end_time_in_millis" : 1607068308537,                                                                                                                                 
    "duration_in_millis" : 31452,                                                                                                                                         
    "failures" : [ ],                                                                                                                                                     
    "shards" : {                                                                                                                                                          
      "total" : 28,                                                                                                                                                       
      "failed" : 0,                                                                                                                                                       
      "successful" : 28                                                                                                                                                   
    }                                                                                                                                                                     
  }                                                                                                                                                                       
}                                                                                                                                                                                                               
action                         task_id                         parent_task_id                  type      start_time    timestamp running_time ip         node                                                     
indices:data/read/search       JZHgYyCKRyiMESiaGlkITA:15888939 -                               transport 1607068308987 07:51:48  2.7ms        10.0.1.215 elastic7-1
cluster:monitor/tasks/lists    JZHgYyCKRyiMESiaGlkITA:15888942 -                               transport 1607068308990 07:51:48  223.2micros  10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] TJJ_eHLIRk6qKq_qRWmd3w:24282763 JZHgYyCKRyiMESiaGlkITA:15888942 transport 1607068308989 07:51:48  61.5micros   10.0.1.212 elastic7-3
cluster:monitor/tasks/lists[n] JZHgYyCKRyiMESiaGlkITA:15888944 JZHgYyCKRyiMESiaGlkITA:15888942 direct    1607068308990 07:51:48  78.2micros   10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] jllZ8mmTRQmsh8Sxm8eDYg:23777841 JZHgYyCKRyiMESiaGlkITA:15888942 transport 1607068308990 07:51:48  63.3micros   10.0.1.218 elastic7-4                                             
cluster:monitor/tasks/lists[n] cI-cn4V3RP65qvE3ZR8MXQ:3422139  JZHgYyCKRyiMESiaGlkITA:15888942 transport 1607068308991 07:51:48  60micros     10.0.1.209 elastic7-2

Вчера вечером (12.12.2020) во время cron я выполнил следующие команды:

curl localhost:9201/_cat/tasks?v
curl localhost:9201/_cat/thread_pool/snapshot?v
curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'
curl localhost:9201/_cat/tasks?v
sleep 1 
curl localhost:9201/_cat/thread_pool/snapshot?v
curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'
sleep 1
curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'
sleep 1
curl -s -X PUT 'http://127.0.0.1:9201/_snapshot/elastic_backup/%3Csnapshot-%7Bnow%2Fd%7D%3E?wait_for_completion=true&pretty'

И вывод для него следующий:

action                         task_id                         parent_task_id                  type      start_time    timestamp running_time ip         node
cluster:monitor/tasks/lists    JZHgYyCKRyiMESiaGlkITA:78016838 -                               transport 1607736001255 01:20:01  314.4micros  10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] TJJ_eHLIRk6qKq_qRWmd3w:82228580 JZHgYyCKRyiMESiaGlkITA:78016838 transport 1607736001254 01:20:01  66micros     10.0.1.212 elastic7-3
cluster:monitor/tasks/lists[n] jllZ8mmTRQmsh8Sxm8eDYg:55806094 JZHgYyCKRyiMESiaGlkITA:78016838 transport 1607736001255 01:20:01  74micros     10.0.1.218 elastic7-4
cluster:monitor/tasks/lists[n] JZHgYyCKRyiMESiaGlkITA:78016839 JZHgYyCKRyiMESiaGlkITA:78016838 direct    1607736001255 01:20:01  94.3micros   10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] cI-cn4V3RP65qvE3ZR8MXQ:63582174 JZHgYyCKRyiMESiaGlkITA:78016838 transport 1607736001255 01:20:01  73.6micros   10.0.1.209 elastic7-2
node_name  name     active queue rejected
elastic7-2 snapshot      0     0        0
elastic7-4 snapshot      0     0        0
elastic7-1 snapshot      0     0        0
elastic7-3 snapshot      0     0        0
{            
  "error" : {       
    "root_cause" : [
      {                                            
        "type" : "concurrent_snapshot_execution_exception",                                                                                      
        "reason" : "[elastic_backup:snapshot-2020.12.12]  a snapshot is already running"
      }
    ],                                         
    "type" : "concurrent_snapshot_execution_exception",                                                                                      
    "reason" : "[elastic_backup:snapshot-2020.12.12]  a snapshot is already running"
  },            
  "status" : 503
}
action                         task_id                         parent_task_id                  type      start_time    timestamp running_time ip         node
cluster:monitor/nodes/stats    JZHgYyCKRyiMESiaGlkITA:78016874 -                               transport 1607736001632 01:20:01  39.6ms       10.0.1.215 elastic7-1
cluster:monitor/nodes/stats[n] TJJ_eHLIRk6qKq_qRWmd3w:82228603 JZHgYyCKRyiMESiaGlkITA:78016874 transport 1607736001631 01:20:01  39.2ms       10.0.1.212 elastic7-3
cluster:monitor/nodes/stats[n] jllZ8mmTRQmsh8Sxm8eDYg:55806114 JZHgYyCKRyiMESiaGlkITA:78016874 transport 1607736001632 01:20:01  39.5ms       10.0.1.218 elastic7-4
cluster:monitor/nodes/stats[n] cI-cn4V3RP65qvE3ZR8MXQ:63582204 JZHgYyCKRyiMESiaGlkITA:78016874 transport 1607736001632 01:20:01  39.4ms       10.0.1.209 elastic7-2
cluster:monitor/nodes/stats[n] JZHgYyCKRyiMESiaGlkITA:78016875 JZHgYyCKRyiMESiaGlkITA:78016874 direct    1607736001632 01:20:01  39.5ms       10.0.1.215 elastic7-1
cluster:monitor/tasks/lists    JZHgYyCKRyiMESiaGlkITA:78016880 -                               transport 1607736001671 01:20:01  348.9micros  10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] JZHgYyCKRyiMESiaGlkITA:78016881 JZHgYyCKRyiMESiaGlkITA:78016880 direct    1607736001671 01:20:01  188.6micros  10.0.1.215 elastic7-1
cluster:monitor/tasks/lists[n] TJJ_eHLIRk6qKq_qRWmd3w:82228608 JZHgYyCKRyiMESiaGlkITA:78016880 transport 1607736001671 01:20:01  106.2micros  10.0.1.212 elastic7-3
cluster:monitor/tasks/lists[n] cI-cn4V3RP65qvE3ZR8MXQ:63582209 JZHgYyCKRyiMESiaGlkITA:78016880 transport 1607736001672 01:20:01  96.3micros   10.0.1.209 elastic7-2
cluster:monitor/tasks/lists[n] jllZ8mmTRQmsh8Sxm8eDYg:55806120 JZHgYyCKRyiMESiaGlkITA:78016880 transport 1607736001672 01:20:01  97.8micros   10.0.1.218 elastic7-4
node_name  name     active queue rejected
elastic7-2 snapshot      0     0        0
elastic7-4 snapshot      0     0        0
elastic7-1 snapshot      0     0        0
elastic7-3 snapshot      0     0        0
{
  "snapshot" : {
    "snapshot" : "snapshot-2020.12.12",
    "uuid" : "DgwuBxC7SWirjyVlFxBnng",
    "version_id" : 7040099,
    "version" : "7.4.0",
    "indices" : [
      "log-db-sbr-2020.06.18-000003",
      "log-db-other-2020.02.19-000002",
      "log-db-sbr-2019.10.25-000001",
      "log-db-trace-2020.11.23-000002",
      "log-db-trace-2019.10.25-000001",
      "log-db-sbr-2019.10.27-000002",
      "log-db-other-2019.10.25-000001"
    ],
    "include_global_state" : true,
    "state" : "SUCCESS",
    "start_time" : "2020-12-12T01:20:02.544Z",
    "start_time_in_millis" : 1607736002544,
    "end_time" : "2020-12-12T01:20:27.776Z",
    "end_time_in_millis" : 1607736027776,
    "duration_in_millis" : 25232,
    "failures" : [ ],
    "shards" : {
      "total" : 28,
      "failed" : 0,
      "successful" : 28
    }
  }
}
{
  "error" : {
    "root_cause" : [
      {
        "type" : "invalid_snapshot_name_exception",
        "reason" : "[elastic_backup:snapshot-2020.12.12] Invalid snapshot name [snapshot-2020.12.12], snapshot with the same name already exists"
      }
    ],
    "type" : "invalid_snapshot_name_exception",
    "reason" : "[elastic_backup:snapshot-2020.12.12] Invalid snapshot name [snapshot-2020.12.12], snapshot with the same name already exists"
  },
  "status" : 400
}
{
  "error" : {
    "root_cause" : [
      {
        "type" : "invalid_snapshot_name_exception",
        "reason" : "[elastic_backup:snapshot-2020.12.12] Invalid snapshot name [snapshot-2020.12.12], snapshot with the same name already exists"
      }
    ],
    "type" : "invalid_snapshot_name_exception",
    "reason" : "[elastic_backup:snapshot-2020.12.12] Invalid snapshot name [snapshot-2020.12.12], snapshot with the same name already exists"
  },
  "status" : 400
}

Также кластер сейчас зеленый, очереди управления не заполнены, вроде все хорошо.

Также есть только один репозиторий:

curl http://127.0.0.1:9201/_cat/repositories?v
id             type
elastic_backup   fs

elasticsearch-7

Lourens Rozema 27.11.2020 источник

comment

Что инструмент Opster говорит о something about snapshots not being configured? - Val 04.12.2020

comment

Кроме того, поскольку это, кажется, происходит регулярно, можете ли вы запустить _cat/tasks?v в следующий раз и вставить результат в свой вопрос? - Val 04.12.2020

comment

Другая идея может заключаться в том, что ваш снимок конфликтует с управлением жизненным циклом снимков (SLM). Можете ли вы показать нам, что вы получаете, работая GET /_slm/policy/? - Val 04.12.2020

comment

Спасибо @Val, я добавил дополнительную информацию в свой пост, и инструмент Opster ничего не говорит о настраиваемых снимках, он говорит только четыре вещи: подкачка памяти включена, а для параметра bootstrap.memory_lock установлено значение false (что неуместно Я думаю, поскольку на наших серверах нет свопа), рекомендуется добавить выделенные главные узлы, настройки Zen Discovery настроены, но не используются, Путь к данным установлен по умолчанию (также неактуально для нас, так как мы запускаем Elastic с помощью Docker и так что фактически наши данные уже хранятся в другой папке). - Lourens Rozema 04.12.2020

comment

Отлично, спасибо, дайте нам знать, как только у вас появится больше информации через несколько часов. - Val 04.12.2020

comment

@Val результаты есть, и я добавил их в сообщение выше. - Lourens Rozema 05.12.2020

comment

Может быть, сообщение об ошибке просто неправильное и происходит что-то еще? Возможно, что-то еще вызывает ошибку «503» и неправильно переведено в сообщение «моментальный снимок уже запущен», а вместо этого должно быть написано «не удалось начать создание снимка по какой-либо другой причине»? - Lourens Rozema 05.12.2020

comment

Можете ли вы также запустить это непосредственно перед запуском нового снимка: GET _cat/thread_pool/snapshot?v и вставить результат? - Val 08.12.2020

comment

Можете ли вы проверить, есть ли что-то подобное non-failed nodes do not form a quorum в ваших журналах, когда вы пытаетесь создать моментальный снимок? Если это так, ваша проблема может быть вызвана нестабильным кластером ... - Val 09.12.2020

comment

Спасибо @Val, я не уверен, происходит ли это при создании снимка, но я вижу, что Причина: org.elasticsearch.cluster.coordination.FailedToCommitClusterStateException: исправные узлы время от времени не образуют кворум. Так что я думаю, это то, на что стоит обратить внимание. Также сегодня вечером я запишу вывод _cat / thread_pool / snapshot. - Lourens Rozema 09.12.2020

comment

Посмотрите прямо перед этой ошибкой, и вы можете увидеть проблему со снимком из-за этого ... Также я думаю, что эта проблема является лишь одним из симптомов гораздо более серьезной проблемы. - Val 09.12.2020

Ответы (2)

arrow_upward
1
arrow_downward

Итак, выяснилось, что проблема началась из-за недавнего обновления до Docker 19.03.6 и перехода от 1x Docker Swarm manager + 4x Docker Swarm worker к 5x Docker Swarm manager + 4x Docker Swarm worker. В обоих случаях Elastic наезжал на рабочих. Из-за этого обновления / изменения нам было представлено изменение количества сетевых интерфейсов внутри контейнеров. Из-за этого нам пришлось использовать publish_host в Elastic, чтобы все снова заработало.

Чтобы решить эту проблему, нам пришлось избавиться от публикации эластичных портов во входящей сети, так что дополнительные сетевые интерфейсы исчезли. Затем мы можем отказаться от параметра publish_host. Это немного улучшило работу. Но чтобы действительно решить наши проблемы, нам пришлось изменить Docker Swarm deploy endpoint_mode на dnsrr, чтобы все не проходило через сетку маршрутизации Docker Swarm.

У нас всегда были проблемы «Сброс соединения одноранговым узлом», но после изменения ситуация ухудшилась, и в Elasticsearch возникли странные проблемы. Я предполагаю, что запуск Elasticsearch внутри Docker Swarm (или любого другого Kubernetes или чего-то еще) может быть сложной задачей для отладки.

Используя tcpdump в контейнерах и conntrack -S на хостах, мы смогли увидеть, как без всякой причины сбрасываются безупречные соединения. Другое решение заключалось в том, чтобы ядро отбрасывало несовпадающие пакеты (вместо отправки сброса), но предотвращение использования DNAT / SNAT в этом случае, насколько это возможно, тоже решало проблему.

Lourens Rozema 14.12.2020

comment

Отлично, рад, что ты в этом разобрался :) - user156327; 14.12.2020

arrow_upward
0
arrow_downward

Elasticsearch версии 7.4 поддерживает только одну операцию создания снимков за раз.

Из-за ошибки кажется, что ранее запущенный моментальный снимок уже был запущен, когда вы запустили новый моментальный снимок, и Elasticsearch выдает concurrent_snapshot_execution_exception.

Вы можете проверить список текущих снимков. с помощью GET /_snapshot/elastic_backup/_current.

Я предлагаю вам сначала проверить, выполняется ли какая-либо операция создания снимка для вашего кластера elasticsearch, используя указанный выше api. Если в данный момент не выполняется никаких операций создания снимков, запускать новый снимок следует только вам.

P.S: Начиная с версии Elasticsearch 7.7, elasticsearch также поддерживает одновременные снимки. Поэтому, если вы планируете выполнять в кластере одновременную операцию создания моментальных снимков, вам следует обновить ES версии 7.7 или выше.

piyush daftary 30.11.2020

comment

Я уверен, что ни один снимок еще не запущен, я добавил вывод _current в свой пост, он пуст. - Lourens Rozema; 03.12.2020

comment

у вас есть несколько репозиториев моментальных снимков, настроенных для кластера? Вы можете поделиться выводом /_cat/repositories?v&pretty - piyush daftary; 11.12.2020

comment

Добавлен вывод в моем сообщении выше, есть только один репозиторий. - Lourens Rozema; 12.12.2020

comment

Теперь вы можете проверить, не застряло ли удаление снимка. Найдите запись snapshot_deletions в /_cluster/state?pretty - piyush daftary; 13.12.2020

comment

Пустой список, но оказалось, что из-за сброса соединения из-за ошибок одноранговых узлов, вызванных ошибками DNAT / SNAT в конфигурации сети Docker Swarm, кластер вел себя некорректно. - Lourens Rozema; 14.12.2020

Elasticsearch 7.4 неправильно жалуется, что моментальный снимок уже запущен

Ответы (2)

Вопросы по теме