本シリーズのリンク
- チーム開発参加の記録【2023-10～2024-03】(1) Go言語用ORM「Bun」をDBファーストで使う試み（SQLite使用）
- チーム開発参加の記録【2023-10～2024-03】(2) Go言語からTursoを使ってみた
- チーム開発参加の記録【2023-10～2024-03】(3) slogを使ってリクエスト・レスポンス情報をログ出力してみた
- チーム開発参加の記録【2023-10～2024-03】(4) Go言語用ORM「Bun」をDBファーストで使う試み（PostgreSQL使用）
- チーム開発参加の記録【2023-10～2024-03】(5) Go言語用ORM「Bun」でトランザクション、UPSERT、JOINを使ってみた
- チーム開発参加の記録【2023-10～2024-03】(6) Go言語用ORM「Bun」で複数のクエリーをまとめてDBサーバーで実行
- チーム開発参加の記録【2023-10～2024-03】(7) slogでErrorレベルのログをSlackに飛ばしてみた
本記事で行うこと
前回（6月～8月）のチーム開発では、ログ出力はWebフレームワークのデフォルトをそのまま使用しました。
今回は「前回より品質を上げていこう」ということで、ログの出力先や中身に手を加えることにしました。
Go公式の新しいロガー「slog」を使って実装していきます。
※ チーム開発はまだ実装初期なので、本記事では実装の完成を目指しておりません。
ソースコード
最初に、今回書いたソースコード全体を載せてしまいます。
コード中のドキュメントは、JetBrains AI Assistantに原案を作ってもらいました。
ディレクトリ構成とファイル一覧
log/ディレクトリはログファイルの出力先です。
Project Root
├── log/
│ └── *.log
├── utils/
│ ├── middlewares/
│ │ └── LoggingMiddleware.go
│ └── log.go
├── app.go
└── go.mod
utils/middlewares/LoggingMiddleware.go
LoggingMiddleware.go
package middlewares
import (
"bytes"
"encoding/json"
"io"
"log/slog"
"net/http"
"strings"
"sync"
"github.com/labstack/echo/v4"
gonanoid "github.com/matoous/go-nanoid/v2"
)
// CustomResponseWriter は http.ResponseWriter インターフェースを実装する型で、
// HTTPレスポンスデータを、指定した io.Writer に書き込むことを可能にします。
type CustomResponseWriter struct {
rw http.ResponseWriter
writer io.Writer
}
// NewCustomResponseWriter は CustomResponseWriter の新しいインスタンスを作成します。
// 引数として http.ResponseWriter と io.Writer を受け取り、io.MultiWriterを利用して
// その両方に書き込まれるように writer を設定します。
func NewCustomResponseWriter(rw http.ResponseWriter, buf io.Writer) *CustomResponseWriter {
return &CustomResponseWriter{
rw: rw,
writer: io.MultiWriter(rw, buf),
}
}
// Header は http.ResponseWriter インターフェースを実装します。
func (c *CustomResponseWriter) Header() http.Header {
return c.rw.Header()
}
// WriteHeader は http.ResponseWriter インターフェースを実装します。
func (c *CustomResponseWriter) WriteHeader(statusCode int) {
c.rw.WriteHeader(statusCode)
}
// Write は http.ResponseWriter インターフェースを実装します。
func (c *CustomResponseWriter) Write(b []byte) (int, error) {
return c.writer.Write(b)
}
// LoggingMiddleware は元のHandlerに、リクエストとレスポンスの情報をログ出力するよう、機能追加したミドルウェア関数です
func LoggingMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
return func(c echo.Context) error {
trace, _ := gonanoid.New()
c.Set("trace", trace)
// request bodyを取得
request := c.Request()
reqBody, err := io.ReadAll(request.Body)
if err != nil {
slog.ErrorContext(request.Context(), "read request body failed", "error", err)
}
request.Body = io.NopCloser(bytes.NewBuffer(reqBody))
// response bodyを取得する準備
response := c.Response()
respBuf := bytes.NewBuffer(nil)
customW := NewCustomResponseWriter(response.Writer, respBuf)
response.Writer = customW
// 非同期でリクエスト情報をログ出力
var wg sync.WaitGroup
wg.Add(1)
go func() {
defer wg.Done()
reqLogging(c, reqBody, trace)
}()
// リクエスト処理
nextErr := next(c)
// 非同期でレスポンス情報をログ出力
go func() {
wg.Wait()
respLogging(c, respBuf, trace)
}()
return nextErr
}
}
// reqLogging はリクエスト情報をログに記録します。
//
// パラメータ:
// - c: 現在のリクエストの echo.Context オブジェクト。
// - reqBody: リクエストボディ（バイトスライスとして）。
// - trace: 現在のリクエストに紐づく一意のトレースID。
//
// この関数はリモートIP、リクエストメソッド、URLパスなどのリクエストデータを抽出します。
// また、クエリパラメータとリクエストボディの内容も確認し、それらをログに記録します。
// ログ情報は slog.InfoContext を使用してロギングフレームワークに送信されます。
func reqLogging(c echo.Context, reqBody []byte, trace string) {
request := c.Request()
var logArgs []any
logArgs = append(logArgs, "remoteIp", c.RealIP())
logArgs = append(logArgs, "method", request.Method)
logArgs = append(logArgs, "path", request.URL.Path)
queryParams := c.QueryParams()
if 0 < len(queryParams) {
logArgs = append(logArgs, "queryParams", queryParams)
}
if 0 < len(reqBody) {
var reqBodyMap map[string]any
err := json.Unmarshal(reqBody, &reqBodyMap)
if err == nil {
logArgs = append(logArgs, "body", reqBodyMap)
} else {
contentType := http.DetectContentType(reqBody)
if strings.HasPrefix(contentType, "text/") {
logArgs = append(logArgs, "body", string(reqBody))
} else {
logArgs = append(logArgs, "contentType", contentType)
}
}
}
slog.InfoContext(request.Context(), "[request]",
slog.String("trace", trace),
slog.Group("request", logArgs...))
}
// respLogging はレスポンス情報をログに記録します。
//
// パラメータ:
// - c: 現在のリクエストの echo.Context オブジェクト。
// - respBuf: レスポンスボディを含むバッファ（*bytes.Bufferとして）。
// - trace: 現在のリクエストに紐づく一意のトレースID。
//
// この関数はリクエストメソッド、URLパス、ステータスコードなどのデータを抽出します。
// また、レスポンスボディとコンテンツタイプの内容も確認し、それらをログに記録します。
// ログ情報は slog.InfoContext を使用してロギングフレームワークに送信されます。
func respLogging(c echo.Context, respBuf *bytes.Buffer, trace string) {
request := c.Request()
response := c.Response()
var logArgs []any
logArgs = append(logArgs, "method", request.Method)
logArgs = append(logArgs, "path", request.URL.Path)
logArgs = append(logArgs, "status", response.Status)
contentType := response.Header().Get(echo.HeaderContentType)
logArgs = append(logArgs, "contentType", contentType)
if strings.Contains(contentType, "json") {
respBody := respBuf.Bytes()
var respBodyMap map[string]any
err := json.Unmarshal(respBody, &respBodyMap)
if err == nil {
logArgs = append(logArgs, "body", respBodyMap)
} else {
logArgs = append(logArgs, "body", string(respBody))
}
} else if strings.HasPrefix(contentType, "text/") {
logArgs = append(logArgs, "body", respBuf.String())
}
slog.InfoContext(request.Context(), "[response]",
slog.String("trace", trace),
slog.Group("response", logArgs...))
}
utils/log.go
log.go
package utils
import (
"io"
"log/slog"
"os"
"path/filepath"
"time"
"github.com/labstack/echo/v4"
)
// GetRootLogger は以下の設定を持つロガーを返します:
// - ログを標準出力とログファイルの両方に出力します
// - ログファイルは "./log" ディレクトリ配下に作成されます
// - "./log" ディレクトリがなければ、0755の権限で作成されます
// - ログファイル名は "YYYY-MM-DD-HH-MM.log" 形式です
// - ロガーはINFO以上のログをJSON形式で書き込みます
// - コード中のAddSourceをtrueにすると、ログ出力したソースコードの場所も出力されます
func GetRootLogger() *slog.Logger {
// ログ出力先
dir := "./log/"
// パスが存在しなければディレクトリを作成
if _, err := os.Stat(dir); os.IsNotExist(err) {
err = os.MkdirAll(dir, 0755) // ディレクトリがない場合は作成
if err != nil { // ディレクトリの作成に失敗したらエラー
panic(err)
}
}
filename := time.Now().Format("2006-01-02-15-04") + ".log"
path := filepath.Join(dir, filename)
logfile, err := os.OpenFile(path, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
if err != nil {
panic(err)
}
// ログを標準出力とログファイルの両方に出力
multiWriter := io.MultiWriter(os.Stdout, logfile)
return slog.New(slog.NewJSONHandler(multiWriter, &slog.HandlerOptions{
AddSource: true,
Level: slog.LevelInfo,
}))
}
// GetApiLogger はAPI用のロガーを返す関数です。
// 各APIのハンドラから呼ばれることを想定しています。
// 引数としてecho.Contextを受け取り、その中から"trace"値を抽出して
// 自動で出力ログに加えます。
//
// 使用例:
//
// logger := GetApiLogger(c)
// logger.Info("こんにちは")
//
// 上記の例では、GetApiLogger関数を使用してロガーを取得し、
// "こんにちは"とメッセージをログ出力します。
func GetApiLogger(c echo.Context) *slog.Logger {
getLoggingTrace := func() string {
trace := c.Get("trace")
if trace != nil {
return trace.(string)
} else {
return "nil"
}
}
return slog.With(slog.String("trace", getLoggingTrace()))
}
app.go
app.go
package main
import (
"exercise_log/utils"
"exercise_log/utils/middlewares"
"log/slog"
"net/http"
"github.com/labstack/echo/v4"
"github.com/labstack/echo/v4/middleware"
)
type (
httpError struct {
Error string `json:"error"`
}
)
func handler(c echo.Context) error {
type (
requestBodyType struct {
No int `json:"no"`
}
responseType struct {
PathParam string `json:"pathParam"`
QueryParam string `json:"queryParam"`
Body int `json:"body"`
}
)
// ハンドラ先頭でGetApiLogger()を呼ぶ
logger := utils.GetApiLogger(c)
// ハンドラへの出入りをログ出力
logger.Info(".. in")
defer logger.Info(".. out")
// パスパラメータ
pathParam := c.Param("pathParam")
// クエリパラメータ
queryParam := c.QueryParam("queryParam")
// リクエストボディ
reqBody := new(requestBodyType)
if err := c.Bind(reqBody); err != nil {
return c.JSON(http.StatusInternalServerError, httpError{Error: err.Error()})
}
return c.JSON(http.StatusOK, responseType{PathParam: pathParam, QueryParam: queryParam, Body: reqBody.No})
}
func main() {
slog.SetDefault(utils.GetRootLogger())
// EchoでAPIサーバー
e := echo.New()
e.Use(middleware.Recover())
e.Use(middlewares.LoggingMiddleware)
// Routing
api := e.Group("/api")
api.POST("/foo/:pathParam", handler)
e.Logger.Fatal(e.Start(":1323"))
}
go.mod
go.mod
module exercise_log
go 1.21
require (
github.com/golang-jwt/jwt v3.2.2+incompatible // indirect
github.com/labstack/echo/v4 v4.11.3 // indirect
github.com/labstack/gommon v0.4.0 // indirect
github.com/matoous/go-nanoid/v2 v2.0.0 // indirect
github.com/mattn/go-colorable v0.1.13 // indirect
github.com/mattn/go-isatty v0.0.19 // indirect
github.com/valyala/bytebufferpool v1.0.0 // indirect
github.com/valyala/fasttemplate v1.2.2 // indirect
golang.org/x/crypto v0.14.0 // indirect
golang.org/x/net v0.17.0 // indirect
golang.org/x/sys v0.13.0 // indirect
golang.org/x/text v0.13.0 // indirect
golang.org/x/time v0.3.0 // indirect
)
動かしてみる
動作確認用に以下のAPIを用意しましたので、必要に応じてソースコードを見ながら、動かしていきます。
POST /api/foo
APIを呼んでみる
APIの仕様を確認します。
app.goのルーティング箇所を見ると、このAPIはパスパラメータを受け取ることがわかります。
api.POST("/foo/:pathParam", handler)
APIハンドラの実装を見ると、このAPIはパスパラメータに加えて、クエリパラメータとリクエストボディも受け取ることが分かります。
// パスパラメータ
pathParam := c.Param("pathParam")
// クエリパラメータ
queryParam := c.QueryParam("queryParam")
// リクエストボディ
reqBody := new(requestBodyType)
if err := c.Bind(reqBody); err != nil {
return err
}
それではPostmanでAPIを呼んでみます。
リクエストボディに以下のjsonを渡しました。
{
"no": 12345
}
パスパラメータとクエリパラメータはURIに含めます。
- パスパラメータ：bar
- クエリパラメータ：queryParam=baz
http://localhost:1323/api/foo/bar?queryParam=baz
実行結果です。
レスポンスとして、以下が返ってきました。
{
"pathParam": "bar",
"queryParam": "baz",
"body": 12345
}
このAPIコールで、どんなログが出力されたか見ていきます。
ログを確認する
標準出力にログが4行出力されました。
____ __
/ __/___/ / ___
/ _// __/ _ \/ _ \
/___/\__/_//_/\___/ v4.11.3
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
O\
⇨ http server started on [::]:1323
{"time":"2023-12-17T08:36:42.080621347+09:00","level":"INFO","source":{"function":"main.handler","file":"/home/user/GolandProjects/exercise_log/app.go","line":29},"msg":".. in","trace":"8z1eEPTiSV1NwJvdPZcJS"}
{"time":"2023-12-17T08:36:42.080727388+09:00","level":"INFO","source":{"function":"main.handler","file":"/home/user/GolandProjects/exercise_log/app.go","line":44},"msg":".. out","trace":"8z1eEPTiSV1NwJvdPZcJS"}
{"time":"2023-12-17T08:36:42.081246732+09:00","level":"INFO","source":{"function":"exercise_log/utils/middlewares.reqLogging","file":"/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go","line":127},"msg":"[request]","trace":"8z1eEPTiSV1NwJvdPZcJS","request":{"remoteIp":"::1","method":"POST","path":"/api/foo/bar","queryParams":{"queryParam":["baz"]},"body":{"no":12345}}}
{"time":"2023-12-17T08:36:42.081308268+09:00","level":"INFO","source":{"function":"exercise_log/utils/middlewares.respLogging","file":"/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go","line":166},"msg":"[response]","trace":"8z1eEPTiSV1NwJvdPZcJS","response":{"method":"POST","path":"/api/foo/bar","status":200,"contentType":"application/json; charset=UTF-8","body":{"body":12345,"pathParam":"bar","queryParam":"baz"}}}
同じ内容のログが、./logディレクトリの下のログファイルにも出力されました。
{"time":"2023-12-17T08:36:42.080621347+09:00","level":"INFO","source":{"function":"main.handler","file":"/home/user/GolandProjects/exercise_log/app.go","line":29},"msg":".. in","trace":"8z1eEPTiSV1NwJvdPZcJS"}
{"time":"2023-12-17T08:36:42.080727388+09:00","level":"INFO","source":{"function":"main.handler","file":"/home/user/GolandProjects/exercise_log/app.go","line":44},"msg":".. out","trace":"8z1eEPTiSV1NwJvdPZcJS"}
{"time":"2023-12-17T08:36:42.081246732+09:00","level":"INFO","source":{"function":"exercise_log/utils/middlewares.reqLogging","file":"/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go","line":127},"msg":"[request]","trace":"8z1eEPTiSV1NwJvdPZcJS","request":{"remoteIp":"::1","method":"POST","path":"/api/foo/bar","queryParams":{"queryParam":["baz"]},"body":{"no":12345}}}
{"time":"2023-12-17T08:36:42.081308268+09:00","level":"INFO","source":{"function":"exercise_log/utils/middlewares.respLogging","file":"/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go","line":166},"msg":"[response]","trace":"8z1eEPTiSV1NwJvdPZcJS","response":{"method":"POST","path":"/api/foo/bar","status":200,"contentType":"application/json; charset=UTF-8","body":{"body":12345,"pathParam":"bar","queryParam":"baz"}}}
このままでは見づらいので、jsonを整形して1行ずつ見ていきます。
1行目
{
"time": "2023-12-17T08:36:42.080621347+09:00",
"level": "INFO",
"source": {
"function": "main.handler",
"file": "/home/user/GolandProjects/exercise_log/app.go",
"line": 29
},
"msg": ".. in",
"trace": "8z1eEPTiSV1NwJvdPZcJS"
}
1行目はapp.goのhandler()内の、以下のコードから出力されたログです。
ログのキー「msg」に「.. in」という値を確認できます。
logger.Info(".. in")
2行目
{
"time": "2023-12-17T08:36:42.080727388+09:00",
"level": "INFO",
"source": {
"function": "main.handler",
"file": "/home/user/GolandProjects/exercise_log/app.go",
"line": 44
},
"msg": ".. out",
"trace": "8z1eEPTiSV1NwJvdPZcJS"
}
2行目はapp.goのhandler()内の、以下のコードから出力されたログです。
ログのキー「msg」に「.. out」という値を確認できます。
defer logger.Info(".. out")
3行目
{
"time": "2023-12-17T08:36:42.081246732+09:00",
"level": "INFO",
"source": {
"function": "exercise_log/utils/middlewares.reqLogging",
"file": "/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go",
"line": 127
},
"msg": "[request]",
"trace": "8z1eEPTiSV1NwJvdPZcJS",
"request": {
"remoteIp": "::1",
"method": "POST",
"path": "/api/foo/bar",
"queryParams": {
"queryParam": [
"baz"
]
},
"body": {
"no": 12345
}
}
}
3行目はLoggingMiddleware.goの、reqLogging関数から自動で出力されたログです。
キーが「request」のデータを見ると、パスパラメータは「path」内に含まれていて、その他のクエリーパラメータやリクエストボディ等も確認できます。
4行目
{
"time": "2023-12-17T08:36:42.081308268+09:00",
"level": "INFO",
"source": {
"function": "exercise_log/utils/middlewares.respLogging",
"file": "/home/user/GolandProjects/exercise_log/utils/middlewares/LoggingMiddleware.go",
"line": 166
},
"msg": "[response]",
"trace": "8z1eEPTiSV1NwJvdPZcJS",
"response": {
"method": "POST",
"path": "/api/foo/bar",
"status": 200,
"contentType": "application/json; charset=UTF-8",
"body": {
"body": 12345,
"pathParam": "bar",
"queryParam": "baz"
}
}
}
4行目はLoggingMiddleware.goの、respLogging関数から自動で出力されたログです。
キーが「response」のデータを見ると、ステータスコード、コンテンツタイプ、レスポンスボディ等が確認できます。
それでは、1～4行の全体を通して見てきます。
ログの出力順序について
LoggingMiddleware.go側はゴルーチンを使っていますので、遅れて出力される傾向があります（今回の3行目と4行目）。
処理に時間がかかるハンドラでは、今回の2行目と3行目が入れ替わるでしょう。
キー「trace」について
キー「trace」が全ての行に含まれています。
これはリクエストに紐づくIDで、同じリクエストでは同じ値になります。
別のリクエストとの区別を可能にするために実装しました。
"trace": "8z1eEPTiSV1NwJvdPZcJS",
各APIのハンドラ先頭で、log.goのGetApiLogger()を呼んでロガーを取得してもらう設計になっています。
このロガーを使用すると、trace情報が自動でログに出力されます。
// ハンドラ先頭でGetApiLogger()を呼ぶ
logger := utils.GetApiLogger(c)
キー「source」について
ログを出力したソースコードの場所です。
"source": {
"function": "main.handler",
"file": "/home/user/GolandProjects/exercise_log/app.go",
"line": 29
},
log.goのGetRootLogger()内のAddSourceをtrueにすると出力されます。
return slog.New(slog.NewJSONHandler(multiWriter, &slog.HandlerOptions{
AddSource: true,
Level: slog.LevelInfo,
}))
全体を俯瞰する
今までログ出力の詳細を確認してきましたので、ここで全体を俯瞰してみます。
app.goのmain()を見ますと、
func main() {
slog.SetDefault(utils.GetRootLogger())
// EchoでAPIサーバー
e := echo.New()
e.Use(middleware.Recover())
e.Use(middlewares.LoggingMiddleware)
// Routing
api := e.Group("/api")
api.POST("/foo/:pathParam", handler)
e.Logger.Fatal(e.Start(":1323"))
}
冒頭でlog.goのGetRootLogger()を呼び出してロガーを取得し、それをslogのデフォルトに設定しています。
slog.SetDefault(utils.GetRootLogger())
GetRootLogger()内で、ログの全体的な設定を行っていて、ログ出力先は標準出力とログファイルの両方にしていますが、出力先は今後変更予定です。
GetRootLogger()は、最初に1回だけ呼ばれる前提で実装しています。
各APIのハンドラからは、log.goのGetApiLogger()の方を呼んでもらう設計です。
次に着目するのは以下の行です。
e.Use(middlewares.LoggingMiddleware)
この行で、LoggingMiddleware.goで実装したLoggingMiddleware()を、Echoのミドルウェアとして登録しています。
以後APIを呼ぶたびに、自動でリクエスト情報とレスポンス情報の2行がログ出力されるようになります。
今後
当面はこの実装で、ログを動かしながら開発を進めようと思います。
現状の実装では、リクエスト情報とレスポンス情報がログ出力されますが、出力したくない情報も出てくると思いますので、その都度対応していきます。
ログの出力先は、とりあえず標準出力とログファイルにしていますが、これもチームメンバーと相談して、出力先をどこにするか決めようと思います。