diff --git a/.travis.yml b/.travis.yml index a23296a..aebdc35 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,8 +1,8 @@ language: go go: - - 1.6.x - - 1.7.x - 1.8.x + - 1.9.x + - 1.10.x - tip env: - GOMAXPROCS=4 GORACE=halt_on_error=1 diff --git a/CHANGELOG.md b/CHANGELOG.md index 8236d8b..1bd1deb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,13 @@ +# 1.0.5 + +* Fix hooks race (#707) +* Fix panic deadlock (#695) + +# 1.0.4 + +* Fix race when adding hooks (#612) +* Fix terminal check in AppEngine (#635) + # 1.0.3 * Replace example files with testable examples diff --git a/README.md b/README.md index 08584b5..072e99b 100644 --- a/README.md +++ b/README.md @@ -220,7 +220,7 @@ Logrus comes with [built-in hooks](hooks/). Add those, or your custom hook, in ```go import ( log "github.com/sirupsen/logrus" - "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "aibrake" + "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "airbrake" logrus_syslog "github.com/sirupsen/logrus/hooks/syslog" "log/syslog" ) @@ -241,58 +241,8 @@ func init() { ``` Note: Syslog hook also support connecting to local syslog (Ex. "/dev/log" or "/var/run/syslog" or "/var/run/log"). For the detail, please check the [syslog hook README](hooks/syslog/README.md). -| Hook | Description | -| ----- | ----------- | -| [Airbrake "legacy"](https://github.com/gemnasium/logrus-airbrake-legacy-hook) | Send errors to an exception tracking service compatible with the Airbrake API V2. Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes. | -| [Airbrake](https://github.com/gemnasium/logrus-airbrake-hook) | Send errors to the Airbrake API V3. Uses the official [`gobrake`](https://github.com/airbrake/gobrake) behind the scenes. | -| [Amazon Kinesis](https://github.com/evalphobia/logrus_kinesis) | Hook for logging to [Amazon Kinesis](https://aws.amazon.com/kinesis/) | -| [Amqp-Hook](https://github.com/vladoatanasov/logrus_amqp) | Hook for logging to Amqp broker (Like RabbitMQ) | -| [AzureTableHook](https://github.com/kpfaulkner/azuretablehook/) | Hook for logging to Azure Table Storage| -| [Bugsnag](https://github.com/Shopify/logrus-bugsnag/blob/master/bugsnag.go) | Send errors to the Bugsnag exception tracking service. | -| [DeferPanic](https://github.com/deferpanic/dp-logrus) | Hook for logging to DeferPanic | -| [Discordrus](https://github.com/kz/discordrus) | Hook for logging to [Discord](https://discordapp.com/) | -| [ElasticSearch](https://github.com/sohlich/elogrus) | Hook for logging to ElasticSearch| -| [Firehose](https://github.com/beaubrewer/logrus_firehose) | Hook for logging to [Amazon Firehose](https://aws.amazon.com/kinesis/firehose/) -| [Fluentd](https://github.com/evalphobia/logrus_fluent) | Hook for logging to fluentd | -| [Go-Slack](https://github.com/multiplay/go-slack) | Hook for logging to [Slack](https://slack.com) | -| [Graylog](https://github.com/gemnasium/logrus-graylog-hook) | Hook for logging to [Graylog](http://graylog2.org/) | -| [Hiprus](https://github.com/nubo/hiprus) | Send errors to a channel in hipchat. | -| [Honeybadger](https://github.com/agonzalezro/logrus_honeybadger) | Hook for sending exceptions to Honeybadger | -| [InfluxDB](https://github.com/Abramovic/logrus_influxdb) | Hook for logging to influxdb | -| [Influxus](http://github.com/vlad-doru/influxus) | Hook for concurrently logging to [InfluxDB](http://influxdata.com/) | -| [Journalhook](https://github.com/wercker/journalhook) | Hook for logging to `systemd-journald` | -| [KafkaLogrus](https://github.com/tracer0tong/kafkalogrus) | Hook for logging to Kafka | -| [LFShook](https://github.com/rifflock/lfshook) | Hook for logging to the local filesystem | -| [Logbeat](https://github.com/macandmia/logbeat) | Hook for logging to [Opbeat](https://opbeat.com/) | -| [Logentries](https://github.com/jcftang/logentriesrus) | Hook for logging to [Logentries](https://logentries.com/) | -| [Logentrus](https://github.com/puddingfactory/logentrus) | Hook for logging to [Logentries](https://logentries.com/) | -| [Logmatic.io](https://github.com/logmatic/logmatic-go) | Hook for logging to [Logmatic.io](http://logmatic.io/) | -| [Logrusly](https://github.com/sebest/logrusly) | Send logs to [Loggly](https://www.loggly.com/) | -| [Logstash](https://github.com/bshuster-repo/logrus-logstash-hook) | Hook for logging to [Logstash](https://www.elastic.co/products/logstash) | -| [Mail](https://github.com/zbindenren/logrus_mail) | Hook for sending exceptions via mail | -| [Mattermost](https://github.com/shuLhan/mattermost-integration/tree/master/hooks/logrus) | Hook for logging to [Mattermost](https://mattermost.com/) | -| [Mongodb](https://github.com/weekface/mgorus) | Hook for logging to mongodb | -| [NATS-Hook](https://github.com/rybit/nats_logrus_hook) | Hook for logging to [NATS](https://nats.io) | -| [Octokit](https://github.com/dorajistyle/logrus-octokit-hook) | Hook for logging to github via octokit | -| [Papertrail](https://github.com/polds/logrus-papertrail-hook) | Send errors to the [Papertrail](https://papertrailapp.com) hosted logging service via UDP. | -| [PostgreSQL](https://github.com/gemnasium/logrus-postgresql-hook) | Send logs to [PostgreSQL](http://postgresql.org) | -| [Promrus](https://github.com/weaveworks/promrus) | Expose number of log messages as [Prometheus](https://prometheus.io/) metrics | -| [Pushover](https://github.com/toorop/logrus_pushover) | Send error via [Pushover](https://pushover.net) | -| [Raygun](https://github.com/squirkle/logrus-raygun-hook) | Hook for logging to [Raygun.io](http://raygun.io/) | -| [Redis-Hook](https://github.com/rogierlommers/logrus-redis-hook) | Hook for logging to a ELK stack (through Redis) | -| [Rollrus](https://github.com/heroku/rollrus) | Hook for sending errors to rollbar | -| [Scribe](https://github.com/sagar8192/logrus-scribe-hook) | Hook for logging to [Scribe](https://github.com/facebookarchive/scribe)| -| [Sentry](https://github.com/evalphobia/logrus_sentry) | Send errors to the Sentry error logging and aggregation service. | -| [Slackrus](https://github.com/johntdyer/slackrus) | Hook for Slack chat. | -| [Stackdriver](https://github.com/knq/sdhook) | Hook for logging to [Google Stackdriver](https://cloud.google.com/logging/) | -| [Sumorus](https://github.com/doublefree/sumorus) | Hook for logging to [SumoLogic](https://www.sumologic.com/)| -| [Syslog](https://github.com/sirupsen/logrus/blob/master/hooks/syslog/syslog.go) | Send errors to remote syslog server. Uses standard library `log/syslog` behind the scenes. | -| [Syslog TLS](https://github.com/shinji62/logrus-syslog-ng) | Send errors to remote syslog server with TLS support. | -| [Telegram](https://github.com/rossmcdonald/telegram_hook) | Hook for logging errors to [Telegram](https://telegram.org/) | -| [TraceView](https://github.com/evalphobia/logrus_appneta) | Hook for logging to [AppNeta TraceView](https://www.appneta.com/products/traceview/) | -| [Typetalk](https://github.com/dragon3/logrus-typetalk-hook) | Hook for logging to [Typetalk](https://www.typetalk.in/) | -| [logz.io](https://github.com/ripcurld00d/logrus-logzio-hook) | Hook for logging to [logz.io](https://logz.io), a Log as a Service using Logstash | -| [SQS-Hook](https://github.com/tsarpaul/logrus_sqs) | Hook for logging to [Amazon Simple Queue Service (SQS)](https://aws.amazon.com/sqs/) | +A list of currently known of service hook can be found in this wiki [page](https://github.com/sirupsen/logrus/wiki/Hooks) + #### Level logging @@ -370,6 +320,8 @@ The built-in logging formatters are: field to `true`. To force no colored output even if there is a TTY set the `DisableColors` field to `true`. For Windows, see [github.com/mattn/go-colorable](https://github.com/mattn/go-colorable). + * When colors are enabled, levels are truncated to 4 characters by default. To disable + truncation set the `DisableLevelTruncation` field to `true`. * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#TextFormatter). * `logrus.JSONFormatter`. Logs fields as JSON. * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#JSONFormatter). @@ -493,7 +445,7 @@ logrus.RegisterExitHandler(handler) #### Thread safety -By default Logger is protected by mutex for concurrent writes, this mutex is invoked when calling hooks and writing logs. +By default, Logger is protected by a mutex for concurrent writes. The mutex is held when calling hooks and writing logs. If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking. Situation when locking is not needed includes: diff --git a/entry.go b/entry.go index 1fad45e..d075d72 100644 --- a/entry.go +++ b/entry.go @@ -48,7 +48,7 @@ type Entry struct { func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, - // Default is three fields, give a little extra room + // Default is five fields, give a little extra room Data: make(Fields, 5), } } @@ -94,32 +94,16 @@ func (entry Entry) log(level Level, msg string) { entry.Level = level entry.Message = msg - entry.Logger.mu.Lock() - err := entry.Logger.Hooks.Fire(level, &entry) - entry.Logger.mu.Unlock() - if err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) - entry.Logger.mu.Unlock() - } + entry.fireHooks() + buffer = bufferPool.Get().(*bytes.Buffer) buffer.Reset() defer bufferPool.Put(buffer) entry.Buffer = buffer - serialized, err := entry.Logger.Formatter.Format(&entry) + + entry.write() + entry.Buffer = nil - if err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) - entry.Logger.mu.Unlock() - } else { - entry.Logger.mu.Lock() - _, err = entry.Logger.Out.Write(serialized) - if err != nil { - fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) - } - entry.Logger.mu.Unlock() - } // To avoid Entry#log() returning a value that only would make sense for // panic() to use in Entry#Panic(), we avoid the allocation by checking @@ -129,6 +113,31 @@ func (entry Entry) log(level Level, msg string) { } } +// This function is not declared with a pointer value because otherwise +// race conditions will occur when using multiple goroutines +func (entry Entry) fireHooks() { + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + err := entry.Logger.Hooks.Fire(entry.Level, &entry) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) + } +} + +func (entry *Entry) write() { + serialized, err := entry.Logger.Formatter.Format(entry) + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) + } else { + _, err = entry.Logger.Out.Write(serialized) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) + } + } +} + func (entry *Entry) Debug(args ...interface{}) { if entry.Logger.level() >= DebugLevel { entry.log(DebugLevel, fmt.Sprint(args...)) diff --git a/entry_test.go b/entry_test.go index 99c3b41..a81e2b3 100644 --- a/entry_test.go +++ b/entry_test.go @@ -75,3 +75,41 @@ func TestEntryPanicf(t *testing.T) { entry := NewEntry(logger) entry.WithField("err", errBoom).Panicf("kaboom %v", true) } + +const ( + badMessage = "this is going to panic" + panicMessage = "this is broken" +) + +type panickyHook struct{} + +func (p *panickyHook) Levels() []Level { + return []Level{InfoLevel} +} + +func (p *panickyHook) Fire(entry *Entry) error { + if entry.Message == badMessage { + panic(panicMessage) + } + + return nil +} + +func TestEntryHooksPanic(t *testing.T) { + logger := New() + logger.Out = &bytes.Buffer{} + logger.Level = InfoLevel + logger.Hooks.Add(&panickyHook{}) + + defer func() { + p := recover() + assert.NotNil(t, p) + assert.Equal(t, panicMessage, p) + + entry := NewEntry(logger) + entry.Info("another message") + }() + + entry := NewEntry(logger) + entry.Info(badMessage) +} diff --git a/formatter.go b/formatter.go index b183ff5..849dc8b 100644 --- a/formatter.go +++ b/formatter.go @@ -30,16 +30,19 @@ type Formatter interface { // // It's not exported because it's still using Data in an opinionated way. It's to // avoid code duplication between the two default formatters. -func prefixFieldClashes(data Fields) { - if t, ok := data["time"]; ok { - data["fields.time"] = t +func prefixFieldClashes(data Fields, fieldMap FieldMap) { + timeKey := fieldMap.resolve(FieldKeyTime) + if t, ok := data[timeKey]; ok { + data["fields."+timeKey] = t } - if m, ok := data["msg"]; ok { - data["fields.msg"] = m + msgKey := fieldMap.resolve(FieldKeyMsg) + if m, ok := data[msgKey]; ok { + data["fields."+msgKey] = m } - if l, ok := data["level"]; ok { - data["fields.level"] = l + levelKey := fieldMap.resolve(FieldKeyLevel) + if l, ok := data[levelKey]; ok { + data["fields."+levelKey] = l } } diff --git a/hooks/test/test_test.go b/hooks/test/test_test.go index 3f55cfe..742be55 100644 --- a/hooks/test/test_test.go +++ b/hooks/test/test_test.go @@ -1,6 +1,7 @@ package test import ( + "sync" "testing" "github.com/sirupsen/logrus" @@ -8,7 +9,6 @@ import ( ) func TestAllHooks(t *testing.T) { - assert := assert.New(t) logger, hook := NewNullLogger() @@ -35,5 +35,27 @@ func TestAllHooks(t *testing.T) { assert.Equal(logrus.ErrorLevel, hook.LastEntry().Level) assert.Equal("Hello error", hook.LastEntry().Message) assert.Equal(1, len(hook.Entries)) - +} + +func TestLoggingWithHooksRace(t *testing.T) { + assert := assert.New(t) + logger, hook := NewNullLogger() + + var wg sync.WaitGroup + wg.Add(100) + + for i := 0; i < 100; i++ { + go func() { + logger.Info("info") + wg.Done() + }() + } + + wg.Wait() + + assert.Equal(logrus.InfoLevel, hook.LastEntry().Level) + assert.Equal("info", hook.LastEntry().Message) + + entries := hook.AllEntries() + assert.Equal(100, len(entries)) } diff --git a/json_formatter.go b/json_formatter.go index fb01c1b..7064947 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -58,7 +58,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[k] = v } } - prefixFieldClashes(data) + prefixFieldClashes(data, f.FieldMap) timestampFormat := f.TimestampFormat if timestampFormat == "" { diff --git a/json_formatter_test.go b/json_formatter_test.go index 51093a7..1c140d0 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -3,6 +3,7 @@ package logrus import ( "encoding/json" "errors" + "fmt" "strings" "testing" ) @@ -106,6 +107,60 @@ func TestFieldClashWithLevel(t *testing.T) { } } +func TestFieldClashWithRemappedFields(t *testing.T) { + formatter := &JSONFormatter{ + FieldMap: FieldMap{ + FieldKeyTime: "@timestamp", + FieldKeyLevel: "@level", + FieldKeyMsg: "@message", + }, + } + + b, err := formatter.Format(WithFields(Fields{ + "@timestamp": "@timestamp", + "@level": "@level", + "@message": "@message", + "timestamp": "timestamp", + "level": "level", + "msg": "msg", + })) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + for _, field := range []string{"timestamp", "level", "msg"} { + if entry[field] != field { + t.Errorf("Expected field %v to be untouched; got %v", field, entry[field]) + } + + remappedKey := fmt.Sprintf("fields.%s", field) + if remapped, ok := entry[remappedKey]; ok { + t.Errorf("Expected %s to be empty; got %v", remappedKey, remapped) + } + } + + for _, field := range []string{"@timestamp", "@level", "@message"} { + if entry[field] == field { + t.Errorf("Expected field %v to be mapped to an Entry value", field) + } + + remappedKey := fmt.Sprintf("fields.%s", field) + if remapped, ok := entry[remappedKey]; ok { + if remapped != field { + t.Errorf("Expected field %v to be copied to %s; got %v", field, remappedKey, remapped) + } + } else { + t.Errorf("Expected field %v to be copied to %s; was absent", field, remappedKey) + } + } +} + func TestJSONEntryEndsWithNewline(t *testing.T) { formatter := &JSONFormatter{} diff --git a/logger.go b/logger.go index fdaf8a6..0ac8ce2 100644 --- a/logger.go +++ b/logger.go @@ -88,7 +88,7 @@ func (logger *Logger) releaseEntry(entry *Entry) { } // Adds a field to the log entry, note that it doesn't log until you call -// Debug, Print, Info, Warn, Fatal or Panic. It only creates a log entry. +// Debug, Print, Info, Warn, Error, Fatal or Panic. It only creates a log entry. // If you want multiple fields, use `WithFields`. func (logger *Logger) WithField(key string, value interface{}) *Entry { entry := logger.newEntry() diff --git a/terminal_bsd.go b/terminal_bsd.go index d7b3893..4880d13 100644 --- a/terminal_bsd.go +++ b/terminal_bsd.go @@ -1,5 +1,5 @@ // +build darwin freebsd openbsd netbsd dragonfly -// +build !appengine +// +build !appengine,!gopherjs package logrus diff --git a/terminal_check_appengine.go b/terminal_check_appengine.go new file mode 100644 index 0000000..3de08e8 --- /dev/null +++ b/terminal_check_appengine.go @@ -0,0 +1,11 @@ +// +build appengine gopherjs + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return true +} diff --git a/terminal_check_notappengine.go b/terminal_check_notappengine.go new file mode 100644 index 0000000..067047a --- /dev/null +++ b/terminal_check_notappengine.go @@ -0,0 +1,19 @@ +// +build !appengine,!gopherjs + +package logrus + +import ( + "io" + "os" + + "golang.org/x/crypto/ssh/terminal" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + return terminal.IsTerminal(int(v.Fd())) + default: + return false + } +} diff --git a/terminal_linux.go b/terminal_linux.go index 88d7298..f29a009 100644 --- a/terminal_linux.go +++ b/terminal_linux.go @@ -3,7 +3,7 @@ // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. -// +build !appengine +// +build !appengine,!gopherjs package logrus diff --git a/text_formatter.go b/text_formatter.go index aa0694c..5af4e56 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -3,14 +3,10 @@ package logrus import ( "bytes" "fmt" - "io" - "os" "sort" "strings" "sync" "time" - - "golang.org/x/crypto/ssh/terminal" ) const ( @@ -24,6 +20,7 @@ const ( var ( baseTimestamp time.Time + emptyFieldMap FieldMap ) func init() { @@ -54,6 +51,10 @@ type TextFormatter struct { // be desired. DisableSorting bool + + // Disables the truncation of the level text to 4 characters. + DisableLevelTruncation bool + // QuoteEmptyFields will wrap empty fields in quotes if true QuoteEmptyFields bool @@ -74,16 +75,7 @@ type TextFormatter struct { func (f *TextFormatter) init(entry *Entry) { if entry.Logger != nil { - f.isTerminal = f.checkIfTerminal(entry.Logger.Out) - } -} - -func (f *TextFormatter) checkIfTerminal(w io.Writer) bool { - switch v := w.(type) { - case *os.File: - return terminal.IsTerminal(int(v.Fd())) - default: - return false + f.isTerminal = checkIfTerminal(entry.Logger.Out) } } @@ -104,7 +96,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { b = &bytes.Buffer{} } - prefixFieldClashes(entry.Data) + prefixFieldClashes(entry.Data, emptyFieldMap) f.Do(func() { f.init(entry) }) @@ -146,7 +138,10 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelColor = blue } - levelText := strings.ToUpper(entry.Level.String())[0:4] + levelText := strings.ToUpper(entry.Level.String()) + if !f.DisableLevelTruncation { + levelText = levelText[0:4] + } if f.DisableTimestamp { fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m %-44s ", levelColor, levelText, entry.Message) diff --git a/text_formatter_test.go b/text_formatter_test.go index 789d52d..4f21861 100644 --- a/text_formatter_test.go +++ b/text_formatter_test.go @@ -130,6 +130,44 @@ func TestTimestampFormat(t *testing.T) { checkTimeStr("") } +func TestDisableLevelTruncation(t *testing.T) { + entry := &Entry{ + Time: time.Now(), + Message: "testing", + } + keys := []string{} + timestampFormat := "Mon Jan 2 15:04:05 -0700 MST 2006" + checkDisableTruncation := func(disabled bool, level Level) { + tf := &TextFormatter{DisableLevelTruncation: disabled} + var b bytes.Buffer + entry.Level = level + tf.printColored(&b, entry, keys, timestampFormat) + logLine := (&b).String() + if disabled { + expected := strings.ToUpper(level.String()) + if !strings.Contains(logLine, expected) { + t.Errorf("level string expected to be %s when truncation disabled", expected) + } + } else { + expected := strings.ToUpper(level.String()) + if len(level.String()) > 4 { + if strings.Contains(logLine, expected) { + t.Errorf("level string %s expected to be truncated to %s when truncation is enabled", expected, expected[0:4]) + } + } else { + if !strings.Contains(logLine, expected) { + t.Errorf("level string expected to be %s when truncation is enabled and level string is below truncation threshold", expected) + } + } + } + } + + checkDisableTruncation(true, DebugLevel) + checkDisableTruncation(true, InfoLevel) + checkDisableTruncation(false, ErrorLevel) + checkDisableTruncation(false, InfoLevel) +} + func TestDisableTimestampWithColoredOutput(t *testing.T) { tf := &TextFormatter{DisableTimestamp: true, ForceColors: true}