Go/EchoでpanicをMiddlewareでキャッチしてError Handlerでレスポンスを返す。ついでにLogも残す。

はじめに

こんにちは。GENDAエンジニアの西尾です。
この記事は GENDA Advent Calendar 2024 6日目の記事です。

https://qiita.com/advent-calendar/2024/genda

TL;DR

• echoでは、複数のエンドポイントに共通の処理はMiddlewareで実装され、エラーハンドリングをError Handlerに一元化することを推奨している。
• 処理の順番は、外側に置かれたMiddlewareから順に処理が走り、そしてHTTP Handlerが呼ばれ、最後にError Handlerが呼ばれる。
• echo.ContextのError()メソッドを呼ぶとすぐに、設定したError Handlerが呼ばれてしまい、後続のMiddlewareやHTTP Handlerがスキップされてレスポンスをコミットしてしまうので呼び出し方に注意が必要。

Echoで使われるMiddlewareとError Handlerとは

Middleware

• 複数のエンドポイントに共通の処理を行う。
• よくあるユースケースとして、Basic認証、CORS、CSRF、Loggerなどがすでにある程度実装されている。

Error Handler

• MiddlewareやHTTP Handlerが返すエラーを一元的に処理する。
• echoでは、エラーハンドリングを集約してエラー時のHTTPレスポンスや外部への記録をError Handler内で行うことを推奨している。
• デフォルトのError Handlerも実装されているが、echo.HTTPErrorHandler型を満たす関数を実装することで挙動をカスタムすることができる。

処理の順番

e := echo.New()

e.HTTPErrorHandler = HTTPErrorHandler()

e.Use(Middleware1())
e.Use(Middleware2())

e.GET("/", HTTPHandler())

以上のようなコードでサーバーを起動した場合、外側のMiddlewareから順番に処理が走り、最終的にHTTP Handlerが呼ばれます。
注意が必要なのはError Handlerの呼ばれ方で、以下の２つのパターンがありえます。

