Enhanced logging #172

guicassolato · 2021-10-18T12:03:17Z

Adds better log levels and log configuration.

Support for log levels (debug → info → error)
Configurable log modes: production, development
No sensitive data output to info log messages
Log tracing ID
Documentation: descriptions of log messages, extra values included and samples
Logging guidelines for developers

Check the added docs page for details about how the log messages look like, limitations regarding sensitive data obfuscating, and log configuration options.

Closes #12 and #161

pkg/common/log/log.go

pkg/config/authorization/kubernetes_authz.go

eguzki · 2021-10-19T10:14:11Z

This is looking good, aligns with logging options offered by controller runtime loggers.

I think whatever it comes out of this, it should be used as pattern for other kuadrant controllers.

This is useful so parsers can focus in either one log level or the other, without missing info when switching levels. Debug version of these log messages continue to include extra info, both about the request and response.

[fix] avoid panicking when the uri is insufficient to find a wristband config in the cache

eguzki · 2021-10-20T09:08:33Z

controllers/auth_config_controller.go

 	return ctrl.Result{}, nil
 }

-func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConfig *configv1beta1.AuthConfig) (map[string]authorinoService.APIConfig, error) {
+func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConfig *configv1beta1.AuthConfig, logger log.Logger) (map[string]authorinoService.APIConfig, error) {


shouldn't be logr.Logger type?

We're using ours instead. Again, the same pattern of abstraction under a layer we control. "github.com/kuadrant/authorino/pkg/common/log".Logger == "github.com/go-logr/logr".Logger

eguzki · 2021-10-20T09:26:24Z

main.go

@@ -62,13 +63,17 @@ var (
 	oidcHTTPPort       = common.FetchEnv("OIDC_HTTP_PORT", "8083")
 	oidcTLSCertPath    = common.FetchEnv("OIDC_TLS_CERT", "")
 	oidcTLSCertKeyPath = common.FetchEnv("OIDC_TLS_CERT_KEY", "")
+
+	logger = log.NewLogger(log.Options{Level: log.ToLogLevel(logLevel), Mode: log.ToLogMode(logMode)}, nil).WithName("authorino")


while I think it is ok, it is not needed to have a global var used for the main package. It is being set in the init, so any function in this package is safe to get the logger as

log.Log.Error(...)

pkg/common/log/log.go

eguzki · 2021-10-20T09:28:45Z

pkg/common/log/log.go

+	Log = logger
+	Level = opts.Level
+
+	ctrl.SetLogger(logger) // fulfills `logger` as the de facto logger used by controller-runtime


TBH I am not sure about this, but let's give it a try.

"SetLogger" means:

to set the singleton (which is used, as a base logger, in a few places where I chose not to inject a previously configured logger in the stack call)

to set whatever delegation logger being used by any dependency that we know of (controller-runtime and klog in our case)

If we don't ctrl.SetLogger(logger), some log entries generated deep down by controlller-runtime would either be skipped (due to null logger set by default) or be printed on a different format (not as JSON, missing "authorino." in the logger's name, etc).

I actually ran into this with klog, that prints leader election-related logs. While most entries were being formatted as configured, klog's ones were leaking completely unformatted.

eguzki · 2021-10-20T09:40:18Z

pkg/common/log/log.go

+}
+
+// configuredLogger is a delegation logger that holds information about the log options.
+type configuredLogger struct {


I understand that the purpose of this new configuredLogger struct is to keep the options for later use. Is it being used?

Correct. Other than that, it's just a delegation logger.

eguzki · 2021-10-20T10:21:13Z

pkg/common/log/log.go

+	// It is useful for checking the log level in the code and avoid expensive
+	// tasks only required for some specific levels.
+	// It is setup by the `SetLogger` function.
+	Level LogLevel


Not sure this is even needed.

As you know, the logr.Logger interface, has this Enabled() method. It is not useful to get the actual log level option of a logger instance, but can tell if a logger instance is being enabled or not.

myLogger = log.Log fmt.Println(myLogger.Enabled()) // true when log level set to debug or info myDebugLogger = myLogger.V(1) fmt.Println(myDebugLogger.Enabled()) // true when log level set to debug

we are using in the kuadrant controller:
https://github.com/Kuadrant/kuadrant-controller/blob/145657005a3a64676281a3799e118c24d47bea83/controllers/apiproduct_controller.go#L70

You are totally right. Good catch!

Added 4f0fe1c.

pkg/config/metadata/generic_http.go

No need to store log level. We can use `logr.Enabled()`.

eguzki · 2021-10-21T09:04:50Z

pkg/config/authorization.go

 	switch {
 	case config.OPA != nil:
-		return config.OPA.Call(pipeline, ctx)
+		return config.OPA.Call(pipeline, ctx, logger)


@guicassolato another option would be to inject the logger in the context.

Check https://github.com/kubernetes-sigs/controller-runtime/blob/1462c6e3a5dbe3b04d11286b190253c845c8e338/pkg/log/log.go#L85

func FromContext(ctx context.Context, keysAndValues ...interface{}) logr.Logger

and

func IntoContext(ctx context.Context, log logr.Logger) context.Context

@eguzki , please tell me if it's better now. 9eb2fa5

…e stack

…log message (object was being stringified)

guicassolato self-assigned this Oct 18, 2021

guicassolato requested a review from a team October 18, 2021 12:08

eguzki reviewed Oct 19, 2021

View reviewed changes

pkg/common/log/log.go Outdated Show resolved Hide resolved

pkg/common/log/log.go Outdated Show resolved Hide resolved

pkg/config/authorization/kubernetes_authz.go Outdated Show resolved Hide resolved

guicassolato added 4 commits October 19, 2021 12:58

Enhanced log messages and configuration

4eb92c8

Log trace id

a600494

[docs] Logging

b541fff

guicassolato force-pushed the log-levels branch from 493db74 to b541fff Compare October 19, 2021 10:58

guicassolato added 3 commits October 20, 2021 08:27

Loggers injected along the call stack

f2e3736

Rename log.Debug() -> log.IsDebug()

bd150ac

Request/response info log messages for the oidc service

3aab319

[fix] avoid panicking when the uri is insufficient to find a wristband config in the cache

guicassolato force-pushed the log-levels branch from a146248 to 3aab319 Compare October 20, 2021 06:31

guicassolato requested a review from a team October 20, 2021 09:01

eguzki reviewed Oct 20, 2021

View reviewed changes

log.Level removed

4f0fe1c

No need to store log level. We can use `logr.Enabled()`.

guicassolato requested a review from a team October 20, 2021 16:43

eguzki previously approved these changes Oct 21, 2021

View reviewed changes

eguzki reviewed Oct 21, 2021

View reviewed changes

guicassolato added 2 commits October 21, 2021 14:12

Added .vscode to .(git|docker)ignore

1ed85e1

Logger injected in the context instead of propagated directly into th…

9eb2fa5

…e stack

guicassolato dismissed eguzki’s stale review via 9eb2fa5 October 21, 2021 12:13

eguzki previously approved these changes Oct 21, 2021

View reviewed changes

guicassolato dismissed eguzki’s stale review via 91f84e0 October 21, 2021 15:38

Some polishing + bug fix in the incoming authorization request debug …

ce80aea

…log message (object was being stringified)

guicassolato force-pushed the log-levels branch from 91f84e0 to ce80aea Compare October 21, 2021 15:49

eguzki approved these changes Oct 21, 2021

View reviewed changes

guicassolato merged commit 6e741f7 into main Oct 21, 2021

guicassolato deleted the log-levels branch October 21, 2021 16:17

jjaferson mentioned this pull request Nov 9, 2021

Migrate to use the same logging system as Authorino Kuadrant/authorino-operator#5

Closed

jjaferson mentioned this pull request Nov 18, 2021

Adds LOG_LEVEL and LOG_MODE to authorino deployment Kuadrant/authorino-operator#8

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enhanced logging #172

Enhanced logging #172

guicassolato commented Oct 18, 2021 •

edited

Loading

eguzki commented Oct 19, 2021

eguzki Oct 20, 2021

guicassolato Oct 20, 2021

eguzki Oct 20, 2021

eguzki Oct 20, 2021

guicassolato Oct 20, 2021 •

edited

Loading

eguzki Oct 20, 2021

guicassolato Oct 20, 2021

eguzki Oct 20, 2021

guicassolato Oct 20, 2021

eguzki Oct 21, 2021

guicassolato Oct 21, 2021

eguzki Oct 21, 2021

Enhanced logging #172

Enhanced logging #172

Conversation

guicassolato commented Oct 18, 2021 • edited Loading

eguzki commented Oct 19, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

guicassolato Oct 20, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

guicassolato commented Oct 18, 2021 •

edited

Loading

guicassolato Oct 20, 2021 •

edited

Loading