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


概要

CoreOS 上の全てのログをリモートサーバへ送る を応用し、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 コマンドの標準出力にコンテナのログを出力させること

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 コマンドでログを見てみる

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

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

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 のログだけ見てみる

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 上の全てのログをリモートサーバへ送る を応用し、 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.servicehello.journal-router.service をログルーター役として必要としているので Wants=hello.journal-router.service としている
  • hello.servicehello.journal-router.service が起動する前に起動したいので Before=hello.journal-router.service としている
  • hello.journal-router.servicehello.service のために起動しているので hello.service が終了したときは一緒に終了したいので、 BindsTo=hello.service としている

hello.service unit を起動してみる

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 の "The Problem with a Coprocess for Registering" の段落で説明されている。

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

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

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

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

{
    "__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 を使って必要な情報だけ抜き出した後にルーティングすることでいける。

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)

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