🐡
Go ログをjsonファイル出力する
はじめに
広大で寛大なネットの海にささやかな検索妨害を一粒添えさせていただきます。
モチベーション
個人開発のプロジェクトの運用でどのようにログを保管し、管理するかを考えたことが始まりです。
sentry に頼ったり、zerolog や logrus 等素晴らしいパッケージを使ってもいいけど、勉強も兼ねてどうせなら go の標準パッケージで自作してしまえと思い作りました。
go のいいところってやっぱり標準パッケージがちょうどいいところだと勝手に思っています。
ログをファイルに書き出す
後から読めるためにファイルでの保管を考えました。
こちらは log パッケージでとても簡単にできます。
logger.go
package domain
import (
".../configs"
".../tools"
"encoding/json"
"fmt"
"net/http"
"os"
"runtime"
"time"
)
const (
/******************
probrem
******************/
// urgency (at once)
LogAlert = "ALT"
// urgency (at many times)
LogCritical = "CRT"
// need fix without urgency (at many times)
LogWarn = "WAN"
/******************
no probrem
******************/
LogInfo = "INF"
/******************
no probrem
******************/
LogDebug = "DBG"
)
// log出力汎用関数
func ErrorLogger(err error, mode string) {
if IsProduction() {
today := time.Now().Format("20060102")
lFile, _ := os.OpenFile(fmt.Sprintf("%s/log_%s.log", configs.ErrorLogDirectory, today), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600)
defer lFile.Close()
// get called place
_, file, line, _ := runtime.Caller(1)
log.SetOutput(lFile) // 出力先の変更
log.SetFlags(log.LstdFlags) // 不要、フラグを付け足すときにはここにパイプで追加
// set prefix
var level string
switch mode {
case "":
level = LogInfo
default:
level = mode
}
log.SetPrefix(level+" ")
log.Println(fmt.Sprintf("%s:%d: %v", file, line, err))
} else {
log.Println(err)
}
}
少し解説します。
runtime を使って呼び出しもとの位置を取得します。
_, file, line, _ := runtime.Caller(1)
SetOutput メソッドでログの出力先を変えることができます。
log.SetOutput(lFile) // 出力先の変更
ここでは Laravel の Log ファサードみたいな形でログのレベルを接頭文字として与えています。
// set prefix
var level string
switch mode {
case "":
level = LogInfo
default:
level = mode
}
log.SetPrefix(level)
ここまでやって Println をするとこんな感じでファイル出力されます。
WAN 2021/07/28 08:05:56 /<秘密>/internal/pkg/interfaces/database/audience_repository.go:121: sql: Rows are closed
WAN 2021/07/28 08:05:58 /<秘密>/internal/pkg/interfaces/database/audience_repository.go:121: sql: Rows are closed
ログを json ファイルに書き出す
検索性を高め、階層化も可能な json にすることにしました。
json ファイル出力
その際にまず json ファイルへの書き出しで一工夫必要だったので、共有します。
json ファイル出力のやり方としては 2 通り考えました。
- 丸ごとファイルを上書きする
- 必要な分だけ、ファイルに追加する
1 のやり方を少し乱暴に感じたこと、ベンチマークをとった結果少しだけ 2 の方法の方が優れていたため 2 を結果的に採用しました。
1 のやり方とテストとその結果は一番最後に補足としてつけておきます。
2 のやり方(追記法)
logger.go
func writeJsonFile(fileName string, object interface{}) {
file, _ := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE, 0600)
defer file.Close()
fi, _ := file.Stat()
leng := fi.Size()
json_, _ := json.Marshal(object)
if leng == 0 {
file.Write([]byte(fmt.Sprintf(`[%s]`, json_)))
} else {
file.WriteAt([]byte(fmt.Sprintf(`,%s]`, json_)), leng-1)
}
}
まず書き込みたいものを json 化します。
次にファイルの長さを取得します。
新規ファイルであればそのまま出力、
そうでない場合最後の 1 文字(])を,<追加分>]の文字列で上書きしています。
エラーログを json にしてファイルに書き込む
先程の writeJson()を使ってこんな感じで書けます。
全文一気にいってしまいます。
logger.go
package domain
import (
"animar/v1/configs"
"animar/v1/internal/pkg/tools/tools"
"encoding/json"
"fmt"
"net/http"
"os"
"runtime"
"time"
)
const (
/******************
probrem
******************/
// urgency (at once)
LogAlert = "ALT"
// urgency (at many times)
LogCritical = "CRT"
// need fix without urgency
LogWarn = "WAN"
/******************
no probrem
******************/
LogInfo = "INF"
/******************
no probrem
******************/
LogDebug = "DBG"
)
// Logの基底構造体
type Log struct {
Kind string `json:"kind"`
Time time.Time `json:"time"`
Level string `json:"level"`
}
// Error用ログの構造体
type LogE struct {
Log
Content string `json:"content"` // エラー内容
Place string `json:"place"` // エラー発生場所
}
// Access用ログの構造体
type LogA struct {
Log
Address string `json:"address"` // IPアドレス
Method string `json:"method"` // request method
Path string `json:"path"` // path
}
func NewAccessLog() *LogA {
// startのlogをここで作る
alog := &LogA{
Log: Log{
Kind: "access",
},
}
return alog
}
func newErrorLog() *LogE {
eLog := &LogE{
Log: Log{
Kind: "error",
},
}
return eLog
}
func ErrorAlert(err error) {
e := newErrorLog()
e.Logging(err, LogAlert)
}
func ErrorCritical(err error) {
e := newErrorLog()
e.Logging(err, LogCritical)
}
func ErrorWarn(err error) {
e := newErrorLog()
e.Logging(err, LogWarn)
}
func (e *LogE) Logging(err error, level string) {
if tools.IsProductionEnv() {
e.write(err, level)
} else {
e.write(err, level)
}
}
func (a *LogA) Logging(r *http.Request) {
if tools.IsProductionEnv() {
a.write(r)
} else {
a.write(r)
}
}
func (a *LogA) write(r *http.Request) {
today := time.Now().Format("20060102")
a.Level = LogInfo
a.Time = time.Now()
a.Address = r.RemoteAddr
a.Method = r.Method
a.Path = r.URL.Path
writeJsonFile(fmt.Sprintf("%s/log_%s.json", configs.ErrorLogDirectory, today), a)
}
func (e *LogE) write(err error, level string) {
today := time.Now().Format("20060102")
e.Level = level
e.Content = err.Error()
// auto
_, file, line, _ := runtime.Caller(3))
e.Place = fmt.Sprintf("%s:%d", file, line)
e.Time = time.Now()
writeJsonFile(fmt.Sprintf("%s/log_%s.json", configs.ErrorLogDirectory, today), e)
}
// 上で解説したjson file書き込み関数
func writeJsonFile(fileName string, object interface{}) {
file, _ := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE, 0600)
defer file.Close()
fi, _ := file.Stat()
leng := fi.Size()
json_, _ := json.Marshal(object)
if leng == 0 {
file.Write([]byte(fmt.Sprintf(`[%s]`, json_)))
} else {
file.WriteAt([]byte(fmt.Sprintf(`,%s]`, json_)), leng-1)
}
}
func HttpLog(h http.Handler, l *LogA) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
l.Logging(r)
h.ServeHTTP(w, r)
})
}
細かく解説します。
ここでは構造体を定義していて、エラーログもアクセスログもどちらも Log 構造体が埋め込まれています。
// Logの基底構造体
type Log struct {
Kind string `json:"kind"`
Time time.Time `json:"time"`
Level string `json:"level"`
}
// Error用ログの構造体
type LogE struct {
Log
Content string `json:"content"` // エラー内容
Place string `json:"place"` // エラー発生場所
}
// Access用ログの構造体
type LogA struct {
Log
Address string `json:"address"` // IPアドレス
Method string `json:"method"` // request method
Path string `json:"path"` // path
}
初期化に際してはこのようにすることで kind にデフォルト値を持たせています。
func NewAccessLog() *LogA {
// startのlogをここで作る
alog := &LogA{
Log: Log{
Kind: "access",
},
}
return alog
}
func newErrorLog() *LogE {
eLog := &LogE{
Log: Log{
Kind: "error",
},
}
return eLog
}
エラーログはこのようにすることで即呼び出せるようにしています。
func ErrorAlert(err error) {
e := newErrorLog()
e.Logging(err, LogAlert)
}
func ErrorCritical(err error) {
e := newErrorLog()
e.Logging(err, LogCritical)
}
func ErrorWarn(err error) {
e := newErrorLog()
e.Logging(err, LogWarn)
}
func (e *LogE) Logging(err error, level string) {
if tools.IsProductionEnv() {
e.write(err, level)
} else {
e.write(err, level)
}
}
func (e *LogE) write(err error, level string) {
today := time.Now().Format("20060102")
e.Level = level
e.Content = err.Error()
// auto
_, file, line, _ := runtime.Caller(2)
e.Place = fmt.Sprintf("%s:%d", file, line)
e.Time = time.Now()
// 前章で解説してたjsonファイル書き込み関数
writeJsonFile(fmt.Sprintf("%s/log_%s.json", configs.ErrorLogDirectory, today), e)
}
一方アクセスログの方はセッションごとにオブジェクトを使い回す形で使用しています。
func (a *LogA) Logging(r *http.Request) {
if tools.IsProductionEnv() {
a.write(r)
} else {
a.write(r)
}
}
func (a *LogA) write(r *http.Request) {
today := time.Now().Format("20060102")
a.Level = LogInfo
a.Time = time.Now()
a.Address = r.RemoteAddr
a.Method = r.Method
a.Path = r.URL.Path
// 前章で解説してたjsonファイル書き込み関数
writeJsonFile(fmt.Sprintf("%s/log_%s.json", configs.ErrorLogDirectory, today), a)
}
// アクセスに関するログを吐き出す関数
func HttpLog(h http.Handler, l *LogA) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
l.Logging(r)
h.ServeHTTP(w, r)
})
}
実際にはこんな感じで使います。
main.go
package main
import (
"net/http"
".../domain"
)
func main() {
router := http.NewServeMux()
l := domain.NewAccessLog()
router.Handle(...)
...
// リクエストごとにHttpLogが発動します。
if err := http.ListenAndServe(":8000", domain.HttpLog(router, l)); err != nil {
domain.ErrorAlert(err)
}
}
出力結果はこんな感じです。(jq してます)
[
{
"kind": "error",
"time": "2021-08-05T07:38:54.051566671+09:00",
"level": "WAN",
"content": "sql: Rows are closed",
"place": "<秘密>/internal/pkg/interfaces/database/review_repository.go:74"
},
{
"kind": "access",
"time": "2021-08-05T07:41:00.609925853+09:00",
"level": "INF",
"address": "52.00.000.000",
"method": "GET",
"path": "/db/anime/"
}
]
まとめ
go でログをファイル出力する方法を紹介。
さらにログを json 形式でファイル出力する方法を紹介しました。
今後はアクセスログを追加したり、レベルが高いときには即座に slack 通知を送る機能の追加、バッチ処理でログを定期的に回収して sentry のように画面から見れるようにしようと思っています。
最終的に sentry を使うと決断したとしてもこうやって自分でそれっぽく作ってみると色々学べて面白いですね。
こうやって自由に実験できるのが個人開発のいいとこですね。
補足 上書き法とベンチマーク比較
上書き法
そもそも書き方自体微妙な気がする
もっとスッキリした書き方があるはず
overrite.go
func overWrite(fileName string, object interface{}) {
file, err := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE, 0600)
if err != nil {
fmt.Print(err)
}
defer file.Close()
buf := make([]byte, 1024*1024)
for {
n, err := file.Read(buf)
if n == 0 {
break
}
if err != nil {
panic(err)
}
}
// resize
idx := bytes.IndexByte(buf, 0)
buf = buf[:idx]
var lst []interface{}
json.Unmarshal(buf, &lst)
lst = append(lst, object)
json_, _ := json.Marshal(lst)
file.WriteAt(json_, 0)
}
やってることとしては、元々ファイルに書かれていた部分を json から slice に変換して新要素を append しています。
そしてそれを json にして、ファイルに上書きする。といった方法です。
なんかクドい
以下にベンチマーク測定の結果も載せておきます。
そこまで大きな差はないですが、新規ファイルに対しても追記するやり方の方がパフォーマンスが良いみたいです。
jsonwrite_test.go
package jsonwrite_test
import (
"bytes"
"encoding/json"
"fmt"
"os"
"testing"
)
// 要素を追加 (既存)
func BenchmarkAppend_AppendJson(b *testing.B) {
b.ResetTimer()
p := &Sample{Name: "Jhone Doe", Old: 20, Explain: "aaaa aaaa"}
appendJson(filePath, p)
}
// まるごと書き換え (既存)
func BenchmarkAppend_Overwrite(b *testing.B) {
b.ResetTimer()
p := &Sample{Name: "Jhone Doe", Old: 20, Explain: "aaaa aaaa"}
overWrite(filePath2, p)
}
// 要素を追加 (新規)
func BenchmarkAppend_AppendJsonNew(b *testing.B) {
b.ResetTimer()
p := &Sample{Name: "Jhone Doe", Old: 20, Explain: "aaaa aaaa"}
appendJson(noFilePath, p)
}
// まるごと書き換え (新規)
func BenchmarkAppend_OverwriteNew(b *testing.B) {
b.ResetTimer()
p := &Sample{Name: "Jhone Doe", Old: 20, Explain: "aaaa aaaa"}
overWrite(noFilePath2, p)
}
// delete file
func BenchmarkAppend_DeleteFile(b *testing.B) {
b.ResetTimer()
os.Remove(noFilePath)
os.Remove(noFilePath2)
}
const filePath = "./sample.json"
const noFilePath = "./no.json"
const filePath2 = "./sample2.json"
const noFilePath2 = "./no2.json"
type Sample struct {
Name string `json:"name"`
Old int `json:"old,omitempty"`
Explain string `json:"explain"`
}
func appendJson(fileName string, object interface{}) {
file, _ := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE, 0600)
defer file.Close()
fi, _ := file.Stat()
leng := fi.Size()
json_, _ := json.Marshal(object)
if leng == 0 {
file.Write([]byte(fmt.Sprintf(`[%s]`, json_)))
} else {
file.WriteAt([]byte(fmt.Sprintf(`,%s]`, json_)), leng-1)
}
}
func overWrite(fileName string, object interface{}) {
file, err := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE, 0600)
if err != nil {
fmt.Print(err)
}
defer file.Close()
buf := make([]byte, 1024*1024)
for {
n, err := file.Read(buf)
if n == 0 {
break
}
if err != nil {
panic(err)
}
}
// resize
idx := bytes.IndexByte(buf, 0)
buf = buf[:idx]
var lst []interface{}
json.Unmarshal(buf, &lst)
lst = append(lst, object)
json_, _ := json.Marshal(lst)
file.WriteAt(json_, 0)
}
// result
/******************************
BenchmarkAppend_AppendJson-8 1000000000 0.001882 ns/op 0 B/op 0 allocs/op
BenchmarkAppend_Overwrite-8 1000000000 0.004287 ns/op 0 B/op 0 allocs/op
BenchmarkAppend_AppendJsonNew-8 1000000000 0.002100 ns/op 0 B/op 0 allocs/op
BenchmarkAppend_OverwriteNew-8 1000000000 0.003463 ns/op 0 B/op 0 allocs/op
******************************/
参考資料等
Discussion