【Golang】Golang:logパッケージを読む

log パッケージを読みました。

src/log/log.go - The Go Programming Language

log

Go の log はロギング処理に使用するパッケージ。
log パッケージはテストコードを除けば log.go のみで構成されており、log.go も 400 数行からなるシンプルな構成となっている。
（ syslog が log パッケージ配下に置かれているが、それとは分けて話す ）

log パッケージ概要

// Package log implements a simple logging package. It defines a type, Logger,
// with methods for formatting output. It also has a predefined 'standard'
// Logger accessible through helper functions Print[f|ln], Fatal[f|ln], and
// Panic[f|ln], which are easier to use than creating a Logger manually.
// That logger writes to standard error and prints the date and time
// of each logged message.
// Every log message is output on a separate line: if the message being
// printed does not end in a newline, the logger will add one.
// The Fatal functions call os.Exit(1) after writing the log message.
// The Panic functions call panic after writing the log message.
package log

• ロギングに使用する Logger 型と、それに紐づくメソッド(Formatter など)を定義している
• Logger を明示的に生成してロギングするか、ヘルパ＝関数経由で標準 Logger によるロギングができる
  • ヘルパー関数を使用すると、標準 Logger がログメッセージに日付・時刻を付加する
• Logger 経由のロギングは以下の特徴を持つ
  • 1 ログにつき 1 行（カスタム Logger でなければ）
  • Fatal 系関数はロギング後 os.Exit(1)を呼ぶ
  • Panic 系関数はロギング後 panic を呼ぶ

Logger 構造体

// 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 on each line to identify the logger (but see Lmsgprefix)
    flag   int        // properties
    out    io.Writer  // destination for output
    buf    []byte     // for accumulating text to write
}

Logger 構造体は log パッケージが提供するロギング機能を実現するための構造体。

• mu: sync.Mutex 値。goroutine による並行処理上でも排他制御しつつロギングするために使用する。
• prefix : ログ行の先頭に付与する文字列。ただし、 Lmsgprefix を flag に指定するとメッセージの先頭に付与される。
• flag : ログの接頭辞を制御するフラグ。指定できるフラグは以下。ビットフラグになっており、 OR 演算で結合して複数指定できる。 ex. Ldate | Lmicroseconds
• out: io.Writer 実装型の値。ログの出力先。
• buf: ログ書き込み文字列のバッファ。

const (
    Ldate         = 1 << iota     // ローカルタイムゾーンの日時を次のフォーマットで表示: 2009/01/23
    Ltime                         // ローカルタイムゾーンの時刻を次のフォーマットで表示: 01:23:23
    Lmicroseconds                 // ローカルタイムゾーンの時刻を次のフォーマットで表示: 01:23:23.123123.  assumes Ltime.
    Llongfile                     // パス/ファイル名と行数を表示: /a/b/c/d.go:23
    Lshortfile                    // ファイル名と行数を表示、Llongfileを上書きする: d.go:23.
    LUTC                          // Ldate, Ltimeが設定されていた場合、タイムゾーンをUTCとする
    Lmsgprefix                    // prefixをログ先頭ではなくメッセージ先頭に移す
    LstdFlags     = Ldate | Ltime
)

Logger を明示的に作成して使用する

log パッケージには Logger 値参照を取得するヘルパー関数 New が提供されている。
引数の詳細は上記参照。

// New creates a new Logger. The out variable sets the
// destination to which log data will be written.
// The prefix appears at the beginning of each generated log line, or
// after the log header if the Lmsgprefix flag is provided.
// The flag argument defines the logging properties.
func New(out io.Writer, prefix string, flag int) *Logger {
    return &Logger{out: out, prefix: prefix, flag: flag}
}

Logger public メソッド

l := log.New(os.Stdout, "prefix: ", log.Ldate | log.Lmicroseconds | log.LUTC)
l.Println("Hello, Logger.")

Logger が使用できる出力系関数は以下。

