LogstashとFilebeatでIISログをあれこれしてみた話 #AWS

この記事はElastic Stack (Elasticsearch) Advent Calendar 2019の22日目の記事です。
21日目は@yukata_unoさんによる「Elastic Machine Learningの歴史を振り返る」でした。

はじめに

先日、知人より下記のご相談を頂きまして、この機会に技術検証してみることにしました^^

AWS環境上のIISサーバのアクセスログを使って
リアルタイムログ監視をやりたいけど、Elasticsearchで宜しくやれないの！？

ということで、、
IISサーバのアクセスログをLogstashとFilebeatを使って、どんな構成が最適か追求してみました。

余談ですが、LogstashとFilebeatは「どちらが良いの？」という質問をよく頂きます。
この記事を通して、vsモードではなく、補完関係にあることもお伝えできればと思います！！

利用環境

product	version
Filebeat	6.5.4
logstash	6.5.4
Elasticsearch	6.5.4
kibana	6.5.4
Java	1.8.0
IIS	10.0.14293.0
EC2 (IIS)	Windows Server 2016 (t3.medium)
AMI ID (IIS)	ami-03efee33577540873
EC2 (ES)	Amazon Linux 2 (t3.large)
AMI ID (ES)	ami-00068cd7555f543d5
AWS Region	us-east-1

※ Elastic Stackのバージョンは少し古いです。(持ち合わせていたAmazon ESのバージョンが6.5.4であったため)
※ AWSのリージョンは料金の安いバージニアで構築しています。

構成図

IISサーバをEC2で構築し、ALB配下に配置しています。(ログ監視にX-Forwarded-forヘッダを利用するため)
IISのアクセスログをAmazon ESに転送するため、LogstashとFilebeatを両方とも導入しています。
Amazon ESのAlerting機能を用いて、Slack経由でシステム管理者に通知が行くようにしています。
EC2で構築したElastic Stackサーバは構築途中で切り分けに利用した環境となっています。

前提として

本記事ではIISサーバやElastic Stackのインストール手順は省力しています。

【参考】
・IISのインストール
・Logstashインストール方法(Linux版)
・Logstashインストール方法(Windows版)
・Filebeatインストール方法
・Elasticsearchインストール方法
・Kibanaインストール方法

検証内容

Elastic Stackの構成を決める上で、以下の内容について今回検証しました。

　1. IISアクセスログのパース処理 (LogstashとFilebeat module)
　2. LogstashとFilebeatのWindowsサーバに与えるCPU負荷
　3. End-to-Endでのデータパイプラインの構築

実施手順

以下の手順で検証を実施します。

　1. IISサーバのログ出力設定
　2. Logstashのログ取得設定とその結果
　3. Filebeat Moduleによるログ取得設定とその結果
　4. FilebeatからLogstash経由でAmazon ESに格納

1. IISサーバのログ出力設定

WindowsサーバでIISマネージャーを起動し、[ホーム画面] > [IIS] >ログ記録で機能を開きます。
ログの形式はW3C、ログファイルの保存先ディレクトリはデフォルトのままとします。
上記画面でフィールドの選択を開くとこの画面が開きます。
ここでアクセスログに出力するフィールドを指定します。
以下、IISアクセスログに関するログ情報一覧になります。(設定値は今回の検証における設定になります)

#	フィールド名(論理)	フィールド名(物理)	デフォルト値	設定値	種別	データ型
1	日付	date	有効	有効	標準	Date
2	時間	time	有効	有効	標準	Date
3	クライアントIPアドレス	c-ip	有効	有効	標準	IP
4	ユーザー名	cs-username	有効	有効	標準	Keyword
5	サービス名	s-sitename	無効	有効	標準	Keyword
6	サーバー名	s-computename	無効	有効	標準	Keyword
7	サーバーIPアドレス	s-ip	有効	有効	標準	IP
8	サーバーポート	s-port	有効	有効	標準	Keyword
9	メソッド	cs-method	有効	有効	標準	Keyword
10	URIステム	cs-uri-stem	有効	有効	標準	Keyword
11	URIクエリ	cs-uri-query	有効	有効	標準	Keyword
12	プロトコルの状態	sc-status	有効	有効	標準	Keyword
13	プロトコルの副状態	sc-substatus	有効	有効	標準	Keyword
14	Win32の状態	sc-win32-status	有効	有効	標準	Keyword
15	送信バイト数	sc-bytes	無効	有効	標準	Float
16	受信バイト数	cs-bytes	無効	有効	標準	Float
17	所要時間	time-taken	有効	有効	標準	Float
18	プロトコルバージョン	cs-version	無効	有効	標準	Keyword
19	ホスト	cs-host	無効	有効	標準	Keyword
20	ユーザーエージェント	cs(User-Agent)	有効	有効	標準	Keyword
21	Cookie	cs(Cookie)	無効	有効	標準	Keyword
22	参照者	cs(Referer)	有効	有効	標準	Keyword
23	X-Forwared-For	X-Forwared-For	無効	有効	カスタム	IP

