Add DEBUG level logging?

[aschrijver]

This feedback is based on my apcore example installation experience.

An example of log output of ./example init-db:

INFO : 2021/01/08 22:07:35.717756 app.go:88: Templates found:
INFO : 2021/01/08 22:07:35.717824 app.go:90: header.tmpl
INFO : 2021/01/08 22:07:35.717836 app.go:90: inline_css.tmpl
INFO : 2021/01/08 22:07:35.717843 app.go:90: list_users.tmpl
INFO : 2021/01/08 22:07:35.717850 app.go:90: 
INFO : 2021/01/08 22:07:35.717857 app.go:90: auth.tmpl
INFO : 2021/01/08 22:07:35.717865 app.go:90: not_found.tmpl
INFO : 2021/01/08 22:07:35.717872 app.go:90: note.tmpl
INFO : 2021/01/08 22:07:35.717880 app.go:90: list_notes.tmpl
INFO : 2021/01/08 22:07:35.717889 app.go:90: nav.tmpl
INFO : 2021/01/08 22:07:35.717900 app.go:90: create_note.tmpl
INFO : 2021/01/08 22:07:35.717917 app.go:90: home.tmpl
INFO : 2021/01/08 22:07:35.717925 app.go:90: inbox.tmpl
INFO : 2021/01/08 22:07:35.717932 app.go:90: internal_error.tmpl
INFO : 2021/01/08 22:07:35.717939 app.go:90: login.tmpl
INFO : 2021/01/08 22:07:35.717945 app.go:90: not_allowed.tmpl
INFO : 2021/01/08 22:07:35.717951 app.go:90: outbox.tmpl
INFO : 2021/01/08 22:07:35.717959 app.go:90: user.tmpl
INFO : 2021/01/08 22:07:35.717965 app.go:90: bad_request.tmpl
INFO : 2021/01/08 22:07:35.717971 app.go:90: followers.tmpl
INFO : 2021/01/08 22:07:35.717977 app.go:90: following.tmpl
INFO : 2021/01/08 22:07:35.717982 app.go:90: footer.tmpl

Lotsa output. The individual templates loading might be DEBUG level info, giving with loglevel == INFO:

INFO : 2021/01/08 22:07:35.717756 app.go:88: Loading templates from './templates'...
INFO : 2021/01/08 22:07:35.717998 app.go:90: Templates successfully loaded.

Another example:

INFO : 2021/01/08 23:16:31.181139 config.go:123: Loading config file: config.ini
INFO : 2021/01/08 23:16:31.181839 db.go:84: Postgres database configuration
INFO : 2021/01/08 23:16:31.181868 db.go:46: Calling sql.Open...
INFO : 2021/01/08 23:16:31.182496 db.go:51: Calling sql.Open complete
INFO : 2021/01/08 23:16:31.182511 db.go:65: Database connections configured successfully
INFO : 2021/01/08 23:16:31.182522 db.go:66: NOTE: No underlying database connections may have happened yet!

Possible output with loglevel == DEBUG:

INFO : 2021/01/08 23:16:31.181139 config.go:123: Using configuration file: ./config.ini
INFO : 2021/01/08 23:16:31.181839 db.go:84: Applying Postgres database configuration...
DEBUG : 2021/01/08 23:16:31.181868 db.go:46: Calling sql.Open...
DEBUG : 2021/01/08 23:16:31.182496 db.go:51: Calling sql.Open complete
INFO : 2021/01/08 23:16:31.182511 db.go:65: Database connections configured successfully.
DEBUG : 2021/01/08 23:16:31.182522 db.go:66: NOTE: No underlying database connections may have happened yet!

Note: Made some changes to log message style. TBD... E.g. if you log a "Loading..." msg, should it be followed by a "Loaded [success]" msg?

[cjslep]

I like the idea. I hadn't pursued it yet because:

1. Golang tends to rely on global logging variables
2. Golang tends to have separate os.StdErr and os.StdOut loggers
3. Other libraries I've found add yet more loggers (for different levels) or have other behaviors that are weird to set up

I haven't found a satisfactory approach, hence the current "verbose everywhere" in lieu of a good strategy.

Thoughts?

[cjslep]

Note: I am also branching this from #56:

2. Script output

Most of the INFO logging (application output) is too much to be part of the script output. I'd consider adding some additional script logging e.g. "Loading templates..." and then have a verbose -v flag to show INFO e.g. "Templates found..".

(Additionally - different issue - there's the question to separate INFO + DEBUG output, e.g. for the latter "Calling sql.Open...")