Go 言語の log パッケージを使ってみる

Go 言語のいろいろなパッケージを使ってみるシリーズ（目次）。　今回は log パッケージ。

log パッケージには fmt パッケージのような Print 関連の関数がありますが、これらは fmt パッケージの同名の関数で書き出し時刻と改行を追加して表示します。　また、デフォルトでは標準出力ではなく標準エラー出力に書き出します。

【この記事の内容】

log パッケージ
Print 関連
Fatal 関連
Panic 関連
ログの設定
Logger 型
- 【修正】

log パッケージ

log パッケージのパッケージドキュメントはこちら。　log パッケージに定義されている関数には以下のようなものがあります：

// Print 関連
func Print(v ...interface{})
func Println(v ...interface{})
func Printf(format string, v ...interface{})

// Fatal 関連
func Fatal(v ...interface{})
func Fatalln(v ...interface{})
func Fatalf(format string, v ...interface{})

// Panic 関連
func Panic(v ...interface{})
func Panicln(v ...interface{})
func Panicf(format string, v ...interface{})

// ログの設定
func Prefix() string
func SetPrefix(prefix string)
func Flags() int
func SetFlags(flag int)
func Output(calldepth int, s string) error
func SetOutput(w io.Writer)

// 定数
const (
  Ldate         = 1 << iota
  Ltime
  Lmicroseconds
  Llongfile
  Lshortfile
  LUTC
  LstdFlags     = Ldate | Ltime
)

また、上記の関数と同じシグニチャを持つメソッドが定義された Logger 型もあります。　いろいろな設定を使い分けたい場合には Logger を複数生成して使います。

Print 関連

log.Print 関数

log.Print 関数は引数のメッセージに出力時間と改行を追加して標準エラー出力に書き出します：

  log.Print("Hello, world!")
  log.Print("Hello, world2!\n")  // 最後に改行をつける
  log.Print("Hello", ", " , "world", 3, "!")  // 複数の引数を与える

これを実行すると以下のように表示されます：

2017/09/28 22:19:30 Hello, world!
2017/09/28 22:19:30 Hello, world2!
2017/09/28 22:19:30 Hello, world3!

引数の文字列の最後に改行を入れても入れなくても、メッセージは改行されます（2度改行されて空行が表示されたりはしない）。　また、複数の引数を与えると fmt.Print 関数のように引数の自然な文字列表現をそのままつなげて出力します。

log.Println 関数

log.Println 関数を同様にして使うと

  log.Println("Hello, world!")
  log.Println("Hello, world2!\n")
  log.Println("Hello", ", " , "world", 3, "!")

これは以下のようなメッセージを表示します：

2017/09/28 22:39:42 Hello, world!
2017/09/28 22:39:42 Hello, world2!

2017/09/28 22:39:42 Hello ,  world 3 !

log.Println 関数は最後に改行があれば改行を入れるようです。　また、複数の引数がある場合はそれぞれの自然な文字列表現をスペースで連結して出力します。　これらの振る舞いをみると、log.Println 関数より log.Print 関数を使う方がよさそうですね。　実際には次の log.Printf 関数を使うことの方が多いと思いますが。

log.Printf 関数

log.Printf 関数は fmt.Printf 関数のように第1引数のフォーマットにしたがってログメッセージを出力します：

  log.Printf("Hello, %s%d!", "world", 1)
  log.Printf("Hello, world%d!\n", 2)
  log.Printf("Hello, world3!")

これを実行すると以下のようなログメッセージが表示されます：

2017/09/28 22:46:24 Hello, world1!
2017/09/28 22:46:24 Hello, world2!
2017/09/28 22:46:24 Hello, world3!

log.Print 関数のように、最後に改行があってもなくても改行され、空行が表示されたりはしません*1。

Fatal 関連

Fatal 関連の関数には

log.Fatal
log.Fatalln
log.Fatalf

があり、これらはそれぞれ対応する Print 関連関数にしたがってログメッセージを出力した後、os.Exit(1) を呼び出してプログラムを終了させます。　

たとえば以下のような "hello-world.txt" ファイルを開くプログラムで

func main(){
  f, err := os.Open("hello-world.txt")  // hello-world.txt ファイルを開く
  if err != nil {
    log.Fatal(err)  // エラーメッセージを表示してプログラムを終了
  }
  ...
}

"hello-world.txt" ファイルが存在しないとき、以下のようなエラーメッセージが表示されてプログラムが終了します：

2017/09/28 22:57:47 open hello-world.txt: The system cannot find the file specified.

Fatal 関連のメソッドはプログラムを終了させるので基本的には main 関数の中で使い、それ以外の場合はエラーを返して伝搬させていくべきです。

