Add --log-file argument and log test result details

Signed-off-by: Kyle Edwards <[email protected]>

cmd/validate.go

@@ -34,11 +34,11 @@ var validateCmd = &cobra.Command{
 	SilenceUsage:  true,
 	SilenceErrors: false,
 	RunE: func(cmd *cobra.Command, args []string) error {
-		file, err := cmd.Flags().GetString("file")
+		configPath, err := cmd.Flags().GetString("file")
 		if err != nil {
 			return err
 		}
-		if file == "" {
+		if configPath == "" {
 			return errors.New("you must specify a manifest with '--file path/url'")
 		}
 
@@ -48,7 +48,12 @@ var validateCmd = &cobra.Command{
 			return err
 		}
 
-		v, err := validator.Validate(image, file, cmd, debug)
+		logPath, err := cmd.Flags().GetString("log-file")
+		if err != nil {
+			return err
+		}
+
+		v, err := validator.Validate(image, configPath, logPath, cmd, debug)
 		if err != nil {
 			cmd.Printf("Error: %s\n", err.Error())
 			return err
@@ -85,6 +90,7 @@ func imageArg(cmd *cobra.Command, args []string) error {
 func init() {
 	rootCmd.AddCommand(validateCmd)
 	validateCmd.PersistentFlags().String("file", "", "Path or URL of a manifest to validate against.")
+	validateCmd.PersistentFlags().String("log-file", "", "File to print log output to.")
 	validateCmd.PersistentFlags().Bool("debug", false, "Keep container running on failure for debugging.")
 
 }

go.mod

@@ -26,6 +26,7 @@ require (
 	github.com/inconshreveable/mousetrap v1.0.0 // indirect
 	github.com/json-iterator/go v1.1.12 // indirect
 	github.com/lucasb-eyer/go-colorful v1.2.0 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
 	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/mattn/go-localereader v0.0.1 // indirect
 	github.com/mattn/go-runewidth v0.0.15 // indirect
@@ -37,6 +38,7 @@ require (
 	github.com/muesli/termenv v0.15.2 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/rivo/uniseg v0.4.7 // indirect
+	github.com/rs/zerolog v1.32.0 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	golang.org/x/net v0.17.0 // indirect
 	golang.org/x/sync v0.6.0 // indirect

go.sum

@@ -107,6 +107,7 @@ github.com/containerd/console v1.0.4 h1:F2g4+oChYvBTsASRTz8NP6iIAi97J3TtSAsLbIFn
 github.com/containerd/console v1.0.4/go.mod h1:YynlIjWYF8myEu6sdkwKIvGQq+cOckRm6So2avqoYAk=
 github.com/coreos/go-semver v0.3.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk=
 github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/cpuguy83/go-md2man/v2 v2.0.1/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -303,13 +304,17 @@ github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVc
 github.com/mattn/go-colorable v0.1.6/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
 github.com/mattn/go-colorable v0.1.9/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
 github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
 github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
 github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s=
 github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84=
 github.com/mattn/go-isatty v0.0.11/go.mod h1:PhnuNfih5lzO57/f3n+odYbM4JtupLOxQOAqxQCu2WE=
 github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
 github.com/mattn/go-isatty v0.0.13/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
 github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
 github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-localereader v0.0.1 h1:ygSAOl7ZXTx4RdPYinUpg6W99U8jWvWi9Ye2JC/oIi4=
@@ -391,6 +396,9 @@ github.com/rivo/uniseg v0.4.7 h1:WUdvkW8uEhrYfLC4ZzdpI2ztxP1I582+49Oc5Mq64VQ=
 github.com/rivo/uniseg v0.4.7/go.mod h1:FN3SvrM+Zdj16jyLfmOkMNblXMcoc8DfTHruCPUcx88=
 github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.32.0 h1:keLypqrlIjaFsbmJOBdB/qvyF8KEtCWHwobLp5l/mQ0=
+github.com/rs/zerolog v1.32.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
 github.com/sagikazarmark/crypt v0.3.0/go.mod h1:uD/D+6UF4SrIR1uGEv7bBNkNqLGqUr43MRiaGWX1Nig=
@@ -635,8 +643,10 @@ golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20211007075335-d3039528d8ac/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20211124211545-fe61309f8881/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20211205182925-97ca703d548d/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.17.0 h1:25cE3gD+tdBA7lp7QfhuV+rJiE9YXTcS3VG1SqssI/Y=
 golang.org/x/sys v0.17.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

internal/container/container.go

@@ -40,7 +40,7 @@ type ContainerInterface interface {
 	Start() error
 	Remove() error
 	Status() (*ContainerInfo, error)
-	Exec(command ...string) (string, error)
+	Exec(command ...string) (exitCode int, stdout string, stderr string, err error)
 	Logs() (string, error)
 }
 

internal/container/docker.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"os/exec"
 	"strings"
 	"time"
@@ -136,11 +137,42 @@ func (c DockerContainer) Status() (*ContainerInfo, error) {
 }
 
 // Exec a command inside a container
-func (c DockerContainer) Exec(command ...string) (string, error) {
+func (c DockerContainer) Exec(command ...string) (exitCode int, stdout string, stderr string, err error) {
 
 	args := append([]string{"exec", c.Name}, command...)
-	out, err := exec.Command("docker", args...).Output()
-	return string(out), err
+	cmd := exec.Command("docker", args...)
+	stdoutPipe, err := cmd.StdoutPipe()
+	if err != nil {
+		return
+	}
+	stderrPipe, err := cmd.StderrPipe()
+	if err != nil {
+		return
+	}
+
+	if err = cmd.Start(); err != nil {
+		return
+	}
+
+	stdoutBytes, err := io.ReadAll(stdoutPipe)
+	if err != nil {
+		return
+	}
+	stderrBytes, err := io.ReadAll(stderrPipe)
+	if err != nil {
+		return
+	}
+
+	if err = cmd.Wait(); err != nil {
+		switch t := err.(type) {
+		case *exec.ExitError:
+			exitCode = t.ExitCode()
+		default:
+			return
+		}
+	}
+
+	return exitCode, string(stdoutBytes), string(stderrBytes), nil
 }
 
 // Get container logs

internal/container/docker_test.go

@@ -58,11 +58,12 @@ func TestDockerContainer(t *testing.T) {
 	}
 	assert.Contains(status.RunCommand, "docker run", "Run command not stored correctly")
 
-	uname, err := c.Exec("uname", "-a")
+	exitCode, uname, _, err := c.Exec("uname", "-a")
 	if err != nil {
 		t.Errorf("Failed to exec command in container: %s", err.Error())
 		return
 	}
+	assert.Equal(0, exitCode)
 	if !strings.Contains(uname, "Linux") {
 		t.Error("Output for command 'uname' did not contain expected string 'Linux'")
 		return

internal/validator/exec.go

@@ -18,15 +18,18 @@
 package validator
 
 import (
+	"github.com/rs/zerolog"
+
 	canaryv1 "github.com/nvidia/container-canary/internal/apis/v1"
 	"github.com/nvidia/container-canary/internal/container"
 )
 
-func ExecCheck(c container.ContainerInterface, probe *canaryv1.Probe) (bool, error) {
+func ExecCheck(c container.ContainerInterface, probe *canaryv1.Probe, e *zerolog.Event) (bool, error) {
 	action := probe.Exec
-	_, err := c.Exec(action.Command...)
+	exitCode, stdout, stderr, err := c.Exec(action.Command...)
 	if err != nil {
-		return false, nil
+		return false, err
 	}
-	return true, nil
+	e.Int("exitCode", exitCode).Str("stdout", stdout).Str("stderr", stderr)
+	return exitCode == 0, nil
 }

internal/validator/httpget.go

@@ -24,9 +24,10 @@ import (
 
 	canaryv1 "github.com/nvidia/container-canary/internal/apis/v1"
 	"github.com/nvidia/container-canary/internal/container"
+	"github.com/rs/zerolog"
 )
 
-func HTTPGetCheck(c container.ContainerInterface, probe *canaryv1.Probe) (bool, error) {
+func HTTPGetCheck(c container.ContainerInterface, probe *canaryv1.Probe, e *zerolog.Event) (bool, error) {
 	action := probe.HTTPGet
 	client := &http.Client{}
 	req, err := http.NewRequest("GET", fmt.Sprintf("http://localhost:%d%s", action.Port, action.Path), nil)
@@ -39,14 +40,23 @@ func HTTPGetCheck(c container.ContainerInterface, probe *canaryv1.Probe) (bool,
 		req.Header.Set(header.Name, header.Value)
 	}
 	resp, err := client.Do(req)
+	if resp != nil {
+		headers := zerolog.Dict()
+		for name, value := range resp.Header {
+			headers.Str(name, strings.Join(value[:], ""))
+		}
+		e.Dict("headers", headers).Int("status", resp.StatusCode)
+	}
 	if err != nil {
 		return false, nil
 	}
 	for _, header := range action.ResponseHTTPHeaders {
-		if val, ok := resp.Header[header.Name]; ok {
+		if val := resp.Header.Values(header.Name); len(val) != 0 {
 			if header.Value != strings.Join(val[:], "") {
 				return false, nil
 			}
+		} else {
+			return false, nil
 		}
 	}
 	defer resp.Body.Close()

internal/validator/tcp.go

@@ -23,9 +23,10 @@ import (
 
 	canaryv1 "github.com/nvidia/container-canary/internal/apis/v1"
 	"github.com/nvidia/container-canary/internal/container"
+	"github.com/rs/zerolog"
 )
 
-func TCPSocketCheck(c container.ContainerInterface, probe *canaryv1.Probe) (bool, error) {
+func TCPSocketCheck(c container.ContainerInterface, probe *canaryv1.Probe, e *zerolog.Event) (bool, error) {
 	action := probe.TCPSocket
 	address := fmt.Sprintf("localhost:%d", action.Port)
 	_, err := net.Dial("tcp", address)

internal/validator/tui.go

@@ -25,6 +25,7 @@ import (
 	tea "github.com/charmbracelet/bubbletea"
 	canaryv1 "github.com/nvidia/container-canary/internal/apis/v1"
 	"github.com/nvidia/container-canary/internal/container"
+	"github.com/rs/zerolog"
 )
 
 type model struct {
@@ -41,6 +42,7 @@ type model struct {
 	configPath       string
 	err              error
 	tty              bool
+	log              zerolog.Logger
 }
 
 func (m model) Init() tea.Cmd {
@@ -148,7 +150,7 @@ func handleContainerStarted(m model, msg containerStarted) (model, tea.Cmd) {
 	}
 	commands = append(commands, tea.Printf("Validating %s against %s", highlightStyle(m.image), highlightStyle(m.validator.Name)))
 	for _, check := range m.validator.Checks {
-		commands = append(commands, runCheck(m.sub, m.container, check))
+		commands = append(commands, runCheck(m.log, m.sub, m.container, check))
 	}
 	return m, tea.Batch(commands...)
 }

internal/validator/validator.go

@@ -33,6 +33,7 @@ import (
 	canaryv1 "github.com/nvidia/container-canary/internal/apis/v1"
 	"github.com/nvidia/container-canary/internal/config"
 	"github.com/nvidia/container-canary/internal/container"
+	"github.com/rs/zerolog"
 	"github.com/spf13/cobra"
 )
 
@@ -59,16 +60,27 @@ type configLoaded struct {
 	Error  error
 }
 
-type probeCallable func(container.ContainerInterface, *canaryv1.Probe) (bool, error)
+type probeCallable func(container.ContainerInterface, *canaryv1.Probe, *zerolog.Event) (bool, error)
 
-func Validate(image string, configPath string, cmd *cobra.Command, debug bool) (bool, error) {
+func Validate(image string, configPath string, logPath string, cmd *cobra.Command, debug bool) (bool, error) {
 	var tty io.Reader
 	isTty := true
 	tty, err := os.Open("/dev/tty")
 	if err != nil {
 		tty = bufio.NewReader(os.Stdin)
 		isTty = false
 	}
+	var log zerolog.Logger
+	if logPath == "" {
+		log = zerolog.Nop()
+	} else {
+		f, err := tea.LogToFile(logPath, "canary")
+		if err != nil {
+			return false, err
+		}
+		log = zerolog.New(f)
+		defer f.Close()
+	}
 	m := model{
 		sub:              make(chan checkResult),
 		configPath:       configPath,
@@ -79,6 +91,7 @@ func Validate(image string, configPath string, cmd *cobra.Command, debug bool) (
 		debug:            debug,
 		image:            image,
 		tty:              isTty,
+		log:              log,
 	}
 	p := tea.NewProgram(m, tea.WithInput(tty), tea.WithOutput(cmd.OutOrStderr()))
 	out, err := p.Run()
@@ -152,17 +165,17 @@ func waitForChecks(sub chan checkResult) tea.Cmd {
 	}
 }
 
-func runCheck(results chan<- checkResult, c container.ContainerInterface, check canaryv1.Check) tea.Cmd {
+func runCheck(log zerolog.Logger, results chan<- checkResult, c container.ContainerInterface, check canaryv1.Check) tea.Cmd {
 	return func() tea.Msg {
 		var p bool
 		var err error
 		// TODO Make more SOLID (O)
 		if check.Probe.Exec != nil {
-			p, err = executeCheck(ExecCheck, c, &check.Probe)
+			p, err = executeCheck(ExecCheck, log, c, check)
 		} else if check.Probe.HTTPGet != nil {
-			p, err = executeCheck(HTTPGetCheck, c, &check.Probe)
+			p, err = executeCheck(HTTPGetCheck, log, c, check)
 		} else if check.Probe.TCPSocket != nil {
-			p, err = executeCheck(TCPSocketCheck, c, &check.Probe)
+			p, err = executeCheck(TCPSocketCheck, log, c, check)
 		} else {
 			results <- checkResult{check.Description, false, fmt.Errorf("check '%s' has no known probes", check.Name)}
 			return nil
@@ -173,13 +186,19 @@ func runCheck(results chan<- checkResult, c container.ContainerInterface, check
 }
 
 // Run a check method with appropriate delay, retries and retry interval
-func executeCheck(method probeCallable, c container.ContainerInterface, probe *canaryv1.Probe) (bool, error) {
-	time.Sleep(time.Duration(probe.InitialDelaySeconds) * time.Second)
+func executeCheck(method probeCallable, log zerolog.Logger, c container.ContainerInterface, check canaryv1.Check) (bool, error) {
+	time.Sleep(time.Duration(check.Probe.InitialDelaySeconds) * time.Second)
 	passes := 0
 	fails := 0
 	start := time.Now()
+	attempt := 1
 	for {
-		passFail, err := method(c, probe)
+		event := log.Info().Str("check", check.Name).Int("attempt", attempt)
+		passFail, err := method(c, &check.Probe, event)
+		event.Bool("pass", passFail)
+		event.Send()
+		attempt++
+
 		if err != nil {
 			return false, err
 		}
@@ -190,13 +209,13 @@ func executeCheck(method probeCallable, c container.ContainerInterface, probe *c
 			fails += 1
 			passes = 0
 		}
-		if passes >= probe.SuccessThreshold || fails >= probe.FailureThreshold {
+		if passes >= check.Probe.SuccessThreshold || fails >= check.Probe.FailureThreshold {
 			return passFail, err
 		}
-		if time.Since(start) > time.Duration(probe.TimeoutSeconds)*time.Second {
-			return false, fmt.Errorf("check timed out after %d seconds", probe.TimeoutSeconds)
+		if time.Since(start) > time.Duration(check.Probe.TimeoutSeconds)*time.Second {
+			return false, fmt.Errorf("check timed out after %d seconds", check.Probe.TimeoutSeconds)
 		}
-		time.Sleep(time.Duration(probe.PeriodSeconds) * time.Second)
+		time.Sleep(time.Duration(check.Probe.PeriodSeconds) * time.Second)
 	}
 }