[Epic] Refactor: Logging system

[jsimnz]

Need to review the entire logging workflow/implementation for the database. Currently use a few randomly initialized global scoped loggers on various packages.

We should define a single logger instance during DB initialization, and propogate that logger to all the sub components. This can be propogated using the new context arguments everywhere.

Child issues:

• Implement new logging system #218
• Use new logger in db package #233
• Use new logger in query package #235
• Remove println from core package #237
• Use new logger in merkle package #239
• Consider banning fmt.Println* via linter rule #242
• Use new logger in net package #243
• Use new logger in node package #245
• Use new logger in store package #247
• Use new logger in http package #249
• Stop benchmarks from spamming logs #260

[jsimnz]

Logging refactor thoughts.

It will inherit design/implementation from https://github.com/ipfs/go-log

Implement a logging package, that defines a clean interface:

type Logger interface {
	Debug(ctx context.Context, args ...interface{})
	Debugf(ctx context.Context, format string, args ...interface{})
	Error(ctx context.Context, args ...interface{})
	Errorf(ctx context.Context, format string, args ...interface{})
	Fatal(ctx context.Context, args ...interface{})
	Fatalf(ctx context.Context, format string, args ...interface{})
	Info(ctx context.Context, args ...interface{})
	Infof(ctx context.Context, format string, args ...interface{})
	Panic(ctx context.Context, args ...interface{})
	Panicf(ctx context.Context, format string, args ...interface{})
	Warn(ctx context.Context, args ...interface{})
	Warnf(ctx context.Context, format string, args ...interface{})
}

With this, we define a package level global variable. If the package is called query then, we should have a query.go file within it that defines the package level logger.

Loggers are named when instanciated

var (
    log = logging.NewLogger("<logger_name>")
)

We should standardize the format to use for the logger name. Right now, a few packages within defra have migrated to a similar logger structure (without the context.Context first parameter).

A few packages so far are, net, merkle/clock, merkle/crdt, cli, db, net, node. However, they all use different naming conventions for their loggers.

Various options are namespace with / (slashes) or . (dots) IE: defra.cli, defra/cli
or we just use the package name directly IE: net, clock.

The benefit of the extra context.Context parameter is to be able to pass various "LogTags" or k/v pairs to be included with the log message. This can be anything thats relevant to a series of log calls, like request IDs, processIDs, etc.

Example

func foo(ctx context.Context) {
    ...
    ctx = logger.WithTag(ctx, "requestID", "abc")
    log.Info(ctx, "Some work") // prints: [INFO] requestID=abc | Some work
    bar(ctx)
}

func bar(ctx context.Context) {
    ...
    log.Debug(ctx, "Other work") // prints: [DEBUG] requestID=abc | Other work
}

We can see here that we extended our context object with a log tag, which is persisted to all followup calls to any log function that uses the same context object. In our example, we added a log tag in foo() and called bar() with the new context, and our defined requestID tag is present on both calls.

This also ensures that we are only logging from functions that accept a context object, which most simple utility functions don't accept as a parameter, so we ensure we are logging in meaningful functions only.

[AndrewSisley]

At risk of over-engineering early on (is a pain to move to this later though, as it would involve re-writing formatted messages), would suggest instead of a sprintf type format we only accept a string constant, and a map of key-value pairs (plus ctx for more long lived kvps) - keeping the log messages as constant string, plus a set of key value pairs can make the logs much much easier to search/aggregate and a lot of 3rd party services have a decent amount of support for working with such a setup.

e.g.:

log.Info(ctx, "Field not found", map[string]interface{}{"DocKey": "baefgnjdgsjngsng", "FieldName": "name"}) 
// DocKey and FieldName should be constants defined somewhere
// prints: [INFO] requestID=abc | Field not found | DocKey: baefgnjdgsjngsng, FieldName: name

Would also suggest that requestId gets shoved on the end with the rest, resulting in:

// prints: [INFO] [TIMESTAMP] | Field not found | RequestID: abc, DocKey: baefgnjdgsjngsng, FieldName: name

With an interface:

type Logger interface {
	Debug(ctx context.Context, message string)
	Debugf(ctx context.Context, message string, keyValues map[string]interface{})
	Info(ctx context.Context, message string)
	Infof(ctx context.Context, message string, keyValues map[string]interface{})
	Warn(ctx context.Context, message string)
	Warnf(ctx context.Context, message string, keyValues map[string]interface{})
	Error(ctx context.Context, message string)
	Errorf(ctx context.Context, message string, keyValues map[string]interface{})
	Fatal(ctx context.Context, message string)
	Fatalf(ctx context.Context, format string, keyValues map[string]interface{})
	Panic(ctx context.Context, message string)
	Panicf(ctx context.Context, message string, keyValues map[string]interface{})
}

Dont know if there is a golang function naming convention for this (instead of the 'f' suffix which doesn't quite fit here), Debug and Debugf would have the same name in C#.

Would also suggest we drop either Debug or Info, as the line between the two is super blurry and I would probably drop both to save code and log clutter from drowning out useful information (although I know I lean that way more than most so I guess we can't drop both :))

Would also ask about the difference between Fatal and Panic?

[jsimnz]

type Logger interface {
....
Infof(ctx context.Context, message string, keyvals ...interface{})
}

called with

func foo(ctx context.Context) {
    log.Infof(ctx, "Hello World", "requestID", "abc", "fieldName", "age")
}

[jsimnz]

type Logger interface {
....
Infof(ctx context.Context, message string, keyvals ...logging.KV)
}

func foo(ctx context.Context) {
    log.Infof(ctx, "Hello World", logging.KV{"requestID", "abc"}, logging.KV("fieldName", "age"))
}

[jsimnz]

func foo(ctx context.Context) {
    log.Infof(ctx, "Hello World", []logging.KVs{{"requestID", "abc"}, {"fieldName", "age"}}...)
}

[jsimnz]

[jsimnz]

https://github.com/uber-go/zap

[jsimnz]

[jsimnz]

For reference: https://github.com/ipfs/go-log