Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

moves clog into clues #56

Merged
merged 1 commit into from
Nov 4, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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 logging 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)
```
291 changes: 291 additions & 0 deletions clog/builder.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,291 @@
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 emits the log message and all attributes using the underlying logger.
//
// If otel is configured in clues, a duplicate log will be delivered to the
// otel receiver. Is this redundant? Yes. Would it be better served by
// having a set of log emitters that registered by an interface so that
// we're not coupling usage? Also yes. These are known design issues that
// we can chase later. This is all still in the early/poc stage and needs
// additional polish to shine.
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.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// Label adds all of the appended labels to the error.
// Label adds all of the appended labels to the log.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fixed in another PR

// 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
Loading