Kubebuilder: weird logging stacktrace when using built-in error logger

[rayanebel]

Hi,

I'm trying to create my first operator using kubebuilder and I have a a weird stack trace which appear when I'm trying to use the built-in error logger.

Here you can find the reconcile function:

func (r *ClusterReconciler) Reconcile(req ctrl.Request) (ctrl.Result, error) {
    _ = context.Background()
    log := r.Log.WithValues("cluster", req.NamespacedName)

    // Faire un Get de la CRD
    cluster := &configv1.Cluster{}
    err := r.Get(context.TODO(), client.ObjectKey{Name: "test", Namespace: req.Namespace}, cluster)
    if err != nil {
        log.Error(err, "failed to get Cluster resource")
        return ctrl.Result{}, client.IgnoreNotFound(err)
    }
    r.Log.Info("Fetch cluster object", "cluster_name", cluster.Spec.ClusterName)
}

and when I test the error case I have the following stacktrace from zapr.go in output:

2020-07-10T14:23:47.586+0200    ERROR   controllers.Cluster     failed to get Cluster resource   {"cluster": "iam/cluster-sample", "error": "Cluster.config.argocd.kubernetes.io \"test\" not found"}
github.com/go-logr/zapr.(*zapLogger).Error
        /home/xxxxxxxx/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128
xxxxxxxxxxxxxxxxxxxxxx/Platform/kargocd/controllers.(*ClusterReconciler).Reconcile
        /home/xxxxxxxx/xxxxxxxxx/argocd/kargocd/controllers/cluster_controller.go:48
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler
        /home/xxxxxxxx/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:256
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem
        /home/xxxxxxxx/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:232
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker
        /home/xxxxxxxx/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:211
k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1
        /home/xxxxxxxx/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:152
k8s.io/apimachinery/pkg/util/wait.JitterUntil
        /home/xxxxxxxx/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:153
k8s.io/apimachinery/pkg/util/wait.Until
        /home/xxxxxxxx/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:88

I'm not sure if it's normal to have this kind of stack trace after my error message. Do I miss something ?

What versions of software are you using? Specifically, the following are often useful:

• go version
  go version go1.14.4 linux/amd64
• kubebuilder version
  Version: version.Version{KubeBuilderVersion:"2.3.1", KubernetesVendor:"1.16.4", GitCommit:"8b53abeb4280186e494b726edf8f54ca7aa64a49", BuildDate:"2020-03-26T16:42:00Z", GoOs:"unknown", GoArch:"unknown"}
• controller-runtime version (check your go.mod file)
  sigs.k8s.io/controller-runtime v0.5.0
• Kubernetes & kubectl versions (just run kubectl version against your API server)
  Client Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.3", GitCommit:"2e7996e3e2712684bc73f0dec0200d64eec7fe40", GitTreeState:"clean", BuildDate:"2020-05-20T12:52:00Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"} Server Version: version.Info{Major:"1", Minor:"14", GitVersion:"v1.14.8", GitCommit:"ea670c3ed1fab723e191551e68da613f8a9c5667", GitTreeState:"clean", BuildDate:"2020-05-30T04:43:12Z", GoVersion:"go1.12.10", Compiler:"gc", Platform:"linux/amd64"}

/kind bug

[camilamacedo86]

Shows that you did not apply the CR of the CRD and then, run kubectl apply -f /config/samples/yourcr.yaml.
Also, see that:

• The project officially supports the go version 1.13 and not 1.14. I'd suggest you use 1.13.
• Your reconcile implementation should be something such as to avoid panic when the CR is not applied/found:

Example where the Kind is Memcached:

    // Fetch the Memcached instance
    memcached := &cachev1alpha1.Memcached{}
    err := r.client.Get(context.TODO(), request.NamespacedName, memcached)
    if err != nil {
        if errors.IsNotFound(err) {
            // Request object not found, could have been deleted after reconcile request.
            // Owned objects are automatically garbage collected. For additional cleanup logic use finalizers.
            // Return and don't requeue
            reqLogger.Info("Memcached resource not found. Ignoring since object must be deleted.")
            return reconcile.Result{}, nil
        }
        // Error reading the object - requeue the request.
        reqLogger.Error(err, "Failed to get Memcached.")
        return reconcile.Result{}, err
    }

Looking for you ok to close this one as sorted out.

[camilamacedo86]

/assign @camilamacedo86

[camilamacedo86]

Hi @rayanebel,

I am closing this one since shows that the above information solves your scenario. However, please feel free to raise new issues or re-open this one if you need.

[camilamacedo86]

/close

[k8s-ci-robot]

@camilamacedo86: Closing this issue.

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[wangweihong]

hi, @camilamacedo86.. I found not matter what error reconcile returns, it always log such a stack trace. I am confused if it is panic problem, or just a normal case.

func (r *WorkSpaceReconciler) Reconcile(req ctrl.Request) (ctrl.Result, error) {
    return ctrl.Result{}, fmt.Errorf("whatever")

2020-09-17T14:42:13.484+0800    ERROR   controller-runtime.controller   Reconciler error    {"controller": "workspace", "request": "/testdelete", "er
ror": "whatever"}github.com/go-logr/zapr.(*zapLogger).Error
    /home/kiongf/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler
    /home/kiongf/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:258
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem
    /home/kiongf/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:232
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).worker
    /home/kiongf/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:211
k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1
    /home/kiongf/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:152
k8s.io/apimachinery/pkg/util/wait.JitterUntil
    /home/kiongf/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:153
k8s.io/apimachinery/pkg/util/wait.Until
    /home/kiongf/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:88

[jroper]

@camilamacedo86 This isn't about the error itself, it's about the controller-runtimes reporting of the error being wrong, the controller runtime is reporting the error as if it came from its own code, but it didn't, it's the wrong stack trace. This makes it very difficult to debug errors returned by a controller, because there's no way to see which line of code the error came from.