Skip to content

Commit

Permalink
Improve logging
Browse files Browse the repository at this point in the history
* Remove all object prints from the debug logs.
* Add metatada to the logger before running the transformation
* Ability to print whole functionIO to the events

If the GRPC server is in devmode, it will save the funcIOs of each
function to configMaps in the `default` namespace. It will always keep
two configMaps per composite and function. One contains the previous and
one the current state. For example for VSHNPostgreSQL this could result
in up to four configMaps; two for the postgresql function and two for
the miniodev function (which provides the local S3 bucket).

These configMaps can be used to see the state of the whole FuncIO and
should help with local debugging. Additionally the GRPC server now
prints a diff of those configMaps on each reconcile.

The configMaps and the diffs will only rotate on `.spec` changes on the
claim/composite, it uses the generation to track current and previous
states. This way we can track the "logical" diff of a change, even if
it needs multiple reconcile loops to be applied fully.
  • Loading branch information
Kidswiss committed Jul 17, 2023
1 parent db03942 commit 1d28c06
Show file tree
Hide file tree
Showing 9 changed files with 360 additions and 68 deletions.
16 changes: 16 additions & 0 deletions cmd/grpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ import (
pb "github.com/crossplane/crossplane/apis/apiextensions/fn/proto/v1alpha1"
"github.com/go-logr/logr"
"github.com/spf13/cobra"
"github.com/vshn/appcat/pkg/comp-functions/functions/helper"
"github.com/vshn/appcat/pkg/comp-functions/functions/miniodev"
vpf "github.com/vshn/appcat/pkg/comp-functions/functions/vshn-postgres-func"
"github.com/vshn/appcat/pkg/comp-functions/functions/vshnredis"
Expand Down Expand Up @@ -148,5 +149,20 @@ func enableDevMode(enable bool) {
TransformFunc: miniodev.ProvisionMiniobucket,
},
}
for key := range images {
found := false
for _, transform := range images[key] {
if transform.Name == "saveFunctionIO" {
found = true
break
}
}
if !found {
images[key] = append(images[key], runtime.Transform{
Name: "saveFunctionIO",
TransformFunc: helper.SaveFuncIOToConfigMap(key),
})
}
}
}
}
68 changes: 68 additions & 0 deletions go.sum

Large diffs are not rendered by default.

236 changes: 236 additions & 0 deletions pkg/comp-functions/functions/helper/funcio.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,236 @@
package helper

import (
"bytes"
"context"
"encoding/json"
"fmt"
"sort"
"strings"

xkube "github.com/crossplane-contrib/provider-kubernetes/apis/object/v1alpha1"
"github.com/pmezard/go-difflib/difflib"
"github.com/vshn/appcat/pkg"
"github.com/vshn/appcat/pkg/comp-functions/runtime"
corev1 "k8s.io/api/core/v1"
apierrors "k8s.io/apimachinery/pkg/api/errors"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
k8sruntime "k8s.io/apimachinery/pkg/runtime"
controllerruntime "sigs.k8s.io/controller-runtime"
ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/client"
)

