Docker logging race condition (master:28ef366ceab60d6ff15b343171da6ff2d5d0992e)

logging.out

WARN[0068] DEPRECATED: Setting host configuration options when the container starts is deprecated and has been removed in Docker 1.12
ERRO[0068] fifo /proc/self/fd/13 was closed before opening
[41] Write event
[41] Recevied event 1
Processed event 1
[19] Write event
[19] Recevied event 2
[41] Write event
Processed event 2
[41] Recevied event 2
Processed event 2
[19] Write event
[19] Recevied event 3
Processed event 3
[41] Write event
[41] Recevied event 3
Processed event 3
[19] Write event
[19] Recevied event 4
Processed event 4
[41] Write event
[41] Recevied event 4
Processed event 4
[19] Write event
[19] Recevied event 5
Processed event 5
[41] Write event
[41] Recevied event 5
Processed event 5
[19] Write event
[19] Recevied event 6
Processed event 6
[41] Write event
[41] Recevied event 6
Processed event 6
[19] Write event
[19] Recevied event 7
Processed event 7
[41] Write event
[41] Recevied event 7
Processed event 7
[19] Write event
[19] Recevied event 8
Processed event 8
[41] Write event
[41] Recevied event 8
Processed event 8
[19] Write event
[19] Recevied event 9
Processed event 9
[41] Write event
[41] Recevied event 9
Processed event 9
[19] Write event
[19] Recevied event 10
Processed event 10
LogWatcher.Close got called
[41] Write event
goroutine 282 [running]:
runtime/debug.Stack(0xc420028010, 0xc420459a48, 0x1)
        /usr/local/go/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
        /usr/local/go/src/runtime/debug/stack.go:16 +0x22
github.com/docker/docker/daemon/logger.(*LogWatcher).Close(0xc421235560)
        /go/src/github.com/docker/docker/daemon/logger/logger.go:126 +0xa4
github.com/docker/docker/daemon/logger/jsonfilelog.(*JSONFileLogger).Close(0xc4215a6d40, 0xc4216e0d80, 0x0)
        /go/src/github.com/docker/docker/daemon/logger/jsonfilelog/jsonfilelog.go:141 +0xd9
github.com/docker/docker/container.(*Container).Reset(0xc4212a3680, 0xc4216e4500)
        /go/src/github.com/docker/docker/container/monitor.go:42 +0x124
github.com/docker/docker/daemon.(*Daemon).StateChanged(0xc42047c1c0, 0xc42114e8c0, 0x40, 0xc4213f19ec, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/src/github.com/docker/docker/daemon/monitor.go:46 +0x2dc
github.com/docker/docker/libcontainerd.(*container).handleEvent.func1()
        /go/src/github.com/docker/docker/libcontainerd/container_linux.go:204 +0x82
github.com/docker/docker/libcontainerd.(*queue).append.func1(0xc420befd00, 0x0, 0xc421143450, 0xc4216e0d20)
        /go/src/github.com/docker/docker/libcontainerd/queue_linux.go:26 +0x30
created by github.com/docker/docker/libcontainerd.(*queue).append
        /go/src/github.com/docker/docker/libcontainerd/queue_linux.go:28 +0x170
[41] Recevied event 10
Received message to close watcher
[41] Removed inotify watcher 1

logging.patch

diff --git a/daemon/logger/jsonfilelog/read.go b/daemon/logger/jsonfilelog/read.go
index 4401fec..73b2dc1 100644
--- a/daemon/logger/jsonfilelog/read.go
+++ b/daemon/logger/jsonfilelog/read.go
@@ -196,11 +196,14 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 		return nil
 	}
 
