into the void

ソフトウェアに関する雑多な調査日記

syslogの使い方をあらためて整理してみた

syslogを使ったログ管理の方法をあらためて整理してみる。
syslogの実装は幾つかあるが、Ubuntuで標準搭載されているrsyslogを使うことにする。

OS Ubuntu Desktop 14.04.4 LTS
rsyslog rsyslog:amd64/trusty-updates 7.4.4-1ubuntu2.6 uptodate
logrotate logrotate:amd64/trusty 3.8.7-1ubuntu1 uptodate

ログの出力先を設定する

rsyslogの設定は下記のファイルで行う。

/etc/rsyslog.conf 共通設定
/etc/rsyslog.d/*.conf カスタマイズ設定

通常はrsyslog.confの方は編集せず、/etc/rsyslog.d/フォルダにファイルを追加して、そこにカスタマイズしたい設定を記入していく。

今回は自分で作ったアプリが出力するログについて、/var/log/myapp.logに出力する設定を追加する。

追加する設定ファイル /etc/rsyslog.d/myapp.conf
ログの出力先 /var/log/myapp.log
ログのファリシリティ local1
ログのレベル info以上

/etc/rsyslog.d/myapp.conf

$ cat /etc/rsyslog.d/myapp.conf 
local1.info	/var/log/myapp.log

rsyslogサービスを再起動する。

$ sudo services rsyslog restart

試しにloggerコマンドを使ってログを出力してみる。

$ logger -p local1.info "hello"

ちゃんと/var/log/myapp.confに出力されていることを確認する。

$ tail -f /var/log/myapp.log 
Sep 10 15:49:55 ik1-303-11997 samehada: hello

もう少し出力してみる。

$ logger -p local1.emerg 'it is emerg log'
$ logger -p local1.alert 'it is alert log'
$ logger -p local1.debug 'it is debug log'

myapp.logにはinfo以上のプライオリティのログが出力されている。debugプラオリティのログは出力されない。

$ tail -f /var/log/myapp.log 
Sep 10 15:49:55 ik1-303-11997 samehada: hello
Sep 10 15:53:22 ik1-303-11997 samehada: it is emerg log
Sep 10 15:53:32 ik1-303-11997 samehada: it is alert log

/var/log/syslogの方にはdebugログの出力されている。

$ tail -f /var/log/syslog
Sep 10 15:49:55 ik1-303-11997 samehada: hello
Sep 10 15:53:01 ik1-303-11997 samehada: emerg log
Sep 10 15:53:22 ik1-303-11997 samehada: it is emerg log
Sep 10 15:53:32 ik1-303-11997 samehada: it is alert log
Sep 10 15:54:28 ik1-303-11997 samehada: it is debug log

ログのフォーマットを設定する

いまログに出力されているのは

ログの出力時刻 %timegenerated%
ホスト名 %hostname%
タグ %syslogtag%
ログメッセージ %msg%

ファィリティとプライオリティも出力してみる。

ログのファリシティ %syslogfacility-text%
ログのプライオリティ %syslogpriority-text%

あとでデータベースに入れやすいように、デリミタをスペースからカンマに変えておく。

/var/log/myapp.conf

$ cat /etc/rsyslog.d/myapp.conf 
$template mytemplate, "%timegenerated%,%syslogfacility-text%,%syslogpriority-text%,%syslogtag%,%msg%\n"
local1.info	/var/log/myapp.log;mytemplate

出力してみる。

$ logger -p local1.info -t MYAPP 'start MYAPP'
$ cat /var/log/myapp.conf
Sep 10 17:24:44,local1,info,MYAPP:, start MYAPP

ログの出力時刻が秒精度でしか出ていないので、もっと高精度な値になるようにオプションを追加する。

ログの出力時刻 %timegenerated%:::date-rfc3339

最終的な設定ファイル。

$ cat /etc/rsyslog.d/myapp.conf 
$template mytemplate, "%timegenerated:::date-rfc3339%,%syslogfacility-text%,%syslogpriority-text%,%syslogtag%,%msg%\n"
local1.info	/var/log/myapp.log;mytemplate

ログ。マイクロ秒まで出力されている。

2016-09-11T20:23:36.244600+09:00,local1,info,TEST001:, this is a test
2016-09-11T20:23:46.247719+09:00,local1,info,TEST001:, this is a test

ログのローテーションの仕方を設定する

シスログで出力されるファイルは、logrotateによって定期的にローテート、圧縮される。
この設定は/etc/logrotate.d/rsyslogに書かれている。

$ cat /etc/logrotate.d/rsyslog 
/var/log/syslog
{
	rotate 7
	daily
	missingok
	notifempty
	delaycompress
	compress
	postrotate
		reload rsyslog >/dev/null 2>&1 || true
	endscript
}

/var/log/mail.info
/var/log/mail.warn
/var/log/mail.err
/var/log/mail.log
/var/log/daemon.log
/var/log/kern.log
/var/log/auth.log
/var/log/user.log
/var/log/lpr.log
/var/log/cron.log
/var/log/debug
/var/log/messages
{
	rotate 4
	weekly
	missingok
	notifempty
	compress
	delaycompress
	sharedscripts
	postrotate
		reload rsyslog >/dev/null 2>&1 || true
	endscript
}

syslogの設定

rotate 6 バックアップするログの数。6ファイル。
daily 毎日ローテートする。
missingok 出力先のログファイルが存在しなくてもエラー処理しない。
notifempty ログファイルのサイズが0の場合はローテートしない。
delaycompress ローテート直後に圧縮せず、次のファイルのローテート時に圧縮する。
compress 古いファイルを圧縮する
postrotate ローテート後に実行する処理。rsyslogをreloadする。

ログファイルの状況。

$ ls -al /var/log/syslog*
-rw-r----- 1 syslog adm 149633 Sep 10 18:05 /var/log/syslog
-rw-r----- 1 syslog adm  59460 Sep 10 06:25 /var/log/syslog.1
-rw-r----- 1 syslog adm   3957 Sep  9 06:25 /var/log/syslog.2.gz
-rw-r----- 1 syslog adm   2293 Sep  8 06:25 /var/log/syslog.3.gz
-rw-r----- 1 syslog adm   1166 Sep  7 06:25 /var/log/syslog.4.gz
-rw-r----- 1 syslog adm   1233 Sep  6 06:25 /var/log/syslog.5.gz
-rw-r----- 1 syslog adm   1290 Sep  5 06:25 /var/log/syslog.6.gz
-rw-r----- 1 syslog adm   2367 Sep  4 06:25 /var/log/syslog.7.gz

ローテート処理のトリガーはlogrotate自身ではなく、crondからひいてもらう。
そのため、crond側に設定が必要。通常はlogrotateをインストールすると/etc/cron.daily/logroateが作成される。

myappのログもsyslogと同じように毎日ローテートされるようにしてみる。
バックアップは一ヶ月(30日)分。圧縮あり。

$ cat /etc/logrotate.d/rsyslog 
/var/log/myapp.log
{
	rotate 30
	daily
	missingok
	notifempty
	delaycompress
	compress
	postrotate
		reload rsyslog > /dev/null 2>&1 || true
	endscript
}
...

ログをデータベースに格納してクエリで検索する

圧縮したログを解凍して、mysqlデータベースに入れてみる。

まずはmysqlをインストール。

$ sudo apt-get install mysql-server

ログ出力時刻をTIMESTAMP型でマイクロ秒まで格納したかったんだけど、mysqlでは5.6.4以降でDATE、DATETIME、TIMESTAMPの精度がマイクロ秒まで引き上げられた模様。
残念ながらubuntu 14.04.4のaptでインストールされるのは5.5。

5.6を入れ直す。

sudo apt-get install mysql-server-5.6

データベースとテーブルを作成。

mysql> create database myapp_log;
Query OK, 1 row affected (0.04 sec)

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| myapp_log          |
| mysql              |
| performance_schema |
+--------------------+
4 rows in set (0.00 sec)
mysql> create table myapp_info (timegenerated DATETIME(6), facility CHAR(10), priority CHAR(10), tag CHAR(10), msg VARCHAR(100));
Query OK, 0 rows affected (1.29 sec)

mysql> show tables;
+---------------------+
| Tables_in_myapp_log |
+---------------------+
| myapp_info          |
+---------------------+
2 rows in set (0.01 sec)

mysql> desc myapp_info;
+---------------+--------------+------+-----+---------+-------+
| Field         | Type         | Null | Key | Default | Extra |
+---------------+--------------+------+-----+---------+-------+
| timegenerated | datetime(6)  | YES  |     | NULL    |       |
| facility      | char(10)     | YES  |     | NULL    |       |
| priority      | char(10)     | YES  |     | NULL    |       |
| tag           | char(10)     | YES  |     | NULL    |       |
| msg           | varchar(100) | YES  |     | NULL    |       |
+---------------+--------------+------+-----+---------+-------+
5 rows in set (0.00 sec)