glogでDebug用ログ出力の関数を作るときの注意点

結論

以下のように、DEBUG環境変数が設定されているときに、ログ出力するような関数を定義した場合は、glog.XxxDepth(例ではglog.InfoDepth)を使いましょう。

package main

import (
    "flag"
    "fmt"
    "github.com/golang/glog"
    "os"
)

func DebugLog(v interface{}) {
    if os.Getenv("DEBUG") != "" {
        glog.InfoDepth(1, fmt.Sprintf("%#v", v))
    }
}

func main() {
    flag.Set("stderrthreshold", "INFO")
    flag.Parse()
    os.Setenv("DEBUG", "1")
    DebugLog("hoge") // ここが20行目
    DebugLog("fuga") // ここが21行目
}

出力結果は以下のようになります。

I0829 22:47:11.932758   24176 main.go:20] "hoge"
I0829 22:55:36.233685   24681 main.go:21] "fuga"

出力場所として、main.go:20 main.go:21 が情報として含まれていますね。多くの場合、DebugLog("hoge")やDebugLog("fuga")が記述されている行数を出力して欲しいので、意図通りとなっています。

InfoDepthの代わりにInfoを使うとどうなるのか

以下のように Info関数を使うとどうなるかを示します。

package main

import (
    "flag"
    "fmt"
    "github.com/golang/glog"
    "os"
)

func DebugLog(v interface{}) {
    if os.Getenv("DEBUG") != "" {
        glog.Info(fmt.Sprintf("%#v", v))  // ここが12行目
    }
}

func main() {
    flag.Set("stderrthreshold", "INFO")
    flag.Parse()
    os.Setenv("DEBUG", "1")
    DebugLog("hoge")
    DebugLog("fuga")
}

出力結果は以下のようになります。

I0829 22:57:00.569297   24777 main.go:12] "hoge"
I0829 22:57:00.569872   24777 main.go:12] "fuga"

はい、hoge の出力も fugaの出力もmain.go:12として出力されてしまっています。つまり glog.Infoを呼び出している箇所ですね。これが InfoDepthを使う理由となっています。