consul/command/debug/debug_test.go

package debug

import (
	"archive/tar"
	"bufio"
	"compress/gzip"
	"fmt"
	"io"
	"io/ioutil"
	"os"
	"path/filepath"
	"regexp"
	"strings"
	"testing"
	"time"

	"github.com/mitchellh/cli"
	"github.com/stretchr/testify/require"

	"github.com/google/pprof/profile"
	"github.com/hashicorp/consul/agent"
	"github.com/hashicorp/consul/sdk/testutil"
	"github.com/hashicorp/consul/testrpc"
)

func TestDebugCommand_noTabs(t *testing.T) {
	t.Parallel()

	if strings.ContainsRune(New(cli.NewMockUi(), nil).Help(), '\t') {
		t.Fatal("help has tabs")
	}
}

func TestDebugCommand(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	testDir := testutil.TempDir(t, "debug")

	a := agent.NewTestAgent(t, `
	enable_debug = true
	`)

	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := fmt.Sprintf("%s/debug", testDir)
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		"-duration=100ms",
		"-interval=50ms",
	}

	code := cmd.Run(args)

	if code != 0 {
		t.Errorf("should exit 0, got code: %d", code)
	}

	errOutput := ui.ErrorWriter.String()
	if errOutput != "" {
		t.Errorf("expected no error output, got %q", errOutput)
	}
}

func TestDebugCommand_Archive(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	testDir := testutil.TempDir(t, "debug")

	a := agent.NewTestAgent(t, `
	enable_debug = true
	`)
	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := fmt.Sprintf("%s/debug", testDir)
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		"-capture=agent",
	}

	if code := cmd.Run(args); code != 0 {
		t.Fatalf("should exit 0, got code: %d", code)
	}

	archivePath := fmt.Sprintf("%s%s", outputPath, debugArchiveExtension)
	file, err := os.Open(archivePath)
	if err != nil {
		t.Fatalf("failed to open archive: %s", err)
	}
	gz, err := gzip.NewReader(file)
	if err != nil {
		t.Fatalf("failed to read gzip archive: %s", err)
	}
	tr := tar.NewReader(gz)

	for {
		h, err := tr.Next()

		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("failed to read file in archive: %s", err)
		}

		// ignore the outer directory
		if h.Name == "debug" {
			continue
		}

		// should only contain this one capture target
		if h.Name != "debug/agent.json" && h.Name != "debug/index.json" {
			t.Fatalf("archive contents do not match: %s", h.Name)
		}
	}

}

func TestDebugCommand_ArgsBad(t *testing.T) {
	t.Parallel()

	ui := cli.NewMockUi()
	cmd := New(ui, nil)

	args := []string{
		"foo",
		"bad",
	}

	if code := cmd.Run(args); code == 0 {
		t.Fatalf("should exit non-zero, got code: %d", code)
	}

	errOutput := ui.ErrorWriter.String()
	if !strings.Contains(errOutput, "Too many arguments") {
		t.Errorf("expected error output, got %q", errOutput)
	}
}

func TestDebugCommand_InvalidFlags(t *testing.T) {
	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := ""
	args := []string{
		"-invalid=value",
		"-output=" + outputPath,
		"-duration=100ms",
		"-interval=50ms",
	}

	if code := cmd.Run(args); code == 0 {
		t.Fatalf("should exit non-zero, got code: %d", code)
	}

	errOutput := ui.ErrorWriter.String()
	if !strings.Contains(errOutput, "==> Error parsing flags: flag provided but not defined:") {
		t.Errorf("expected error output, got %q", errOutput)
	}
}

func TestDebugCommand_OutputPathBad(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	t.Parallel()

	a := agent.NewTestAgent(t, "")
	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := ""
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		"-duration=100ms",
		"-interval=50ms",
	}

	if code := cmd.Run(args); code == 0 {
		t.Fatalf("should exit non-zero, got code: %d", code)
	}

	errOutput := ui.ErrorWriter.String()
	if !strings.Contains(errOutput, "no such file or directory") {
		t.Errorf("expected error output, got %q", errOutput)
	}
}

func TestDebugCommand_OutputPathExists(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	testDir := testutil.TempDir(t, "debug")

	a := agent.NewTestAgent(t, "")
	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := fmt.Sprintf("%s/debug", testDir)
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		"-duration=100ms",
		"-interval=50ms",
	}

	// Make a directory that conflicts with the output path
	err := os.Mkdir(outputPath, 0755)
	if err != nil {
		t.Fatalf("duplicate test directory creation failed: %s", err)
	}

	if code := cmd.Run(args); code == 0 {
		t.Fatalf("should exit non-zero, got code: %d", code)
	}

	errOutput := ui.ErrorWriter.String()
	if !strings.Contains(errOutput, "directory already exists") {
		t.Errorf("expected error output, got %q", errOutput)
	}
}

