Dockert調査 ~ログ編~

今日は、Dockerのログについて調べたいと思います。
運用するにも、開発で利用するにもログを出力するということは非常に重要です。

私は運用で使用するプログラムでは、よくsyslogに対して出力をすることが多いです。
また、開発中にはprintなどの標準出力、エラー出力を利用することが多いです。
Dockerではどのようになっているのでしょうか。

Dockerのログ出力

デフォルトは？

Dockerのデフォルトの出力は、JSON形式で保存されています。

コンテナ起動

まず、コンテナを起動してコマンドを実行してみましょう。

# docker run -it -v /dev/log:/dev/log --name test01 centos:6 /bin/bash                                                    
[root@ca4bd7b2ad6a /]# ps -ef
UID         PID   PPID  C STIME TTY          TIME CMD
root          1      0  0 15:49 ?        00:00:00 /bin/bash
root         13      1  0 15:50 ?        00:00:00 ps -ef
[root@ca4bd7b2ad6a /]# ls
bin  dev  etc  home  lib  lib64  lost+found  media  mnt  opt  proc  root  run  sbin  selinux  srv  sys  tmp  usr  var
[root@ca4bd7b2ad6a /]# df -h
Filesystem            Size  Used Avail Use% Mounted on
rootfs                 10G  248M  9.8G   3% /
/dev/mapper/docker-253:0-67434730-ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a
                       10G  248M  9.8G   3% /
tmpfs                 914M     0  914M   0% /dev
shm                    64M     0   64M   0% /dev/shm
tmpfs                 914M     0  914M   0% /run/secrets
devtmpfs              905M     0  905M   0% /dev/log
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/resolv.conf
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/hostname
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/hosts
tmpfs                 914M     0  914M   0% /proc/kcore
tmpfs                 914M     0  914M   0% /proc/timer_stats
[root@ca4bd7b2ad6a /]# exit
exit

ログの確認

Dockerコマンドには、logsというコマンドがあります。
このコマンドで実行結果(ログ)を確認することができます。このコマンドでは、コンテナ内に出力されたSTDOUTとSTDERRが出力されます。
(Dockerエンジンでは、Docker作成時にコンテナに対して仮想端末/dev/ptmxを提供し監視しています。)

詳しくは、docker logsを見てください。

# docker logs test01
[root@ca4bd7b2ad6a /]# ps -ef                                                                                UID         PID   PPID  C STIME TTY          TIME CMD
root          1      0  0 15:49 ?        00:00:00 /bin/bash
root         13      1  0 15:50 ?        00:00:00 ps -ef
[root@ca4bd7b2ad6a /]# ls
bin  dev  etc  home  lib  lib64  lost+found  media  mnt  opt  proc  root  run  sbin  selinux  srv  sys  tmp  usr  var
[root@ca4bd7b2ad6a /]# df -h
Filesystem            Size  Used Avail Use% Mounted on
rootfs                 10G  248M  9.8G   3% /
/dev/mapper/docker-253:0-67434730-ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a
                       10G  248M  9.8G   3% /
tmpfs                 914M     0  914M   0% /dev
shm                    64M     0   64M   0% /dev/shm
tmpfs                 914M     0  914M   0% /run/secrets
devtmpfs              905M     0  905M   0% /dev/log
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/resolv.conf
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/hostname
/dev/mapper/centos-root
                       50G  1.1G   49G   3% /etc/hosts
tmpfs                 914M     0  914M   0% /proc/kcore
tmpfs                 914M     0  914M   0% /proc/timer_stats
[root@ca4bd7b2ad6a /]# exit
exit

docker logsをうまく使う

docker logsコマンドには非常な便利なオプションがついています。
1. docker logs -t (--timestamps)
2. docker logs -f (--follow)

オプション-fはtailコマンドでもおなじみログをリアルタイムに表示し続けてくれます。
オプション-tは出力した時刻を付加してくれます。しかもRFC3339Nano timestamp(例：2014-09-16T06:17:46.000000000Z)で表示してくれます。

実行してみましょう。
この精度で出力されるのは、開発上非常にありがたいですね。