+  eventCount := 0
 	errRetry := errors.New("retry")
 	errDone := errors.New("done")
 	waitRead := func() error {
 		select {
 		case e := <-fileWatcher.Events():
+      eventCount = eventCount + 1
+      fmt.Printf("Processed event %d\n", eventCount)
 			switch e.Op {
 			case fsnotify.Write:
 				dec = json.NewDecoder(f)
@@ -232,6 +235,7 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 			}
 			return err
 		case <-logWatcher.WatchClose():
+      fmt.Println("Received message to close watcher")
 			fileWatcher.Remove(name)
 			return errDone
 		}
diff --git a/daemon/logger/logger.go b/daemon/logger/logger.go
index 1ce7ed5..0e23d2e 100644
--- a/daemon/logger/logger.go
+++ b/daemon/logger/logger.go
@@ -9,6 +9,8 @@ package logger
 
 import (
 	"errors"
+  "fmt"
+  "runtime/debug"
 	"sort"
 	"strings"
 	"sync"
@@ -120,6 +122,8 @@ func NewLogWatcher() *LogWatcher {
 
 // Close notifies the underlying log reader to stop.
 func (w *LogWatcher) Close() {
+  fmt.Println("LogWatcher.Close got called")
+  debug.PrintStack()
 	// only close if not already closed
 	w.closeOnce.Do(func() {
 		close(w.closeNotifier)
diff --git a/daemon/logs.go b/daemon/logs.go
index 0e1fdfa..d98f198 100644
--- a/daemon/logs.go
+++ b/daemon/logs.go
@@ -82,10 +82,12 @@ func (daemon *Daemon) ContainerLogs(ctx context.Context, containerName string, c
 			logrus.Errorf("Error streaming logs: %v", err)
 			return nil
 		case <-ctx.Done():
+      fmt.Println("Context says we are done")
 			logs.Close()
 			return nil
 		case msg, ok := <-logs.Msg:
 			if !ok {
+        fmt.Println("We are ending because a msg !ok")
 				logrus.Debug("logs: end stream")
 				logs.Close()
 				if cLog != container.LogDriver {
diff --git a/vendor/src/gopkg.in/fsnotify.v1/inotify.go b/vendor/src/gopkg.in/fsnotify.v1/inotify.go
index 780b2a0..b813043 100644
--- a/vendor/src/gopkg.in/fsnotify.v1/inotify.go
+++ b/vendor/src/gopkg.in/fsnotify.v1/inotify.go
@@ -151,6 +151,8 @@ func (w *Watcher) Remove(name string) error {
 		return errno
 	}
 
+  fmt.Printf("[%d] Removed inotify watcher %d\n", w.fd, watch.wd)
+
 	// wait until ignoreLinux() deleting maps
 	exists := true
 	for exists {
@@ -182,6 +184,8 @@ func (w *Watcher) readEvents() {
 	defer syscall.Close(w.fd)
 	defer w.poller.close()
 
+  eventCount := 0
+
 	for {
 		// See if we have been closed.
 		if w.isClosed() {
@@ -259,9 +263,12 @@ func (w *Watcher) readEvents() {
 			}
 
 			event := newEvent(name, mask)
+      event.printDebug(w.fd)
 
 			// Send the events that are not ignored on the events channel
 			if !event.ignoreLinux(w, raw.Wd, mask) {
+        eventCount = eventCount + 1
+        fmt.Printf("[%d] Recevied event %d\n", w.fd, eventCount)
 				select {
 				case w.Events <- event:
 				case <-w.done:
@@ -275,12 +282,28 @@ func (w *Watcher) readEvents() {
 	}
 }
 
+func (e *Event) printDebug(fd int) {
+  switch e.Op {
+  case Create:
+    fmt.Printf("[%d] Create event\n", fd)
+  case Remove:
+    fmt.Printf("[%d] Remove event\n", fd)
+  case Write:
+    fmt.Printf("[%d] Write event\n", fd)
+  case Rename:
+    fmt.Printf("[%d] Rename event\n", fd)
+  case Chmod:
+    fmt.Printf("[%d] Chmod event\n", fd)
+  }
+}
+
 // Certain types of events can be "ignored" and not sent over the Events
 // channel. Such as events marked ignore by the kernel, or MODIFY events
 // against files that do not exist.
 func (e *Event) ignoreLinux(w *Watcher, wd int32, mask uint32) bool {
 	// Ignore anything the inotify API says to ignore
 	if mask&syscall.IN_IGNORED == syscall.IN_IGNORED {
+    fmt.Printf("[%d] Got an ignore message\n", w.fd)
 		w.mu.Lock()
 		defer w.mu.Unlock()
 		name := w.paths[int(wd)]