e2a19b1799
The unix timestamps that were used make the debug data a little bit more difficult to consume. By using human readable dates we can easily see when the profile data was collected. This commit also improves the test coverage. Two test cases are removed and the assertions from those cases are moved to TestDebugCommand. Now TestDebugCommand is able to validate the contents of all files. This change reduces the test runtime of the command/debug package by almost 50%. It also makes much more strict assertions about the contents by using gotest.tools/v3/fs.
525 lines
12 KiB
Go
525 lines
12 KiB
Go
package debug
|
|
|
|
import (
|
|
"archive/tar"
|
|
"bufio"
|
|
"bytes"
|
|
"compress/gzip"
|
|
"encoding/json"
|
|
"fmt"
|
|
"io"
|
|
"os"
|
|
"path/filepath"
|
|
"regexp"
|
|
"strings"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/google/pprof/profile"
|
|
"github.com/mitchellh/cli"
|
|
"github.com/stretchr/testify/require"
|
|
"gotest.tools/v3/assert"
|
|
"gotest.tools/v3/assert/cmp"
|
|
"gotest.tools/v3/fs"
|
|
|
|
"github.com/hashicorp/consul/agent"
|
|
"github.com/hashicorp/consul/sdk/testutil"
|
|
"github.com/hashicorp/consul/testrpc"
|
|
)
|
|
|
|
func TestDebugCommand_Help_TextContainsNoTabs(t *testing.T) {
|
|
if strings.ContainsRune(New(cli.NewMockUi()).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)
|
|
cmd.validateTiming = false
|
|
|
|
it := &incrementalTime{
|
|
base: time.Date(2021, 7, 8, 9, 10, 11, 0, time.UTC),
|
|
}
|
|
cmd.timeNow = it.Now
|
|
|
|
outputPath := fmt.Sprintf("%s/debug", testDir)
|
|
args := []string{
|
|
"-http-addr=" + a.HTTPAddr(),
|
|
"-output=" + outputPath,
|
|
"-duration=2s",
|
|
"-interval=1s",
|
|
"-archive=false",
|
|
}
|
|
|
|
code := cmd.Run(args)
|
|
require.Equal(t, 0, code)
|
|
require.Equal(t, "", ui.ErrorWriter.String())
|
|
|
|
expected := fs.Expected(t,
|
|
fs.WithDir("debug",
|
|
fs.WithFile("index.json", "", fs.MatchFileContent(validIndexJSON)),
|
|
fs.WithFile("agent.json", "", fs.MatchFileContent(validJSON)),
|
|
fs.WithFile("host.json", "", fs.MatchFileContent(validJSON)),
|
|
fs.WithFile("members.json", "", fs.MatchFileContent(validJSON)),
|
|
fs.WithFile("metrics.json", "", fs.MatchAnyFileContent),
|
|
fs.WithFile("consul.log", "", fs.MatchFileContent(validLogFile)),
|
|
fs.WithFile("profile.prof", "", fs.MatchFileContent(validProfileData)),
|
|
fs.WithFile("trace.out", "", fs.MatchAnyFileContent),
|
|
fs.WithDir("2021-07-08T09-10-12Z",
|
|
fs.WithFile("goroutine.prof", "", fs.MatchFileContent(validProfileData)),
|
|
fs.WithFile("heap.prof", "", fs.MatchFileContent(validProfileData))),
|
|
fs.WithDir("2021-07-08T09-10-13Z",
|
|
fs.WithFile("goroutine.prof", "", fs.MatchFileContent(validProfileData)),
|
|
fs.WithFile("heap.prof", "", fs.MatchFileContent(validProfileData))),
|
|
// Ignore the extra directories, they should be the same as the first two
|
|
fs.MatchExtraFiles))
|
|
assert.Assert(t, fs.Equal(testDir, expected))
|
|
|
|
require.Equal(t, "", ui.ErrorWriter.String(), "expected no error output")
|
|
}
|
|
|
|
func validLogFile(raw []byte) fs.CompareResult {
|
|
scanner := bufio.NewScanner(bytes.NewReader(raw))
|
|
for scanner.Scan() {
|
|
logLine := scanner.Text()
|
|
if !validateLogLine([]byte(logLine)) {
|
|
return cmp.ResultFailure(fmt.Sprintf("log line is not valid %s", logLine))
|
|
}
|
|
}
|
|
if scanner.Err() != nil {
|
|
return cmp.ResultFailure(scanner.Err().Error())
|
|
}
|
|
return cmp.ResultSuccess
|
|
}
|
|
|
|
func validIndexJSON(raw []byte) fs.CompareResult {
|
|
var target debugIndex
|
|
decoder := json.NewDecoder(bytes.NewReader(raw))
|
|
decoder.DisallowUnknownFields()
|
|
if err := decoder.Decode(&target); err != nil {
|
|
return cmp.ResultFailure(err.Error())
|
|
}
|
|
return cmp.ResultSuccess
|
|
}
|
|
|
|
func validJSON(raw []byte) fs.CompareResult {
|
|
var target interface{}
|
|
decoder := json.NewDecoder(bytes.NewReader(raw))
|
|
if err := decoder.Decode(&target); err != nil {
|
|
return cmp.ResultFailure(err.Error())
|
|
}
|
|
return cmp.ResultSuccess
|
|
}
|
|
|
|
func validProfileData(raw []byte) fs.CompareResult {
|
|
if _, err := profile.ParseData(raw); err != nil {
|
|
return cmp.ResultFailure(err.Error())
|
|
}
|
|
return cmp.ResultSuccess
|
|
}
|
|
|
|
type incrementalTime struct {
|
|
base time.Time
|
|
next uint64
|
|
}
|
|
|
|
func (t *incrementalTime) Now() time.Time {
|
|
t.next++
|
|
return t.base.Add(time.Duration(t.next) * time.Second)
|
|
}
|
|
|
|
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)
|
|
cmd.validateTiming = false
|
|
|
|
outputPath := fmt.Sprintf("%s/debug", testDir)
|
|
args := []string{
|
|
"-http-addr=" + a.HTTPAddr(),
|
|
"-output=" + outputPath,
|
|
"-capture=agent",
|
|
}
|
|
|
|
code := cmd.Run(args)
|
|
require.Equal(t, 0, code)
|
|
require.Equal(t, "", ui.ErrorWriter.String())
|
|
|
|
archivePath := outputPath + debugArchiveExtension
|
|
file, err := os.Open(archivePath)
|
|
require.NoError(t, err)
|
|
|
|
gz, err := gzip.NewReader(file)
|
|
require.NoError(t, err)
|
|
tr := tar.NewReader(gz)
|
|
|
|
for {
|
|
h, err := tr.Next()
|
|
switch {
|
|
case err == io.EOF:
|
|
return
|
|
case 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) {
|
|
ui := cli.NewMockUi()
|
|
cmd := New(ui)
|
|
|
|
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)
|
|
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)
|
|
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)
|
|
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", "members.json"},
|
|
},
|
|
"static": {
|
|
[]string{"agent", "host", "cluster"},
|
|
[]string{"agent.json", "host.json", "members.json"},
|
|
[]string{"metrics.json"},
|
|
},
|
|
"metrics-only": {
|
|
[]string{"metrics"},
|
|
[]string{"metrics.json"},
|
|
[]string{"agent.json", "host.json", "members.json"},
|
|
},
|
|
"all-but-pprof": {
|
|
[]string{
|
|
"metrics",
|
|
"logs",
|
|
"host",
|
|
"agent",
|
|
"cluster",
|
|
},
|
|
[]string{
|
|
"host.json",
|
|
"agent.json",
|
|
"members.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)
|
|
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 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_Prepare_ValidateTiming(t *testing.T) {
|
|
cases := map[string]struct {
|
|
duration string
|
|
interval string
|
|
expected string
|
|
}{
|
|
"both": {
|
|
duration: "20ms",
|
|
interval: "10ms",
|
|
expected: "duration must be longer",
|
|
},
|
|
"short interval": {
|
|
duration: "10s",
|
|
interval: "10ms",
|
|
expected: "interval must be longer",
|
|
},
|
|
"lower duration": {
|
|
duration: "20s",
|
|
interval: "30s",
|
|
expected: "must be longer than interval",
|
|
},
|
|
}
|
|
|
|
for name, tc := range cases {
|
|
t.Run(name, func(t *testing.T) {
|
|
ui := cli.NewMockUi()
|
|
cmd := New(ui)
|
|
|
|
args := []string{
|
|
"-duration=" + tc.duration,
|
|
"-interval=" + tc.interval,
|
|
}
|
|
err := cmd.flags.Parse(args)
|
|
require.NoError(t, err)
|
|
|
|
_, err = cmd.prepare()
|
|
testutil.RequireErrorContains(t, err, tc.expected)
|
|
})
|
|
}
|
|
}
|
|
|
|
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)
|
|
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")
|
|
|
|
}
|