Enable per-reconcile logger customization

[sbueringer]

It would be great if it would be possible to modify loggers for individual reconciles.

Some context:

• When using the standard controller pkg/builder.Builder today you can set a logger which is later adjusted:
  • during Builder.Build():
    • "reconciler group" and "reconciler kind" k/v pairs are added
    • "controller" and "<controller-name>" are added as logger name
    • "controller": "<controller-name>" is added as k/v pair
  • per reconcile in reconcileHandler:
    • "name": "<object-name>", "namespace": "<object-namespace>" k/v pairs are added

The name and the k/v pair are added on top of either the logger provided in the builder or on top of mgr.GetLogger().

We would like to be able to customize the logger according to our requirements. Concrete this means we would like to add a "traceID" and "<kind>": "<namespace>/<name>" k/v pair to the logger (more background info below). We could do this during the Reconcile call, but then the error logged by controller-runtime wouldn't have this context (this one).

As I'm pretty sure there are different opinions about what the name of a logger should look like and which k/v pairs should or shouldn't be added, I would propose to add a "hook" so that folks are able to customize the logger in the way they want.
Also e.g. dropping the current "name"/"namespace" k/v pairs would be a breaking change in controller-runtime.

Background info about "traceID" and "<kind>": "<namespace>/<name>"

• "traceID": we want to be able to correlate logs of an individual reconcile. Furthermore we want to be able to correlate them with traces and metrics in the future
• "<kind>": "<namespace>/<name>": We are trying to follow the upstream Kubernetes structured logging KEP. The KEP standardizes the "value" of the k/v pair to be "'<namespace>/<name>". It doesn't exactly standardize the key of it but in CAPI we will probably follow the examples there and use the lower case singular kind.

I just wanted to provide this as background information. I think the discussion if this is a good or bad idea is out-of-scope (and still TBD in the CAPI project). But I think it should illustrate that it's worth making the logger customizable, so it's possible to accommodate requirements like this.

I've opened the following PR to illustrate how a solution could look like:

• CR: [WIP] 🌱 Enable per-reconcile logger customization #1812
• CAPI (very-WIP): https://github.com/kubernetes-sigs/cluster-api/pull/6150/files#r808443915

[sbueringer]

/cc @alvaroaleman @fabriziopandini @vincepri
(of course feel free to cc other folks, not sure who else would want to be cc'ed)

[sbueringer]

Additional note about the trace use case:

I think we won't be able to create the traceID at that point when we actually use tracing, because we have to create a trace span like this:

	ctx, span := tracer.Start(ctx, "Reconcile")
	defer span.End()

This has to be inside of the Reconcile function because of the defer. As we don't want to pull the traceID out of the logger we've customized before, we have to create the span in Reconcile and then add the TraceID to the logger there.

But I think the use case about "<kind>": "<namespace>/<name>" k/v pair still applies (as we don't want the "name" and "namespace" k/v pair).

Is there potentially a way to make the error logging after reconcile optional (enabled per default)? (https://github.com/kubernetes-sigs/controller-runtime/blob/master/pkg/internal/controller/controller.go#L317)

It would be really great if we would be able to log the error in our Reconcile func with the full log context, without ending up with the error logged twice.

[vincepri]

Could we consider starting the trace within Controller Runtime (other folks might want to use this as well) and inject it into the context?

[sbueringer]

Could we consider starting the trace within Controller Runtime (other folks might want to use this as well) and inject it into the context?

I think that is reasonable. Although I would like to think about tracing specifically a bit more before proposing that and then open a new separate issue. But I think it should be fine to treat tracing as a separate topic and focus here on the log customization as it's (at least in my opinion) still a reasonable improvement independent of tracing.

[sbueringer]

I'll open a new with an alternative proposal, i.e. just changing the logging in CR vs. making it customizable.

Let's hold this issue for now.

[sbueringer]

/close
in favor of #1826

[k8s-ci-robot]

@sbueringer: Closing this issue.

In response to this:

/close
in favor of #1826

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.