IBM Cloud Privateのログ収集の仕組みの調査（Logstashまで）

[LibertyからLogstash CollectorでELKへのログ出力を試す](https://qiita.com/sotoiwa/items/da89f095a0644dae966c)
[Libertyのログをjson形式で出力してFilebeatでELKに送る](https://qiita.com/sotoiwa/items/13e08d2426289e5c5c67)
の続きです。

IBM Cloud PrivateにLibertyアプリケーションをデプロイした場合に、どのようにコンテナのログを収集されるのかを調べたメモです。ICP 2.1.0.3で確認しています。

## ICPのログ収集の仕組みの概要

コンテナのログ収集の仕組みをの概要を図示すると次のようになります。

![image.png](https://qiita-image-store.s3.amazonaws.com/0/86449/e89ba5cc-f415-2557-aaab-9ba53347f791.png)

- コンテナが標準出力／標準エラー出力は、Dockerのロギング・ドライバーによって`/var/log/containers/`にファイルとして保存される
- DaemonSetとして稼働しているFilebeatが`/var/log/containers/*.log`を監視し、Logstashに送る
- Logstashがデータを加工してElasticsearchに送る
- 管理者はKibanaコンソールからデータを検索

## コンテナのログ収集

コンテナの標準出力／標準エラー出力は、Dockerのロギング・ドライバーによってノードの`/var/log/containers/`ディレクトリーの下に出力されます。

```
/var/log/containers/hello-758d49f796-g9nm5_ns3_hello-df0feb5068ebfa125cee2582bd8bdbeef33fb30fa78d2fc502bd6b19745a0259.log
```

ファイル名は`<Pod名>_<Namespace名>_<コンテナ名>-<コンテナID>.log`となっています。

コンテナが標準出力に以下のメッセージを出力したとすると、

```
Hello World!
```

ノード上のログファイルとしては以下が保存されます（1行で）。

```json
{
  "log":"Hello World!",
  "stream":"stdout",
  "time":"2018-05-31T05:49:56.659607745Z"
}
```

これはDockerのLogging Driverとしてjson-fileを使っているためです。

```
[root@myicp01 ~]# docker info|grep "Logging Driver"
WARNING: devicemapper: usage of loopback devices is strongly discouraged for production use.
         Use `--storage-opt dm.thinpooldev` to specify a custom block storage device.
Logging Driver: json-file
[root@myicp01 ~]#
```

（参考）
[Dockerのlogging driver: それぞれの特徴と使いどころ(json-file, syslog, journald, fluentd)](https://qiita.com/tkit/items/9eb2a952b986b35956cd)

ちなみに、Libertyがjson形式でログを出力すると（実際は1行で）、

```json
{
	"type": "liberty_message",
	"host": "hello-758d49f796-g9nm5",
	"ibm_userDir": "/opt/ibm/wlp/usr/",
	"ibm_serverName": "defaultServer",
	"ibm_datetime": "2018-06-20T08:54:46.617+0000",
	"ibm_threadId": "000000fc",
	"module": "SystemOut",
	"loglevel": "SystemOut",
	"ibm_sequence": "1529484886617_000000000001F",
	"message": "Hello World!"
}
```

jsonがjsonのなかに入るので`/var/log/containers/hogehoge.log`は次のようになります。

```json
{
	"log": "{\"type\":\"liberty_message\",\"host\":\"hello-758d49f796-g9nm5\",\"ibm_userDir\":\"\\/opt\\/ibm\\/wlp\\/usr\\/\",\"ibm_serverName\":\"defaultServer\",\"ibm_datetime\":\"2018-06-20T08:54:46.617+0000\",\"ibm_threadId\":\"000000fc\",\"module\":\"SystemOut\",\"loglevel\":\"SystemOut\",\"ibm_sequence\":\"1529484886617_000000000001F\",\"message\":\"Hello World!\"}\n",
	"stream": "stdout",
	"time": "2018-06-20T08:54:46.618375708Z"
}
```

## Filebeatの動作

Filebeatが`/var/log/containers/*.log`を監視し、Logstashに送ります。Filebeatから直接Elasticsearchに送ることもできますが、Logstashを経由するようになっています。Filebeatでも簡単な変換処理はできますが、Logstashの方が複雑な処理ができます。

FilebeatはDaemonSetとしてデプロイされています。DaemonSetなので、各ノードに必ず1つFilebeatのPodが稼働します。

```shell-session
[root@myicp01 ~]# kubectl get ds -n kube-system logging-elk-filebeat-ds -o wide
NAME                      DESIRED   CURRENT   READY     UP-TO-DATE   AVAILABLE   NODE SELECTOR   AGE       CONTAINERS   IMAGES                  SELECTOR
logging-elk-filebeat-ds   1         1         1         1            1           <none>          8d        filebeat     ibmcom/filebeat:5.5.1   app=logging-elk-elasticsearch,component=filebeat-ds,heritage=Tiller,release=logging,role=filebeat
[root@myicp01 ~]#
```

Filebeatの設定は以下のConfigMapに保管されています。

```shell-session
[root@myicp01 ~]# kubectl get cm -n kube-system logging-elk-filebeat-ds-config -o yaml
apiVersion: v1
data:
  filebeat.yml: |-
    filebeat.prospectors:
    - input_type: log
      paths:
        - /var/log/containers/*.log

（省略）
```

`filebeat.yml`部分を抜き出すと以下です。

```yaml:filebeat.yml
    filebeat.prospectors:
    - input_type: log
      paths:
        - /var/log/containers/*.log
      scan_frequency: 10s
      symlinks: true
      json.message_key: log
      json.keys_under_root: true
      json.add_error_key: true
      multiline.pattern: '^\s'
      multiline.match: after
      fields_under_root: true
      fields:
        type: kube-logs
        node.hostname: ${NODE_HOSTNAME}
        pod.ip: ${POD_IP}
      tags:
          - k8s-app
    filebeat.config.modules:
      # Set to true to enable config reloading
      reload.enabled: true
    output.logstash:
      hosts: logstash:5044
      timeout: 15
    logging.level: info
```

`input_type`は`log`です。

（参考）
[Log input](https://www.elastic.co/guide/en/beats/filebeat/master/filebeat-input-log.html)

`paths:`で`/var/log/containers/*.log`を監視対象に指定しています。
`json.message_key: log`によってログがjson形式であり、メッセージ本文が`log`フィールドに入っていることを指定しています。
`fields:`で`type: kube-logs`などのフィールドを追加しています。
`${NODE_HOSTNAME}`と`${POD_IP}`は、KubernetesによってこのFilebeatのコンテナにセットされている環境変数です。すなわち以下のIPとNODEです。

出力先はlogstashで、ホスト名が`logstash`でポートが`5044`です。SSLは使用していません。

（参考）
[Configure the Logstash output](https://www.elastic.co/guide/en/beats/filebeat/master/logstash-output.html)

`filebeat.yml`で以下の設定を追加してコンソール出力すると、実際にどのような内容が送られるか確認できます。

```yaml
output.console:
  pretty: true
```

例えば、

```json
{
  "log":"Hello World!",
  "stream":"stdout",
  "time":"2018-05-31T05:49:56.659607745Z"
}
```

のログは、以下の内容でLogstashに送られます。

※以下はローカルPCでFilebeatとLogstashを動かして確認したログなのでホスト名やファイルパスはICP環境と異なります。

```json
{
  "@timestamp": "2018-06-20T09:44:43.575Z",
  "beat": {
    "hostname": "soto-no-air.hogehoge.com",
    "name": "soto-no-air.hogehoge.com",
    "version": "5.3.3"
  },
  "input_type": "log",
  "log": "Hello World!",
  "node": {
    "hostname": "<node_hostname>"
  },
  "offset": 23978,
  "pod": {
    "ip": "<pod_ip>"
  },
  "source": "/var/log/containers/hello-758d49f796-g9nm5_ns3_hello-df0feb5068ebfa125cee2582bd8bdbeef33fb30fa78d2fc502bd6b19745a0259.log",
  "stream": "stdout",
  "tags": [
    "k8s-app"
  ],
  "time": "2018-05-31T05:49:56.659607745Z",
  "type": "kube-logs"
}
```

Logstashの側でも、filterなしで受け取った内容をjsonとしてコンソール出力して確認してみます。

```ruby
output {
    stdout { codec => json }
}
```

確認すると以下です。`host`と`@version`フィールド、そして`tags`フィールドの`beats_input_raw_event`が追加となっていて、これらはLogstashが追加しています。
`@timestamp`は同じですが、もしかしたらFilebeatの処理時間からLogstashの処理時間に変わっているかもしれませんが未確認。

```json
{
	"offset": 23978,
	"pod": {
		"ip": "<pod_ip>"
	},
	"log": "Hello World!",
	"input_type": "log",
	"source": "/var/log/containers/hello-758d49f796-g9nm5_ns3_hello-df0feb5068ebfa125cee2582bd8bdbeef33fb30fa78d2fc502bd6b19745a0259.log",
	"type": "kube-logs",
	"tags": [
		"k8s-app",
		"beats_input_raw_event"
	],
	"node": {
		"hostname": "<node_hostname>"
	},
	"@timestamp": "2018-06-20T09:44:43.575Z",
	"stream": "stdout",
	"beat": {
		"hostname": "soto-no-air.hogehoge.com",
		"name": "soto-no-air.hogehoge.com",
		"version": "5.3.3"
	},
	"@version": "1",
	"host": "soto-no-air.hogehoge.com",
	"time": "2018-05-31T05:49:56.659607745Z"
}
```

## Logstashの動作

LogstashはFilebeatから受け取った内容を少し加工してElasticsearchに送ります。

LogstashはDeploymentとしてデプロイされています。Managementノードにデプロイされます。Managementノードが複数でもレプリカ数は1です。

```
[root@myicp01 ~]# kubectl get deploy -n kube-system -o wide logging-elk-logstash
NAME                   DESIRED   CURRENT   UP-TO-DATE   AVAILABLE   AGE       CONTAINERS   IMAGES                  SELECTOR
logging-elk-logstash   1         1         1            1           8d        logstash     ibmcom/logstash:5.5.1   app=logging-elk-elasticsearch,component=logstash,heritage=Tiller,release=logging,role=logstash
[root@myicp01 ~]#
```

設定はConfigMapに保管されています。

```
[root@myicp01 ~]# kubectl get cm -n kube-system logging-elk-logstash-config -o yaml
apiVersion: v1
data:
  k8s.conf: |-
    input {
      beats {
        port => 5044
      }
    }

（省略）
```

Logstashの設定ファイル部分は以下です。コメントで補足説明を加えました。

```ruby
    input {
      # Filebeatから入力
      beats {
        port => 5044
        # SSLは使用していない
      }
    }

    filter {
      # if文により、type: kube-logsである場合のみ処理
      # このフィールドはFilebeatが付けている
      if [type] == "kube-logs" {
        # mutate filterは基本的なフィールドの操作を行う汎用的なフィルター
        mutate {
          # messageフィールドをlogフィールドにリネーム
          # （しかしmessageフィールドはないので何のためか不明）
          rename => { "message" => "log" }
          # hostフィールドを削除
          # このフィールドはLogstashが追加したフィールド
          remove_field => ["host"]
        }

        # date filterは日付文字列を扱う
        date {
          # timeフィールドをISO8601形式で時刻としてマッチング
          # targetが指定されていないので、結果は@timestampフィールドにセットされる
          match => ["time", "ISO8601"]
        }

        # Sample:
        # tiller-1279707952-sgd08_kube-system_tiller-0c51282d195d1c21307f6a48b9118d690441cda498fc5a2790c043407eab235b.log
        # filebeat-j357d_default_filebeat-1a3113e374ad7937a3efa36c4bb42b46b976bcd7cd96223e6b9e6e3df08d802a.log
        # appstdoutpod_default_app-stdout-container-01c2e7a7b105d9141825ea3ae5634b580fdd20a5a4ee890cdbe0816ca002623c.log
        # unified-router-4047118581-sm913_kube-system_unified-router-ddda8a8cbcb74c45b64a4b18997b4f2928c998a37e45037cd0304eaa56d1634f.log

        # dissect filterは文字列の分割に使える
        dissect {
          # sourceフィールドから一部を切り出して
          # kubernetes.pod
          # kubernetes.namespace
          # container_file_ext
          # にマッピング
          mapping => {
            "source" => "/var/log/containers/%{kubernetes.pod}_%{kubernetes.namespace}_%{container_file_ext}"
          }
        }

        dissect {
          # container_file_extからcontainerを切りだす
          # file_extの?はskipしてフィールドにはセットしないことを意味する
          mapping => {
            "container_file_ext" => "%{container}.%{?file_ext}"
          }
          # hostとcontainer_file_extフィールドを削除
          # （hostは上の方でも削除しているのでなぜもう一度削除するのか不明）
          remove_field => ["host", "container_file_ext"]
        }

        # grok filterはパターンを指定して文字列をフィールドに分割する
        grok {
          # containerから
          # kubernetes.container_name
          # kubernetes.container_id
          # を取り出している
          "match" => {
            "container" => "^%{DATA:kubernetes.container_name}-(?<kubernetes.container_id>[0-9A-Za-z]{64,64})"
          }
          remove_field => ["container"]
        }
      }
    }

    # type: kube-logsでない場合も処理対象
    filter {
      # Drop empty lines
      # 空行をドロップする
      if [log] =~ /^\s*$/ {
        drop { }
      }
      # Attempt to parse JSON, but ignore failures and pass entries on as-is
      # logフィールドについて、JSONとしてパースを試みる
      # Libertyのログをjsonで出力した場合はここでパースされる
      # パースできなかったらスキップしてそのまま次に渡す
      json {
        source => "log"
        skip_on_invalid_json => true
      }
    }

    output {
      # Elastcisearch出力プラグイン
      elasticsearch {
        hosts => "elasticsearch:9200"
        # indexの名前を指定しているがデフォルト値と同じ指定
        index => "logstash-%{+YYYY.MM.dd}"
        document_type => "%{[@metadata][type]}"
      }
    }
```

いろいろやっていますが、つまり、以下のことをやっています。

- `time`フィールドを`@timestamp`フィールドにセットする
- ログファイル名から以下の情報を切り出して追加する

```json
{
    "kubernetes.pod": "hello-758d49f796-g9nm5",
    "kubernetes.namespace": "ns3",
    "kubernetes.container_name": "hello",
    "kubernetes.container_id": "df0feb5068ebfa125cee2582bd8bdbeef33fb30fa78d2fc502bd6b19745a0259"
}
```

- logがjsonの場合はパースする
- 空行は削除

以上がLogstashがElasticsearchに送るまでの設定内容です。

フィルター後のデータ全体をICP実機で確認したところ以下となっていました。

```json
{
	"offset": 6275,
	"pod": {
		"ip": "10.1.170.243"
	},
	"log": "Hello World!",
	"kubernetes.pod": "hello-5564fcdfc6-v2n72",
	"kubernetes.container_name": "hello",
	"input_type": "log",
	"source": "/var/log/containers/hello-5564fcdfc6-v2n72_ns3_hello-32ee39e2d8d4dec3e65964b9f579456269bf97e8a4d742ccd65fb906e33363c6.log",
	"type": "kube-logs",
	"tags": [
		"k8s-app",
		"beats_input_raw_event"
	],
	"kubernetes.container_id": "32ee39e2d8d4dec3e65964b9f579456269bf97e8a4d742ccd65fb906e33363c6",
	"node": {
		"hostname": "172.30.1.224"
	},
	"@timestamp": "2018-07-23T07:16:54.353Z",
	"stream": "stdout",
	"kubernetes.namespace": "ns3",
	"beat": {
		"hostname": "logging-elk-filebeat-ds-ln2gp",
		"name": "logging-elk-filebeat-ds-ln2gp",
		"version": "5.5.1"
	},
	"@version": "1",
	"time": "2018-07-23T07:16:54.353021511Z"
}
```

## 参考リンク

[IBM® Cloud Private logging](https://www.ibm.com/support/knowledgecenter/en/SSBS6K_2.1.0.3/manage_metrics/logging_elk.html)

[IBM Cloud Private での Liberty メッセージの分析](https://www.ibm.com/support/knowledgecenter/ja/SSEQTP_liberty/com.ibm.websphere.wlp.doc/ae/twlp_icp_json_logging.html)

[ロギングおよびトレース](https://www.ibm.com/support/knowledgecenter/ja/SSEQTP_liberty/com.ibm.websphere.wlp.doc/ae/rwlp_logging.html)

[Filebeat Reference](https://www.elastic.co/guide/en/beats/filebeat/current/index.html)

[Logstash Reference](https://www.elastic.co/guide/en/logstash/current/index.html)

[IBM Cloud Private(ICP)でコンテナログをsyslogに転送する - logstash差替編](https://qiita.com/teruq/items/ff7a55eed3929d5e6a30)