Skip to content

Commit

Permalink
moves clog into clues
Browse files Browse the repository at this point in the history
Transferring Clog into Clues as a subpackage will solve:
1. multi-package updates (clues -> clog -> something with both clog and
   clues)
2. better preparation for OTEL support integration into clues and clog.
3. sets up future extensions like metrics tracking via clues.
  • Loading branch information
ryanfkeepers committed Oct 14, 2024
1 parent 721af7f commit aa9d90d
Show file tree
Hide file tree
Showing 9 changed files with 1,084 additions and 4 deletions.
90 changes: 90 additions & 0 deletions clog/README.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,90 @@
# The Clues Logger

## Regular logging

Infow/Debugw/Errorw are also supported.
So are the \*f variations. Because I'm trying to be nice.
Warn is not included. Because I'm not _that_ nice.

```go
clog.Ctx(ctx).Info("information")
clog.Ctx(ctx).Label(clog.ExampleDebugLabel).Debug("debugging")
clog.Ctx(ctx).Err(err).Error("badness")
```

## Labeling your logs

Labeling is intended to make _categorical_ lookup of logs much easier.

Many times we build unintentional colloquialisms into our log vocabulary
and try to filter on those when looking for info. Ex: logs that say
"recoverable error" are "the important error logs". No, none of that.

If you have a set of loging that you always want to include or exclude, put
a label on it.
"How was this run configured?" -> filter clabel like /clabel_configuration/
"What caused the process to fail?" -> filter clabel like /clabel_error_origin/

```go
clog.CtxErr(ctx, err).
Label(clog.LStartOfRun, clog.LFailureSource).
Info("couldn't start up process")
```

## Commenting your logs

