anz-bank / pkg Goto Github PK

The Logger interface allows messages to be logged at three levels (debug, info, error), but the level can only be conveyed to Formatter.Format via the LogEntry struct.

Currently the LogEntry struct communicates this information between Logger and Formatter via a boolean field Verbose, which obviously only allows 2 levels to be differentiated.

Is there an intention to extend this API to allow all three levels to be communicated between Logger and Formatter?

Context:
Transactions and Fakerock use the /log pkg for their logging. While the log levels appear as expected in the logs, it seems like they are not correctly interpreted by GCP logging.

• On GCP log console, filtering by SEVERITY>=ERROR or severity=ERROR shows all ERROR, INFO and DEBUG logs(if verbose enabled)
• Filtering on INFO or DEBUG works as expected

Reference:
https://console.cloud.google.com/logs/viewer?interval=NO_LIMIT&project=anz-x-apps-np-e1bb39&minLogLevel=0&expandAll=false&timestamp=2020-05-25T21:48:04.367514516Z&customFacets=&limitCustomFacetWidth=true&advancedFilter=resource.type%3D%22k8s_container%22%0Aresource.labels.project_id%3D%22anz-x-apps-np-e1bb39%22%0Aresource.labels.location%3D%22australia-southeast1%22%0Aresource.labels.cluster_name%3D%22anz-x-apps-np-gke%22%0Aresource.labels.namespace_name%3D%22fabric-services-sit%22%0Aresource.labels.pod_name%3D%22transactions-v085-fzw8v%22%0Aresource.labels.container_name%3D%22transactions%22%0Aseverity%3E%3DERROR&scrollTimestamp=2020-05-25T07:17:55.506941691Z

This has been discussed with @anzboi who will be looking into this.

Example directory is published without godocs:
https://pkg.go.dev/github.com/anz-bank/pkg

Rename example to _example so that directory is ignored by go tools.

Regarding the WithFunc, it was added just for more flexibility should a field value depends on context or anything else.

YAGNI. Can you give a specific example of a problem it solves? I can give an example of a problem it introduces: you've now got a way to get into an infinite loop without really realising it.

fields.WithFunc("foo", func(ctx context.Context) interface{} {
    return util.getValueOfFoo(ctx)
}).Onto(ctx)

// somewhere else, some utility package etc
func getValueOfFoo(ctx context.Context) string {
    log.From(ctx).Info("getting value of foo") // infinite recursion here
    return "bar"
}

Originally posted by @jamesrom in #18 (comment)

In https://github.com/anz-bank/pkg/blob/master/log/util.go#L17 the library will panic if logger isn't created yet. Should the library fail or not?

Currently fields are logged in a random order. Is it important for fields to be sorted?

The health package serves on three http endpoints. This should be captured in an OpenAPI spec. It should capture just the default paths the HTTP server serves on. If an application moves the endpoints, they can copy and update the spec.

All the OS CI for testing and godoc generation

It would be nice to have diffing tool for the godoc to see the impact in documentation

Add test logger for testing the log messages of code. The API needs to be something that can be used to assert values instead of just recording the whole log. Current plan:

