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

僕は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を見て下さい。

-logbacktraceat

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

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

例えば、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で実装されたロギングライブラリ的なものは散見されます。単純なものは作り易いけれども、本気なものを作るのは凄く大変なのもロギングライブラリです。

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