Merge pull request #125 from postfinance/feat/v1.13

metrics and logging refactor !

Author: clementnuss

.github/actions/check-deployment/action.yml

@@ -22,7 +22,7 @@ runs:
     run: |
       echo "Check for unexpected log lines"
       test $(kubectl -n ${{ inputs.namespace }} logs -l app.kubernetes.io/name=kubenurse \
-        | grep -v "I'm ready to help you" \
+        | grep -v "kubenurse just started" \
         | wc -l) -eq 0 \
   - shell: bash
     run: |
@@ -36,14 +36,14 @@ runs:
       curl -k -s --resolve \
         ${{ inputs.svc-domain }}:443:127.0.0.1 \
         https://${{ inputs.svc-domain }}:443/metrics \
-        | grep "kubenurse_request_" > /dev/null
+        | grep "kubenurse_httpclient_request_" > /dev/null
   - shell: bash
     run: |
       echo "Check that metrics contain neighbours"
       curl -k -s --resolve \
         ${{ inputs.svc-domain }}:443:127.0.0.1 \
         https://${{ inputs.svc-domain }}:443/metrics \
-        | grep "kubenurse_request_" | grep 'type="path_' > /dev/null
+        | grep "kubenurse_httpclient_request_" | grep 'type="path_' > /dev/null
   - shell: bash
     run: |
       echo "Check that metrics contain no errors"

CHANGELOG.md

