Docker logging deadlock

logging.out

ERRO[0462] Handler for POST /v1.15/containers/60fdad645340b738cbf433654d683378538081a62f32ac6b89daed2027aec95b/stop returned error: Container 60fdad645340b738cbf433654d683378538081a62f32ac6b89daed2027aec95b is already stopped
WARN[0462] DEPRECATED: Setting host configuration options when the container starts is deprecated and will be removed in Docker 1.12
[38] Write event
[38] Recevied event 1
Processed event 1
[19] Write event
[19] Recevied event 2
Processed event 2
[38] Write event
[38] Recevied event 2
Processed event 2
[19] Write event
[19] Recevied event 3
Processed event 3
[38] Write event
[38] Recevied event 3
Processed event 3
[19] Write event
[19] Recevied event 4
Processed event 4
[38] Write event
[38] Recevied event 4
Processed event 4
[19] Write event
[19] Recevied event 5
Processed event 5
[38] Write event
[38] Recevied event 5
Processed event 5
[19] Write event
[19] Recevied event 6
Processed event 6
[38] Write event
[38] Recevied event 6
Processed event 6
[19] Write event
[19] Recevied event 7
Processed event 7
[38] Write event
[38] Recevied event 7
Processed event 7
[19] Write event
[19] Recevied event 8
Processed event 8
[38] Write event
[38] Recevied event 8
Processed event 8
[19] Write event
[19] Recevied event 9
Processed event 9
LogWatcher.Close got called
goroutine 271 [running]:
runtime/debug.Stack(0x0, 0x0, 0x0)
        /usr/local/go/src/runtime/debug/stack.go:24 +0x80
runtime/debug.PrintStack()
        /usr/local/go/src/runtime/debug/stack.go:16 +0x18
github.com/docker/docker/daemon/logger.(*LogWatcher).Close(0xc82089a090)
        /go/src/github.com/docker/docker/daemon/logger/logger.go:105 +0xdf
github.com/docker/docker/daemon/logger/jsonfilelog.(*JSONFileLogger).Close(0xc82127c200, 0x0, 0x0)
        /go/src/github.com/docker/docker/daemon/logger/jsonfilelog/jsonfilelog.go:137 +0xd9
github.com/docker/docker/container.(*Container).Reset(0xc82125c3c0, 0x221bf00)
        /go/src/github.com/docker/docker/container/monitor.go:42 +0x665
github.com/docker/docker/daemon.(*Daemon).StateChanged(0xc820414340, 0xc8211d4e40, 0x40, 0xc8207c7d98, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/src/github.com/docker/docker/daemon/monitor.go:34 +0x44c
github.com/docker/docker/libcontainerd.(*container).handleEvent.func1()
        /go/src/github.com/docker/docker/libcontainerd/container_linux.go:184 +0xab
github.com/docker/docker/libcontainerd.(*queue).append.func1(0xc8209b3c00, 0x0, 0xc82089a360, 0xc8207b8ba0)
        /go/src/github.com/docker/docker/libcontainerd/queue_linux.go:26 +0x47
created by github.com/docker/docker/libcontainerd.(*queue).append
        /go/src/github.com/docker/docker/libcontainerd/queue_linux.go:28 +0x1da
[38] Write event
[38] Recevied event 9
Received message to close watcher
[38] Removed inotify watcher 1

logging.patch

diff --git a/daemon/logger/jsonfilelog/read.go b/daemon/logger/jsonfilelog/read.go
index bea83dd..4330006 100644
--- a/daemon/logger/jsonfilelog/read.go
+++ b/daemon/logger/jsonfilelog/read.go
@@ -154,6 +154,8 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 		}
 	}
 
+  eventCount := 0
+
 	var retries int
 	for {
 		msg, err := decodeLogLine(dec, l)
@@ -182,12 +184,15 @@ func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan int
 
 			select {
 			case <-fileWatcher.Events():
+        eventCount = eventCount + 1
+        fmt.Printf("Processed event %d\n", eventCount)
 				dec = json.NewDecoder(f)
 				continue
 			case <-fileWatcher.Errors():
 				logWatcher.Err <- err
 				return
 			case <-logWatcher.WatchClose():
+        fmt.Println("Received message to close watcher")
 				fileWatcher.Remove(name)
 				return
 			case <-notifyRotate:
diff --git a/daemon/logger/logger.go b/daemon/logger/logger.go
index 77c6c90..064b810 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"
@@ -99,6 +101,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 1b285c6..c723a83 100644
--- a/daemon/logs.go
+++ b/daemon/logs.go
@@ -81,10 +81,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..794eb54 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", wd)
 		w.mu.Lock()
 		defer w.mu.Unlock()
 		name := w.paths[int(wd)]