Merge pull request #236 from colin-stuart/add-flag-to-log-requests-at…

…-info-level Add flag to log requests at info level
weaveworks · Mar 2, 2022 · 00e2e23 · 00e2e23
2 parents 933588f + a4dd3f6
commit 00e2e23
Show file tree

Hide file tree

Showing 3 changed files with 73 additions and 17 deletions.
diff --git 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
@@ -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, "<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 {

diff --git 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,