[RFC] Logging improvements

[aghoulcoder]

Problem

Currently the stash-box code is littered with these error handling conditionals that fail silently, without propagating the error through the return and without logging.

ret, err := somefunction()
if err != nil {
    return
}

As a result, investigating even the simplest failures in production is difficult. (e.g. was an email sent or did it fail? Why are favicons not saved when I create a site? etc...)
Instead, all these failures should be logged.

Current situation

stash-box currently has a logger package package. But it has several issues:

1. It's not used very much. These are all the instances where it is used.

   pkg/database/postgres.go:79:	logger.Debugf("Migration: "+format, v...)
   pkg/models/sqlite_date.go:42:		logger.Debugf("date conversion error: %s", err.Error())
   pkg/models/sql_translate.go:19:		logger.Errorf("Target must be pointer")
   pkg/models/sql_translate.go:28:		logger.Errorf("source must be value")
   pkg/manager/cron/cron.go:25:		logger.Debug("Edit cronjob failed to start, already running.")
   pkg/manager/cron/cron.go:31:		logger.Errorf("Edit cronjob failed to fetch completed edits: %s", err.Error())
   pkg/manager/cron/cron.go:35:	logger.Debugf("Edit cronjob running for %d edits", len(edits))
   pkg/manager/cron/cron.go:52:			logger.Errorf("Edit cronjob failed to apply edit %s: %s", e.ID.String(), err.Error())
   pkg/manager/cron/cron.go:73:		logger.Errorf("Error cleaning drafts: %s", err)
   pkg/manager/cron/cron.go:94:		logger.Debugf("Edit cronjob initialized to run every %s", interval)
   pkg/manager/manager.go:93:		logger.Infof("failed to bind flags: %s", err.Error())
   pkg/api/server.go:80:					logger.Error(err)
   pkg/api/server.go:136:		logger.Error(err)
   pkg/api/server.go:180:			logger.Infof("profiler is running at http://localhost:%d/", *config.GetProfilerPort())
   pkg/api/server.go:201:			logger.Infof("stash-box is running on HTTPS at https://" + address + "/")
   pkg/api/server.go:212:			logger.Infof("stash-box is running on HTTP at http://" + address + "/")
   

2. It's partially undocumented. The logFile and logLevel config options are not documented in the README.md.

3. Logger is initialized after the config file is parsed, so configuration errors are logged with the errors package from the standard library.
   

   stash-box/pkg/manager/manager.go

   Lines 33 to 44 in 914f67b

   	func Initialize() *singleton {
   	once.Do(func() {
   	initFlags()
   	initConfig()
   	initLog()
   	instance = &singleton{
   	EmailManager: email.NewManager(),
   	}
   	})
   	return instance
   	}

4. Logger is built around github.com/sirupsen/logrus which is no longer being developed. There are likely better packages for structured logging, some of which are recommended in logrus' README.

Solutions?

The simplest thing would be to start adding logger.Debug() calls in all those error handling conditionals throughout the code. But, one problem I noticed is that there's no call trace with this approach which makes it difficult to understand the context of the error. This is something that friendsofgo/errors accomplices with their Wrap method. EDIT: This is now part of the errors package of the go standard library.
EDIT2: There have also been improvements to the log package of the standard library.

I'm no expert in Go's logging options so I don't feel confident in proposing a solution yet. But I am interested in helping improve the logging situation. Therefore, I would appreciate any pointers for how to go about this.

[aghoulcoder]

Today I learned that error joining and unwrapping was added in go 1.13 and the stash-box logger package was written when stash-box was using go 1.12. Just making a note here for myself.

[aghoulcoder]

watching this now...
A consistent logging format for Go - Google Open Source YoutTube

[WithoutPants]

Currently the stash-box code is littered with these error handling conditionals that fail silently, without propagating the error through the return and without logging.
...
Instead, all these failures should be logged.

Agree. A PR should be made to amend these to either return the error (with context if possible) or log them to the Error level.

It's not used very much. These are all the instances where it is used.

This one is a bit harder to implement generally. Debug-level logging should be added where useful and necessary. My go-to method is to add debug-level logging in whatever code I'm working in as needed (rather than trying to add debug level logging everywhere at once).

It's partially undocumented. The logFile and logLevel config options are not documented in the README.md.

Agree. This can be done pretty easily.

Logger is initialized after the config file is parsed, so configuration errors are logged with the errors package from the standard library.

I don't really see an issue with this. Configuration errors as far as I can tell should cause a panic during the initialisation process, which should give enough information for the user to fix the issues with the config.

Logger is built around github.com/sirupsen/logrus which is no longer being developed. There are likely better packages for structured logging, some of which are recommended in logrus' README.

Not a huge issue. It works and afaik isn't causing any major issues. In stash I generalised the public logger interface and made the implementation in an internal package and initialised it during startup. I think this is fairly low priority though.

The simplest thing would be to start adding logger.Debug() calls in all those error handling conditionals throughout the code.

As mentioned at the top, where an error only needs to be logged, then it should generally be logged at the error log-level. Each instance however should be assessed as to whether it should only be logging or whether it should be kicking the error up the chain to be handled upstream.