今回は全てのフィールドをログに利用するように設定します。
またカスタムフィールドとしてX-Forwarded-Forを出力設定します。

※ 1行1件のログを出力します。以下のフィールド順で各フィールド間はスペース区切りのTSV形式になります。

ログのフォーマット

date time s-sitename s-computername s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs-version cs(User-Agent) cs(Cookie) cs(Referer) cs-host sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken X-Forwarded-For

サンプルログ

2019-11-10 14:48:35 W3SVC1 EC2AMAZ-1D0KC7E 172.31.90.5 GET /favicon.ico - 80 - 172.31.6.170 HTTP/1.1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/78.0.3904.87+Safari/537.36 - http://iis-212063043.us-east-1.elb.amazonaws.com/ iis-212063043.us-east-1.elb.amazonaws.com 404 0 2 1383 583 0 17.7.42.220

【参考】
・X-Forwarded-Forフィールド追加方法

2. Logstashのログ取得設定とその結果

公式HPからZIPダウンロード後、解凍したLogstash-6.5.4フォルダを以下のディレクトリに配置します。(コンフィグファイルは、iislog.cfgというファイルとしています。)

※ C:\Program Files配下にフォルダを配置したら、エラーが出たため、C:直下に配置してます。

logstash.conf(今回はiislog.cfgという名前)の内容は以下のように設定します。

iislog.cfg

input {
# input from iis accesslog
  file{
    path=> ["C:/inetpub/logs/LogFiles/W3SVC1/*"]
    start_position => "beginning"
  }
}

filter {
  # skip header
  if "^#" in [message] {
    drop {}
  }
  dissect {
  # log format is TSV
    mapping => {
      "message" => "%{ts} %{+ts} %{s-sitename} %{s-computername} %{s-ip} %{cs-method} %{cs-uri-stem} %{cs-uri-query} %{s-port} %{cs-username} %{c-ip} %{cs-version} %{cs(User-Agent)} %{cs(Cookie)} %{cs(Referer)} %{cs-host} %{sc-status} %{sc-substatus} %{sc-win32-status} %{sc-bytes} %{cs-bytes} %{time-taken} %{X-Forwarded-For}"
    }
  }
  # skip ELB-HealthCheck
  if "ELB-HealthChecker/2.0" in [cs(User-Agent)] {
    drop {}
  }
  date {
    match => ["ts", "YYYY-MM-dd HH:mm:ss"]
    timezone => "UTC"
  }
  ruby {
    code => "event.set('[@metadata][local_time]',event.get('[@timestamp]').time.localtime.strftime('%Y-%m-%d'))"
  }
  mutate {
    convert => { 
      "sc-bytes" => "integer"
      "cs-bytes" => "integer"
      "time-taken" => "integer"
    }
    remove_field => "message"
  }
}

output {
# output to Amazon Elasticsearch Service
  elasticsearch { 
    hosts => ["https://search-test-iislogs-************************.us-east-1.es.amazonaws.com:443"]
    index => "iislog-%{[@metadata][local_time]}" 
  }
}

【補足】
※ grok filterではなく、処理負荷が低く記述が簡単なdissect filterでパース処理しています。
※ ファイルの冒頭4行に#(コメント)があるため、drop filterで削除しています。
※ LBのヘルスチェックがログ記録されるため、同様にdrop filterで削除しています。
※ 時刻が-18時間ズレてしまったため、date filterでtime zoneをUTC指定しています。

Windowsコマンドプロンプトを起動し、上記コンフィグを読み込むようにLogstashをバッチ起動します。

Logstash起動

C:\>logstash-6.5.4\bin\logstash.bat -f \logstash-6.5.4\iislog.cfg

Logstashパース結果

{
  "_index": "iislog-2019.11.12",
  "_type": "doc",
  "_id": "cVM7X24BErkrDIwplkLo",
  "_version": 1,
  "_score": null,
  "_source": {
    "s-computername": "EC2AMAZ-1D0KC7E",
    "s-ip": "172.31.90.5",
    "cs(User-Agent)": "Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/78.0.3904.87+Safari/537.36",
    "path": "C:/inetpub/logs/LogFiles/W3SVC1/u_ex191112_x.log",
    "cs-username": "-",
    "host": "EC2AMAZ-1D0KC7E",
    "time-taken": 0,
    "cs-method": "GET",
    "sc-status": "304",
    "cs-host": "iis-212063043.us-east-1.elb.amazonaws.com",
    "@version": "1",
    "c-ip": "172.31.15.135",
    "cs-uri-stem": "/",
    "ts": "2019-11-12 10:49:01",
    "@timestamp": "2019-11-12T10:49:01.000Z",
    "s-port": "80",
    "sc-win32-status": "0",
    "X-Forwarded-For": "126.xxx.248.xxx",
    "cs-version": "HTTP/1.1",
    "cs(Cookie)": "-",
    "sc-bytes": 143,
    "sc-substatus": "0",
    "cs(Referer)": "-",
    "cs-uri-query": "-",
    "s-sitename": "W3SVC1",
    "cs-bytes": 685
  },
  "fields": {
    "@timestamp": [
      "2019-11-12T10:49:01.000Z"
    ]
  },
  "sort": [
    1573555741000
  ]
}

無事きれいにログをAmazon ESに取り込めました。
しかし、LogstashはJVMヒープ上で起動し、CPUとメモリリソースを消費します。
(以下は15MB程度のログをまとめて取り始めた時のCPU負荷)

3. Filebeat Moduleによるログ取得設定とその結果

WindowsサーバにLogstashを導入してフィルタ処理をすると
それなりの負荷がかかる可能性があるため、軽量なFilebeatを試してみます。
Filebeatには決まったログフォーマットをパース処理してくれるFilebeat moduleがあります。
今回、IIS Moduleを使ってみます。(フィールドは、IIS Fieldsの通りにパースされます)

公式HPからZIPダウンロード後、解凍したFilebeatフォルダをC:\Program Files配下に配置します。
WindowsでPowerShellを管理者権限で起動し、以下の手順でIIS Moduleをセットアップします。

IIS_Moduleのセットアップ

Windows PowerShell
Copyright (C) 2016 Microsoft Corporation. All rights reserved.

PS C:\> cd '.\Program Files\Filebeat\'
PS C:\Program Files\Filebeat> dir

    ディレクトリ: C:\Program Files\Filebeat

Mode                LastWriteTime         Length Name
----                -------------         ------ ----
d-----       2019/12/19      8:17                kibana
d-----       2019/12/19      8:17                module
d-----       2019/12/19      8:17                modules.d
-a----       2018/12/17     20:24             41 .build_hash.txt
-a----       2018/12/17     20:21          83009 fields.yml
-a----       2018/12/17     20:22       37665280 filebeat.exe
-a----       2018/12/17     20:21          67865 filebeat.reference.yml
-a----       2019/12/19     13:45           7686 filebeat.yml
-a----       2018/12/17     20:24            566 install-service-filebeat.ps1
-a----       2018/12/17     20:17          11358 LICENSE.txt
-a----       2018/12/17     20:18         163067 NOTICE.txt
-a----       2018/12/17     20:24            802 README.md
-a----       2018/12/17     20:24            250 uninstall-service-filebeat.ps1

PS C:\Program Files\Filebeat> .\filebeat.exe modules enable iis
Enabled iis
PS C:\Program Files\Filebeat> .\filebeat.exe modules list
Enabled:
iis

Disabled:
apache2
auditd
elasticsearch
haproxy
icinga
kafka
kibana
logstash
mongodb
mysql
nginx
osquery
postgresql
redis
system
traefik

PS C:\Program Files\Filebeat> .\filebeat.exe setup -e

C:\Program Files\Filebeat配下にあるfilebeat.ymlにAmazon ESのURLを指定します。

filebeat.ymlの抜粋

#-------------------------- Elasticsearch output ------------------------------
output.elasticsearch:
  # Array of hosts to connect to.
  hosts: ["https://search-test-iislogs-************************.us-east-1.es.amazonaws.com:443"]

Filebeatをサービス起動しますが、ログは転送されてきません。

Filebeat起動

PS C:\Program Files\Filebeat> Start-Service filebeat