// SaveFuncIOToConfigMap is a helper function to make it easy to determine the contents of the FunctionIO.
// This function is not a normall composition function! It won't add anything to the functionIO object to
// avoid it being bloated.
// It will keep two configmaps:
// previous generation functionIO
// current generation functionIO
// The config maps are always written to the default namespace and contain the
// composite name as the name.
func SaveFuncIOToConfigMap(funcName string) func(context.Context, *runtime.Runtime) runtime.Result {
return func(ctx context.Context, iof *runtime.Runtime) runtime.Result {

kubeClient, err := client.New(ctrl.GetConfigOrDie(), client.Options{
Scheme: pkg.SetupScheme(),
})
if err != nil {
return runtime.NewFatalErr(ctx, "cannot create kube client", err)
}

// missusing the xkube object a bit here...
// I'm only interested in the metadata
meta := &xkube.Object{}
if err := iof.Desired.GetComposite(ctx, meta); err != nil {
return runtime.NewFatalErr(ctx, "can't parse composite for functionIO configmap", err)
}

rawIO := iof.GetRawFuncIO()

sort.Slice(rawIO.Desired.Resources, func(i, j int) bool {
return rawIO.Desired.Resources[i].Name < rawIO.Desired.Resources[j].Name
})

for _, res := range rawIO.Desired.Resources {
sort.Slice(res.ConnectionDetails, func(i, j int) bool {
return *res.ConnectionDetails[i].Name < *res.ConnectionDetails[j].Name
})
}

sort.Slice(rawIO.Observed.Resources, func(i, j int) bool {
return rawIO.Observed.Resources[i].Name < rawIO.Observed.Resources[j].Name
})

for _, res := range rawIO.Observed.Resources {
sort.Slice(res.ConnectionDetails, func(i, j int) bool {
return res.ConnectionDetails[i].Name < res.ConnectionDetails[j].Name
})
}

sort.Slice(rawIO.Desired.Composite.ConnectionDetails, func(i, j int) bool {
return rawIO.Desired.Composite.ConnectionDetails[i].Name < rawIO.Desired.Composite.ConnectionDetails[j].Name
})

sort.Slice(rawIO.Observed.Composite.ConnectionDetails, func(i, j int) bool {
return rawIO.Observed.Composite.ConnectionDetails[i].Name < rawIO.Observed.Composite.ConnectionDetails[j].Name
})

for i := range rawIO.Observed.Resources {
err := removeMetadata(&rawIO.Observed.Resources[i].Resource)
if err != nil {
return runtime.NewFatalErr(ctx, "cannot cleanup observed resources", err)
}
}

for i := range rawIO.Desired.Resources {
err := removeMetadata(&rawIO.Desired.Resources[i].Resource)
if err != nil {
return runtime.NewFatalErr(ctx, "cannot cleanup desired resources", err)
}
}

err = removeMetadata(&rawIO.Observed.Composite.Resource)
if err != nil {
return runtime.NewFatalErr(ctx, "cannote cleanup observed composite", err)
}

err = removeMetadata(&rawIO.Desired.Composite.Resource)
if err != nil {
return runtime.NewFatalErr(ctx, "cannot cleanup desired composite", err)
}

funcIO, err := json.Marshal(rawIO)
if err != nil {
return runtime.NewFatalErr(ctx, "cannot marshal functionIO to JSON", err)
}

currentIndex := meta.Generation % 2

configMap := &corev1.ConfigMap{
ObjectMeta: metav1.ObjectMeta{
Name: fmt.Sprintf("%s-%s-%d", meta.GetName(), funcName, currentIndex),
Namespace: "default",
},
Data: map[string]string{
"funcIO": string(funcIO),
},
}

err = diffFuncIOs(ctx, currentIndex, configMap, kubeClient, funcName)
if err != nil {
return runtime.NewFatalErr(ctx, "cannot diff funcIO", err)
}

err = createOrUpdateObject(ctx, configMap, kubeClient)
if err != nil {
return runtime.NewFatalErr(ctx, "can't save configmap containing functionIO", err)
}

return runtime.NewNormal()
}
}

func removeMetadata(res *k8sruntime.RawExtension) error {
obj := map[string]interface{}{}
err := json.Unmarshal(res.Raw, &obj)
if err != nil {
return err
}
if err != nil {
return err
}
// outer kubec objects
unstructured.RemoveNestedField(obj, "metadata", "generation")
unstructured.RemoveNestedField(obj, "metadata", "resourceVersion")
unstructured.RemoveNestedField(obj, "metadata", "annotations", "kubectl.kubernetes.io/last-applied-configuration")
unstructured.RemoveNestedField(obj, "metadata", "managedFields")

// inner observed objects
unstructured.RemoveNestedField(obj, "status", "atProvider", "manifest", "metadata", "generation")
unstructured.RemoveNestedField(obj, "status", "atProvider", "manifest", "metadata", "resourceVersion")
unstructured.RemoveNestedField(obj, "status", "atProvider", "manifest", "metadata", "annotations", "kubectl.kubernetes.io/last-applied-configuration")
unstructured.RemoveNestedField(obj, "status", "atProvider", "manifest", "metadata", "managedFields")

// inner spec objects
unstructured.RemoveNestedField(obj, "spec", "forProvider", "manifest", "metadata", "generation")
unstructured.RemoveNestedField(obj, "spec", "forProvider", "manifest", "metadata", "resourceVersion")
unstructured.RemoveNestedField(obj, "spec", "forProvider", "manifest", "metadata", "annotations", "kubectl.kubernetes.io/last-applied-configuration")
unstructured.RemoveNestedField(obj, "spec", "atProvider", "manifest", "metadata", "managedFields")

res.Raw, err = json.Marshal(&obj)
if err != nil {
return err
}
return err
}

func createOrUpdateObject(ctx context.Context, configMap *corev1.ConfigMap, kubeClient client.Client) error {

tmpMap := &corev1.ConfigMap{}

err := kubeClient.Get(ctx, client.ObjectKeyFromObject(configMap), tmpMap)
if err != nil && apierrors.IsNotFound(err) {
err := kubeClient.Create(ctx, configMap)
if err != nil {
return err
}
return nil
} else if err != nil {
return nil
}

err = kubeClient.Update(ctx, configMap)
if err != nil {
return err
}

return nil
}

