helpers.go 12.4 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35
/*
Copyright 2019 The Kubernetes Authors All rights reserved.

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

    http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

package integration

// These are test helpers that:
//
// - Accept *testing.T arguments (see helpers.go)
// - Are used in multiple tests
// - Must not compare test values

import (
	"bufio"
	"bytes"
	"context"
	"fmt"
	"io/ioutil"
	"os/exec"
	"strings"
	"testing"
	"time"

36
	"github.com/docker/machine/libmachine/state"
37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65
	"github.com/shirou/gopsutil/process"
	core "k8s.io/api/core/v1"
	meta "k8s.io/apimachinery/pkg/apis/meta/v1"
	"k8s.io/apimachinery/pkg/util/wait"
	"k8s.io/minikube/pkg/kapi"
)

// RunResult stores the result of an cmd.Run call
type RunResult struct {
	Stdout   *bytes.Buffer
	Stderr   *bytes.Buffer
	ExitCode int
	Args     []string
}

// Command returns a human readable command string that does not induce eye fatigue
func (rr RunResult) Command() string {
	var sb strings.Builder
	sb.WriteString(strings.TrimPrefix(rr.Args[0], "../../"))
	for _, a := range rr.Args[1:] {
		if strings.Contains(a, " ") {
			sb.WriteString(fmt.Sprintf(` "%s"`, a))
			continue
		}
		sb.WriteString(fmt.Sprintf(" %s", a))
	}
	return sb.String()
}

M
Medya Gh 已提交
66
// indentLines indents every line in a bytes.Buffer and returns it as string
67 68
func indentLines(b []byte) string {
	scanner := bufio.NewScanner(bytes.NewReader(b))
M
Medya Gh 已提交
69 70 71 72 73 74 75
	var lines string
	for scanner.Scan() {
		lines = lines + "\t" + scanner.Text() + "\n"
	}
	return lines
}

76
// Output returns human-readable output for an execution result
77
func (rr RunResult) Output() string {
78 79
	var sb strings.Builder
	if rr.Stdout.Len() > 0 {
80
		sb.WriteString(fmt.Sprintf("\n-- stdout --\n%s\n-- /stdout --", indentLines(rr.Stdout.Bytes())))
81 82
	}
	if rr.Stderr.Len() > 0 {
83
		sb.WriteString(fmt.Sprintf("\n** stderr ** \n%s\n** /stderr **", indentLines(rr.Stderr.Bytes())))
84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108
	}
	return sb.String()
}

// Run is a test helper to log a command being executed \_(ツ)_/¯
func Run(t *testing.T, cmd *exec.Cmd) (*RunResult, error) {
	t.Helper()
	rr := &RunResult{Args: cmd.Args}
	t.Logf("(dbg) Run:  %v", rr.Command())

	var outb, errb bytes.Buffer
	cmd.Stdout, rr.Stdout = &outb, &outb
	cmd.Stderr, rr.Stderr = &errb, &errb
	start := time.Now()
	err := cmd.Run()
	elapsed := time.Since(start)
	if err == nil {
		// Reduce log spam
		if elapsed > (1 * time.Second) {
			t.Logf("(dbg) Done: %v: (%s)", rr.Command(), elapsed)
		}
	} else {
		if exitError, ok := err.(*exec.ExitError); ok {
			rr.ExitCode = exitError.ExitCode()
		}
109
		t.Logf("(dbg) Non-zero exit: %v: %v (%s)\n%s", rr.Command(), err, elapsed, rr.Output())
110 111 112 113 114 115 116 117 118 119 120 121 122 123
	}
	return rr, err
}

// StartSession stores the result of an cmd.Start call
type StartSession struct {
	Stdout *bufio.Reader
	Stderr *bufio.Reader
	cmd    *exec.Cmd
}

// Start starts a process in the background, streaming output
func Start(t *testing.T, cmd *exec.Cmd) (*StartSession, error) {
	t.Helper()
124
	t.Logf("(dbg) daemon: %v", cmd.Args)
125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141

	stdoutPipe, err := cmd.StdoutPipe()
	if err != nil {
		t.Fatalf("stdout pipe failed: %v %v", cmd.Args, err)
	}
	stderrPipe, err := cmd.StderrPipe()
	if err != nil {
		t.Fatalf("stderr pipe failed: %v %v", cmd.Args, err)
	}

	sr := &StartSession{Stdout: bufio.NewReader(stdoutPipe), Stderr: bufio.NewReader(stderrPipe), cmd: cmd}
	return sr, cmd.Start()
}

// Stop stops the started process
func (ss *StartSession) Stop(t *testing.T) {
	t.Helper()
142
	t.Logf("(dbg) stopping %s ...", ss.cmd.Args)
143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174
	if ss.cmd.Process == nil {
		t.Logf("%s has a nil Process. Maybe it's dead? How weird!", ss.cmd.Args)
		return
	}
	killProcessFamily(t, ss.cmd.Process.Pid)
	if t.Failed() {
		if ss.Stdout.Size() > 0 {
			stdout, err := ioutil.ReadAll(ss.Stdout)
			if err != nil {
				t.Logf("read stdout failed: %v", err)
			}
			t.Logf("(dbg) %s stdout:\n%s", ss.cmd.Args, stdout)
		}
		if ss.Stderr.Size() > 0 {
			stderr, err := ioutil.ReadAll(ss.Stderr)
			if err != nil {
				t.Logf("read stderr failed: %v", err)
			}
			t.Logf("(dbg) %s stderr:\n%s", ss.cmd.Args, stderr)
		}
	}
}

// Cleanup cleans up after a test run
func Cleanup(t *testing.T, profile string, cancel context.CancelFunc) {
	// No helper because it makes the call log confusing.
	if *cleanup {
		_, err := Run(t, exec.Command(Target(), "delete", "-p", profile))
		if err != nil {
			t.Logf("failed cleanup: %v", err)
		}
	} else {
175
		t.Logf("skipping cleanup of %s (--cleanup=false)", profile)
176 177 178 179 180 181 182
	}
	cancel()
}

// CleanupWithLogs cleans up after a test run, fetching logs and deleting the profile
func CleanupWithLogs(t *testing.T, profile string, cancel context.CancelFunc) {
	t.Helper()
183 184 185 186 187 188
	if !t.Failed() {
		Cleanup(t, profile, cancel)
		return
	}

	t.Logf("*** %s FAILED at %s", t.Name(), time.Now())
189
	PostMortemLogs(t, profile)
190 191
	Cleanup(t, profile, cancel)
}
192

193 194 195 196 197 198 199 200 201 202
// PostMortemLogs shows logs for debugging a failed cluster
func PostMortemLogs(t *testing.T, profile string) {
	if !t.Failed() {
		return
	}

	if !*postMortemLogs {
		t.Logf("post-mortem logs disabled, oh-well!")
	}

M
Medya Gh 已提交
203 204 205
	t.Logf("-----------------------post-mortem--------------------------------")

	if DockerDriver() {
S
Sharif Elgamal 已提交
206
		t.Logf("======>  post-mortem[%s]: docker inspect <======", t.Name())
207
		rr, err := Run(t, exec.Command("docker", "inspect", profile))
M
Medya Gh 已提交
208
		if err != nil {
209
			t.Logf("failed to get docker inspect: %v", err)
M
Medya Gh 已提交
210 211
		} else {
			t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Output())
M
Medya Gh 已提交
212 213
		}
	}
214

215
	st := Status(context.Background(), t, Target(), profile, "Host")
216
	if st != state.Running.String() {
217
		t.Logf("%q host is not running, skipping log retrieval (state=%q)", profile, st)
218 219 220
		return
	}
	t.Logf("<<< %s FAILED: start of post-mortem logs <<<", t.Name())
T
Thomas Stromberg 已提交
221
	t.Logf("======>  post-mortem[%s]: minikube logs <======", t.Name())
T
Thomas Stromberg 已提交
222

223
	rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "-n", "25"))
224 225 226 227
	if err != nil {
		t.Logf("failed logs error: %v", err)
		return
	}
228
	t.Logf("%s logs: %s", t.Name(), rr.Output())
229

230 231 232 233 234 235
	st = Status(context.Background(), t, Target(), profile, "APIServer")
	if st != state.Running.String() {
		t.Logf("%q apiserver is not running, skipping kubectl commands (state=%q)", profile, st)
		return
	}

236 237
	// Get non-running pods. NOTE: This does not yet contain pods which are "running", but not "ready"
	rr, rerr := Run(t, exec.Command("kubectl", "--context", profile, "get", "po", "-o=jsonpath={.items[*].metadata.name}", "-A", "--field-selector=status.phase!=Running"))
238 239 240
	if rerr != nil {
		t.Logf("%s: %v", rr.Command(), rerr)
		return
241
	}
242 243
	notRunning := strings.Split(rr.Stdout.String(), " ")
	t.Logf("non-running pods: %s", strings.Join(notRunning, " "))
244

245
	t.Logf("======> post-mortem[%s]: describe non-running pods <======", t.Name())
246

247 248 249 250 251
	args := append([]string{"--context", profile, "describe", "pod"}, notRunning...)
	rr, rerr = Run(t, exec.Command("kubectl", args...))
	if rerr != nil {
		t.Logf("%s: %v", rr.Command(), rerr)
		return
252
	}
253
	t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Output())
254

255
	t.Logf("<<< %s FAILED: end of post-mortem logs <<<", t.Name())
M
Medya Gh 已提交
256
	t.Logf("---------------------/post-mortem---------------------------------")
257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294
}

// podStatusMsg returns a human-readable pod status, for generating debug status
func podStatusMsg(pod core.Pod) string {
	var sb strings.Builder
	sb.WriteString(fmt.Sprintf("%q [%s] %s", pod.ObjectMeta.GetName(), pod.ObjectMeta.GetUID(), pod.Status.Phase))
	for i, c := range pod.Status.Conditions {
		if c.Reason != "" {
			if i == 0 {
				sb.WriteString(": ")
			} else {
				sb.WriteString(" / ")
			}
			sb.WriteString(fmt.Sprintf("%s:%s", c.Type, c.Reason))
		}
		if c.Message != "" {
			sb.WriteString(fmt.Sprintf(" (%s)", c.Message))
		}
	}
	return sb.String()
}

// PodWait waits for pods to achieve a running state.
func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selector string, timeout time.Duration) ([]string, error) {
	t.Helper()
	client, err := kapi.Client(profile)
	if err != nil {
		return nil, err
	}

	// For example: kubernetes.io/minikube-addons=gvisor
	listOpts := meta.ListOptions{LabelSelector: selector}
	minUptime := 5 * time.Second
	podStart := time.Time{}
	foundNames := map[string]bool{}
	lastMsg := ""

	start := time.Now()
295
	t.Logf("(dbg) %s: waiting %s for pods matching %q in namespace %q ...", t.Name(), timeout, selector, ns)
296 297 298
	f := func() (bool, error) {
		pods, err := client.CoreV1().Pods(ns).List(listOpts)
		if err != nil {
299
			t.Logf("%s: WARNING: pod list for %q %q returned: %v", t.Name(), ns, selector, err)
T
tstromberg 已提交
300 301 302
			// Don't return the error upwards so that this is retried, in case the apiserver is rescheduled
			podStart = time.Time{}
			return false, nil
303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323
		}
		if len(pods.Items) == 0 {
			podStart = time.Time{}
			return false, nil
		}

		for _, pod := range pods.Items {
			foundNames[pod.ObjectMeta.Name] = true
			msg := podStatusMsg(pod)
			// Prevent spamming logs with identical messages
			if msg != lastMsg {
				t.Log(msg)
				lastMsg = msg
			}
			// Successful termination of a short-lived process, will not be restarted
			if pod.Status.Phase == core.PodSucceeded {
				return true, nil
			}
			// Long-running process state
			if pod.Status.Phase != core.PodRunning {
				if !podStart.IsZero() {
324
					t.Logf("%s: WARNING: %s was running %s ago - may be unstable", t.Name(), selector, time.Since(podStart))
325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340
				}
				podStart = time.Time{}
				return false, nil
			}

			if podStart.IsZero() {
				podStart = time.Now()
			}

			if time.Since(podStart) > minUptime {
				return true, nil
			}
		}
		return false, nil
	}

341
	err = wait.PollImmediate(1*time.Second, timeout, f)
342 343 344 345 346 347
	names := []string{}
	for n := range foundNames {
		names = append(names, n)
	}

	if err == nil {
348
		t.Logf("(dbg) %s: %s healthy within %s", t.Name(), selector, time.Since(start))
349 350 351
		return names, nil
	}

352
	t.Logf("***** %s: pod %q failed to start within %s: %v ****", t.Name(), selector, timeout, err)
353 354 355 356
	showPodLogs(ctx, t, profile, ns, names)
	return names, fmt.Errorf("%s: %v", fmt.Sprintf("%s within %s", selector, timeout), err)
}

357 358 359 360 361 362 363 364 365 366 367
// Status returns a minikube component status as a string
func Status(ctx context.Context, t *testing.T, path string, profile string, key string) string {
	t.Helper()
	// Reminder of useful keys: "Host", "Kubelet", "APIServer"
	rr, err := Run(t, exec.CommandContext(ctx, path, "status", fmt.Sprintf("--format={{.%s}}", key), "-p", profile))
	if err != nil {
		t.Logf("status error: %v (may be ok)", err)
	}
	return strings.TrimSpace(rr.Stdout.String())
}

368 369
// showPodLogs logs debug info for pods
func showPodLogs(ctx context.Context, t *testing.T, profile string, ns string, names []string) {
370 371 372 373 374 375 376
	t.Helper()
	st := Status(context.Background(), t, Target(), profile, "APIServer")
	if st != state.Running.String() {
		t.Logf("%q apiserver is not running, skipping kubectl commands (state=%q)", profile, st)
		return
	}

377
	t.Logf("%s: showing logs for failed pods as of %s", t.Name(), time.Now())
378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424

	for _, name := range names {
		rr, err := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "describe", "po", name, "-n", ns))
		if err != nil {
			t.Logf("%s: %v", rr.Command(), err)
		} else {
			t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout)
		}

		rr, err = Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "logs", name, "-n", ns))
		if err != nil {
			t.Logf("%s: %v", rr.Command(), err)
		} else {
			t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout)
		}
	}
}

// MaybeParallel sets that the test should run in parallel
func MaybeParallel(t *testing.T) {
	t.Helper()
	// TODO: Allow paralellized tests on "none" that do not require independent clusters
	if NoneDriver() {
		return
	}
	t.Parallel()
}

// killProcessFamily kills a pid and all of its children
func killProcessFamily(t *testing.T, pid int) {
	parent, err := process.NewProcess(int32(pid))
	if err != nil {
		t.Logf("unable to find parent, assuming dead: %v", err)
		return
	}
	procs := []*process.Process{}
	children, err := parent.Children()
	if err == nil {
		procs = append(procs, children...)
	}
	procs = append(procs, parent)

	for _, p := range procs {
		if err := p.Terminate(); err != nil {
			t.Logf("unable to terminate pid %d: %v", p.Pid, err)
			continue
		}
425 426
		// Allow process a chance to cleanup before instant death.
		time.Sleep(100 * time.Millisecond)
427 428 429 430 431 432
		if err := p.Kill(); err != nil {
			t.Logf("unable to kill pid %d: %v", p.Pid, err)
			continue
		}
	}
}