func (l *Logger) Printf(format string, v ...interface{})
func (l *Logger) Print(v ...interface{})
func (l *Logger) Println(v ...interface{})
func (l *Logger) Fatal(v ...interface{})
func (l *Logger) Fatalf(format string, v ...interface{})
func (l *Logger) Fatalln(v ...interface{})
func (l *Logger) Panic(v ...interface{})
func (l *Logger) Panicf(format string, v ...interface{})
func (l *Logger) Panicln(v ...interface{})

これらの関数全ては、内部で Logger::Output 関数を呼び出している。

Logger::Output

Logger::Output は、各種出力系関数から呼ばれる汎用出力関数。
呼び出すごとに１行のログを出力する。

// 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 {
// ...
}

Logger の sync.Mutex を使用して排他制御をしているため、ロギングはスレッドセーフ（goroutine セーフ?）。

   l.mu.Lock()
    defer l.mu.Unlock()
    // ...
    _, err := l.out.Write(l.buf)
    return err

Logger.flag に Lshortfile Llongfile が設定されている場合、ファイル名・行数を取得するため、ロックを外して runtime.Caller を呼ぶ。

   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()
    }

Caller は runtime パッケージの関数で、ゴルーチンスタック中の関数呼び出し情報を取得できる。この関数呼び出しの情報の中にロギング時のファイル・行数情報が含まれていて、 Output ではそれを使う。

package runtime

import "runtime/internal/sys"

// Caller reports file and line number information about function invocations on
// the calling goroutine's stack. The argument skip is the number of stack frames
// to ascend, with 0 identifying the caller of Caller.  (For historical reasons the
// meaning of skip differs between Caller and Callers.) The return values report the
// program counter, file name, and line number within the file of the corresponding
// call. The boolean ok is false if it was not possible to recover the information.
func Caller(skip int) (pc uintptr, file string, line int, ok bool) {
    rpc := make([]uintptr, 1)
    n := callers(skip+1, rpc[:])
    if n < 1 {
        return
    }
    frame, _ := CallersFrames(rpc).Next()
    return frame.PC, frame.File, frame.Line, frame.PC != 0
}

フラグ指定による接頭辞を付与するために、 formatHeader を呼ぶ。

   l.buf = l.buf[:0]
    l.formatHeader(&l.buf, now, file, line)

formatHeader は Logger.flags ビットフラグに従い接頭辞を指定する。
接頭辞は以下の優先順位で付与される。

• Logger.prefix に指定した文字列
• 日時・時刻
• ファイル名・行数
• （ Lmsgprefix を Logger.prefix に設定した場合 ）Logger.prefix に指定した文字列

// formatHeader writes log header to buf in following order:
//   * l.prefix (if it's not blank and Lmsgprefix is unset),
//   * date and/or time (if corresponding flags are provided),
//   * file and line number (if corresponding flags are provided),
//   * l.prefix (if it's not blank and Lmsgprefix is set).
func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
// ...
}

あとは Logger.out に文字列を書き込む。
文字列末尾に改行が含まれていなければ追加する。

   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

Logger をヘルパー関数経由で使用する

log パッケージクライアントは Logger 型の値を生成しなくても、下記関数でロギング機能を使用することはできる。

func Printf(format string, v ...interface{})
func Print(v ...interface{})
func Println(v ...interface{})
func Fatal(v ...interface{})
func Fatalf(format string, v ...interface{})
func Fatalln(v ...interface{})
func Panic(v ...interface{})
func Panicf(format string, v ...interface{})
func Panicln(v ...interface{})

これらの関数は共通のローカル Logger 値である std を使用する。
std の出力先は os.Stderr であり、接頭辞として日付・時刻がつく。

var std = New(os.Stderr, "", LstdFlags)

上記関数群は内部で std.Output を呼び、ロギング処理を実行する。
std 経由で Logger メソッドを呼び出さない理由は不明（ユースケース別にあえて分けた？）。

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

参考文献

src/log/log.go - The Go Programming Language