diff --git a/src/core/metrics/metrics_util.go b/src/core/metrics/metrics_util.go index 46f942f95..af9393d90 100644 --- a/src/core/metrics/metrics_util.go +++ b/src/core/metrics/metrics_util.go @@ -12,9 +12,10 @@ import ( "sync" "time" - "github.com/gogo/protobuf/types" "github.com/nginx/agent/sdk/v2/proto" "github.com/nginx/agent/v2/src/core/config" + + "github.com/gogo/protobuf/types" ) type Collector interface { @@ -129,6 +130,16 @@ func GetCalculationMap() map[string]string { "nginx.http.v1_0": "sum", "nginx.http.v1_1": "sum", "nginx.http.v2": "sum", + "nginx.upstream.connect.time": "avg", + "nginx.upstream.connect.time.count": "sum", + "nginx.upstream.connect.time.max": "avg", + "nginx.upstream.connect.time.median": "avg", + "nginx.upstream.connect.time.pctl95": "avg", + "nginx.upstream.header.time": "avg", + "nginx.upstream.header.time.count": "sum", + "nginx.upstream.header.time.max": "avg", + "nginx.upstream.header.time.median": "avg", + "nginx.upstream.header.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", "nginx.http.conn.writing": "avg", diff --git a/src/core/metrics/sources/cpu.go b/src/core/metrics/sources/cpu.go index 391913c53..def4a1404 100644 --- a/src/core/metrics/sources/cpu.go +++ b/src/core/metrics/sources/cpu.go @@ -15,6 +15,7 @@ import ( "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" cgroup "github.com/nginx/agent/v2/src/core/metrics/sources/cgroup" + "github.com/shirou/gopsutil/v3/cpu" log "github.com/sirupsen/logrus" ) diff --git a/src/core/metrics/sources/cpu_test.go b/src/core/metrics/sources/cpu_test.go index 5009e1144..2ab0330b9 100644 --- a/src/core/metrics/sources/cpu_test.go +++ b/src/core/metrics/sources/cpu_test.go @@ -18,6 +18,7 @@ import ( "github.com/nginx/agent/sdk/v2/proto" cgroup "github.com/nginx/agent/v2/src/core/metrics/sources/cgroup" tutils "github.com/nginx/agent/v2/test/utils" + "github.com/shirou/gopsutil/v3/cpu" "github.com/stretchr/testify/assert" ) diff --git a/src/core/metrics/sources/nginx_access_log.go b/src/core/metrics/sources/nginx_access_log.go index 6617354cc..124a39415 100644 --- a/src/core/metrics/sources/nginx_access_log.go +++ b/src/core/metrics/sources/nginx_access_log.go @@ -18,18 +18,18 @@ import ( "time" "github.com/nginx/agent/sdk/v2/proto" - log "github.com/sirupsen/logrus" - "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" "github.com/nginx/agent/v2/src/core/metrics/sources/tailer" + + log "github.com/sirupsen/logrus" ) const ( spaceDelim = " " ) -// This metrics source is used to tail the NGINX access logs to retrieve http metrics. +// This metrics source is used to tail the NGINX access logs to retrieve metrics. type NginxAccessLog struct { baseDimensions *metrics.CommonDim @@ -49,7 +49,7 @@ func NewNginxAccessLog( binary core.NginxBinary, nginxType string, collectionInterval time.Duration) *NginxAccessLog { - log.Trace("Creating NewNginxAccessLog") + log.Trace("Creating NginxAccessLog") nginxAccessLog := &NginxAccessLog{ baseDimensions, @@ -78,7 +78,6 @@ func NewNginxAccessLog( func (c *NginxAccessLog) Collect(ctx context.Context, wg *sync.WaitGroup, m chan<- *proto.StatsEntity) { defer wg.Done() - c.collectLogStats(ctx, m) } @@ -153,15 +152,22 @@ func (c *NginxAccessLog) collectLogStats(ctx context.Context, m chan<- *proto.St c.buf = []*proto.StatsEntity{} } +var httpRequestMetrics = []string{ + "request.time", + "request.time.count", + "request.time.max", + "request.time.median", + "request.time.pctl95", +} + func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string) { logPattern := convertLogFormat(logFormat) log.Debugf("Collecting from: %s using format: %s", logFile, logFormat) log.Debugf("Pattern used for tailing logs: %s", logPattern) - counters := getDefaultCounters() - gzipRatios := []float64{} - requestLengths := []float64{} - requestTimes := []float64{} + httpCounters, connCounters, headerCounters := getDefaultCounters() + gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + mu := sync.Mutex{} t, err := tailer.NewPatternTailer(logFile, map[string]string{"DEFAULT": logPattern}) @@ -187,34 +193,34 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string mu.Lock() if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { n := "request.body_bytes_sent" - counters[n] = float64(v) + counters[n] + httpCounters[n] = float64(v) + httpCounters[n] } else { - log.Debugf("Error getting body_bytes_sent value from access logs, %v", err) + log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) } if v, err := strconv.Atoi(access.BytesSent); err == nil { n := "request.bytes_sent" - counters[n] = float64(v) + counters[n] + httpCounters[n] = float64(v) + httpCounters[n] } else { - log.Debugf("Error getting bytes_sent value from access logs, %v", err) + log.Debugf("Error getting bytes_sent value from access logs: %v", err) } if v, err := strconv.Atoi(access.GzipRatio); err == nil { gzipRatios = append(gzipRatios, float64(v)) } else { - log.Debugf("Error getting gzip_ratio value from access logs, %v", err) + log.Debugf("Error getting gzip_ratio value from access logs: %v", err) } if v, err := strconv.Atoi(access.RequestLength); err == nil { requestLengths = append(requestLengths, float64(v)) } else { - log.Debugf("Error getting request_length value from access logs, %v", err) + log.Debugf("Error getting request_length value from access logs: %v", err) } if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { requestTimes = append(requestTimes, v) } else { - log.Debugf("Error getting request_time value from access logs, %v", err) + log.Debugf("Error getting request_time value from access logs: %v", err) } if access.Request != "" { @@ -223,24 +229,46 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string if isOtherMethod(n) { n = "method.others" } - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 if access.ServerProtocol == "" { if strings.Count(protocol, "/") == 1 { httpProtocolVersion := strings.Split(protocol, "/")[1] httpProtocolVersion = strings.ReplaceAll(httpProtocolVersion, ".", "_") n = fmt.Sprintf("v%s", httpProtocolVersion) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } } + for _, cTime := range strings.Split(access.UpstreamConnectTime, ", ") { + // nginx uses '-' to represent TCP connection failures + cTime = strings.ReplaceAll(cTime, "-", "0") + + if v, err := strconv.ParseFloat(cTime, 64); err == nil { + connectTimes = append(connectTimes, v) + } else { + log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) + } + } + + for _, hTime := range strings.Split(access.UpstreamHeaderTime, ", ") { + // nginx uses '-' to represent TCP connection failures + hTime = strings.ReplaceAll(hTime, "-", "0") + + if v, err := strconv.ParseFloat(hTime, 64); err == nil { + headerTimes = append(headerTimes, v) + } else { + log.Debugf("Error getting upstream_header_time value from access logs: %v", err) + } + } + if access.ServerProtocol != "" { if strings.Count(access.ServerProtocol, "/") == 1 { httpProtocolVersion := strings.Split(access.ServerProtocol, "/")[1] httpProtocolVersion = strings.ReplaceAll(httpProtocolVersion, ".", "_") n := fmt.Sprintf("v%s", httpProtocolVersion) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } @@ -248,18 +276,18 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string if c.nginxType == OSSNginxType { if v, err := strconv.Atoi(access.Status); err == nil { n := fmt.Sprintf("status.%dxx", v/100) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 if v == 403 || v == 404 || v == 500 || v == 502 || v == 503 || v == 504 { n := fmt.Sprintf("status.%d", v) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } if v == 499 { n := "status.discarded" - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } if v == 400 { n := "request.malformed" - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } else { log.Debugf("Error getting status value from access logs, %v", err) @@ -270,29 +298,41 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string case <-tick.C: c.baseDimensions.NginxType = c.nginxType c.baseDimensions.PublishedAPI = logFile - c.group = "http" mu.Lock() if len(requestLengths) > 0 { - counters["request.length"] = getRequestLengthMetricValue(requestLengths) + httpCounters["request.length"] = getRequestLengthMetricValue(requestLengths) } + if len(gzipRatios) > 0 { - counters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) + httpCounters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) } - for key, value := range getRequestTimeMetrics(requestTimes) { - counters[key] = value + for _, metricName := range httpRequestMetrics { + httpCounters[metricName] = getTimeMetrics(metricName, requestTimes) } - simpleMetrics := c.convertSamplesToSimpleMetrics(counters) + for metricName := range connCounters { + connCounters[metricName] = getTimeMetrics(metricName, connectTimes) + } + + for metricName := range headerCounters { + headerCounters[metricName] = getTimeMetrics(metricName, headerTimes) + } + + c.group = "http" + simpleMetrics := c.convertSamplesToSimpleMetrics(httpCounters) + + c.group = "" + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(connCounters)...) + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(headerCounters)...) + log.Tracef("Access log metrics collected: %v", simpleMetrics) // reset the counters - counters = getDefaultCounters() - gzipRatios = []float64{} - requestLengths = []float64{} - requestTimes = []float64{} + httpCounters, connCounters, headerCounters = getDefaultCounters() + gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{} c.buf = append(c.buf, metrics.NewStatsEntity(c.baseDimensions.ToDimensions(), simpleMetrics)) @@ -368,43 +408,52 @@ func getGzipRatioMetricValue(gzipRatios []float64) float64 { return value } -func getRequestTimeMetrics(requestTimes []float64) map[string]float64 { - counters := make(map[string]float64) +func getTimeMetrics(metricName string, times []float64) float64 { + if len(times) == 0 { + return 0 + } + + metricType := metricName[strings.LastIndex(metricName, ".")+1:] - if len(requestTimes) > 0 { - // Calculate request time average - sort.Float64s(requestTimes) - requestTimesSum := 0.0 - for _, requestTime := range requestTimes { - requestTimesSum += requestTime + switch metricType { + case "time": + // Calculate average + sum := 0.0 + for _, t := range times { + sum += t } + return sum / float64(len(times)) - counters["request.time"] = requestTimesSum / float64(len(requestTimes)) + case "count": + return float64(len(times)) - // Calculate request time count - sort.Float64s(requestTimes) - counters["request.time.count"] = float64(len(requestTimes)) + case "max": + sort.Float64s(times) + return times[len(times)-1] - // Calculate request time max - sort.Float64s(requestTimes) - counters["request.time.max"] = requestTimes[len(requestTimes)-1] + case "median": + sort.Float64s(times) - // Calculate request time median - mNumber := len(requestTimes) / 2 - if len(requestTimes)%2 != 0 { - counters["request.time.median"] = requestTimes[mNumber] + mNumber := len(times) / 2 + if len(times)%2 != 0 { + return times[mNumber] } else { - counters["request.time.median"] = (requestTimes[mNumber-1] + requestTimes[mNumber]) / 2 + return (times[mNumber-1] + times[mNumber]) / 2 } - // Calculate request time 95 percentile - index := int(math.RoundToEven(float64(0.95)*float64(len(requestTimes)))) - 1 - counters["request.time.pctl95"] = requestTimes[index] + case "pctl95": + sort.Float64s(times) + + index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 + return times[index] } - return counters + log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) + + return 0 } +// convertLogFormat converts log format into a pattern that can be parsed by the tailer func convertLogFormat(logFormat string) string { newLogFormat := strings.ReplaceAll(logFormat, "$remote_addr", "%{IPORHOST:remote_addr}") newLogFormat = strings.ReplaceAll(newLogFormat, "$remote_user", "%{USERNAME:remote_user}") @@ -421,6 +470,8 @@ func convertLogFormat(logFormat string) string { newLogFormat = strings.ReplaceAll(newLogFormat, "$request_time", "%{DATA:request_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "\"$request\"", "\"%{DATA:request}\"") newLogFormat = strings.ReplaceAll(newLogFormat, "$request ", "%{DATA:request} ") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_connect_time", "%{DATA:upstream_connect_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_header_time", "%{DATA:upstream_header_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "[", "\\[") newLogFormat = strings.ReplaceAll(newLogFormat, "]", "\\]") return newLogFormat @@ -435,8 +486,8 @@ func isOtherMethod(method string) bool { method != "method.options" } -func getDefaultCounters() map[string]float64 { - return map[string]float64{ +func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64) { + httpCounters := map[string]float64{ "gzip.ratio": 0, "method.delete": 0, "method.get": 0, @@ -471,4 +522,22 @@ func getDefaultCounters() map[string]float64 { "v1_1": 0, "v2": 0, } + + upstreamConnectCounters := map[string]float64{ + "upstream.connect.time": 0, + "upstream.connect.time.count": 0, + "upstream.connect.time.max": 0, + "upstream.connect.time.median": 0, + "upstream.connect.time.pctl95": 0, + } + + upstreamHeaderCounters := map[string]float64{ + "upstream.header.time": 0, + "upstream.header.time.count": 0, + "upstream.header.time.max": 0, + "upstream.header.time.median": 0, + "upstream.header.time.pctl95": 0, + } + + return httpCounters, upstreamConnectCounters, upstreamHeaderCounters } diff --git a/src/core/metrics/sources/nginx_access_log_test.go b/src/core/metrics/sources/nginx_access_log_test.go index 4b42a3d44..dab5e819f 100644 --- a/src/core/metrics/sources/nginx_access_log_test.go +++ b/src/core/metrics/sources/nginx_access_log_test.go @@ -9,7 +9,6 @@ package sources import ( "context" - "io/ioutil" "os" "sort" "testing" @@ -19,18 +18,19 @@ import ( "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/config" "github.com/nginx/agent/v2/src/core/metrics" - testutils "github.com/nginx/agent/v2/test/utils" tutils "github.com/nginx/agent/v2/test/utils" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestAccessLogUpdate(t *testing.T) { - binary := testutils.NewMockNginxBinary() + binary := tutils.NewMockNginxBinary() binary.On("GetAccessLogs").Return(map[string]string{"/tmp/access.log": ""}).Once() binary.On("GetAccessLogs").Return(map[string]string{"/tmp/new_access.log": ""}).Once() - collectionDuration, _ := time.ParseDuration("300ms") - newCollectionDuration, _ := time.ParseDuration("500ms") + collectionDuration := time.Millisecond * 300 + newCollectionDuration := time.Millisecond * 500 nginxAccessLog := NewNginxAccessLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) assert.Equal(t, "", nginxAccessLog.baseDimensions.InstanceTags) @@ -54,10 +54,10 @@ func TestAccessLogUpdate(t *testing.T) { } func TestAccessLogStop(t *testing.T) { - binary := testutils.NewMockNginxBinary() + binary := tutils.NewMockNginxBinary() binary.On("GetAccessLogs").Return(map[string]string{"/tmp/access.log": ""}).Once() - collectionDuration, _ := time.ParseDuration("300ms") + collectionDuration := time.Millisecond * 300 nginxAccessLog := NewNginxAccessLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) _, ok := nginxAccessLog.logs["/tmp/access.log"] @@ -65,7 +65,7 @@ func TestAccessLogStop(t *testing.T) { nginxAccessLog.Stop() - assert.Equal(t, 0, len(nginxAccessLog.logs)) + assert.Len(t, nginxAccessLog.logs, 0) } func TestAccessLogStats(t *testing.T) { @@ -73,7 +73,6 @@ func TestAccessLogStats(t *testing.T) { name string logFormat string logLines []string - m chan *proto.StatsEntity expectedStats *proto.StatsEntity }{ { @@ -83,7 +82,6 @@ func TestAccessLogStats(t *testing.T) { "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\"\n", `127.0.0.1 - - [19/May/2022:09:30:39 +0000] "GET /user/register?ahref HTTP/1.1" 200 98 "-" "-" "-"`, }, - make(chan *proto.StatsEntity, 1), &proto.StatsEntity{ Simplemetrics: []*proto.SimpleMetric{ { @@ -218,29 +216,68 @@ func TestAccessLogStats(t *testing.T) { Name: "nginx.http.v2", Value: 0, }, + { + Name: "nginx.upstream.connect.time", + Value: 0, + }, + { + Name: "nginx.upstream.connect.time.count", + Value: 0, + }, + { + Name: "nginx.upstream.connect.time.max", + Value: 0, + }, + { + Name: "nginx.upstream.connect.time.median", + Value: 0, + }, + { + Name: "nginx.upstream.connect.time.pctl95", + Value: 0, + }, + { + Name: "nginx.upstream.header.time", + Value: 0, + }, + { + Name: "nginx.upstream.header.time.count", + Value: 0, + }, + { + Name: "nginx.upstream.header.time.max", + Value: 0, + }, + { + Name: "nginx.upstream.header.time.median", + Value: 0, + }, + { + Name: "nginx.upstream.header.time.pctl95", + Value: 0, + }, }, }, }, { "full_access_log_test", - `$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for" "$bytes_sent" "$request_length" "$request_time" "$gzip_ratio" "$server_protocol"`, + `$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for" "$bytes_sent" "$request_length" "$request_time" "$gzip_ratio" "$server_protocol" "$upstream_connect_time" "$upstream_header_time"`, []string{ - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"10\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"POST /nginx_status HTTP/1.1\" 201 98 \"-\" \"Go-http-client/1.1\" \"-\" \"250\" \"110\" \"0.300\" \"20\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 400 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 403 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"HEAD /nginx_status HTTP/1.1\" 404 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 499 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 500 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.0\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.0\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/2\" 503 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/2\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/0.9\" 504 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/0.9\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.1\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\"\n", - "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"10\" \"HTTP/1.1\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"POST /nginx_status HTTP/1.1\" 201 98 \"-\" \"Go-http-client/1.1\" \"-\" \"250\" \"110\" \"0.300\" \"20\" \"HTTP/1.1\" \"350\" \"730\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 400 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"DELETE /nginx_status HTTP/1.1\" 403 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"100\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"HEAD /nginx_status HTTP/1.1\" 404 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"505\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 499 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"350\" \"2000\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"PUT /nginx_status HTTP/1.1\" 500 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"2350\" \"250\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.0\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.0\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/2\" 503 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/2\" \"350\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/0.9\" 504 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/0.9\" \"350\" \"590\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"OPTIONS /nginx_status HTTP/1.1\" 502 98 \"-\" \"Go-http-client/1.1\" \"-\" \"200\" \"100\" \"0.200\" \"-\" \"HTTP/1.1\" \"900\" \"500\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"170\"\n", + "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"TRACE /nginx_status HTTP/1.1\" 200 98 \"-\" \"Go-http-client/1.1\" \"-\" \"150\" \"105\" \"0.100\" \"-\" \"HTTP/1.1\" \"350\" \"500\"\n", }, - make(chan *proto.StatsEntity, 1), &proto.StatsEntity{ Simplemetrics: []*proto.SimpleMetric{ { @@ -249,7 +286,7 @@ func TestAccessLogStats(t *testing.T) { }, { Name: "nginx.http.request.time", - Value: 0.1857142857142857, + Value: 0.18571428571428572, }, { Name: "nginx.http.request.time.count", @@ -375,29 +412,67 @@ func TestAccessLogStats(t *testing.T) { Name: "nginx.http.v2", Value: 1, }, + { + Name: "nginx.upstream.connect.time", + Value: 514.2857142857143, + }, + { + Name: "nginx.upstream.connect.time.count", + Value: 14, + }, + { + Name: "nginx.upstream.connect.time.max", + Value: 2350, + }, + { + Name: "nginx.upstream.connect.time.median", + Value: 350, + }, + { + Name: "nginx.upstream.connect.time.pctl95", + Value: 900, + }, + { + Name: "nginx.upstream.header.time", + Value: 588.9285714285714, + }, + { + Name: "nginx.upstream.header.time.count", + Value: 14, + }, + { + Name: "nginx.upstream.header.time.max", + Value: 2000, + }, + { + Name: "nginx.upstream.header.time.median", + Value: 500, + }, + { + Name: "nginx.upstream.header.time.pctl95", + Value: 730, + }, }, }, }, } binary := core.NewNginxBinary(tutils.NewMockEnvironment(), &config.Config{}) - collectionDuration, _ := time.ParseDuration("300ms") - sleepDuration, _ := time.ParseDuration("100ms") + collectionDuration := time.Millisecond * 300 + sleepDuration := time.Millisecond * 100 for _, test := range tests { t.Run(test.name, func(tt *testing.T) { - context := context.TODO() - accessLogFile, _ := ioutil.TempFile(os.TempDir(), "access.log") + accessLogFile, _ := os.CreateTemp(os.TempDir(), "access.log") nginxAccessLog := NewNginxAccessLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) - go nginxAccessLog.logStats(context, accessLogFile.Name(), test.logFormat) + go nginxAccessLog.logStats(context.TODO(), accessLogFile.Name(), test.logFormat) time.Sleep(sleepDuration) + for _, logLine := range test.logLines { _, err := accessLogFile.WriteString(logLine) - if err != nil { - tt.Fatalf("Error writing data to access log") - } + require.NoError(t, err, "Error writing data to access log") } time.Sleep(collectionDuration) diff --git a/src/core/metrics/sources/nginx_error_log.go b/src/core/metrics/sources/nginx_error_log.go index 6b1943956..b9889ed59 100644 --- a/src/core/metrics/sources/nginx_error_log.go +++ b/src/core/metrics/sources/nginx_error_log.go @@ -14,11 +14,11 @@ import ( "time" "github.com/nginx/agent/sdk/v2/proto" - log "github.com/sirupsen/logrus" - "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" "github.com/nginx/agent/v2/src/core/metrics/sources/tailer" + + log "github.com/sirupsen/logrus" ) const ( diff --git a/src/core/metrics/sources/nginx_error_log_test.go b/src/core/metrics/sources/nginx_error_log_test.go index 3209e4f51..8e5e4bdb9 100644 --- a/src/core/metrics/sources/nginx_error_log_test.go +++ b/src/core/metrics/sources/nginx_error_log_test.go @@ -9,7 +9,6 @@ package sources import ( "context" - "io/ioutil" "os" "sort" "testing" @@ -19,18 +18,19 @@ import ( "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/config" "github.com/nginx/agent/v2/src/core/metrics" - testutils "github.com/nginx/agent/v2/test/utils" tutils "github.com/nginx/agent/v2/test/utils" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestNginxErrorLogUpdate(t *testing.T) { - binary := testutils.NewMockNginxBinary() + binary := tutils.NewMockNginxBinary() binary.On("GetErrorLogs").Return(map[string]string{"/tmp/error.log": ""}).Once() binary.On("GetErrorLogs").Return(map[string]string{"/tmp/new_error.log": ""}).Once() - collectionDuration, _ := time.ParseDuration("300ms") - newCollectionDuration, _ := time.ParseDuration("500ms") + collectionDuration := time.Millisecond * 300 + newCollectionDuration := time.Millisecond * 500 nginxErrorLog := NewNginxErrorLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) assert.Equal(t, "", nginxErrorLog.baseDimensions.InstanceTags) @@ -54,10 +54,10 @@ func TestNginxErrorLogUpdate(t *testing.T) { } func TestNginxErrorLogStop(t *testing.T) { - binary := testutils.NewMockNginxBinary() + binary := tutils.NewMockNginxBinary() binary.On("GetErrorLogs").Return(map[string]string{"/tmp/error.log": ""}).Once() - collectionDuration, _ := time.ParseDuration("300ms") + collectionDuration := time.Millisecond * 300 nginxErrorLog := NewNginxErrorLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) _, ok := nginxErrorLog.logs["/tmp/error.log"] @@ -65,14 +65,13 @@ func TestNginxErrorLogStop(t *testing.T) { nginxErrorLog.Stop() - assert.Equal(t, 0, len(nginxErrorLog.logs)) + assert.Len(t, nginxErrorLog.logs, 0) } func TestErrorLogStats(t *testing.T) { tests := []struct { name string logLines []string - m chan *proto.StatsEntity expectedStats *proto.StatsEntity }{ { @@ -84,7 +83,6 @@ func TestErrorLogStats(t *testing.T) { `2022/05/24 13:18:37 [error] 21314#21314: *91 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /frontend1 HTTP/1.1", upstream: "http://127.0.0.1:9091/frontend1", host: "127.0.0.1:8081"`, `2022/05/24 13:18:37 [error] 21314#21314: client request body is buffered.`, }, - make(chan *proto.StatsEntity, 1), &proto.StatsEntity{ Simplemetrics: []*proto.SimpleMetric{ { @@ -109,23 +107,21 @@ func TestErrorLogStats(t *testing.T) { } binary := core.NewNginxBinary(tutils.NewMockEnvironment(), &config.Config{}) - collectionDuration, _ := time.ParseDuration("300ms") - sleepDuration, _ := time.ParseDuration("100ms") + collectionDuration := time.Millisecond * 300 + sleepDuration := time.Millisecond * 100 for _, test := range tests { t.Run(test.name, func(tt *testing.T) { - context := context.TODO() - errorLogFile, _ := ioutil.TempFile(os.TempDir(), "error.log") + errorLogFile, _ := os.CreateTemp(os.TempDir(), "error.log") nginxErrorLog := NewNginxErrorLog(&metrics.CommonDim{}, OSSNamespace, binary, OSSNginxType, collectionDuration) - go nginxErrorLog.logStats(context, errorLogFile.Name()) + go nginxErrorLog.logStats(context.TODO(), errorLogFile.Name()) time.Sleep(sleepDuration) + for _, logLine := range test.logLines { _, err := errorLogFile.WriteString(logLine) - if err != nil { - tt.Fatalf("Error writing data to error log") - } + require.NoError(t, err, "Error writing data to error log") } time.Sleep(collectionDuration) diff --git a/src/core/metrics/sources/nginx_oss.go b/src/core/metrics/sources/nginx_oss.go index a82176f9f..1773f302c 100644 --- a/src/core/metrics/sources/nginx_oss.go +++ b/src/core/metrics/sources/nginx_oss.go @@ -13,10 +13,10 @@ import ( "sync" "github.com/nginx/agent/sdk/v2/proto" + "github.com/nginx/agent/v2/src/core/metrics" + "github.com/nginxinc/nginx-prometheus-exporter/client" log "github.com/sirupsen/logrus" - - "github.com/nginx/agent/v2/src/core/metrics" ) type NginxOSS struct { diff --git a/src/core/metrics/sources/nginx_oss_test.go b/src/core/metrics/sources/nginx_oss_test.go index db2db35d1..aa636273c 100644 --- a/src/core/metrics/sources/nginx_oss_test.go +++ b/src/core/metrics/sources/nginx_oss_test.go @@ -15,10 +15,10 @@ import ( "testing" "github.com/nginx/agent/sdk/v2/proto" - "github.com/stretchr/testify/assert" - "github.com/nginx/agent/v2/src/core/config" "github.com/nginx/agent/v2/src/core/metrics" + + "github.com/stretchr/testify/assert" ) func TestNginxOSSUpdate(t *testing.T) { diff --git a/src/core/metrics/sources/tailer/tailer.go b/src/core/metrics/sources/tailer/tailer.go index 42a245b5d..dfc6aeb3a 100644 --- a/src/core/metrics/sources/tailer/tailer.go +++ b/src/core/metrics/sources/tailer/tailer.go @@ -13,9 +13,8 @@ import ( "github.com/mitchellh/mapstructure" "github.com/nxadm/tail" - "github.com/trivago/grok" - log "github.com/sirupsen/logrus" + "github.com/trivago/grok" ) var ( @@ -31,16 +30,18 @@ var ( // NginxAccessItem represents the decoded access log data type NginxAccessItem struct { - BodyBytesSent string `mapstructure:"body_bytes_sent"` - Status string `mapstructure:"status"` - RemoteAddress string `mapstructure:"remote_addr"` - HTTPUserAgent string `mapstructure:"http_user_agent"` - Request string `mapstructure:"request"` - BytesSent string `mapstructure:"bytes_sent"` - RequestLength string `mapstructure:"request_length"` - RequestTime string `mapstructure:"request_time"` - GzipRatio string `mapstructure:"gzip_ratio"` - ServerProtocol string `mapstructure:"server_protocol"` + BodyBytesSent string `mapstructure:"body_bytes_sent"` + Status string `mapstructure:"status"` + RemoteAddress string `mapstructure:"remote_addr"` + HTTPUserAgent string `mapstructure:"http_user_agent"` + Request string `mapstructure:"request"` + BytesSent string `mapstructure:"bytes_sent"` + RequestLength string `mapstructure:"request_length"` + RequestTime string `mapstructure:"request_time"` + GzipRatio string `mapstructure:"gzip_ratio"` + ServerProtocol string `mapstructure:"server_protocol"` + UpstreamConnectTime string `mapstructure:"upstream_connect_time"` + UpstreamHeaderTime string `mapstructure:"upstream_header_time"` } func NewNginxAccessItem(v map[string]string) (*NginxAccessItem, error) { diff --git a/src/core/metrics/sources/tailer/tailer_test.go b/src/core/metrics/sources/tailer/tailer_test.go index 70e24a3a7..6ddb5aecc 100644 --- a/src/core/metrics/sources/tailer/tailer_test.go +++ b/src/core/metrics/sources/tailer/tailer_test.go @@ -9,7 +9,6 @@ package tailer import ( "context" - "io/ioutil" "os" "testing" "time" @@ -62,16 +61,13 @@ func TestGrok(t *testing.T) { } func TestTailer(t *testing.T) { - errorLogFile, _ := ioutil.TempFile(os.TempDir(), "error.log") + errorLogFile, _ := os.CreateTemp(os.TempDir(), "error.log") logLine := `2015/07/15 05:56:30 [info] 28386#28386: *94160 client 10.196.158.41 closed keepalive connection` tailer, err := NewTailer(errorLogFile.Name()) require.Nil(t, err) - timeoutDuration, err := time.ParseDuration("300ms") - if err != nil { - t.Fatal("Error creating timeout duration") - } + timeoutDuration := time.Millisecond * 300 ctx, cancel := context.WithTimeout(context.Background(), timeoutDuration) defer cancel() @@ -79,11 +75,7 @@ func TestTailer(t *testing.T) { data := make(chan string, 100) go tailer.Tail(ctx, data) - sleepDuration, err := time.ParseDuration("100ms") - if err != nil { - t.Fatal("Error creating sleep duration") - } - time.Sleep(sleepDuration) + time.Sleep(time.Millisecond * 100) _, err = errorLogFile.WriteString(logLine) if err != nil { t.Fatalf("Error writing data to error log") @@ -109,29 +101,20 @@ T: } func TestPatternTailer(t *testing.T) { - accessLogFile, _ := ioutil.TempFile(os.TempDir(), "access.log") + accessLogFile, _ := os.CreateTemp(os.TempDir(), "access.log") logLine := "127.0.0.1 - - [19/May/2022:09:30:39 +0000] \"GET /nginx_status HTTP/1.1\" 500 98 \"-\" \"Go-http-client/1.1\" \"-\"\n" tailer, err := NewPatternTailer(accessLogFile.Name(), defaultPatterns) require.Nil(t, err) - timeoutDuration, err := time.ParseDuration("300ms") - if err != nil { - t.Fatal("Error creating timeout duration") - } - + timeoutDuration := time.Millisecond * 300 ctx, cancel := context.WithTimeout(context.Background(), timeoutDuration) defer cancel() data := make(chan map[string]string, 100) go tailer.Tail(ctx, data) - sleepDuration, err := time.ParseDuration("100ms") - if err != nil { - t.Fatal("Error creating sleep duration") - } - - time.Sleep(sleepDuration) + time.Sleep(time.Millisecond * 100) _, err = accessLogFile.WriteString(logLine) if err != nil { t.Fatalf("Error writing data to access log") diff --git a/test/integration/go.mod b/test/integration/go.mod index 316b3f910..05f7e56da 100644 --- a/test/integration/go.mod +++ b/test/integration/go.mod @@ -149,7 +149,6 @@ require ( ) replace ( - // https://github.com/cucumber/godog/releases/tag/v0.12.0 - this version breaks github.com/cucumber/godog => github.com/cucumber/godog v0.11.0 github.com/docker/cli => github.com/docker/cli v20.10.3-0.20221013132413-1d6c6e2367e2+incompatible // 22.06 master branch diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go index 46f942f95..af9393d90 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/metrics_util.go @@ -12,9 +12,10 @@ import ( "sync" "time" - "github.com/gogo/protobuf/types" "github.com/nginx/agent/sdk/v2/proto" "github.com/nginx/agent/v2/src/core/config" + + "github.com/gogo/protobuf/types" ) type Collector interface { @@ -129,6 +130,16 @@ func GetCalculationMap() map[string]string { "nginx.http.v1_0": "sum", "nginx.http.v1_1": "sum", "nginx.http.v2": "sum", + "nginx.upstream.connect.time": "avg", + "nginx.upstream.connect.time.count": "sum", + "nginx.upstream.connect.time.max": "avg", + "nginx.upstream.connect.time.median": "avg", + "nginx.upstream.connect.time.pctl95": "avg", + "nginx.upstream.header.time": "avg", + "nginx.upstream.header.time.count": "sum", + "nginx.upstream.header.time.max": "avg", + "nginx.upstream.header.time.median": "avg", + "nginx.upstream.header.time.pctl95": "avg", "nginx.http.conn.handled": "sum", "nginx.http.conn.reading": "avg", "nginx.http.conn.writing": "avg", diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/cpu.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/cpu.go index 391913c53..def4a1404 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/cpu.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/cpu.go @@ -15,6 +15,7 @@ import ( "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" cgroup "github.com/nginx/agent/v2/src/core/metrics/sources/cgroup" + "github.com/shirou/gopsutil/v3/cpu" log "github.com/sirupsen/logrus" ) diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go index 6617354cc..124a39415 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_access_log.go @@ -18,18 +18,18 @@ import ( "time" "github.com/nginx/agent/sdk/v2/proto" - log "github.com/sirupsen/logrus" - "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" "github.com/nginx/agent/v2/src/core/metrics/sources/tailer" + + log "github.com/sirupsen/logrus" ) const ( spaceDelim = " " ) -// This metrics source is used to tail the NGINX access logs to retrieve http metrics. +// This metrics source is used to tail the NGINX access logs to retrieve metrics. type NginxAccessLog struct { baseDimensions *metrics.CommonDim @@ -49,7 +49,7 @@ func NewNginxAccessLog( binary core.NginxBinary, nginxType string, collectionInterval time.Duration) *NginxAccessLog { - log.Trace("Creating NewNginxAccessLog") + log.Trace("Creating NginxAccessLog") nginxAccessLog := &NginxAccessLog{ baseDimensions, @@ -78,7 +78,6 @@ func NewNginxAccessLog( func (c *NginxAccessLog) Collect(ctx context.Context, wg *sync.WaitGroup, m chan<- *proto.StatsEntity) { defer wg.Done() - c.collectLogStats(ctx, m) } @@ -153,15 +152,22 @@ func (c *NginxAccessLog) collectLogStats(ctx context.Context, m chan<- *proto.St c.buf = []*proto.StatsEntity{} } +var httpRequestMetrics = []string{ + "request.time", + "request.time.count", + "request.time.max", + "request.time.median", + "request.time.pctl95", +} + func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string) { logPattern := convertLogFormat(logFormat) log.Debugf("Collecting from: %s using format: %s", logFile, logFormat) log.Debugf("Pattern used for tailing logs: %s", logPattern) - counters := getDefaultCounters() - gzipRatios := []float64{} - requestLengths := []float64{} - requestTimes := []float64{} + httpCounters, connCounters, headerCounters := getDefaultCounters() + gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes := []float64{}, []float64{}, []float64{}, []float64{}, []float64{} + mu := sync.Mutex{} t, err := tailer.NewPatternTailer(logFile, map[string]string{"DEFAULT": logPattern}) @@ -187,34 +193,34 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string mu.Lock() if v, err := strconv.Atoi(access.BodyBytesSent); err == nil { n := "request.body_bytes_sent" - counters[n] = float64(v) + counters[n] + httpCounters[n] = float64(v) + httpCounters[n] } else { - log.Debugf("Error getting body_bytes_sent value from access logs, %v", err) + log.Debugf("Error getting body_bytes_sent value from access logs: %v", err) } if v, err := strconv.Atoi(access.BytesSent); err == nil { n := "request.bytes_sent" - counters[n] = float64(v) + counters[n] + httpCounters[n] = float64(v) + httpCounters[n] } else { - log.Debugf("Error getting bytes_sent value from access logs, %v", err) + log.Debugf("Error getting bytes_sent value from access logs: %v", err) } if v, err := strconv.Atoi(access.GzipRatio); err == nil { gzipRatios = append(gzipRatios, float64(v)) } else { - log.Debugf("Error getting gzip_ratio value from access logs, %v", err) + log.Debugf("Error getting gzip_ratio value from access logs: %v", err) } if v, err := strconv.Atoi(access.RequestLength); err == nil { requestLengths = append(requestLengths, float64(v)) } else { - log.Debugf("Error getting request_length value from access logs, %v", err) + log.Debugf("Error getting request_length value from access logs: %v", err) } if v, err := strconv.ParseFloat(access.RequestTime, 64); err == nil { requestTimes = append(requestTimes, v) } else { - log.Debugf("Error getting request_time value from access logs, %v", err) + log.Debugf("Error getting request_time value from access logs: %v", err) } if access.Request != "" { @@ -223,24 +229,46 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string if isOtherMethod(n) { n = "method.others" } - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 if access.ServerProtocol == "" { if strings.Count(protocol, "/") == 1 { httpProtocolVersion := strings.Split(protocol, "/")[1] httpProtocolVersion = strings.ReplaceAll(httpProtocolVersion, ".", "_") n = fmt.Sprintf("v%s", httpProtocolVersion) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } } + for _, cTime := range strings.Split(access.UpstreamConnectTime, ", ") { + // nginx uses '-' to represent TCP connection failures + cTime = strings.ReplaceAll(cTime, "-", "0") + + if v, err := strconv.ParseFloat(cTime, 64); err == nil { + connectTimes = append(connectTimes, v) + } else { + log.Debugf("Error getting upstream_connect_time value from access logs, %v", err) + } + } + + for _, hTime := range strings.Split(access.UpstreamHeaderTime, ", ") { + // nginx uses '-' to represent TCP connection failures + hTime = strings.ReplaceAll(hTime, "-", "0") + + if v, err := strconv.ParseFloat(hTime, 64); err == nil { + headerTimes = append(headerTimes, v) + } else { + log.Debugf("Error getting upstream_header_time value from access logs: %v", err) + } + } + if access.ServerProtocol != "" { if strings.Count(access.ServerProtocol, "/") == 1 { httpProtocolVersion := strings.Split(access.ServerProtocol, "/")[1] httpProtocolVersion = strings.ReplaceAll(httpProtocolVersion, ".", "_") n := fmt.Sprintf("v%s", httpProtocolVersion) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } @@ -248,18 +276,18 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string if c.nginxType == OSSNginxType { if v, err := strconv.Atoi(access.Status); err == nil { n := fmt.Sprintf("status.%dxx", v/100) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 if v == 403 || v == 404 || v == 500 || v == 502 || v == 503 || v == 504 { n := fmt.Sprintf("status.%d", v) - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } if v == 499 { n := "status.discarded" - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } if v == 400 { n := "request.malformed" - counters[n] = counters[n] + 1 + httpCounters[n] = httpCounters[n] + 1 } } else { log.Debugf("Error getting status value from access logs, %v", err) @@ -270,29 +298,41 @@ func (c *NginxAccessLog) logStats(ctx context.Context, logFile, logFormat string case <-tick.C: c.baseDimensions.NginxType = c.nginxType c.baseDimensions.PublishedAPI = logFile - c.group = "http" mu.Lock() if len(requestLengths) > 0 { - counters["request.length"] = getRequestLengthMetricValue(requestLengths) + httpCounters["request.length"] = getRequestLengthMetricValue(requestLengths) } + if len(gzipRatios) > 0 { - counters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) + httpCounters["gzip.ratio"] = getGzipRatioMetricValue(gzipRatios) } - for key, value := range getRequestTimeMetrics(requestTimes) { - counters[key] = value + for _, metricName := range httpRequestMetrics { + httpCounters[metricName] = getTimeMetrics(metricName, requestTimes) } - simpleMetrics := c.convertSamplesToSimpleMetrics(counters) + for metricName := range connCounters { + connCounters[metricName] = getTimeMetrics(metricName, connectTimes) + } + + for metricName := range headerCounters { + headerCounters[metricName] = getTimeMetrics(metricName, headerTimes) + } + + c.group = "http" + simpleMetrics := c.convertSamplesToSimpleMetrics(httpCounters) + + c.group = "" + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(connCounters)...) + simpleMetrics = append(simpleMetrics, c.convertSamplesToSimpleMetrics(headerCounters)...) + log.Tracef("Access log metrics collected: %v", simpleMetrics) // reset the counters - counters = getDefaultCounters() - gzipRatios = []float64{} - requestLengths = []float64{} - requestTimes = []float64{} + httpCounters, connCounters, headerCounters = getDefaultCounters() + gzipRatios, requestLengths, requestTimes, connectTimes, headerTimes = []float64{}, []float64{}, []float64{}, []float64{}, []float64{} c.buf = append(c.buf, metrics.NewStatsEntity(c.baseDimensions.ToDimensions(), simpleMetrics)) @@ -368,43 +408,52 @@ func getGzipRatioMetricValue(gzipRatios []float64) float64 { return value } -func getRequestTimeMetrics(requestTimes []float64) map[string]float64 { - counters := make(map[string]float64) +func getTimeMetrics(metricName string, times []float64) float64 { + if len(times) == 0 { + return 0 + } + + metricType := metricName[strings.LastIndex(metricName, ".")+1:] - if len(requestTimes) > 0 { - // Calculate request time average - sort.Float64s(requestTimes) - requestTimesSum := 0.0 - for _, requestTime := range requestTimes { - requestTimesSum += requestTime + switch metricType { + case "time": + // Calculate average + sum := 0.0 + for _, t := range times { + sum += t } + return sum / float64(len(times)) - counters["request.time"] = requestTimesSum / float64(len(requestTimes)) + case "count": + return float64(len(times)) - // Calculate request time count - sort.Float64s(requestTimes) - counters["request.time.count"] = float64(len(requestTimes)) + case "max": + sort.Float64s(times) + return times[len(times)-1] - // Calculate request time max - sort.Float64s(requestTimes) - counters["request.time.max"] = requestTimes[len(requestTimes)-1] + case "median": + sort.Float64s(times) - // Calculate request time median - mNumber := len(requestTimes) / 2 - if len(requestTimes)%2 != 0 { - counters["request.time.median"] = requestTimes[mNumber] + mNumber := len(times) / 2 + if len(times)%2 != 0 { + return times[mNumber] } else { - counters["request.time.median"] = (requestTimes[mNumber-1] + requestTimes[mNumber]) / 2 + return (times[mNumber-1] + times[mNumber]) / 2 } - // Calculate request time 95 percentile - index := int(math.RoundToEven(float64(0.95)*float64(len(requestTimes)))) - 1 - counters["request.time.pctl95"] = requestTimes[index] + case "pctl95": + sort.Float64s(times) + + index := int(math.RoundToEven(float64(0.95)*float64(len(times)))) - 1 + return times[index] } - return counters + log.Debugf("Could not get time metrics for %s: invalid metric type", metricName) + + return 0 } +// convertLogFormat converts log format into a pattern that can be parsed by the tailer func convertLogFormat(logFormat string) string { newLogFormat := strings.ReplaceAll(logFormat, "$remote_addr", "%{IPORHOST:remote_addr}") newLogFormat = strings.ReplaceAll(newLogFormat, "$remote_user", "%{USERNAME:remote_user}") @@ -421,6 +470,8 @@ func convertLogFormat(logFormat string) string { newLogFormat = strings.ReplaceAll(newLogFormat, "$request_time", "%{DATA:request_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "\"$request\"", "\"%{DATA:request}\"") newLogFormat = strings.ReplaceAll(newLogFormat, "$request ", "%{DATA:request} ") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_connect_time", "%{DATA:upstream_connect_time}") + newLogFormat = strings.ReplaceAll(newLogFormat, "$upstream_header_time", "%{DATA:upstream_header_time}") newLogFormat = strings.ReplaceAll(newLogFormat, "[", "\\[") newLogFormat = strings.ReplaceAll(newLogFormat, "]", "\\]") return newLogFormat @@ -435,8 +486,8 @@ func isOtherMethod(method string) bool { method != "method.options" } -func getDefaultCounters() map[string]float64 { - return map[string]float64{ +func getDefaultCounters() (map[string]float64, map[string]float64, map[string]float64) { + httpCounters := map[string]float64{ "gzip.ratio": 0, "method.delete": 0, "method.get": 0, @@ -471,4 +522,22 @@ func getDefaultCounters() map[string]float64 { "v1_1": 0, "v2": 0, } + + upstreamConnectCounters := map[string]float64{ + "upstream.connect.time": 0, + "upstream.connect.time.count": 0, + "upstream.connect.time.max": 0, + "upstream.connect.time.median": 0, + "upstream.connect.time.pctl95": 0, + } + + upstreamHeaderCounters := map[string]float64{ + "upstream.header.time": 0, + "upstream.header.time.count": 0, + "upstream.header.time.max": 0, + "upstream.header.time.median": 0, + "upstream.header.time.pctl95": 0, + } + + return httpCounters, upstreamConnectCounters, upstreamHeaderCounters } diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_error_log.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_error_log.go index 6b1943956..b9889ed59 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_error_log.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_error_log.go @@ -14,11 +14,11 @@ import ( "time" "github.com/nginx/agent/sdk/v2/proto" - log "github.com/sirupsen/logrus" - "github.com/nginx/agent/v2/src/core" "github.com/nginx/agent/v2/src/core/metrics" "github.com/nginx/agent/v2/src/core/metrics/sources/tailer" + + log "github.com/sirupsen/logrus" ) const ( diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_oss.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_oss.go index a82176f9f..1773f302c 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_oss.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/nginx_oss.go @@ -13,10 +13,10 @@ import ( "sync" "github.com/nginx/agent/sdk/v2/proto" + "github.com/nginx/agent/v2/src/core/metrics" + "github.com/nginxinc/nginx-prometheus-exporter/client" log "github.com/sirupsen/logrus" - - "github.com/nginx/agent/v2/src/core/metrics" ) type NginxOSS struct { diff --git a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go index 42a245b5d..dfc6aeb3a 100644 --- a/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go +++ b/test/performance/vendor/github.com/nginx/agent/v2/src/core/metrics/sources/tailer/tailer.go @@ -13,9 +13,8 @@ import ( "github.com/mitchellh/mapstructure" "github.com/nxadm/tail" - "github.com/trivago/grok" - log "github.com/sirupsen/logrus" + "github.com/trivago/grok" ) var ( @@ -31,16 +30,18 @@ var ( // NginxAccessItem represents the decoded access log data type NginxAccessItem struct { - BodyBytesSent string `mapstructure:"body_bytes_sent"` - Status string `mapstructure:"status"` - RemoteAddress string `mapstructure:"remote_addr"` - HTTPUserAgent string `mapstructure:"http_user_agent"` - Request string `mapstructure:"request"` - BytesSent string `mapstructure:"bytes_sent"` - RequestLength string `mapstructure:"request_length"` - RequestTime string `mapstructure:"request_time"` - GzipRatio string `mapstructure:"gzip_ratio"` - ServerProtocol string `mapstructure:"server_protocol"` + BodyBytesSent string `mapstructure:"body_bytes_sent"` + Status string `mapstructure:"status"` + RemoteAddress string `mapstructure:"remote_addr"` + HTTPUserAgent string `mapstructure:"http_user_agent"` + Request string `mapstructure:"request"` + BytesSent string `mapstructure:"bytes_sent"` + RequestLength string `mapstructure:"request_length"` + RequestTime string `mapstructure:"request_time"` + GzipRatio string `mapstructure:"gzip_ratio"` + ServerProtocol string `mapstructure:"server_protocol"` + UpstreamConnectTime string `mapstructure:"upstream_connect_time"` + UpstreamHeaderTime string `mapstructure:"upstream_header_time"` } func NewNginxAccessItem(v map[string]string) (*NginxAccessItem, error) {