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

Add flag to log requests at info level #236

Merged
merged 7 commits into from
Mar 2, 2022
Merged

Add flag to log requests at info level #236

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
50f933a
add flag to log requests at info level
colin-stuart Feb 7, 2022
45b53a4
fix comment for LogRequestsAtInfoLevel
colin-stuart Feb 7, 2022
4baf7ef
add yaml tag & add LogRequestsAtInfoLevel to RegisterFlags
colin-stuart Feb 7, 2022
2a9f7dd
add method to set log level for logging with request
colin-stuart Feb 9, 2022
99c5b78
Revert "add method to set log level for logging with request"
colin-stuart Feb 18, 2022
e26aac2
call logWithRequest once
colin-stuart Feb 18, 2022
a4dd3f6
fix typo in registering LogRequestAtInfoLevel flag
colin-stuart Mar 1, 2022
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
25 changes: 19 additions & 6 deletions middleware/logging.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,9 +14,10 @@ import (

// Log middleware logs http requests
type Log struct {
Log logging.Interface
LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level
SourceIPs *SourceIPExtractor
Log logging.Interface
LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level
LogRequestsAtInfoLevel bool // LogRequestAtInfoLevel true -> dump requests at info log level
colin-stuart marked this conversation as resolved.
Show resolved Hide resolved
SourceIPs *SourceIPExtractor
}

// logWithRequest information from the request and context as fields.
Expand Down Expand Up @@ -56,17 +57,29 @@ func (l Log) Wrap(next http.Handler) http.Handler {

if writeErr != nil {
if errors.Is(writeErr, context.Canceled) {
l.logWithRequest(r).Debugf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
if l.LogRequestsAtInfoLevel {
l.logWithRequest(r).Infof("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
} else {
l.logWithRequest(r).Debugf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
}
} else {
l.logWithRequest(r).Warnf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
}

return
}
if 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable {
l.logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
if l.LogRequestsAtInfoLevel {
l.logWithRequest(r).Infof("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
} else {
l.logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
}
if l.LogRequestHeaders && headers != nil {
l.logWithRequest(r).Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
if l.LogRequestsAtInfoLevel {
l.logWithRequest(r).Infof("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
} else {
l.logWithRequest(r).Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
}
}
} else {
l.logWithRequest(r).Warnf("%s %s (%d) %s Response: %q ws: %v; %s",
Expand Down
39 changes: 39 additions & 0 deletions middleware/logging_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,46 @@ func TestBadWriteLogging(t *testing.T) {
require.True(t, bytes.Contains(buf.Bytes(), []byte(content)))
}
}
}

func TestLoggingRequestsAtInfoLevel(t *testing.T) {
for _, tc := range []struct {
err error
logContains []string
}{{
err: context.Canceled,
logContains: []string{"info", "request cancelled: context canceled"},
}, {
err: nil,
logContains: []string{"info", "GET http://example.com/foo (200)"},
}} {
buf := bytes.NewBuffer(nil)
logrusLogger := logrus.New()
logrusLogger.Out = buf
logrusLogger.Level = logrus.DebugLevel

loggingMiddleware := Log{
Log: logging.Logrus(logrusLogger),
LogRequestsAtInfoLevel: true,
}
handler := func(w http.ResponseWriter, r *http.Request) {
io.WriteString(w, "<html><body>Hello World!</body></html>")
}
loggingHandler := loggingMiddleware.Wrap(http.HandlerFunc(handler))

req := httptest.NewRequest("GET", "http://example.com/foo", nil)
recorder := httptest.NewRecorder()

w := errorWriter{
err: tc.err,
w: recorder,
}
loggingHandler.ServeHTTP(w, req)

for _, content := range tc.logContains {
require.True(t, bytes.Contains(buf.Bytes(), []byte(content)))
}
}
}

type errorWriter struct {
Expand Down
6 changes: 4 additions & 2 deletions server/server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,7 @@ type Config struct {
HTTPMiddleware []middleware.Interface `yaml:"-"`
Router *mux.Router `yaml:"-"`
DoNotAddDefaultHTTPMiddleware bool `yaml:"-"`
LogRequestsAtInfoLevel bool `yaml:"-"`
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My hunch is that it would preferable to place this under LogSourceIPsRegex alongside the the log-related flags.

Also, we should:

  • Add a yaml tag so it can be configured via file
  • Update (cfg *Config).RegisterFlags to accept a server.log-requests-at-info-level flag.


GPRCServerMaxRecvMsgSize int `yaml:"grpc_server_max_recv_msg_size"`
GRPCServerMaxSendMsgSize int `yaml:"grpc_server_max_send_msg_size"`
Expand Down Expand Up @@ -367,8 +368,9 @@ func New(cfg Config) (*Server, error) {
SourceIPs: sourceIPs,
},
middleware.Log{
Log: log,
SourceIPs: sourceIPs,
Log: log,
SourceIPs: sourceIPs,
LogRequestsAtInfoLevel: cfg.LogRequestsAtInfoLevel,
},
middleware.Instrument{
RouteMatcher: router,
Expand Down