fortio.org/log@v1.12.2/http_logging.go (about)

     1  // Copyright 2017-2023 Fortio Authors
     2  //
     3  // Licensed under the Apache License, Version 2.0 (the "License");
     4  // you may not use this file except in compliance with the License.
     5  // You may obtain a copy of the License at
     6  //
     7  //     http://www.apache.org/licenses/LICENSE-2.0
     8  //
     9  // Unless required by applicable law or agreed to in writing, software
    10  // distributed under the License is distributed on an "AS IS" BASIS,
    11  // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    12  // See the License for the specific language governing permissions and
    13  // limitations under the License.
    14  
    15  package log
    16  
    17  import (
    18  	"crypto/tls"
    19  	"fmt"
    20  	"log"
    21  	"net/http"
    22  	"runtime/debug"
    23  	"sort"
    24  	"strings"
    25  	"time"
    26  )
    27  
    28  // TLSInfo returns ' https <cipher suite> "<peer CN>"' if the request is using TLS
    29  // (and ' "<peer CN>"' part if mtls / a peer certificate is present) or "" otherwise.
    30  // Use [AppendTLSInfoAttrs] unless you do want to just output text.
    31  func TLSInfo(r *http.Request) string {
    32  	if r.TLS == nil {
    33  		return ""
    34  	}
    35  	cliCert := ""
    36  	if len(r.TLS.PeerCertificates) > 0 {
    37  		cliCert = fmt.Sprintf(" %q", r.TLS.PeerCertificates[0].Subject)
    38  	}
    39  	return fmt.Sprintf(" https %s%s", tls.CipherSuiteName(r.TLS.CipherSuite), cliCert)
    40  }
    41  
    42  func AppendTLSInfoAttrs(attrs []KeyVal, r *http.Request) []KeyVal {
    43  	if r.TLS == nil {
    44  		return attrs
    45  	}
    46  	attrs = append(attrs, Attr("tls", true))
    47  	if len(r.TLS.PeerCertificates) > 0 {
    48  		attrs = append(attrs, Str("tls.peer_cn", r.TLS.PeerCertificates[0].Subject.CommonName))
    49  	}
    50  	return attrs
    51  }
    52  
    53  func AddIfNotEmpty(attrs []KeyVal, key, value string) []KeyVal {
    54  	if value != "" {
    55  		attrs = append(attrs, Str(key, value))
    56  	}
    57  	return attrs
    58  }
    59  
    60  // LogRequest logs the incoming request, TLSInfo,
    61  // including headers when loglevel is verbose.
    62  // additional key:value pairs can be passed as extraAttributes.
    63  //
    64  //nolint:revive // name is fine.
    65  func LogRequest(r *http.Request, msg string, extraAttributes ...KeyVal) {
    66  	if !Log(Info) {
    67  		return
    68  	}
    69  	// URL struct is quite verbose and not that interesting to log all pieces so we log the String() version
    70  	var url KeyVal
    71  	if r.URL == nil {
    72  		url = Any("url", r.URL) // basically 'null'
    73  	} else {
    74  		url = Str("url", r.URL.String())
    75  	}
    76  	attr := []KeyVal{
    77  		Str("method", r.Method), url, Str("host", r.Host),
    78  		Str("proto", r.Proto), Str("remote_addr", r.RemoteAddr),
    79  	}
    80  	if !LogVerbose() { // in verbose all headers are already logged
    81  		attr = AddIfNotEmpty(attr, "user-agent", r.Header.Get("User-Agent"))
    82  		// note this only prints the first one, while verbose mode will join all values with ','
    83  		attr = AddIfNotEmpty(attr, "header.x-forwarded-proto", r.Header.Get("X-Forwarded-Proto"))
    84  		attr = AddIfNotEmpty(attr, "header.x-forwarded-for", r.Header.Get("X-Forwarded-For"))
    85  		attr = AddIfNotEmpty(attr, "header.x-forwarded-host", r.Header.Get("X-Forwarded-Host"))
    86  	}
    87  	attr = AppendTLSInfoAttrs(attr, r)
    88  	attr = append(attr, extraAttributes...)
    89  	if LogVerbose() {
    90  		// Host is removed from headers map and put separately
    91  		// Need to sort to get a consistent order
    92  		keys := make([]string, 0, len(r.Header))
    93  		for name := range r.Header {
    94  			keys = append(keys, name)
    95  		}
    96  		sort.Strings(keys)
    97  		for _, name := range keys {
    98  			nl := strings.ToLower(name)
    99  			if nl != "user-agent" {
   100  				nl = "header." + nl
   101  			}
   102  			attr = append(attr, Str(nl, strings.Join(r.Header[name], ",")))
   103  		}
   104  	}
   105  	// not point in having the line number be this file
   106  	s(Info, false, Config.JSON, msg, attr...)
   107  }
   108  
   109  // LogResponse logs the response code, byte size and duration of the request.
   110  // additional key:value pairs can be passed as extraAttributes.
   111  //
   112  //nolint:revive // name is fine.
   113  func LogResponse[T *ResponseRecorder | *http.Response](r T, msg string, extraAttributes ...KeyVal) {
   114  	if !Log(Info) {
   115  		return
   116  	}
   117  	var status int
   118  	var size int64
   119  	switch v := any(r).(type) { // go generics...
   120  	case *ResponseRecorder:
   121  		status = v.StatusCode
   122  		size = v.ContentLength
   123  	case *http.Response:
   124  		status = v.StatusCode
   125  		size = v.ContentLength
   126  	}
   127  	attr := []KeyVal{
   128  		Int("status", status),
   129  		Int64("size", size),
   130  	}
   131  	attr = append(attr, extraAttributes...)
   132  	// not point in having the line number be this file
   133  	s(Info, false, Config.JSON, msg, attr...)
   134  }
   135  
   136  // Can be used (and is used by LogAndCall()) to wrap a http.ResponseWriter to record status code and size.
   137  type ResponseRecorder struct {
   138  	w             http.ResponseWriter
   139  	startTime     time.Time
   140  	StatusCode    int
   141  	ContentLength int64
   142  }
   143  
   144  func (rr *ResponseRecorder) Header() http.Header {
   145  	return rr.w.Header()
   146  }
   147  
   148  func (rr *ResponseRecorder) Write(p []byte) (int, error) {
   149  	size, err := rr.w.Write(p)
   150  	rr.ContentLength += int64(size)
   151  	if err != nil {
   152  		rr.StatusCode = http.StatusInternalServerError
   153  	} else if rr.StatusCode == 0 {
   154  		rr.StatusCode = http.StatusOK
   155  	}
   156  	return size, err
   157  }
   158  
   159  func (rr *ResponseRecorder) WriteHeader(code int) {
   160  	rr.w.WriteHeader(code)
   161  	rr.StatusCode = code
   162  }
   163  
   164  // Implement http.Flusher interface.
   165  func (rr *ResponseRecorder) Flush() {
   166  	if f, ok := rr.w.(http.Flusher); ok {
   167  		f.Flush()
   168  	}
   169  }
   170  
   171  // LogAndCall logs the incoming request and the response code, byte size and duration
   172  // of the request.
   173  //
   174  // If Config.CombineRequestAndResponse or the LOGGER_COMBINE_REQUEST_AND_RESPONSE
   175  // environment variable is true, then a single log entry is done combining request and
   176  // response information, including catching for panic.
   177  //
   178  // Additional key:value pairs can be passed as extraAttributes.
   179  //
   180  //nolint:revive // name is fine.
   181  func LogAndCall(msg string, handlerFunc http.HandlerFunc, extraAttributes ...KeyVal) http.HandlerFunc {
   182  	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
   183  		// This is really 2 functions but we want to be able to change config without rewiring the middleware
   184  		if Config.CombineRequestAndResponse {
   185  			respRec := &ResponseRecorder{w: w, startTime: time.Now()}
   186  			defer func() {
   187  				if err := recover(); err != nil {
   188  					s(Critical, false, Config.JSON, "panic in handler", Any("error", err))
   189  					if Log(Verbose) {
   190  						s(Verbose, false, Config.JSON, "stack trace", Str("stack", string(debug.Stack())))
   191  					}
   192  				}
   193  				attr := []KeyVal{
   194  					Int("status", respRec.StatusCode),
   195  					Int64("size", respRec.ContentLength),
   196  					Int64("microsec", time.Since(respRec.startTime).Microseconds()),
   197  				}
   198  				attr = append(attr, extraAttributes...)
   199  				LogRequest(r, msg, attr...)
   200  			}()
   201  			handlerFunc(respRec, r)
   202  			return
   203  		}
   204  		LogRequest(r, msg, extraAttributes...)
   205  		respRec := &ResponseRecorder{w: w, startTime: time.Now()}
   206  		handlerFunc(respRec, r)
   207  		LogResponse(respRec, msg, Int64("microsec", time.Since(respRec.startTime).Microseconds()))
   208  	})
   209  }
   210  
   211  type logWriter struct {
   212  	source string
   213  	level  Level
   214  }
   215  
   216  // Returns a Std logger that will log to the given level with the given source attribute.
   217  // Can be passed for instance to net/http/httputil.ReverseProxy.ErrorLog.
   218  func NewStdLogger(source string, level Level) *log.Logger {
   219  	return log.New(logWriter{source, level}, "", 0)
   220  }
   221  
   222  func (w logWriter) Write(p []byte) (n int, err error) {
   223  	// Force JSON to avoid infinite loop and also skip file/line so it doesn't show this file as the source
   224  	// (TODO consider passing the level up the stack to look for the caller)
   225  	s(w.level, false, true, strings.TrimSpace(string(p)), Str("src", w.source))
   226  	return len(p), nil
   227  }
   228  
   229  // InterceptStandardLogger changes the output of the standard logger to use ours, at the given
   230  // level, with the source "std", as a catchall.
   231  func InterceptStandardLogger(level Level) {
   232  	log.SetFlags(0)
   233  	log.SetOutput(logWriter{"std", level})
   234  }