メインコンテンツまでスキップ

go言語におけるロギングについて

Sato Taichi

僕は Java 方面に慣れていますのでslf4j(Logback)やlog4j2の様なロギングライブラリがあると扱い易いなぁ…と思う次第です。

まとめ#

例によって結論から書くと XML で設定する事に耐えられる ならseelogがオススメ。

CLI で指定出来る程度の設定が出来れば良いなら、公式リリースなglogがオススメ。

標準のlogパッケージについて#

まず、僕の開発環境は Windows7 ですので、log/syslog を直接使うようなコードは避けたいのです。

加えて、コードをあまり変更せずに出力先や出力内容を変更したいのですけども、その為の標準的な方法は機能としてライブラリ内に組込まれていません。

テスティングフレームワークの時も同様に感じましたけども、go 言語のコアライブラリは本当に一番下の足回りがあるのみです。

例えば、設定可能な項目はこれだけです。抜粋すると、

  • 時間や日付をどういう単位で出力するか？(日付、時間、マイクロ秒)
  • ログを出力した.go ファイルのパスをどう出力するか？(出さない、絶対パス、ファイル名のみ)

Loggerという型は定義されているので、設定可能なロギングフレームワークを実現する足回りはきちんと揃っています。

Logger 毎に抱え込んだ Mutex を使ってログの出力処理を同期している部分を見ると、パフォーマンス上の不安が 少しだけ ありますが、それでも複数の goroutine から安全に呼び出せるので面倒は少ないでしょう。

サンプルコード#

package main
import (    "log"    "os")
func main() {    useGlobalLogger()    useLogger()}
func useGlobalLogger() {    log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile)    log.SetPrefix("gyappa gyappa ")    log.Println("Hello logging")}
func useLogger() {    logger := log.New(os.Stderr, "**** ", log.LstdFlags|log.Llongfile)    logger.Fatalf("Hey!! %s", "logging")}

golang/glog#

インストール#

go get github.com/golang/glog

解説#

Google で開発してるC++の glogを golang にポートしたライブラリで、あまりドキュメントがありません。またファイルと標準出力にしかログを出力出来ません。

コード量的には極めてコンパクトなのでコード読んで使うライブラリです。

このライブラリを使う上で確実に抑えておくべき事柄はflag.Parse()の呼び出しを忘れない様にする事です。

glog.go#init を見れば分かる様にコマンドラインオプションを追加しているもののオプションのパーズを終了していません。

これは、呼び出し元のコードが更にオプションを追加出来る様にやっているのですけども、一見すると処理が不完全である様に感じますね。

確実に理解しておかなければならない事柄はもう一つあります。FATAL レベルのログを出すとプロセスが exit(255)するという事です。

これは、C++版でも同様の実装になっているのである種の方面では常識なのかもしれませんが、僕はびっくりしました。

サンプルコード#

  • main.go
package main
import (    "flag"    "github.com/golang/glog")
func main() {    flag.Parse()
    glog.Info("IINNFF")    glog.Warning("WWWWaaarn")    glog.Error("ERRR")
    glog.V(3).Infoln("<<<", 3333, ">>>")
    XXXXX()    ZZZZZ()}
  • a_x.go
package main
import "github.com/golang/glog"
func XXXXX() {    glog.Error("ERR : XXXXX")    glog.V(2).Info("V2 *** XXXXX ***")    glog.V(3).Info("V3 --- XXXXX ---")}
  • a_z.go
package main
import "github.com/golang/glog"
func ZZZZZ() {    glog.Error("ERR : ZZZZZ")    glog.V(2).Info("V2 *** ZZZZZ ***")    glog.V(3).Info("V3 --- ZZZZZ ---")}

コマンドラインオプションについて#

分かり辛いので、僕の分かった事だけをメモしておきます。

ログの出力処理はglog.go#outputを読めば大体分かります。

-logtostderr#

これを指定すると、ログを標準出力します。例えば、以下の様に指定します。

  • glog.exe -logtostderr
  • glog.exe -logtostderr=true

このオプションと、後述する-log_dirオプションの両方が指定されないと、-stderrthresholdで指定する severity 未満のログは、亜空間に消えてしまいます。

-alsologtostderr#

これを指定すると、ログをファイルと標準出力の両方に出力します。

-stderrthreshold#

標準出力する severity を設定します。デフォルトは ERROR ですが以下の 4 種類を指定できます。

  • INFO
  • WARNING
  • ERROR
  • FATAL

-logtostderrもしくは-alsologtostderrを指定しなくとも、-stderrthreshold=INFOを指定することで全てのログを標準出力できます。

-log_dir=""#

ログファイルを出力するディレクトリを指定します。これを指定しない場合、OS 毎のテンポラリディレクトリにログが出力されます。

例えば、Windows の場合は、TEMP環境変数にディレクトリパスが設定されています。

当該ディレクトリ内には severity 毎にファイルが作成されます。どんなファイル名になるかはglog_file.go#logNameを見て下さい。

-log_backtrace_at#

ログを出力しているコードのファイル名と行番号を指定すると前後のスタックトレースがログに出力されます。

但し、当該行がログに出力されるようオプションが構成されていなければなりません。

