package handler import ( "bufio" "bytes" "context" "errors" "fmt" "io" "io/ioutil" "net" "net/http" "net/http/httputil" "strings" "time" "github.com/zeromicro/go-zero/core/iox" "github.com/zeromicro/go-zero/core/logx" "github.com/zeromicro/go-zero/core/syncx" "github.com/zeromicro/go-zero/core/timex" "github.com/zeromicro/go-zero/core/utils" "github.com/zeromicro/go-zero/rest/httpx" "github.com/zeromicro/go-zero/rest/internal" ) const ( limitBodyBytes = 1024 defaultSlowThreshold = time.Millisecond * 500 ) var slowThreshold = syncx.ForAtomicDuration(defaultSlowThreshold) type loggedResponseWriter struct { w http.ResponseWriter r *http.Request code int } func (w *loggedResponseWriter) Flush() { if flusher, ok := w.w.(http.Flusher); ok { flusher.Flush() } } func (w *loggedResponseWriter) Header() http.Header { return w.w.Header() } // Hijack implements the http.Hijacker interface. // This expands the Response to fulfill http.Hijacker if the underlying http.ResponseWriter supports it. func (w *loggedResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { if hijacked, ok := w.w.(http.Hijacker); ok { return hijacked.Hijack() } return nil, nil, errors.New("server doesn't support hijacking") } func (w *loggedResponseWriter) Write(bytes []byte) (int, error) { return w.w.Write(bytes) } func (w *loggedResponseWriter) WriteHeader(code int) { w.w.WriteHeader(code) w.code = code } // LogHandler returns a middleware that logs http request and response. func LogHandler(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { timer := utils.NewElapsedTimer() logs := new(internal.LogCollector) lrw := loggedResponseWriter{ w: w, r: r, code: http.StatusOK, } var dup io.ReadCloser r.Body, dup = iox.DupReadCloser(r.Body) next.ServeHTTP(&lrw, r.WithContext(context.WithValue(r.Context(), internal.LogContext, logs))) r.Body = dup logBrief(r, lrw.code, timer, logs) }) } type detailLoggedResponseWriter struct { writer *loggedResponseWriter buf *bytes.Buffer } func newDetailLoggedResponseWriter(writer *loggedResponseWriter, buf *bytes.Buffer) *detailLoggedResponseWriter { return &detailLoggedResponseWriter{ writer: writer, buf: buf, } } func (w *detailLoggedResponseWriter) Flush() { w.writer.Flush() } func (w *detailLoggedResponseWriter) Header() http.Header { return w.writer.Header() } // Hijack implements the http.Hijacker interface. // This expands the Response to fulfill http.Hijacker if the underlying http.ResponseWriter supports it. func (w *detailLoggedResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { if hijacked, ok := w.writer.w.(http.Hijacker); ok { return hijacked.Hijack() } return nil, nil, errors.New("server doesn't support hijacking") } func (w *detailLoggedResponseWriter) Write(bs []byte) (int, error) { w.buf.Write(bs) return w.writer.Write(bs) } func (w *detailLoggedResponseWriter) WriteHeader(code int) { w.writer.WriteHeader(code) } // DetailedLogHandler returns a middleware that logs http request and response in details. func DetailedLogHandler(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { timer := utils.NewElapsedTimer() var buf bytes.Buffer lrw := newDetailLoggedResponseWriter(&loggedResponseWriter{ w: w, r: r, code: http.StatusOK, }, &buf) var dup io.ReadCloser r.Body, dup = iox.DupReadCloser(r.Body) logs := new(internal.LogCollector) next.ServeHTTP(lrw, r.WithContext(context.WithValue(r.Context(), internal.LogContext, logs))) r.Body = dup logDetails(r, lrw, timer, logs) }) } // SetSlowThreshold sets the slow threshold. func SetSlowThreshold(threshold time.Duration) { slowThreshold.Set(threshold) } func dumpRequest(r *http.Request) string { reqContent, err := httputil.DumpRequest(r, true) if err != nil { return err.Error() } return string(reqContent) } func logBrief(r *http.Request, code int, timer *utils.ElapsedTimer, logs *internal.LogCollector) { var buf bytes.Buffer duration := timer.Duration() logger := logx.WithContext(r.Context()) buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s - %s - %s", r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent(), timex.ReprOfDuration(duration))) if duration > slowThreshold.Load() { logger.Slowf("[HTTP] %s - %d - %s - %s - %s - slowcall(%s)", r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent(), timex.ReprOfDuration(duration)) } ok := isOkResponse(code) if !ok { fullReq := dumpRequest(r) limitReader := io.LimitReader(strings.NewReader(fullReq), limitBodyBytes) body, err := ioutil.ReadAll(limitReader) if err != nil { buf.WriteString(fmt.Sprintf("\n%s", fullReq)) } else { buf.WriteString(fmt.Sprintf("\n%s", string(body))) } } body := logs.Flush() if len(body) > 0 { buf.WriteString(fmt.Sprintf("\n%s", body)) } if ok { logger.Info(buf.String()) } else { logger.Error(buf.String()) } } func logDetails(r *http.Request, response *detailLoggedResponseWriter, timer *utils.ElapsedTimer, logs *internal.LogCollector) { var buf bytes.Buffer duration := timer.Duration() code := response.writer.code logger := logx.WithContext(r.Context()) buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s\n=> %s\n", r.Method, code, r.RemoteAddr, timex.ReprOfDuration(duration), dumpRequest(r))) if duration > defaultSlowThreshold { logger.Slowf("[HTTP] %s - %d - %s - slowcall(%s)\n=> %s\n", r.Method, code, r.RemoteAddr, timex.ReprOfDuration(duration), dumpRequest(r)) } body := logs.Flush() if len(body) > 0 { buf.WriteString(fmt.Sprintf("%s\n", body)) } respBuf := response.buf.Bytes() if len(respBuf) > 0 { buf.WriteString(fmt.Sprintf("<= %s", respBuf)) } if isOkResponse(code) { logger.Info(buf.String()) } else { logger.Error(buf.String()) } } func isOkResponse(code int) bool { // not server error return code < http.StatusInternalServerError }