github.com/weaveworks/common@v0.0.0-20230728070032-dd9e68f319d5/middleware/logging.go (about)

     1  package middleware
     2  
     3  import (
     4  	"bytes"
     5  	"context"
     6  	"errors"
     7  	"net/http"
     8  	"time"
     9  
    10  	"github.com/weaveworks/common/logging"
    11  	"github.com/weaveworks/common/tracing"
    12  	"github.com/weaveworks/common/user"
    13  )
    14  
    15  // Log middleware logs http requests
    16  type Log struct {
    17  	Log                      logging.Interface
    18  	DisableRequestSuccessLog bool
    19  	LogRequestHeaders        bool // LogRequestHeaders true -> dump http headers at debug log level
    20  	LogRequestAtInfoLevel    bool // LogRequestAtInfoLevel true -> log requests at info log level
    21  	SourceIPs                *SourceIPExtractor
    22  	HttpHeadersToExclude     map[string]bool
    23  }
    24  
    25  var defaultExcludedHeaders = map[string]bool{
    26  	"Cookie":        true,
    27  	"X-Csrf-Token":  true,
    28  	"Authorization": true,
    29  }
    30  
    31  func NewLogMiddleware(log logging.Interface, logRequestHeaders bool, logRequestAtInfoLevel bool, sourceIPs *SourceIPExtractor, headersList []string) Log {
    32  	httpHeadersToExclude := map[string]bool{}
    33  	for header := range defaultExcludedHeaders {
    34  		httpHeadersToExclude[header] = true
    35  	}
    36  	for _, header := range headersList {
    37  		httpHeadersToExclude[header] = true
    38  	}
    39  
    40  	return Log{
    41  		Log:                   log,
    42  		LogRequestHeaders:     logRequestHeaders,
    43  		LogRequestAtInfoLevel: logRequestAtInfoLevel,
    44  		SourceIPs:             sourceIPs,
    45  		HttpHeadersToExclude:  httpHeadersToExclude,
    46  	}
    47  }
    48  
    49  // logWithRequest information from the request and context as fields.
    50  func (l Log) logWithRequest(r *http.Request) logging.Interface {
    51  	localLog := l.Log
    52  	traceID, ok := tracing.ExtractTraceID(r.Context())
    53  	if ok {
    54  		localLog = localLog.WithField("traceID", traceID)
    55  	}
    56  
    57  	if l.SourceIPs != nil {
    58  		ips := l.SourceIPs.Get(r)
    59  		if ips != "" {
    60  			localLog = localLog.WithField("sourceIPs", ips)
    61  		}
    62  	}
    63  
    64  	return user.LogWith(r.Context(), localLog)
    65  }
    66  
    67  // Wrap implements Middleware
    68  func (l Log) Wrap(next http.Handler) http.Handler {
    69  	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    70  		begin := time.Now()
    71  		uri := r.RequestURI // capture the URI before running next, as it may get rewritten
    72  		requestLog := l.logWithRequest(r)
    73  		// Log headers before running 'next' in case other interceptors change the data.
    74  		headers, err := dumpRequest(r, l.HttpHeadersToExclude)
    75  		if err != nil {
    76  			headers = nil
    77  			requestLog.Errorf("Could not dump request headers: %v", err)
    78  		}
    79  		var buf bytes.Buffer
    80  		wrapped := newBadResponseLoggingWriter(w, &buf)
    81  		next.ServeHTTP(wrapped, r)
    82  
    83  		statusCode, writeErr := wrapped.getStatusCode(), wrapped.getWriteError()
    84  
    85  		if writeErr != nil {
    86  			if errors.Is(writeErr, context.Canceled) {
    87  				if l.LogRequestAtInfoLevel {
    88  					requestLog.Infof("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
    89  				} else {
    90  					requestLog.Debugf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
    91  				}
    92  			} else {
    93  				requestLog.Warnf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
    94  			}
    95  
    96  			return
    97  		}
    98  
    99  		switch {
   100  		// success and shouldn't log successful requests.
   101  		case statusCode >= 200 && statusCode < 300 && l.DisableRequestSuccessLog:
   102  			return
   103  
   104  		case 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable:
   105  			if l.LogRequestAtInfoLevel {
   106  				requestLog.Infof("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
   107  
   108  				if l.LogRequestHeaders && headers != nil {
   109  					requestLog.Infof("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
   110  				}
   111  				return
   112  			}
   113  
   114  			requestLog.Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
   115  			if l.LogRequestHeaders && headers != nil {
   116  				requestLog.Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
   117  			}
   118  		default:
   119  			requestLog.Warnf("%s %s (%d) %s Response: %q ws: %v; %s",
   120  				r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)
   121  		}
   122  	})
   123  }
   124  
   125  // Logging middleware logs each HTTP request method, path, response code and
   126  // duration for all HTTP requests.
   127  var Logging = Log{
   128  	Log: logging.Global(),
   129  }
   130  
   131  func dumpRequest(req *http.Request, httpHeadersToExclude map[string]bool) ([]byte, error) {
   132  	var b bytes.Buffer
   133  
   134  	// In case users initialize the Log middleware using the exported struct, skip the default headers anyway
   135  	if len(httpHeadersToExclude) == 0 {
   136  		httpHeadersToExclude = defaultExcludedHeaders
   137  	}
   138  	// Exclude some headers for security, or just that we don't need them when debugging
   139  	err := req.Header.WriteSubset(&b, httpHeadersToExclude)
   140  	if err != nil {
   141  		return nil, err
   142  	}
   143  
   144  	ret := bytes.Replace(b.Bytes(), []byte("\r\n"), []byte("; "), -1)
   145  	return ret, nil
   146  }