Merge pull request #25 from section-io/ee-211

Introduce response time p8s metrics for Section Modules

.github/workflows/module-metrics.yaml

@@ -16,8 +16,7 @@ jobs:
     runs-on: ubuntu-latest
     steps:
       - name: Check out code
-        uses: actions/checkout@v2
+        uses: actions/checkout@v4
       - name: Run docker build
         run: |
-          pwd
-          ./build.sh main
+          docker image build "${GITHUB_WORKSPACE}"

Dockerfile

@@ -1,15 +1,33 @@
-FROM golang:1.19
+FROM golang:1.23
 
 ENV CGO_ENABLED=0
 
-RUN curl -sSfL https://raw.githubusercontent.com/golangci/golangci-lint/master/install.sh | sh -s -- -b $(go env GOPATH)/bin v1.48.0
+RUN curl -sSfL https://raw.githubusercontent.com/golangci/golangci-lint/master/install.sh | sh -s -- -b $(go env GOPATH)/bin v1.60.1
+
+RUN go env GOCACHE | grep -xF '/root/.cache/go-build'
+RUN go env GOMODCACHE | grep -xF '/go/pkg/mod'
 
 WORKDIR /src
 
 COPY go.mod go.sum ./
-RUN go mod download
+RUN --mount=type=cache,target=/go/pkg/mod/ \
+  --mount=type=cache,target=/root/.cache/go-build/ \
+  go mod download
 
 COPY . .
 
-RUN golangci-lint run ./...
-RUN go test -short -v ./...
+RUN --mount=type=cache,target=/go/pkg/mod/ \
+  --mount=type=cache,target=/root/.cache/go-build/ \
+  go build -v ./...
+
+RUN --mount=type=cache,target=/go/pkg/mod/ \
+  --mount=type=cache,target=/root/.cache/go-build/ \
+  golangci-lint run ./...
+
+RUN --mount=type=cache,target=/go/pkg/mod/ \
+  --mount=type=cache,target=/root/.cache/go-build/ \
+  go test -short -v ./...
+
+RUN --mount=type=cache,target=/go/pkg/mod/ \
+  --mount=type=cache,target=/root/.cache/go-build/ \
+  go test -run=BenchmarkOnlyNoTests -bench=. ./...

config.go

@@ -0,0 +1,42 @@
+package metrics
+
+type SecondsMultiplier float64
+
+const (
+	LogUnitSeconds      = SecondsMultiplier(1.0)
+	LogUnitMilliseconds = SecondsMultiplier(1.0 / 1000.0)
+	LogUnitMicroseconds = SecondsMultiplier(1.0 / 1000000.0)
+)
+
+type LogFieldValueFunc func(map[string]interface{}) interface{}
+
+func FirstLevelLogField(fieldName string) LogFieldValueFunc {
+	return func(log map[string]interface{}) interface{} {
+		return log[fieldName]
+	}
+}
+
+func SecondLevelLogField(firstLevelFieldName, secondLevelFieldName string) LogFieldValueFunc {
+	return func(log map[string]interface{}) interface{} {
+		first, ok := log[firstLevelFieldName]
+		if !ok {
+			return nil
+		}
+		m, ok := first.(map[string]interface{})
+		if !ok {
+			return nil
+		}
+		return m[secondLevelFieldName]
+	}
+}
+
+type Configuration struct {
+	RequestTimeLogField LogFieldValueFunc
+	RequestTimeLogUnit  SecondsMultiplier
+}
+
+var defaultConfig = &Configuration{}
+
+func Configure(c *Configuration) {
+	defaultConfig = c
+}

go.mod

@@ -1,27 +1,28 @@
 module github.com/section-io/module-metrics
 
