【Go】お手軽ログ出力モジュール

概要

ロギングモジュールなんてN番煎じだと思いますが、あくまで自分用ということで作ってみることにしました。これは、その記録となります。

要件

ログ出力の要件は次の通りです。

• log/slog と natefinch/lumberjack を組み合わせて構造化ロギング＆ログローテーションを行う。
• ログの内容を標準出力にも出力する。
• できる限り簡単に利用できるようにする。
  • その際のデフォルトのオプションは自分好みにしておく。
  • でも、オプションも変更できるようにしておく。

経緯

ちょっとしたツールを作るとき、最近はGoで書くことが増えてきました。
他の人に使ってもらうときに、単独のバイナリにビルドできることや簡単にクロスコンパイルできることがとても便利です。

そういったツールを書くとき、ログを出力しておきたいことがよくあります。
ツールを定期的に実行しっぱなしにすることもよくあるので、ログローテーションも欲しいですね。
あと、手元で実行したときは標準出力に今回分のログが表示されると便利です。

Goでログ出力するには、標準ライブラリの log/slog を使うのが良さそうですが、ログローテーション機能は無いようなので、オープンソースの natefinch/lumberjack と組み合わせて使うことになりそうです。それに、slog の標準のログフォーマットはちょっと好みではないので、カスタマイズもしたいです。

毎回これらを実現するための同じようなコードを書いてられないので、再利用可能なモジュールにしてしまいましょう。Goで公開モジュールを作る練習もしてみたかったところなので丁度良かったです。

公開したモジュール

できたのがこちらです。

https://github.com/bugph0bia/go-logging

簡単な使い方

デフォルトでログ出力したければ、以下のように使えます。

package main

import (
    "log/slog"

    "github.com/bugph0bia/go-logging"
)

func main() {
    // 「log.txt」にログ出力するように設定
    slog.SetDefault(logging.NewLogger("log.txt"))

    // ログ出力
    slog.Info("message1")
    slog.Error("message2", "foo", 10, "bar", "abc") // 属性を指定
}

こんな感じのログが出力されます。

2024/10/24 11:22:33 INFO: message1
2024/10/24 11:22:33 ERROR [foo=10, bar=abc]: message2

標準出力にも同じ内容が出力されますし、ログローテーションも行われます。

動作を変更したい場合は、オプションを指定します。
そのためには、一度ハンドラを作ってからロガーを生成する必要があります。

    // ハンドラを生成
    handler := logging.NewHandler("log.txt")

    // オプション指定
    // ...

    // ハンドラからロガーを生成
    slog.SetDefault(logging.NewLoggerFromHandler(handler))

利用できるオプションは下記の通りです。

■基本的なオプション

用途	型	変数	デフォルト値
出力するログレベル	slog.LogLevel	handler.Option.Level	slog.LevelInfo
標準出力にもログを出力	bool	handler.Option.WithStdout	true

■書式に関するオプション

用途	型	変数	デフォルト値
ログの書式 (※1)	string	handler.Format.Line	fmt.Sprintf("${Datetime} ${Level} ${Attrs}: ${Message}")
日時の書式 (※2)	string	handler.Format.Datetime	"2006/01/02 15:04:05"
属性のキーと値の間の文字	string	handler.Format.AttrBetween	"="
属性間の区切り文字	string	handler.Format.AttrDelimiter	", "
属性リストの接頭辞	string	handler.Format.AttrPrefix	"["
属性リストの接尾辞	string	handler.Format.AttrSuffix	"]"

■ログローテーションに関するオプション
（natefinch/lumberjack に指定できるオプションほぼそのまま）

用途	型	変数	デフォルト値
ログファイルの最大サイズ(MB)	int	handler.RotateLogger.MaxSizeMB	1
バックアップファイルの最大数 (※3)	int	handler.RotateLogger.MaxBackups	10
バックアップファイルの最大保持日数 (※2)	string	handler.RotateLogger.MaxAge	0
バックアップファイル名に付与する日時をローカルのものにする	bool	handler.RotateLogger.LocalTime	true
バックアップファイルを gzip 圧縮する	bool	handler.RotateLogger.Compress	false

