feat: improve structured logging

errorsx/errors.go

@@ -1,5 +1,7 @@
 package errorsx
 
+import "github.com/pkg/errors"
+
 // Cause returns the underlying cause of the error, if possible.
 // An error value has a cause if it implements the following
 // interface:
@@ -25,3 +27,43 @@ func Cause(err error) error {
 	}
 	return err
 }
+
+// StatusCodeCarrier can be implemented by an error to support setting status codes in the error itself.
+type StatusCodeCarrier interface {
+	// StatusCode returns the status code of this error.
+	StatusCode() int
+}
+
+// RequestIDCarrier can be implemented by an error to support error contexts.
+type RequestIDCarrier interface {
+	// RequestID returns the ID of the request that caused the error, if applicable.
+	RequestID() string
+}
+
+// ReasonCarrier can be implemented by an error to support error contexts.
+type ReasonCarrier interface {
+	// Reason returns the reason for the error, if applicable.
+	Reason() string
+}
+
+// DebugCarrier can be implemented by an error to support error contexts.
+type DebugCarrier interface {
+	// Debug returns debugging information for the error, if applicable.
+	Debug() string
+}
+
+// StatusCarrier can be implemented by an error to support error contexts.
+type StatusCarrier interface {
+	// ID returns the error id, if applicable.
+	Status() string
+}
+
+// DetailsCarrier can be implemented by an error to support error contexts.
+type DetailsCarrier interface {
+	// Details returns details on the error, if applicable.
+	Details() map[string]interface{}
+}
+
+type StackTracer interface {
+	StackTrace() errors.StackTrace
+}

go.mod

