Log パッケージで遊ぶ

今回は Go 言語の標準パッケージに含まれる log について。

log パッケージは,名前の通り,ログ出力を行うパッケージである。 例えば以下のように書ける。

package main

import (
    "log"
)

func main() {
    log.Println("Hello, World")
}

これを実行すると以下のフォーマットで標準エラー出力に出力される。

2009/11/10 23:00:00 Hello, World

Log パッケージの中身

具体的に log パッケージを見てみよう。

// A Logger represents an active logging object that generates lines of
// output to an io.Writer. Each logging operation makes a single call to
// the Writer's Write method. A Logger can be used simultaneously from
// multiple goroutines; it guarantees to serialize access to the Writer.
type Logger struct {
    mu     sync.Mutex // ensures atomic writes; protects the following fields
    prefix string     // prefix to write at beginning of each line
    flag   int        // properties
    out    io.Writer  // destination for output
    buf    []byte     // for accumulating text to write
}

// Printf calls l.Output to print to the logger.
// Arguments are handled in the manner of fmt.Printf.
func (l *Logger) Printf(format string, v ...interface{}) {
    l.Output(2, fmt.Sprintf(format, v...))
}

// Output writes the output for a logging event. The string s contains
// the text to print after the prefix specified by the flags of the
// Logger. A newline is appended if the last character of s is not
// already a newline. Calldepth is used to recover the PC and is
// provided for generality, although at the moment on all pre-defined
// paths it will be 2.
func (l *Logger) Output(calldepth int, s string) error {
    now := time.Now() // get this early.
    var file string
    var line int
    l.mu.Lock()
    defer l.mu.Unlock()
    if l.flag&(Lshortfile|Llongfile) != 0 {
        // Release lock while getting caller info - it's expensive.
        l.mu.Unlock()
        var ok bool
        _, file, line, ok = runtime.Caller(calldepth)
        if !ok {
            file = "???"
            line = 0
        }
        l.mu.Lock()
    }
    l.buf = l.buf[:0]
    l.formatHeader(&l.buf, now, file, line)
    l.buf = append(l.buf, s...)
    if len(s) == 0 || s[len(s)-1] != '\n' {
        l.buf = append(l.buf, '\n')
    }
    _, err := l.out.Write(l.buf)
    return err
}

ログ出力時は log.Logger 内部のバッファを使って整形するため,複数の goroutine から非同期に呼ばれる可能性を考慮し, sync.Mutex を使って排他的に処理している。

Log のカスタマイズ

log パッケージではログの出力先や出力フォーマットをある程度カスタマイズできる。 たとえば,こんな感じ。

package main

import (
    "log"
    "os"
)

func main() {
    log.SetFlags(log.LstdFlags | log.Lmicroseconds | log.Lshortfile)
    log.SetOutput(os.Stdout)
    log.SetPrefix("[Hello] ")

    log.Println("Hello, World")
}

この場合,以下の形式で標準出力に出力される。

[Hello] 2009/11/10 23:00:00.000000 main.go:13: Hello, World

また log.New() 関数で新たな log.Logger インスタンスを作成することもできる。

package main

import (
    "log"
    "os"
)

func main() {
    l := log.New(os.Stdout, "[Hello] ", log.LstdFlags|log.Lmicroseconds|log.Lshortfile)

    l.Println("Hello, World")
}

このコードのログ出力は先ほどと同じになる。

出力レベルとフィルタリング

log パッケージの欠点は出力のフィルタリングができないことである。 ログメッセージ毎に ERROR, WARN, INFO, DEBUG といった出力レベルの設定を行い,あらかじめ指定したレベル以下のメッセージについてはフィルタリングできる仕掛けが欲しいところである。

サードパーティーではフィルタリング機能を持つ logger が色々あるが,せっかく log パッケージが「できる子」なんだから,なるべく生かした形で実装を考えてみる。

フィルタリング付き Writer

まずは,出力時にフィルタリングを行う Writer を考えてみる。 有り難いことに既にこの機能を持ったパッケージが存在する。

これは log.Logger インスタンスにセットする Writer をラップしてフィルタリング機能を付加するものである。 こんな感じで使うらしい。

package main

import (
    "log"
    "os"

    "github.com/hashicorp/logutils"
)

