web APIのテスト時に500のときにはstack traceを表示したい
通常、status codeが500のresponseにstack traceなどが含まれているとセキュリティ的にはよろしくない。そんなわけで500のresponseは簡素な表現になる。一方でテストのときなどに、簡素な表現だけが表示された場合には、stack traceを含めたい。含めない場合には原因の特定に一手間かかるようになってしまう。
そこで、以下の様になっていると嬉しい。
500のresponseを返すときに
- responseとしてはstack traceは表示しない
- ログ出力としてはstack traceを表示したい
- test時には通常のログではなく
testing.TB.Logf()
として扱われて欲しい
これを実現するにはxerrorsの記事のものと組み合わせると便利かもしれない。
例えばの例
例えば以下の様なコードを書いてみる。
ポイントは、loggerをinterfaceにしている点とlogger時の出力には%+v
を使い、responseへの出力には%v
を使っている点1。
staging環境などでの確認においては、DEBUG=1
のような環境変数を見て、responseに%+v
を使う処理を入れても良いかもしれない。
package main import ( "fmt" "log" "net/http" "os" "github.com/go-chi/chi" "github.com/go-chi/render" "golang.org/x/xerrors" ) func main() { s := &Server{ Router: chi.NewRouter(), logger: log.New(os.Stdout, "app", 0), } s.Mount() addr := os.Getenv("Addr") if addr == "" { addr = ":4444" } log.Printf("listen: %s", addr) if err := http.ListenAndServe(addr, s); err != nil { log.Fatalf("!! %+v", err) } } type logger interface { Printf(string, ...interface{}) } type Server struct { logger logger chi.Router } func (s *Server) Mount() { s.Get("/500", func(w http.ResponseWriter, r *http.Request) { err := f() if err != nil { s.logger.Printf("! %+v", err) render.Status(r, 500) render.JSON(w, r, map[string]string{"error": fmt.Sprintf("%s", err)}) return } render.JSON(w, r, map[string]string{"message": "never"}) }) } func f() error { err := g() return xerrors.Errorf("f %w", err) } func g() error { err := h() return xerrors.Errorf("g %w", err) } func h() error { return fmt.Errorf("h") }
クライアントからはこのように見える2。
$ http :4444/500 HTTP/1.1 500 Internal Server Error Content-Length: 29 Content-Type: application/json; charset=utf-8 Date: Wed, 23 Sep 2020 00:56:00 GMT { "error": "f g h: h: g h: h" }
サーバー側はこの様な形の出力。標準ライブラリのlogを使っているからこの様な形だが、他のloggerライブラリを使っても別に良い。
go run 05test-log/main.go 2020/09/23 09:44:26 listen: :44444 app! f g h: h: main.f /tmp/xxx/testlog/main.go:56 - g h: main.g /tmp/xxx/testlog/main.go:60 - h
テスト時
テストのときはどの様になるかと言うとこういう形。出力に色をつけたので画像を。
このときのテストコードは以下の様な形。loggerをinterfaceにしてテストコードではtesting.TBを使った実装を渡すことで、テスト失敗時に良い感じのログ出力を得る事ができるようになる。
package main import ( "fmt" "io" "net/http" "net/http/httptest" "os" "testing" "github.com/go-chi/chi" ) type testlogger struct { testing.TB } func (tl *testlogger) Printf(fmt string, args ...interface{}) { tl.Helper() tl.Logf("\x1b[90m"+fmt+"\x1b[0m", args...) } func TestIt(t *testing.T) { s := &Server{ Router: chi.NewRouter(), logger: &testlogger{TB: t}, } s.Mount() ts := httptest.NewServer(s) defer ts.Close() res, err := http.Get(fmt.Sprintf("%s/500", ts.URL)) if err != nil { t.Fatalf("unexpected %v", err) } if res.StatusCode != 200 { t.Errorf("want 200 but %d", res.StatusCode) } fmt.Println("----------------------------------------") fmt.Print("response: ") io.Copy(os.Stderr, res.Body) fmt.Println("----------------------------------------") defer res.Body.Close() }
contextにloggerを埋め込む?
この記事のコード例ではやっていないが、場合によっては、contextにloggerを埋め込むのも有効かもしれない。これは解釈が分かれるポイントかもしれないが、個人的には、loggerは特にcontextual loggingならリクエスト単位のものなはずなので、contextに埋め込んでも良いのではないかと思っている3。
contextに埋め込むと何ができる様になるのかといえば、この種のログの表示を関数呼び出しの下部も下部のところのログ出力まで対応できるようになる点。そして通常のテスト実行ではログ出力を抑制したいはずなので一石二鳥かもしれない。*testing.T.Logf()
の出力はgo test -v
で実行するか失敗しない限り見えないので。
この辺をしっかり調整しておくとデバッグなどのときに捗るが、意外とテキトーだったりしがち。