introduce structured logging

components/function-controller/config/crd/bases/serverless.kyma-project.io_functions.yaml

@@ -242,8 +242,6 @@ spec:
               type: string
             source:
               type: string
-          required:
-          - runtime
           type: object
       type: object
   version: v1alpha1

components/function-controller/internal/controllers/serverless/build_resources.go

@@ -7,14 +7,15 @@ import (
 
 	"github.com/kyma-project/kyma/components/function-controller/internal/git"
 
-	"github.com/kyma-project/kyma/components/function-controller/internal/controllers/serverless/runtime"
-	serverlessv1alpha1 "github.com/kyma-project/kyma/components/function-controller/pkg/apis/serverless/v1alpha1"
 	appsv1 "k8s.io/api/apps/v1"
 	autoscalingv1 "k8s.io/api/autoscaling/v1"
 	batchv1 "k8s.io/api/batch/v1"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/util/intstr"
+
+	"github.com/kyma-project/kyma/components/function-controller/internal/controllers/serverless/runtime"
+	serverlessv1alpha1 "github.com/kyma-project/kyma/components/function-controller/pkg/apis/serverless/v1alpha1"
 )
 
 const (
@@ -245,18 +246,6 @@ func (r *FunctionReconciler) buildGitJob(instance *serverlessv1alpha1.Function,
 				},
 				Spec: corev1.PodSpec{
 					Volumes: []corev1.Volume{
-						{
-							Name:         "workspace",
-							VolumeSource: corev1.VolumeSource{EmptyDir: &corev1.EmptyDirVolumeSource{}},
-						},
-						{
-							Name: "runtime",
-							VolumeSource: corev1.VolumeSource{
-								ConfigMap: &corev1.ConfigMapVolumeSource{
-									LocalObjectReference: corev1.LocalObjectReference{Name: rtmConfig.DockerfileConfigMapName},
-								},
-							},
-						},
 						{
 							Name: "credentials",
 							VolumeSource: corev1.VolumeSource{
@@ -271,6 +260,18 @@ func (r *FunctionReconciler) buildGitJob(instance *serverlessv1alpha1.Function,
 								},
 							},
 						},
+						{
+							Name: "runtime",
+							VolumeSource: corev1.VolumeSource{
+								ConfigMap: &corev1.ConfigMapVolumeSource{
+									LocalObjectReference: corev1.LocalObjectReference{Name: rtmConfig.DockerfileConfigMapName},
+								},
+							},
+						},
+						{
+							Name:         "workspace",
+							VolumeSource: corev1.VolumeSource{EmptyDir: &corev1.EmptyDirVolumeSource{}},
+						},
 					},
 					InitContainers: []corev1.Container{
 						{

tests/function-controller/go.mod

@@ -19,7 +19,7 @@ require (
 	github.com/onsi/gomega v1.9.0
 	github.com/pkg/errors v0.9.1
 	github.com/robfig/cron v1.2.0 // indirect
-	github.com/sirupsen/logrus v1.4.2
+	github.com/sirupsen/logrus v1.6.0
 	github.com/spf13/pflag v1.0.5
 	github.com/vrischmann/envconfig v1.2.0
 	golang.org/x/crypto v0.0.0-20200414173820-0848c9571904 // indirect

tests/function-controller/go.sum

@@ -298,6 +298,7 @@ github.com/kisielk/errcheck v1.2.0/go.mod h1:/BMXB+zMLi60iA8Vv6Ksmxu/1UDYcXs4uQL
 github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1 h1:mweAR1A6xJ3oS2pRaGiHgQ4OO8tzTaLawm8vnODuwDk=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
+github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
@@ -408,6 +409,8 @@ github.com/sergi/go-diff v1.1.0/go.mod h1:STckp+ISIX8hZLjrqAeVduY0gWCT9IjLuqbuNX
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
 github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
+github.com/sirupsen/logrus v1.6.0 h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I=
+github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
 github.com/soheilhy/cmux v0.1.4/go.mod h1:IM3LyeVVIOuxMH7sFAkER9+bJ4dT7Ms6E4xg4kGIyLM=
 github.com/spf13/afero v1.1.2/go.mod h1:j4pytiNVoe2o6bmDsKpLACNPDBIoEAkihy7loJ1B0CQ=
 github.com/spf13/afero v1.2.2/go.mod h1:9ZxEEn6pIJ8Rxe320qSDBk6AsU0r9pR7Q4OcevTdifk=

tests/function-controller/main_test.go

@@ -5,6 +5,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/kyma-project/kyma/tests/function-controller/pkg/step"
 	"github.com/kyma-project/kyma/tests/function-controller/testsuite/scenarios"
 
@@ -30,7 +32,11 @@ func TestRuntimes(t *testing.T) {
 
 	restConfig := controllerruntime.GetConfigOrDie()
 
-	steps, err := scenarios.FunctionTestStep(restConfig, cfg.Test, t, g)
+	logf := logrus.New()
+	logf.SetFormatter(&logrus.TextFormatter{})
+	logf.SetOutput(&testLoggerSink{t: t})
+
+	steps, err := scenarios.FunctionTestStep(restConfig, cfg.Test, logf, t)
 	failOnError(g, err)
 	runner := step.NewRunner(step.WithCleanupDefault(cfg.Test.Cleanup))
 
@@ -47,3 +53,18 @@ func loadConfig(prefix string) (config, error) {
 func failOnError(g *gomega.GomegaWithT, err error) {
 	g.Expect(err).NotTo(gomega.HaveOccurred())
 }
+
+type testLoggerSink struct {
+	t *testing.T
+}
+
+func (t *testLoggerSink) Write(p []byte) (n int, err error) {
+	t.t.Logf("%s", string(p))
+	return len(p), nil
+}
+
+type testLogger interface {
+	Write(p []byte) (n int, err error)
+}
+
+var _ testLogger = &testLoggerSink{}

tests/function-controller/pkg/apirule/apirule.go

@@ -143,7 +143,7 @@ func (a *APIRule) isApiRuleReady(name string) func(event watch.Event) (bool, err
 			return false, shared.ErrInvalidDataType
 		}
 		if u.GetName() != name {
-			a.log.Logf("names mismatch, object's name %s, supplied %s", u.GetName(), name)
+			a.log.Infof("names mismatch, object's name %s, supplied %s", u.GetName(), name)
 			return false, nil
 		}
 

tests/function-controller/pkg/broker/broker.go

@@ -89,7 +89,7 @@ func (b *Broker) isBrokerReady(name string) func(event watch.Event) (bool, error
 			return false, shared.ErrInvalidDataType
 		}
 		if u.GetName() != name {
-			b.log.Logf("names mismatch, object's name %s, supplied %s", u.GetName(), name)
+			b.log.Infof("names mismatch, object's name %s, supplied %s", u.GetName(), name)
 			return false, nil
 		}
 

tests/function-controller/pkg/job/job.go

@@ -29,7 +29,6 @@ func New(parentFunctionName string, batchCli batchv1typed.BatchV1Interface, c sh
 		parentFunctionName: parentFunctionName,
 		namespace:          c.Namespace,
 		waitTimeout:        c.WaitTimeout,
-		log:                c.Log,
 		verbose:            c.Verbose,
 	}
 }

tests/function-controller/pkg/namespace/namespace.go

@@ -71,17 +71,17 @@ func (n *Namespace) Create() (string, error) {
 		return n.name, errors.Wrapf(err, "while creating namespace %s", n.name)
 	}
 
-	n.log.Logf("CREATE: namespace %s", n.name)
+	n.log.Infof("CREATE: namespace %s", n.name)
 	if n.verbose {
-		n.log.Logf("%+v", ns)
+		n.log.Infof("%+v", ns)
 	}
 	return n.name, nil
 }
 
 func (n *Namespace) Delete() error {
 	err := retry.WithIgnoreOnNotFound(retry.DefaultBackoff, func() error {
 		if n.verbose {
-			n.log.Logf("DELETE: namespace: %s", n.name)
+			n.log.Infof("DELETE: namespace: %s", n.name)
 		}
 		return n.coreCli.Namespaces().Delete(n.name, &metav1.DeleteOptions{})
 	}, n.log)

tests/function-controller/pkg/poller/poller.go

@@ -21,6 +21,11 @@ type Poller struct {
 	DataKey            string
 }
 
+func (p *Poller) WithLogger(l shared.Logger) Poller {
+	p.Log = l
+	return *p
+}
+
 func (p Poller) PollForAnswer(url, payloadStr, expected string) error {
 	tr := &http.Transport{
 		TLSClientConfig: &tls.Config{InsecureSkipVerify: p.InsecureSkipVerify},
@@ -39,7 +44,7 @@ func (p Poller) PollForAnswer(url, payloadStr, expected string) error {
 			payload := strings.NewReader(fmt.Sprintf(`{ "%s": "%s" }`, p.DataKey, payloadStr))
 			req, err := http.NewRequest(http.MethodGet, url, payload)
 			if err != nil {
-				return false, err // TODO erros.wrap
+				return false, errors.Wrapf(err, "while creating new request to ping url %s with payload %s", url, payloadStr)
 			}
 
 			req.Header.Add("content-type", "application/json")
@@ -50,12 +55,12 @@ func (p Poller) PollForAnswer(url, payloadStr, expected string) error {
 			defer func() {
 				errClose := res.Body.Close()
 				if errClose != nil {
-					p.Log.Logf("Error closing body in request to %s: %v", url, errClose)
+					p.Log.Infof("Error closing body in request to %s: %v", url, errClose)
 				}
 			}()
 
 			if res.StatusCode != http.StatusOK {
-				p.Log.Logf("Expected status %s, got %s, retrying...", http.StatusText(http.StatusOK), res.Status)
+				p.Log.Infof("Expected status %s, got %s, retrying...", http.StatusText(http.StatusOK), res.Status)
 				return false, nil
 			}
 
@@ -67,11 +72,11 @@ func (p Poller) PollForAnswer(url, payloadStr, expected string) error {
 			body := string(byteRes)
 
 			if body != expected {
-				p.Log.Logf("Got: %q, expected: %s, retrying...", body, expected)
+				p.Log.Infof("Got: %q, expected: %s, retrying...", body, expected)
 				return false, nil
 			}
 
-			p.Log.Logf("Got: %q, correct...", body)
+			p.Log.Infof("Got: %q, correct...", body)
 			return true, nil
 		}, done)
 }

tests/function-controller/pkg/resource/resource.go

@@ -57,7 +57,7 @@ func (r *Resource) Create(res interface{}) (string, error) {
 	}
 
 	if r.verbose {
-		r.log.Logf("[CREATE]: name %s, namespace %s, resource %v", unstructuredObj.GetName(), unstructuredObj.GetNamespace(), unstructuredObj)
+		r.log.Infof("[CREATE]: name %s, namespace %s, resource %v", unstructuredObj.GetName(), unstructuredObj.GetNamespace(), unstructuredObj)
 	}
 
 	return resourceVersion, nil
@@ -84,7 +84,7 @@ func (r *Resource) List(set map[string]string) (*unstructured.UnstructuredList,
 	}
 
 	if r.verbose {
-		r.log.Logf("LIST %s: namespace:%s kind:%s\n%v", selector, namespace, r.kind, result)
+		r.log.Infof("LIST %s: namespace:%s kind:%s\n%v", selector, namespace, r.kind, result)
 	}
 
 	return result, nil
@@ -106,7 +106,7 @@ func (r *Resource) Get(name string) (*unstructured.Unstructured, error) {
 	}
 
 	if r.verbose {
-		r.log.Logf("GET name:%s: namespace:%s kind:%s\n%v", name, namespace, r.kind, result)
+		r.log.Infof("GET name:%s: namespace:%s kind:%s\n%v", name, namespace, r.kind, result)
 	}
 
 	return result, nil
@@ -135,7 +135,7 @@ func (r *Resource) Delete(name string, timeout time.Duration) error {
 		}
 
 		if r.verbose {
-			r.log.Logf("DELETE %s: namespace:%s name:%s", r.kind, namespace, name)
+			r.log.Infof("DELETE %s: namespace:%s name:%s", r.kind, namespace, name)
 		}
 
 		return r.ResCli.Delete(name, &metav1.DeleteOptions{})
@@ -192,9 +192,9 @@ func (r *Resource) Update(res interface{}) (*unstructured.Unstructured, error) {
 		namespace = r.namespace
 	}
 
-	r.log.Logf("UPDATE %s: namespace:%s kind:%s", result.GetName(), namespace, r.kind)
+	r.log.Infof("UPDATE %s: namespace:%s kind:%s", result.GetName(), namespace, r.kind)
 	if r.verbose {
-		r.log.Logf("%+v", result)
+		r.log.Infof("%+v", result)
 	}
 
 	return result, nil

tests/function-controller/pkg/retry/retry.go

@@ -25,7 +25,7 @@ func fnWithIgnore(fn func() error, ignoreErr func(error) bool, log shared.Logger
 			return err
 		}
 		if ignoreErr(err) {
-			log.Logf("ignoring: %s", err)
+			log.Infof("ignoring: %s", err)
 			return nil
 		}
 		return err
@@ -35,7 +35,7 @@ func fnWithIgnore(fn func() error, ignoreErr func(error) bool, log shared.Logger
 func errorFn(log shared.Logger) func(error) bool {
 	return func(err error) bool {
 		if errors.IsTimeout(err) || errors.IsServerTimeout(err) || errors.IsTooManyRequests(err) {
-			log.Logf("retrying due to: %s", err)
+			log.Infof("retrying due to: %s", err)
 			return true
 		}
 		return false

tests/function-controller/pkg/shared/shared.go

@@ -9,7 +9,7 @@ import (
 )
 
 type Logger interface {
-	Logf(format string, args ...interface{})
+	Infof(format string, args ...interface{})
 }
 
 var (
@@ -28,13 +28,12 @@ func LogReadiness(ready, verbose bool, name string, log Logger, resource interfa
 	typeName := fmt.Sprintf("%T", resource)
 
 	if ready {
-		log.Logf("%s %s is ready", typeName, name)
-
+		log.Infof("%s %s is ready", typeName, name)
 	} else {
-		log.Logf("%s %s is not ready", typeName, name)
+		log.Infof("%s %s is not ready", typeName, name)
 	}
 
 	if verbose {
-		log.Logf("%+v", resource)
+		log.Infof("%+v", resource)
 	}
 }