feat: added kyverno_admission_review_latency_milliseconds metric

Signed-off-by: Yashvardhan Kukreja <yash.kukreja.98@gmail.com>

pkg/metrics/admissionreviewlatency/admissionReviewLatency.go

@@ -0,0 +1,68 @@
+package admissionreviewlatency
+
+import (
+	"fmt"
+	kyverno "github.com/kyverno/kyverno/pkg/api/kyverno/v1"
+	"github.com/kyverno/kyverno/pkg/engine/response"
+	"github.com/kyverno/kyverno/pkg/metrics"
+	prom "github.com/prometheus/client_golang/prometheus"
+)
+
+func (pm PromMetrics) registerAdmissionReviewLatencyMetric(
+	clusterPoliciesCount, namespacedPoliciesCount int,
+	validateRulesCount, mutateRulesCount, generateRulesCount int,
+	resourceName, resourceKind, resourceNamespace string,
+	resourceRequestOperation metrics.ResourceRequestOperation,
+	admissionRequestLatency float64,
+) error {
+	pm.AdmissionReviewLatency.With(prom.Labels{
+		"cluster_policies_count":     fmt.Sprintf("%d", clusterPoliciesCount),
+		"namespaced_policies_count":  fmt.Sprintf("%d", namespacedPoliciesCount),
+		"validate_rules_count":       fmt.Sprintf("%d", validateRulesCount),
+		"mutate_rules_count":         fmt.Sprintf("%d", mutateRulesCount),
+		"generate_rules_count":       fmt.Sprintf("%d", generateRulesCount),
+		"resource_name":              resourceName,
+		"resource_kind":              resourceKind,
+		"resource_namespace":         resourceNamespace,
+		"resource_request_operation": string(resourceRequestOperation),
+	}).Set(admissionRequestLatency)
+	return nil
+}
+
+func (pm PromMetrics) ProcessEngineResponses(engineResponses []*response.EngineResponse, triggeredPolicies []kyverno.ClusterPolicy, admissionReviewLatencyDuration int64, resourceRequestOperation metrics.ResourceRequestOperation) error {
+	if len(engineResponses) == 0 {
+		return nil
+	}
+	resourceName, resourceNamespace, resourceKind := engineResponses[0].PolicyResponse.Resource.Name, engineResponses[0].PolicyResponse.Resource.Namespace, engineResponses[0].PolicyResponse.Resource.Kind
+	clusterPoliciesCount, namespacedPoliciesCount, totalValidateRulesCount, totalMutateRulesCount, totalGenerateRulesCount := 0, 0, 0, 0, 0
+	for i, e := range engineResponses {
+		validateRulesCount, mutateRulesCount, generateRulesCount := 0, 0, 0
+		for _, rule := range e.PolicyResponse.Rules {
+			switch rule.Type {
+			case "Validation":
+				validateRulesCount++
+			case "Mutation":
+				mutateRulesCount++
+			case "Generation":
+				generateRulesCount++
+			}
+		}
+		// no rules triggered
+		if validateRulesCount+mutateRulesCount+generateRulesCount == 0 {
+			continue
+		}
+		if triggeredPolicies[i].Namespace == "" {
+			clusterPoliciesCount++
+		} else {
+			namespacedPoliciesCount++
+		}
+		totalValidateRulesCount += validateRulesCount
+		totalMutateRulesCount += mutateRulesCount
+		totalGenerateRulesCount += generateRulesCount
+	}
+	if totalValidateRulesCount+totalMutateRulesCount+totalGenerateRulesCount == 0 {
+		return nil
+	}
+	admissionReviewLatencyDurationInMs := float64(admissionReviewLatencyDuration) / float64(1000*1000)
+	return pm.registerAdmissionReviewLatencyMetric(clusterPoliciesCount, namespacedPoliciesCount, totalValidateRulesCount, totalMutateRulesCount, totalGenerateRulesCount, resourceName, resourceKind, resourceNamespace, resourceRequestOperation, admissionReviewLatencyDurationInMs)
+}