理由は、Amazon ESに必要なプラグインが足りていないからになります。
ingest-geoipとingest-user-agentが必要ですが、Amazon ESにingest-geoipが入りません。

【参考】
・必要なElasticsearchプラグイン
・Amazon ESでサポートされるプラグイン

※ 切り分けのため、EC2でElastic Stackを構築し、必要なプラグインを入れ、IIS Moduleの動作を確認しました。
※ IIS ModuleではカスタムフィールドのX-Forwarded-Forが処理できませんでした。
※ IIS Moduleだと不要なログの除外ができないため、ALBヘルスチェックもログに記録されてしまいました。

IIS_Moduleパース結果

{
  "_index": "filebeat-6.5.4-2019.12.19",
  "_type": "doc",
  "_id": "88QcHm8BmhZ_RuQ5BSok",
  "_version": 1,
  "_score": null,
  "_source": {
    "offset": 100308,
    "prospector": {
      "type": "log"
    },
    "read_timestamp": "2019-12-19T12:22:11.963Z",
    "source": "C:\\inetpub\\logs\\LogFiles\\W3SVC1\\u_ex191219_x.log",
    "fileset": {
      "module": "iis",
      "name": "access"
    },
    "input": {
      "type": "log"
    },
    "iis": {
      "access": {
        "server_name": "EC2AMAZ-1D0KC7E",
        "response_code": "200",
        "cookie": "-",
        "method": "GET",
        "sub_status": "0",
        "user_name": "-",
        "http_version": "1.1",
        "url": "/",
        "site_name": "W3SVC1",
        "referrer": "-",
        "body_received": {
          "bytes": "126"
        },
        "hostname": "172.31.90.5",
        "remote_ip": "172.31.15.196",
        "port": "80",
        "server_ip": "172.31.90.5",
        "body_sent": {
          "bytes": "947"
        },
        "win32_status": "0",
        "request_time_ms": "0",
        "query_string": "-",
        "user_agent": {
          "original": "ELB-HealthChecker/2.0",
          "os": "Other",
          "name": "Other",
          "os_name": "Other",
          "device": "Other"
        }
      }
    },
    "@timestamp": "2019-12-19T12:21:59.000Z",
    "host": {
      "os": {
        "build": "14393.3274",
        "family": "windows",
        "version": "10.0",
        "platform": "windows"
      },
      "name": "EC2AMAZ-1D0KC7E",
      "id": "0f6315cb-94f6-4f67-a538-ffb397bb4b12",
      "architecture": "x86_64"
    },
    "beat": {
      "hostname": "EC2AMAZ-1D0KC7E",
      "name": "EC2AMAZ-1D0KC7E",
      "version": "6.5.4"
    }
  },
  "fields": {
    "@timestamp": [
      "2019-12-19T12:21:59.000Z"
    ]
  },
  "sort": [
    1576758119000
  ]
}

4. FilebeatからLogstash経由でAmazon ESに格納

ということで、最終形態として以下のような構成になりました。普通に推奨構成ですね(笑)

以下、FilebeatとLogstashの設定内容になります。

filebeat.yml抜粋

#=========================== Filebeat inputs =============================
filebeat.inputs:

# Each - is an input. Most options can be set at the input level, so
# you can use different inputs for various configurations.
# Below are the input specific configurations.

- type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    #- /var/log/*.log
    - C:\inetpub\logs\LogFiles\W3SVC1\*.log

  # Exclude lines. A list of regular expressions to match. It drops the lines that are
  # matching any regular expression from the list.
  #exclude_lines: ['^DBG']
  exclude_lines: ['^#','HealthChecker']

#----------------------------- Logstash output --------------------------------
output.logstash:
  # The Logstash hosts
  hosts: ["172.31.89.243:5044"]

iislog.cfg

input {
# input from Filebeat
  beats {
    port => 5044
  }
}

filter {
  dissect {
  # log format is TSV
    mapping => {
      "message" => "%{ts} %{+ts} %{s-sitename} %{s-computername} %{s-ip} %{cs-method} %{cs-uri-stem} %{cs-uri-query} %{s-port} %{cs-username} %{c-ip} %{cs-version} %{cs(User-Agent)} %{cs(Cookie)} %{cs(Referer)} %{cs-host} %{sc-status} %{sc-substatus} %{sc-win32-status} %{sc-bytes} %{cs-bytes} %{time-taken} %{X-Forwarded-For}"
    }
  }
  date {
    match => ["ts", "YYYY-MM-dd HH:mm:ss"]
    timezone => "UTC"
  }
  ruby {
    code => "event.set('[@metadata][local_time]',event.get('[@timestamp]').time.localtime.strftime('%Y-%m-%d'))"
  }
  mutate {
    convert => { 
      "sc-bytes" => "integer"
      "cs-bytes" => "integer"
      "time-taken" => "integer"
    }
    remove_field => "message"
  }
}

