1251 fix generate panic (#1252)

* improve error message * fix panic and add error logs * update log levels and messages * fix tests
kyverno · Nov 13, 2020 · 74b6567 · 74b6567
1 parent 5ffbb37
commit 74b6567
Show file tree

Hide file tree

Showing 8 changed files with 22 additions and 13 deletions.
diff --git a/go.sum b/go.sum
@@ -341,6 +341,7 @@ github.com/google/gofuzz v0.0.0-20161122191042-44d81051d367/go.mod h1:HP5RmnzzSN
 github.com/google/gofuzz v0.0.0-20170612174753-24818f796faf/go.mod h1:HP5RmnzzSNb993RKQDq4+1A4ia9nllfqcQFTQJedwGI=
 github.com/google/gofuzz v1.0.0 h1:A8PeW59pxE9IoFRqBp37U+mSNaQoZ46F1f0f863XSXw=
 github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
+github.com/google/gofuzz v1.1.0 h1:Hsa8mG0dQ46ij8Sl2AYJDUv1oA9/d6Vk+3LG99Oe02g=
 github.com/google/gofuzz v1.1.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
 github.com/google/martian v2.1.0+incompatible/go.mod h1:9I4somxYTbIHy5NJKHRl3wXiIaQGbYVAs8BPL6v8lEs=
 github.com/google/pprof v0.0.0-20181206194817-3ea8567a2e57/go.mod h1:zfwlbNMJ+OItoe0UupaVj+oy1omPYYDuagoSzA8v9mc=
@@ -1114,6 +1115,7 @@ k8s.io/utils v0.0.0-20190221042446-c2654d5206da/go.mod h1:8k8uAuAQ0rXslZKaEWd0c3
 k8s.io/utils v0.0.0-20190801114015-581e00157fb1/go.mod h1:sZAwmy6armz5eXlNoLmJcl4F1QuKu7sr+mFQ0byX7Ew=
 k8s.io/utils v0.0.0-20191114184206-e782cd3c129f h1:GiPwtSzdP43eI1hpPCbROQCCIgCuiMMNF8YUVLF3vJo=
 k8s.io/utils v0.0.0-20191114184206-e782cd3c129f/go.mod h1:sZAwmy6armz5eXlNoLmJcl4F1QuKu7sr+mFQ0byX7Ew=
+k8s.io/utils v0.0.0-20200324210504-a9aa75ae1b89 h1:d4vVOjXm687F1iLSP2q3lyPPuyvTUt3aVoBpi2DqRsU=
 k8s.io/utils v0.0.0-20200324210504-a9aa75ae1b89/go.mod h1:sZAwmy6armz5eXlNoLmJcl4F1QuKu7sr+mFQ0byX7Ew=
 mvdan.cc/interfacer v0.0.0-20180901003855-c20040233aed/go.mod h1:Xkxe497xwlCKkIaQYRfC7CSLworTXY9RMqwhhCm+8Nc=
 mvdan.cc/lint v0.0.0-20170908181259-adc824a0674b/go.mod h1:2odslEg/xrtNQqCYg2/jCoyKnw3vv5biOc3JnIcYfL4=
@@ -1137,6 +1139,7 @@ sigs.k8s.io/structured-merge-diff v1.0.1-0.20191108220359-b1b620dd3f06/go.mod h1
 sigs.k8s.io/structured-merge-diff v1.0.1 h1:LOs1LZWMsz1xs77Phr/pkB4LFaavH7IVq/3+WTN9XTA=
 sigs.k8s.io/structured-merge-diff v1.0.1/go.mod h1:IIgPezJWb76P0hotTxzDbWsMYB8APh18qZnxkomBpxA=
 sigs.k8s.io/structured-merge-diff/v3 v3.0.0-20200116222232-67a7b8c61874/go.mod h1:PlARxl6Hbt/+BC80dRLi1qAmnMqwqDg62YvvVkZjemw=
+sigs.k8s.io/structured-merge-diff/v3 v3.0.0 h1:dOmIZBMfhcHS09XZkMyUgkq5trg3/jRyJYFZUiaOp8E=
 sigs.k8s.io/structured-merge-diff/v3 v3.0.0/go.mod h1:PlARxl6Hbt/+BC80dRLi1qAmnMqwqDg62YvvVkZjemw=
 sigs.k8s.io/yaml v1.1.0/go.mod h1:UJmg0vDUVViEyp3mgSv9WPwZCDxu4rQW1olrI1uml+o=
 sigs.k8s.io/yaml v1.2.0 h1:kr/MCeFWJWTwyaHoR9c8EjH9OumOmoF9YGiZd7lFm/Q=

diff --git a/pkg/engine/mutation_test.go b/pkg/engine/mutation_test.go
@@ -160,7 +160,7 @@ func Test_variableSubstitutionPathNotExist(t *testing.T) {
 		Context:     ctx,
 		NewResource: *resourceUnstructured}
 	er := Mutate(policyContext)
-	expectedErrorStr := "could not find variable request.object.metadata.name1 at path /spec/name"
+	expectedErrorStr := "variable request.object.metadata.name1 not found (path: /spec/name)"
 	t.Log(er.PolicyResponse.Rules[0].Message)
 	assert.Equal(t, er.PolicyResponse.Rules[0].Message, expectedErrorStr)
 }