1. Have it be able to assert Fields
2. Assert message
3. Assert time (not important but nice to have)
4. Assert codelinker (after #10)
5. Assert level

Have an API that will let users configure their logger.

Part of #5

Need to add a license so that this repo can be documented by pkg.go.dev. Godoc is closing so we need to do this soon.

Need JSON Formatter for logger

The canonical log line is a lightweight pattern where the key information for a request is logged only once at the end of the request.

Some default values should be added (request method, api version, grpc service method name, etc) and perhaps a simple API to register values in the lifetime of the request?

I found a segmentation fault in the health package but I don't have write access to it as I think I need to be added to the anz-bank GitHub org.

The trigger for this segmentation fault is when a race condition between the calls to health.RegisterWithGRPC and health.RegisterWithHTTP results in the second go routine to reach line github.com/anz-bank/pkg/health/default.go#45 to reference a nil pointer if the first go routine has not finished creating the DefaultServer.

An example when this guaranteed to occur is if the first go routine encounters an error creating the default server. In my case I had provided an invalid value for the health.RepoURL field. This problem is compounded by the fact that the seg fault can kill the program before the offending error (the invalid RepoURL field) is logged. The result is a segmentation fault with often no clear cause.

What's the solution?

The simplest (and in my opinion best) solution is to add the following check to the RegisterWithGRPC and RegisterWithHTTP functions:

if DefaultServer == nil {
	return fmt.Errorf("Default server failed to start")
}

I have written a fix but do not have write access to this repo so cannot PR it.

https://github.com/github/linguist#generated-code

A convenience function to help with error handling could be useful.

if err != nil {
    log.From(ctx).Error("Couldn't foo", err)
    return err
}

Should produce something like

msg="Couldn't foo" error_message="connection timed out"

Previously (1ee4e1f), the NewNullLogger method was exported but was used internally to benchmark the standard logger. The NewNullLogger has since been updated to a logger that logs nothing.

This ticket is track the recreation of a suitable logger component for use in benchmarking.

Currently, nullLogger has an internal field that still does some operations so the name nullLogger doesn't fit.

The directory log/_examples contains a main program that uses many (all?) of the features of the log package, and includes a lot of code comments. Those code comments are more detailed/verbose than any of the godocs from what I can see. Additionally, godocs support testable examples that appear in the docs and can be run directly from the docs - see https://blog.golang.org/examples for details.

Rework the examples in log/_examples to be godoc examples.

When done, remove the target from the Makefile that builds the examples, as go test will then build and run the examples.

This will also help by making many smaller targeted examples, rather than one or two big ones that does a bit of everything but does not make a lot of sense together.

Add fields that cannot be changed (or suppressed) after assignment.

Details can be found here https://cloud.google.com/error-reporting/docs/formatting-error-messages

The logging needs to be able to refer to the function or repository that calls the log.

the APIs available to the user

func From(ctx context.Context) Logger { /*…*/ }

func Suppress(keys ...string) Fields                                  { /*…*/ }
func With(key string, val interface{}) Fields                         { /*…*/ }
func WithCtxRef(key string, ctxKey interface{}) Fields                { /*…*/ }
func WithFunc(key string, f func(context.Context) interface{}) Fields { /*…*/ }
func WithLogger(logger Logger) Fields                                 { /*…*/ }

func (Fields) Chain(fieldses ...Fields) Fields                                 { /*…*/ }
func (Fields) From(ctx context.Context) Logger                                 { /*…*/ }
func (Fields) Onto(ctx context.Context) context.Context                        { /*…*/ }
func (Fields) Suppress(keys ...string) Fields                                  { /*…*/ }
func (Fields) With(key string, val interface{}) Fields                         { /*…*/ }
func (Fields) WithCtxRef(key string, ctxKey interface{}) Fields                { /*…*/ }
func (Fields) WithFunc(key string, f func(context.Context) interface{}) Fields { /*…*/ }
func (Fields) WithLogger(logger Logger) Fields                                 { /*…*/ }

// Logger is the underlying logger that is to be added to a context
type Logger interface {
	// Debug logs the message at the Debug level
	Debug(args ...interface{})
	// Debugf logs the message at the Debug level
	Debugf(format string, args ...interface{})
	// Info logs the message at the Info level
	Info(args ...interface{})
	// Infof logs the message at the Info level
	Infof(format string, args ...interface{})
}

and for the internal logger operation unavailable to the users, i'll also make

type internalLoggerOps interface {
	// PutFields returns the Logger with the new fields added
	PutFields(fields frozen.Map) Logger
	// Copy returns a logger whose data is copied from the caller
	Copy() Logger
}

A few reasons as to why we would use 'pkg', to make sure they are captured:

• Approval for working on open source projects may be easier it it's a smaller number of repos
• go imports use the last part of the path as the import name as best practice, so either we would need a package called 'log' in the top level of the repo, which is greedy, or 'go-log', which misses the best practice.

A common method to address the second one is to use an alias server, e.g., gopkg.anz.com/log is a static website with a go get redirect to github.com/anz-bank/log.go or something similar.

The potential downside for using a monorepo for packages is that we end up creating a standard set of libraries which are interdependent and need to be versioned together (as two separate issues possibly?). E.g., if we wrote a 'httpLib' here which logged, it would probably use the pkg/log library. We might add a 'trace' package which the logger and httpLib know to check for certain IDs, then an errors package which httpLib knows to inspect for 'http specific' errors, etc etc. That pattern allows you to create a whole 'world' in which we work, a whole new basis for writing go code, and effectively creates our own highly opinionated ecosystem of go, independent from the wider go community.

I see this as a 'bad thing', but maybe it's not, and maybe that's exactly what we want to create, so raising it here as a ticket so that it's explicitly discussed and decided, rather than accidentally done to solve unrelated problems with go packaging and ANZ policy.

Is there a reason why we need access to the logger directly? Logging is inherently global (stdout is all you need) so I can't think of a strong reason a developer might need direct access to the logger. If there is a reason, we can still expose it such that it hints to the engineer that they really should know what they are doing.

Some other thoughts I have about the existing API:

• From and Onto are a bit obscure, could lead to bugs where a logger is used in the wrong context
• Construction of fields is unintuitive. For example, it's not clear in the API that this wouldn't work:

logger := log.NewStandardLogger()
fields := log.With("greet", "world").WithLogger(logger)
logger.Info("hello")
// expected
// 2020-02-04T09:52:37.844322+11:00 INFO msg=hello greet=world
// got
// 2020-02-04T09:52:37.844322+11:00 INFO hello

• I would like to know the reasoning behind fields.WithFunc. It opens up a class of bugs and accidental misuse that seems far worse than the problem it solves.

With that said, here's my thinking on a simple pragmatic API.

type Fields map[string]interface{}

// Notice how fields are optional
func Debug(ctx context.Context, msg string, fields ...Fields) {}
func Info(ctx context.Context, msg string, fields ...Fields) {}
func Error(ctx context.Context, msg string, fields ...Fields) {}

func Debugf(ctx context.Context, format string, args ...interface{}) {}
func Infof(ctx context.Context, format string, args ...interface{}) {}
func Errorf(ctx context.Context, format string, args ...interface{}) {}

// Convenience function because go doesn't support multi variadic args
func (f Fields) Debugf(ctx context.Context, format string, args ...interface{}) {}
func (f Fields) Infof(ctx context.Context, format string, args ...interface{}) {}
func (f Fields) Errorf(ctx context.Context, format string, args ...interface{}) {}

func AddContextKey(ctx context.Context, key string, ctxKey interface{}) context.Context {}
func AddContextKeys(ctx context.Context, contextKeys Fields) context.Context {}
func AddField(ctx context.Context, key string, value interface{}) context.Context {}
func AddFields(ctx context.Context, fields Fields) context.Context {}

// Not sure we need this, but if we do we can just expose the logrus.Logger
// (otherwise we can reimpl our own logger, but I'm even less sure that's required)
func RawLogger(ctx context.Context) *logrus.Logger {}
func OverrideLogger(ctx context.Context, logger *logrus.Logger) context.Context {}

Example usage

// basic usage
ctx := context.Background()
log.Debug(ctx, "hello")
// msg="hello"

// format string usage
log.Debugf(ctx, "hello %s", "world")
// msg="hello world"

// fields usage
fields := log.Fields{"greet": "world"}
log.Debug(ctx, "hello", fields)
// msg="hello" greet="world"

// fields with format string usage
fields.Debugf(ctx, "hello %s", ":)")
// msg="hello :)" greet="world"

// adding context key
ctx = context.WithValue(ctx, "greet", "world")
ctx = log.AddContextKey(ctx, "greet")
log.Debug(ctx, "hello")
// msg="hello" greet="world"

// adding fields
ctx = log.AddField(ctx, "size", 100)
log.Debug(ctx, "increased size")
// msg="increased size" size=100 greet="world"

I'm willing to be persuaded here. I would love your thoughts.