output {
# output to Amazon Elasticsearch Service
  elasticsearch { 
    hosts => ["https://search-test-iislogs-************************.us-east-1.es.amazonaws.com:443"]
    index => "iislog-%{[@metadata][local_time]}" 
  }
}

【参考】
・Filebeat output logstash

Amazon ESに格納されたログは以下の通りです。

Elasticsearch格納結果

{
  "_index": "iislog-2019.12.20",
  "_type": "doc",
  "_id": "pixjIm8BSanoT0aR-wUf",
  "_version": 1,
  "_score": null,
  "_source": {
    "sc-win32-status": "0",
    "prospector": {
      "type": "log"
    },
    "cs-method": "GET",
    "cs-uri-stem": "/",
    "cs-version": "HTTP/1.1",
    "tags": [
      "beats_input_codec_plain_applied"
    ],
    "cs(Cookie)": "-",
    "s-port": "80",
    "cs-username": "-",
    "ts": "2019-12-20 08:13:47",
    "sc-bytes": 143,
    "cs(User-Agent)": "Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/79.0.3945.79+Safari/537.36",
    "time-taken": 1,
    "offset": 169190,
    "input": {
      "type": "log"
    },
    "host": {
      "id": "0f6315cb-94f6-4f67-a538-ffb397bb4b12",
      "os": {
        "family": "windows",
        "platform": "windows",
        "build": "14393.3274",
        "version": "10.0"
      },
      "name": "EC2AMAZ-1D0KC7E",
      "architecture": "x86_64"
    },
    "s-ip": "172.31.90.5",
    "cs(Referer)": "-",
    "@timestamp": "2019-12-20T08:13:47.000Z",
    "cs-bytes": 691,
    "@version": "1",
    "cs-uri-query": "-",
    "c-ip": "172.31.8.185",
    "source": "C:\\inetpub\\logs\\LogFiles\\W3SVC1\\u_ex191220_x.log",
    "s-computername": "EC2AMAZ-1D0KC7E",
    "cs-host": "iis-212063043.us-east-1.elb.amazonaws.com",
    "sc-substatus": "0",
    "beat": {
      "hostname": "EC2AMAZ-1D0KC7E",
      "name": "EC2AMAZ-1D0KC7E",
      "version": "6.5.4"
    },
    "s-sitename": "W3SVC1",
    "X-Forwarded-For": "126.182.xxx.xxx",
    "sc-status": "304"
  },
  "fields": {
    "@timestamp": [
      "2019-12-20T08:13:47.000Z"
    ]
  },
  "sort": [
    1576829627000
  ]
}

WindowsサーバにLogstashを導入して取り込んだ時と同様に
15MB程度のログをまとめて取り始めた時のCPU負荷は以下のようになりました。
瞬発的に50%くらいまで上がっていますが、取り込みもすぐ落ち着き
その後は1～2%程度を推移するくらいでCPUもメモリも負荷は圧倒的に低かったです。

取り込んだログを用いて、Amazon ESのAlerting機能を設定すれば
閾値監視も簡単に出来そうでした。(今回、設定方法は割愛しています。)

まとめ

さて、いかがでしたでしょうか？

IISアクセスログの取り込みだけでも色々な方法がありましたが、今回要件を満たせた構成は推奨構成でした。
Filebeat Moduleもセットアップは非常に簡単で良かったですが、痒いところに手が届かない結果となりました。
FilebeatとLogstashを組み合わせることで、Windowsサーバへのサービス影響を極力抑えることができました。
しかしながら、Logstash用にEC2を別途立てて管理する必要があるところは頭を抱えてしまいますね。。

これまでLogstashとFilebeat Moduleをちゃんと使い分けたり、技術検証まではしたことはなかったので
この機会に自分なりに突き詰めてみました。皆様にとって何かの参考になれば幸いです^^/

長文になってしまいましたが、お付き合いいただき、ありがとうございましたー！！

明日は残念ながら不在のようですが、24日の@tetsuyasodoさんに期待しましょう！！