[19.03 backport] test-fixes and improvements

cmd/dockerd/daemon.go

@@ -91,6 +91,8 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
 		return err
 	}
 
+	logrus.Info("Starting up")
+
 	cli.configFile = &opts.configFile
 	cli.flags = opts.flags
 
@@ -266,6 +268,7 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
 		return errors.Wrap(errAPI, "shutting down due to ServeAPI error")
 	}
 
+	logrus.Info("Daemon shutdown complete")
 	return nil
 }
 

cmd/dockerd/daemon_unix.go

@@ -20,6 +20,7 @@ import (
 	"github.com/docker/docker/pkg/homedir"
 	"github.com/docker/libnetwork/portallocator"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/sys/unix"
 )
 
@@ -152,6 +153,7 @@ func (cli *DaemonCli) initContainerD(ctx context.Context) (func(time.Duration) e
 			return nil, errors.Wrap(err, "could not determine whether the system containerd is running")
 		}
 		if !ok {
+			logrus.Debug("Containerd not running, starting daemon managed containerd")
 			opts, err := cli.getContainerdDaemonOpts()
 			if err != nil {
 				return nil, errors.Wrap(err, "failed to generate containerd options")
@@ -161,6 +163,7 @@ func (cli *DaemonCli) initContainerD(ctx context.Context) (func(time.Duration) e
 			if err != nil {
 				return nil, errors.Wrap(err, "failed to start containerd")
 			}
+			logrus.Debug("Started daemon managed containerd")
 			cli.Config.ContainerdAddr = r.Address()
 
 			// Try to wait for containerd to shutdown

integration-cli/docker_cli_ps_test.go

@@ -439,15 +439,11 @@ func (s *DockerSuite) TestPsListContainersFilterLabel(c *check.C) {
 func (s *DockerSuite) TestPsListContainersFilterExited(c *check.C) {
 	runSleepingContainer(c, "--name=sleep")
 
-	dockerCmd(c, "run", "--name", "zero1", "busybox", "true")
-	firstZero := getIDByName(c, "zero1")
-
-	dockerCmd(c, "run", "--name", "zero2", "busybox", "true")
-	secondZero := getIDByName(c, "zero2")
+	firstZero, _ := dockerCmd(c, "run", "-d", "busybox", "true")
+	secondZero, _ := dockerCmd(c, "run", "-d", "busybox", "true")
 
 	out, _, err := dockerCmdWithError("run", "--name", "nonzero1", "busybox", "false")
 	c.Assert(err, checker.NotNil, check.Commentf("Should fail.", out, err))
-
 	firstNonZero := getIDByName(c, "nonzero1")
 
 	out, _, err = dockerCmdWithError("run", "--name", "nonzero2", "busybox", "false")
@@ -456,17 +452,16 @@ func (s *DockerSuite) TestPsListContainersFilterExited(c *check.C) {
 
 	// filter containers by exited=0
 	out, _ = dockerCmd(c, "ps", "-a", "-q", "--no-trunc", "--filter=exited=0")
-	ids := strings.Split(strings.TrimSpace(out), "\n")
-	c.Assert(ids, checker.HasLen, 2, check.Commentf("Should be 2 zero exited containers got %d: %s", len(ids), out))
-	c.Assert(ids[0], checker.Equals, secondZero, check.Commentf("First in list should be %q, got %q", secondZero, ids[0]))
-	c.Assert(ids[1], checker.Equals, firstZero, check.Commentf("Second in list should be %q, got %q", firstZero, ids[1]))
+	c.Assert(out, checker.Contains, strings.TrimSpace(firstZero))
+	c.Assert(out, checker.Contains, strings.TrimSpace(secondZero))
+	c.Assert(out, checker.Not(checker.Contains), strings.TrimSpace(firstNonZero))
+	c.Assert(out, checker.Not(checker.Contains), strings.TrimSpace(secondNonZero))
 
 	out, _ = dockerCmd(c, "ps", "-a", "-q", "--no-trunc", "--filter=exited=1")
-	ids = strings.Split(strings.TrimSpace(out), "\n")
-	c.Assert(ids, checker.HasLen, 2, check.Commentf("Should be 2 zero exited containers got %d", len(ids)))
-	c.Assert(ids[0], checker.Equals, secondNonZero, check.Commentf("First in list should be %q, got %q", secondNonZero, ids[0]))
-	c.Assert(ids[1], checker.Equals, firstNonZero, check.Commentf("Second in list should be %q, got %q", firstNonZero, ids[1]))
-
+	c.Assert(out, checker.Contains, strings.TrimSpace(firstNonZero))
+	c.Assert(out, checker.Contains, strings.TrimSpace(secondNonZero))
+	c.Assert(out, checker.Not(checker.Contains), strings.TrimSpace(firstZero))
+	c.Assert(out, checker.Not(checker.Contains), strings.TrimSpace(secondZero))
 }
 
 func (s *DockerSuite) TestPsRightTagName(c *check.C) {

internal/test/daemon/daemon.go

@@ -281,41 +281,44 @@ func (d *Daemon) StartWithLogFile(out *os.File, providedArgs ...string) error {
 
 	d.Wait = wait
 
+	clientConfig, err := d.getClientConfig()
+	if err != nil {
+		return err
+	}
+	client := &http.Client{
+		Transport: clientConfig.transport,
+	}
+
+	req, err := http.NewRequest("GET", "/_ping", nil)
+	if err != nil {
+		return errors.Wrapf(err, "[%s] could not create new request", d.id)
+	}
+	req.URL.Host = clientConfig.addr
+	req.URL.Scheme = clientConfig.scheme
+
 	ticker := time.NewTicker(500 * time.Millisecond)
 	defer ticker.Stop()
 	tick := ticker.C
 
+	timeout := time.NewTimer(60 * time.Second) // timeout for the whole loop
+	defer timeout.Stop()
+
 	// make sure daemon is ready to receive requests
-	startTime := time.Now().Unix()
 	for {
 		d.log.Logf("[%s] waiting for daemon to start", d.id)
-		if time.Now().Unix()-startTime > 5 {
-			// After 5 seconds, give up
-			return errors.Errorf("[%s] Daemon exited and never started", d.id)
-		}
+
 		select {
-		case <-time.After(2 * time.Second):
-			return errors.Errorf("[%s] timeout: daemon does not respond", d.id)
+		case <-timeout.C:
+			return errors.Errorf("[%s] Daemon exited and never started", d.id)
 		case <-tick:
-			clientConfig, err := d.getClientConfig()
-			if err != nil {
-				return err
-			}
-
-			client := &http.Client{
-				Transport: clientConfig.transport,
-			}
-
-			req, err := http.NewRequest("GET", "/_ping", nil)
-			if err != nil {
-				return errors.Wrapf(err, "[%s] could not create new request", d.id)
-			}
-			req.URL.Host = clientConfig.addr
-			req.URL.Scheme = clientConfig.scheme
-			resp, err := client.Do(req)
+			ctx, cancel := context.WithTimeout(context.TODO(), 2*time.Second)
+			resp, err := client.Do(req.WithContext(ctx))
+			cancel()
 			if err != nil {
+				d.log.Logf("[%s] error pinging daemon on start: %v", d.id, err)
 				continue
 			}
+
 			resp.Body.Close()
 			if resp.StatusCode != http.StatusOK {
 				d.log.Logf("[%s] received status != 200 OK: %s\n", d.id, resp.Status)
@@ -411,12 +414,16 @@ func (d *Daemon) Stop(t testingT) {
 // If it timeouts, a SIGKILL is sent.
 // Stop will not delete the daemon directory. If a purged daemon is needed,
 // instantiate a new one with NewDaemon.
-func (d *Daemon) StopWithError() error {
+func (d *Daemon) StopWithError() (err error) {
 	if d.cmd == nil || d.Wait == nil {
 		return errDaemonNotStarted
 	}
-
 	defer func() {
+		if err == nil {
+			d.log.Logf("[%s] Daemon stopped", d.id)
+		} else {
+			d.log.Logf("[%s] Error when stopping daemon: %v", d.id, err)
+		}
 		d.logFile.Close()
 		d.cmd = nil
 	}()
@@ -426,12 +433,15 @@ func (d *Daemon) StopWithError() error {
 	defer ticker.Stop()
 	tick := ticker.C
 
+	d.log.Logf("[%s] Stopping daemon", d.id)
+
 	if err := d.cmd.Process.Signal(os.Interrupt); err != nil {
 		if strings.Contains(err.Error(), "os: process already finished") {
 			return errDaemonNotStarted
 		}
 		return errors.Errorf("could not send signal: %v", err)
 	}
+
 out1:
 	for {
 		select {