evcc-io/util/request/roundtrip.go

package request

import (
	"bytes"
	"io"
	"mime"
	"net/http"
	"net/http/httputil"
	"strconv"
	"strings"
	"time"

	"github.com/evcc-io/evcc/util"
	"github.com/prometheus/client_golang/prometheus"
	"github.com/sandrolain/httpcache"
)

type roundTripper struct {
	log  *util.Logger
	base http.RoundTripper
}

var (
	LogHeaders bool
	LogMaxLen  = 1024 * 8
	reqMetric  *prometheus.SummaryVec
	resMetric  *prometheus.CounterVec
)

func init() {
	labels := []string{"host"}

	reqMetric = prometheus.NewSummaryVec(prometheus.SummaryOpts{
		Namespace: "evcc",
		Subsystem: "http",
		Name:      "request_duration_seconds",
		Help:      "A summary of HTTP request durations",
		Objectives: map[float64]float64{
			0.5:  0.05,  // 50th percentile with a max. absolute error of 0.05
			0.9:  0.01,  // 90th percentile with a max. absolute error of 0.01
			0.99: 0.001, // 99th percentile with a max. absolute error of 0.001
		},
	}, labels)

	resMetric = prometheus.NewCounterVec(prometheus.CounterOpts{
		Namespace: "evcc",
		Subsystem: "http",
		Name:      "request_total",
		Help:      "Total count of HTTP requests",
	}, append(labels, "status"))

	prometheus.MustRegister(reqMetric, resMetric)
}

// NewTripper creates a logging roundtrip handler
func NewTripper(log *util.Logger, base http.RoundTripper) http.RoundTripper {
	tripper := &roundTripper{
		log:  log,
		base: base,
	}

	return tripper
}

func isWebSocket(req *http.Request) bool {
	// WebSocket handshake must be GET
	if req.Method != http.MethodGet {
		return false
	}

	// Must contain: Connection: Upgrade
	if !headerContainsToken(req.Header, "Connection", "Upgrade") {
		return false
	}

	// Must contain: Upgrade: websocket
	if !headerContainsToken(req.Header, "Upgrade", "websocket") {
		return false
	}

	// Must contain WebSocket-specific headers
	if req.Header.Get("Sec-WebSocket-Key") == "" {
		return false
	}

	if req.Header.Get("Sec-WebSocket-Version") == "" {
		return false
	}

	return true
}

func headerContainsToken(h http.Header, key, token string) bool {
	for _, v := range h.Values(key) {
		for part := range strings.SplitSeq(v, ",") {
			if strings.EqualFold(strings.TrimSpace(part), token) {
				return true
			}
		}
	}
	return false
}

// binaryContent reports whether the response carries a binary body whose raw
// bytes are not useful in the trace log, such as a downloaded archive.
func binaryContent(h http.Header) bool {
	mediatype, _, _ := mime.ParseMediaType(h.Get("Content-Type"))
	return mediatype == "application/octet-stream"
}

// copy of http.drainBody
func drainBody(b io.ReadCloser) (r1, r2 io.ReadCloser, err error) {
	if b == nil || b == http.NoBody {
		// No copying needed. Preserve the magic sentinel meaning of NoBody.
		return http.NoBody, http.NoBody, nil
	}
	var buf bytes.Buffer
	if _, err = buf.ReadFrom(b); err != nil {
		return nil, b, err
	}
	if err = b.Close(); err != nil {
		return nil, b, err
	}
	return io.NopCloser(&buf), io.NopCloser(bytes.NewReader(buf.Bytes())), nil
}

// Truncate limits a string to LogMaxLen for trace logs, appending an ellipsis when cut
func Truncate(s string) string {
	if len(s) > LogMaxLen {
		return s[:LogMaxLen] + "..."
	}
	return s
}

// dump http request/response body
func dump(r io.ReadCloser, w *strings.Builder) error {
	body, err := io.ReadAll(r)
	if err != nil {
		return err
	}
	if w.Len() > 0 && len(body) > 0 {
		w.WriteString("\n--\n")
	}
	_, err = w.WriteString(Truncate(strings.TrimSpace(string(body))))
	return err
}

func (r *roundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
	// add evcc user agent
	if req.Header.Get("User-Agent") == "" {
		req = req.Clone(req.Context())
		req.Header.Set("User-Agent", "evcc/"+util.FormattedVersion())
	}

	// dump without headers
	var err error
	var save io.ReadCloser

	bld := new(strings.Builder)

	isWebSocketReq := isWebSocket(req)
	if !isWebSocketReq {
		if LogHeaders {
			if body, err := httputil.DumpRequestOut(req, true); err == nil {
				bld.WriteString("\n")
				bld.WriteString(Truncate(strings.TrimSpace(string(body))))
			}
		} else {
			if save, req.Body, err = drainBody(req.Body); err == nil {
				err = dump(save, bld)
			}
			if err != nil {
				return nil, err
			}
		}
	}

	startTime := time.Now()
	resp, err := r.base.RoundTrip(req)

	reqMetric.WithLabelValues(req.URL.Hostname()).Observe(time.Since(startTime).Seconds())

	var cached string
	if err == nil && resp.Header.Get(httpcache.XFromCache) != "" {
		cached = " CACHED"
	}
	r.log.TRACE.Printf("%s%s %s", req.Method, cached, req.URL.String())

	if err == nil {
		resMetric.WithLabelValues(req.URL.Hostname(), strconv.Itoa(resp.StatusCode)).Add(1)

		if !isWebSocketReq {
			// skip binary bodies (e.g. downloaded archives) - their raw bytes are noise in the trace log
			logBody := !binaryContent(resp.Header)
			if LogHeaders {
				if body, err := httputil.DumpResponse(resp, logBody); err == nil {
					bld.WriteString("\n\n")
					bld.WriteString(Truncate(strings.TrimSpace(string(body))))
				}
			} else if logBody {
				if save, resp.Body, err = drainBody(resp.Body); err == nil {
					err = dump(save, bld)
				}
				if err != nil {
					return nil, err
				}
			}
		}
	} else {
		resMetric.WithLabelValues(req.URL.Hostname(), "999").Add(1)
	}

	if bld.Len() > 0 {
		r.log.TRACE.Println(bld.String())
	}

	return resp, err
}