Skip to content

Commit

Permalink
Merge pull request #41 from vshn/change/logging
Browse files Browse the repository at this point in the history
Improve logging
  • Loading branch information
Kidswiss authored Jul 18, 2023
2 parents db03942 + 6130c8e commit af99cb9
Show file tree
Hide file tree
Showing 11 changed files with 381 additions and 70 deletions.
34 changes: 32 additions & 2 deletions cmd/grpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@ 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"
"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 All @@ -16,6 +18,7 @@ import (
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/client"
)

func init() {
Expand Down Expand Up @@ -122,7 +125,10 @@ type server struct {

func (s *server) RunFunction(ctx context.Context, in *pb.RunFunctionRequest) (*pb.RunFunctionResponse, error) {
ctx = logr.NewContext(ctx, s.logger)
enableDevMode(DevMode)
err := enableDevMode(DevMode)
if err != nil {
return nil, status.Errorf(codes.Aborted, "cannot enable devMode: %s", err)
}
fnio, err := runtime.RunCommand(ctx, in.Input, images[in.Image])
if err != nil {
err = status.Errorf(codes.Aborted, "Can't process request for PostgreSQL")
Expand All @@ -140,13 +146,37 @@ func cleanStart(socketName string) error {
return nil
}

func enableDevMode(enable bool) {
func enableDevMode(enable bool) error {

kubeClient, err := client.New(ctrl.GetConfigOrDie(), client.Options{
Scheme: pkg.SetupScheme(),
})
if err != nil {
return err
}

if enable {
images["miniodev"] = []runtime.Transform{
{
Name: "miniodevbucket",
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, kubeClient),
})
}
}
}
return nil
}
1 change: 1 addition & 0 deletions docs/modules/ROOT/nav.adoc
Original file line number Diff line number Diff line change
Expand Up @@ -16,3 +16,4 @@
* xref:explanations/comp-functions/vshn-postgres.adoc[VSHN Postgres Functions]
* xref:explanations/slareports.adoc[]
* xref:explanations/dev-notes.adoc[]
* xref:explanations/debug.adoc[]
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
= Debugging

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.
68 changes: 68 additions & 0 deletions go.sum

Large diffs are not rendered by default.

233 changes: 233 additions & 0 deletions pkg/comp-functions/functions/helper/funcio.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,233 @@
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/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"
"sigs.k8s.io/controller-runtime/pkg/client"
"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
)

// 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, kubeClient client.Client) func(context.Context, *runtime.Runtime) runtime.Result {
return func(ctx context.Context, iof *runtime.Runtime) runtime.Result {

// 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 = controllerutil.CreateOrUpdate(ctx, kubeClient, configMap, func() error {
return nil
})
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", "forProvider", "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, err := difflib.GetUnifiedDiffString(diff)
if err != nil {
return err
}
controllerruntime.LoggerFrom(ctx).V(1).Info("\n"+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
Loading

0 comments on commit af99cb9

Please sign in to comment.