pkg/metrics/admissionreviewlatency/parsers.go

@@ -0,0 +1,25 @@
+package admissionreviewlatency
+
+import (
+	"fmt"
+	"github.com/kyverno/kyverno/pkg/metrics"
+)
+
+func ParsePromMetrics(pm metrics.PromMetrics) PromMetrics {
+	return PromMetrics(pm)
+}
+
+func ParseResourceRequestOperation(requestOperationStr string) (metrics.ResourceRequestOperation, error) {
+	switch requestOperationStr {
+	case "CREATE":
+		return metrics.ResourceCreated, nil
+	case "UPDATE":
+		return metrics.ResourceUpdated, nil
+	case "DELETE":
+		return metrics.ResourceDeleted, nil
+	case "CONNECT":
+		return metrics.ResourceConnected, nil
+	default:
+		return "", fmt.Errorf("Unknown request operation made by resource: %s. Allowed requests: 'CREATE', 'UPDATE', 'DELETE', 'CONNECT'", requestOperationStr)
+	}
+}

pkg/metrics/admissionreviewlatency/types.go

@@ -0,0 +1,7 @@
+package admissionreviewlatency
+
+import (
+	"github.com/kyverno/kyverno/pkg/metrics"
+)
+
+type PromMetrics metrics.PromMetrics

pkg/metrics/metrics.go

