Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Better logging (#6038) #6095

Merged
merged 88 commits into from
Apr 2, 2019
Merged

Better logging (#6038) #6095

merged 88 commits into from
Apr 2, 2019

Conversation

zeripath
Copy link
Contributor

@zeripath zeripath commented Feb 16, 2019

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:

Screenshot from 2019-03-31 23-05-21

More options

Screenshot from 2019-03-31 23-07-55

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:

Screenshot from 2019-03-31 23-09-43

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.

Screenshot from 2019-03-28 11-11-00

(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

Screenshot from 2019-03-28 11-34-58

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
Copy link
Contributor Author

zeripath commented Feb 16, 2019

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.

@GiteaBot GiteaBot added the lgtm/need 2 This PR needs two approvals by maintainers to be considered for merging. label Feb 16, 2019
@zeripath
Copy link
Contributor Author

zeripath commented Feb 16, 2019

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

@codecov-io
Copy link

codecov-io commented Feb 16, 2019

Codecov Report

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

Impacted file tree graph

@@            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.

@techknowlogick techknowlogick added this to the 1.9.0 milestone Feb 19, 2019
@0x5c
Copy link
Contributor

0x5c commented Apr 1, 2019

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
Copy link
Contributor

0x5c commented Apr 1, 2019

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

@zeripath
Copy link
Contributor Author

zeripath commented Apr 1, 2019

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
Copy link
Contributor

0x5c commented Apr 1, 2019

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

@lunny
Copy link
Member

lunny commented Apr 2, 2019

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
Copy link
Contributor Author

zeripath commented Apr 2, 2019

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
Copy link
Contributor Author

zeripath commented Apr 2, 2019

@GiteaBot GiteaBot added lgtm/done This PR has enough approvals to get merged. There are no important open reservations anymore. and removed lgtm/need 1 This PR needs approval from one additional maintainer to be merged. labels Apr 2, 2019
@zeripath
Copy link
Contributor Author

zeripath commented Apr 2, 2019

Extensive changes to logging system.

@zeripath zeripath merged commit 704da08 into go-gitea:master Apr 2, 2019
@zeripath zeripath deleted the better-logging branch April 2, 2019 16:02
@sapk sapk mentioned this pull request Apr 21, 2019
7 tasks
@lunny lunny added the pr/breaking Merging this PR means builds will break. Needs a description what exactly breaks, and how to fix it! label May 14, 2019
@go-gitea go-gitea locked and limited conversation to collaborators Nov 24, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
lgtm/done This PR has enough approvals to get merged. There are no important open reservations anymore. pr/breaking Merging this PR means builds will break. Needs a description what exactly breaks, and how to fix it! type/enhancement An improvement of existing functionality type/refactoring Existing code has been cleaned up. There should be no new functionality.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants