本シリーズのリンク

チーム開発参加の記録【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行がログ出力されるようになります。

今後

当面はこの実装で、ログを動かしながら開発を進めようと思います。
現状の実装では、リクエスト情報とレスポンス情報がログ出力されますが、出力したくない情報も出てくると思いますので、その都度対応していきます。
ログの出力先は、とりあえず標準出力とログファイルにしていますが、これもチームメンバーと相談して、出力先をどこにするか決めようと思います。