systemd で CoreOS 上の Docker コンテナのログを集約・ルーティングする


## 概要
[CoreOS 上の全てのログをリモートサーバへ送る](http://qiita.com/spesnova/items/631ffb5c13e1d0da258b) を応用し、systemd で起動した Docker コンテナのログをリモートサーバへ送る。 systemd で Docker コンテナを起動しておけば journalctl でログが取得でき、さらに systemd の unit のグルーピング（bind）機能を使ってログルーティングプロセスをバインドする。これは "coprocess" や "sidekick" というらしい。

## ログの収集
コンテナのログ収集は systemctl を使ってコンテナを起動するだけでよい。そうすれば `journalctl` でログを見る事が出来るようになる

```
# /etc/systemd/system/hello.service
[Unit]
Description=Hello
After=hello.service
Requires=docker.service

[Service]
TimeoutStartSec=0
ExecStartPre=-/usr/bin/docker kill hello
ExecStartPre=-/usr/bin/docker rm hello
ExecStartPre=/usr/bin/docker pull busybox
ExecStart=/usr/bin/docker run -name hello busybox /bin/sh -c "while true; do echo hello world; sleep 1; done"

[Install]
WantedBy=multi-user.target
```

ポイントとしては `-d` を付けずに `docker run` コマンドの標準出力にコンテナのログを出力させること

```bash
core@core-01 ~ $ sudo systemctl enable /etc/systemd/system/hello.service
Created symlink from /etc/systemd/system/multi-user.target.wants/hello.service to /etc/systemd/system/hello.service.
core@core-01 ~ $ sudo systemctl start hello.service
```

`docker logs` コマンドでログを見てみる

```bash
core@core-01 ~ $ docker logs -f hello
hello world
hello world
hello world
hello world
hello world
```

`journalctl` でログを見てみる（hello world しか出てないが、ここは CoreOS 上の全てのログが出てくる）


```bash
core@core-01 ~ $ journalctl -f
-- Logs begin at Mon 2014-09-08 15:37:51 JST. --
Sep 08 21:31:59 core-01 docker[2164]: hello world
Sep 08 21:32:00 core-01 docker[2164]: hello world
Sep 08 21:32:01 core-01 docker[2164]: hello world
Sep 08 21:32:02 core-01 docker[2164]: hello world
Sep 08 21:32:03 core-01 docker[2164]: hello world
Sep 08 21:32:04 core-01 docker[2164]: hello world
```

あらゆるログが出るので漏れはないのだが、どのログがどのコンテナのものか、というのが非常に分かりにくい。 hello.service のログだけ見てみる


```bash
core@core-01 ~ $ journalctl -f -u hello.service
-- Logs begin at Mon 2014-09-08 15:37:51 JST. --
Sep 08 21:24:04 core-01 docker[2164]: hello world
Sep 08 21:24:05 core-01 docker[2164]: hello world
Sep 08 21:24:06 core-01 docker[2164]: hello world
Sep 08 21:24:07 core-01 docker[2164]: hello world
Sep 08 21:24:08 core-01 docker[2164]: hello world
Sep 08 21:24:09 core-01 docker[2164]: hello world
Sep 08 21:24:10 core-01 docker[2164]: hello world
```

## 集約したログのルーティング
[CoreOS 上の全てのログをリモートサーバへ送る](http://qiita.com/spesnova/items/631ffb5c13e1d0da258b) を応用し、 Docker コンテナのログをリモートサーバへ送る。

* 起動したいコンテナ `hello.service`

に加え

* ログルーティング用 unit `hello.journal-router.service` 

を起動することで実現する。

```
# /etc/systemd/system/hello.service
[Unit]
Description=Hello
Requires=docker.service
After=docker.service
Wants=hello.journal-router.service
Before=hello.journal-router.service

[Service]
TimeoutStartSec=0
ExecStartPre=-/usr/bin/docker kill hello
ExecStartPre=-/usr/bin/docker rm hello
ExecStartPre=/usr/bin/docker pull busybox
ExecStart=/usr/bin/docker run -name hello busybox /bin/sh -c "while true; do echo hello world; sleep 1; done"

[Install]
WantedBy=multi-user.target
```

```
# /etc/systemd/system/hello.journal-router.service
[Unit]
Description=Journal Router for Hello
Requires=hello.service
After=hello.service
BindsTo=hello.service

[Service]
TimeoutStartSec=0
ExecStart=/bin/sh -c '/usr/bin/journalctl -o short -u hello.service -f | sed \"s/^/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx \\0/g\" | ncat data.logentries.com 10000'

[Install]
WantedBy=multi-user.target
```

ポイント

* `hello.service` は `hello.journal-router.service` をログルーター役として必要としているので `Wants=hello.journal-router.service` としている
* `hello.service` を `hello.journal-router.service` が起動する前に起動したいので `Before=hello.journal-router.service` としている
* `hello.journal-router.service` は `hello.service` のために起動しているので `hello.service` が終了したときは一緒に終了したいので、 `BindsTo=hello.service` としている

`hello.service` unit を起動してみる

```bash
core@core-02 ~ $ sudo systemctl enable /etc/systemd/system/hello.service
core@core-02 ~ $ sudo systemctl enable /etc/systemd/system/hello.journal-router.service
core@core-02 ~ $ sudo systemctl start hello.service
```

すると、`hello.service` 起動後に `hello.journal-router.service` も systemd によって起動される。また `hello.service` を止めると `hello.journal-router.service` も止まる。

#### このやり方の問題点
新規に追加したいコンテナの unit file を書く際にログ収集用 unit についても気にする必要があること。コンテナを起動すれば勝手にログについてはハンドリングしてくれている方が楽だ。この話は [Automatic Docker Service Announcement with Registrator](http://progrium.com/blog/2014/09/10/automatic-docker-service-announcement-with-registrator/) の "The Problem with a Coprocess for Registering" の段落で説明されている。

ただ、 journalctl を json フォーマットで出力すると、このログがどのコンテナのものかわかるので、json を human readable に直して送るならば、[CoreOS 上の全てのログをリモートサーバへ送る](http://qiita.com/spesnova/items/631ffb5c13e1d0da258b) のようにするだけで Docker のログ管理は完結する。

### json output を jq で整形したのちルーティングする

* どのコンテナのログ
* human readable なフォーマット
* 起動したいアプリケーションコンテナはログのことは気にしなくてよい（"sidekick" アプローチを取らない

を実現したい。`journalctl` の json output からは

```json
{
	"__CURSOR" : "s=78035e49faa2491e8dedcb38fc1b5c5e;i=4eb;b=a48ed2e1bee74f18a171e8ac4b8dea9e;m=13e50316;t=502b24b3c9e12;x=96f3d2082539aec9",
	"__REALTIME_TIMESTAMP" : "1410339673251346",
	"__MONOTONIC_TIMESTAMP" : "333775638",
	"_BOOT_ID" : "a48ed2e1bee74f18a171e8ac4b8dea9e",
	"PRIORITY" : "6",
	"_UID" : "0",
	"_GID" : "0",
	"_SYSTEMD_SLICE" : "system.slice",
	"SYSLOG_FACILITY" : "3",
	"_CAP_EFFECTIVE" : "1fffffffff",
	"_TRANSPORT" : "stdout",
	"_MACHINE_ID" : "ce5fac63ce624124a15ea8a52e838b17",
	"_HOSTNAME" : "core-02",
	"SYSLOG_IDENTIFIER" : "docker",
	"_COMM" : "docker",
	"_EXE" : "/usr/bin/docker",
	"_SYSTEMD_UNIT" : "dd-agent.service",
	"_PID" : "1075",
	"_CMDLINE" : "/usr/bin/docker run --privileged --name dd-agent -h core-02 -v /var/run/docker.sock:/var/run/docker.sock -v /proc/mounts:/host/proc/mounts:ro -v /sys/fs/cgroup/:/host/sys/fs/cgroup:ro -e API_KEY=xxxxxxxxxxxxxxxxx datadog/docker-dd-agent",
	"_SYSTEMD_CGROUP" : "/system.slice/dd-agent.service",
	"MESSAGE" : "2014-09-10 09:01:13,250 CRIT Server 'unix_http_server' running without any HTTP authentication checking"
}
```

のように、

* ログメッセージ
* ホスト
* コンテナ（unit）

が取得できるので、あまり綺麗ではないが、以下のように jq を使って必要な情報だけ抜き出した後にルーティングすることでいける。

```bash
core@core-01 ~ $ journalctl -f -l -o json | \
  jq '._HOSTNAME + " " + ._SYSTEMD_UNIT + ": " + .MESSAGE' -c | \
  sed -e "s/^\"*\"$/\0/" | \
  sed -e "s/^/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx \0/g" | \
  ncat data.logentries.com 10000
```

これで以下のようなログをルーティングできる。(`xxxxxxxx` みたいな部分は token）

```bash
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:28,697 INFO: Boto based storage initialized
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:29 [1] [INFO] Starting gunicorn 18.0
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:29 [1] [INFO] Listening at: http://0.0.0.0:5000 (1)
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:29 [1] [INFO] Using worker: gevent
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:29 [22] [INFO] Booting worker with pid: 22
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx core-01 registry.service: 2014-09-12 06:54:29 [23] [INFO] Booting worker with pid: 23
```


## メモと感想


## REF

* [Using systemd with CoreOS](https://coreos.com/using-coreos/systemd/)
* [systemd.unit — Unit configuration](http://www.freedesktop.org/software/systemd/man/systemd.unit.html)
* [systemd (日本語)](https://wiki.archlinux.org/index.php/Systemd_(%E6%97%A5%E6%9C%AC%E8%AA%9E))