Proposal: Better logging infrastructure

[zeripath]

Description

Although our logging infrastructure is quite configurable and better than the original Go logging, it could be better.

There are three main issues at present:

1. Any use of go "log.Printf" (rather than "code.gitea.io/modules/log") will log to stdout by default - In the case of Macaron this can be ameliorated by REDIRECT_MACARON_LOG - however, there are likely other places

• A sub-issue is that log.Fatal will kill Gitea...

2. The Router logs are not in the NCSA Common Log format, and are not configurable to be so. This means that we cannot leverage external tools to use this.
3. It is not possible to set different log levels for different gitea modules. Thus setting the log level to TRACE will lead to massive amounts of difficult to follow logging.

Proposals

Redirect the standard logger output to "gitea.log"

Through the use of log.SetOutput, log.SetPrefix and log.SetFlags with appropriate options - we could then reparse the output and re-log ourselves as appropriate.

Configurable NCSA Common Log Format for the Router

This is fixable through the use of a different logger, say log.NewAccessLogger, which has no flags set and with a potentially configurable template.

defaultTemplate := "{{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format \"[02/Jan/2006:15:04:05 -0700]\" }} \"{{.Ctx.Req.Method}} {{.Ctx.Req.RequestURI}} {{.Ctx.Req.Proto}}\" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} \"{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}\""

type ncsaLoggerOptions struct {
	Ctx            *macaron.Context
	Identity       *string
	Start          *time.Time
	ResponseWriter *macaron.ResponseWriter
}

func ncsaLogger() macaron.Handler {
	log.NewAccessLogger(filepath.Join(setting.LogRootPath, "access.log"))
	l := log.NewLoggerAsWriter("INFO", log.AccessLogger)
	logTemplate, _ := template.New("log").Parse(defaultTemplate)
	return func(ctx *macaron.Context) {
		start := time.Now()
		ctx.Next()
		identity := "-"
		if val, ok := ctx.Data["SignedUserName"]; ok {
			if stringVal, ok := val.(string); ok && stringVal != "" {
				identity = stringVal
			}
		}
		rw := ctx.Resp.(macaron.ResponseWriter)

		buf := bytes.NewBuffer([]byte{})
		logTemplate.Execute(buf, ncsaLoggerOptions{
			Ctx:            ctx,
			Identity:       &identity,
			Start:          &start,
			ResponseWriter: &rw,
		})
		l.Log(buf.String())
	}
}

TRACE/DEBUG etc. for specific modules/packages/files

Through judicious use of runtime.Caller(), runtime.FuncForPC() and Func.Name() it should be possible to get the function name and go package for callers to log functions. Instead of making the log channel simply pass a level and a string message it could be changed to also pass the function or filename name - allowing individual loggers to check if it should log these.

I'm uncertain as to the cost of touching runtime.Caller() etc., however, it is unlikely to be a major cost unless we're logging too much. We could add IsDebug etc to the loggers to allow us to know check whether we would do any Debug/Tracing for any file to avoid having to look up the caller stack at all.

Configuration

Of course, configuration of this will require some thought.

It should be clear that at present that the XORM logger and the REDIRECT_MACARON_LOG options different beasts to those of the other log options. If we were to do this we would need a general log section dealing with these sort of special case loggers and specific gitea logger sections. (I think this can already be done?)

• We would need to add configuration for the templated router logger - passing in a template, setting the output file, and switching it on.
• In each logger section we would need configuration to match the chosen modules etc.

Summary

The proposed changes substantially complicate logging however, provide much more power. It should be possible to make these changes in a backwards compatible way.