```go
clog.Ctx(ctx).
Comment(`I could just add this in code... but now we can pull double duty!
whatever I say here is readable to anyone who is looking at the logs (which is good
if I'm trying to tell them what they need to know about due to this log occurring);
it's also a regular comment, as if in code, so the code is now also commented!`).
Info("information")
```

## Automatically adds structured data from clues

```go
ctx := clues.Add(ctx, "foo", "bar")
err := clues.New("a bad happened").With("fnords", "smarf")

clog.CtxErr(ctx, err).
With("beaux", "regarde").
Debug("all the info!")

// this produces a log containing:
// {
// "msg": "all the info!",
// "foo": "bar",
// "fnords": "smarf",
// "beaux": "regarde",
// }
```

## Setting up logs

```go
set := clog.Settings{
Format: clog.FormatForHumans,
Level: clog.LevelInfo,
}

ctx := clog.Init(ctx, set)
```

## Filtering Debug Logs (aka, improved debug levels)

You're using labels to categorize your logs, right? Right?
Well then you've already built out your debug logging levels!
Want to only include a certain set of your very noisy debug logs?
Just specify which label you want included in the debug level.

```go
set := clog.Settings{
Format: clog.FormatForHumans,
Level: clog.LevelDebug,
OnlyLogDebugIfContainsLabel: []string{clog.APICall},
}

ctx := clog.Init(ctx, set)
```
284 changes: 284 additions & 0 deletions clog/builder.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,284 @@
package clog

import (
"context"
"fmt"
"reflect"

"github.com/alcionai/clues"
"go.uber.org/zap"
"golang.org/x/exp/maps"
)

// ------------------------------------------------------------------------------------------------
// builder is the primary logging handler
// most funcs that people would use in the daily drive are going
// to modfiy and/or return a builder instance. The builder aggregates
// data passed to it until a log func is called (debug, info, or error).
// At that time it consumes all of the gathered data to send the log message.
// ------------------------------------------------------------------------------------------------

type builder struct {
ctx context.Context
err error
zsl *zap.SugaredLogger
with map[any]any
labels map[string]struct{}
comments map[string]struct{}
skipCallerJumps int
}

func newBuilder(ctx context.Context) *builder {
clgr := fromCtx(ctx)

return &builder{
ctx: ctx,
zsl: clgr.zsl,
with: map[any]any{},
labels: map[string]struct{}{},
comments: map[string]struct{}{},
}
}

// log actually delivers the log to the underlying logger with the given
func (b builder) log(l logLevel, msg string) {
cv := clues.In(b.ctx).Map()
zsl := b.zsl

if b.err != nil {
// error values should override context values.
maps.Copy(cv, clues.InErr(b.err).Map())

// attach the error and its labels
zsl = zsl.
With("error", b.err).
With("error_labels", clues.Labels(b.err))
}

for k, v := range cv {
zsl = zsl.With(k, v)
}

// plus any values added using builder.With()
for k, v := range b.with {
zsl = zsl.With(k, v)
}

// finally, make sure we attach the labels and comments
zsl = zsl.With("clog_labels", maps.Keys(b.labels))
zsl = zsl.With("clog_comments", maps.Keys(b.comments))

if b.skipCallerJumps > 0 {
zsl = zsl.WithOptions(zap.AddCallerSkip(b.skipCallerJumps))
}

// then write everything to the logger
switch l {
case LevelDebug:
var ok bool

for _, l := range cloggerton.set.OnlyLogDebugIfContainsLabel {
if _, match := b.labels[l]; match {
ok = true
break
}
}

if !ok {
return
}

zsl.Debug(msg)
case LevelInfo:
zsl.Info(msg)
case LevelError:
zsl.Error(msg)
}
}

// Err attaches the error to the builder.
// When logged, the error will be parsed for any clues parts
// and those values will get added to the resulting log.
//
// ex: if you have some `err := clues.New("badness").With("cause", reason)`
// then this will add both of the following to the log:
// - "error": "badness"
// - "cause": reason
func (b *builder) Err(err error) *builder {
b.err = err
return b
}

// Label adds all of the appended labels to the error.
// Adding labels is a great way to categorize your logs into broad scale
// concepts like "configuration", "process kickoff", or "process conclusion".
// they're also a great way to set up various granularities of debugging
// like "api queries" or "fine grained item review", since you can configure
// clog to automatically filter debug level logging to only deliver if the
// logs match one or more labels, allowing you to only emit some of the
// overwhelming number of debug logs that we all know you produce, you
// little overlogger, you.
func (b *builder) Label(ls ...string) *builder {
if len(b.labels) == 0 {
b.labels = map[string]struct{}{}
}

for _, l := range ls {
b.labels[l] = struct{}{}
}

return b
}

// Comments are available because why make your devs go all the way back to
// the code to find the comment about this log case? Add them into the log
// itself!
func (b *builder) Comment(cmnt string) *builder {
if len(b.comments) == 0 {
b.comments = map[string]struct{}{}
}

b.comments[cmnt] = struct{}{}

return b
}

// SkipCaller allows the logger to set its stackTrace N levels back from the
// current call. This is great for helper functions that handle log actions
// which get used by many different consumers, as it will always report the
// log line as the call to the helper function, instead of the line within the
// helper func.
func (b *builder) SkipCaller(nSkips int) *builder {
b.skipCallerJumps = nSkips
return b
}

// getValue will return the value if not pointer, or the dereferenced
// value if it is a pointer.
func getValue(v any) any {
rv := reflect.ValueOf(v)
if rv.Kind() == reflect.Ptr {
if rv.IsNil() {
return nil
}

return rv.Elem().Interface()
}
return v
}

// With is your standard "With" func. Add data in K:V pairs here to have them
// added to the log message metadata. Ex: builder.With("foo", "bar") will add
// "foo": "bar" to the resulting log structure. An uneven number of pairs will
// give the last key a nil value.
func (b *builder) With(vs ...any) *builder {
if len(vs) == 0 {
return b
}

if len(b.with) == 0 {
b.with = map[any]any{}
}

for i := 0; i < len(vs); i += 2 {
k := vs[i]
var v any

if (i + 1) < len(vs) {
v = vs[i+1]
}

b.with[k] = getValue(v)
}

return b
}

// Debug level logging. Whenever possible, you should add a debug category
// label to the log, as that will help your org maintain fine grained control
// of debug-level log filtering.
func (b builder) Debug(msgArgs ...any) {
b.log(LevelDebug, fmt.Sprint(msgArgs...))
}

// Debugf level logging. Whenever possible, you should add a debug category
// label to the log, as that will help your org maintain fine grained control
// of debug-level log filtering.
// f is for format.
// f is also for "Why? Why are you using this? Use Debugw instead, it's much better".
func (b builder) Debugf(tmpl string, vs ...any) {
b.log(LevelDebug, fmt.Sprintf(tmpl, vs...))
}

// Debugw level logging. Whenever possible, you should add a debug category
// label to the log, as that will help your org maintain fine grained control
// of debug-level log filtering.
// w is for With(key:values). log.Debugw("msg", foo, bar) is the same as
// log.With(foo, bar).Debug("msg").
func (b builder) Debugw(msg string, keyValues ...any) {
b.With(keyValues...).log(LevelDebug, msg)
}

// Info is your standard info log. You know. For information.
func (b builder) Info(msgArgs ...any) {
b.log(LevelInfo, fmt.Sprint(msgArgs...))
}

// Infof is your standard info log. You know. For information.
// f is for format.
// f is also for "Don't make bloated log messages, kids. Use Infow instead.".
func (b builder) Infof(tmpl string, vs ...any) {
b.log(LevelInfo, fmt.Sprintf(tmpl, vs...))
}

// Infow is your standard info log. You know. For information.
// w is for With(key:values). log.Infow("msg", foo, bar) is the same as
// log.With(foo, bar).Info("msg").
func (b builder) Infow(msg string, keyValues ...any) {
b.With(keyValues...).log(LevelInfo, msg)
}

// Error is an error level log. It doesn't require an error, because there's no
// rule about needing an error to log at error level. Or the reverse; feel free to
// add an error to your info or debug logs. Log levels are just a fake labeling
// system, anyway.
func (b builder) Error(msgArgs ...any) {
b.log(LevelError, fmt.Sprint(msgArgs...))
}

// Error is an error level log. It doesn't require an error, because there's no
// rule about needing an error to log at error level. Or the reverse; feel free to
// add an error to your info or debug logs. Log levels are just a fake labeling
// system, anyway.
// f is for format.
// f is also for "Good developers know the value of using Errorw before Errorf."
func (b builder) Errorf(tmpl string, vs ...any) {
b.log(LevelError, fmt.Sprintf(tmpl, vs...))
}

// Error is an error level log. It doesn't require an error, because there's no
// rule about needing an error to log at error level. Or the reverse; feel free to
// add an error to your info or debug logs. Log levels are just a fake labeling
// system, anyway.
// w is for With(key:values). log.Errorw("msg", foo, bar) is the same as
// log.With(foo, bar).Error("msg").
func (b builder) Errorw(msg string, keyValues ...any) {
b.With(keyValues...).log(LevelError, msg)
}

// ------------------------------------------------------------------------------------------------
// wrapper: io.writer
// ------------------------------------------------------------------------------------------------

// Writer is a wrapper that turns the logger embedded in
// the given ctx into an io.Writer. All logs are currently
// info-level.
type Writer struct {
Ctx context.Context
}

// Write writes to the the Writer's clogger.
func (w Writer) Write(p []byte) (int, error) {
Ctx(w.Ctx).log(LevelInfo, string(p))
return len(p), nil
}
Loading

0 comments on commit aa9d90d

Please sign in to comment.