例えば、a_z.goの 6 行目にあるログの出力処理でついでにスタックトレースを出力するには、-log_backtrace_at=a_z.go:6とオプションを指定します。

後述する vmodule オプションとの決定的な違いはファイル名のサフィックスである.goを省略しない事です。

-v=0#

glog#V 関数を使っている個所を制御出来ます。

このオプションで設定した値以下の数値を glog#V 関数に渡している部分のログだけが出力されます。

後述の -vmoduleオプションと設定が重複する場合、値の大きい方が優先されます。

-vmodule=""#

一番柔軟にログ出力制御する為のオプションです。

但し、glog#V 関数を使っている個所のみ制御出来ます、加えて、必ず INFO レベルのログになります。

まず、-vmodule オプションは、,(カンマ)区切りで値を設定できます。

カンマで区切られた、それぞれの値は=(イコール)で名前とレベルに分割されます。

その名前としては拡張子の.goを抜いたファイル名もしくは、glob 形式のパターンを設定出来ます。

例えば、上記の 3 つのファイルを想定してオプションを指定すると以下のようになります。尚、vmodule オプションによって対象を明示しない場合、レベルは 0 とみなされます。

  • -vmodule=main=3
    • main.go において glog.V(3)以下のログが出力される
  • -vmodule=main=3,a_x=2
    • main.go において 3 以下、加えて、a_x.go において 2 以下のログが出力される
  • -vmodule=a_z=2,*_x=3
    • a_z.go において 2 以下、_x.goをサフィックスとするモジュールにおいてログが出力される。

対象が重複している場合は、より左にある定義が優先されます。

PowerShell で動かしている場合の落とし穴#

PowerShell では、.(ドット)や,(カンマ)や:(コロン)には特別な意味がありますのでコマンドの一部に含まれている場合には、オプションの一部を明確に文字列であると宣言しなければなりません。

例えば、.\glog.exe -vmodule=a_z=2,*_x=3というコマンドを実行すると、glog.exe には、-vmodule=a_z=2と*_x=3の二つのオプションが渡されますので期待した動作になりません。

期待した動作にする為には一まとめにしたい部分を.\glog.exe "-vmodule=a_z=2,*_x=3"のように"(ダブルクォート)でくくります。

cihub/seelog#

インストール#

go get github.com/cihub/seelog

ドキュメント#

ドキュメントがちゃんと書いてあるので使い易いです、はい。

解説#

まずもって、ロギングの処理がデフォルトで非同期です。同期化する方法はありますけども、それは開発環境のみでそうするのが良いよとの事。

次に、非常に残念な事ですが設定ファイルが XML です、はい。

<seelog>    <outputs>        <console formatid="colored"/>    </outputs>    <formats>        <format id="colored"  format="%EscM(46)%Level%EscM(49) %Msg%n%EscM(0)"/>    </formats></seelog>
package main
import log "github.com/cihub/seelog"
func main() {    defer log.Flush()    loadConfig()    log.Info("IINNFF")    log.Warn("WWWWaaarn")    log.Error("ERRR")}
func loadConfig() {    logger, err := log.LoggerFromConfigAsFile("seelog.xml")
    if err != nil {        panic("fail to load config")    }
    log.ReplaceLogger(logger)}

例によってWindows では色が付いたりはしないんですけどね。

windows でコマンドラインコンソールに色をつけたければANSICONを導入すると良いでしょう。

ANSICON

こうなるとエラーレベル毎に色が違って欲しい感じがあります。

Filterの機能を使うとこんな風に書けます。

<seelog>    <outputs formatid="simple">        <filter levels="info">            <console/>        </filter>        <filter levels="warn">            <console formatid="warn"/>        </filter>        <filter levels="error,critical">            <console formatid="error"/>        </filter>    </outputs>    <formats>        <format id="simple" format="%Level %Msg%n"/>        <format id="warn" format="%EscM(33)%Level%EscM(39) %Msg%n%EscM(0)"/>        <format id="error" format="%EscM(31)%Level%EscM(39) %Msg%n%EscM(0)"/>    </formats></seelog>

今度はレベル毎に色分けされましたね。 colored

今一歩なライブラリ#

  • op/go-logging
    • 出力先をカスタマイズする為の抽象化レイヤーはあるものの、コードを変更せずにそれらを切替える方法が無い為パス。
  • log4go
    • 一年以上メンテナンスされていない上に mercurial をインストールしないと使えないのでパス。

運用時ロギングについて#

今回の探索範囲とは若干ずれているので参考情報として挙げておきます。

まとめ

使い易いロギングフレームワークが欲しければ自分で作れ的な話はあるものの、出力するログの量次第ではロギングフレームワークのせいで、アプリケーションのパフォーマンスが大きく劣化するなんて事はある訳で悩ましいですね。

実際、GitHub 辺りを探すと go で実装されたロギングライブラリ的なものは散見されます。単純なものは作り易いけれども、本気なものを作るのは凄く大変なのもロギングライブラリです。

そもそもログというものの位置づけをキチンと定義してアプリケーションを実装するには相応の知識と経験が必要なので、最初のうちは雑にやっても後でそれなりに何とかなる方法でやりたいものです。