[root@localhost ~]# docker logs -t test01
2015-07-26T15:50:21.328049960Z [root@ca4bd7b2ad6a /]# ps -ef                                                                                   
2015-07-26T15:50:21.335650349Z UID         PID   PPID  C STIME TTY          TIME CMD
2015-07-26T15:50:21.336891709Z root          1      0  0 15:49 ?        00:00:00 /bin/bash
2015-07-26T15:50:21.336924723Z root         13      1  0 15:50 ?        00:00:00 ps -ef
2015-07-26T15:50:22.542839444Z [root@ca4bd7b2ad6a /]# ls
2015-07-26T15:50:22.552921417Z bin  dev  etc  home  lib  lib64  lost+found  media  mnt  opt  proc  root  run  sbin  selinux  srv  sys  tmp  usr  var
2015-07-26T15:50:27.124427260Z [root@ca4bd7b2ad6a /]# df -h
2015-07-26T15:50:27.132413673Z Filesystem            Size  Used Avail Use% Mounted on
2015-07-26T15:50:27.132438123Z rootfs                 10G  248M  9.8G   3% /
2015-07-26T15:50:27.132443158Z /dev/mapper/docker-253:0-67434730-ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a
2015-07-26T15:50:27.132447429Z                        10G  248M  9.8G   3% /
2015-07-26T15:50:27.132450523Z tmpfs                 914M     0  914M   0% /dev
2015-07-26T15:50:27.132453366Z shm                    64M     0   64M   0% /dev/shm
2015-07-26T15:50:27.132456124Z tmpfs                 914M     0  914M   0% /run/secrets
2015-07-26T15:50:27.132459014Z devtmpfs              905M     0  905M   0% /dev/log
2015-07-26T15:50:27.132461844Z /dev/mapper/centos-root
2015-07-26T15:50:27.132464686Z                        50G  1.1G   49G   3% /etc/resolv.conf
2015-07-26T15:50:27.132467524Z /dev/mapper/centos-root
2015-07-26T15:50:27.132470205Z                        50G  1.1G   49G   3% /etc/hostname
2015-07-26T15:50:27.132472998Z /dev/mapper/centos-root
2015-07-26T15:50:27.132475723Z                        50G  1.1G   49G   3% /etc/hosts
2015-07-26T15:50:27.132478541Z tmpfs                 914M     0  914M   0% /proc/kcore
2015-07-26T15:50:27.132481697Z tmpfs                 914M     0  914M   0% /proc/timer_stats
2015-07-26T15:50:29.009087142Z [root@ca4bd7b2ad6a /]# exit
2015-07-26T15:50:29.009112772Z exit

このlogはどのように保存されているのでしょうか

Dockerコンテナのログは、/var/lib/docker/containers/(コンテナID)/(コンテナID)-json.logに出力されています。
見てみましょう。中身は名前の通り、jsonで保存されています。

# ls -al /var/lib/docker/containers/ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a/
合計 32
drwx------. 3 root root 4096  7月 27 00:49 .
drwx------. 3 root root   77  7月 27 00:49 ..
-rw-------. 1 root root 3582  7月 27 00:50 ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a-json.log
-rw-r--r--. 1 root root 2004  7月 27 00:50 config.json
-rw-r--r--. 1 root root  516  7月 27 00:50 hostconfig.json
-rw-r--r--. 1 root root   13  7月 27 00:49 hostname
-rw-r--r--. 1 root root  174  7月 27 00:49 hosts
-rw-r--r--. 1 root root   85  7月 27 00:49 resolv.conf
-rw-r--r--. 1 root root   71  7月 27 00:49 resolv.conf.hash
drwx------. 2 root root    6  7月 27 00:49 secrets
# cat /var/lib/docker/containers/ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a/ca4bd7b2ad6aa1fc6f35f2f006533f1e803ebfe5037c26b5036aabfa9986fd2a-json.log 
{"log":"\u001b]0;@ca4bd7b2ad6a:/\u0007\u001b[?1034h[root@ca4bd7b2ad6a /]# ps -ea\u0008\u001b[Kf\n","stream":"stdout","time":"2015-07-26T15:50:21.32804996Z"}
{"log":"UID         PID   PPID  C STIME TTY          TIME CMD\n","stream":"stdout","time":"2015-07-26T15:50:21.335650349Z"}
{"log":"root          1      0  0 15:49 ?        00:00:00 /bin/bash\n","stream":"stdout","time":"2015-07-26T15:50:21.336891709Z"}
{"log":"root         13      1  0 15:50 ?        00:00:00 ps -ef\n","stream":"stdout","time":"2015-07-26T15:50:21.336924723Z"}
{"log":"\u001b]0;@ca4bd7b2ad6a:/\u0007[root@ca4bd7b2ad6a /]# ls\n","stream":"stdout","time":"2015-07-26T15:50:22.542839444Z"}
...(略)
{"log":"tmpfs                 914M     0  914M   0% /proc/timer_stats\n","stream":"stdout","time":"2015-07-26T15:50:27.132481697Z"}
{"log":"\u001b]0;@ca4bd7b2ad6a:/\u0007[root@ca4bd7b2ad6a /]# exit\n","stream":"stdout","time":"2015-07-26T15:50:29.009087142Z"}
{"log":"exit\n","stream":"stdout","time":"2015-07-26T15:50:29.009112772Z"}

