Fixes remote attach and exec to signal IdleTracker

 - Fixes issue where remote attach and exec only signaled the IdleTracker
   on errors. Needs to done anytime after connection has been hijacked
 - Fixes trying to send multiple http status codes to client
 - Changes pprof and API server shutdowns to run in parallel
 - Changes shutdown to run in sync.Once block

Signed-off-by: Jhon Honce <jhonce@redhat.com>

4 files changed, 79 insertions, 57 deletions

diff --git a/pkg/api/handlers/compat/containers_attach.go b/pkg/api/handlers/compat/containers_attach.go
index 4a1196c89..a4013469b 100644
--- a/pkg/api/handlers/compat/containers_attach.go
+++ b/pkg/api/handlers/compat/containers_attach.go
@@ -92,30 +92,29 @@ func AttachContainer(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	idleTracker := r.Context().Value("idletracker").(*idle.Tracker)
-	hijackChan := make(chan bool, 1)
+	logErr := func(e error) {
+		logrus.Error(errors.Wrapf(e, "error attaching to container %s", ctr.ID()))
+	}
 
 	// Perform HTTP attach.
 	// HTTPAttach will handle everything about the connection from here on
 	// (including closing it and writing errors to it).
-	if err := ctr.HTTPAttach(r, w, streams, detachKeys, nil, query.Stream, query.Logs, hijackChan); err != nil {
-		hijackComplete := <-hijackChan
+	hijackChan := make(chan bool, 1)
+	err = ctr.HTTPAttach(r, w, streams, detachKeys, nil, query.Stream, query.Logs, hijackChan)
 
-		// We can't really do anything about errors anymore. HTTPAttach
-		// should be writing them to the connection.
-		logrus.Errorf("Error attaching to container %s: %v", ctr.ID(), err)
+	if <-hijackChan {
+		// If connection was Hijacked, we have to signal it's being closed
+		t := r.Context().Value("idletracker").(*idle.Tracker)
+		defer t.Close()
 
-		if hijackComplete {
-			// We do need to tell the idle tracker that the
-			// connection has been closed, though. We can guarantee
-			// that is true after HTTPAttach exits.
-			idleTracker.Close()
-		} else {
-			// A hijack was not successfully completed. We need to
-			// report the error normally.
-			utils.InternalServerError(w, err)
+		if err != nil {
+			// Cannot report error to client as a 500 as the Upgrade set status to 101
+			logErr(err)
 		}
+	} else {
+		// If the Hijack failed we are going to assume we can still inform client of failure
+		utils.InternalServerError(w, err)
+		logErr(err)
 	}
-
 	logrus.Debugf("Attach for container %s completed successfully", ctr.ID())
 }
diff --git a/pkg/api/handlers/compat/exec.go b/pkg/api/handlers/compat/exec.go
index df51293c2..cc5db8efe 100644
--- a/pkg/api/handlers/compat/exec.go
+++ b/pkg/api/handlers/compat/exec.go
@@ -174,25 +174,26 @@ func ExecStartHandler(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	idleTracker := r.Context().Value("idletracker").(*idle.Tracker)
-	hijackChan := make(chan bool, 1)
+	logErr := func(e error) {
+		logrus.Error(errors.Wrapf(e, "error attaching to container %s exec session %s", sessionCtr.ID(), sessionID))
+	}
 
-	if err := sessionCtr.ExecHTTPStartAndAttach(sessionID, r, w, nil, nil, nil, hijackChan); err != nil {
-		hijackComplete := <-hijackChan
+	hijackChan := make(chan bool, 1)
+	err = sessionCtr.ExecHTTPStartAndAttach(sessionID, r, w, nil, nil, nil, hijackChan)
 
-		logrus.Errorf("Error attaching to container %s exec session %s: %v", sessionCtr.ID(), sessionID, err)
+	if <-hijackChan {
+		// If connection was Hijacked, we have to signal it's being closed
+		t := r.Context().Value("idletracker").(*idle.Tracker)
+		defer t.Close()
 
-		if hijackComplete {
-			// We do need to tell the idle tracker that the
-			// connection has been closed, though. We can guarantee
-			// that is true after HTTPAttach exits.
-			idleTracker.Close()
-		} else {
-			// A hijack was not successfully completed. We need to
-			// report the error normally.
-			utils.InternalServerError(w, err)
+		if err != nil {
+			// Cannot report error to client as a 500 as the Upgrade set status to 101
+			logErr(err)
 		}
+	} else {
+		// If the Hijack failed we are going to assume we can still inform client of failure
+		utils.InternalServerError(w, err)
+		logErr(err)
 	}
-
 	logrus.Debugf("Attach for container %s exec session %s completed successfully", sessionCtr.ID(), sessionID)
 }
diff --git a/pkg/api/server/idle/tracker.go b/pkg/api/server/idle/tracker.go
index 1b378c492..50e41b7bf 100644
--- a/pkg/api/server/idle/tracker.go
+++ b/pkg/api/server/idle/tracker.go
@@ -61,10 +61,14 @@ func (t *Tracker) ConnState(conn net.Conn, state http.ConnState) {
 		oldActive := t.ActiveConnections()
 
 		// Either the server or a hijacking handler has closed the http connection to a client
-		if _, found := t.managed[conn]; found {
-			delete(t.managed, conn)
-		} else {
+		if conn == nil {
 			t.hijacked-- // guarded by t.mux above
+		} else {
+			if _, found := t.managed[conn]; found {
+				delete(t.managed, conn)
+			} else {
+				logrus.Warnf("IdleTracker %p: StateClosed transition by un-managed connection", conn)
+			}
 		}
 
 		// Transitioned from any "active" connection to no connections
diff --git a/pkg/api/server/server.go b/pkg/api/server/server.go
index 09a9f6370..355a46fb7 100644
--- a/pkg/api/server/server.go
+++ b/pkg/api/server/server.go
@@ -8,9 +8,9 @@ import (
 	"net/http"
 	"os"
 	"os/signal"
-	"runtime"
 	goRuntime "runtime"
 	"strings"
+	"sync"
 	"syscall"
 	"time"
 
@@ -42,13 +42,19 @@ const (
 	UnlimitedServiceDuration = 0 * time.Second
 )
 
+// shutdownOnce ensures Shutdown() may safely be called from several go routines
+var shutdownOnce sync.Once
+
 // NewServer will create and configure a new API server with all defaults
 func NewServer(runtime *libpod.Runtime) (*APIServer, error) {
 	return newServer(runtime, DefaultServiceDuration, nil)
 }
 
 // NewServerWithSettings will create and configure a new API server using provided settings
-func NewServerWithSettings(runtime *libpod.Runtime, duration time.Duration, listener *net.Listener) (*APIServer, error) {
+func NewServerWithSettings(runtime *libpod.Runtime, duration time.Duration, listener *net.Listener) (
+	*APIServer,
+	error,
+) {
 	return newServer(runtime, duration, listener)
 }
 
@@ -180,7 +186,7 @@ func (s *APIServer) Serve() error {
 
 	go func() {
 		<-s.idleTracker.Done()
-		logrus.Debugf("API Server idle for %v", s.idleTracker.Duration)
+		logrus.Debugf("API Server idle for %s", s.idleTracker.Duration.Round(time.Second).String())
 		_ = s.Shutdown()
 	}()
 
@@ -224,31 +230,43 @@ func (s *APIServer) Serve() error {
 // Shutdown is a clean shutdown waiting on existing clients
 func (s *APIServer) Shutdown() error {
 	if s.idleTracker.Duration == UnlimitedServiceDuration {
-		logrus.Debug("APIServer.Shutdown ignored as Duration is UnlimitedService.")
+		logrus.Debug("APIServer.Shutdown ignored as Duration is UnlimitedService")
 		return nil
 	}
 
-	// Gracefully shutdown server(s), duration of wait same as idle window
-	// TODO: Should we really wait the idle window for shutdown?
-	ctx, cancel := context.WithTimeout(context.Background(), s.idleTracker.Duration)
-	defer cancel()
+	shutdownOnce.Do(func() {
+		if logrus.IsLevelEnabled(logrus.DebugLevel) {
+			_, file, line, _ := goRuntime.Caller(1)
+			logrus.Debugf("APIServer.Shutdown by %s:%d, %d/%d connection(s)",
+				file, line, s.idleTracker.ActiveConnections(), s.idleTracker.TotalConnections())
 
-	if logrus.IsLevelEnabled(logrus.DebugLevel) {
-		_, file, line, _ := runtime.Caller(1)
-		logrus.Debugf("APIServer.Shutdown by %s:%d, %d/%d connection(s)",
-			file, line, s.idleTracker.ActiveConnections(), s.idleTracker.TotalConnections())
-		if err := s.pprof.Shutdown(ctx); err != nil {
-			logrus.Warn("Failed to cleanly shutdown pprof Server: " + err.Error())
+			go func() {
+				ctx, cancel := context.WithTimeout(context.Background(), s.idleTracker.Duration)
+				go func() {
+					defer cancel()
+					if err := s.pprof.Shutdown(ctx); err != nil {
+						logrus.Warn(
+							errors.Wrapf(err, "failed to cleanly shutdown pprof Server"))
+					}
+				}()
+				<-ctx.Done()
+			}()
 		}
-	}
 
-	go func() {
-		err := s.Server.Shutdown(ctx)
-		if err != nil && err != context.Canceled && err != http.ErrServerClosed {
-			logrus.Error("Failed to cleanly shutdown APIServer: " + err.Error())
-		}
-	}()
-	<-ctx.Done()
+		// Gracefully shutdown server(s), duration of wait same as idle window
+		ctx, cancel := context.WithTimeout(context.Background(), s.idleTracker.Duration)
+		go func() {
+			defer cancel()
+
+			err := s.Server.Shutdown(ctx)
+			if err != nil && err != context.Canceled && err != http.ErrServerClosed {
+				logrus.Error(
+					errors.Wrapf(err, "failed to cleanly shutdown APIServer"))
+			}
+		}()
+		<-ctx.Done()
+	})
+
 	return nil
 }