Fix CI flake on time of shutdown for API service

* Increase timeout for tests to 10s
* To aid in debugging add PID to shutdown package logging
* Added new message for forced service shutdown
* Always wait for HTTP server to shutdown, duration of 0 not friendly
  to clients

Note: The log event

"IdleTracker: StateClosed transition by connection marked un-managed"

denotes a TCP connection has been initiated but no HTTP request was sent.
And is expected during these tests.

Fixes #11921

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

4 files changed, 31 insertions, 20 deletions

diff --git a/cmd/podman/system/service_abi.go b/cmd/podman/system/service_abi.go
index 0a4be6aea..b9bd7538f 100644
--- a/cmd/podman/system/service_abi.go
+++ b/cmd/podman/system/service_abi.go
@@ -93,7 +93,7 @@ func restService(flags *pflag.FlagSet, cfg *entities.PodmanConfig, opts entities
 		return err
 	}
 	defer func() {
-		if err := server.Shutdown(false); err != nil {
+		if err := server.Shutdown(true); err != nil {
 			logrus.Warnf("Error when stopping API service: %s", err)
 		}
 	}()
diff --git a/libpod/shutdown/handler.go b/libpod/shutdown/handler.go
index b0feafa0b..9add05c9c 100644
--- a/libpod/shutdown/handler.go
+++ b/libpod/shutdown/handler.go
@@ -5,9 +5,10 @@ import (
 	"os/signal"
 	"sync"
 	"syscall"
+	"time"
 
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
+	logrusImport "github.com/sirupsen/logrus"
 )
 
 var (
@@ -25,6 +26,7 @@ var (
 	// Ordering that on-shutdown handlers will be invoked.
 	handlerOrder    []string
 	shutdownInhibit sync.RWMutex
+	logrus          = logrusImport.WithField("PID", os.Getpid())
 )
 
 // Start begins handling SIGTERM and SIGINT and will run the given on-signal
@@ -44,25 +46,31 @@ func Start() error {
 	go func() {
 		select {
 		case <-cancelChan:
+			logrus.Infof("Received shutdown.Stop(), terminating!")
 			signal.Stop(sigChan)
 			close(sigChan)
 			close(cancelChan)
 			stopped = true
 			return
 		case sig := <-sigChan:
-			logrus.Infof("Received shutdown signal %v, terminating!", sig)
+			logrus.Infof("Received shutdown signal %q, terminating!", sig.String())
 			shutdownInhibit.Lock()
 			handlerLock.Lock()
+
 			for _, name := range handlerOrder {
 				handler, ok := handlers[name]
 				if !ok {
-					logrus.Errorf("Shutdown handler %s definition not found!", name)
+					logrus.Errorf("Shutdown handler %q definition not found!", name)
 					continue
 				}
-				logrus.Infof("Invoking shutdown handler %s", name)
+
+				logrus.Infof("Invoking shutdown handler %q", name)
+				start := time.Now()
 				if err := handler(sig); err != nil {
-					logrus.Errorf("Running shutdown handler %s: %v", name, err)
+					logrus.Errorf("Running shutdown handler %q: %v", name, err)
 				}
+				logrus.Debugf("Completed shutdown handler %q, duration %v", name,
+					time.Since(start).Round(time.Second))
 			}
 			handlerLock.Unlock()
 			shutdownInhibit.Unlock()
diff --git a/pkg/api/server/server.go b/pkg/api/server/server.go
index 6e9578cd1..8c5c7aeeb 100644
--- a/pkg/api/server/server.go
+++ b/pkg/api/server/server.go
@@ -207,7 +207,7 @@ func (s *APIServer) setupSystemd() {
 func (s *APIServer) Serve() error {
 	s.setupPprof()
 
-	if err := shutdown.Register("server", func(sig os.Signal) error {
+	if err := shutdown.Register("service", func(sig os.Signal) error {
 		return s.Shutdown(true)
 	}); err != nil {
 		return err
@@ -272,20 +272,24 @@ func (s *APIServer) setupPprof() {
 
 // Shutdown is a clean shutdown waiting on existing clients
 func (s *APIServer) Shutdown(halt bool) error {
-	if s.idleTracker.Duration == UnlimitedServiceDuration && !halt {
-		logrus.Debug("API service shutdown request ignored as Duration is UnlimitedService")
+	switch {
+	case halt:
+		logrus.Debug("API service forced shutdown, ignoring timeout Duration")
+	case s.idleTracker.Duration == UnlimitedServiceDuration:
+		logrus.Debug("API service shutdown request ignored as timeout Duration is UnlimitedService")
 		return nil
 	}
 
 	shutdownOnce.Do(func() {
-		if logrus.IsLevelEnabled(logrus.DebugLevel) {
-			_, file, line, _ := runtime.Caller(1)
-			logrus.Debugf("API service shutdown by %s:%d, %d/%d connection(s)",
-				file, line, s.idleTracker.ActiveConnections(), s.idleTracker.TotalConnections())
-		}
+		logrus.Debugf("API service shutdown, %d/%d connection(s)",
+			s.idleTracker.ActiveConnections(), s.idleTracker.TotalConnections())
 
 		// Gracefully shutdown server(s), duration of wait same as idle window
-		ctx, cancel := context.WithTimeout(context.Background(), s.idleTracker.Duration)
+		deadline := 1 * time.Second
+		if s.idleTracker.Duration > 0 {
+			deadline = s.idleTracker.Duration
+		}
+		ctx, cancel := context.WithTimeout(context.Background(), deadline)
 		go func() {
 			defer cancel()
 
@@ -296,7 +300,6 @@ func (s *APIServer) Shutdown(halt bool) error {
 		}()
 		<-ctx.Done()
 	})
-
 	return nil
 }
 
diff --git a/test/e2e/system_service_test.go b/test/e2e/system_service_test.go
index 684ac56b4..9a4d687c3 100644
--- a/test/e2e/system_service_test.go
+++ b/test/e2e/system_service_test.go
@@ -65,7 +65,7 @@ var _ = Describe("podman system service", func() {
 
 			pprofPort := randomPort()
 			session := podmanTest.Podman([]string{
-				"system", "service", "--log-level=info", "--time=0",
+				"system", "service", "--log-level=debug", "--time=0",
 				"--pprof-address=localhost:" + pprofPort, address.String(),
 			})
 			defer session.Kill()
@@ -91,7 +91,7 @@ var _ = Describe("podman system service", func() {
 			Expect(body).ShouldNot(BeEmpty())
 
 			session.Interrupt().Wait(2 * time.Second)
-			Eventually(session, 2).Should(Exit(1))
+			Eventually(session).Should(Exit(1))
 		})
 
 		It("are not available", func() {
@@ -103,7 +103,7 @@ var _ = Describe("podman system service", func() {
 			}
 
 			session := podmanTest.Podman([]string{
-				"system", "service", "--log-level=info", "--time=0", address.String(),
+				"system", "service", "--log-level=debug", "--time=0", address.String(),
 			})
 			defer session.Kill()
 
@@ -113,7 +113,7 @@ var _ = Describe("podman system service", func() {
 			Expect(session.Err.Contents()).ShouldNot(ContainSubstring(magicComment))
 
 			session.Interrupt().Wait(2 * time.Second)
-			Eventually(session, 2).Should(Exit(1))
+			Eventually(session).Should(Exit(1))
 		})
 	})
 })