func diffFuncIOs(ctx context.Context, currentIndex int64, currentMap *corev1.ConfigMap, kubeClient client.Client, funcName string) error {

prevIndex := 0
if currentIndex == 0 {
prevIndex = 1
}

prevMap := &corev1.ConfigMap{}

prevMapName := strings.TrimRight(currentMap.GetName(), fmt.Sprintf("%d", currentIndex)) + fmt.Sprintf("%d", prevIndex)

prevMap.ObjectMeta.Name = prevMapName
prevMap.ObjectMeta.Namespace = "default"

err := kubeClient.Get(ctx, client.ObjectKeyFromObject(prevMap), prevMap)
if err != nil && apierrors.IsNotFound(err) {
return nil
} else if err != nil {
return err
}

prevPretty := bytes.Buffer{}
err = json.Indent(&prevPretty, []byte(prevMap.Data["funcIO"]), "", " ")
if err != nil {
return err
}

currentPretty := bytes.Buffer{}
err = json.Indent(&currentPretty, []byte(currentMap.Data["funcIO"]), "", " ")
if err != nil {
return err
}

diff := difflib.UnifiedDiff{
A: difflib.SplitLines(prevPretty.String()),
B: difflib.SplitLines(currentPretty.String()),
FromFile: "Previous",
ToFile: "Current",
Context: 3,
}
text, _ := difflib.GetUnifiedDiffString(diff)
controllerruntime.LoggerFrom(ctx).V(1).Info(text, "functionName", funcName)

return nil
}
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ func AddPvcSecret(ctx context.Context, iof *runtime.Runtime) runtime.Result {
}
log.Info("Check if encrypted storage is enabled")

log.V(1).Info("Transforming", "obj", iof)
log.V(1).Info("Transforming")

encryptionSpec := comp.Spec.Parameters.Encryption

Expand Down
12 changes: 6 additions & 6 deletions pkg/comp-functions/runtime/desired.go
Original file line number Diff line number Diff line change
Expand Up @@ -105,7 +105,7 @@ func (d *DesiredResources) PutIntoObject(ctx context.Context, o client.Object, k
return err
}

log.V(1).Info("Preparing to put object into desired kube object", "object", o, "kube object name", kon)
log.V(1).Info("Preparing to put object into desired kube object", "kube object name", kon)
err = updateKubeObject(o, ko)
if err != nil {
return err
Expand Down Expand Up @@ -144,7 +144,7 @@ func (d *DesiredResources) PutCompositeConnectionDetail(ctx context.Context, cd
log := controllerruntime.LoggerFrom(ctx)
for i, c := range d.composite.ConnectionDetails {
if cd.Name == c.Name {
log.V(1).Info("Updating existing desired composite connection detail", "cd", cd)
log.V(1).Info("Updating existing desired composite connection detail", "name", cd.Name)
d.composite.ConnectionDetails[i] = cd
return
}
Expand Down Expand Up @@ -172,7 +172,7 @@ func (d *DesiredResources) RemoveCompositeConnectionDetail(ctx context.Context,
// when there might be multiple transformation functions in the pipeline
func (d *DesiredResources) fromKubeObject(ctx context.Context, kobj *xkube.Object, obj client.Object) error {
log := controllerruntime.LoggerFrom(ctx)
log.V(1).Info("Unmarshalling resource from desired kube object", "kube object", kobj)
log.V(1).Info("Unmarshalling resource from desired kube object")
if kobj.Spec.ForProvider.Manifest.Raw == nil {
return ErrNotFound
}
Expand All @@ -181,7 +181,7 @@ func (d *DesiredResources) fromKubeObject(ctx context.Context, kobj *xkube.Objec

func (d *DesiredResources) put(ctx context.Context, obj client.Object, resName string) error {
log := controllerruntime.LoggerFrom(ctx)
log.V(1).Info("Putting object into desired kube object", "object", obj, "kube object name", resName)
log.V(1).Info("Putting object into desired kube object", "kube object name", resName)
kind, _, err := s.ObjectKinds(obj)
if err != nil {
return fmt.Errorf("cannot get object kinds from %s: %v", obj.GetName(), err)
Expand All @@ -195,7 +195,7 @@ func (d *DesiredResources) put(ctx context.Context, obj client.Object, resName s

for _, res := range d.resources {
if res.GetName() == resName {
log.V(1).Info("Updating existing desired kube object with resource", "object", obj, "kube object name", resName)
log.V(1).Info("Updating existing desired kube object with resource", "kube object name", resName)
res.SetRaw(rawData)
return nil
}
Expand All @@ -210,7 +210,7 @@ func (d *DesiredResources) put(ctx context.Context, obj client.Object, resName s
},
}

log.V(1).Info("No desired kube object found, adding new one with resource", "object", obj, "kube object name", resName)
log.V(1).Info("No desired kube object found, adding new one with resource", "kube object name", resName)
d.resources = append(d.resources, &dr)
return nil
}
Expand Down
57 changes: 0 additions & 57 deletions pkg/comp-functions/runtime/logger.go

This file was deleted.

2 changes: 1 addition & 1 deletion pkg/comp-functions/runtime/observed.go
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ func (o *ObservedResources) GetCompositeConnectionDetails(_ context.Context) *[]
// and the status field will not be changed with multiple transformation functions
func (o *ObservedResources) fromKubeObject(ctx context.Context, kobj *xkube.Object, obj client.Object) error {
log := controllerruntime.LoggerFrom(ctx)
log.V(1).Info("Unmarshalling resource from observed kube object", "kube object", kobj)
log.V(1).Info("Unmarshalling resource from observed kube object", "name", kobj.GetName())
if kobj.Status.AtProvider.Manifest.Raw == nil {
return ErrNotFound
}
Expand Down
Loading

0 comments on commit 1d28c06

Please sign in to comment.