Merge pull request #347 from stevvooe/nanosecond-logging-timestamps

main: nanosecond logging timestamps

Godeps/Godeps.json

@@ -29,8 +29,8 @@
 		},
 		{
 			"ImportPath": "github.com/Sirupsen/logrus",
-			"Comment": "v0.7.1",
+			"Comment": "v0.7.3",
-			"Rev": "3fc34d061b9c78a70db853c7cb6b0576b6d4f32d"
+			"Rev": "55eb11d21d2a31a3cc93838241d04800f52e823d"
 		},
 		{
 			"ImportPath": "github.com/bugsnag/bugsnag-go",

Godeps/_workspace/src/github.com/Sirupsen/logrus/CHANGELOG.md

@@ -0,0 +1,7 @@
+# 0.7.3
+
+formatter/\*: allow configuration of timestamp layout
+
+# 0.7.2
+
+formatter/text: Add configuration option for time format (#158)

Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md

@@ -37,11 +37,13 @@ attached, the output is compatible with the
 [logfmt](http://godoc.org/github.com/kr/logfmt) format:
 
 ```text
-time="2014-04-20 15:36:23.830442383 -0400 EDT" level="info" msg="A group of walrus emerges from the ocean" animal="walrus" size=10
+time="2015-03-26T01:27:38-04:00" level=debug msg="Started observing beach" animal=walrus number=8
-time="2014-04-20 15:36:23.830584199 -0400 EDT" level="warning" msg="The group's number increased tremendously!" omg=true number=122
+time="2015-03-26T01:27:38-04:00" level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10
-time="2014-04-20 15:36:23.830596521 -0400 EDT" level="info" msg="A giant walrus appears!" animal="walrus" size=10
+time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased tremendously!" number=122 omg=true
-time="2014-04-20 15:36:23.830611837 -0400 EDT" level="info" msg="Tremendously sized cow enters the ocean." animal="walrus" size=9
+time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4
-time="2014-04-20 15:36:23.830626464 -0400 EDT" level="fatal" msg="The ice breaks!" omg=true number=100
+time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009
+time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true
+exit status 1
 ```
 
 #### Example
@@ -106,6 +108,16 @@ func main() {
     "omg":    true,
     "number": 100,
   }).Fatal("The ice breaks!")
+
+  // A common pattern is to re-use fields between logging statements by re-using
+  // the logrus.Entry returned from WithFields()
+  contextLogger := log.WithFields(log.Fields{
+    "common": "this is a common field",
+    "other": "I also should be logged always",
+  })
+
+  contextLogger.Info("I'll be logged with common and other field")
+  contextLogger.Info("Me too")
 }
 ```
 
@@ -187,31 +199,18 @@ func init() {
 }
 ```
 
-* [`github.com/Sirupsen/logrus/hooks/airbrake`](https://github.com/Sirupsen/logrus/blob/master/hooks/airbrake/airbrake.go)
-  Send errors to an exception tracking service compatible with the Airbrake API.
-  Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes.
 
-* [`github.com/Sirupsen/logrus/hooks/papertrail`](https://github.com/Sirupsen/logrus/blob/master/hooks/papertrail/papertrail.go)
+| Hook  | Description |
-  Send errors to the Papertrail hosted logging service via UDP.
+| ----- | ----------- |
-
+| [Airbrake](https://github.com/Sirupsen/logrus/blob/master/hooks/airbrake/airbrake.go) | Send errors to an exception tracking service compatible with the Airbrake API. Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes. |
-* [`github.com/Sirupsen/logrus/hooks/syslog`](https://github.com/Sirupsen/logrus/blob/master/hooks/syslog/syslog.go)
+| [Papertrail](https://github.com/Sirupsen/logrus/blob/master/hooks/papertrail/papertrail.go) | Send errors to the Papertrail hosted logging service via UDP. |
-  Send errors to remote syslog server.
+| [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. |
-  Uses standard library `log/syslog` behind the scenes.
+| [BugSnag](https://github.com/Sirupsen/logrus/blob/master/hooks/bugsnag/bugsnag.go) | Send errors to the Bugsnag exception tracking service. |
-
+| [Hiprus](https://github.com/nubo/hiprus) | Send errors to a channel in hipchat. |
-* [`github.com/Sirupsen/logrus/hooks/bugsnag`](https://github.com/Sirupsen/logrus/blob/master/hooks/bugsnag/bugsnag.go)
+| [Logrusly](https://github.com/sebest/logrusly) | Send logs to [Loggly](https://www.loggly.com/) |
-  Send errors to the Bugsnag exception tracking service.
+| [Slackrus](https://github.com/johntdyer/slackrus) | Hook for Slack chat. |
-
+| [Journalhook](https://github.com/wercker/journalhook) | Hook for logging to `systemd-journald` |
-* [`github.com/nubo/hiprus`](https://github.com/nubo/hiprus)
+| [Graylog](https://github.com/gemnasium/logrus-hooks/tree/master/graylog) | Hook for logging to [Graylog](http://graylog2.org/) |
-  Send errors to a channel in hipchat.
-
-* [`github.com/sebest/logrusly`](https://github.com/sebest/logrusly)
-  Send logs to Loggly (https://www.loggly.com/)
-
-* [`github.com/johntdyer/slackrus`](https://github.com/johntdyer/slackrus)
-  Hook for Slack chat.
-
-* [`github.com/wercker/journalhook`](https://github.com/wercker/journalhook).
-  Hook for logging to `systemd-journald`.
 
 #### Level logging
 

Godeps/_workspace/src/github.com/Sirupsen/logrus/formatter.go

@@ -1,5 +1,9 @@
 package logrus
 
+import "time"
+
+const DefaultTimestampFormat = time.RFC3339
+
 // The Formatter interface is used to implement a custom Formatter. It takes an
 // `Entry`. It exposes all the fields, including the default ones:
 //

Godeps/_workspace/src/github.com/Sirupsen/logrus/formatters/logstash/logstash.go

@@ -3,19 +3,27 @@ package logstash
 import (
 	"encoding/json"
 	"fmt"
+
 	"github.com/Sirupsen/logrus"
-	"time"
 )
 
 // Formatter generates json in logstash format.
 // Logstash site: http://logstash.net/
 type LogstashFormatter struct {
 	Type string // if not empty use for logstash type field.
+
+	// TimestampFormat sets the format used for timestamps.
+	TimestampFormat string
 }
 
 func (f *LogstashFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 	entry.Data["@version"] = 1
-	entry.Data["@timestamp"] = entry.Time.Format(time.RFC3339)
+
+	if f.TimestampFormat == "" {
+		f.TimestampFormat = logrus.DefaultTimestampFormat
+	}
+
+	entry.Data["@timestamp"] = entry.Time.Format(f.TimestampFormat)
 
 	// set message field
 	v, ok := entry.Data["message"]

Godeps/_workspace/src/github.com/Sirupsen/logrus/json_formatter.go

@@ -3,10 +3,12 @@ package logrus
 import (
 	"encoding/json"
 	"fmt"
-	"time"
 )
 
-type JSONFormatter struct{}
+type JSONFormatter struct {
+	// TimestampFormat sets the format used for marshaling timestamps.
+	TimestampFormat string
+}
 
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 	data := make(Fields, len(entry.Data)+3)
@@ -21,7 +23,12 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 		}
 	}
 	prefixFieldClashes(data)
-	data["time"] = entry.Time.Format(time.RFC3339)
+
+	if f.TimestampFormat == "" {
+		f.TimestampFormat = DefaultTimestampFormat
+	}
+
+	data["time"] = entry.Time.Format(f.TimestampFormat)
 	data["msg"] = entry.Message
 	data["level"] = entry.Level.String()
 

Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter.go

@@ -46,6 +46,9 @@ type TextFormatter struct {
 	// the time passed since beginning of execution.
 	FullTimestamp bool
 
+	// TimestampFormat to use for display when a full timestamp is printed
+	TimestampFormat string
+
 	// The fields are sorted by default for a consistent output. For applications
 	// that log extremely frequently and don't use the JSON formatter this may not
 	// be desired.
@@ -68,11 +71,14 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 
 	isColored := (f.ForceColors || isTerminal) && !f.DisableColors
 
+	if f.TimestampFormat == "" {
+		f.TimestampFormat = DefaultTimestampFormat
+	}
 	if isColored {
 		f.printColored(b, entry, keys)
 	} else {
 		if !f.DisableTimestamp {
-			f.appendKeyValue(b, "time", entry.Time.Format(time.RFC3339))
+			f.appendKeyValue(b, "time", entry.Time.Format(f.TimestampFormat))
 		}
 		f.appendKeyValue(b, "level", entry.Level.String())
 		f.appendKeyValue(b, "msg", entry.Message)
@@ -103,7 +109,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin
 	if !f.FullTimestamp {
 		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Message)
 	} else {
-		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(time.RFC3339), entry.Message)
+		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(f.TimestampFormat), entry.Message)
 	}
 	for _, k := range keys {
 		v := entry.Data[k]

Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter_test.go

@@ -3,8 +3,8 @@ package logrus
 import (
 	"bytes"
 	"errors"
-
 	"testing"
+	"time"
 )
 
 func TestQuoting(t *testing.T) {
@@ -33,5 +33,29 @@ func TestQuoting(t *testing.T) {
 	checkQuoting(true, errors.New("invalid argument"))
 }
 
+func TestTimestampFormat(t *testing.T) {
+	checkTimeStr := func(format string) {
+		customFormatter := &TextFormatter{DisableColors: true, TimestampFormat: format}
+		customStr, _ := customFormatter.Format(WithField("test", "test"))
+		timeStart := bytes.Index(customStr, ([]byte)("time="))
+		timeEnd := bytes.Index(customStr, ([]byte)("level="))
+		timeStr := customStr[timeStart+5 : timeEnd-1]
+		if timeStr[0] == '"' && timeStr[len(timeStr)-1] == '"' {
+			timeStr = timeStr[1 : len(timeStr)-1]
+		}
+		if format == "" {
+			format = time.RFC3339
+		}
+		_, e := time.Parse(format, (string)(timeStr))
+		if e != nil {
+			t.Errorf("time string \"%s\" did not match provided time format \"%s\": %s", timeStr, format, e)
+		}
+	}
+
+	checkTimeStr("2006-01-02T15:04:05.000000000Z07:00")
+	checkTimeStr("Mon Jan _2 15:04:05 2006")
+	checkTimeStr("")
+}
+
 // TODO add tests for sorting etc., this requires a parser for the text
 // formatter output.

cmd/registry/main.go

@@ -10,6 +10,7 @@ import (
 	"net/http"
 	_ "net/http/pprof"
 	"os"
+	"time"
 
 	log "github.com/Sirupsen/logrus"
 	"github.com/Sirupsen/logrus/formatters/logstash"
@@ -196,13 +197,24 @@ func configureLogging(ctx context.Context, config *configuration.Configuration)
 
 	log.SetLevel(logLevel(config.Log.Level))
 
-	switch config.Log.Formatter {
+	formatter := config.Log.Formatter
+	if formatter == "" {
+		formatter = "text" // default formatter
+	}
+
+	switch formatter {
 	case "json":
-		log.SetFormatter(&log.JSONFormatter{})
+		log.SetFormatter(&log.JSONFormatter{
+			TimestampFormat: time.RFC3339Nano,
+		})
 	case "text":
-		log.SetFormatter(&log.TextFormatter{})
+		log.SetFormatter(&log.TextFormatter{
+			TimestampFormat: time.RFC3339Nano,
+		})
 	case "logstash":
-		log.SetFormatter(&logstash.LogstashFormatter{})
+		log.SetFormatter(&logstash.LogstashFormatter{
+			TimestampFormat: time.RFC3339Nano,
+		})
 	default:
 		// just let the library use default on empty string.
 		if config.Log.Formatter != "" {