From 48786ba842b9ab6f19e68084714f846b9b26550a Mon Sep 17 00:00:00 2001 From: Brian Goff Date: Wed, 17 Apr 2019 16:04:25 -0700 Subject: [PATCH 1/3] Optimize test daemon startup This adds some logs, handles timers better, and sets a request timeout for the ping request. I'm not sure the ticker in that loop is what we really want since the ticker keeps ticking while we are (attempting) to make a request... but I opted to not change that for now. Signed-off-by: Brian Goff (cherry picked from commit 20ea8942b86b271f49c25aa70c53f7ca38571a2c) Signed-off-by: Sebastiaan van Stijn --- internal/test/daemon/daemon.go | 53 ++++++++++++++++++++-------------- 1 file changed, 31 insertions(+), 22 deletions(-) diff --git a/internal/test/daemon/daemon.go b/internal/test/daemon/daemon.go index cb94d80631..75f8215993 100644 --- a/internal/test/daemon/daemon.go +++ b/internal/test/daemon/daemon.go @@ -281,41 +281,46 @@ 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 - } + ctx, cancel := context.WithTimeout(context.TODO(), 2*time.Second) + req := req.WithContext(ctx) - 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) + 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) @@ -415,8 +420,8 @@ func (d *Daemon) StopWithError() error { if d.cmd == nil || d.Wait == nil { return errDaemonNotStarted } - defer func() { + d.log.Logf("[%s] Daemon stopped", d.id) d.logFile.Close() d.cmd = nil }() @@ -426,12 +431,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 { @@ -485,6 +493,7 @@ func (d *Daemon) Restart(t testingT, args ...string) { // RestartWithError will restart the daemon by first stopping it and then starting it. func (d *Daemon) RestartWithError(arg ...string) error { if err := d.StopWithError(); err != nil { + d.log.Logf("[%s] Error when stopping daemon: %v", d.id, err) return err } return d.StartWithError(arg...) From a24b9087ce87cf6696ddd63d72f2089408ef68f8 Mon Sep 17 00:00:00 2001 From: Brian Goff Date: Fri, 19 Apr 2019 09:06:59 -0700 Subject: [PATCH 2/3] Add log entries for daemon startup/shutdown Signed-off-by: Brian Goff (cherry picked from commit 595987fd082165b0c5739993b374bb5b6fa3f466) Signed-off-by: Sebastiaan van Stijn --- cmd/dockerd/daemon.go | 3 +++ cmd/dockerd/daemon_unix.go | 3 +++ internal/test/daemon/daemon.go | 13 +++++++------ 3 files changed, 13 insertions(+), 6 deletions(-) diff --git a/cmd/dockerd/daemon.go b/cmd/dockerd/daemon.go index fcb7b0b5b2..0359411af1 100644 --- a/cmd/dockerd/daemon.go +++ b/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 } diff --git a/cmd/dockerd/daemon_unix.go b/cmd/dockerd/daemon_unix.go index 8f74026d2e..a0f1b893b4 100644 --- a/cmd/dockerd/daemon_unix.go +++ b/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 diff --git a/internal/test/daemon/daemon.go b/internal/test/daemon/daemon.go index 75f8215993..bb8451db8c 100644 --- a/internal/test/daemon/daemon.go +++ b/internal/test/daemon/daemon.go @@ -312,9 +312,7 @@ func (d *Daemon) StartWithLogFile(out *os.File, providedArgs ...string) error { return errors.Errorf("[%s] Daemon exited and never started", d.id) case <-tick: ctx, cancel := context.WithTimeout(context.TODO(), 2*time.Second) - req := req.WithContext(ctx) - - resp, err := client.Do(req) + resp, err := client.Do(req.WithContext(ctx)) cancel() if err != nil { d.log.Logf("[%s] error pinging daemon on start: %v", d.id, err) @@ -416,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() { - d.log.Logf("[%s] Daemon stopped", d.id) + 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 }() @@ -493,7 +495,6 @@ func (d *Daemon) Restart(t testingT, args ...string) { // RestartWithError will restart the daemon by first stopping it and then starting it. func (d *Daemon) RestartWithError(arg ...string) error { if err := d.StopWithError(); err != nil { - d.log.Logf("[%s] Error when stopping daemon: %v", d.id, err) return err } return d.StartWithError(arg...) From 020bb75219ab327e4cff2f04431bae46faa37e4e Mon Sep 17 00:00:00 2001 From: Sebastiaan van Stijn Date: Wed, 5 Jun 2019 17:02:44 +0200 Subject: [PATCH 3/3] Harden TestPsListContainersFilterExited This test runs on a daemon also used by other tests so make sure we don't get failures if another test doesn't cleanup or is running in parallel. Signed-off-by: Sebastiaan van Stijn (cherry picked from commit 915acffdb4cf95b934dd9872c1f54ea4487819b7) Signed-off-by: Sebastiaan van Stijn --- integration-cli/docker_cli_ps_test.go | 25 ++++++++++--------------- 1 file changed, 10 insertions(+), 15 deletions(-) diff --git a/integration-cli/docker_cli_ps_test.go b/integration-cli/docker_cli_ps_test.go index f34cd0f8a8..cab75f4696 100644 --- a/integration-cli/docker_cli_ps_test.go +++ b/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) {