1. docker
  2. Commit aa0eca03e6662c5f6b4f0f47190a45f49b61e357
Browse code

Updated docker logs timestamp to RFC3339

Currently the docker logs timestamp flag generates log entries like:

$ sudo docker logs -ft daemon_dave
[May 10 13:06:17.934] hello world

It uses Go's StampMilli timestamp to generate the timestamp. The entry
is also wrapped in [ ].

This is non-standard operational timestamp and one that will require
custom parsing.

The new timestamp is RFC3999Nano and generates entries like:

2014-05-10T17:42:14.999999999Z07:00 hello world

These are readily parsed by tools like ELK.

Docker-DCO-1.1-Signed-off-by: James Turnbull <james@lovedthanlost.net> (github: jamtur01)

Docker-DCO-1.1-Signed-off-by: Tibor Vass <teabee89@gmail.com> (github: tiborvass)

James Turnbull authored on 2014/05/11 01:51:16
Showing 5 changed files
api/client/commands.go
History View file @ aa0eca0
... ... 
@@ -1616,7 +1616,7 @@ func (cli *DockerCli) CmdEvents(args ...string) error {
1616 1616 
 		loc = time.FixedZone(time.Now().Zone())
1617 1617 
 	)
1618 1618 
 	var setTime = func(key, value string) {
1619 
-		format := "2006-01-02 15:04:05 -0700 MST"
1619 
+		format := time.RFC3339Nano
1620 1620 
 		if len(value) < len(format) {
1621 1621 
 			format = format[:len(value)]
1622 1622 
 		}
docs/sources/reference/commandline/cli.md
History View file @ aa0eca0
... ... 
@@ -425,24 +425,24 @@ You'll need two shells for this example.
425 425
426 426 
 **Shell 1: (Again .. now showing events):**
427 427
428 
-    [2013-09-03 15:49:26 +0200 CEST] 4386fb97867d: (from 12de384bfb10) start
429 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) die
430 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) stop
428 
+    2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) start
429 
+    2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) die
430 
+    2014-05-10T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) stop
431 431
432 432 
 **Show events in the past from a specified time:**
433 433
434 434 
     $ sudo docker events --since 1378216169
435 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) die
436 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) stop
435 
+    2014-03-10T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) die
436 
+    2014-03-10T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) stop
437 437
438 438 
     $ sudo docker events --since '2013-09-03'
439 
-    [2013-09-03 15:49:26 +0200 CEST] 4386fb97867d: (from 12de384bfb10) start
440 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) die
441 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) stop
439 
+    2014-09-03T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) start
440 
+    2014-09-03T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) die
441 
+    2014-09-03T17:42:14.999999999Z07:00 4386fb97867d: (from 12de384bfb10) stop
442 442
443 443 
     $ sudo docker events --since '2013-09-03 15:49:29 +0200 CEST'
444 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) die
445 
-    [2013-09-03 15:49:29 +0200 CEST] 4386fb97867d: (from 12de384bfb10) stop
444 
+    2014-09-03T15:49:29.999999999Z07:00 4386fb97867d: (from 12de384bfb10) die
445 
+    2014-09-03T15:49:29.999999999Z07:00 4386fb97867d: (from 12de384bfb10) stop
446 446
447 447 
 ## export
448 448
... ... 
@@ -750,6 +750,10 @@ the container's `STDOUT` and `STDERR`.
750 750 
 Passing a negative number or a non-integer to `--tail` is invalid and the
751 751 
 value is set to `all` in that case. This behavior may change in the future.
752 752
753 
+The `docker logs --timestamp` commands will add an RFC3339Nano
754 
+timestamp, for example `2014-05-10T17:42:14.999999999Z07:00`, to each
755 
+log entry.
756 
+
753 757 
 ## port
754 758
755 759 
     Usage: docker port CONTAINER PRIVATE_PORT
integration-cli/docker_cli_logs_test.go
History View file @ aa0eca0
... ... 
@@ -98,11 +98,11 @@ func TestLogsTimestamps(t *testing.T) {
98 98 
 		t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines))
99 99 
 	}
100 100
101 
-	ts := regexp.MustCompile(`^\[.*?\]`)
101 
+	ts := regexp.MustCompile(`^.* `)
102 102
103 103 
 	for _, l := range lines {
104 104 
 		if l != "" {
105 
-			_, err := time.Parse("["+time.StampMilli+"]", ts.FindString(l))
105 
+			_, err := time.Parse(time.RFC3339Nano+" ", ts.FindString(l))
106 106 
 			if err != nil {
107 107 
 				t.Fatalf("Failed to parse timestamp from %v: %v", l, err)
108 108 
 			}
server/server.go
History View file @ aa0eca0
... ... 
@@ -2212,7 +2212,7 @@ func (srv *Server) ContainerLogs(job *engine.Job) engine.Status {
2212 2212 
 		return job.Errorf("You must choose at least one stream")
2213 2213 
 	}
2214 2214 
 	if times {
2215 
-		format = time.StampMilli
2215 
+		format = time.RFC3339Nano
2216 2216 
 	}
2217 2217 
 	if tail == "" {
2218 2218 
 		tail = "all"
... ... 
@@ -2277,7 +2277,7 @@ func (srv *Server) ContainerLogs(job *engine.Job) engine.Status {
2277 2277 
 				}
2278 2278 
 				logLine := l.Log
2279 2279 
 				if times {
2280 
-					logLine = fmt.Sprintf("[%s] %s", l.Created.Format(format), logLine)
2280 
+					logLine = fmt.Sprintf("%s %s", l.Created.Format(format), logLine)
2281 2281 
 				}
2282 2282 
 				if l.Stream == "stdout" && stdout {
2283 2283 
 					fmt.Fprintf(job.Stdout, "%s", logLine)
utils/jsonmessage.go
History View file @ aa0eca0
... ... 
@@ -95,7 +95,7 @@ func (jm *JSONMessage) Display(out io.Writer, isTerminal bool) error {
95 95 
 		return nil
96 96 
 	}
97 97 
 	if jm.Time != 0 {
98 
-		fmt.Fprintf(out, "[%s] ", time.Unix(jm.Time, 0))
98 
+		fmt.Fprintf(out, "%s ", time.Unix(jm.Time, 0).Format(time.RFC3339Nano))
99 99 
 	}
100 100 
 	if jm.ID != "" {
101 101 
 		fmt.Fprintf(out, "%s: ", jm.ID)