はじめに

こちらで、goaでのログ出力に悩まされたので、こちらに続きを記載します。

サンプルについて

サンプルについては、こちらと同様にgithubにあります。

自前で`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の整備など充実していきたいです。