labstack/echoとmiddleware.Loggerとエラーレスポンス

github.com/labstack/echoのロギングについての備忘録です.
echoのログを活用していきたい...と考えてます。

前提

• go 1.19
• echo v4.10.0
• echoのErrorHandlerはDefaultHTTPErrorHandlerを使用
  • https://github.com/labstack/echo/blob/v4.10.0/echo.go#L389-L429

はじめに、正常応答させてみる

echoのmiddleware.Loggerをカスタマイズせずに使用します。

// ~省略

e := echo.New()
e.Use(middleware.Logger())

// ~省略

e.GET("/", func(ctx echo.Context) error {
  return ctx.String(http.StatusOK, "Hello world!")
})

curlで呼び出します

#localhost, port=8888で実行しているとき
curl http://localhost:8888/

logの内容

{"time":"2023-01-22T03:52:21.307000008Z","id":"","remote_ip":"/*remote ip*/","host":"localhost:8888","method":"GET","uri":"/","user_agent":"curl/7.84.0","status":200,"error":"","latency":134542,"latency_human":"134.542µs","bytes_in":0,"bytes_out":12}

正常な振る舞いをしているのでerrorは空です

エラー応答について

正常時のログを確認したので、エラー応答のさせ方によるログやレスポンスの違いを見ていきます

1. echo.HTTPErrorを返してみる

e.GET("/", func(ctx echo.Context) error {
  // return ctx.String(http.StatusOK, "Hello world!")
  return &echo.HTTPError{Code: http.StatusNotFound, Message: "エラーメッセージ", Internal: errors.New("エラー内容")}
})

logの内容です

{"time":"2023-01-22T04:01:40.613879378Z","id":"","remote_ip":"/*remote ip*/","host":"localhost:8888","method":"GET","uri":"/","user_agent":"curl/7.84.0","status":404,"error":"code=404, message=エラーメッセージ, internal=エラー内容","latency":84958,"latency_human":"84.958µs","bytes_in":0,"bytes_out":39}

errorの値としてecho.HTTPErrorで定義した内容（Code, message, internal）が出力されてます。

この時のhttpレスポンスのBodyです

{"message":"エラーメッセージ"}

（補足）echo.HTTPErrorを返すけどレスポンスのBodyを自前のstructで定義したい場合

レスポンスに含まれるのがmessageだけでは物足りないという場合、echo.HTTPErrorのMessageに文字列ではなく構造体をセットすることでレスポンスBodyの内容を変えることができます。

e.GET("/", func(ctx echo.Context) error {
	// return ctx.String(http.StatusOK, "Hello world!")
    // return &echo.HTTPError{Code: http.StatusNotFound, Message: "エラーメッセージ", Internal: errors.New("エラー内容")}

	msgObj := struct {
		Prop1 int
		Prop2 string
	}{
		Prop1: 100,
		Prop2: "AAAAA",
	}
	return &echo.HTTPError{Code: http.StatusNotFound, Message: msgObj, Internal: errors.New("エラー内容")}
})

logの内容です

{"time":"2023-01-22T04:05:37.928444793Z","id":"","remote_ip":"/*remote ip*/","host":"localhost:8888","method":"GET","uri":"/","user_agent":"curl/7.84.0","status":404,"error":"code=404, message={100 AAAAA}, internal=エラー内容","latency":3021208,"latency_human":"3.021208ms","bytes_in":0,"bytes_out":30}

errorのmessage部分が構造体に置き換わっていることが確認できます。

httpレスポンスのBody

{"Prop1":100,"Prop2":"AAAAA"}

狙い通り、構造体をjson化して返してくれています。今回はProp1/Prop2といった形でレスポンスをさせましたが、{"error_code":"~", "message":"~~"}など、レスポンスBodyにmessageだけでなく、サービス固有のエラーIDなどを付け加えたい場合に使えそうです。

2. errorをそのまま返してみる

func e.GET("/", func(ctx echo.Context) error {
	// return ctx.String(http.StatusOK, "Hello world!")
	// return &echo.HTTPError{Code: http.StatusNotFound, Message: "エラーメッセージ", Internal: errors.New("エラー内容")}
	// msgObj := struct {
	// 	Prop1 int
	// 	Prop2 string
	// }{
	// 	Prop1: 100,
	// 	Prop2: "AAAAA",
	// }
	// return &echo.HTTPError{Code: http.StatusNotFound, Message: msgObj, Internal: errors.New("エラー内容")}

	return errors.New("エラー内容")
})

logの内容です

{"time":"2023-01-22T04:13:47.412619673Z","id":"","remote_ip":"/*remote ip*/","host":"localhost:8888","method":"GET","uri":"/","user_agent":"curl/7.84.0","status":500,"error":"エラー内容","latency":832958,"latency_human":"832.958µs","bytes_in":0,"bytes_out":36}

errorの値にはerrors.New()した内容が出力されています

httpレスポンスのBodyです

{"message":"Internal Server Error"}

InternalServerError（StatusCode=500)固定なので400, 401, 404など使い分けをしたい場合は要求を満たせないです。

3. 正常な挙動を装ってInternalServerErrorを返してみる

func e.GET("/", func(ctx echo.Context) error {
	// return ctx.String(http.StatusOK, "Hello world!")
	// return &echo.HTTPError{Code: http.StatusNotFound, Message: "エラーメッセージ", Internal: errors.New("エラー内容")}
	// msgObj := struct {
	// 	Prop1 int
	// 	Prop2 string
	// }{
	// 	Prop1: 100,
	// 	Prop2: "AAAAA",
	// }
	// return &echo.HTTPError{Code: http.StatusNotFound, Message: msgObj, Internal: errors.New("エラー内容")}

	// return errors.New("エラー内容")

	msgObj := struct {
		Prop1 int
		Prop2 string
	}{
		Prop1: 100,
		Prop2: "AAAAA",
	}
	return ctx.JSON(http.StatusInternalServerError, msgObj)
})

logの内容です

{"time":"2023-01-22T04:30:00.244131346Z","id":"","remote_ip":"/*remote ip*/","host":"localhost:8888","method":"GET","uri":"/","user_agent":"curl/7.84.0","status":500,"error":"","latency":1925000,"latency_human":"1.925ms","bytes_in":0,"bytes_out":30}

errorの値は空

httpレスポンスのBodyです

{"Prop1":100,"Prop2":"AAAAA"}

まとめ

DefaultHTTPErrorHandlerを使う前提でのエラー時のログについて

• echo.HTTPErrorを返す場合
• errorを返す場合
• ctx.JSON()で返す場合

それぞれのログ出力を確認しました。

StatusCodeの使い分けやログ出力内容の充実など考えると、echo.HTTPErrorを返すようにするのが良さそうです