@@ -1,3 +1,30 @@
+## [1.13.0] - 2024-04-12
+
+**Full Changelog**: https://github.com/postfinance/kubenurse/compare/v1.12.3...v1.13.0
+
+### 🚀 Features
+
+- [**breaking**] Use slog and add event type to error counter - ([e9d51a2](https://github.com/postfinance/kubenurse/commit/e9d51a2f781eaa2cb7e415fd175d158fdd681bb3))
+
+### 🐛 Bug Fixes
+
+- *(ci)* Change kubenurse startup string in test condition - ([bd91d7d](https://github.com/postfinance/kubenurse/commit/bd91d7da68b3408d70dfe846562557396b4522c4))
+- *(ci)* Update metric name for sanity check - ([c3e7287](https://github.com/postfinance/kubenurse/commit/c3e72874e509cff3fa72381d8aa882878ef32385))
+
+### 🚜 Refactor
+
+- [**breaking**] Remove kubenurse_request_duration histogram - ([3061b64](https://github.com/postfinance/kubenurse/commit/3061b6490d26e39bf096d050e54e15f7d43c0f8e))
+
+### 📚 Documentation
+
+- *(drawings)* Add excalidraw file - ([852ab85](https://github.com/postfinance/kubenurse/commit/852ab85fc2ec00804a290730b5276fb9689116f4))
+- *(readme.md)* Format metrics as a table - ([6a35209](https://github.com/postfinance/kubenurse/commit/6a3520955e2e91e3cccb203c528e23cd2032e127))
+
+### Build
+
+- *(artifacthub)* Add validation file - ([e2bf079](https://github.com/postfinance/kubenurse/commit/e2bf079504223a3293ed1be73d061bed49e00e02))
+
+
 ## [1.12.1] - 2024-04-05
 
 **Full Changelog**: https://github.com/postfinance/kubenurse/compare/v1.12.0...1.12.1

README.md

@@ -47,7 +47,7 @@ The following command can be used to install kubenurse with Helm: `helm upgrade
 #### Configuration settings
 
 | Setting                            | Description                                                                                                          | Default                            |
-|------------------------------------|----------------------------------------------------------------------------------------------------------------------|------------------------------------|
+| ---------------------------------- | -------------------------------------------------------------------------------------------------------------------- | ---------------------------------- |
 | daemonset.image.repository         | The repository name                                                                                                  | `postfinance/kubenurse`            |
 | daemonset.image.tag                | The tag/ version of the image                                                                                        | `v1.4.0`                           |
 | daemonset.podLabels                | Additional labels to be added to the pods of the daemonset                                                           | `[]`                               |
@@ -74,7 +74,7 @@ The following command can be used to install kubenurse with Helm: `helm upgrade
 | allow_unschedulable                | Sets `KUBENURSE_ALLOW_UNSCHEDULABLE` environment variable                                                            | `false`                            |
 | neighbour_filter                   | Sets `KUBENURSE_NEIGHBOUR_FILTER` environment variable                                                               | `app.kubernetes.io/name=kubenurse` |
 | neighbour_limit                    | Sets `KUBENURSE_NEIGHBOUR_LIMIT` environment variable                                                                | `10`                               |
-| histogram_buckets                  | Sets `KUBENURSE_HISTOGRAM_BUCKETS` environment variable                                                              |                                  |
+| histogram_buckets                  | Sets `KUBENURSE_HISTOGRAM_BUCKETS` environment variable                                                              |                                    |
 | extra_ca                           | Sets `KUBENURSE_EXTRA_CA` environment variable                                                                       |                                    |
 | check_api_server_direct            | Sets `KUBENURSE_CHECK_API_SERVER_DIRECT` environment variable                                                        | `true`                             |
 | check_api_server_dns               | Sets `KUBENURSE_CHECK_API_SERVER_DNS` environment variable                                                           | `true`                             |
@@ -298,13 +298,21 @@ All performed checks expose metrics which can be used to monitor/alert:
 
 At `/metrics` you will find the following metrics:
 
-- `kubenurse_errors_total`: Kubenurse error counter partitioned by error type
-- `kubenurse_request_duration`: a histogram for Kubenurse request duration partitioned by error type
-- `kubenurse_httpclient_request_duration_seconds`:  a latency histogram of request latencies from the kubenurse http client.
-- `kubenurse_httpclient_trace_requests_total`: a latency histogram for the http
-  client _trace_ metric instrumentation, with detailed statistics for e.g.
-  `dns_start`, `got_conn` events, and more. the details can be seen in the
-  [`httptrace.go`](https://github.com/postfinance/kubenurse/blob/52767fbb280b65c06ac926dac49dd874e9ec4aee/internal/servicecheck/httptrace.go#L73)
-  file
-- `kubenurse_neighbourhood_incoming_checks`: a gauge which reports how many
-  unique neighbours have queried the current pod in the last minute
+| metric name                                           | labels               | description                                                                                                                  |
+| ----------------------------------------------------- | -------------------- | ---------------------------------------------------------------------------------------------------------------------------- |
+| ~~`kubenurse request duration`~~                      | `type`               | (deprecated since v1.13.0) latency histogram for request duration, replaced with the metric below.                           |
+| `kubenurse httpclient request duration seconds`       | `type`               | latency histogram for request duration, partitioned by request type                                                          |
+| `kubenurse httpclient trace request duration seconds` | `type, event`        | latency histogram for httpclient _trace_ metric instrumentation, partitioned by request type and httptrace connection events |
+| `kubenurse httpclient requests total`                 | `type, code, method` | counter for the total number of http requests, partitioned by HTTP code, method, and request type                            |
+| `kubenurse errors total`                              | `type, event`        | error counter, partitioned by httptrace event and request type                                                               |
+| `kubenurse neighbourhood incoming checks`             | n\a                  | gauge which reports how many unique neighbours have queried the current pod in the last minute                               |
+
+For metrics partitioned with a `type` label, it is possible to precisely know
+which request type increased an error counter, or to compare the latencies of
+multiple request types, for example compare how your service and ingress
+latencies differ.
+
+Some `event` labels include `dns_start`, `got_conn`, `tls_handshake_done`, and
+more. the details can be  seen in the
+[`httptrace.go`](https://github.com/postfinance/kubenurse/blob/v1.13.0/internal/servicecheck/httptrace.go#L91)
+file.

internal/kubenurse/server.go

@@ -4,7 +4,7 @@ package kubenurse
 import (
 	"context"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
 	"os"
 	"strconv"
@@ -119,10 +119,11 @@ func New(ctx context.Context, c client.Client) (*Server, error) { //nolint:funle
 
 	if bucketsString := os.Getenv("KUBENURSE_HISTOGRAM_BUCKETS"); bucketsString != "" {
 		for _, bucketStr := range strings.Split(bucketsString, ",") {
-			bucket, e := strconv.ParseFloat(bucketStr, 64)
+			bucket, err := strconv.ParseFloat(bucketStr, 64)
 
-			if e != nil {
-				log.Fatalf("couldn't parse one of the custom histogram buckets. error:\n%v", e)
+			if err != nil {
+				slog.Error("couldn't parse one of the custom histogram buckets", "bucket", bucket, "err", err)
+				os.Exit(1)
 			}
 
 			histogramBuckets = append(histogramBuckets, bucket)
@@ -243,6 +244,8 @@ func (s *Server) Run() error {
 		}()
 	}
 
+	slog.Info("kubenurse just started")
+
 	wg.Wait()
 	close(errc)
 

internal/servicecheck/httptrace.go

@@ -3,7 +3,7 @@ package servicecheck
 import (
 	"context"
 	"crypto/tls"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/http/httptrace"
 	"time"
@@ -24,7 +24,9 @@ func (rt RoundTripperFunc) RoundTrip(r *http.Request) (*http.Response, error) {
 
 // This collects traces and logs errors. As promhttp.InstrumentRoundTripperTrace doesn't process
 // errors, this is custom made and inspired by prometheus/client_golang's promhttp
-func withHttptrace(registry *prometheus.Registry, next http.RoundTripper, durationHistogram []float64) http.RoundTripper {
+//
+//nolint:funlen // needed to pack all histograms and use them directly in the httptrace wrapper
+func withHttptrace(registry *prometheus.Registry, next http.RoundTripper, durHist []float64) http.RoundTripper {
 	httpclientReqTotal := prometheus.NewCounterVec(
 		prometheus.CounterOpts{
 			Namespace: MetricsNamespace,
@@ -39,7 +41,7 @@ func withHttptrace(registry *prometheus.Registry, next http.RoundTripper, durati
 			Namespace: MetricsNamespace,
 			Name:      "httpclient_request_duration_seconds",
 			Help:      "A latency histogram of request latencies from the kubenurse http client.",
-			Buckets:   durationHistogram,
+			Buckets:   durHist,
 		},
 		[]string{"type"},
 	)
@@ -49,20 +51,31 @@ func withHttptrace(registry *prometheus.Registry, next http.RoundTripper, durati
 			Namespace: MetricsNamespace,
 			Name:      "httpclient_trace_request_duration_seconds",
 			Help:      "Latency histogram for requests from the kubenurse http client. Time in seconds since the start of the http request.",
-			Buckets:   durationHistogram,
+			Buckets:   durHist,
 		},
 		[]string{"event", "type"},
 	)
 
-	registry.MustRegister(httpclientReqTotal, httpclientReqDuration, httpclientTraceReqDuration)
+	errorCounter := prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: MetricsNamespace,
+			Name:      "errors_total",
+			Help:      "Kubenurse error counter partitioned by error type",
+		},
+		[]string{"event", "type"},
+	)
+
+	registry.MustRegister(httpclientReqTotal, httpclientReqDuration, httpclientTraceReqDuration, errorCounter)
 
 	collectMetric := func(traceEventType string, start time.Time, r *http.Request, err error) {
 		td := time.Since(start).Seconds()
 		kubenurseTypeLabel := r.Context().Value(kubenurseTypeKey{}).(string)
 
-		// If we got an error inside a trace, log it and do not collect metrics
+		// If we get an error inside a trace, log it
 		if err != nil {
-			log.Printf("httptrace: failed %s for %s with %v", traceEventType, kubenurseTypeLabel, err)
+			errorCounter.WithLabelValues(traceEventType, kubenurseTypeLabel).Inc()
+			slog.Error("request failure in httptrace", "event_type", traceEventType, "request_type", kubenurseTypeLabel, "err", err)
+
 			return
 		}
 
@@ -94,8 +107,8 @@ func withHttptrace(registry *prometheus.Registry, next http.RoundTripper, durati
 			TLSHandshakeStart: func() {
 				collectMetric("tls_handshake_start", start, r, nil)
 			},
-			TLSHandshakeDone: func(_ tls.ConnectionState, _ error) {
-				collectMetric("tls_handshake_done", start, r, nil)
+			TLSHandshakeDone: func(_ tls.ConnectionState, err error) {
+				collectMetric("tls_handshake_done", start, r, err)
 			},
 			WroteRequest: func(info httptrace.WroteRequestInfo) {
 				collectMetric("wrote_request", start, r, info.Err)

internal/servicecheck/neighbours.go

@@ -103,7 +103,7 @@ func (c *Checker) checkNeighbours(nh []*Neighbour) {
 			return c.doRequest(ctx, "http://"+neighbour.PodIP+":8080/alwayshappy", true)
 		}
 
-		_, _ = c.measure(check, "path_"+neighbour.NodeName)
+		c.measure(check, "path_"+neighbour.NodeName)
 	}
 }
 

internal/servicecheck/servicecheck.go

@@ -5,7 +5,7 @@ import (
 	"context"
 	"crypto/tls"
 	"fmt"
-	"log"
+	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -26,31 +26,11 @@ const (
 // results. Other parameters of the Checker struct need to be configured separately.
 func New(_ context.Context, cl client.Client, promRegistry *prometheus.Registry,
 	allowUnschedulable bool, cacheTTL time.Duration, durationHistogramBuckets []float64) (*Checker, error) {
-	errorCounter := prometheus.NewCounterVec(
-		prometheus.CounterOpts{
-			Namespace: MetricsNamespace,
-			Name:      "errors_total",
-			Help:      "Kubenurse error counter partitioned by error type",
-		},
-		[]string{"type"},
-	)
-
-	durationHistogram := prometheus.NewHistogramVec(
-		prometheus.HistogramOpts{
-			Namespace: MetricsNamespace,
-			Name:      "request_duration",
-			Help:      "Kubenurse request duration partitioned by target path",
-			Buckets:   durationHistogramBuckets,
-		},
-		[]string{"type"},
-	)
-
-	promRegistry.MustRegister(errorCounter, durationHistogram)
-
 	// setup http transport
 	tlsConfig, err := generateTLSConfig(os.Getenv("KUBENURSE_EXTRA_CA"))
 	if err != nil {
-		log.Printf("cannot generate tlsConfig with KUBENURSE_EXTRA_CA: %s", err)
+		slog.Error("cannot generate tlsConfig with provided KUBENURSE_EXTRA_CA. Continuing with default tlsConfig",
+			"KUBENURSE_EXTRA_CA", os.Getenv("KUBENURSE_EXTRA_CA"), "err", err)
 
 		tlsConfig = &tls.Config{MinVersion: tls.VersionTLS12}
 	}
@@ -82,40 +62,26 @@ func New(_ context.Context, cl client.Client, promRegistry *prometheus.Registry,
 		client:             cl,
 		httpClient:         httpClient,
 		cacheTTL:           cacheTTL,
-		errorCounter:       errorCounter,
-		durationHistogram:  durationHistogram,
 		stop:               make(chan struct{}),
 	}, nil
 }
 
 // Run runs all servicechecks and returns the result togeter with a boolean which indicates success. The cache
 // is respected.
-func (c *Checker) Run() (Result, bool) {
-	var (
-		haserr bool
-		err    error
-	)
-
+func (c *Checker) Run() {
 	// Run Checks
 	res := Result{}
 
-	res.APIServerDirect, err = c.measure(c.APIServerDirect, "api_server_direct")
-	haserr = haserr || (err != nil)
-
-	res.APIServerDNS, err = c.measure(c.APIServerDNS, "api_server_dns")
-	haserr = haserr || (err != nil)
-
-	res.MeIngress, err = c.measure(c.MeIngress, "me_ingress")
-	haserr = haserr || (err != nil)
-
-	res.MeService, err = c.measure(c.MeService, "me_service")
-	haserr = haserr || (err != nil)
+	res.APIServerDirect = c.measure(c.APIServerDirect, "api_server_direct")
+	res.APIServerDNS = c.measure(c.APIServerDNS, "api_server_dns")
+	res.MeIngress = c.measure(c.MeIngress, "me_ingress")
+	res.MeService = c.measure(c.MeService, "me_service")
 
 	if c.SkipCheckNeighbourhood {
 		res.NeighbourhoodState = skippedStr
 	} else {
+		var err error
 		res.Neighbourhood, err = c.GetNeighbours(context.Background(), c.KubenurseNamespace, c.NeighbourFilter)
-		haserr = haserr || (err != nil)
 
 		// Neighbourhood special error treating
 		if err != nil {
@@ -130,8 +96,6 @@ func (c *Checker) Run() (Result, bool) {
 
 	// Cache result (used for /alive handler)
 	c.LastCheckResult = &res
-
-	return res, haserr
 }
 
 // RunScheduled runs the checks in the specified interval which can be used to keep the metrics up-to-date. This
@@ -196,23 +160,13 @@ func (c *Checker) MeService(ctx context.Context) (string, error) {
 }
 
 // measure implements metric collections for the check
-func (c *Checker) measure(check Check, label string) (string, error) {
-	start := time.Now()
-
+func (c *Checker) measure(check Check, requestType string) string {
 	// Add our label (check type) to the context so our http tracer can annotate
 	// metrics and errors based with the label
-	ctx := context.WithValue(context.Background(), kubenurseTypeKey{}, label)
+	ctx := context.WithValue(context.Background(), kubenurseTypeKey{}, requestType)
 
 	// Execute check
-	res, err := check(ctx)
-
-	// Process metrics
-	c.durationHistogram.WithLabelValues(label).Observe(time.Since(start).Seconds())
-
-	if err != nil {
-		log.Printf("failed request for %s with %v", label, err)
-		c.errorCounter.WithLabelValues(label).Inc()
-	}
+	res, _ := check(ctx) // this error is ignored as it is already logged in httptrace
 
-	return res, err
+	return res
 }

internal/servicecheck/servicecheck_test.go

@@ -42,9 +42,9 @@ func TestCombined(t *testing.T) {
 
 	t.Run("run", func(t *testing.T) {
 		r := require.New(t)
-		result, hadError := checker.Run()
-		r.True(hadError)
-		r.Len(result.Neighbourhood, 1)
+		checker.Run()
+
+		r.Len(checker.LastCheckResult.Neighbourhood, 1)
 	})
 
 	t.Run("scheduled", func(t *testing.T) {

internal/servicecheck/types.go

@@ -5,7 +5,6 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/prometheus/client_golang/prometheus"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 )
 
@@ -39,10 +38,6 @@ type Checker struct {
 	// Controller runtime cached client
 	client client.Client
 
-	// metrics
-	errorCounter      *prometheus.CounterVec
-	durationHistogram *prometheus.HistogramVec
-
 	// Http Client for https requests
 	httpClient *http.Client