杀死集群的IngestNode和Grok

2 年 ago
宇, 华
2 minutes

这篇文章是2018年Elastic stack（Elasticsearch）圣诞日历的第八天的文章。

首先

你好，我叫tshohe。

Elasticsearch是一种非常重要的软件，经常在日志和度量的收集与可视化中使用。在本文中，我想深入研究我今年遇到的Elasticsearch集群停止故障情况。

环境

    • Elasticsearch6.1.1 + Filebeat6.1.1(PostgreSQL Module)

 

    各ノードはmaster/data/ingestを兼任

我今年年初开始使用PostgreSQL10，当时pg_stats_reporter还没有配套，我在考虑如何进行监控。正好在那个时候，Beats新增了PostgreSQL模块，所以我决定试用一下。

Filebeat 的 PostgreSQL 模块在当时仍处于实验性阶段，但它只是通过 Filebeat 将日志转发并在 IngestNode 的 Pipeline（Grok）中进行处理，所以我并没有太担心会发生什么奇怪的事情。（自负责任…）
※ 现在似乎已经正式取消了实验性质
https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-module-postgresql.html

有一天，当我看到配备了可视化/仪表盘的时候，我觉得它可以很好地进行可视化，感觉很不错。然而，发生了一场悲剧。

我突然陷入了这样的困境…!

    • write処理が溜まってキューが枯渇

 

    • リクエストがrejectされまくりDocumentが全く追加されない状態

 

    リクエストを受けるノードのCPU使用率（user）が100%に張り付き
image.png

发生了什么事？

在停止各种日志传输的同时，我们发现问题的原因是由filebeat添加的名为”filebeat-6.1.1-postgresql-log-pipeline”的Pipeline。
这个Pipeline的grok processor在处理特定日志时花费了很长时间，导致队列堵塞。

让我们来看一下导致问题的Grok设置。

Filebeat-6.1.1-postgresql-log-pipeline是一个链接到GitHub上的文件，它包含了一个路径为filebeat/module/postgresql/log/ingest/pipeline.json的文件的引用，我们可以从这个文件的第18行中找到所需信息。

      "grok": {
        "field": "message",
        "ignore_missing": true,
        "patterns": [
          "%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] %{USERNAME:postgresql.log.user}@%{HOSTNAME:postgresql.log.database} %{WORD:postgresql.log.level}:  duration: %{NUMBER:postgresql.log.duration} ms  statement: %{MULTILINEQUERY:postgresql.log.query}",
          "%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] \\[%{USERNAME:postgresql.log.user}\\]@\\[%{HOSTNAME:postgresql.log.database}\\] %{WORD:postgresql.log.level}:  duration: %{NUMBER:postgresql.log.duration} ms  statement: %{MULTILINEQUERY:postgresql.log.query}",
          "%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] %{USERNAME:postgresql.log.user}@%{HOSTNAME:postgresql.log.database} %{WORD:postgresql.log.level}:  ?%{GREEDYDATA:postgresql.log.message}",
          "%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] \\[%{USERNAME:postgresql.log.user}\\]@\\[%{HOSTNAME:postgresql.log.database}\\] %{WORD:postgresql.log.level}:  ?%{GREEDYDATA:postgresql.log.message}",
          "%{LOCALDATETIME:postgresql.log.timestamp} %{WORD:postgresql.log.timezone} \\[%{NUMBER:postgresql.log.thread_id}\\] %{WORD:postgresql.log.level}:  ?%{GREEDYDATA:postgresql.log.message}"
        ],
        "pattern_definitions": {
          "LOCALDATETIME": "[-0-9]+ %{TIME}",
          "GREEDYDATA": ".*",
          "MULTILINEQUERY" : "(.|\n|\t)*?;$"
        }
      }

如果MULTILINEQUERY不匹配，则使用GREEDYDATA进行处理。

顺便提一下，这个正则表达式已经不太好，已经被修改成了以下的样式。

6.5.1版本的Elastic Beats的filebeat模块中的postgresql/log/ingest/pipeline.json文件，可以在以下链接找到：
https://github.com/elastic/beats/blob/v6.5.1/filebeat/module/postgresql/log/ingest/pipeline.json

-          "GREEDYDATA": ".*",
-          "MULTILINEQUERY" : "(.|\n|\t)*?;$",
+          "GREEDYDATA": "(.|\n|\t)*",

让我们检查一下，MULTILINEQUERY和GREEDYDATA这两个表达式是否需要以分号结束，并且找出正则表达式(.*)?;$的不正常之处。

由于不是org.joni.Regex，所以准确的操作可能会有所不同，但我们可以在一个能够简单跟踪步骤的网站（https://regex101.com）上进行确认。

如果假设在MULTILINEQUERY的地方输入的查询是以下这种情况的话…

select a.b,
                   a,
                   b,
                   c,
                   d
              from t1
              join t3
                on a = a
               and b = b
             where aaaaaaaaa between '2018-12-07 00:00:00' and '2018-12-08 00:00:00'
            union all
            select a.b,
                   a,
                   b,
                   c,
                   d
              from t2
              join t4
                on a = a
               and b = b
             where bbbbbbbb between '2018-12-07 00:00:00' and '2018-12-08 00:00:00';

大约需要1788步处理（耗时187毫秒）。

由于对任何文本的后面进行了”;”的检查，所以与普通的GREEDYDATA相比，步骤数似乎更多。
然而，真正糟糕的是当后面出现意外的字符串时。

这次问题涉及的日志是指当PostgreSQL的log_min_duration_statement超过设定时间时输出的慢查询日志，因此查询会被直接输出。因此可能会在下面的注释中提到。

...
             where bbbbbbbb between '2018-12-07 00:00:00' and '2018-12-08 00:00:00'; -- hogehoge piyopiyo

一下子踏出的步数飚升至934,154步（1.06秒）。

由于字符数量的增加，步数会急剧增加，所以如果SQL语句的缩进和空格有很多的话会出大问题。（就像这个PostgreSQL的例子中的慢查询一样，非常长…）

    • .*があることでバックトラックが発生（最大限マッチするパターンを探すため）

 

    ;で終わっていればよいが、終わっていないと1~n文字目の地点から開始した場合の文字列全てのパターンを確認するのでとんでもない計算量になる

总结

只要输入像hogehogepiyopiyoA hogehogepiyopiyo……这样的数据到定义了类似于 (.*)A$ 的grok模式的地方，就可以给集群带来巨大负荷，甚至导致集群崩溃。

刚刚在讨论Elasticsearch，或者说是正则表达式的问题。。。

教训切勿忽视

    1. 应该写入能够容忍日志的混乱的程度。

当将Pipeline或Grok设置专门用于特定字符串时，对于意外值的行为是不可预料的，这令人担忧。应该在测试环境中检查各种模式。

应该将IngestNode与MasterNode/DataNode分离。

至少应该能够进行搜索。但只有这样的话，IngestNode的优点就消失了，就算没有Fluentd/Logstash，也可以插入处理。

✖
广告
将在 10 秒后关闭
bannerAds