• ※1
  • ログの書式を指定するために、${xxx} というスタイルの書式指定子を用意してあります。
  • ${Datetime} ${Level} ${Attrs} ${Message} の4種類があり、それぞれ、日時、ログレベル、属性リスト、ログメッセージです。
  • 書式指定子は定数も用意してあるので、デフォルト値の書式は fmt.Sprintf("%s %s %s: %s", logging.FDatetime, logging.FLevel, logging.FAttrs, logging.FMessage) のようにも書けます。
• ※2
  • Go標準の time パッケージと同じ書式です。
• ※3
  • 0 を指定すると「上限なし」の意味になります（natefinch/lumberjack の仕様です）。

得られた知見

ログ出力に関して

• slog/log と natefinch/lumberjack の使い方。
  • またその便利さを実感しました。
• slog/log でログの書式を変更する方法。
• ファイル出力や標準出力を伴うテストの書き方。

モジュールの公開に関して

• github.com を使ってモジュールを公開するのはとても簡単。
  • 最初は、自前で立てたリポジトリサーバーで公開しようと試行錯誤しましたが、結局断念しました。うまくいかなかった要因は、ローカルネットワーク内だったので http で公開していたこと、8080 ポートで公開していたこと、の２点です（http://foo.bar:8080/... って感じのURLだったということです）。Goは、https(443ポート)経由でしかモジュールをダウンロードしてくれないようですね。

おまけ：ログ出力のテストを書く

単純に関数から返される値に対してテストするなら簡単なのですが、出力されたログファイルや標準出力の内容をテストしなければならなかったので一工夫必要でした。

①直前に出力されたログを取得する

これは、単純にログファイルの最終行を取得してこればよいです。
ちゃんと書くならファイルオープン後に最終行までシークする必要があるんですが、面倒なので先頭から行を読み捨てて最終行まで辿り着く方法にしました。
テスト中のログファイルは大したサイズではないのでこの妥協案でも良いという考えです。

こんな関数を用意することで解決しました。

// 最終ログを取得
func lastLog() string {
	f, err := os.Open(logfile)
	if err != nil {
		return ""
	}
	defer f.Close()

	// 最終行まで読み捨てる
	// テスト上はログファイルは大きくならないためこの方法で問題なし
	scanner := bufio.NewScanner(f)
	var line string
	for scanner.Scan() {
		line = scanner.Text()
	}
	return line
}

②テスト終了後にログファイルを削除する

立つ鳥跡を濁さず。家に帰るまでが遠足也。
テストもそれに倣うべきです。テスト中に生成されたファイルは削除しなければらないですね。

Goのテスト機能にはクリーンナップという仕組みがあり、テスト終了後に行いたい処理を指定することができます。この機能を使ってログファイルを削除すればよいと考えましたが、うまくいきませんでした。
どうやら、natefinch/lumberjack を使用するとパッケージ内でファイルハンドルを掴んだ状態になるようで、それが原因でファイル削除に失敗しているようです。

では、ファイルを明示的に閉じてから削除する処理をクリーンナップに登録すれば解決です。

	t.Cleanup(func() {
		// lumberjack がファイルを開いているため Close してから削除する必要がある
		handler.RotateLogger.Close()
		os.Remove(logfile)
	})

③標準出力の内容を取得する

ログを標準出力にも出力する機能を用意してしまったばかりに、こちらもテストをしなければなりません。

次の関数を用意してテストコードの前に呼び出すことで、これから出力される標準出力の内容をキャプチャすることができます。

// 標準出力のキャプチャを開始
func startStdoutCapture() (r *os.File, w *os.File, orgStdout *os.File) {
	// パイプを作成して標準出力をフック
	r, w, _ = os.Pipe()
	orgStdout = os.Stdout
	os.Stdout = w
	return
}

テストコードの後で、キャプチャされた内容を返す関数を呼び出せば目的達成です。キャプチャを解除することも忘れずに。

// 標準出力のキャプチャを終了
func endStdoutCapture(r *os.File, w *os.File, orgStdout *os.File) string {
	// 標準出力のフックを終了
	os.Stdout = orgStdout
	w.Close()

	// パイプを通して標準出力の内容を取得する
	var buf bytes.Buffer
	io.Copy(&buf, r)
	return buf.String()
}