Logstash の conf ファイルをリグレッションテストする

こんにちは。アキバです。

この記事は、 Elastic Stack (Elasticsearch) Advent Calendar 2019 の14日目です。
qiita.com

今年の8月にElastic Certified Engineerになることができました。
ということで、今年の Advent Calendar は Elastic Stack のカレンダーにお邪魔します。

構築したシステムの「正しさ」

突然ですが、Elastic Stackを使って構築する／したシステムの「正しさ」を検証していますか？
きちんと検証できていないと、インフラ／ミドルウェアの障害は影響も大きく、問題になりがちです。

そもそも、「正しさ」を検証するべき箇所は何があるでしょうか？

一つは、「設定の正しさ」があるでしょう。

OS環境
Elasticsearchのパラメータ（elasticsearch.ymlの記載や _settings API など）
Index Mapping

など。

これらについては、静的なファイルチェックに加えて、構築後の環境に対する Serverspecや、Karateを使ったAPIテストなどが有効そうです。

※Karateを使ったAPIテストについては、以前にshin0higuchiが書いた以下の記事も見てください
acro-engineer.hatenablog.com

もう一つは、「ロジックの正しさ」がありますね。

JavaやPythonなど、Elasticsearchを使うアプリケーションのロジックはユニットテストをすることを考えますが、Logstashのconfはどうでしょうか？

書いてみたことがある方は分かると思いますが、Logstashのconf（つまりパイプライン）は、れっきとしたロジックであると言えます。
すなわち、入力（input）があり、処理（filter）があり、出力（output）があり、filter部分にロジックがあるわけです。

今回は、この「Logstash conf （の filter）をテストする」ことを考えてみたいと思います。

logstash-test-runner

Logstash の conf それ自体は、定義ファイルのような形で作成・デプロイするので、このファイルを単体で試験しようとする人は多くないようです。

しかしながら、少し検索してみたら、以下のような、node.js ベースのTest Runnerを作っている方がいました。

github.com

原理はシンプルで、以下の３種類

入力となるログデータ
テストしたいconfファイル
出力として期待する正解データ

を１セットとして用意すると、実際に 2. の conf を実行して得られたデータと 3. の正解データを比較して合否を判定してくれるというものです。

Logstashの実行は、Elastic社の純正Dockerイメージを取得して行うため、実行環境にあらかじめLogstashをインストールしておく必要はありませんし、バージョンの切り替えも簡単に行えます。

テストの仕組みとしては手軽で面白そうです。これを実際に使ってみましょう。

環境の準備

実行する環境は、Linux（bash シェルスクリプトが動作する環境）にします。

今回は、Azure上にVM（OSはUbuntu 18.04.3 LTS）を立てましたが、以下の要件を満たせるLinux環境を作れるなら、オンプレでも問題ないと思います。

※logstash-test-runner のページから抜粋

NodeJS > v8
Docker
Bash > v4

なお、前述の通り、ツール動作時にElastic社のDockerイメージを取得するため、インターネットに接続できる環境にしてください。

今回、私が構築した環境は以下の通りです。
本当は、node.jsはv11とかを入れておくべきなのでしょうけれども、手抜きで済ませております。

$ node -v
v8.10.0

$ docker -v
Docker version 19.03.5, build 633a0ea838

$ bash --version
GNU bash, version 4.4.20(1)-release (x86_64-pc-linux-gnu)

早速動かしてみる

まずは、git を使って、テストツールをクローンします。

$ git clone https://github.com/agolo/logstash-test-runner.git
$ cd logstash-test-runner

デフォルトで用意されているテスト（__tests__）を実行してみます。

テストは、test.sh というスクリプトから実行します。（お試しで作ったスクリプトではありません）
test.shの第１引数にディレクトリを指定すると、その配下のディレクトリをテストケースとして認識するようです。

今回の環境では、dockerコマンドはrootで実行する必要があるため、test.shもsudoをつけて実行します。

また、実行の際には、明示的にbashで実行する必要がありました。（この点はディストリビューションにもよるでしょう）

$ sudo bash test.sh __tests__

f:id:acro-engineer:20191215070512p:plain

通りました。簡単ですね！
初回はDockerイメージを取得するのに少々時間がかかりますが、2回目以降は各テスト30～60秒で通ります。
（テストにかかる時間の半分ぐらいは、Logstashの起動時間ですが）

Logstashのバージョン指定

デフォルトではlogstashのバージョンが5.5.1なのですが、第2引数を指定することで変えることができます。

せっかくなので、最新バージョンである7.5で試してみましょう。

$ sudo bash test.sh __tests__ docker.elastic.co/logstash/logstash:7.5.0

f:id:acro-engineer:20191215070515p:plain

おや、mongoのテストが失敗しました。
差分が出ると、上記のような diff結果が表示されます。

どこから失敗するようになるのでしょうか？

ということで、それぞれのバージョンで試してみました。
（これがコマンドラインオプションだけで試せるのはとても便利ですね）

バージョン	結果
5.5.1	成功
6.0.0	成功
6.5.0	成功
6.8.0	成功
7.0.0	失敗
7.5.0	失敗

上の結果から、6.x → 7.0 にバージョンアップするときに Logstash の動作仕様が変わったということがわかります。

差分を修正する

前述の差分は、よく見ると mongo テストの出力データの先頭2行が入れ替わっていることがわかります。

本来は、「なぜ入れ替わったのか」の原因を特定し、Logstash conf を修正するなどして解決するべきですが、
今回の入れ替わりがなぜ発生するのかは、少し調べてみただけではわかりませんでした。

ということで、（本来は良くない対処ですが）正解データを修正して、テストが通るようになるか試してみましょう。

mongo テストの正解データは、 __tests__/mongo/output.log です
これを開いて編集します。

