Merge remote-tracking branch 'origin/master' into text-field-map

.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

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

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 |
+A list of currently known of service hook can be found in this wiki [page](https://github.com/sirupsen/logrus/wiki/Hooks)
-| ----- | ----------- |
+
-| [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/) |
 
 #### 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:

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()
+	entry.fireHooks()
-	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()
-	}
 	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...))

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)
+}

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) {
+func prefixFieldClashes(data Fields, fieldMap FieldMap) {
-	if t, ok := data["time"]; ok {
+	timeKey := fieldMap.resolve(FieldKeyTime)
-		data["fields.time"] = t
+	if t, ok := data[timeKey]; ok {
+		data["fields."+timeKey] = t
 	}
 
-	if m, ok := data["msg"]; ok {
+	msgKey := fieldMap.resolve(FieldKeyMsg)
-		data["fields.msg"] = m
+	if m, ok := data[msgKey]; ok {
+		data["fields."+msgKey] = m
 	}
 
-	if l, ok := data["level"]; ok {
+	levelKey := fieldMap.resolve(FieldKeyLevel)
-		data["fields.level"] = l
+	if l, ok := data[levelKey]; ok {
+		data["fields."+levelKey] = l
 	}
 }

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))
 }

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 == "" {

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{}
 

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()

terminal_bsd.go

@@ -1,5 +1,5 @@
 // +build darwin freebsd openbsd netbsd dragonfly
-// +build !appengine
+// +build !appengine,!gopherjs
 
 package logrus
 

terminal_check_appengine.go

@@ -0,0 +1,11 @@
+// +build appengine gopherjs
+
+package logrus
+
+import (
+	"io"
+)
+
+func checkIfTerminal(w io.Writer) bool {
+	return true
+}

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
+	}
+}

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
 

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)
+		f.isTerminal = 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
 	}
 }
 
@@ -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)

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}