@@ -2,6 +2,7 @@ module github.com/ory/x
 
 require (
 	github.com/cenkalti/backoff v2.2.1+incompatible
+	github.com/davecgh/go-spew v1.1.1
 	github.com/fatih/structs v1.1.0
 	github.com/fsnotify/fsnotify v1.4.9
 	github.com/go-bindata/go-bindata v3.1.1+incompatible

logrusx/helper.go

@@ -0,0 +1,116 @@
+package logrusx
+
+import (
+	"errors"
+	"fmt"
+	"net/http"
+	"reflect"
+	"strings"
+
+	"github.com/sirupsen/logrus"
+
+	"github.com/ory/x/errorsx"
+)
+
+type Logger struct {
+	*logrus.Entry
+	leakSensitive bool
+}
+
+func (l *Logger) Logrus() *logrus.Logger {
+	return l.Entry.Logger
+}
+
+func (l *Logger) WithRequest(r *http.Request) *Logger {
+	headers := map[string]interface{}{}
+	if ua := r.UserAgent(); len(ua) > 0 {
+		headers["user-agent"] = ua
+	}
+
+	if cookie := l.maybeRedact(r.Header.Get("Cookie")); cookie != nil {
+		headers["cookie"] = cookie
+	}
+
+	if auth := l.maybeRedact(r.Header.Get("Authorization")); auth != nil {
+		headers["authorization"] = auth
+	}
+
+	for _, key := range []string{"Referer", "Origin", "Accept", "X-Request-ID", "If-None-Match",
+		"X-Forwarded-For", "X-Forwarded-Proto", "Cache-Control", "Accept-Encoding", "Accept-Language", "If-Modified-Since"} {
+		if value := r.Header.Get(key); len(value) > 0 {
+			headers[strings.ToLower(key)] = value
+		}
+	}
+
+	scheme := "https"
+	if r.TLS == nil {
+		scheme = "http"
+	}
+
+	return l.WithField("http_request", map[string]interface{}{
+		"remote":  r.RemoteAddr,
+		"method":  r.Method,
+		"path":     r.URL.EscapedPath(),
+		"query":   l.maybeRedact(r.URL.RawQuery),
+		"scheme":  scheme,
+		"host":    r.Host,
+		"headers": headers,
+	})
+}
+
+func (l *Logger) WithFields(f logrus.Fields) *Logger {
+	ll := *l
+	ll.Entry = l.Entry.WithFields(f)
+	return &ll
+}
+
+func (l *Logger) WithField(key string, value interface{}) *Logger {
+	ll := *l
+	ll.Entry = l.Entry.WithField(key, value)
+	return &ll
+}
+
+func (l *Logger) maybeRedact(value interface{}) interface{} {
+	if fmt.Sprintf("%v", value) == "" || value == nil {
+		return nil
+	}
+	if !l.leakSensitive {
+		return `Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true".`
+	}
+	return value
+}
+
+func (l *Logger) WithSensitiveField(key string, value interface{}) *Logger {
+	return l.WithField(key, l.maybeRedact(value))
+}
+
+func (l *Logger) WithError(err error) *Logger {
+	ctx := map[string]interface{}{"message": err.Error()}
+	if l.Entry.Logger.IsLevelEnabled(logrus.TraceLevel) {
+		if e, ok := err.(errorsx.StackTracer); ok {
+			ctx["trace"] = fmt.Sprintf("%+v", e.StackTrace())
+		} else {
+			ctx["trace"] = fmt.Sprintf("stack trace could not be recovered from error type %s", reflect.TypeOf(err))
+		}
+	}
+	if c := errorsx.ReasonCarrier(nil); errors.As(err, &c) {
+		ctx["reason"] = c.Reason()
+	}
+	if c := errorsx.RequestIDCarrier(nil); errors.As(err, &c) && c.RequestID() != "" {
+		ctx["request_id"] = c.RequestID()
+	}
+	if c := errorsx.DetailsCarrier(nil); errors.As(err, &c) && c.Details() != nil {
+		ctx["details"] = c.Details()
+	}
+	if c := errorsx.StatusCarrier(nil); errors.As(err, &c) && c.Status() != "" {
+		ctx["status"] = c.Status()
+	}
+	if c := errorsx.StatusCodeCarrier(nil); errors.As(err, &c) && c.StatusCode() != 0 {
+		ctx["status_code"] = c.StatusCode()
+	}
+	if c := errorsx.DebugCarrier(nil); errors.As(err, &c) {
+		ctx["debug"] = c.Debug()
+	}
+
+	return l.WithField("error", ctx)
+}

logrusx/logrus.go

@@ -8,46 +8,122 @@ import (
 	"github.com/ory/x/stringsx"
 )
 
-// New initializes logrus with environment variable configuration LOG_LEVEL and LOG_FORMAT.
-func New() *logrus.Logger {
-	l := logrus.New()
-	ll, err := logrus.ParseLevel(
-		stringsx.Coalesce(
+func newLogger(o *options) *logrus.Logger {
+
+	l := o.l
+	if l == nil {
+		l = logrus.New()
+	}
+
+	if o.exitFunc != nil {
+		l.ExitFunc = o.exitFunc
+	}
+
+	if o.level != nil {
+		l.Level = *o.level
+	} else {
+		var err error
+		l.Level, err = logrus.ParseLevel(stringsx.Coalesce(
 			viper.GetString("log.level"),
-			viper.GetString("LOG_LEVEL"),
-		),
-	)
-	if err != nil {
-		ll = logrus.InfoLevel
-	}
-	l.Level = ll
-
-	switch stringsx.Coalesce(
-		viper.GetString("log.format"),
-		viper.GetString("LOG_FORMAT"),
-	){
-	case "json":
-		l.Formatter = &logrus.JSONFormatter{}
-	case "json_pretty":
-		l.Formatter = &logrus.JSONFormatter{
-			PrettyPrint: true,
+			viper.GetString("LOG_LEVEL")))
+		if err != nil {
+			l.Level = logrus.InfoLevel
 		}
-	default:
-		l.Formatter = &logrus.TextFormatter{
-			DisableQuote: true,
+	}
+
+	if o.formatter != nil {
+		l.Formatter = o.formatter
+	} else {
+		switch stringsx.Coalesce(o.format, viper.GetString("log.formatter"), viper.GetString("LOG_FORMAT")) {
+		case "json":
+			l.Formatter = &logrus.JSONFormatter{
+				PrettyPrint: l.IsLevelEnabled(logrus.DebugLevel),
+			}
+		default:
+			l.Formatter = &logrus.TextFormatter{
+				DisableQuote:     true,
+				DisableTimestamp: false,
+				FullTimestamp:    true,
+			}
 		}
 	}
 
+	l.ReportCaller = o.reportCaller || l.IsLevelEnabled(logrus.TraceLevel)
 	return l
 }
 
-// HelpMessage returns a string containing a help message for setting up the logger.
-func HelpMessage() string {
-	return `- LOG_LEVEL: Set the log level, supports "panic", "fatal", "error", "warn", "info" and "debug". Defaults to "info".
+type options struct {
+	l             *logrus.Logger
+	level         *logrus.Level
+	formatter     *logrus.TextFormatter
+	format        string
+	reportCaller  bool
+	exitFunc      func(int)
+	leakSensitive bool
+}
 
-	Example: LOG_LEVEL=panic
+type Option func(*options)
 
-- LOG_FORMAT: Leave empty for text based log format, or set to "json" for JSON formatting.
+func ForceLevel(level logrus.Level) Option {
+	return func(o *options) {
+		o.level = &level
+	}
+}
+
+func ForceFormatter(formatter *logrus.TextFormatter) Option {
+	return func(o *options) {
+		o.formatter = formatter
+	}
+}
+func ForceFormat(format string) Option {
+	return func(o *options) {
+		o.format = format
+	}
+}
+
+func WithExitFunc(exitFunc func(int)) Option {
+	return func(o *options) {
+		o.exitFunc = exitFunc
+	}
+}
+
+func ReportCaller(reportCaller bool) Option {
+	return func(o *options) {
+		o.reportCaller = reportCaller
+	}
+}
+
+func UseLogger(l *logrus.Logger) Option {
+	return func(o *options) {
+		o.l = l
+	}
+}
+
+func LeakSensitive() Option {
+	return func(o *options) {
+		o.leakSensitive = true
+	}
+}
+
+func newOptions(opts []Option) *options {
+	o := new(options)
+	for _, f := range opts {
+		f(o)
+	}
+	return o
+}
+
+// New creates a new logger with all the important fields set.
+func New(name string, version string, opts ...Option) *Logger {
+	o := newOptions(opts)
+	return &Logger{
+		leakSensitive: o.leakSensitive ||
+			viper.GetBool("log.leak_sensitive_values") || viper.GetBool("LOG_LEAK_SENSITIVE_VALUES"),
+		Entry: newLogger(o).WithFields(logrus.Fields{
+			"audience": "application", "service_name": name, "service_version": version}),
+	}
+}
 
-	Example: LOG_FORMAT=json`
+func NewAudit(name string, version string, opts ...Option) *Logger {
+	return New(name,version,opts...).WithField("audience","audit")
 }