@@ -79,7 +79,7 @@ func NewPromConfig() *PromConfig {
 	}
 	admissionReviewLatencyMetric := prom.NewGaugeVec(
 		prom.GaugeOpts{
-			Name: "kyverno_admission_review_latency",
+			Name: "kyverno_admission_review_latency_milliseconds",
 			Help: "can be used to track the latencies associated with the entire individual admission review. For example, if an incoming request trigger, say, five policies, this metric will track the e2e latency associated with the execution of all those policies.",
 		},
 		admissionReviewLatency,

pkg/webhooks/generation.go

@@ -36,7 +36,7 @@ import (
 )
 
 //HandleGenerate handles admission-requests for policies with generate rules
-func (ws *WebhookServer) HandleGenerate(request *v1beta1.AdmissionRequest, policies []*kyverno.ClusterPolicy, ctx *context.Context, userRequestInfo kyverno.RequestInfo, dynamicConfig config.Interface, admissionRequestTimestamp int64) {
+func (ws *WebhookServer) HandleGenerate(request *v1beta1.AdmissionRequest, policies []*kyverno.ClusterPolicy, ctx *context.Context, userRequestInfo kyverno.RequestInfo, dynamicConfig config.Interface, admissionRequestTimestamp int64, latencySender *chan int64) {
 	logger := ws.log.WithValues("action", "generation", "uid", request.UID, "kind", request.Kind, "namespace", request.Namespace, "name", request.Name, "operation", request.Operation, "gvk", request.Kind.String())
 	logger.V(4).Info("incoming request")
 	var engineResponses []*response.EngineResponse
@@ -104,6 +104,10 @@ func (ws *WebhookServer) HandleGenerate(request *v1beta1.AdmissionRequest, polic
 	if request.Operation == v1beta1.Update {
 		ws.handleUpdate(request, policies)
 	}
+
+	// sending the admission request latency to other goroutine (reporting the metrics) over the channel
+	admissionReviewLatencyDuration := int64(time.Since(time.Unix(admissionRequestTimestamp, 0)))
+	*latencySender <- admissionReviewLatencyDuration
 }
 
 func (ws *WebhookServer) registerPolicyRuleResultsMetricGeneration(logger logr.Logger, resourceRequestOperation string, policy kyverno.ClusterPolicy, engineResponse response.EngineResponse, admissionRequestTimestamp int64) {

pkg/webhooks/mutation.go

@@ -22,17 +22,17 @@ import (
 )
 
 // HandleMutation handles mutating webhook admission request
-// return value: generated patches
+// return value: generated patches, triggered policies, engine responses correspdonding to the triggered policies
 func (ws *WebhookServer) HandleMutation(
 	request *v1beta1.AdmissionRequest,
 	resource unstructured.Unstructured,
 	policies []*kyverno.ClusterPolicy,
 	ctx *context.Context,
 	userRequestInfo kyverno.RequestInfo,
-	admissionRequestTimestamp int64) []byte {
+	admissionRequestTimestamp int64) ([]byte, []kyverno.ClusterPolicy, []*response.EngineResponse) {
 
 	if len(policies) == 0 {
-		return nil
+		return nil, nil, nil
 	}
 
 	resourceName := request.Kind.Kind + "/" + request.Name
@@ -100,6 +100,7 @@ func (ws *WebhookServer) HandleMutation(
 
 		// registering the kyverno_policy_rule_execution_latency_milliseconds metric concurrently
 		go ws.registerPolicyRuleExecutionLatencyMetricMutate(logger, string(request.Operation), *policy, *engineResponse, admissionRequestTimestamp)
+		triggeredPolicies = append(triggeredPolicies, *policy)
 	}
 
 	// generate annotations
@@ -131,7 +132,7 @@ func (ws *WebhookServer) HandleMutation(
 	}()
 
 	// patches holds all the successful patches, if no patch is created, it returns nil
-	return engineutils.JoinPatches(patches)
+	return engineutils.JoinPatches(patches), triggeredPolicies, engineResponses
 }
 
 func (ws *WebhookServer) registerPolicyRuleResultsMetricMutation(logger logr.Logger, resourceRequestOperation string, policy kyverno.ClusterPolicy, engineResponse response.EngineResponse, admissionRequestTimestamp int64) {

pkg/webhooks/server.go

@@ -19,9 +19,11 @@ import (
 	"github.com/kyverno/kyverno/pkg/config"
 	client "github.com/kyverno/kyverno/pkg/dclient"
 	enginectx "github.com/kyverno/kyverno/pkg/engine/context"
+	"github.com/kyverno/kyverno/pkg/engine/response"
 	"github.com/kyverno/kyverno/pkg/event"
 	"github.com/kyverno/kyverno/pkg/generate"
 	"github.com/kyverno/kyverno/pkg/metrics"
+	admissionReviewLatency "github.com/kyverno/kyverno/pkg/metrics/admissionreviewlatency"
 	"github.com/kyverno/kyverno/pkg/openapi"
 	"github.com/kyverno/kyverno/pkg/policycache"
 	"github.com/kyverno/kyverno/pkg/policyreport"
@@ -362,18 +364,30 @@ func (ws *WebhookServer) ResourceMutation(request *v1beta1.AdmissionRequest) *v1
 	patchedResource := request.Object.Raw
 
 	// MUTATION
-	patches = ws.HandleMutation(request, resource, mutatePolicies, ctx, userRequestInfo, admissionRequestTimestamp)
+	var triggeredMutatePolicies []v1.ClusterPolicy
+	var mutateEngineResponses []*response.EngineResponse
+
+	patches, triggeredMutatePolicies, mutateEngineResponses = ws.HandleMutation(request, resource, mutatePolicies, ctx, userRequestInfo, admissionRequestTimestamp)
 	logger.V(6).Info("", "generated patches", string(patches))
 
 	// patch the resource with patches before handling validation rules
 	patchedResource = processResourceWithPatches(patches, request.Object.Raw, logger)
 	logger.V(6).Info("", "patchedResource", string(patchedResource))
+	admissionReviewLatencyDuration := int64(time.Since(time.Unix(admissionRequestTimestamp, 0)))
+	// registering the kyverno_admission_review_latency_milliseconds metric concurrently
+	go registerAdmissionReviewLatencyMetricMutate(logger, *ws.promConfig.Metrics, string(request.Operation), mutateEngineResponses, triggeredMutatePolicies, admissionReviewLatencyDuration)
 
 	// GENERATE
 	newRequest := request.DeepCopy()
 	newRequest.Object.Raw = patchedResource
-	go ws.HandleGenerate(newRequest, generatePolicies, ctx, userRequestInfo, ws.configHandler, admissionRequestTimestamp)
 
+	// this channel will be used to transmit the admissionReviewLatency from ws.HandleGenerate(..,) goroutine to registeGeneraterPolicyAdmissionReviewLatencyMetric(...) goroutine
+	admissionReviewCompletionLatencyChannel := make(chan int64, 1)
+
+	go ws.HandleGenerate(newRequest, generatePolicies, ctx, userRequestInfo, ws.configHandler, admissionRequestTimestamp, &admissionReviewCompletionLatencyChannel)
+
+	// registering the kyverno_admission_review_latency_milliseconds metric concurrently
+	go registerAdmissionReviewLatencyMetricGenerate(logger, *ws.promConfig.Metrics, string(request.Operation), mutateEngineResponses, triggeredMutatePolicies, &admissionReviewCompletionLatencyChannel)
 	patchType := v1beta1.PatchTypeJSONPatch
 	return &v1beta1.AdmissionResponse{
 		Allowed: true,
@@ -385,6 +399,29 @@ func (ws *WebhookServer) ResourceMutation(request *v1beta1.AdmissionRequest) *v1
 	}
 }
 
+func registerAdmissionReviewLatencyMetricMutate(logger logr.Logger, promMetrics metrics.PromMetrics, requestOperation string, engineResponses []*response.EngineResponse, triggeredPolicies []v1.ClusterPolicy, admissionReviewLatencyDuration int64) {
+	resourceRequestOperationPromAlias, err := admissionReviewLatency.ParseResourceRequestOperation(requestOperation)
+	if err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+	if err := admissionReviewLatency.ParsePromMetrics(promMetrics).ProcessEngineResponses(engineResponses, triggeredPolicies, admissionReviewLatencyDuration, resourceRequestOperationPromAlias); err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+}
+
+func registerAdmissionReviewLatencyMetricGenerate(logger logr.Logger, promMetrics metrics.PromMetrics, requestOperation string, engineResponses []*response.EngineResponse, triggeredPolicies []v1.ClusterPolicy, latencyReceiver *chan int64) {
+	defer close(*latencyReceiver)
+	resourceRequestOperationPromAlias, err := admissionReviewLatency.ParseResourceRequestOperation(requestOperation)
+	if err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+	// this goroutine will keep on waiting here till it doesn't receive the admission review latency int64 from the other goroutine i.e. ws.HandleGenerate
+	admissionReviewLatencyDuration := <-(*latencyReceiver)
+	if err := admissionReviewLatency.ParsePromMetrics(promMetrics).ProcessEngineResponses(engineResponses, triggeredPolicies, admissionReviewLatencyDuration, resourceRequestOperationPromAlias); err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+}
+
 func (ws *WebhookServer) resourceValidation(request *v1beta1.AdmissionRequest) *v1beta1.AdmissionResponse {
 	logger := ws.log.WithName("Validate").WithValues("uid", request.UID, "kind", request.Kind.Kind, "namespace", request.Namespace, "name", request.Name, "operation", request.Operation)
 	if request.Operation == v1beta1.Delete {

pkg/webhooks/validation.go

@@ -5,16 +5,19 @@ import (
 	"sort"
 	"time"
 
-	client "github.com/kyverno/kyverno/pkg/dclient"
-
 	"github.com/go-logr/logr"
 	kyverno "github.com/kyverno/kyverno/pkg/api/kyverno/v1"
 	v1 "github.com/kyverno/kyverno/pkg/api/kyverno/v1"
 	"github.com/kyverno/kyverno/pkg/config"
+	client "github.com/kyverno/kyverno/pkg/dclient"
 	"github.com/kyverno/kyverno/pkg/engine"
 	"github.com/kyverno/kyverno/pkg/engine/context"
 	"github.com/kyverno/kyverno/pkg/engine/response"
 	"github.com/kyverno/kyverno/pkg/event"
+	"github.com/kyverno/kyverno/pkg/metrics"
+	admissionReviewLatency "github.com/kyverno/kyverno/pkg/metrics/admissionreviewlatency"
+	policyRuleExecutionLatency "github.com/kyverno/kyverno/pkg/metrics/policyruleexecutionlatency"
+	policyRuleResults "github.com/kyverno/kyverno/pkg/metrics/policyruleresults"
 	"github.com/kyverno/kyverno/pkg/policyreport"
 	"github.com/kyverno/kyverno/pkg/policystatus"
 	"github.com/kyverno/kyverno/pkg/resourcecache"
@@ -22,10 +25,6 @@ import (
 	v1beta1 "k8s.io/api/admission/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
-
-	"github.com/kyverno/kyverno/pkg/metrics"
-	policyRuleExecutionLatency "github.com/kyverno/kyverno/pkg/metrics/policyruleexecutionlatency"
-	policyRuleResults "github.com/kyverno/kyverno/pkg/metrics/policyruleresults"
 )
 
 // HandleValidation handles validating webhook admission request
@@ -94,6 +93,7 @@ func HandleValidation(
 	}
 
 	var engineResponses []*response.EngineResponse
+	var triggeredPolicies []kyverno.ClusterPolicy
 	for _, policy := range policies {
 		logger.V(3).Info("evaluating policy", "policy", policy.Name)
 		policyContext.Policy = *policy
@@ -111,6 +111,7 @@ func HandleValidation(
 		go registerPolicyRuleExecutionLatencyMetricValidate(promConfig, logger, string(request.Operation), policyContext.Policy, *engineResponse, admissionRequestTimestamp)
 
 		engineResponses = append(engineResponses, engineResponse)
+		triggeredPolicies = append(triggeredPolicies, *policy)
 		statusListener.Update(validateStats{
 			resp:      engineResponse,
 			namespace: policy.Namespace,
@@ -144,6 +145,9 @@ func HandleValidation(
 	eventGen.Add(events...)
 	if blocked {
 		logger.V(4).Info("resource blocked")
+		//registering the kyverno_admission_review_latency_milliseconds metric concurrently
+		admissionReviewLatencyDuration := int64(time.Since(time.Unix(admissionRequestTimestamp, 0)))
+		go registerAdmissionReviewLatencyMetricValidate(promConfig, logger, string(request.Operation), engineResponses, triggeredPolicies, admissionReviewLatencyDuration)
 		return false, getEnforceFailureErrorMsg(engineResponses)
 	}
 
@@ -155,6 +159,10 @@ func HandleValidation(
 	prInfos := policyreport.GeneratePRsFromEngineResponse(engineResponses, logger)
 	prGenerator.Add(prInfos...)
 
+	//registering the kyverno_admission_review_latency_milliseconds metric concurrently
+	admissionReviewLatencyDuration := int64(time.Since(time.Unix(admissionRequestTimestamp, 0)))
+	go registerAdmissionReviewLatencyMetricValidate(promConfig, logger, string(request.Operation), engineResponses, triggeredPolicies, admissionReviewLatencyDuration)
+
 	return true, ""
 }
 
@@ -178,6 +186,16 @@ func registerPolicyRuleExecutionLatencyMetricValidate(promConfig *metrics.PromCo
 	}
 }
 
+func registerAdmissionReviewLatencyMetricValidate(promConfig *metrics.PromConfig, logger logr.Logger, requestOperation string, engineResponses []*response.EngineResponse, triggeredPolicies []kyverno.ClusterPolicy, admissionReviewLatencyDuration int64) {
+	resourceRequestOperationPromAlias, err := admissionReviewLatency.ParseResourceRequestOperation(requestOperation)
+	if err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+	if err := admissionReviewLatency.ParsePromMetrics(*promConfig.Metrics).ProcessEngineResponses(engineResponses, triggeredPolicies, admissionReviewLatencyDuration, resourceRequestOperationPromAlias); err != nil {
+		logger.Error(err, "error occurred while registering kyverno_admission_review_latency_milliseconds metrics")
+	}
+}
+
 func buildDeletionPrInfo(oldR unstructured.Unstructured) policyreport.Info {
 	return policyreport.Info{
 		Namespace: oldR.GetNamespace(),