-go 1.19
+go 1.23
 
 require (
 	github.com/mmcloughlin/geohash v0.10.0
 	github.com/pkg/errors v0.9.1
-	github.com/prometheus/client_golang v1.13.0
-	github.com/prometheus/common v0.37.0
-	github.com/stretchr/testify v1.8.0
+	github.com/prometheus/client_golang v1.20.1
+	github.com/prometheus/common v0.55.0
+	github.com/stretchr/testify v1.9.0
 	github.com/thedevsaddam/gojsonq/v2 v2.5.2
-	golang.org/x/exp v0.0.0-20220722155223-a9213eeb770e
+	golang.org/x/exp v0.0.0-20240808152545-0cdaa3abc0fa
 )
 
 require (
 	github.com/beorn7/perks v1.0.1 // indirect
-	github.com/cespare/xxhash/v2 v2.1.2 // indirect
+	github.com/cespare/xxhash/v2 v2.3.0 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
-	github.com/golang/protobuf v1.5.2 // indirect
-	github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect
+	github.com/klauspost/compress v1.17.9 // indirect
+	github.com/kr/text v0.2.0 // indirect
+	github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
-	github.com/prometheus/client_model v0.2.0 // indirect
-	github.com/prometheus/procfs v0.8.0 // indirect
-	golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a // indirect
-	google.golang.org/protobuf v1.28.1 // indirect
+	github.com/prometheus/client_model v0.6.1 // indirect
+	github.com/prometheus/procfs v0.15.1 // indirect
+	golang.org/x/sys v0.24.0 // indirect
+	google.golang.org/protobuf v1.34.2 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

histogram.go

@@ -0,0 +1,93 @@
+package metrics
+
+import (
+	"fmt"
+	"strconv"
+
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+const statusLabel = "status"
+const statusBucketLabel = "status_bucket"
+const cacheHandlingLabel = "cache_handling"
+const varnishHandlingLabel = "varnish_handling"
+
+type requestTimeProcessor struct {
+	vec      *prometheus.HistogramVec
+	logField LogFieldValueFunc
+	logUnit  SecondsMultiplier
+}
+
+type noopRequestTimeProcessor struct{}
+
+func (p *noopRequestTimeProcessor) Observe(_ map[string]string, _ map[string]interface{}) {}
+
+func newRequestTimeProcessor(vec *prometheus.HistogramVec, logField LogFieldValueFunc, logUnit SecondsMultiplier) *requestTimeProcessor {
+	return &requestTimeProcessor{
+		vec:      vec,
+		logField: logField,
+		logUnit:  logUnit,
+	}
+}
+
+func (p *requestTimeProcessor) Observe(requestLabels map[string]string, logline map[string]interface{}) {
+	subject := p.logField(logline)
+	floatValue, err := strconv.ParseFloat(fmt.Sprintf("%v", subject), 64)
+	if err != nil {
+		return
+	}
+	floatValue = floatValue * float64(p.logUnit)
+
+	labels := make(map[string]string, len(requestLabels))
+	for label, labelValue := range requestLabels {
+		histogramLabel := translateRequestLabelToHistogramLabel(label)
+		if histogramLabel == "" {
+			continue
+		}
+		switch histogramLabel {
+		case statusBucketLabel:
+			labels[histogramLabel] = statusBucket(labelValue)
+		case cacheHandlingLabel:
+			labels[histogramLabel] = translateCacheHandling(labelValue)
+		}
+	}
+
+	p.vec.With(labels).Observe(floatValue)
+}
+
+func translateRequestLabelToHistogramLabel(requestLabel string) string {
+	switch requestLabel {
+
+	// translations
+	case statusLabel:
+		return statusBucketLabel
+	case varnishHandlingLabel:
+		// Varnish should emit metrics consistent with other caches
+		return cacheHandlingLabel
+
+	// allow list
+	case statusBucketLabel:
+		return requestLabel
+	case cacheHandlingLabel:
+		return requestLabel
+
+	}
+	return ""
+}
+
+func translateCacheHandling(handlingLogValue string) string {
+	// allow list
+	switch handlingLogValue {
+	case "hit":
+		return handlingLogValue
+	case "miss":
+		return handlingLogValue
+	case "pass":
+		return handlingLogValue
+	case "synth":
+		return handlingLogValue
+	case "pipe":
+		return handlingLogValue
+	}
+	return ""
+}

metrics.go

@@ -38,6 +38,14 @@ func sanitizeLabelName(label string) string {
 	}
 }
 
+func statusBucket(status string) string {
+	if len(status) != 3 {
+		return ""
+	}
+	base := status[:len(status)-2]
+	return base + "--"
+}
+
 func sanitizeLabelValue(label string, value interface{}) string {
 
 	if value == nil || value == "" || value == "-" {
@@ -180,7 +188,6 @@ func StartReader(file io.ReadCloser, output io.Writer, errorWriter io.Writer) {
 			var logline map[string]interface{}
 			jsonErr := json.Unmarshal(line, &logline)
 			if jsonErr != nil {
-				_, _ = fmt.Fprintf(errorWriter, "json.Unmarshal failed: %v", jsonErr)
 				jsonParseErrorTotal.Inc()
 			} else {
 				labelValues := map[string]string{}
@@ -206,6 +213,7 @@ func StartReader(file io.ReadCloser, output io.Writer, errorWriter io.Writer) {
 				isAeeHealthcheck := aeeUserAgentRegex.MatchString(extractUserAgent(logline))
 				labelValues[aeeHealthcheckLabel] = strconv.FormatBool(isAeeHealthcheck)
 				addRequest(labelValues, logline)
+				requestTimeObserver.Observe(labelValues, logline)
 			}
 
 			line, err = reader.ReadBytes('\n')

p8s.go

@@ -28,6 +28,10 @@ const (
 	aeeHealthcheckLabel = "section_aee_healthcheck"
 )
 
+type logObserver interface {
+	Observe(requestLabels map[string]string, logline map[string]interface{})
+}
+
 var (
 	jsonParseErrorTotal prometheus.Counter
 	pageViewTotal       prometheus.Counter
@@ -39,6 +43,8 @@ var (
 	requestsByHostnameTotal *prometheus.CounterVec
 	bytesByHostnameTotal    *prometheus.CounterVec
 
+	requestTimeObserver logObserver
+
 	logFieldNames      []string
 	sanitizedP8sLabels []string
 	withGeoLabel       []string
@@ -184,6 +190,33 @@ func InitMetrics(additionalLabels ...string) *prometheus.Registry {
 	registry = prometheus.NewRegistry()
 	registry.MustRegister(requestsTotal, bytesTotal, pageViewTotal, jsonParseErrorTotal)
 
+	if defaultConfig.RequestTimeLogField != nil && defaultConfig.RequestTimeLogUnit > 0 {
+		// allow-list for histogram labels
+		histogramLabels := []string{}
+		for _, label := range requestLabels {
+			histogramLabel := translateRequestLabelToHistogramLabel(label)
+			if histogramLabel != "" {
+				histogramLabels = append(histogramLabels, histogramLabel)
+			}
+		}
+
+		responseTimeHistogram := prometheus.NewHistogramVec(
+			prometheus.HistogramOpts{
+				Namespace: promeNamespace,
+				Subsystem: promeSubsystem,
+				Name:      "request_duration_seconds",
+				Help:      "The latency of the HTTP requests",
+				Buckets:   []float64{.5, 1, 5, 10, 25},
+			},
+			histogramLabels,
+		)
+		registry.MustRegister(responseTimeHistogram)
+
+		requestTimeObserver = newRequestTimeProcessor(responseTimeHistogram, defaultConfig.RequestTimeLogField, defaultConfig.RequestTimeLogUnit)
+	} else {
+		requestTimeObserver = &noopRequestTimeProcessor{}
+	}
+
 	if includeHostnameMetrics {
 		requestsByHostnameTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
 			Namespace: promeNamespace,

p8s_test.go

@@ -339,6 +339,50 @@ func testContentTypeBucket(t *testing.T, stdout *bytes.Buffer) {
 	assert.Contains(t, actual, `section_http_request_count_by_hostname_total{hostname="www.example.com"} 4`)
 }
 
+func testHistogramStatusBucket_seconds(t *testing.T, stdout *bytes.Buffer) {
+
+	logs := []string{
+		`{"time":"2019-06-20T01:34:36+00:00","request_time":"0.010","hostname":"www.example.com","status":"200","content_type": "text/html", "bytes":"10","request":"GET /a/path HTTP/1.1","http_accept_encoding":"gzip","http_x_forwarded_proto":"https","http_upgrade":"-","http_connection":"-","body_bytes_sent":"0","upstream_label":"default","upstream_addr":"198.51.100.1:443","upstream_status":"304","upstream_request_connection":"","upstream_request_host":"in.example.com","upstream_header_time":"0.070","upstream_connect_time":"0.052","upstream_response_time":"0.070","upstream_response_length":"0","upstream_bytes_received":"288","upstream_http_content_type":"-","upstream_http_cache_control":"max-age=60","upstream_http_content_length":"-","upstream_http_content_encoding":"-","upstream_http_transfer_encoding":"-","sent_http_content_length":"-","sent_http_content_encoding":"-","sent_http_transfer_encoding":"-","section-io-id":"cf99df8057b93ec96c0ee1253ba4c309"}`,
+		`{"time":"2019-06-20T01:34:36+00:00","request_time":"1.069","hostname":"www.example.com","status":"200","content_type": "text/html", "bytes":"20","request":"GET /a/path HTTP/1.1","http_accept_encoding":"gzip","http_x_forwarded_proto":"https","http_upgrade":"-","http_connection":"-","body_bytes_sent":"0","upstream_label":"default","upstream_addr":"198.51.100.1:443","upstream_status":"304","upstream_request_connection":"","upstream_request_host":"in.example.com","upstream_header_time":"0.069","upstream_connect_time":"0.052","upstream_response_time":"0.069","upstream_response_length":"0","upstream_bytes_received":"288","upstream_http_content_type":"-","upstream_http_cache_control":"max-age=60","upstream_http_content_length":"-","upstream_http_content_encoding":"-","upstream_http_transfer_encoding":"-","sent_http_content_length":"-","sent_http_content_encoding":"-","sent_http_transfer_encoding":"-","section-io-id":"451e230222237f722eb49324d47142f6"}`,
+		`{"time":"2019-06-20T01:34:36+00:00","request_time":"2.069","hostname":"www.example.com","status":"404","content_type": "text/html", "bytes":"20","request":"GET /a/path HTTP/1.1","http_accept_encoding":"gzip","http_x_forwarded_proto":"https","http_upgrade":"-","http_connection":"-","body_bytes_sent":"0","upstream_label":"default","upstream_addr":"198.51.100.1:443","upstream_status":"304","upstream_request_connection":"","upstream_request_host":"in.example.com","upstream_header_time":"0.069","upstream_connect_time":"0.052","upstream_response_time":"0.069","upstream_response_length":"0","upstream_bytes_received":"288","upstream_http_content_type":"-","upstream_http_cache_control":"max-age=60","upstream_http_content_length":"-","upstream_http_content_encoding":"-","upstream_http_transfer_encoding":"-","sent_http_content_length":"-","sent_http_content_encoding":"-","sent_http_transfer_encoding":"-","section-io-id":"451e230222237f722eb49324d47142f6"}`,
+		`{"time":"2019-06-20T01:34:36+00:00","request_time":"3.069","hostname":"www.example.com","status":"200","content_type": "-", "bytes":"20","request":"GET /a/path HTTP/1.1","http_accept_encoding":"gzip","http_x_forwarded_proto":"https","http_upgrade":"-","http_connection":"-","body_bytes_sent":"0","upstream_label":"default","upstream_addr":"198.51.100.1:443","upstream_status":"304","upstream_request_connection":"","upstream_request_host":"in.example.com","upstream_header_time":"0.069","upstream_connect_time":"0.052","upstream_response_time":"0.069","upstream_response_length":"0","upstream_bytes_received":"288","upstream_http_content_type":"-","upstream_http_cache_control":"max-age=60","upstream_http_content_length":"-","upstream_http_content_encoding":"-","upstream_http_transfer_encoding":"-","sent_http_content_length":"-","sent_http_content_encoding":"-","sent_http_transfer_encoding":"-","section-io-id":"451e230222237f722eb49324d47142f6"}`,
+	}
+
+	Configure(&Configuration{
+		RequestTimeLogField: FirstLevelLogField("request_time"),
+		RequestTimeLogUnit:  LogUnitSeconds,
+	})
+	InitMetrics("status")
+
+	writeLogs(t, logs)
+
+	actual := gatherP8sResponse(t)
+
+	assert.Contains(t, actual, `section_http_request_duration_seconds_bucket{status_bucket="2--",le="0.5"} 1`)
+	assert.Contains(t, actual, `section_http_request_duration_seconds_bucket{status_bucket="2--",le="1"} 1`)
+	assert.Contains(t, actual, `section_http_request_duration_seconds_bucket{status_bucket="2--",le="5"} 3`)
+	assert.Contains(t, actual, `section_http_request_duration_seconds_bucket{status_bucket="4--",le="5"} 1`)
+}
+
+func testHistogramStatusBucket_microseconds(t *testing.T, stdout *bytes.Buffer) {
+
+	logs := []string{
+		`{"time":"2024-06-25T16:24:42+0000","inner":{"time_taken_microseconds":"113706"},"request":"GET /ex/image-1.jpeg HTTP/1.1","status":"200","bytes":"104819","response_body_bytes":"104011","content_type":"image/jpeg","hostname":"lili-main.wnet.ninja","referrer":"https://lili-main.wnet.ninja/ex/echnidna.html","useragent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/126.0.0.0 Safari/537.36","http_x_forwarded_proto":"https","section_io_tag":"","section_io_id":"eee5ca48eb43cd76fbce992f78546ce7","varnish_handling": "pass","varnish_hitmiss": "miss","varnish_vxid": "1005096","varnish_hit_vxid": "-"}`,
+	}
+
+	Configure(&Configuration{
+		RequestTimeLogField: SecondLevelLogField("inner", "time_taken_microseconds"),
+		RequestTimeLogUnit:  LogUnitMicroseconds,
+	})
+	InitMetrics("status")
+
+	writeLogs(t, logs)
+
+	actual := gatherP8sResponse(t)
+
+	assert.Contains(t, actual, `section_http_request_duration_seconds_bucket{status_bucket="2--",le="0.5"} 1`)
+}
+
 func TestReaderRunning(t *testing.T) {
 	stdout := setupReader(t)
 
@@ -357,6 +401,8 @@ func TestReaderRunning(t *testing.T) {
 
 	// Above test always pass "hostname" as an additionalLabel and test
 	t.Run("testCountersIncreaseWithoutHostnameLabel", func(t *testing.T) { testCountersIncreaseWithoutHostnameLabel(t, stdout) })
+	t.Run("testHistogramStatusBucket_seconds", func(t *testing.T) { testHistogramStatusBucket_seconds(t, stdout) })
+	t.Run("testHistogramStatusBucket_microseconds", func(t *testing.T) { testHistogramStatusBucket_microseconds(t, stdout) })
 }
 
 func TestSetupModule(t *testing.T) {