1行のデータを見てみると、log(表示内容),stream(stdout,stderr),time(時刻)の情報で構成されていることがわかります。

{
    "log": "                       50G  1.1G   49G   3% /etc/hostname\n",
    "stream": "stdout",
    "time": "2015-07-26T15:50:27.132470205Z"
}

syslogに出力しよう(1)

Docker 1.6からsyslogに対して出力できるようになりました。
＃ここでは、STDOUT、STDERRをそのままsyslogに出力した結果です。syslogを出力する方法は、下のsyslogに出力しよう(2)の方で説明しているのでそちらを見てください。

このページを参照ください。
　　Docker 1.6がリリースされたのでLogging driversを試してみた

コンテナ実行方法

docker run のオプションで「--log-driver=syslog」をつけて実行します。
残念ながらdocker runのページに参考になる情報はありません。

では、実行してみましょう。
tail -f /var/log/messageを実行しておいてください。それのほうがわかりやすいです。

# docker run -it --log-driver=syslog --name test02 centos:6 /bin/bash
[root@83ae0f3b3997 /]# ps
   PID TTY          TIME CMD
     1 ?        00:00:00 bash
    13 ?        00:00:00 ps
[root@83ae0f3b3997 /]# ls
bin  dev  etc  home  lib  lib64  lost+found  media  mnt  opt  proc  root  run  sbin  selinux  srv  sys  tmp  usr  var
[root@83ae0f3b3997 /]# exit
exit

tail -f /var/log/messagesの方はどういう出力になっているでしょうか。
こんな感じです。

Jul 27 01:22:38 localhost kernel: docker0: port 1(veth1faa836) entered forwarding state
Jul 27 01:25:07 localhost docker/83ae0f3b3997[2510]: [root@83ae0f3b3997 /]# ps
Jul 27 01:25:07 localhost docker/83ae0f3b3997[2510]: PID TTY          TIME CMD
Jul 27 01:25:07 localhost docker/83ae0f3b3997[2510]: 1 ?        00:00:00 bash
Jul 27 01:25:07 localhost docker/83ae0f3b3997[2510]: 13 ?        00:00:00 ps
Jul 27 01:25:12 localhost docker/83ae0f3b3997[2510]: [root@83ae0f3b3997 /]# ls
Jul 27 01:25:12 localhost docker/83ae0f3b3997[2510]: bin  dev  etc  home  lib  lib64  lost+found  media  mnt  opt  proc  root  run  sbin  selinux  srv  sys  tmp  usr  var
Jul 27 01:25:13 localhost docker/83ae0f3b3997[2510]: [root@83ae0f3b3997 /]# exit
Jul 27 01:25:13 localhost docker/83ae0f3b3997[2510]: exit
Jul 27 01:25:13 localhost kernel: docker0: port 1(veth1faa836) entered disabled state

どうでしょうか。
rsyslogでうまく制御できれば、ファイルに分けて出力したり、負荷分散したり、転送したり。。。
利用する方法はありますよね。

注意事項

「--log-driver=syslog 」を利用した場合は、/var/lib/docker/containers/(コンテナID)/(コンテナID)-json.logには出力されません。したがって、docker logsコマンドログを表示することはできません。

syslogに出力しよう(2)

ここでは、アプリケーションで出力するsyslogをホスト側に記録する方法を記載します。

syslogはどういう経路で保存されているのでしょうか。
syslogは、/dev/log経由でログデータの受け渡しがされています。
詳細は、UNIXサーバの運用管理で欠かせないログ管理 (1/2)を参考にしていただければと思います。

つまり、Dockerでコンテナを実行する際に、「-v」オプションを指定することで利用可能になります。
　※参照：docker run

以下のように実行します。

# docker run -it -v /dev/log:/dev/log --name test03 centos:6 /bin/bash 
[root@a33d9166db48 /]#
[root@a33d9166db48 /]# logger -p local2.info "a33d9166db48 - Message" -t "DOCKER"

/var/log/messsagesにはどのように出力されたでしょうか。
こんな感じです。

Jul 27 01:54:12 localhost DOCKER: a33d9166db48 - Message

最後に

Dockerのログについて調べました。
実行した結果を標準でログに残してくれるのでたいへん助かります。
実際には標準出力していないソフトウェアも多いので、syslogで出力しているログをホストに保存できると非常に助かりますね。