Logging

[enrichman]

Ok, this is a broad topic, so I will try to focus only on specific things!

Error messages

We are missing them. That's a big problem while debugging, or trying to understand what's going on (#1130)

Anyway, at the end I've found what we were missing, basically in order to be logged by the Gin formatter we should add the errors in the Gin context with the c.Error

Adding this to the Error response will fix it, I will open a PR.

Levels

This is quite confusing. In logr the verbosity is additive so a level 0/1 is for important stuff, and also in the errorHandler we can see that probably the V(1) was meant to be used to log the error

func errorHandler(action APIActionFunc) gin.HandlerFunc {
	return func(c *gin.Context) {
		if errors := action(c); errors != nil {
			tracelog.Logger(c.Request.Context()).V(1).
				Info("responding with json error response", "action", funcName(action), "errors", errors)
			response.Error(c, errors)
		}
	}
}

but if we have a look at the log we are actually logging to level 2

2022/02/10 08:56:54 fallback: "level"=2 "msg"="responding with json error response" "action"="github.com/epinio/epinio/internal/api/v1/application.Controller.Stage-fm" "errors"="thi was on porpouse"

and the logger was actually a fallback (// this should not happen, but let's be cautious)

// Logger returns the logger from the context, the server injects a logger into
// each request.
func Logger(ctx context.Context) logr.Logger {
	log, ok := ctx.Value(CtxLoggerKey{}).(logr.Logger)
	if !ok {
		// this should not happen, but let's be cautious
		return NewLogger().WithName("fallback")
	}
	return log
}

I'm not sure on how we should handle this but I would like to propose to avoid to use the int levels and just log with the Info or Error. If we need to have a Debug level (probably yes) I would implement a specific method to get a logger with increased level, but "fixed", so we know that we can rely on the fact that the Debug logger will have a value of 2, and that maybe a Trace logger will have a level of 5.

Trace/Request ID

I've seen that we are missing a trace or request ID that is very useful to trace and correlate logs of the same request. Probably this was not felt as a need because we are still in an early development phase, and there are no concurrent requests.

Log format

At the moment we have two format (as far as I've seen), the one used by the stdr logger with logr and the one used by the Gin formatter.
I would choose one between the twos:

2022/02/10 08:56:54 fallback: "msg"="ERROR" "error"="thi was on porpouse" "origin"="/api/v1/namespaces/workspace/applications/samplejava/stage" "error"="thi was on porpouse"
Method: POST | Path: /api/v1/namespaces/workspace/applications/samplejava/stage | User: admin | IP: 10.42.0.1 | Timestamp: 2022-02-10T08:56:54Z | Latency: 1.984465ms | Status: 400 | Message: Error #01: thi was on porpouse  

[andreas-kupries]

We might be able to influence gin logging by changing the argument of gin.SetMode(gin.ReleaseMode).
That said, IIRC release mode is already the minimal logging. Debug mode will log more.
I do not remember if there is a mode to disable it entirely.

[andreas-kupries]

... googled ... https://pkg.go.dev/github.com/gin-gonic/gin#pkg-constants lists the possibilities (release, debug, test). Does not look like we can switch logging off entirely, at least not via setmode.

[enrichman]

How the mode affect the logging? I'm not familiar with Gin. is it something that you have to handle checking it at runtime maybe?

[andreas-kupries]

IIRC it affects the amount of logging done by gin. In debug mode, for example, it prints the list of all endpoints known to it, possible with handler information, as part of server startup. I never used test mode, so no idea what this activates.

[manno]

This is where we create the request ID, I remember it was in the logging previously: https://github.com/epinio/epinio/blob/main/internal/cli/server/server.go#L271

[enrichman]

Ah, yes. As written in the other comment we are not actually retrieving the logger from the context, and probably we are never initialize it in the requests.

[manno]

The go-logr is using non-descriptive log levels by design. If you want to log at a certain absolute level you can use logger.V(15).Enabled() (e.g.: https://github.com/epinio/epinio/blob/main/internal/cli/server/server.go#L98-L102)

+1 to using the Gin logger more in the server.

[enrichman]

Hm, I don't think that's correct. If the passed logger has already a different level (i.e. 20) then the V(15) will return a new logger with a level 35, that will not log for a trace set up to 20.

By the way I don't think we overwrite the logger in the context, or I don't see even any place where we actually initialize it, so we are everytime asking for a new Logger (that's where the fallback is coming from).

I don't think that a "ginLogger" exists, it just use the standard output with a custom formatter, if I'm not wrong: https://github.com/epinio/epinio/blob/main/internal/cli/server/server.go#L34