Better logging (#6038)

[zeripath]

As discussed in #6038 this is an attempt to improve the logging infrastructure of Gitea.

The major change is that the logger now has the ability to log the caller. Flags can be set to change the level of information passed and an expression can be set to restrict loggers - an example would be to set log trace and to only show Trace logs which match.

I have gone through all of the log.Fatals and log.Errors and changed their skip to hopefully set their
caller to refer to the correct place.

Side-by-side comparison of logging by default:

More options

on the left the log configuration section reads:

[log]
REDIRECT_MACARON_LOG = true

on the right it reads:

[log]
REDIRECT_MACARON_LOG = true
ENABLE_ACCESS_LOG = true
ACCESS = console

By default the ACCESS LOG will be redirected to a file so will not be displayed.

If you look carefully the router component doesn't have the same prefixes as the main logger, which is because it has its own logger but it can be redirected to the main logger through: ROUTER = , and similarly for MACARON causing the following logging:

The ACCESS logger can similarly be redirected but because of slightly different architecture it doesn't appear normally and is not recommended.

Stacktraces

By adding STACKTRACE_LEVEL = Error to the [log] section or appropriate subloggers you can add the logging of stacktraces for those levels or above to the logger.

(Note how the Fatal event is now logged.)

SubLoggers

Previously you could configure the different modes of the loggers but you could only have one sublogger for each log provider - so only one type of file log. You can now have multiple file logs, or even multiple console logs.

[log]
MODE = file,file1,file2

[log.file]
FILE_NAME = file.log

[log.file1]
MODE = file
FILE_NAME = trace.log
LEVEL = TRACE

[log.file2]
MODE = file
FILE_NAME = stacktrace.log
STACKTRACE_LEVEL = INFO

Subloggers for Macaron, Router and Access

The macaron, router and access sub loggers can be specifically configured in log sections:

[log.sublogger.macaron]

[log.sublogger.router]

[log.sublogger.access]

Similar to the main gitea loggers, if your sublogger name is the same as a log provider then you don't need to set MODE otherwise you should add it.

Due to the way go-ini will read sections if you do not provide specific sublogger configuration, most information will propogate from [log.sublogger], the exceptions being:

• MODE
• FILE_NAME
• FLAGS
• EXPRESSION
• PREFIX

Expression matching

You can restrict a sublogger to log only events that match a regular expression. You cannot put this expression at the main log configuration, but rather it must be put in the sublogger configuration. E.g.

[log]
LEVEL = TRACE
MODE = file

[log.file]
EXPRESSION = Doing

❯ cat log/gitea.log                                                                                             [11:39:03]
2019/03/28 11:39:04 models/repo.go:2306:CheckRepoStats() [T] Doing: CheckRepoStats
2019/03/28 11:39:04 models/branches.go:464:RemoveOldDeletedBranches() [T] Doing: DeletedBranchesCleanup
2019/03/28 11:39:04 models/repo.go:2090:DeleteOldRepositoryArchives() [T] Doing: ArchiveCleanup

The EXPRESSION will match on the log message with colors removed or the longfilename:linenumber:functionname.

Changing the Flags

Just like the default go logger the preceding flags can be changed. The configuration for this is with the FLAGS setting. Similar to EXPRESSION this setting has to be on the sublogger section itself - this is due to the way that go-ini will default to looking in the parent section. The value of the FLAGS setting is a comma separated list of the flags. The possible flags can be reviewed in modules/log/base.go with the preceding L removed. E.g.:

FLAGS = date,time,levelinitial # no function or filename and line number

The default for most is:

FLAGS = stdflags 
## OR ##
FLAGS = date,time,medfile,shortfuncname,levelinitial

NB: The flags are not ordered. Changing their position in the comma separated list makes no difference.

Colorized logs

Logs can be Colorized with ANSI codes and the console logs will be colorized by default if gitea is not running on Windows, and will be colorized by default on Windows if we successfully set ENABLE_VIRTUAL_TERMINAL_PROCESSING using windows.SetConsoleMode.

This can be overridden with the COLORIZE configuration which can be set at the [log] level.

The values in log events with formatted string values are automatically bolded. This can be changed by looking at modules/log/router

Stderr

You can now send the console log to stderr using STDERR = true

Compression

You can compress the old file logs using COMPRESS = true and set different compression levels using COMPRESSION_LEVEL = -1 -> 9

Access Logger & Router Logger

Most webservers provide a semi-standardised way of logging access to their routes. This format is called the (NCSA) Common Log Format. The current router log does not conform to this standard meaning that common tools will not work on Gitea's logs.

This PR therefore provides a new logger - the Access Log which can be enabled with ENABLE_ACCESS_LOG = true in [log]. This by default logs like the default nginx access.log and will default to logging to log/access.log. You can change the template with ACCESS_LOG_TEMPLATE, which is a go template: {{.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}}" .

The original macaron Router log is still available, and can be disabled with DISABLE_ROUTER_LOG as before, or can remain switched on. You can also change the level it logs at making it at TRACE or DEBUG level - to help with debugging using ROUTER_LOG_LEVEL - although this setting only takes effect if REDIRECT_MACARON_LOG is enabled.

Log Spoofing Prevention

In the previous logging system it could have been possible to spoof log lines by including a newline within the message. This is prevented by tab prefixing all newlines within the message with a \t.

I'm not certain if there was a way to do this - but there was no way to prevent this.

Further ANSI Color strings will not be passed to non-colored logs and other control sequences will be escaped with as a octal values with a preceding \

Old unused configuration removed

There was a possible logger in GOGS 0.83 that would log directly to a database - this functionality was removed in 2016 but the configuration was not removed. I have removed this.

FILE_NAME relative to ROOT_PATH

BREAKING CHANGE

Previously although there was an option called ROOT_PATH in the [log] section. This would set the location of the default named logs but, if you provided a relative FILE_NAME in a [log.file] section Gitea would log relative to the working directory. This has now been fixed.

---

EDIT: This PR original colorized file logs by default - this part was later reverted by #6949

[zeripath]

TODO:

• Fixup the documentation
• Deal with the "GitLogger" it's not entirely clear what this is supposed to do
• Ensure that the changes aren't too breaking.

[zeripath]

Of note this also fixes #5854 - by ensuring that log.Fatal logs before shutting down.

[codecov-io]

Codecov Report

Merging #6095 into master will increase coverage by 0.77%.
The diff coverage is 52.59%.

@@            Coverage Diff             @@
##           master    #6095      +/-   ##
==========================================
+ Coverage    39.4%   40.18%   +0.77%     
==========================================
  Files         393      402       +9     
  Lines       53269    54020     +751     
==========================================
+ Hits        20990    21706     +716     
- Misses      29295    29306      +11     
- Partials     2984     3008      +24

Impacted Files	Coverage Δ
models/u2f.go	63.15% <0%> (ø)	⬆️
routers/admin/admin.go	0% <0%> (ø)	⬆️
routers/repo/http.go	39.78% <0%> (ø)	⬆️
models/admin.go	81.63% <0%> (ø)	⬆️
routers/init.go	68.49% <0%> (ø)	⬆️
models/branches.go	43.33% <0%> (ø)	⬆️
models/migrations/v45.go	0% <0%> (ø)	⬆️
routers/repo/setting.go	10.05% <0%> (ø)	⬆️
modules/util/url.go	69.44% <0%> (ø)	⬆️
models/migrations/v61.go	0% <0%> (ø)	⬆️
... and 97 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ef2a343...6c492fe. Read the comment docs.

[0x5c]

Note for reviewers: it would be nice to check how old (pre win10) windows consoles handle the call to enable the colouring.
Expected behaviour is silent failure to enable the colouring, followed by no colours like before, but it could be ugly if they choke on the call.

I also tested in windows 10, and I can confirm the fantastic results.

[0x5c]

According to this, it shouldn't cause problems (error is handled correctly).

[zeripath]

This code is very common - it turns out that contained also uses very similar format: https://github.com/containerd/console/blob/master/console_windows.go

Therefore I cannot believe that it will throw any unusual behaviour.

@jolheiser I'll switch to the constant now.

[0x5c]

The actual reference implementation code first checks for it being defined (through the system library) , and then defines it if it isn't.

[lunny]

When I enable internal SSH and pull via ssh, I see this log

[Macaron] 2019-04-02 08:59:49: Completed GET /api/internal/repositories/67/user/24/checkunituser?isAdmin=true&unitType=1 200 OK in 5.780271ms
[Macaron] 2019-04-02 08:59:49: Started POST /api/internal/ssh/12/update for [::1]
2019/04/02 08:59:49 [T] ParseOAuth2Token%!(EXTRA *jwt.ValidationError=signature is invalid)

That should be something missing log format changed.

And also, this request is an internal http request, the OAuth2 check should not be applied on that. @jonasfranz

[zeripath]

Hi @lunny. I've already fixed that. I think you must not have built with the PR properly.

(It wasn't the fault of my PR anyway - but rather the OAUTH patch)

[zeripath]

See https://github.com/go-gitea/gitea/pull/6095/files#diff-b34c0e680173ccf8d67d378411a54208R95

[zeripath]

Extensive changes to logging system.