events/jsonmessage: add and prefer TimeNano for events

This way provide both Time and TimeNano in the event. For the display of
the JSONMessage, use either, but prefer TimeNano Proving only TimeNano
would break Subscribers that are using the `Time` field, so both are set
for backwards compatibility.

The events logging uses nano formatting, but only provides a Unix()
time, therefor ordering may get lost in the output. Example:
```
2015-09-15T14:18:51.000000000-04:00 ee46febd64ac629f7de9cd8bf58582e6f263d97ff46896adc5b508db804682da: (from busybox) resize
2015-09-15T14:18:51.000000000-04:00 a78c9149b1c0474502a117efaa814541926c2ae6ec3c76607e1c931b84c3a44b: (from busybox) resize
```

By having a field just for Nano time, when set, the marshalling back to
`time.Unix(sec int64, nsec int64)` has zeros exactly where it needs to.
This does not break any existing use of jsonmessage.JSONMessage, but now
allows for use of `UnixNano()` and get event formatting that has
distinguishable order. Example:
```
2015-09-15T15:37:23.810295632-04:00 6adcf8ed9f5f5ec059a915466cd1cde86a18b4a085fc3af405e9cc9fecbbbbaf: (from busybox) resize
2015-09-15T15:37:23.810412202-04:00 6b7c5bfdc3f902096f5a91e628f21bd4b56e32590c5b4b97044aafc005ddcb0d: (from busybox) resize
```

Including tests for TimeNano and updated event API reference doc.

Signed-off-by: Vincent Batts <vbatts@redhat.com>

daemon/events/events.go

@@ -45,7 +45,8 @@ func (e *Events) Evict(l chan interface{}) {
 // Log broadcasts event to listeners. Each listener has 100 millisecond for
 // receiving event or it will be skipped.
 func (e *Events) Log(action, id, from string) {
-	jm := &jsonmessage.JSONMessage{Status: action, ID: id, From: from, Time: time.Now().UTC().Unix()}
+	now := time.Now().UTC()
+	jm := &jsonmessage.JSONMessage{Status: action, ID: id, From: from, Time: now.Unix(), TimeNano: now.UnixNano()}
 	e.mu.Lock()
 	if len(e.events) == cap(e.events) {
 		// discard oldest event

docs/reference/api/docker_remote_api.md

@@ -87,6 +87,7 @@ This section lists each version from latest to oldest.  Each listing includes a
 * The `hostConfig` option now accepts the field `DnsOptions`, which specifies a
 list of DNS options to be used in the container.
 * `POST /build` now optionally takes a serialized map of build-time variables.
+* `GET /events` now includes a `timenano` field, in addition to the existing `time` field.
 
 ### v1.20 API changes
 

docs/reference/api/docker_remote_api_v1.21.md

@@ -2014,10 +2014,10 @@ and Docker images report:
     HTTP/1.1 200 OK
     Content-Type: application/json
 
-    {"status": "create", "id": "dfdf82bd3881","from": "ubuntu:latest", "time":1374067924}
+    {"status":"pull","id":"busybox:latest","time":1442421700,"timeNano":1442421700598988358}
-    {"status": "start", "id": "dfdf82bd3881","from": "ubuntu:latest", "time":1374067924}
+    {"status":"create","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716853979870}
-    {"status": "stop", "id": "dfdf82bd3881","from": "ubuntu:latest", "time":1374067966}
+    {"status":"attach","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716894759198}
-    {"status": "destroy", "id": "dfdf82bd3881","from": "ubuntu:latest", "time":1374067970}
+    {"status":"start","id":"5745704abe9caa5","from":"busybox","time":1442421716,"timeNano":1442421716983607193}
 
 Query Parameters:
 

pkg/jsonmessage/jsonmessage.go

@@ -99,6 +99,7 @@ type JSONMessage struct {
 	ID              string        `json:"id,omitempty"`
 	From            string        `json:"from,omitempty"`
 	Time            int64         `json:"time,omitempty"`
+	TimeNano        int64         `json:"timeNano,omitempty"`
 	Error           *JSONError    `json:"errorDetail,omitempty"`
 	ErrorMessage    string        `json:"error,omitempty"` //deprecated
 }
@@ -121,7 +122,9 @@ func (jm *JSONMessage) Display(out io.Writer, isTerminal bool) error {
 	} else if jm.Progress != nil && jm.Progress.String() != "" { //disable progressbar in non-terminal
 		return nil
 	}
-	if jm.Time != 0 {
+	if jm.TimeNano != 0 {
+		fmt.Fprintf(out, "%s ", time.Unix(0, jm.TimeNano).Format(timeutils.RFC3339NanoFixed))
+	} else if jm.Time != 0 {
 		fmt.Fprintf(out, "%s ", time.Unix(jm.Time, 0).Format(timeutils.RFC3339NanoFixed))
 	}
 	if jm.ID != "" {

pkg/jsonmessage/jsonmessage_test.go

@@ -53,7 +53,7 @@ func TestProgress(t *testing.T) {
 }
 
 func TestJSONMessageDisplay(t *testing.T) {
-	now := time.Now().Unix()
+	now := time.Now()
 	messages := map[JSONMessage][]string{
 		// Empty
 		JSONMessage{}: {"\n", "\n"},
@@ -66,13 +66,34 @@ func TestJSONMessageDisplay(t *testing.T) {
 		},
 		// General
 		JSONMessage{
-			Time:   now,
+			Time:   now.Unix(),
 			ID:     "ID",
 			From:   "From",
 			Status: "status",
 		}: {
-			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(now, 0).Format(timeutils.RFC3339NanoFixed)),
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(now.Unix(), 0).Format(timeutils.RFC3339NanoFixed)),
-			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(now, 0).Format(timeutils.RFC3339NanoFixed)),
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(now.Unix(), 0).Format(timeutils.RFC3339NanoFixed)),
+		},
+		// General, with nano precision time
+		JSONMessage{
+			TimeNano: now.UnixNano(),
+			ID:       "ID",
+			From:     "From",
+			Status:   "status",
+		}: {
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(0, now.UnixNano()).Format(timeutils.RFC3339NanoFixed)),
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(0, now.UnixNano()).Format(timeutils.RFC3339NanoFixed)),
+		},
+		// General, with both times Nano is preferred
+		JSONMessage{
+			Time:     now.Unix(),
+			TimeNano: now.UnixNano(),
+			ID:       "ID",
+			From:     "From",
+			Status:   "status",
+		}: {
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(0, now.UnixNano()).Format(timeutils.RFC3339NanoFixed)),
+			fmt.Sprintf("%v ID: (from From) status\n", time.Unix(0, now.UnixNano()).Format(timeutils.RFC3339NanoFixed)),
 		},
 		// Stream over status
 		JSONMessage{