今日は、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] (https://docs.docker.com/reference/commandline/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コマンドには非常な便利なオプションがついています。
- docker logs -t (--timestamps)
- 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で出力しているログをホストに保存できると非常に助かりますね。