refactor: add more tracing information to writes (#16118)

refactor: add more tracing information to writes

go.mod

@@ -54,6 +54,7 @@ require (
 	github.com/mattn/go-isatty v0.0.8
 	github.com/mattn/go-zglob v0.0.1 // indirect
 	github.com/matttproud/golang_protobuf_extensions v1.0.1
+	github.com/mileusna/useragent v0.0.0-20190129205925-3e331f0949a5
 	github.com/mitchellh/go-homedir v1.1.0 // indirect
 	github.com/mna/pigeon v1.0.1-0.20180808201053-bb0192cfc2ae
 	github.com/mschoch/smat v0.0.0-20160514031455-90eadee771ae // indirect

go.sum

@@ -302,6 +302,8 @@ github.com/mattn/go-zglob v0.0.1 h1:xsEx/XUoVlI6yXjqBK062zYhRTZltCNmYPx6v+8DNaY=
 github.com/mattn/go-zglob v0.0.1/go.mod h1:9fxibJccNxU2cnpIKLRRFA7zX7qhkJIQWBb449FYHOo=
 github.com/matttproud/golang_protobuf_extensions v1.0.1 h1:4hp9jkHxhMHkqkrB3Ix0jegS5sx/RkqARlsWZ6pIwiU=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
+github.com/mileusna/useragent v0.0.0-20190129205925-3e331f0949a5 h1:pXqZHmHOz6LN+zbbUgqyGgAWRnnZEI40IzG3tMsXcSI=
+github.com/mileusna/useragent v0.0.0-20190129205925-3e331f0949a5/go.mod h1:JWhYAp2EXqUtsxTKdeGlY8Wp44M7VxThC9FEoNGi2IE=
 github.com/mitchellh/cli v1.0.0/go.mod h1:hNIlj7HEI86fIcpObd7a0FcrxTWetlwJDGcceTlRvqc=
 github.com/mitchellh/copystructure v1.0.0/go.mod h1:SNtv71yrdKgLRyLFxmLdkAbkKEFWgYaq1OVrnRcwhnw=
 github.com/mitchellh/go-homedir v1.0.0 h1:vKb8ShqSby24Yrqr/yDYkuFz8d0WUjys40rvnGC8aR0=

http/handler.go

@@ -85,9 +85,14 @@ func NewHandlerFromRegistry(name string, reg *prom.Registry) *Handler {
 func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	var span opentracing.Span
 	span, r = tracing.ExtractFromHTTPRequest(r, h.name)
-	userAgent := r.Header.Get("User-Agent")
-	if userAgent == "" {
-		userAgent = "unknown"
+	ua := userAgent(r)
+	span.LogKV("user_agent", ua, "referer", r.Referer(), "remote_addr", r.RemoteAddr)
+	for k, v := range r.Header {
+		if len(v) == 0 {
+			continue
+		}
+		// If header has multiple values, only the first value will be logged on the trace.
+		span.LogKV(k, v[0])
 	}
 
 	defer span.Finish()
@@ -105,14 +110,14 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			"method":     r.Method,
 			"path":       r.URL.Path,
 			"status":     statusClass,
-			"user_agent": userAgent,
+			"user_agent": ua,
 		}).Inc()
 		h.requestDur.With(prometheus.Labels{
 			"handler":    h.name,
 			"method":     r.Method,
 			"path":       r.URL.Path,
 			"status":     statusClass,
-			"user_agent": userAgent,
+			"user_agent": ua,
 		}).Observe(duration.Seconds())
 	}(time.Now())
 

http/ua.go

@@ -0,0 +1,17 @@
+package http
+
+import (
+	"net/http"
+
+	useragent "github.com/mileusna/useragent"
+)
+
+func userAgent(r *http.Request) string {
+	header := r.Header.Get("User-Agent")
+	if header == "" {
+		return "unknown"
+	}
+
+	ua := useragent.Parse(header)
+	return ua.Name
+}

http/ua_test.go

@@ -0,0 +1,59 @@
+package http
+
+import (
+	nethttp "net/http"
+	"testing"
+)
+
+func Test_userAgent(t *testing.T) {
+	tests := []struct {
+		name string
+		ua   string
+		want string
+	}{
+		{
+			name: "linux chrome",
+			ua:   "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36",
+			want: "Chrome",
+		},
+		{
+			name: "telegraf",
+			ua:   "Telegraf/1.12.6",
+			want: "Telegraf",
+		},
+		{
+			name: "curl",
+			ua:   "curl/7.67.0",
+			want: "curl",
+		},
+		{
+			name: "go",
+			ua:   "Go-http-client/1.1",
+			want: "Go-http-client",
+		},
+		{
+			name: "influx client",
+			ua:   "InfluxDBClient/0.0.1  (golang; windows; amd64)",
+			want: "InfluxDBClient",
+		},
+		{
+			name: "iphone",
+			ua:   "Mozilla/5.0 (iPhone; CPU iPhone OS 13_3 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.0.4 Mobile/15E148 Safari/604.1",
+			want: "Safari",
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			r := &nethttp.Request{
+				Header: nethttp.Header{
+					"User-Agent": []string{tt.ua},
+				},
+			}
+
+			got := userAgent(r)
+			if got != tt.want {
+				t.Fatalf("userAgent %v want %v", got, tt.want)
+			}
+		})
+	}
+}

http/write_handler.go

@@ -145,6 +145,7 @@ func (h *WriteHandler) handleWrite(w http.ResponseWriter, r *http.Request) {
 	}
 
 	orgID = org.ID
+	span.LogKV("org_id", orgID)
 
 	var bucket *influxdb.Bucket
 	if id, err := influxdb.IDFromString(req.Bucket); err == nil {
@@ -173,6 +174,7 @@ func (h *WriteHandler) handleWrite(w http.ResponseWriter, r *http.Request) {
 
 		bucket = b
 	}
+	span.LogKV("bucket_id", bucket.ID)
 
 	p, err := influxdb.NewPermissionAtID(bucket.ID, influxdb.WriteAction, influxdb.BucketsResourceType, org.ID)
 	if err != nil {
@@ -197,7 +199,10 @@ func (h *WriteHandler) handleWrite(w http.ResponseWriter, r *http.Request) {
 	// TODO(jeff): we should be publishing with the org and bucket instead of
 	// parsing, rewriting, and publishing, but the interface isn't quite there yet.
 	// be sure to remove this when it is there!
+	span, _ = tracing.StartSpanFromContextWithOperationName(ctx, "read request body")
 	data, err := ioutil.ReadAll(in)
+	span.LogKV("request_bytes", len(data))
+	span.Finish()
 	if err != nil {
 		logger.Error("Error reading body", zap.Error(err))
 		h.HandleHTTPError(ctx, &influxdb.Error{
@@ -219,9 +224,12 @@ func (h *WriteHandler) handleWrite(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	span, _ = tracing.StartSpanFromContextWithOperationName(ctx, "encoding and parsing")
 	encoded := tsdb.EncodeName(org.ID, bucket.ID)
 	mm := models.EscapeMeasurement(encoded[:])
 	points, err := models.ParsePointsWithPrecision(data, mm, time.Now(), req.Precision)
+	span.LogKV("values_total", len(points))
+	span.Finish()
 	if err != nil {
 		logger.Error("Error parsing points", zap.Error(err))
 		h.HandleHTTPError(ctx, &influxdb.Error{