Add debug logging option

This makes it easier to report verbose program
logging to troubleshooting issues with the
preflight itself.

CHANGELOG.md

@@ -15,6 +15,9 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 - `conjur-preflight` now detects whether it is writing standard output to a
   terminal or to a file/pipe and formats with rich or plain text accordingly.
   [conjurinc/conjur-preflight#19](https://github.com/conjurinc/conjur-preflight/pull/19)
+- A new CLI flag `--debug` causes `conjur-preflight` to log more verbose
+  information about the execution of the application and its checks.
+  [conjurinc/conjur-preflight#19](https://github.com/conjurinc/conjur-preflight/pull/19)
 
 ### Fixed
 - Previously, the application version was not properly embedded in the final

ci/integration/test

@@ -80,6 +80,7 @@ run_integration_test() {
     "$@" \
     "${image}" \
       /conjur-preflight/dist/conjur-preflight_linux_amd64_v1/conjur-preflight \
+        --debug \
       | tee "./results/${name}.txt"
 }
 

pkg/cmd/root.go

@@ -5,26 +5,37 @@ import (
 	"os"
 
 	"github.com/conjurinc/conjur-preflight/pkg/framework"
+	"github.com/conjurinc/conjur-preflight/pkg/log"
 	"github.com/conjurinc/conjur-preflight/pkg/report"
 	"github.com/conjurinc/conjur-preflight/pkg/version"
 	"github.com/spf13/cobra"
 )
 
 func newRootCommand() *cobra.Command {
+	var debug bool
+
 	rootCmd := &cobra.Command{
 		Use:   "conjur-preflight",
 		Short: "Qualification CLI for common Conjur Enterprise self-hosted issues",
 		RunE: func(cmd *cobra.Command, args []string) error {
+			if debug {
+				log.EnableDebugMode()
+			}
+
 			report := report.NewDefaultReport()
+
+			log.Debug("Running report...")
 			result := report.Run()
 
 			// Determine whether we want to use rich text or plain text based on
 			// whether we're outputting directly to a terminal or not
 			o, _ := os.Stdout.Stat()
 			var formatStrategy framework.FormatStrategy
 			if (o.Mode() & os.ModeCharDevice) == os.ModeCharDevice { //Terminal
+				log.Debug("Using rich text report formatting")
 				formatStrategy = &framework.RichTextFormatStrategy{}
 			} else { //It is not the terminal
+				log.Debug("Using plain text report formatting")
 				formatStrategy = &framework.PlainTextFormatStrategy{}
 			}
 
@@ -34,12 +45,14 @@ func newRootCommand() *cobra.Command {
 			}
 
 			fmt.Println(reportText)
-
+			log.Debug("Preflight finished!")
 			return nil
 		},
 		Version: version.FullVersionName,
 	}
 
+	rootCmd.PersistentFlags().BoolVarP(&debug, "debug", "", false, "debug logging output")
+
 	// TODO: Add JSON output option
 	// TODO: Verbose logging control
 	// TODO: Ability to adjust requirement criteria (PASS, WARN, FAIL checks)
@@ -56,6 +69,7 @@ func Execute() {
 	err := rootCmd.Execute()
 
 	if err != nil {
+		log.Error("ERROR: %s\n", err)
 		os.Exit(1)
 	}
 }

pkg/log/logger.go

@@ -0,0 +1,78 @@
+package log
+
+import (
+	"errors"
+	"fmt"
+	"log"
+	"os"
+)
+
+// We want all logging to go to the standard error stream, since we output data
+// on the standard output stream.
+var infoLogger = log.New(os.Stderr, "INFO:  ", log.LUTC|log.Ldate|log.Ltime|log.Lmicroseconds|log.Lshortfile)
+var errorLogger = log.New(os.Stderr, "ERROR: ", log.LUTC|log.Ldate|log.Ltime|log.Lmicroseconds|log.Lshortfile)
+var isDebug = false
+
+/*
+RecordedError prints an error message to the error log and returns a new error with the given message.
+This method can receive also more arguments (e.g an external error) and they will be appended to the given error message.
+
+For example, we have a local method `someMethod()`. This method handles its own error printing and thus we can consume
+the error and not append it to the new error message, as follows:
+
+	returnVal, err := someMethod()
+	if err != nil {
+		return nil, log.RecordedError("failed to run someMethod")
+	}
+
+On the other hand, if `someMethod()` is a 3rd party method we want to print also the returned error as it wasn't printed
+to the error log. So we'll have the following code:
+
+	returnVal, err := 3rdParty.someMethod()
+	if err != nil {
+		return nil, log.RecordedError("failed to run someMethod. Reason: %s", err)
+	}
+*/
+func RecordedError(errorMessage string, args ...interface{}) error {
+	message := fmt.Sprintf(errorMessage, args...)
+	writeLog(errorLogger, "ERROR", message)
+	return errors.New(message)
+}
+
+// Error prints a message to the error log with the "ERROR" label.
+func Error(message string, args ...interface{}) {
+	writeLog(errorLogger, "ERROR", message, args...)
+}
+
+// Warn prints a message to the info log with the "WARN" label.
+func Warn(message string, args ...interface{}) {
+	writeLog(infoLogger, "WARN", message, args...)
+}
+
+// Info prints a message to the info log with the "INFO" label.
+func Info(message string, args ...interface{}) {
+	writeLog(infoLogger, "INFO", message, args...)
+}
+
+// Debug prints a message to the info log with the "DEBUG" label.
+func Debug(infoMessage string, args ...interface{}) {
+	if isDebug {
+		writeLog(infoLogger, "DEBUG", infoMessage, args...)
+	}
+}
+
+// EnableDebugMode enables writing DEBUG level messages to the log output.
+func EnableDebugMode() {
+	isDebug = true
+	Debug("Debug mode is enabled")
+}
+
+func writeLog(logger *log.Logger, logLevel string, message string, args ...interface{}) {
+	// -7 format ensures logs alignment, by padding spaces to log level to ensure 7 characters length.
+	// 5 for longest log level, 1 for ':', and a space separator.
+	logger.SetPrefix(fmt.Sprintf("%-7s", logLevel+":"))
+	if len(args) > 0 {
+		message = fmt.Sprintf(message, args...)
+	}
+	logger.Output(3, message)
+}

pkg/log/logger_test.go

@@ -0,0 +1,60 @@
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"log"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestAuthenticator(t *testing.T) {
+	t.Run("Logger", func(t *testing.T) {
+		t.Run("Calling RecordedError logs the message and return error object with that message", func(t *testing.T) {
+			validateLog(t, func(message string, params ...interface{}) {
+				err := RecordedError(message, params...)
+				assert.Contains(t, err.Error(), fmt.Sprintf(message, params...))
+			}, "ERROR", "log message with param: <%s>", "param value")
+		})
+
+		t.Run("Calling Error logs the message", func(t *testing.T) {
+			validateLog(t, Error, "ERROR", "log message with param: <%s>", "param value")
+		})
+
+		t.Run("Calling Warn logs the message", func(t *testing.T) {
+			validateLog(t, Warn, "WARN", "log message with param: <%s>", "param value")
+		})
+
+		t.Run("Calling Info logs the message", func(t *testing.T) {
+			validateLog(t, Info, "INFO", "log message with param: <%s>", "param value")
+		})
+
+		t.Run("Calling Debug does nothing before Calling EnableDebugMode", func(t *testing.T) {
+			var logBuffer bytes.Buffer
+			infoLogger = log.New(&logBuffer, "", 0)
+
+			Debug("message")
+
+			assert.Equal(t, logBuffer.Len(), 0)
+		})
+
+		t.Run("Calling Debug logs the message after Calling EnableDebugMode", func(t *testing.T) {
+			EnableDebugMode()
+			validateLog(t, Debug, "DEBUG", "log message with param: <%s>", "param value")
+		})
+	})
+}
+
+func validateLog(t *testing.T, logFunc func(string, ...interface{}), logLevel, messageFormat, param string) {
+	// Replace logger with buffer to test its value
+	var logBuffer bytes.Buffer
+	errorLogger = log.New(&logBuffer, "", 0)
+	infoLogger = log.New(&logBuffer, "", 0)
+
+	logFunc(messageFormat, param)
+
+	logMessages := logBuffer.String()
+	assert.Contains(t, logMessages, logLevel)
+	assert.Contains(t, logMessages, fmt.Sprintf(messageFormat, param))
+}