Panic 関連

Panic 関連の関数には

log.Panic
log.Panicln
log.Panicf

があり、これらは対応する Print 関連の関数でエラーメッセージを表示した後、パニックを起こします。

以下のような、割る数 y が0の場合にパニックを起こすコードに対して

func main(){
  div(2, 0)
}

func div(x, y float64) float64 {
  if y == 0 {
    log.Panicf("0での除算： %1.f/%1.f", x, y)
  }
  return x/y
}

これを実行すると以下のようなログメッセージを表示します（その後にスタックダンプも表示されますが）：

2017/09/28 23:14:56 0での除算： 2/0

パニックは呼び出し元にエラーを伝搬させずにプログラムを終了させるので、バグに分類される分岐（switch 文など）に到達した場合に使用します。

ログの設定

接頭辞 Prefix

log.Prefix / log.SetPrefix 関数はログメッセージの先頭に表示する接頭辞を取得/設定します：

// init 関数は main 関数の前に実行される初期化関数
func init(){
  log.SetPrefix("[TEST]")  // 接頭辞の設定
}

func main(){
  fmt.Println(log.Prefix())  // 接頭辞の取得
  log.Print("Hello, world!")
}

これを実行すると

[TEST]
[TEST]2017/09/28 23:33:59 Hello, world!

と表示されます。

フラグ Flag

ログの出力日時以外にも出力時の情報を付加したい場合には、log.SetFlag 関数によってフラグを設定します。　使用できるフラグは定数として定義されています：

const (
  Ldate         = 1 << iota  // 日付
  Ltime                      // 時刻
  Lmicroseconds              // 時刻のマイクロ秒
  Llongfile                  // ソースファイル（ディレクトリパスを含む）
  Lshortfile                 // ソースファイル（ファイル名のみ）
  LUTC                       // タイムゾーンに依らない UTC 時刻
  LstdFlags     = Ldate | Ltime  // 日付 (Ldata) と時刻 (Ltime) ：デフォルト
)

定数はビットフラグで定義されているので、| でまとめて設定できます：

func init(){
  // 時刻と時刻のマイクロ秒、ディレクトリパスを含めたファイル名を出力
  log.SetFlags(log.Ltime|log.Lmicroseconds|log.Llongfile)
}

func main(){
  log.Printf("Hello, world!")
}

これを実行すると以下のようなエラーメッセージが出力されます（一部省略）：

00:31:07.196881 C:/Users/waman/.../main.go:12: Hello, world!

特定のフラグが設定されているかどうかを見るには、Flags 関数で全フラグ（単なる int 値ですけど）を取得して & を使います：

  if log.Flags() & log.LUTC == 0 {
    fmt.Println("出力するのは UTC 時刻ではありません。")
  }else{
    fmt.Println("出力するのは UTC 時刻です。")
  }

出力先 Output

log.SetOutput 関数はログを出力する io.Writer を設定します。　たとえば標準エラー出力ではなく標準出力にログメッセージを表示させたい場合は

func init(){
  log.SetOutput(os.Stdout)
}

func main(){
  log.Print("Hello, world!")
}

とします。

log.Output 関数は（出力先の io.Writer を返すのではなく）呼び出しているコードの深さを指定してログメッセージを出力します（よく考えると「ログの設定」の箇所に書くのはおかしいですが ^^;）。　深さはフラグとして log.Llongfile もしくは log.Lshortfile を指定している場合のみ意味があります。　たとえば以下のようなコード

package main

import (
  "log"
)

func init(){
  log.SetPrefix("[TEST]")
  log.SetFlags(log.LstdFlags|log.Lshortfile)
}

func main(){
  outputLog()  // 13行目
}

func outputLog(){
  log.Output(1, "Hello, world!")  // 17 行目
}

を実行すると

[TEST]2017/09/29 00:52:13 main.go:17: Hello, world!

のように、呼び出し位置として log.Output 関数が呼び出された「main.go:17」が表示されますが、log.Output 関数の第1引数を1から2に変更して実行すると

[TEST]2017/09/29 00:55:26 main.go:13: Hello, world!

のように、呼び出し位置として outputLog 関数を呼び出した「main.go:13」が表示されます。

Logger 型

前節の設定では全てのログに設定が反映されてしまうので、一部のログに別の設定を行いたい場合は log.New 関数によって Logger オブジェクトを生成して設定を行います：

var wlog *log.Logger

func init(){
  wlog = log.New(os.Stdout, "[WAMAN]", log.LstdFlags|log.LUTC)
}

func main(){
  log.Print("Hello, world!")         // 普通のログ
  wlog.Print("Hello, Waman world!")  // カスタムログ
}