diff --git a/middleware/logging.go b/middleware/logging.go index 81e1e48a..015cc3b5 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -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 + LogRequestAtInfoLevel bool // LogRequestAtInfoLevel true -> log requests at info log level + SourceIPs *SourceIPExtractor } // logWithRequest information from the request and context as fields. @@ -42,11 +43,12 @@ func (l Log) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { begin := time.Now() uri := r.RequestURI // capture the URI before running next, as it may get rewritten + requestLog := l.logWithRequest(r) // Log headers before running 'next' in case other interceptors change the data. headers, err := dumpRequest(r) if err != nil { headers = nil - l.logWithRequest(r).Errorf("Could not dump request headers: %v", err) + requestLog.Errorf("Could not dump request headers: %v", err) } var buf bytes.Buffer wrapped := newBadResponseLoggingWriter(w, &buf) @@ -56,20 +58,32 @@ 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.LogRequestAtInfoLevel { + requestLog.Infof("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers) + } else { + requestLog.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) + requestLog.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.LogRequestAtInfoLevel { + requestLog.Infof("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin)) + } else { + requestLog.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.LogRequestAtInfoLevel { + requestLog.Infof("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) + } else { + requestLog.Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers)) + } } } else { - l.logWithRequest(r).Warnf("%s %s (%d) %s Response: %q ws: %v; %s", + requestLog.Warnf("%s %s (%d) %s Response: %q ws: %v; %s", r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers) } }) diff --git a/middleware/logging_test.go b/middleware/logging_test.go index 249026c1..c1efeb1d 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -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), + LogRequestAtInfoLevel: true, + } + handler := func(w http.ResponseWriter, r *http.Request) { + io.WriteString(w, "Hello World!") + } + 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 { diff --git a/server/server.go b/server/server.go index 6a27afc5..ef325ffc 100644 --- a/server/server.go +++ b/server/server.go @@ -91,12 +91,13 @@ type Config struct { GRPCServerMinTimeBetweenPings time.Duration `yaml:"grpc_server_min_time_between_pings"` GRPCServerPingWithoutStreamAllowed bool `yaml:"grpc_server_ping_without_stream_allowed"` - LogFormat logging.Format `yaml:"log_format"` - LogLevel logging.Level `yaml:"log_level"` - Log logging.Interface `yaml:"-"` - LogSourceIPs bool `yaml:"log_source_ips_enabled"` - LogSourceIPsHeader string `yaml:"log_source_ips_header"` - LogSourceIPsRegex string `yaml:"log_source_ips_regex"` + LogFormat logging.Format `yaml:"log_format"` + LogLevel logging.Level `yaml:"log_level"` + Log logging.Interface `yaml:"-"` + LogSourceIPs bool `yaml:"log_source_ips_enabled"` + LogSourceIPsHeader string `yaml:"log_source_ips_header"` + LogSourceIPsRegex string `yaml:"log_source_ips_regex"` + LogRequestAtInfoLevel bool `yaml:"log_request_at_info_level_enabled"` // If not set, default signal handler is used. SignalHandler SignalHandler `yaml:"-"` @@ -149,6 +150,7 @@ func (cfg *Config) RegisterFlags(f *flag.FlagSet) { f.BoolVar(&cfg.LogSourceIPs, "server.log-source-ips-enabled", false, "Optionally log the source IPs.") f.StringVar(&cfg.LogSourceIPsHeader, "server.log-source-ips-header", "", "Header field storing the source IPs. Only used if server.log-source-ips-enabled is true. If not set the default Forwarded, X-Real-IP and X-Forwarded-For headers are used") f.StringVar(&cfg.LogSourceIPsRegex, "server.log-source-ips-regex", "", "Regex for matching the source IPs. Only used if server.log-source-ips-enabled is true. If not set the default Forwarded, X-Real-IP and X-Forwarded-For headers are used") + f.BoolVar(&cfg.LogRequestAtInfoLevel, "server.log-request-at-info-level-enabled", false, "Optionally log requests at info level instead of debug level.") } // Server wraps a HTTP and gRPC server, and some common initialization. @@ -367,8 +369,9 @@ func New(cfg Config) (*Server, error) { SourceIPs: sourceIPs, }, middleware.Log{ - Log: log, - SourceIPs: sourceIPs, + Log: log, + SourceIPs: sourceIPs, + LogRequestAtInfoLevel: cfg.LogRequestAtInfoLevel, }, middleware.Instrument{ RouteMatcher: router,