func TestDebugCommand_CaptureTargets(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	cases := map[string]struct {
		// used in -target param
		targets []string
		// existence verified after execution
		files []string
		// non-existence verified after execution
		excludedFiles []string
	}{
		"single": {
			[]string{"agent"},
			[]string{"agent.json"},
			[]string{"host.json", "cluster.json"},
		},
		"static": {
			[]string{"agent", "host", "cluster"},
			[]string{"agent.json", "host.json", "cluster.json"},
			[]string{"*/metrics.json"},
		},
		"metrics-only": {
			[]string{"metrics"},
			[]string{"*/metrics.json"},
			[]string{"agent.json", "host.json", "cluster.json"},
		},
		"all-but-pprof": {
			[]string{
				"metrics",
				"logs",
				"host",
				"agent",
				"cluster",
			},
			[]string{
				"host.json",
				"agent.json",
				"cluster.json",
				"*/metrics.json",
				"*/consul.log",
			},
			[]string{},
		},
	}

	for name, tc := range cases {
		testDir := testutil.TempDir(t, "debug")

		a := agent.NewTestAgent(t, `
		enable_debug = true
		`)

		defer a.Shutdown()
		testrpc.WaitForLeader(t, a.RPC, "dc1")

		ui := cli.NewMockUi()
		cmd := New(ui, nil)
		cmd.validateTiming = false

		outputPath := fmt.Sprintf("%s/debug-%s", testDir, name)
		args := []string{
			"-http-addr=" + a.HTTPAddr(),
			"-output=" + outputPath,
			"-archive=false",
			"-duration=100ms",
			"-interval=50ms",
		}
		for _, t := range tc.targets {
			args = append(args, "-capture="+t)
		}

		if code := cmd.Run(args); code != 0 {
			t.Fatalf("should exit 0, got code: %d", code)
		}

		errOutput := ui.ErrorWriter.String()
		if errOutput != "" {
			t.Errorf("expected no error output, got %q", errOutput)
		}

		// Ensure the debug data was written
		_, err := os.Stat(outputPath)
		if err != nil {
			t.Fatalf("output path should exist: %s", err)
		}

		// Ensure the captured static files exist
		for _, f := range tc.files {
			path := fmt.Sprintf("%s/%s", outputPath, f)
			// Glob ignores file system errors
			fs, _ := filepath.Glob(path)
			if len(fs) <= 0 {
				t.Fatalf("%s: output data should exist for %s", name, f)
			}
		}

		// Ensure any excluded files do not exist
		for _, f := range tc.excludedFiles {
			path := fmt.Sprintf("%s/%s", outputPath, f)
			// Glob ignores file system errors
			fs, _ := filepath.Glob(path)
			if len(fs) > 0 {
				t.Fatalf("%s: output data should not exist for %s", name, f)
			}
		}
	}
}

func TestDebugCommand_CaptureLogs(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	cases := map[string]struct {
		// used in -target param
		targets []string
		// existence verified after execution
		files []string
		// non-existence verified after execution
		excludedFiles []string
	}{
		"logs-only": {
			[]string{"logs"},
			[]string{"*/consul.log"},
			[]string{"agent.json", "host.json", "cluster.json", "*/metrics.json"},
		},
	}

	for name, tc := range cases {
		testDir := testutil.TempDir(t, "debug")

		a := agent.NewTestAgent(t, `
		enable_debug = true
		`)

		defer a.Shutdown()
		testrpc.WaitForLeader(t, a.RPC, "dc1")

		ui := cli.NewMockUi()
		cmd := New(ui, nil)
		cmd.validateTiming = false

		outputPath := fmt.Sprintf("%s/debug-%s", testDir, name)
		args := []string{
			"-http-addr=" + a.HTTPAddr(),
			"-output=" + outputPath,
			"-archive=false",
			"-duration=1000ms",
			"-interval=50ms",
		}
		for _, t := range tc.targets {
			args = append(args, "-capture="+t)
		}

		if code := cmd.Run(args); code != 0 {
			t.Fatalf("should exit 0, got code: %d", code)
		}

		errOutput := ui.ErrorWriter.String()
		if errOutput != "" {
			t.Errorf("expected no error output, got %q", errOutput)
		}

		// Ensure the debug data was written
		_, err := os.Stat(outputPath)
		if err != nil {
			t.Fatalf("output path should exist: %s", err)
		}

		// Ensure the captured static files exist
		for _, f := range tc.files {
			path := fmt.Sprintf("%s/%s", outputPath, f)
			// Glob ignores file system errors
			fs, _ := filepath.Glob(path)
			if len(fs) <= 0 {
				t.Fatalf("%s: output data should exist for %s", name, f)
			}
			for _, logFile := range fs {
				content, err := ioutil.ReadFile(logFile)
				require.NoError(t, err)
				scanner := bufio.NewScanner(strings.NewReader(string(content)))
				for scanner.Scan() {
					logLine := scanner.Text()
					if !validateLogLine([]byte(logLine)) {
						t.Fatalf("%s: log line is not valid %s", name, logLine)
					}
				}
			}
		}

		// Ensure any excluded files do not exist
		for _, f := range tc.excludedFiles {
			path := fmt.Sprintf("%s/%s", outputPath, f)
			// Glob ignores file system errors
			fs, _ := filepath.Glob(path)
			if len(fs) > 0 {
				t.Fatalf("%s: output data should not exist for %s", name, f)
			}
		}
	}
}

