From a65cdddec4f15025b4fba2ad5efe51461bb6abea Mon Sep 17 00:00:00 2001 From: Rahim Date: Thu, 11 Jul 2024 22:02:25 +0100 Subject: [PATCH] Feat 31/logging (#35) * response writer interface update * mod wrap method * add hlog package for logging at the http layer --- net/http/httputil/hlog/limit_reader.go | 37 +++++++++ net/http/httputil/hlog/log.go | 106 ++++++++++++++++++++----- net/http/httputil/response_writer.go | 35 ++++++-- 3 files changed, 153 insertions(+), 25 deletions(-) create mode 100644 net/http/httputil/hlog/limit_reader.go diff --git a/net/http/httputil/hlog/limit_reader.go b/net/http/httputil/hlog/limit_reader.go new file mode 100644 index 0000000..4976dfe --- /dev/null +++ b/net/http/httputil/hlog/limit_reader.go @@ -0,0 +1,37 @@ +package hlog + +import ( + "bytes" + "io" +) + +// limitBuffer is used to pipe response body information from the +// response writer to a certain limit amount. The idea is to read +// a portion of the response body such as an error response so we +// may log it. +type limitBuffer struct { + *bytes.Buffer + limit int +} + +func newLimitBuffer(size int) io.ReadWriter { + return limitBuffer{ + Buffer: bytes.NewBuffer(make([]byte, 0, size)), + limit: size, + } +} + +func (b limitBuffer) Write(p []byte) (n int, err error) { + if b.Buffer.Len() >= b.limit { + return len(p), nil + } + limit := b.limit + if len(p) < limit { + limit = len(p) + } + return b.Buffer.Write(p[:limit]) +} + +func (b limitBuffer) Read(p []byte) (n int, err error) { + return b.Buffer.Read(p) +} diff --git a/net/http/httputil/hlog/log.go b/net/http/httputil/hlog/log.go index 2ca0203..7af4de6 100644 --- a/net/http/httputil/hlog/log.go +++ b/net/http/httputil/hlog/log.go @@ -1,38 +1,89 @@ package hlog import ( + "context" + "io" "log/slog" "net/http" + "os" + "strings" "time" "go.adoublef.dev/sdk/net/http/httputil" ) -// Log wraps a http.Handler with a request logger. -func Log(h http.Handler) http.Handler { +type contextKey struct{ string } + +func (k *contextKey) String() string { return "hlog: context value " + k.string } + +var ( + LoggerContextKey = &contextKey{"http-log"} +) + +func LogHandler(h http.Handler, sl *slog.Logger) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - rw := httputil.Wrap(w, r) + l := newLogger(sl, r) + ww := httputil.Wrap(w, r) - start := time.Now() + buf := newLimitBuffer(512) + ww.Tee(buf) + + t1 := time.Now() defer func() { - duration := time.Since(start) - - slog.LogAttrs( - r.Context(), - statusLevel(rw.Status()), - "http request", - slog.String("method", r.Method), - slog.Int64("time_ms", int64(duration/time.Millisecond)), - slog.String("path", r.URL.Path), - slog.Int("status", rw.Status()), - slog.String("duration", duration.String()), - ) + var error []byte + if ww.Status() >= 400 { + error, _ = io.ReadAll(buf) // lorem is 3091 + } + l.Write(ww.Status(), ww.Size(), ww.Header(), time.Since(t1), error) }() - - h.ServeHTTP(rw, r) + ctx := context.WithValue(r.Context(), LoggerContextKey, l) + h.ServeHTTP(ww, r.WithContext(ctx)) }) } +// Logger returns the in-context Logger for a request. +func Logger(r *http.Request) *slog.Logger { + entry, ok := r.Context().Value(LoggerContextKey).(*logger) + if !ok || entry == nil { + opts := &slog.HandlerOptions{ + AddSource: true, + // LevelError+1 will be higher than all levels + // hence logs would be skipped + Level: slog.LevelError + 1, + } + return slog.New(slog.NewTextHandler(os.Stderr, opts)) + } else { + return entry.l + } +} + +type logger struct { + l *slog.Logger +} + +func newLogger(l *slog.Logger, r *http.Request) *logger { + // request can be passed via context + l = l.With( + slog.String("path", r.URL.Path), + slog.String("method", r.Method), + slog.String("remoteIP", r.RemoteAddr), + ) + return &logger{l: l} +} + +func (l *logger) Write(status, bytes int, header http.Header, elapsed time.Duration, body []byte) { + // response + l.l = l.l.With( + slog.Int("status", status), + slog.Int("bytes", bytes), + slog.Duration("elapsed", elapsed), + ) + if status >= 400 { + l.l = l.l.With(slog.String("body", strings.TrimSpace(string(body)))) + } + l.l.Log(context.Background(), statusLevel(status), statusLabel(status)) +} + func statusLevel(status int) slog.Level { switch { case status <= 0: @@ -48,3 +99,22 @@ func statusLevel(status int) slog.Level { return slog.LevelInfo } } + +func statusLabel(status int) string { + switch { + case status >= 100 && status < 300: + return "OK" + case status >= 300 && status < 400: + return "Redirect" + case status >= 400 && status < 500: + return "Client Error" + case status >= 500: + return "Server Error" + default: + return "Unknown" + } +} + +func ErrAttr(err error) slog.Attr { + return slog.Any("err", err) +} diff --git a/net/http/httputil/response_writer.go b/net/http/httputil/response_writer.go index ec60447..7b090f5 100644 --- a/net/http/httputil/response_writer.go +++ b/net/http/httputil/response_writer.go @@ -3,8 +3,10 @@ package httputil import ( "bufio" "errors" + "io" "net" "net/http" + "sync" ) type ResponseWriter interface { @@ -17,6 +19,8 @@ type ResponseWriter interface { // Size returns the size of the response body. Size() int Unwrap() http.ResponseWriter + // Tee allows the caller to write to multiple writers. + Tee(w io.Writer) } type response struct { @@ -24,6 +28,15 @@ type response struct { method string status int size int + mu sync.Mutex + tee io.Writer +} + +// Tee implements ResponseWriter. +func (r *response) Tee(w io.Writer) { + r.mu.Lock() + r.tee = w + r.mu.Unlock() } // Size implements ResponseWriter. @@ -48,14 +61,22 @@ func (rw *response) Status() int { // Write implements ResponseWriter. // Subtle: this method shadows the method (ResponseWriter).Write of response.ResponseWriter. -func (rw *response) Write(b []byte) (size int, err error) { - if !rw.Written() { +func (r *response) Write(b []byte) (size int, err error) { + if !r.Written() { // The status will be StatusOK if WriteHeader has not been called yet - rw.WriteHeader(http.StatusOK) + r.WriteHeader(http.StatusOK) } - if rw.method != http.MethodHead { - size, err = rw.ResponseWriter.Write(b) - rw.size += size + if r.method != http.MethodHead { + size, err = r.ResponseWriter.Write(b) + r.mu.Lock() + if r.tee != nil { + _, err2 := r.tee.Write(b[:size]) + if err == nil { + err = err2 + } + } + r.mu.Unlock() + r.size += size } return size, err } @@ -99,7 +120,7 @@ func Wrap(w http.ResponseWriter, r *http.Request) ResponseWriter { if rw, ok := w.(ResponseWriter); ok { return rw } - return &response{w, r.Method, 0, 0} + return &response{ResponseWriter: w, method: r.Method} } var (