diff --git a/errorsx/errors.go b/errorsx/errors.go index 773f8be2..a81604f2 100644 --- a/errorsx/errors.go +++ b/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 +} diff --git a/go.mod b/go.mod index 5cd258cd..122a086c 100644 --- a/go.mod +++ b/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 diff --git a/logrusx/helper.go b/logrusx/helper.go new file mode 100644 index 00000000..a7bc6454 --- /dev/null +++ b/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) +} diff --git a/logrusx/logrus.go b/logrusx/logrus.go index d7b09cab..8399fe4b 100644 --- a/logrusx/logrus.go +++ b/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") } diff --git a/logrusx/logrus_test.go b/logrusx/logrus_test.go index 41a6e3b6..47fd73e0 100644 --- a/logrusx/logrus_test.go +++ b/logrusx/logrus_test.go @@ -1 +1,159 @@ -package logrusx +package logrusx_test + +import ( + "bytes" + "net/http" + "net/url" + "strconv" + "strings" + "testing" + + "github.com/ory/herodot" + "github.com/pkg/errors" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" + + . "github.com/ory/x/logrusx" +) + +var fakeRequest = &http.Request{ + Method: "GET", + URL: &url.URL{Path: "/foo/bar", RawQuery: "bar=foo"}, + Proto: "HTTP/1.1", + ProtoMajor: 1, + ProtoMinor: 1, + Header: http.Header{ + "User-Agent": {"Go-http-client/1.1"}, + "Accept-Encoding": {"gzip"}, + "X-Request-Id": {"id1234"}, + "Accept": {"application/json"}, + }, + Body: nil, + Host: "127.0.0.1:63232", + RemoteAddr: "127.0.0.1:63233", + RequestURI: "/foo/bar?bar=foo", +} + +func TestJSONFormatter(t *testing.T) { + t.Run("pretty=true", func(t *testing.T) { + l := New("logrusx-audit", "v0.0.0", ForceFormat("json"), ForceLevel(logrus.DebugLevel)) + var b bytes.Buffer + l.Logrus().Out = &b + + l.Info("foo bar") + assert.True(t, strings.Count(b.String(), "\n") > 1) + assert.Contains(t, b.String(), " ") + }) + + t.Run("pretty=false", func(t *testing.T) { + l := New("logrusx-audit", "v0.0.0", ForceFormat("json"), ForceLevel(logrus.InfoLevel)) + var b bytes.Buffer + l.Logrus().Out = &b + + l.Info("foo bar") + assert.EqualValues(t,1, strings.Count(b.String(), "\n")) + assert.NotContains(t, b.String(), " ") + }) +} + +func TestTextLogger(t *testing.T) { + audit := NewAudit("logrusx-audit", "v0.0.0", ForceFormat("text"), ForceLevel(logrus.TraceLevel)) + tracer := New("logrusx-app", "v0.0.0", ForceFormat("text"), ForceLevel(logrus.TraceLevel)) + debugger := New("logrusx-server", "v0.0.1", ForceFormat("text"), ForceLevel(logrus.DebugLevel)) + for k, tc := range []struct { + l *Logger + expect []string + notExpect []string + call func(l *Logger) + }{ + { + l: audit, + expect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", + "audience=audit", "service_name=logrusx-audit", "service_version=v0.0.0", + "An error occurred.", "message:some error", "trace", "testing.tRunner"}, + call: func(l *Logger) { + l.WithError(errors.New("some error")).Error("An error occurred.") + }, + }, + { + l: tracer, + expect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", + "audience=application", "service_name=logrusx-app", "service_version=v0.0.0", + "An error occurred.", "message:some error", "trace", "testing.tRunner"}, + call: func(l *Logger) { + l.WithError(errors.New("some error")).Error("An error occurred.") + }, + }, + { + l: tracer, + expect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", + "audience=application", "service_name=logrusx-app", "service_version=v0.0.0", + "An error occurred.", "headers:map[", "accept:application/json", "accept-encoding:gzip", + "user-agent:Go-http-client/1.1", "x-request-id:id1234", "host:127.0.0.1:63232", "method:GET", + "query: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\".", + "remote:127.0.0.1:63233", "scheme:http", "path:/foo/bar", + }, + notExpect: []string{"testing.tRunner", "bar=foo"}, + call: func(l *Logger) { + l.WithRequest(fakeRequest).Error("An error occurred.") + }, + }, + { + l: New("logrusx-server", "v0.0.1", ForceFormat("text"), LeakSensitive(), ForceLevel(logrus.DebugLevel)), + expect: []string{ + "audience=application", "service_name=logrusx-server", "service_version=v0.0.1", + "An error occurred.", + "headers:map[", "accept:application/json", "accept-encoding:gzip", + "user-agent:Go-http-client/1.1", "x-request-id:id1234", "host:127.0.0.1:63232", "method:GET", + "query:bar=foo", + "remote:127.0.0.1:63233", "scheme:http", "path:/foo/bar", + }, + notExpect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", "testing.tRunner", "?bar=foo"}, + call: func(l *Logger) { + l.WithRequest(fakeRequest).Error("An error occurred.") + }, + }, + { + l: tracer, + expect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", + "audience=application", "service_name=logrusx-app", "service_version=v0.0.0", + "An error occurred.", "message:The requested resource could not be found", "reason:some reason", + "status:Not Found", "status_code:404", "debug:some debug", "trace", "testing.tRunner"}, + call: func(l *Logger) { + l.WithError(errors.WithStack(herodot.ErrNotFound.WithReason("some reason").WithDebug("some debug"))).Error("An error occurred.") + }, + }, + { + l: debugger, + expect: []string{"audience=application", "service_name=logrusx-server", "service_version=v0.0.1", + "An error occurred.", "message:some error"}, + notExpect: []string{"logrus_test.go", "logrusx_test.TestTextLogger", "trace", "testing.tRunner"}, + call: func(l *Logger) { + l.WithError(errors.New("some error")).Error("An error occurred.") + }, + }, + { + l: debugger, + expect: []string{"audience=application", "service_name=logrusx-server", "service_version=v0.0.1", "baz!", "foo=bar"}, + notExpect: []string{"logrus_test.go", "logrusx_test.TestTextLogger"}, + call: func(l *Logger) { + l.WithField("foo", "bar").Info("baz!") + }, + }, + } { + t.Run("case="+strconv.Itoa(k), func(t *testing.T) { + var b bytes.Buffer + tc.l.Logrus().Out = &b + + tc.call(tc.l) + + t.Logf(b.String()) + for _, expect := range tc.expect { + assert.Contains(t, b.String(), expect) + } + for _, expect := range tc.notExpect { + assert.NotContains(t, b.String(), expect) + } + }) + } +} diff --git a/logrusx/logrusx.schema.json b/logrusx/logrusx.schema.json index 7fda81fe..9f1a208b 100644 --- a/logrusx/logrusx.schema.json +++ b/logrusx/logrusx.schema.json @@ -6,6 +6,7 @@ "properties": { "level": { "title": "Log Level", + "description": "Supports the following values:\n\n- `panic`: highest level of severity. This event is so rare that it is, with almost absolute certainty, unlikely for you to encounter ever.\n- `fatal`: the program is unable to continue execution and ended with a fatal state. Can happen when the configuration is invalid, for example.\n- `error`: used for errors that should definitely be noted.\n- `warn`: non-critical entries that deserve eyes.\n- `info`: general operational entries about what's going on inside the application.\n- `debug`: usually only enabled when debugging. Very verbose logging. If `json` is the log format, the JSON will be prettified for better readability.\n- `trace`: designates finer-grained informational events than debug. Includes call traces of errors and log calls.\n", "type": "string", "enum": [ "trace", @@ -18,11 +19,11 @@ ] }, "format": { - "title": "Log Level", + "title": "Log Format", + "description": "If set to `json` and the log level is `debug`, the JSON output will be prettified.", "type": "string", "enum": [ "json", - "json_pretty", "text" ] } diff --git a/sqlcon/error.go b/sqlcon/error.go index bd36bfe7..e57d223e 100644 --- a/sqlcon/error.go +++ b/sqlcon/error.go @@ -45,7 +45,7 @@ func HandleError(err error) error { return errors.WithStack(ErrNoRows) } - if e, ok := errorsx.Cause(err).(interface{ + if e, ok := errorsx.Cause(err).(interface { SQLState() string }); ok { switch e.SQLState() { diff --git a/viperx/helper_test.go b/viperx/helper_test.go index bc871133..cb2d8b40 100644 --- a/viperx/helper_test.go +++ b/viperx/helper_test.go @@ -12,6 +12,8 @@ import ( "github.com/stretchr/testify/require" "github.com/ory/viper" + + "github.com/ory/x/logrusx" ) func setEnv(key, value string) func(t *testing.T) { @@ -367,8 +369,8 @@ func TestGetDuration(t *testing.T) { } func TestGetStringMapConfig(t *testing.T) { - l := logrus.New() - l.ExitFunc = func(code int) { + l := logrusx.New("","") + l.Entry.Logger.ExitFunc = func(code int) { panic(code) } diff --git a/viperx/viper.go b/viperx/viper.go index 2c4729d7..27d1e3f4 100644 --- a/viperx/viper.go +++ b/viperx/viper.go @@ -8,7 +8,6 @@ import ( "github.com/fsnotify/fsnotify" "github.com/mitchellh/go-homedir" - "github.com/sirupsen/logrus" "github.com/spf13/cobra" "github.com/ory/viper" @@ -52,9 +51,9 @@ func ResetWatchers() { } // WatchConfig is a helper makes watching configuration files easy. -func WatchConfig(l logrus.FieldLogger, o *WatchOptions) { +func WatchConfig(l *logrusx.Logger, o *WatchOptions) { if l == nil { - l = logrusx.New() + l = logrusx.New("", "") } if o == nil { @@ -109,7 +108,7 @@ func WatchConfig(l logrus.FieldLogger, o *WatchOptions) { } // InitializeConfig initializes viper. -func InitializeConfig(applicationName string, homeOverride string, l logrus.FieldLogger) logrus.FieldLogger { +func InitializeConfig(applicationName string, homeOverride string, l *logrusx.Logger) *logrusx.Logger { if cfgFile != "" { // Use config file from the flag. viper.SetConfigFile(cfgFile) @@ -117,7 +116,7 @@ func InitializeConfig(applicationName string, homeOverride string, l logrus.Fiel // Find home directory. home, err := homedir.Dir() if err != nil { - logrusx.New().WithField("error", err.Error()).Fatal("Unable to locate home directory") + logrusx.New(applicationName, "").WithField("error", err.Error()).Fatal("Unable to locate home directory") } if homeOverride != "" { @@ -134,7 +133,7 @@ func InitializeConfig(applicationName string, homeOverride string, l logrus.Fiel err := viper.ReadInConfig() if l == nil { - l = logrusx.New() + l = logrusx.New(applicationName, "") } if err == nil { diff --git a/viperx/viper_test.go b/viperx/viper_test.go index dfc58dcd..fb9baf6d 100644 --- a/viperx/viper_test.go +++ b/viperx/viper_test.go @@ -12,11 +12,13 @@ import ( "github.com/stretchr/testify/require" "github.com/ory/viper" + + "github.com/ory/x/logrusx" ) func TestViperInit(t *testing.T) { - l := logrus.New() - l.ExitFunc = func(code int) { + l := logrusx.New("","") + l.Entry.Logger.ExitFunc = func(code int) { panic(code) } diff --git a/viperx/watch_and_validate_viper.go b/viperx/watch_and_validate_viper.go index 543cda5f..21a09e49 100644 --- a/viperx/watch_and_validate_viper.go +++ b/viperx/watch_and_validate_viper.go @@ -5,12 +5,12 @@ import ( "os" "github.com/fsnotify/fsnotify" - "github.com/sirupsen/logrus" - "github.com/ory/viper" + + "github.com/ory/x/logrusx" ) -func WatchAndValidateViper(l logrus.FieldLogger, schema []byte, productName string, immutables []string) { +func WatchAndValidateViper(l *logrusx.Logger, schema []byte, productName string, immutables []string) { if err := Validate("config.schema.json", schema); err != nil { l.WithField("config_file", viper.ConfigFileUsed()).Error("The provided configuration is invalid and could not be loaded. Check the output below to understand why.") _, _ = fmt.Fprintln(os.Stderr, "") diff --git a/viperx/watch_and_validate_viper_test.go b/viperx/watch_and_validate_viper_test.go index 46bc8de5..3a214550 100644 --- a/viperx/watch_and_validate_viper_test.go +++ b/viperx/watch_and_validate_viper_test.go @@ -15,6 +15,8 @@ import ( "github.com/stretchr/testify/require" "github.com/ory/viper" + + "github.com/ory/x/logrusx" ) func failOnExit(t *testing.T) func(i int) { @@ -34,11 +36,11 @@ const productName = "Test" func tmpConfigFile(t *testing.T, dsn, foo string) *os.File { config := fmt.Sprintf("dsn: %s\nfoo: %s\n", dsn, foo) - tdir := os.TempDir()+"/"+strconv.Itoa(time.Now().Nanosecond()) + tdir := os.TempDir() + "/" + strconv.Itoa(time.Now().Nanosecond()) require.NoError(t, os.MkdirAll(tdir, // DO NOT CHANGE THIS: https://github.com/fsnotify/fsnotify/issues/340 os.ModePerm)) - configFile, err := ioutil.TempFile(tdir,"config-*.yml") + configFile, err := ioutil.TempFile(tdir, "config-*.yml") _, err = io.WriteString(configFile, config) require.NoError(t, err) require.NoError(t, configFile.Sync()) @@ -58,9 +60,9 @@ func updateConfigFile(t *testing.T, configFile *os.File, dsn, foo string) { require.NoError(t, configFile.Sync()) } -func setup(t *testing.T, exitFunc func(int), configFile *os.File) (*logrus.Logger, *test.Hook) { - l := logrus.New() - l.ExitFunc = exitFunc +func setup(t *testing.T, exitFunc func(int), configFile *os.File) (*logrusx.Logger, *test.Hook) { + l := logrusx.New("","") + l.Entry.Logger.ExitFunc =exitFunc viper.Reset() if configFile != nil { @@ -70,7 +72,7 @@ func setup(t *testing.T, exitFunc func(int), configFile *os.File) (*logrus.Logge t.Logf("Config file is nil") } - return l, test.NewLocal(l) + return l, test.NewLocal(l.Entry.Logger) } func TestWatchAndValidateViper(t *testing.T) {