Merge pull request #48 from Sirupsen/break-out-specials

entry: break out time, level and message from data

README.md

@@ -191,10 +191,10 @@ that severity or anything above it:
 
 ```go
 // Will log anything that is info or above (warn, error, fatal, panic). Default.
-log.Level = logrus.Info
+log.Level = logrus.InfoLevel
 ```
 
-It may be useful to set `log.Level = logrus.Debug` in a debug or verbose
+It may be useful to set `log.Level = logrus.DebugLevel` in a debug or verbose
 environment if your application has that.
 
 #### Entries
@@ -261,6 +261,9 @@ type MyJSONFormatter struct {
 log.Formatter = new(MyJSONFormatter)
 
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
+  // Note this doesn't include Time, Level and Message which are available on
+  // the Entry. Consult `godoc` on information about those fields or read the
+  // source of the official loggers.
   serialized, err := json.Marshal(entry.Data)
     if err != nil {
       return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)

entry.go

@@ -8,9 +8,24 @@ import (
 	"time"
 )
 
+// An entry is the final or intermediate Logrus logging entry. It containts all
+// the fields passed with WithField{,s}. It's finally logged when Debug, Info,
+// Warn, Error, Fatal or Panic is called on it. These objects can be reused and
+// passed around as much as you wish to avoid field duplication.
 type Entry struct {
 	Logger *Logger
+
+	// Contains all the fields set by the user.
 	Data Fields
+
+	// Time at which the log entry was created
+	Time time.Time
+
+	// Level the log entry was logged at: Debug, Info, Warn, Error, Fatal or Panic
+	Level Level
+
+	// Message passed to Debug, Info, Warn, Error, Fatal or Panic
+	Message string
 }
 
 var baseTimestamp time.Time
@@ -23,11 +38,14 @@ func NewEntry(logger *Logger) *Entry {
 	}
 }
 
+// Returns a reader for the entry, which is a proxy to the formatter.
 func (entry *Entry) Reader() (*bytes.Buffer, error) {
 	serialized, err := entry.Logger.Formatter.Format(entry)
 	return bytes.NewBuffer(serialized), err
 }
 
+// Returns the string representation from the reader and ultimately the
+// formatter.
 func (entry *Entry) String() (string, error) {
 	reader, err := entry.Reader()
 	if err != nil {
@@ -37,10 +55,12 @@ func (entry *Entry) String() (string, error) {
 	return reader.String(), err
 }
 
+// Add a single field to the Entry.
 func (entry *Entry) WithField(key string, value interface{}) *Entry {
 	return entry.WithFields(Fields{key: value})
 }
 
+// Add a map of fields to the Entry.
 func (entry *Entry) WithFields(fields Fields) *Entry {
 	data := Fields{}
 	for k, v := range entry.Data {
@@ -53,9 +73,9 @@ func (entry *Entry) WithFields(fields Fields) *Entry {
 }
 
 func (entry *Entry) log(level Level, msg string) string {
-	entry.Data["time"] = time.Now().String()
+	entry.Time = time.Now()
-	entry.Data["level"] = level.String()
+	entry.Level = level
-	entry.Data["msg"] = msg
+	entry.Message = msg
 
 	if err := entry.Logger.Hooks.Fire(level, entry); err != nil {
 		fmt.Fprintf(os.Stderr, "Failed to fire hook", err)

formatter.go

@@ -1,5 +1,9 @@
 package logrus
 
+import (
+	"time"
+)
+
 // The Formatter interface is used to implement a custom Formatter. It takes an
 // `Entry`. It exposes all the fields, including the default ones:
 //
@@ -13,3 +17,38 @@ package logrus
 type Formatter interface {
 	Format(*Entry) ([]byte, error)
 }
+
+// This is to not silently overwrite `time`, `msg` and `level` fields when
+// dumping it. If this code wasn't there doing:
+//
+//  logrus.WithField("level", 1).Info("hello")
+//
+// Would just silently drop the user provided level. Instead with this code
+// it'll logged as:
+//
+//  {"level": "info", "fields.level": 1, "msg": "hello", "time": "..."}
+//
+// It's not exported because it's still using Data in an opionated way. It's to
+// avoid code duplication between the two default formatters.
+func prefixFieldClashes(entry *Entry) {
+	_, ok := entry.Data["time"]
+	if ok {
+		entry.Data["fields.time"] = entry.Data["time"]
+	}
+
+	entry.Data["time"] = entry.Time.Format(time.RFC3339)
+
+	_, ok = entry.Data["msg"]
+	if ok {
+		entry.Data["fields.msg"] = entry.Data["msg"]
+	}
+
+	entry.Data["msg"] = entry.Message
+
+	_, ok = entry.Data["level"]
+	if ok {
+		entry.Data["fields.level"] = entry.Data["level"]
+	}
+
+	entry.Data["level"] = entry.Level.String()
+}

json_formatter.go

@@ -9,6 +9,8 @@ type JSONFormatter struct {
 }
 
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
+	prefixFieldClashes(entry)
+
 	serialized, err := json.Marshal(entry.Data)
 	if err != nil {
 		return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)

logrus_test.go

@@ -129,6 +129,40 @@ func TestWithFieldsShouldAllowAssignments(t *testing.T) {
 	assert.Equal(t, "value1", fields["key1"])
 }
 
+func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) {
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.WithField("msg", "hello").Info("test")
+	}, func(fields Fields) {
+		assert.Equal(t, fields["msg"], "test")
+	})
+}
+
+func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) {
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.WithField("msg", "hello").Info("test")
+	}, func(fields Fields) {
+		assert.Equal(t, fields["msg"], "test")
+		assert.Equal(t, fields["fields.msg"], "hello")
+	})
+}
+
+func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) {
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.WithField("time", "hello").Info("test")
+	}, func(fields Fields) {
+		assert.Equal(t, fields["fields.time"], "hello")
+	})
+}
+
+func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) {
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.WithField("level", 1).Info("test")
+	}, func(fields Fields) {
+		assert.Equal(t, fields["level"], "info")
+		assert.Equal(t, fields["fields.level"], 1)
+	})
+}
+
 func TestConvertLevelToString(t *testing.T) {
 	assert.Equal(t, "debug", DebugLevel.String())
 	assert.Equal(t, "info", InfoLevel.String())

text_formatter.go

@@ -32,6 +32,8 @@ type TextFormatter struct {
 func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 	b := &bytes.Buffer{}
 
+	prefixFieldClashes(entry)
+
 	if f.ForceColors || IsTerminal() {
 		levelText := strings.ToUpper(entry.Data["level"].(string))[0:4]