はじめに
こちらで、goaでのログ出力に悩まされたので、こちらに続きを記載します。
サンプルについて
自前でLogRequestのmiddlewareを用意
goa を起動する前に、middlewareの登録をするが、API実行時のlogについてはmiddleware.LogRequestで登録された内容で出力されます。
main.go
service := goa.New("goa-sample")
// Mount middleware
service.Use(middleware.RequestID())
service.Use(middleware.LogRequest(true))
service.Use(middleware.ErrorHandler(service, true))
service.Use(middleware.Recover())
ログ出力の内容を変更したい場合、このmiddlewareを自分で実装する必要があります。
logger
まずは下記のようにloggerを用意します。
json形式でログ出力をしたいため、log15を利用しました（他にも方法はあるかもしれません）。
このloggerはcontroller側で上位に伝搬されたエラーを検知した際、出力する等で利用します。
なお、便宜上、Functional Option Patternを採用しております。
sample_logger/logger.go
package sample_logger
import (
"context"
"encoding/json"
"os"
"time"
"github.com/goadesign/goa"
"github.com/goadesign/goa/middleware"
"github.com/hiroykam/goa-sample/sample_error"
"github.com/inconshreveable/log15"
)
type SampleLogger struct {
logTime string
requestID string
requestBody string
requestPath string
uid string
message string
Logger log15.Logger
}
type Option func(*SampleLogger)
func LogTime(l string) Option {
return func(args *SampleLogger) {
args.logTime = l
}
}
func RequestId(id string) Option {
return func(args *SampleLogger) {
args.requestID = id
}
}
func RequestPath(p string) Option {
return func(args *SampleLogger) {
args.requestPath = p
}
}
func UID(uid string) Option {
return func(args *SampleLogger) {
args.uid = uid
}
}
func NewSampleLooger(ctx context.Context, opts ...Option) (*SampleLogger, *sample_error.SampleError) {
p := &SampleLogger{
logTime: time.Now().Format(time.RFC3339),
requestID: middleware.ContextRequestID(ctx),
requestPath: "",
requestBody: "",
uid: "",
message: "",
Logger: log15.New(log15.Ctx{"module": "goa-sample"}),
}
p.Logger.SetHandler(log15.StreamHandler(os.Stdout, log15.JsonFormat()))
gc := goa.ContextRequest(ctx)
j, err := json.Marshal(gc.Payload)
if err != nil {
return nil, sample_error.NewSampleError(sample_error.InternalError, err.Error())
}
p.requestPath = gc.RequestURI
p.requestBody = string(j)
for _, opt := range opts {
opt(p)
}
return p, nil
}
func (p *SampleLogger) Info(msg string) {
p.Logger.Info(msg,
"logTime", p.logTime,
"RequestID", p.requestID,
"RequestBody", p.requestBody,
"RequestPath", p.requestPath,
"UID", p.uid)
}
func (p *SampleLogger) Debug(msg string) {
p.Logger.Debug(msg,
"logTime", p.logTime,
"RequestID", p.requestID,
"RequestBody", p.requestBody,
"RequestPath", p.requestPath,
"UID", p.uid)
}
func (p *SampleLogger) Error(msg string) {
p.Logger.Error(msg,
"logTime", p.logTime,
"RequestID", p.requestID,
"RequestBody", p.requestBody,
"RequestPath", p.requestPath,
"UID", p.uid)
}
func (p *SampleLogger) Warn(msg string) {
p.Logger.Warn(msg,
"logTime", p.logTime,
"RequestID", p.requestID,
"RequestBody", p.requestBody,
"RequestPath", p.requestPath,
"UID", p.uid)
}
func (p *SampleLogger) SampleError(err *sample_error.SampleError) {
if err.Code == sample_error.InternalError {
p.Error(err.Msg)
} else {
p.Warn(err.Msg)
}
}
LogRequestのmiddleware
続いて、LogRequestのmiddlewareを用意します。
goaのソースをほとんど流用しております。
sample_middleware/log_request.go
package sample_middleware
import (
"context"
"encoding/json"
"fmt"
"net"
"net/http"
"sort"
"strings"
"time"
"github.com/goadesign/goa"
"github.com/hiroykam/goa-sample/sample_logger"
)
func LogRequest(verbose bool, sensitiveHeaders ...string) goa.Middleware {
var suppressed map[string]struct{}
if len(sensitiveHeaders) > 0 {
suppressed = make(map[string]struct{}, len(sensitiveHeaders))
for _, sh := range sensitiveHeaders {
suppressed[strings.ToLower(sh)] = struct{}{}
}
}
return func(h goa.Handler) goa.Handler {
return func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
r := goa.ContextRequest(ctx)
l, err := sample_logger.NewSampleLooger(ctx, sample_logger.LogTime(time.Now().Format(time.RFC3339)))
if err != nil {
return err
}
l.Logger.Info("started", "method", r.Method, "url", r.URL.String(), "from", from(req),
"ctrl", goa.ContextController(ctx), "action", goa.ContextAction(ctx))
if verbose {
if len(r.Header) > 0 {
logCtx := make([]interface{}, 2*len(r.Header))
i := 0
keys := make([]string, len(r.Header))
for k := range r.Header {
keys[i] = k
i++
}
sort.Strings(keys)
i = 0
for _, k := range keys {
v := r.Header[k]
logCtx[i] = k
if _, ok := suppressed[strings.ToLower(k)]; ok {
logCtx[i+1] = "<hidden>"
} else {
logCtx[i+1] = interface{}(strings.Join(v, ", "))
}
i = i + 2
}
fmt.Println(logCtx)
l.Logger.Info("headers", "ctx", logCtx)
}
if len(r.Params) > 0 {
logCtx := make([]interface{}, 2*len(r.Params))
i := 0
for k, v := range r.Params {
logCtx[i] = k
logCtx[i+1] = interface{}(strings.Join(v, ", "))
i = i + 2
}
l.Logger.Info("params", "ctx", logCtx)
}
if r.ContentLength > 0 {
if mp, ok := r.Payload.(map[string]interface{}); ok {
logCtx := make([]interface{}, 2*len(mp))
i := 0
for k, v := range mp {
logCtx[i] = k
logCtx[i+1] = interface{}(v)
i = i + 2
}
j, err := json.Marshal(logCtx)
if err != nil {
return err
}
l.Info(string(j))
} else {
// Not the most efficient but this is used for debugging
js, err := json.Marshal(r.Payload)
if err != nil {
js = []byte("<invalid JSON>")
}
goa.LogInfo(ctx, "payload", "raw", string(js))
}
}
}
hErr := h(ctx, rw, req)
resp := goa.ContextResponse(ctx)
msg := fmt.Sprintf("status: %d", resp.Status)
if code := resp.ErrorCode; code != "" {
l.Error(msg)
} else {
l.Info(msg)
}
return hErr
}
}
}
func from(req *http.Request) string {
if f := req.Header.Get("X-Forwarded-For"); f != "" {
return f
}
f := req.RemoteAddr
ip, _, err := net.SplitHostPort(f)
if err != nil {
return f
}
return ip
}
LogRequestのmiddlewareをセット
下記で用意したLogRequestのmiddlewareをセットします。
main.go
service.Use(sample_middleware.LogRequest(true))
ログ出力
ログ出力がJSONになりました。
sample-api | 2019/02/10 22:04:04 stdout: {"action":"list","ctrl":"SamplesController","from":"172.20.0.1","lvl":"info","method":"GET","module":"goa-sample","msg":"started","t":"2019-02-10T22:04:04.8149308+09:00","url":"/api/v1/samples/?user_id=123"}
sample-api | 2019/02/10 22:04:04 stdout: [Accept */* Accept-Encoding gzip, deflate Cache-Control no-cache Connection keep-alive Postman-Token dacf3eb8-0494-465b-9141-5041b5e7043c Referer http://localhost:8080/api/v1/samples?user_id=123 User-Agent PostmanRuntime/7.6.0]
sample-api | 2019/02/10 22:04:04 stdout: {"ctx":["Accept","*/*","Accept-Encoding","gzip, deflate","Cache-Control","no-cache","Connection","keep-alive","Postman-Token","dacf3eb8-0494-465b-9141-5041b5e7043c","Referer","http://localhost:8080/api/v1/samples?user_id=123","User-Agent","PostmanRuntime/7.6.0"],"lvl":"info","module":"goa-sample","msg":"headers","t":"2019-02-10T22:04:04.8150801+09:00"}
sample-api | 2019/02/10 22:04:04 stdout: {"ctx":["user_id","123"],"lvl":"info","module":"goa-sample","msg":"params","t":"2019-02-10T22:04:04.8151225+09:00"}
sample-api | 2019/02/10 22:04:04 stdout: {"RequestBody":"null","RequestID":"EF92duKEUd-1","RequestPath":"/api/v1/samples/?user_id=123","UID":"","logTime":"2019-02-10T22:04:04+09:00","lvl":"info","module":"goa-sample","msg":"status: 200","t":"2019-02-10T22:04:04.8191072+09:00"}
レスポンスデータについて
レスポンスデータについても同様にmiddlewareを用意することで、実現できます。
LogResponseのmiddleware
下記のLogResponseのmiddlewareを用意します。
sample_middleware/log_response.go
package sample_middleware
import (
"context"
"net/http"
"time"
"github.com/goadesign/goa"
"github.com/hiroykam/goa-sample/sample_logger"
)
type loggingResponseWriter struct {
http.ResponseWriter
ctx context.Context
}
func (lrw *loggingResponseWriter) Write(buf []byte) (int, error) {
l, err := sample_logger.NewSampleLooger(lrw.ctx, sample_logger.LogTime(time.Now().Format(time.RFC3339)))
if err != nil {
return 0, err
}
l.Logger.Debug("response", "body", string(buf))
return lrw.ResponseWriter.Write(buf)
}
func LogResponse() goa.Middleware {
return func(h goa.Handler) goa.Handler {
return func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
// chain a new logging writer to the current response writer.
resp := goa.ContextResponse(ctx)
resp.SwitchWriter(
&loggingResponseWriter{
ResponseWriter: resp.SwitchWriter(nil),
ctx: ctx,
})
// next
return h(ctx, rw, req)
}
}
}
LogResponseのmiddlewareをセット
main.go
service.Use(sample_middleware.LogResponse())
ログ出力
下記のようなパラメータ不足によるエラー等も出力できるようになりました。
sample-api | 2019/02/10 22:32:30 stdout: {"body":"{\"id\":\"YwK29ppI\",\"code\":\"invalid_request\",\"status\":400,\"detail\":\"missing required parameter \\\"user_id\\\"\",\"meta\":{\"name\":\"user_id\"}}\n","lvl":"dbug","module":"goa-sample","msg":"response","t":"2019-02-10T22:32:30.96074+09:00"}
その他
テストコードや、jwt、Makefileの整備など充実していきたいです。