Browse code

Merge pull request #39105 from cpuguy83/optimize_test_daemon_startup

Optimize test daemon startup

Kirill Kolyshkin authored on 2019/05/24 03:58:47
Showing 3 changed files
... ...
@@ -91,6 +91,8 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
91 91
 		return err
92 92
 	}
93 93
 
94
+	logrus.Info("Starting up")
95
+
94 96
 	cli.configFile = &opts.configFile
95 97
 	cli.flags = opts.flags
96 98
 
... ...
@@ -266,6 +268,7 @@ func (cli *DaemonCli) start(opts *daemonOptions) (err error) {
266 266
 		return errors.Wrap(errAPI, "shutting down due to ServeAPI error")
267 267
 	}
268 268
 
269
+	logrus.Info("Daemon shutdown complete")
269 270
 	return nil
270 271
 }
271 272
 
... ...
@@ -20,6 +20,7 @@ import (
20 20
 	"github.com/docker/docker/pkg/homedir"
21 21
 	"github.com/docker/libnetwork/portallocator"
22 22
 	"github.com/pkg/errors"
23
+	"github.com/sirupsen/logrus"
23 24
 	"golang.org/x/sys/unix"
24 25
 )
25 26
 
... ...
@@ -152,6 +153,7 @@ func (cli *DaemonCli) initContainerD(ctx context.Context) (func(time.Duration) e
152 152
 			return nil, errors.Wrap(err, "could not determine whether the system containerd is running")
153 153
 		}
154 154
 		if !ok {
155
+			logrus.Debug("Containerd not running, starting daemon managed containerd")
155 156
 			opts, err := cli.getContainerdDaemonOpts()
156 157
 			if err != nil {
157 158
 				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
161 161
 			if err != nil {
162 162
 				return nil, errors.Wrap(err, "failed to start containerd")
163 163
 			}
164
+			logrus.Debug("Started daemon managed containerd")
164 165
 			cli.Config.ContainerdAddr = r.Address()
165 166
 
166 167
 			// Try to wait for containerd to shutdown
... ...
@@ -290,41 +290,44 @@ func (d *Daemon) StartWithLogFile(out *os.File, providedArgs ...string) error {
290 290
 
291 291
 	d.Wait = wait
292 292
 
293
+	clientConfig, err := d.getClientConfig()
294
+	if err != nil {
295
+		return err
296
+	}
297
+	client := &http.Client{
298
+		Transport: clientConfig.transport,
299
+	}
300
+
301
+	req, err := http.NewRequest("GET", "/_ping", nil)
302
+	if err != nil {
303
+		return errors.Wrapf(err, "[%s] could not create new request", d.id)
304
+	}
305
+	req.URL.Host = clientConfig.addr
306
+	req.URL.Scheme = clientConfig.scheme
307
+
293 308
 	ticker := time.NewTicker(500 * time.Millisecond)
294 309
 	defer ticker.Stop()
295 310
 	tick := ticker.C
296 311
 
312
+	timeout := time.NewTimer(60 * time.Second) // timeout for the whole loop
313
+	defer timeout.Stop()
314
+
297 315
 	// make sure daemon is ready to receive requests
298
-	startTime := time.Now().Unix()
299 316
 	for {
300 317
 		d.log.Logf("[%s] waiting for daemon to start", d.id)
301
-		if time.Now().Unix()-startTime > 5 {
302
-			// After 5 seconds, give up
303
-			return errors.Errorf("[%s] Daemon exited and never started", d.id)
304
-		}
318
+
305 319
 		select {
306
-		case <-time.After(2 * time.Second):
307
-			return errors.Errorf("[%s] timeout: daemon does not respond", d.id)
320
+		case <-timeout.C:
321
+			return errors.Errorf("[%s] Daemon exited and never started", d.id)
308 322
 		case <-tick:
309
-			clientConfig, err := d.getClientConfig()
310
-			if err != nil {
311
-				return err
312
-			}
313
-
314
-			client := &http.Client{
315
-				Transport: clientConfig.transport,
316
-			}
317
-
318
-			req, err := http.NewRequest("GET", "/_ping", nil)
319
-			if err != nil {
320
-				return errors.Wrapf(err, "[%s] could not create new request", d.id)
321
-			}
322
-			req.URL.Host = clientConfig.addr
323
-			req.URL.Scheme = clientConfig.scheme
324
-			resp, err := client.Do(req)
323
+			ctx, cancel := context.WithTimeout(context.TODO(), 2*time.Second)
324
+			resp, err := client.Do(req.WithContext(ctx))
325
+			cancel()
325 326
 			if err != nil {
327
+				d.log.Logf("[%s] error pinging daemon on start: %v", d.id, err)
326 328
 				continue
327 329
 			}
330
+
328 331
 			resp.Body.Close()
329 332
 			if resp.StatusCode != http.StatusOK {
330 333
 				d.log.Logf("[%s] received status != 200 OK: %s\n", d.id, resp.Status)
... ...
@@ -420,12 +423,16 @@ func (d *Daemon) Stop(t testingT) {
420 420
 // If it timeouts, a SIGKILL is sent.
421 421
 // Stop will not delete the daemon directory. If a purged daemon is needed,
422 422
 // instantiate a new one with NewDaemon.
423
-func (d *Daemon) StopWithError() error {
423
+func (d *Daemon) StopWithError() (err error) {
424 424
 	if d.cmd == nil || d.Wait == nil {
425 425
 		return errDaemonNotStarted
426 426
 	}
427
-
428 427
 	defer func() {
428
+		if err == nil {
429
+			d.log.Logf("[%s] Daemon stopped", d.id)
430
+		} else {
431
+			d.log.Logf("[%s] Error when stopping daemon: %v", d.id, err)
432
+		}
429 433
 		d.logFile.Close()
430 434
 		d.cmd = nil
431 435
 	}()
... ...
@@ -435,12 +442,15 @@ func (d *Daemon) StopWithError() error {
435 435
 	defer ticker.Stop()
436 436
 	tick := ticker.C
437 437
 
438
+	d.log.Logf("[%s] Stopping daemon", d.id)
439
+
438 440
 	if err := d.cmd.Process.Signal(os.Interrupt); err != nil {
439 441
 		if strings.Contains(err.Error(), "os: process already finished") {
440 442
 			return errDaemonNotStarted
441 443
 		}
442 444
 		return errors.Errorf("could not send signal: %v", err)
443 445
 	}
446
+
444 447
 out1:
445 448
 	for {
446 449
 		select {