はじめに

背景

とあるプラグイン開発をしていて、そのプラグインのためのライブラリ群にはログを吐く方法がちゃんと整備されていないことに気が付いた。
"終了コードが0以外の場合のみログにエラーを吐く"仕様なので、状況確認やコード修正時のデバッグが厄介だ。

logrotateを気にしたりするのは面倒なので、Loggerライブラリを利用して簡単にログ出力をさせたい。しかし、Golangにはログ出力のための「log」ライブラリがあるが、こちらはさすがに非力で目的に合わない。

比較的メジャーで、使い勝手の良いLoggerライブラリを探してみた。

要件

以下の要件で探した。

fmt.Printf()に近しいコードで利用できる
ファイルに出力できる
一定期間/一定サイズで自動ローテートさせられる
ローテートしたファイルは世代管理される（増え続けない）

調査結果

これらの記事を参考にして、色々眺めてみる。

log4go

サイト: https://godoc.org/code.google.com/p/log4go

いかにも期待できる名前なのだが、試そうとすると

$ go get code.google.com/p/log4go
go: missing Mercurial command. See http://golang.org/s/gogetcmd
package code.google.com/p/log4go: exec: "hg": executable file not found in $PATH

Mercurialがインストールされていないとダメという。
もうこの時点でげんなりである。

glog

サイト: https://github.com/golang/glog

google-glogというC++ライブラリをGolangに移植したもののようだ。
一見シンプルで良さそうだったのだけれど、設定値を起動オプションで渡すという仕様がイマイチで、コードの中で完結させにくく、採用をやめた。

logrus

サイト: https://github.com/Sirupsen/logrus

高機能で、評判も良いのだが、ログローテートはこのライブラリ内では実装していないようだ。

Rotation
Log rotation is not provided with Logrus.

要件外なので、残念ながら今回の選定からは外す。

seelog

サイト: https://github.com/cihub/seelog

設定(ファイル)がXML形式というナンデ？？な実装だけど、高機能。ドキュメントも充実。
現時点では、これが大本命だ。

seelogを試す

インストール

$ go get github.com/cihub/seelog

サンプルコード

全文

なんていうか、色々突っ込みたいところがあるとは思うけど、雰囲気で察して欲しい。XMLがそのまま突っ込まれているのがカッコ悪い。

testcode.go

package main

import (
	"fmt"
	log "github.com/cihub/seelog"
	"os"
)

const logConfig = `
<seelog type="adaptive" mininterval="200000000" maxinterval="1000000000" critmsgcount="5">
<formats>
	<format id="main" format="%Date(2006-01-02T15:04:05.999999999Z07:00) [%File:%FuncShort:%Line] [%LEV] %Msg%n" />
</formats>
<outputs formatid="main">
	<filter levels="trace,debug,info,warn,error,critical">
		<console />
	</filter>
	<filter levels="info,warn,error,critical">
		<rollingfile filename="/tmp/log.log" type="size" maxsize="102400" maxrolls="1" />
	</filter>
</outputs>
</seelog>`

func initLogger() {
	logger, err := log.LoggerFromConfigAsBytes([]byte(logConfig))
	if err != nil {
		fmt.Println(err.Error())
		os.Exit(1)
	}
	log.ReplaceLogger(logger)
}

func main() {
	initLogger()
	defer log.Flush()

	log.Debugf("This is debug")
	log.Infof("This is info")
	log.Errorf("This is err")
}

解説: 動作について

importとmain()を見てもらえれば全てなのだが、

seelogライブラリを log という名前でimportし
initLogger() でlogモジュールを初期設定して
プログラム終了時に備えて log.Flush() をdeferしておき
log.レベル名関数 でログを出力する

という、logger系あるあるな利用方法で使える。
initLogger()の中身は、こういうもんだと思ってもらえたら。

ポイントは設定がXML形式だということ。
基本的にはオフィシャルのドキュメントを読むべきだが、以下では、サンプルコードの中でも疑問が湧いてきそうな部分について説明する。

解説: format

ログのフォーマットなのは推測できると思うが、「2006-01-02」ってなんやねん！ってなると思う。

オフィシャルの記載を読むと、GolangのTimeフォーマットに従えという記載が出てくる。

%Date(...) - date with format, specified in parentheses. Uses standard time.Format, so check http://golang.org/src/pkg/time/format.go for identifiers list. Use it like that: "%Date(2006-01-02)" (or any other format)

つまるところ、GolangのTimeフォーマットの冒頭に宣言されているフォーマットを使えということらしい。

私の例では、RFC3339Nanoを採用している。

解説: outputs / filter

XMLを読むと雰囲気はわかると思う。filterの数だけログは出力される。私の例では以下の2つに出力している。

console: コンソール
rollingfile: 容量か時間によってローテートするログファイル

<filter levels="foobar">のfoobarのあたりが冗長に見えるかもしれないが、これはseelogのfilterの動作が

「指定したログレベル以上を出力する」

ではなく、

「指定したログレベルを出力する」

という、本当にフィルターとして動作するからだ。
つまり、このサンプルでは

コンソールには全てのログレベルのログを出力
ログファイルにはInfoレベル以上を出力

としている。

解説: rollingfile

このルールでは「100KBになったら、最大1回だけローテート」する。
つまり、生ログと過去ログの2つだけが、合計200KBほどのサイズで、作られ続ける。

オフィシャルのここを読むと指定できる内容の詳細がある。

解説: seelog type="adaptive" ....

XMLの冒頭にあるのでおまじないのように見えるけれど、もちろんちゃんとした設定。
Loggerのパフォーマンスを決定づける大切な設定部分なのだが、私の用途ではきっちり設計する必要がなかったためサンプルに従っている。

正直、性能面は説明できないのでオフィシャルのここを読んでほしい。

試験実行

まず1回実行してみる。

$ ./testcode
2015-07-22T20:17:45.112677239+09:00 [testcode.go:main:31] [DBG] This is debug
2015-07-22T20:17:45.112881482+09:00 [testcode.go:main:32] [INF] This is info
2015-07-22T20:17:45.112887201+09:00 [testcode.go:main:33] [ERR] This is err

$ tail /tmp/log.log
2015-07-22T20:17:45.112881482+09:00 [testcode.go:main:32] [INF] This is info
2015-07-22T20:17:45.112887201+09:00 [testcode.go:main:33] [ERR] This is err

コンソールには3行、ログファイルには2行が出力された。
これはfilter設定通りだ。

大量にログを吐いてみる。

$ while true; do ./testcode; done

しばらくしたら [Ctrl]+C

$ ls -lh /tmp/log.log*
-rw-rw-r-- 1 user user  50K Jul 22 20:18 /tmp/log.log
-rw-rw-r-- 1 user user 101K Jul 22 20:18 /tmp/log.log.1

100KBほどでローテートしたことが確認できた。
目的の「logrotateを考えない」が実現できた。 これで私には十分。

終わりに

誰かもっと簡単なライブラリか、もっと簡単な利用例を教えて下さい。