func main() {
    filter := &logutils.LevelFilter{
        Levels:   []logutils.LogLevel{"DEBUG", "WARN", "ERROR"},
        MinLevel: logutils.LogLevel("WARN"),
        Writer:   os.Stderr,
    }
    log.SetOutput(filter)

    log.Print("[DEBUG] Debugging")         // this will not print
    log.Print("[WARN] Warning")            // this will
    log.Print("[ERROR] Erroring")          // and so will this
    log.Print("Message I haven't updated") // and so will this
}

これを実行するとこんな感じになる。

2009/11/10 23:00:00 [WARN] Warning
2009/11/10 23:00:00 [ERROR] Erroring
2009/11/10 23:00:00 Message I haven't updated

あらかじめキーワード("DEBUG" など)を決めておいて,ログ出力する文字列にこのキーワードを埋め込むことで出力レベルの設定とフィルタリングを行うようだ。 実際には埋め込むキーワードの typo を防ぐために何らかの仕掛けを作る必要があると思うが,とてもシンプルな作りなので,気軽に導入できそうである。

Logger に渡す前にフィルタリングする

hashicorp/logutils は Writer への書き込み時にフィルタリングを行うものだったが,別のアプローチで log.Logger に渡す前にフィルタリングすることを考えてみる。 というわけで作ってみた。

logf.Logger はこんな感じで log.Logger インスタンス(へのポインタ)を内部に持つ。

//Logger is logger class
type Logger struct {
    lg   *log.Logger // logger
    mu   sync.Mutex  // ensures atomic writes; protects the following fields
    flag int         // properties
    min  Level
}

実際の出力はこんな感じにしてみた。

//Output writes the output for a logging event.
func (l *Logger) Output(lv Level, calldepth int, s string) error {
    if lv >= l.min {
        if (l.flag & Llevel) != 0 {
            return l.lg.Output(calldepth, fmt.Sprintf("[%v] %s", lv, s))
        }
        return l.lg.Output(calldepth, s)
    }
    return nil
}

出力レベルのチェック時に排他処理を行っていないが,値の参照だけで状態を変えるわけではないので,まぁいいかなと。

これを使ってログ出力のコードを書いてみる。

package main

import (
    "os"

    "github.com/spiegel-im-spiegel/logf"
)

func main() {
    logf.SetOutput(os.Stdout)
    logf.SetMinLevel(logf.WARN)

    logf.Debug("Debugging")   // this will not print
    logf.Print("Information") // this will not print
    logf.Warn("Warning")      // this will
    logf.Error("Erroring")    // and so will this
}

これを実行するとこんな感じになる。

2009/11/10 23:00:00 [WARN] Warning
2009/11/10 23:00:00 [ERROR] Erroring

んー。 杜撰なコードだが,取り敢えずこんな感じかな。

【追記】ログファイルの分割とローテーション

もうひとつ log パッケージにない機能としてログファイルの分割とローテーション機能がある。 たとえば Apache HTTP Serverrotatelogs のような機能があると便利である。

と思って探したらありましたよ。

rotatelogs パッケージと先ほどの logf パッケージを組み合わせれば,こんな感じに書ける。

package main

import (
    rotatelogs "github.com/lestrrat-go/file-rotatelogs"
    "github.com/spiegel-im-spiegel/logf"
)

func main() {
    logf.SetMinLevel(logf.WARN)
    rl, err := rotatelogs.New("./log.%Y%m%d%H%M.txt")
    if err != nil {
        logf.Fatal(err)
        return
    }
    logf.SetOutput(rl)

    logf.Debug("Debugging")   // this will not print
    logf.Print("Information") // this will not print
    logf.Warn("Warning")      // this will
    logf.Error("Erroring")    // and so will this
}

よーし,うむうむ,よーし。

ブックマーク

構造化ログ

その他

参考図書

photo
プログラミング言語Go (ADDISON-WESLEY PROFESSIONAL COMPUTING SERIES)
Alan A.A. Donovan (著), Brian W. Kernighan (著), 柴田 芳樹 (翻訳)
丸善出版 2016-06-20
単行本(ソフトカバー)
4621300253 (ASIN), 9784621300251 (EAN), 4621300253 (ISBN), 9784621300251 (ISBN)
評価     

著者のひとりは(あの「バイブル」とも呼ばれる)通称 “K&R” の K のほうである。この本は Go 言語の教科書と言ってもいいだろう。

reviewed by Spiegel on 2016-07-13 (powered by PA-APIv5)


  1. lestrrat-go/file-rotatelogs パッケージは Perl の File::RotateLogs から Go 言語へのポーティングのようだ。 ↩︎