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で実行するか失敗しない限り見えないので。

この辺をしっかり調整しておくとデバッグなどのときに捗るが、意外とテキトーだったりしがち。

gist


  1. “%s"のほうが良かったりする?たしか記憶が正しければ、encoding/jsonJSON化したときにerrorを持つフィールドなどは含まれない様になっていたが、直接err.Error()をする分には問題なかったはず。そういう意味ではerr.Error()でも良いかもしれない。

  2. err.Unwrap()しきったもののほうが良いかもしれない。

  3. 昔にcontextual loggingとstuctured loggingについて記事を書いていたみたい。https://pod.hatenablog.com/entry/2017/05/20/232522