Operator-sdk: Logger.Error is ambiguous and non-informative

[nrvnrvn]

Bug Report

What did you do?
I am trying to be informative and concise while writing messages to log.
And I got stuck with two problems:

1. the choice is between logger.Error, logger.Info, logger.V(1).Info. These are Error, Info, and Debug levels accordingly. But there are no means for Warning the end user.
2. logger.Error is behaving as it was a controller failure and the stacktrace is included, for instance:

2019-06-28T17:34:29.623Z    ERROR   controller_coolcontroller   hell    {"Request.Namespace": "default", "Request.Name": "test", "error": "some error"}
cooloperator/vendor/github.com/go-logr/zapr.(*zapLogger).Error
    /Users/me/go/src/cooloperator/vendor/github.com/go-logr/zapr/zapr.go:128
cooloperator/pkg/controller/cooltype.(*Reconcilecooltype).Reconcile
    /Users/me/go/src/cooloperator/pkg/controller/cooltype/cooltype_controller.go:164
cooloperator/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem
    /Users/me/go/src/cooloperator/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:215
cooloperator/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func1
    /Users/me/go/src/cooloperator/vendor/sigs.k8s.io/controller-runtime/pkg/internal/controller/controller.go:158
cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1
    /Users/me/go/src/cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133
cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil
    /Users/me/go/src/cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:134
cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait.Until
    /Users/me/go/src/cooloperator/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:88

Sometimes showing the whole stacktrace is not needed when all is needed is to indicate that some error happened during reconciling the request and what's happened is really wrong and the end user should be aware of it.

The question is:

1. what is the recommended way to show errors and warnings not related to the Reconciler itself but related to some logic behind processing resources?

Currently I am considering to implements something like this:

logErr := log.WithValues("loglevel", "ERROR").Info
logWarn := log.WithValues("loglevel", "WARN").Info

but it looks more like an ugly hack than a solution...

Environment

• operator-sdk version:
  0.8.1
  

• go version:
  go version go1.12.6 darwin/amd64
  

• Kubernetes version information:

• Kubernetes cluster kind:

• Are you writing your operator in ansible, helm, or go?

Possible Solution

Additional context
Add any other context about the problem here.

[joelanford]

@nrvnrvn since operator-sdk depends on controller-runtime, it also inherits the logr interface, which is pretty opinionated. The default logr implementation chosen by controller-runtime (and operator-sdk) is zapr.

the choice is between logger.Error, logger.Info, logger.V(1).Info. These are Error, Info, and Debug levels accordingly. But there are no means for Warning the end user.

You might be able to use logger.V(-1) to log at the WARN level with the current zapr implementation, but there's an impedance mismatch between what zap and logr support, so the mechanism used by zapr to convert a logr-based level to zap may stop working for non-logr levels at some point in the future.

logger.Error is behaving as it was a controller failure and the stacktrace is included

This is actually something that's bothered me as well. The logger returned by SDK's zap.Logger() sets the stacktrace level based on the --zap-devel flag (here and here).

I've been meaning to add a --zap-stacktrace flag that makes that more customizable, but haven't had the time. Would you be interested in submitting a PR for this?

what is the recommended way to show errors and warnings not related to the Reconciler itself but related to some logic behind processing resources?

If you return an error from the Reconcile() function, controller-runtime will log that error at the error level, so I'd recommend relying on that in those cases.

For errors related to logic processing the resources, are you gracefully handling those errors, or returning them back to the caller of Reconcile()? If the latter, I'd still recommend letting controller-runtime's logger handle it.

If the former, you have some options:

• Use V(-1), if it still works. It did last time I checked.
• Use Info/V(0) level for any underlying errors that are gracefully handled and not returned from Reconcile
• Use WithName to separate logs by name based on whatever section of processing is happening.
• Use your own custom logr implementation (or any other implementation for that matter). Ideally, its format would be compatible with controller-runtime's configured logr, so that log aggregators and analyzers that might be inspecting your operator logs aren't having to deal with different intermingled formats.

[joelanford]

@nrvnrvn Just wanted to follow up to see if I was able to answer your question? I'll go ahead and close this for now, but I can re-open if this needs more discussion.

[nrvnrvn]

@joelanford thanks a lot for your help and clarification. I’ll follow controller-runtime with the logging questions.