From 0c84604f5458bc38b793e5bcdf86624eef3e3184 Mon Sep 17 00:00:00 2001 From: Brian Goff Date: Thu, 4 Jun 2015 12:15:33 -0700 Subject: [PATCH] Fix goroutine leak on logs -f with no output Also noticed potential hang when only stdout or stderr are used with follow=1 Signed-off-by: Brian Goff --- api/server/server.go | 6 ++++ daemon/logs.go | 36 ++++++++++++++++------ integration-cli/docker_cli_logs_test.go | 41 +++++++++++++++++++++++++ 3 files changed, 73 insertions(+), 10 deletions(-) diff --git a/api/server/server.go b/api/server/server.go index d7ec2d47d7..d7924be73c 100644 --- a/api/server/server.go +++ b/api/server/server.go @@ -597,6 +597,11 @@ func (s *Server) getContainersLogs(version version.Version, w http.ResponseWrite since = time.Unix(s, 0) } + var closeNotifier <-chan bool + if notifier, ok := w.(http.CloseNotifier); ok { + closeNotifier = notifier.CloseNotify() + } + logsConfig := &daemon.ContainerLogsConfig{ Follow: boolValue(r, "follow"), Timestamps: boolValue(r, "timestamps"), @@ -605,6 +610,7 @@ func (s *Server) getContainersLogs(version version.Version, w http.ResponseWrite UseStdout: stdout, UseStderr: stderr, OutStream: ioutils.NewWriteFlusher(w), + Stop: closeNotifier, } if err := s.daemon.ContainerLogs(vars["name"], logsConfig); err != nil { diff --git a/daemon/logs.go b/daemon/logs.go index d388b9c1b6..08b3472494 100644 --- a/daemon/logs.go +++ b/daemon/logs.go @@ -25,6 +25,7 @@ type ContainerLogsConfig struct { Since time.Time UseStdout, UseStderr bool OutStream io.Writer + Stop <-chan bool } func (daemon *Daemon) ContainerLogs(name string, config *ContainerLogsConfig) error { @@ -119,7 +120,8 @@ func (daemon *Daemon) ContainerLogs(name string, config *ContainerLogsConfig) er } if config.Follow && container.IsRunning() { - chErr := make(chan error) + chErrStderr := make(chan error) + chErrStdout := make(chan error) var stdoutPipe, stderrPipe io.ReadCloser // write an empty chunk of data (this is to ensure that the @@ -131,7 +133,7 @@ func (daemon *Daemon) ContainerLogs(name string, config *ContainerLogsConfig) er stdoutPipe = container.StdoutLogPipe() go func() { logrus.Debug("logs: stdout stream begin") - chErr <- jsonlog.WriteLog(stdoutPipe, outStream, format, config.Since) + chErrStdout <- jsonlog.WriteLog(stdoutPipe, outStream, format, config.Since) logrus.Debug("logs: stdout stream end") }() } @@ -139,19 +141,33 @@ func (daemon *Daemon) ContainerLogs(name string, config *ContainerLogsConfig) er stderrPipe = container.StderrLogPipe() go func() { logrus.Debug("logs: stderr stream begin") - chErr <- jsonlog.WriteLog(stderrPipe, errStream, format, config.Since) + chErrStderr <- jsonlog.WriteLog(stderrPipe, errStream, format, config.Since) logrus.Debug("logs: stderr stream end") }() } - err = <-chErr - if stdoutPipe != nil { - stdoutPipe.Close() + select { + case err = <-chErrStderr: + if stdoutPipe != nil { + stdoutPipe.Close() + <-chErrStdout + } + case err = <-chErrStdout: + if stderrPipe != nil { + stderrPipe.Close() + <-chErrStderr + } + case <-config.Stop: + if stdoutPipe != nil { + stdoutPipe.Close() + <-chErrStdout + } + if stderrPipe != nil { + stderrPipe.Close() + <-chErrStderr + } + return nil } - if stderrPipe != nil { - stderrPipe.Close() - } - <-chErr // wait for 2nd goroutine to exit, otherwise bad things will happen if err != nil && err != io.EOF && err != io.ErrClosedPipe { if e, ok := err.(*net.OpError); ok && e.Err != syscall.EPIPE { diff --git a/integration-cli/docker_cli_logs_test.go b/integration-cli/docker_cli_logs_test.go index 2e41f8a192..099ee9f929 100644 --- a/integration-cli/docker_cli_logs_test.go +++ b/integration-cli/docker_cli_logs_test.go @@ -425,3 +425,44 @@ func (s *DockerSuite) TestLogsFollowGoroutinesWithStdout(c *check.C) { } } } + +func (s *DockerSuite) TestLogsFollowGoroutinesNoOutput(c *check.C) { + out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done") + id := strings.TrimSpace(out) + c.Assert(waitRun(id), check.IsNil) + + type info struct { + NGoroutines int + } + getNGoroutines := func() int { + var i info + status, b, err := sockRequest("GET", "/info", nil) + c.Assert(err, check.IsNil) + c.Assert(status, check.Equals, 200) + c.Assert(json.Unmarshal(b, &i), check.IsNil) + return i.NGoroutines + } + + nroutines := getNGoroutines() + + cmd := exec.Command(dockerBinary, "logs", "-f", id) + c.Assert(cmd.Start(), check.IsNil) + time.Sleep(200 * time.Millisecond) + c.Assert(cmd.Process.Kill(), check.IsNil) + + // NGoroutines is not updated right away, so we need to wait before failing + t := time.After(30 * time.Second) + for { + select { + case <-t: + if n := getNGoroutines(); n > nroutines { + c.Fatalf("leaked goroutines: expected less than or equal to %d, got: %d", nroutines, n) + } + default: + if n := getNGoroutines(); n <= nroutines { + return + } + time.Sleep(200 * time.Millisecond) + } + } +}