func validateLogLine(content []byte) bool {
	fields := strings.SplitN(string(content), " ", 2)
	if len(fields) != 2 {
		return false
	}
	const logTimeFormat = "2006-01-02T15:04:05.000"
	t := content[:len(logTimeFormat)]
	_, err := time.Parse(logTimeFormat, string(t))
	if err != nil {
		return false
	}
	re := regexp.MustCompile(`(\[(ERROR|WARN|INFO|DEBUG|TRACE)]) (.*?): (.*)`)
	valid := re.Match([]byte(fields[1]))
	return valid
}

func TestDebugCommand_ProfilesExist(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	testDir := testutil.TempDir(t, "debug")

	a := agent.NewTestAgent(t, `
	enable_debug = true
	`)
	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := fmt.Sprintf("%s/debug", testDir)
	println(outputPath)
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		// CPU profile has a minimum of 1s
		"-archive=false",
		"-duration=2s",
		"-interval=1s",
		"-capture=pprof",
	}

	if code := cmd.Run(args); code != 0 {
		t.Fatalf("should exit 0, got code: %d", code)
	}

	profiles := []string{"heap.prof", "profile.prof", "goroutine.prof", "trace.out"}
	// Glob ignores file system errors
	for _, v := range profiles {
		fs, _ := filepath.Glob(fmt.Sprintf("%s/*/%s", outputPath, v))
		if len(fs) < 1 {
			t.Errorf("output data should exist for %s", v)
		}
		for _, f := range fs {
			if !strings.Contains(f, "trace.out") {
				content, err := ioutil.ReadFile(f)
				require.NoError(t, err)
				_, err = profile.ParseData(content)
				require.NoError(t, err)
			}
		}
	}

	errOutput := ui.ErrorWriter.String()
	if errOutput != "" {
		t.Errorf("expected no error output, got %s", errOutput)
	}
}

func TestDebugCommand_ValidateTiming(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	cases := map[string]struct {
		duration string
		interval string
		output   string
		code     int
	}{
		"both": {
			"20ms",
			"10ms",
			"duration must be longer",
			1,
		},
		"short interval": {
			"10s",
			"10ms",
			"interval must be longer",
			1,
		},
		"lower duration": {
			"20s",
			"30s",
			"must be longer than interval",
			1,
		},
	}

	for name, tc := range cases {
		// Because we're only testng validation, we want to shut down
		// the valid duration test to avoid hanging
		shutdownCh := make(chan struct{})

		a := agent.NewTestAgent(t, "")
		defer a.Shutdown()
		testrpc.WaitForLeader(t, a.RPC, "dc1")

		ui := cli.NewMockUi()
		cmd := New(ui, shutdownCh)

		args := []string{
			"-http-addr=" + a.HTTPAddr(),
			"-duration=" + tc.duration,
			"-interval=" + tc.interval,
			"-capture=agent",
		}
		code := cmd.Run(args)

		if code != tc.code {
			t.Errorf("%s: should exit %d, got code: %d", name, tc.code, code)
		}

		errOutput := ui.ErrorWriter.String()
		if !strings.Contains(errOutput, tc.output) {
			t.Errorf("%s: expected error output '%s', got '%q'", name, tc.output, errOutput)
		}
	}
}

func TestDebugCommand_DebugDisabled(t *testing.T) {
	if testing.Short() {
		t.Skip("too slow for testing.Short")
	}

	t.Parallel()

	testDir := testutil.TempDir(t, "debug")

	a := agent.NewTestAgent(t, `
	enable_debug = false
	`)
	defer a.Shutdown()
	testrpc.WaitForLeader(t, a.RPC, "dc1")

	ui := cli.NewMockUi()
	cmd := New(ui, nil)
	cmd.validateTiming = false

	outputPath := fmt.Sprintf("%s/debug", testDir)
	args := []string{
		"-http-addr=" + a.HTTPAddr(),
		"-output=" + outputPath,
		"-archive=false",
		// CPU profile has a minimum of 1s
		"-duration=1s",
		"-interval=1s",
	}

	if code := cmd.Run(args); code != 0 {
		t.Fatalf("should exit 0, got code: %d", code)
	}

	profiles := []string{"heap.prof", "profile.prof", "goroutine.prof", "trace.out"}
	// Glob ignores file system errors
	for _, v := range profiles {
		fs, _ := filepath.Glob(fmt.Sprintf("%s/*r/%s", outputPath, v))
		require.True(t, len(fs) == 0)
	}

	errOutput := ui.ErrorWriter.String()
	require.Contains(t, errOutput, "failed to collect")

}