From f134e194bd392d8b10ef09ec1b439331570f8c3e Mon Sep 17 00:00:00 2001 From: dillon Date: Wed, 5 Jul 2023 20:01:37 -0500 Subject: [PATCH 1/9] introduce AccessHandlerNew --- README.md | 10 ++++++++++ hlog/hlog.go | 30 ++++++++++++++++++++++++++++++ hlog/internal/mutil/body.go | 30 ++++++++++++++++++++++++++++++ 3 files changed, 70 insertions(+) create mode 100644 hlog/internal/mutil/body.go diff --git a/README.md b/README.md index 972b729f..bc2d2556 100644 --- a/README.md +++ b/README.md @@ -592,6 +592,16 @@ c = c.Append(hlog.AccessHandler(func(r *http.Request, status, size int, duration Dur("duration", duration). Msg("") })) +c = c.Append(hlog.AccessHandlerNew(func(data hlog.AccessHandlerNewData) { + hlog.FromRequest(data.Request).Info(). + Str("method", data.Request.Method). + Stringer("url", data.Request.URL). + Int("status", data.Status). + Int("sizeWritten", data.BytesWritten). + Int64("sizeRead", data.BytesRead). + Dur("duration", data.Duration). + Msg("") +})) c = c.Append(hlog.RemoteAddrHandler("ip")) c = c.Append(hlog.UserAgentHandler("user_agent")) c = c.Append(hlog.RefererHandler("referer")) diff --git a/hlog/hlog.go b/hlog/hlog.go index 06ca4adf..16a5461c 100644 --- a/hlog/hlog.go +++ b/hlog/hlog.go @@ -324,3 +324,33 @@ func HostHandler(fieldKey string, trimPort ...bool) func(next http.Handler) http }) } } + +type AccessHandlerNewData struct { + Request *http.Request + Duration time.Duration + Status int + BytesWritten int + BytesRead int64 +} + +// AccessHandlerNew returns a handler that call f after each request. +func AccessHandlerNew(f func(data AccessHandlerNewData)) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + + lw := mutil.WrapWriter(w) + body := mutil.NewByteCountReadCloser(r.Body) + r.Body = body + + next.ServeHTTP(lw, r) + f(AccessHandlerNewData{ + Request: r, + Duration: time.Since(start), + Status: lw.Status(), + BytesWritten: lw.BytesWritten(), + BytesRead: body.BytesRead(), + }) + }) + } +} diff --git a/hlog/internal/mutil/body.go b/hlog/internal/mutil/body.go new file mode 100644 index 00000000..857c77bf --- /dev/null +++ b/hlog/internal/mutil/body.go @@ -0,0 +1,30 @@ +package mutil + +import "io" + +type byteCountReadCloser struct { + rc io.ReadCloser + read int64 +} + +var _ io.ReadCloser = (*byteCountReadCloser)(nil) + +func NewByteCountReadCloser(body io.ReadCloser) *byteCountReadCloser { + return &byteCountReadCloser{ + rc: body, + } +} + +func (bcrc *byteCountReadCloser) Read(p []byte) (int, error) { + n, err := bcrc.rc.Read(p) + bcrc.read += int64(n) + return n, err +} + +func (bcrc *byteCountReadCloser) Close() error { + return bcrc.rc.Close() +} + +func (bcrc *byteCountReadCloser) BytesRead() int64 { + return bcrc.read +} From 64880ff4b00ce31aa96137755aa47dde1bc0777e Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 12:09:19 -0600 Subject: [PATCH 2/9] add read count atomically --- hlog/hlog.go | 16 ++++++++-------- hlog/internal/mutil/body.go | 23 +++++++++++++---------- 2 files changed, 21 insertions(+), 18 deletions(-) diff --git a/hlog/hlog.go b/hlog/hlog.go index 16a5461c..b436593b 100644 --- a/hlog/hlog.go +++ b/hlog/hlog.go @@ -325,7 +325,7 @@ func HostHandler(fieldKey string, trimPort ...bool) func(next http.Handler) http } } -type AccessHandlerNewData struct { +type AccessHandlerData struct { Request *http.Request Duration time.Duration Status int @@ -333,22 +333,22 @@ type AccessHandlerNewData struct { BytesRead int64 } -// AccessHandlerNew returns a handler that call f after each request. -func AccessHandlerNew(f func(data AccessHandlerNewData)) func(next http.Handler) http.Handler { +// AccessHandlerWithData returns a handler that call f after each request. +func AccessHandlerWithData(f func(data AccessHandlerData)) func(next http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() - lw := mutil.WrapWriter(w) + ww := mutil.WrapWriter(w) body := mutil.NewByteCountReadCloser(r.Body) r.Body = body - next.ServeHTTP(lw, r) - f(AccessHandlerNewData{ + next.ServeHTTP(ww, r) + f(AccessHandlerData{ Request: r, Duration: time.Since(start), - Status: lw.Status(), - BytesWritten: lw.BytesWritten(), + Status: ww.Status(), + BytesWritten: ww.BytesWritten(), BytesRead: body.BytesRead(), }) }) diff --git a/hlog/internal/mutil/body.go b/hlog/internal/mutil/body.go index 857c77bf..78292705 100644 --- a/hlog/internal/mutil/body.go +++ b/hlog/internal/mutil/body.go @@ -1,6 +1,9 @@ package mutil -import "io" +import ( + "io" + "sync/atomic" +) type byteCountReadCloser struct { rc io.ReadCloser @@ -9,22 +12,22 @@ type byteCountReadCloser struct { var _ io.ReadCloser = (*byteCountReadCloser)(nil) -func NewByteCountReadCloser(body io.ReadCloser) *byteCountReadCloser { +func NewByteCountReadCloser(rc io.ReadCloser) *byteCountReadCloser { return &byteCountReadCloser{ - rc: body, + rc: rc, } } -func (bcrc *byteCountReadCloser) Read(p []byte) (int, error) { - n, err := bcrc.rc.Read(p) - bcrc.read += int64(n) +func (b *byteCountReadCloser) Read(p []byte) (int, error) { + n, err := b.rc.Read(p) + atomic.AddInt64(&b.read, int64(n)) return n, err } -func (bcrc *byteCountReadCloser) Close() error { - return bcrc.rc.Close() +func (b *byteCountReadCloser) Close() error { + return b.rc.Close() } -func (bcrc *byteCountReadCloser) BytesRead() int64 { - return bcrc.read +func (b *byteCountReadCloser) BytesRead() int64 { + return b.read } From 6df9ed3e771a02a1c422c3f0f416930864c5cf2e Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 12:17:55 -0600 Subject: [PATCH 3/9] implement io.WriterTo on byteCountReadCloser --- hlog/internal/mutil/body.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/hlog/internal/mutil/body.go b/hlog/internal/mutil/body.go index 78292705..a36835a6 100644 --- a/hlog/internal/mutil/body.go +++ b/hlog/internal/mutil/body.go @@ -11,6 +11,7 @@ type byteCountReadCloser struct { } var _ io.ReadCloser = (*byteCountReadCloser)(nil) +var _ io.WriterTo = (*byteCountReadCloser)(nil) func NewByteCountReadCloser(rc io.ReadCloser) *byteCountReadCloser { return &byteCountReadCloser{ @@ -28,6 +29,12 @@ func (b *byteCountReadCloser) Close() error { return b.rc.Close() } +func (b *byteCountReadCloser) WriteTo(w io.Writer) (int64, error) { + n, err := io.Copy(w, b.rc) + atomic.AddInt64(&b.read, n) + return n, err +} + func (b *byteCountReadCloser) BytesRead() int64 { return b.read } From b05cb18e2e5560e71068428e2506bea72ff8f4b5 Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 12:19:03 -0600 Subject: [PATCH 4/9] update readme doc --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index bc2d2556..edbe4534 100644 --- a/README.md +++ b/README.md @@ -592,7 +592,7 @@ c = c.Append(hlog.AccessHandler(func(r *http.Request, status, size int, duration Dur("duration", duration). Msg("") })) -c = c.Append(hlog.AccessHandlerNew(func(data hlog.AccessHandlerNewData) { +c = c.Append(hlog.AccessHandlerWithData(func(data hlog.AccessHandlerData) { hlog.FromRequest(data.Request).Info(). Str("method", data.Request.Method). Stringer("url", data.Request.URL). From c1cdcd2394e971f67b44bf37a27cd31a3c2a7c06 Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 13:08:16 -0600 Subject: [PATCH 5/9] atomically read --- hlog/internal/mutil/body.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/hlog/internal/mutil/body.go b/hlog/internal/mutil/body.go index a36835a6..86acadb2 100644 --- a/hlog/internal/mutil/body.go +++ b/hlog/internal/mutil/body.go @@ -7,7 +7,7 @@ import ( type byteCountReadCloser struct { rc io.ReadCloser - read int64 + read *int64 } var _ io.ReadCloser = (*byteCountReadCloser)(nil) @@ -21,7 +21,7 @@ func NewByteCountReadCloser(rc io.ReadCloser) *byteCountReadCloser { func (b *byteCountReadCloser) Read(p []byte) (int, error) { n, err := b.rc.Read(p) - atomic.AddInt64(&b.read, int64(n)) + atomic.AddInt64(b.read, int64(n)) return n, err } @@ -31,10 +31,10 @@ func (b *byteCountReadCloser) Close() error { func (b *byteCountReadCloser) WriteTo(w io.Writer) (int64, error) { n, err := io.Copy(w, b.rc) - atomic.AddInt64(&b.read, n) + atomic.AddInt64(b.read, n) return n, err } func (b *byteCountReadCloser) BytesRead() int64 { - return b.read + return atomic.LoadInt64(b.read) } From 412c0112d933422bb1e07da5dc70470fa2704383 Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 13:08:28 -0600 Subject: [PATCH 6/9] defer f --- hlog/hlog.go | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/hlog/hlog.go b/hlog/hlog.go index b436593b..c3750507 100644 --- a/hlog/hlog.go +++ b/hlog/hlog.go @@ -343,14 +343,16 @@ func AccessHandlerWithData(f func(data AccessHandlerData)) func(next http.Handle body := mutil.NewByteCountReadCloser(r.Body) r.Body = body + defer func() { + f(AccessHandlerData{ + Request: r, + Duration: time.Since(start), + Status: ww.Status(), + BytesWritten: ww.BytesWritten(), + BytesRead: body.BytesRead(), + }) + }() next.ServeHTTP(ww, r) - f(AccessHandlerData{ - Request: r, - Duration: time.Since(start), - Status: ww.Status(), - BytesWritten: ww.BytesWritten(), - BytesRead: body.BytesRead(), - }) }) } } From 660b0a520af2ab96c2e5ff67b925f16eca914546 Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 13:10:11 -0600 Subject: [PATCH 7/9] define AccessHandlerWithData near AccessHandler --- hlog/hlog.go | 48 +++++++++++++++++++++++------------------------- 1 file changed, 23 insertions(+), 25 deletions(-) diff --git a/hlog/hlog.go b/hlog/hlog.go index c3750507..fc3857e7 100644 --- a/hlog/hlog.go +++ b/hlog/hlog.go @@ -302,29 +302,6 @@ func AccessHandler(f func(r *http.Request, status, size int, duration time.Durat } } -// HostHandler adds the request's host as a field to the context's logger -// using fieldKey as field key. If trimPort is set to true, then port is -// removed from the host. -func HostHandler(fieldKey string, trimPort ...bool) func(next http.Handler) http.Handler { - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - var host string - if len(trimPort) > 0 && trimPort[0] { - host = getHost(r.Host) - } else { - host = r.Host - } - if host != "" { - log := zerolog.Ctx(r.Context()) - log.UpdateContext(func(c zerolog.Context) zerolog.Context { - return c.Str(fieldKey, host) - }) - } - next.ServeHTTP(w, r) - }) - } -} - type AccessHandlerData struct { Request *http.Request Duration time.Duration @@ -338,11 +315,9 @@ func AccessHandlerWithData(f func(data AccessHandlerData)) func(next http.Handle return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() - ww := mutil.WrapWriter(w) body := mutil.NewByteCountReadCloser(r.Body) r.Body = body - defer func() { f(AccessHandlerData{ Request: r, @@ -356,3 +331,26 @@ func AccessHandlerWithData(f func(data AccessHandlerData)) func(next http.Handle }) } } + +// HostHandler adds the request's host as a field to the context's logger +// using fieldKey as field key. If trimPort is set to true, then port is +// removed from the host. +func HostHandler(fieldKey string, trimPort ...bool) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + var host string + if len(trimPort) > 0 && trimPort[0] { + host = getHost(r.Host) + } else { + host = r.Host + } + if host != "" { + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, host) + }) + } + next.ServeHTTP(w, r) + }) + } +} From 0df6e506a19a51f6018a10da2ee59ed0dce752f5 Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 13:32:15 -0600 Subject: [PATCH 8/9] add test and initialize read to zero --- hlog/hlog_test.go | 38 ++++++++++++++++++++++++++++++++----- hlog/internal/mutil/body.go | 4 +++- 2 files changed, 36 insertions(+), 6 deletions(-) diff --git a/hlog/hlog_test.go b/hlog/hlog_test.go index 3dc7d317..0b0da0d7 100644 --- a/hlog/hlog_test.go +++ b/hlog/hlog_test.go @@ -7,11 +7,12 @@ import ( "bytes" "context" "fmt" - "io/ioutil" + "io" "net/http" "net/http/httptest" "net/url" "reflect" + "strings" "testing" "github.com/rs/xid" @@ -333,10 +334,10 @@ func BenchmarkHandlers(b *testing.B) { })) h2 := MethodHandler("method")(RequestHandler("request")(h1)) handlers := map[string]http.Handler{ - "Single": NewHandler(zerolog.New(ioutil.Discard))(h1), - "Combined": NewHandler(zerolog.New(ioutil.Discard))(h2), - "SingleDisabled": NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h1), - "CombinedDisabled": NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h2), + "Single": NewHandler(zerolog.New(io.Discard))(h1), + "Combined": NewHandler(zerolog.New(io.Discard))(h2), + "SingleDisabled": NewHandler(zerolog.New(io.Discard).Level(zerolog.Disabled))(h1), + "CombinedDisabled": NewHandler(zerolog.New(io.Discard).Level(zerolog.Disabled))(h2), } for name := range handlers { h := handlers[name] @@ -433,3 +434,30 @@ func TestGetHost(t *testing.T) { }) } } + +func TestAccessHandlerWithData(t *testing.T) { + bodyValue := "hello, world!" + req := httptest.NewRequest(http.MethodGet, "/", strings.NewReader(bodyValue)) + + handler := AccessHandlerWithData(func(data AccessHandlerData) { + expectedBytes := int64(len(bodyValue)) + if data.BytesRead != expectedBytes { + t.Errorf("unexpected bytes read, got: %d, want: %d", data.BytesRead, expectedBytes) + } + if data.BytesWritten != int(expectedBytes) { + t.Errorf("unexpected bytes read, got: %d, want: %d", data.BytesWritten, expectedBytes) + } + if data.Status != http.StatusOK { + t.Errorf("unexpected status, got: %d, want: %d", data.Status, http.StatusOK) + } + if data.Request != req { + t.Error("unexpected request object") + } + }) + + rr := httptest.NewRecorder() + + handler(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + io.Copy(w, r.Body) + })).ServeHTTP(rr, req) +} diff --git a/hlog/internal/mutil/body.go b/hlog/internal/mutil/body.go index 86acadb2..b40f6558 100644 --- a/hlog/internal/mutil/body.go +++ b/hlog/internal/mutil/body.go @@ -14,8 +14,10 @@ var _ io.ReadCloser = (*byteCountReadCloser)(nil) var _ io.WriterTo = (*byteCountReadCloser)(nil) func NewByteCountReadCloser(rc io.ReadCloser) *byteCountReadCloser { + read := int64(0) return &byteCountReadCloser{ - rc: rc, + rc: rc, + read: &read, } } From 334d58a2ec1df5218a43612b78122bcd4ee5261e Mon Sep 17 00:00:00 2001 From: dillonstreator Date: Tue, 21 Nov 2023 13:35:41 -0600 Subject: [PATCH 9/9] extend test case to assert against response --- hlog/hlog_test.go | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/hlog/hlog_test.go b/hlog/hlog_test.go index 0b0da0d7..63b73cb0 100644 --- a/hlog/hlog_test.go +++ b/hlog/hlog_test.go @@ -460,4 +460,17 @@ func TestAccessHandlerWithData(t *testing.T) { handler(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { io.Copy(w, r.Body) })).ServeHTTP(rr, req) + + if rr.Result().StatusCode != http.StatusOK { + t.Errorf("unexpected status, got: %d, want: %d", rr.Result().StatusCode, http.StatusOK) + } + + b, err := io.ReadAll(rr.Result().Body) + if err != nil { + t.Errorf("unexpected error: %s", err.Error()) + } + + if bodyValue != string(b) { + t.Errorf("unexpected response body, got: %s, want: %s", string(b), bodyValue) + } }