diff --git a/pkg/engine/validation_test.go b/pkg/engine/validation_test.go
@@ -1330,7 +1330,7 @@ func Test_VariableSubstitutionPathNotExistInPattern(t *testing.T) {
 		NewResource: *resourceUnstructured}
 	er := Validate(policyContext)
 	assert.Assert(t, !er.PolicyResponse.Rules[0].Success)
-	assert.Equal(t, er.PolicyResponse.Rules[0].Message, "Validation error: ; Validation rule 'test-path-not-exist' failed. 'could not find variable request.object.metadata.name1 at path /spec/containers/0/name'")
+	assert.Equal(t, er.PolicyResponse.Rules[0].Message, "Validation error: ; Validation rule 'test-path-not-exist' failed. 'variable request.object.metadata.name1 not found (path: /spec/containers/0/name)'")
 }
 
 func Test_VariableSubstitutionPathNotExistInAnyPattern_OnePatternStatisfies(t *testing.T) {
@@ -1512,7 +1512,7 @@ func Test_VariableSubstitutionPathNotExistInAnyPattern_AllPathNotPresent(t *test
 		NewResource: *resourceUnstructured}
 	er := Validate(policyContext)
 	assert.Assert(t, !er.PolicyResponse.Rules[0].Success)
-	assert.Equal(t, er.PolicyResponse.Rules[0].Message, "Substitutions failed: [could not find variable request.object.metadata.name1 at path /spec/template/spec/containers/0/name could not find variable request.object.metadata.name2 at path /spec/template/spec/containers/0/name]")
+	assert.Equal(t, er.PolicyResponse.Rules[0].Message, "Substitutions failed: [variable request.object.metadata.name1 not found (path: /spec/template/spec/containers/0/name) variable request.object.metadata.name2 not found (path: /spec/template/spec/containers/0/name)]")
 }
 
 func Test_VariableSubstitutionPathNotExistInAnyPattern_AllPathPresent_NonePatternSatisfy(t *testing.T) {

diff --git a/pkg/engine/variables/vars.go b/pkg/engine/variables/vars.go
@@ -76,7 +76,7 @@ type NotFoundVariableErr struct {
 }
 
 func (n NotFoundVariableErr) Error() string {
-	return fmt.Sprintf("could not find variable %v at path %v", n.variable, n.path)
+	return fmt.Sprintf("variable %v not found (path: %v)", n.variable, n.path)
 }
 
 // subValR resolves the variables if defined

diff --git a/pkg/generate/cleanup/controller.go b/pkg/generate/cleanup/controller.go
@@ -260,9 +260,9 @@ func (c *Controller) syncGenerateRequest(key string) error {
 	logger := c.log.WithValues("key", key)
 	var err error
 	startTime := time.Now()
-	logger.Info("started syncing generate request", "startTime", startTime)
+	logger.V(3).Info("started syncing generate request", "startTime", startTime)
 	defer func() {
-		logger.V(4).Info("finished syncying generate request", "processingTIme", time.Since(startTime).String())
+		logger.V(4).Info("finished syncing generate request", "processingTIme", time.Since(startTime).String())
 	}()
 	_, grName, err := cache.SplitMetaNamespaceKey(key)
 	if errors.IsNotFound(err) {

diff --git a/pkg/generate/controller.go b/pkg/generate/controller.go
@@ -294,7 +294,7 @@ func (c *Controller) syncGenerateRequest(key string) error {
 	logger := c.log
 	var err error
 	startTime := time.Now()
-	logger.Info("started sync", "key", key, "startTime", startTime)
+	logger.V(3).Info("started sync", "key", key, "startTime", startTime)
 	defer func() {
 		logger.V(4).Info("finished sync", "key", key, "processingTime", time.Since(startTime).String())
 	}()

diff --git a/pkg/generate/generate.go b/pkg/generate/generate.go
@@ -30,7 +30,7 @@ func (c *Controller) processGR(gr *kyverno.GenerateRequest) error {
 	resource, err = getResource(c.client, gr.Spec.Resource)
 	if err != nil {
 		// Dont update status
-		logger.Error(err, "resource does not exist or is yet to be created, requeueing")
+		logger.V(3).Info("resource does not exist or is pending creation, re-queueing", "details", err.Error())
 		return err
 	}
 
@@ -58,7 +58,8 @@ func (c *Controller) applyGenerate(resource unstructured.Unstructured, gr kyvern
 			for _, e := range gr.Status.GeneratedResources {
 				resp, err := c.client.GetResource(e.APIVersion, e.Kind, e.Namespace, e.Name)
 				if err != nil {
-					logger.Error(err, "Generated resource failed to get", "Resource", e.Name)
+					logger.Error(err, "failed to find generated resource", "name", e.Name)
+					continue
 				}
 
 				labels := resp.GetLabels()
@@ -68,9 +69,11 @@ func (c *Controller) applyGenerate(resource unstructured.Unstructured, gr kyvern
 					}
 				}
 			}
+
 			return nil, nil
 		}
-		logger.Error(err, "error in getting policy")
+
+		logger.Error(err, "error in fetching policy")
 		return nil, err
 	}
 
@@ -117,8 +120,10 @@ func (c *Controller) applyGenerate(resource unstructured.Unstructured, gr kyvern
 		if !r.Success {
 			grList, err := c.kyvernoClient.KyvernoV1().GenerateRequests(config.KubePolicyNamespace).List(contextdefault.TODO(), metav1.ListOptions{})
 			if err != nil {
+				logger.Error(err, "failed to list generate requests")
 				continue
 			}
+
 			for _, v := range grList.Items {
 				if engineResponse.PolicyResponse.Policy == v.Spec.Policy && engineResponse.PolicyResponse.Resource.Name == v.Spec.Resource.Name && engineResponse.PolicyResponse.Resource.Kind == v.Spec.Resource.Kind && engineResponse.PolicyResponse.Resource.Namespace == v.Spec.Resource.Namespace {
 					err := c.kyvernoClient.KyvernoV1().GenerateRequests(config.KubePolicyNamespace).Delete(contextdefault.TODO(), v.GetName(), metav1.DeleteOptions{})
@@ -161,8 +166,8 @@ func (c *Controller) applyGeneratePolicy(log logr.Logger, policyContext engine.P
 		if !rule.HasGenerate() {
 			continue
 		}
-		startTime := time.Now()
 
+		startTime := time.Now()
 		processExisting := false
 
 		if len(rule.MatchResources.Kinds) > 0 {
@@ -182,8 +187,9 @@ func (c *Controller) applyGeneratePolicy(log logr.Logger, policyContext engine.P
 		}
 
 		genResource, err := applyRule(log, c.client, rule, resource, ctx, policy.Name, gr, processExisting)
-
 		if err != nil {
+			log.Error(err, "failed to apply generate rule", "policy", policy.Name,
+				"rule", rule.Name, "resource", resource.GetName())
 			return nil, err
 		}
 

diff --git a/pkg/generate/status.go b/pkg/generate/status.go
@@ -32,7 +32,7 @@ func (sc StatusControl) Failed(gr kyverno.GenerateRequest, message string, genRe
 		log.Log.Error(err, "failed to update generate request status", "name", gr.Name)
 		return err
 	}
-	log.Log.Info("updated generate request status", "name", gr.Name, "status", string(kyverno.Failed))
+	log.Log.V(3).Info("updated generate request status", "name", gr.Name, "status", string(kyverno.Failed))
 	return nil
 }