From 17b698b854b9fa3c770d6ff29ee00fe4011f46ca Mon Sep 17 00:00:00 2001 From: Keepers Date: Mon, 6 Feb 2023 18:32:09 -0700 Subject: [PATCH] logging standards examples (#2411) ## Description Adds an example set to the logging for logging code standards guidance. ## Does this PR need a docs update or release note? - [x] :no_entry: No ## Type of change - [x] :world_map: Documentation ## Issue(s) * #1970 ## Test Plan - [x] :zap: Unit test --- src/go.sum | 2 - src/pkg/fault/example_fault_test.go | 48 ++++++++++ src/pkg/logger/example_logger_test.go | 125 ++++++++++++++++++++++++++ website/docs/developers/logging.md | 3 + 4 files changed, 176 insertions(+), 2 deletions(-) create mode 100644 src/pkg/logger/example_logger_test.go create mode 100644 website/docs/developers/logging.md diff --git a/src/go.sum b/src/go.sum index 566adbca0..d3c038ca4 100644 --- a/src/go.sum +++ b/src/go.sum @@ -52,8 +52,6 @@ github.com/VividCortex/ewma v1.2.0 h1:f58SaIzcDXrSy3kWaHNvuJgJ3Nmz59Zji6XoJR/q1o github.com/VividCortex/ewma v1.2.0/go.mod h1:nz4BbCtbLyFDeC9SUHbtcT5644juEuWfUAUnGx7j5l4= github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d h1:licZJFw2RwpHMqeKTCYkitsPqHNxTmd4SNR5r94FGM8= github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d/go.mod h1:asat636LX7Bqt5lYEZ27JNDcqxfjdBQuJ/MM4CN/Lzo= -github.com/alcionai/clues v0.0.0-20230131232239-cee86233b005 h1:eTgICcmcydEWG8J+hgnidf0pzujV3Gd2XqmknykZkzA= -github.com/alcionai/clues v0.0.0-20230131232239-cee86233b005/go.mod h1:UlAs8jkWIpsOMakiC8NxPgQQVQRdvyf1hYMszlYYLb4= github.com/alcionai/clues v0.0.0-20230202001016-cbda58c9de9e h1:KMRGDB9lh0wC/WYVmQ28MJ07qiHszCSH2PRwkw2YElM= github.com/alcionai/clues v0.0.0-20230202001016-cbda58c9de9e/go.mod h1:UlAs8jkWIpsOMakiC8NxPgQQVQRdvyf1hYMszlYYLb4= github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= diff --git a/src/pkg/fault/example_fault_test.go b/src/pkg/fault/example_fault_test.go index 4ad5945d2..f1e614996 100644 --- a/src/pkg/fault/example_fault_test.go +++ b/src/pkg/fault/example_fault_test.go @@ -34,6 +34,14 @@ type mockOper struct { func newOperation() mockOper { return mockOper{fault.New(true)} } func (m mockOper) Run() *fault.Errors { return m.Errors } +type mockDepenedency struct{} + +func (md mockDepenedency) do() error { + return errors.New("caught one") +} + +var dependency = mockDepenedency{} + // --------------------------------------------------------------------------- // examples // --------------------------------------------------------------------------- @@ -289,3 +297,43 @@ func Example_errors_e2e() { fmt.Println("recoverable err occurred", err) } } + +// ExampleErrorsErr showcases when to return err or nil vs errs.Err() +func Example_errors_err() { + // The general rule of thumb is to always handle the error directly + // by returning err, or nil, or any variety of extension (wrap, + // stack, clues, etc). + fn := func() error { + if err := dependency.do(); err != nil { + return errors.Wrap(err, "direct") + } + + return nil + } + if err := fn(); err != nil { + fmt.Println(err) + } + + // The exception is if you're handling recoverable errors. Those + // funcs should always return errs.Err(), in case a recoverable + // error happened on the last round of iteration. + fn2 := func(todo []string, errs *fault.Errors) error { + for range todo { + if errs.Err() != nil { + return errs.Err() + } + + if err := dependency.do(); err != nil { + errs.Add(errors.Wrap(err, "recoverable")) + } + } + + return errs.Err() + } + if err := fn2([]string{"a"}, fault.New(true)); err != nil { + fmt.Println(err) + } + + // Output: direct: caught one + // recoverable: caught one +} diff --git a/src/pkg/logger/example_logger_test.go b/src/pkg/logger/example_logger_test.go new file mode 100644 index 000000000..d04cc02ff --- /dev/null +++ b/src/pkg/logger/example_logger_test.go @@ -0,0 +1,125 @@ +package logger_test + +import ( + "context" + + "github.com/alcionai/clues" + "github.com/alcionai/corso/src/pkg/logger" +) + +// --------------------------------------------------------------------------- +// mock helpers +// --------------------------------------------------------------------------- + +const ( + loglevel = "info" + logfile = "stderr" + itemID = "item_id" +) + +var err error + +// --------------------------------------------------------------------------- +// examples +// --------------------------------------------------------------------------- + +// ExampleSeed showcases seeding a logger into the context. +func Example_seed() { + // Before logging, a logger instance first needs to get seeded into + // the context. Seeding only needs to be done once. For example + // Corso's CLI layer seeds the logger in the cli initialization. + ctx := context.Background() + ctx, log := logger.Seed(ctx, loglevel, logfile) + + // SDK consumers who configure their own zap logger can Set their logger + // into the context directly, instead of Seeding a new one. + ctx = logger.Set(ctx, log) + + // logs should always be flushed before exiting whichever func + // seeded the logger. + defer func() { + _ = log.Sync() // flush all logs in the buffer + }() + + // downstream, the logger will retrieve its configuration from + // the context. + func(ctx context.Context) { + log := logger.Ctx(ctx) + log.Info("hello, world!") + }(ctx) +} + +// ExampleLoggerStandards reviews code standards around logging in Corso. +func Example_logger_standards() { + log := logger.Ctx(context.Background()) + + // 1. Keep messsages short. Lowercase text, no ending punctuation. + // This ensures logs are easy to scan, and simple to grok. + // + // preferred + log.Info("getting item") + // avoid + log.Info("Getting one item from the service so that we can send it through the item feed.") + + // 2. Do not fmt values into the message. Use With() or -w() to add structured data. + // By keeping dynamic data in a structured format, we maximize log readability, + // and make logs very easy to search or filter in bulk, and very easy to control pii. + // + // preferred + log.With("err", err).Error("getting item") + log.Errorw("getting item", "err", err) + // avoid + log.Errorf("getting item %s: %v", itemID, err) + + // 3. Give data keys reasonable namespaces. Use snake_case. + // Overly generic keys can collide unexpectedly. + // + // preferred + log.With("item_id", itemID).Info("getting item") + // avoid + log.With("id", itemID).Error("getting item") + + // 4. Avoid Warn-level logging. Prefer Info or Error. + // Minimize confusion/contention about what level a log + // "should be". Error during a failure, Info (or Debug) + // otherwise. + // + // preferred + log.With("err", err).Error("getting item") + // avoid + log.With("err", err).Warn("getting item") + + // 4. Avoid Panic/Fatal-level logging. Prefer Error. + // Panic and Fatal logging can crash the application without + // flushing buffered logs and finishing out other telemetry. + // + // preferred + log.With("err", err).Error("unable to connect") + // avoid + log.With("err", err).Panic("unable to connecct") +} + +// ExampleLoggerCluesStandards reviews code standards around using the Clues package while logging. +func Example_logger_clues_standards() { + log := logger.Ctx(context.Background()) + + // 1. Clues Ctx values are always added in .Ctx(); you don't + // need to add them directly. + // + // preferred + ctx := clues.Add(context.Background(), "item_id", itemID) + logger.Ctx(ctx).Info("getting item") + // avoid + ctx = clues.Add(context.Background(), "item_id", itemID) + logger.Ctx(ctx).With(clues.In(ctx).Slice()...).Info("getting item") + + // 2. Always extract structured data from errors. + // + // preferred + log.With("err", err).Errorw("getting item", clues.InErr(err).Slice()...) + // avoid + log.Errorw("getting item", "err", err) + + // TODO(keepers): PII + // 3. Protect pii in logs. +} diff --git a/website/docs/developers/logging.md b/website/docs/developers/logging.md new file mode 100644 index 000000000..c2fee4e95 --- /dev/null +++ b/website/docs/developers/logging.md @@ -0,0 +1,3 @@ +# Corso Logging Standards + +Logging standards and SDK consumer logging integration details can be found in the Corso repo [logging examples](https://github.com/alcionai/corso/blob/main/src/pkg/logger/example_logger_test.go).