Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add headers to log output #61

Merged
merged 1 commit into from
Jan 30, 2024
Merged

Add headers to log output #61

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
77 changes: 77 additions & 0 deletions internal_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,11 @@
package rc

import (
"fmt"
"io"
"net/http"
"net/http/httptest"
"reflect"
"strings"
"testing"
)
Expand Down Expand Up @@ -49,3 +51,78 @@ func TestDuplicateRequest(t *testing.T) {
})
}
}

func TestMaskHeader(t *testing.T) {
tests := []struct {
h http.Header
want http.Header
}{
{nil, nil},
{
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
},
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
},
},
{
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"session=1234; Path=/; Expires=Wed, 09 Jun 2021 10:18:14 GMT; HttpOnly"},
},
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"*****"},
},
},
{
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{
"session=1234; Path=/; Expires=Wed, 09 Jun 2021 10:18:14 GMT; HttpOnly",
"session=5678; Path=/; Expires=Wed, 09 Jun 2021 10:18:14 GMT; HttpOnly",
},
},
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"*****"},
},
},
{
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"session=1234; Path=/; Expires=Wed, 09 Jun 2021 10:18:14 GMT; HttpOnly"},
"Authorization": []string{"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9."},
},
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"*****"},
"Authorization": []string{"*****"},
},
},
{
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"session=1234; Path=/; Expires=Wed, 09 Jun 2021 10:18:14 GMT; HttpOnly"},
"Authorization": []string{
"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.",
"Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.",
},
},
http.Header{
"Date": []string{"Mon, 02 Jan 2006 15:04:05 GMT"},
"Set-Cookie": []string{"*****"},
"Authorization": []string{"*****"},
},
},
}
for i, tt := range tests {
t.Run(fmt.Sprintf("%d", i), func(t *testing.T) {
got := maskHeader(tt.h)
if !reflect.DeepEqual(got, tt.want) {
t.Errorf("got %v want %v", got, tt.want)
}
})
}
}
42 changes: 27 additions & 15 deletions rc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,18 +86,18 @@ func (m *cacheMw) Handler(next http.Handler) http.Handler {
if err != nil {
switch {
case errors.Is(err, ErrCacheNotFound):
m.logger.Debug("cache not found", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()))
m.logger.Debug("cache not found", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)))
case errors.Is(err, ErrCacheExpired):
m.logger.Warn("cache expired", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()))
m.logger.Warn("cache expired", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)))
case errors.Is(err, ErrShouldNotUseCache):
m.logger.Debug("should not use cache", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()))
m.logger.Debug("should not use cache", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)))
default:
m.logger.Error("failed to load cache", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()))
m.logger.Error("failed to load cache", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)))
}
}
cacheUsed, res, err := m.cacher.Handle(req, cachedReq, cachedRes, HandlerToRequester(next), now) //nostyle:handlerrors
if err != nil {
m.logger.Error("failed to handle cache", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()))
m.logger.Error("failed to handle cache", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)))
}

// Response
Expand All @@ -115,37 +115,37 @@ func (m *cacheMw) Handler(next http.Handler) http.Handler {
w.WriteHeader(res.StatusCode)
body, err := io.ReadAll(res.Body)
if err != nil {
m.logger.Error("failed to read response body", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Error("failed to read response body", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode), slog.Any("response_headers", maskHeader(res.Header)))
} else {
if _, err := w.Write(body); err != nil {
if errors.Is(err, http.ErrBodyNotAllowed) {
m.logger.Warn("failed to write response body", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Warn("failed to write response body", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode), slog.Any("response_headers", maskHeader(res.Header)))
} else {
m.logger.Error("failed to write response body", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Error("failed to write response body", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode), slog.Any("response_headers", maskHeader(res.Header)))
}
}
}
if err := res.Body.Close(); err != nil {
m.logger.Error("failed to close response body", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Error("failed to close response body", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode), slog.Any("response_headers", maskHeader(res.Header)))
}

if cacheUsed {
m.logger.Debug("cache used", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Debug("cache used", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode))
return
}
ok, expires := m.cacher.Storable(preq, res, now)
if !ok {
m.logger.Debug("cache not storable", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Debug("cache not storable", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode), slog.Any("response_headers", maskHeader(res.Header)))
return
}
// Restore response body
res.Body = io.NopCloser(bytes.NewReader(body))

// Store response as cache
if err := m.cacher.Store(preq, res, expires); err != nil {
m.logger.Error("failed to store cache", slog.String("error", err.Error()), slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Error("failed to store cache", slog.String("error", err.Error()), slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode))
}
m.logger.Debug("cache stored", slog.String("method", preq.Method), slog.String("host", preq.Host), slog.String("url", preq.URL.String()), slog.Int("status", res.StatusCode))
m.logger.Debug("cache stored", slog.String("host", preq.Host), slog.String("method", preq.Method), slog.String("url", preq.URL.String()), slog.Any("headers", maskHeader(preq.Header)), slog.Int("status", res.StatusCode))
})
}

Expand All @@ -158,10 +158,10 @@ func (m *cacheMw) duplicateRequest(req *http.Request) (*http.Request, *http.Requ
}
b, err := io.ReadAll(copy.Body)
if err != nil {
m.logger.Error("failed to read request body", slog.String("error", err.Error()), slog.String("method", copy.Method), slog.String("host", copy.Host), slog.String("url", copy.URL.String()))
m.logger.Error("failed to read request body", slog.String("error", err.Error()), slog.String("host", copy.Host), slog.String("method", copy.Method), slog.Any("headers", maskHeader(copy.Header)), slog.String("url", copy.URL.String()))
}
if err := copy.Body.Close(); err != nil {
m.logger.Error("failed to close request body", slog.String("error", err.Error()), slog.String("method", copy.Method), slog.String("host", copy.Host), slog.String("url", copy.URL.String()))
m.logger.Error("failed to close request body", slog.String("error", err.Error()), slog.String("host", copy.Host), slog.String("method", copy.Method), slog.Any("headers", maskHeader(copy.Header)), slog.String("url", copy.URL.String()))
}
req.Body = io.NopCloser(bytes.NewReader(b))
copy.Body = io.NopCloser(bytes.NewReader(b))
Expand Down Expand Up @@ -200,3 +200,15 @@ func HandlerToRequester(h http.Handler) func(*http.Request) (*http.Response, err
return res, nil
}
}

func maskHeader(h http.Header) http.Header {
const masked = "*****"
c := h.Clone()
if c.Get("Set-Cookie") != "" {
c.Set("Set-Cookie", masked)
}
if c.Get("Authorization") != "" {
c.Set("Authorization", masked)
}
return c
}
Loading