{"conn_type":"COMMAND","querytime_ms":109,"@message":"command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command","@timestamp":"2017-08-24T18:16:02.110Z","mongo_message":"command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command","loglevel":"I","@version":"1","host":"testing_host","context":"conn88987","message":"2017-08-24T18:16:02.110+0000 I COMMAND  [conn88987] command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 109ms","tags":["_jsonparsefailure"],"timestamp":"2017-08-24T18:16:02.110+0000"}
{"conn_type":"ASIO","message":"2017-08-24T21:55:01.204+0000 I ASIO     [NetworkInterfaceASIO-ShardRegistry-0] Successfully connected to mydatabase.com:27019, took 66ms (1 connections now open to mydatabase.com:27019)","tags":["_jsonparsefailure"],"querytime_ms":66,"@message":"Successfully connected to mydatabase.com:27019, took (1 connections now open to mydatabase.com:27019)","@timestamp":"2017-08-24T21:55:01.204Z","mongo_message":"Successfully connected to mydatabase.com:27019, took (1 connections now open to mydatabase.com:27019)","loglevel":"I","@version":"1","host":"testing_host","context":"NetworkInterfaceASIO-ShardRegistry-0","timestamp":"2017-08-24T21:55:01.204+0000","mongo_message2":" (1 connections now open to mydatabase.com:27019)"}
{"conn_type":"NETWORK","@message":"received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","@timestamp":"2017-08-24T22:01:36.933Z","mongo_message":"received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","loglevel":"I","@version":"1","host":"testing_host","context":"conn99615","message":"2017-08-24T22:01:36.933+0000 I NETWORK  [conn99615] received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","tags":["_jsonparsefailure"],"timestamp":"2017-08-24T22:01:36.933+0000"}

これを、以下のように変えます。（つまり、COMMAND と ASIO の2行を入れ替えただけです）

{"conn_type":"ASIO","message":"2017-08-24T21:55:01.204+0000 I ASIO     [NetworkInterfaceASIO-ShardRegistry-0] Successfully connected to mydatabase.com:27019, took 66ms (1 connections now open to mydatabase.com:27019)","tags":["_jsonparsefailure"],"querytime_ms":66,"@message":"Successfully connected to mydatabase.com:27019, took (1 connections now open to mydatabase.com:27019)","@timestamp":"2017-08-24T21:55:01.204Z","mongo_message":"Successfully connected to mydatabase.com:27019, took (1 connections now open to mydatabase.com:27019)","loglevel":"I","@version":"1","host":"testing_host","context":"NetworkInterfaceASIO-ShardRegistry-0","timestamp":"2017-08-24T21:55:01.204+0000","mongo_message2":" (1 connections now open to mydatabase.com:27019)"}
{"conn_type":"COMMAND","querytime_ms":109,"@message":"command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command","@timestamp":"2017-08-24T18:16:02.110Z","mongo_message":"command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command","loglevel":"I","@version":"1","host":"testing_host","context":"conn88987","message":"2017-08-24T18:16:02.110+0000 I COMMAND  [conn88987] command production.feeds command: find { find: \"feeds\", filter: { _id: \"abcdefg\" }, limit: 1, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:2031 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 108897 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 109ms","tags":["_jsonparsefailure"],"timestamp":"2017-08-24T18:16:02.110+0000"}
{"conn_type":"NETWORK","@message":"received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","@timestamp":"2017-08-24T22:01:36.933Z","mongo_message":"received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","loglevel":"I","@version":"1","host":"testing_host","context":"conn99615","message":"2017-08-24T22:01:36.933+0000 I NETWORK  [conn99615] received client metadata from 40.70.67.250:43270 conn99615: { driver: { name: \"NetworkInterfaceASIO-TaskExecutorPool-1\", version: \"3.4.7\" }, os: { type: \"Linux\", name: \"Ubuntu\", architecture: \"x86_64\", version: \"16.04\" } }","tags":["_jsonparsefailure"],"timestamp":"2017-08-24T22:01:36.933+0000"}

これで、もう一度実行してみましょう。

$ sudo bash test.sh __tests__ docker.elastic.co/logstash/logstash:7.5.0

f:id:acro-engineer:20191215070519p:plain

成功するようになりました。

まとめ

logstash-test-runner を用いることで、conf ファイルをリグレッションテストする仕組みが比較的簡単に作れることがわかりました。

このツールは、ツール出力を正解データと差分比較することで合否判定をするため、正解データを予め用意しておくことが必要になります。
通常、Logstashの出力で正解データを手動で作成して用意することは現実的ではありませんので、「一回実行してうまくいったログ」を正解データとして使用することになるでしょう。

そういった意味で、このツールは「リグレッションテスト」用途に向いていると言えるでしょう。
それでも、Logstash の conf に対して、変更による破壊が起きていないかを早い段階で見つけられるようになるので、安心感が得られると思いました。

さて、そうすると、CIを回したくなりますね。
このツールの結果をJenkinsなどでレポート表示するには、多少解析する必要がありそうです。

この辺りの仕組みが作れないか、いずれ検討してみたいと思います。

では。

Acroquest Technologyでは、キャリア採用を行っています。

ディープラーニング等を使った自然言語／画像／音声／動画解析の研究開発

Elasticsearch等を使ったデータ収集／分析／可視化

マイクロサービス、DevOps、最新のOSSを利用する開発プロジェクト

書籍・雑誌等の執筆や、社内外での技術の発信・共有によるエンジニアとしての成長

　
少しでも上記に興味を持たれた方は、是非以下のページをご覧ください。
世界初のElastic認定エンジニアと一緒に働きたい人Wanted！ - Acroquest Technology株式会社のエンジニアの求人 - Wantedlywww.wantedly.com