• MiddlewareおよびHTTP Handlerがすべて呼ばれた後
• echo.ContextのError()`メソッドを明示的に呼んだ後

Error Handlerにエラーレスポンスを返す処理を入れている場合は、その後の処理でステータスコードなどが変更できなくなるので、Errorメソッドの呼び方には注意が必要です。HTTP Hadlerではerrorを返すようにしてこのメソッドを使わないようにすることが推奨されています。（参考）

panicをMiddlewareでキャッチしてError Handlerでレスポンスを返す。ついでにLogも残す。

panicをMiddlewareでキャッチしてError Handlerでレスポンスを返す

リクエストを処理している最中にpanicが起きたらrecoverしてサーバーを正常に動かし続けるためのMiddlewareはすでに実装されていますが、勝手にLogを出力してしまうのとスタックトレースが見づらいので、挙動をカスタムできるCustomRecoverを実装します。
このMiddleware内でdeferを呼ぶことでHTTP Handlerおよびその他の内側のMiddleware内で発生したpanicをキャッチして、recoverすることができます。

同様にError Handlerについてもエラーのレスポンスをカスタマイズするために、CustomHTTPErrorHandlerを実装します。

func CustomRecover() echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            defer func() {
                slog.Debug("called recover middleware defer")

                if er := recover(); er != nil {
                    errVal, ok := er.(error)
                    if !ok {
                        errVal = errors.New("panic error in middleware")
                    }

                    c.Error(echo.NewHTTPError(http.StatusInternalServerError, errVal.Error()))
                }
            }()

            slog.Debug("called recover middleware before next")
            return next(c)
        }
    }
}

func CustomHTTPErrorHandler(err error, c echo.Context) {
    slog.Debug("called http error handler")

    code := http.StatusInternalServerError
    if he, ok := err.(*echo.HTTPError); ok {
        code = he.Code
    }

    c.String(code, "Internal Server Error")
}

挙動を理解するために、デバッグログを仕込んでいます。
HTTP Handlerで擬似的にpanicを起こし挙動を確認します。

func main() {
    e := echo.New()
    e.HTTPErrorHandler = CustomHTTPErrorHandler

    e.Use(CustomRecover())

    e.GET("/", func(c echo.Context) error {
        slog.Debug("called HTTP handler")
        panic("panic error in HTTP handler")
    })

    e.Logger.Fatal(e.Start(":1323"))
}

サーバーを起動し、リクエストを飛ばしてみます。

curl http://localhost:1323 -v
***
< HTTP/1.1 500 Internal Server Error
< Content-Type: text/plain; charset=UTF-8
***
Internal Server Error

ステータスコード500とCustomHTTPErrorHandlerで設定したInternal Server Errorという文字列が返ってきています。
サーバーのログを見てみると、処理の流れがわかります。

{"level":"DEBUG","msg":"called recover middleware before next"}
{"level":"DEBUG","msg":"called HTTP handler"}
{"level":"DEBUG","msg":"called recover middleware defer"}
{"level":"DEBUG","msg":"called http error handler","err":"code=500, message=panic error in middleware"}

CustomRecoverのdeferが呼ばれた後にErro Handlerが呼ばれていることがわかります。
無事、カスタムMiddlewareでpanicをキャッチしてError Handlerからレスポンスを返すことができました。

ついでにLogも残す

CustomRecoverがLogを出力しない実装になったので、echoで実装されているRequestLoggerのMiddlewareを利用してLogを出力します。
echoの例に倣って、LoggerのMiddlewareをCustomRecoverの外側におきます。

func main() {
    e := echo.New()
    e.HTTPErrorHandler = CustomHTTPErrorHandler

+   logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
+   e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
+       LogStatus: true,
+       LogError:  true,
+       LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
+          if v.Error == nil {
+              logger.LogAttrs(context.Background(), slog.LevelInfo, "REQUEST",
+                  slog.String("uri", v.URI),
+              )
+           } else {
+               logger.LogAttrs(context.Background(), slog.LevelError, "REQUEST_ERROR",
+                   slog.String("uri", v.URI),
+                   slog.String("err", v.Error.Error()),
+               )
+           }
+           return nil
+       },
+  }))
   e.Use(CustomRecover())

しかし、このままでは出力が成功Logになってしまいます。

{"level":"DEBUG","msg":"called recover middleware before next"}
{"level":"DEBUG","msg":"called HTTP handler"}
{"level":"DEBUG","msg":"called recover middleware defer"}
{"level":"DEBUG","msg":"called http error handler"}
# 成功Logが出力されてしまう
{"time":"2024-12-03T17:19:43.227378+09:00","level":"INFO","msg":"REQUEST","uri":""}

原因は echo.ContextのError()メソッドの呼び方です。
前述のように、Error()メソッドが呼ばれるとエラーハンドラーが呼ばれてレスポンスがコミットされます。そして、外側のMiddlewareにerrorが返されなくなるため、Loggerにエラーが伝搬せず、Logは成功扱いになってしまいます。

以下のようにCustomRecoverを修正し、エラーハンドラーとLoggerの呼び出される順番をコントロールします。
外側のMiddlewareにerrorを返し、一番外側のLoggerにエラーを渡すようにすることでエラーログを出力できるようにします。
panicの発生をdeferでキャッチしてエラーを返すために、named returnを利用してエラーを返します。

func CustomRecover() echo.MiddlewareFunc {
     return func(next echo.HandlerFunc) echo.HandlerFunc {
+         return func(c echo.Context) (err error) {
             defer func() {
               slog.Debug("called recover middleware defer")

               if er := recover(); er != nil {
                  errVal, ok := er.(error)
                  if !ok {
                    errVal = errors.New("panic error in middleware")
                  }

-                 c.Error(echo.NewHTTPError(http.StatusInternalServerError, errVal.Error()))
+                 err = errVal
              }
            }()

           slog.Debug("called recover middleware before next")
           return next(c)
        }
    }
}

リクエストを送ると想定通りステータスコード500が返ってきます。

curl http://localhost:1323 -v
***
< HTTP/1.1 500 Internal Server Error
***
Internal Server Error

ログを見ると正しい順序で呼ばれていることがわかります。

{"level":"DEBUG","msg":"called recover middleware before next"}
{"level":"DEBUG","msg":"called HTTP handler"}
{"level":"DEBUG","msg":"called recover middleware defer"}
{"level":"DEBUG","msg":"called http error handler"}
# 先に失敗Logが出力される
{"time":"2024-12-03T17:23:31.529786+09:00","level":"ERROR","msg":"REQUEST_ERROR","uri":"","err":"panic error in middleware"}
# 最後にエラーハンドラーが呼ばれる
{"level":"DEBUG","msg":"called http error handler"}

まとめ

RecoverするMiddlewareがエラーを出力するようにカスタムし、Loggerをいい感じに設定することで、Logが二重に出ないようにしつつpanicをキャッチすることができました。
その際に、Error()メソッドの呼び方には注意が必要でした。

参考

• echo Middleware: https://echo.labstack.com/docs/quick-start
• echo Error handler: https://echo.labstack.com/docs/error-handling