Repository: klothoplatform/klotho (go)

Issue:
better handling of Errors in console logging
Errors are an odd duck: on the one hand, they (usually? always?) represent pretty low-level information. On the other hand, they can be large, multiline dumps of information (especially if they contain stack traces).

Today (as of the auth branch), we just drop them on console output. We should do something better.

- [ ] only output them when `internalDebug` is on
- [ ] if the field is multi-line:
  - [ ] we should understand that in `printableWidth`, and have that return the maximum width
  - [ ] we should probably print it on its own lines, rather than just inline in the comma-delimited list

As of 752b31b (on the auth branch), the current usages of `zap.Error(e)` and `zap.NamedError` are:

- [`pkg/analytics/user.go`](https://github.com/klothoplatform/klotho/blob/752b31bae8c111ef58555dcb8341325863a4b577/pkg/analytics/user.go#L40): try to write the `analytics.json` file, but if that fails, just log at DEBUG and move on
- `pkg/auth/auth.go`:
  - [1](https://github.com/klothoplatform/klotho/blob/752b31bae8c111ef58555dcb8341325863a4b577/pkg/auth/auth.go): if the PEM file doesn't exist, log at DEBUG that we need to download one and move on
  - [2](https://github.com/klothoplatform/klotho/blob/752b31bae8c111ef58555dcb8341325863a4b577/pkg/auth/auth.go#L285) if we're able to download the PEM file but not save it to disk, then log at DEBUG and move on
- [`pkg/cli/klothomain.go`](https://github.com/klothoplatform/klotho/blob/752b31bae8c111ef58555dcb8341325863a4b577/pkg/cli/klothomain.go#L307): If there is a credentials file, but for whatever reason we can't authorize those credentials, then log a WARN to the effect of "couldn't auth, this is fine for now but may block you in the future" and move on (this is auth's fail open)
- [`pkg/closenicely/closeutil.go`](https://github.com/klothoplatform/klotho/blob/752b31bae8c111ef58555dcb8341325863a4b577/pkg/closenicely/closeutil.go#L14): if a `Close()` errors, log at DEBUG and move on

One thing to note is that dropping `errors` also affect fields whose value interfaces just happen to conform to Error, even if those fields weren’t created with zap.Error. Hopefully that doesn't happen, though. We only define four structs that conform to Error today: `CompileError`, `multierror.Error`, `PluginError`, `WrappedError`. I haven't actually traced those all through, but it seems unlikely that any of them would end up in a zap field other than `zap.[Named]Error(e)`.

Pull request description:
print out error fields on log lines
* always log the error message
* with `--verbose`, also log the stack trace (if available)

This resolves #195. This does not touch panics.

Here's an example with and without `--verbose`. I added three log lines, each with a stack trace: one at info, one at warn, one at error.

Without verbose:
> ![example with no verbose; prints only the message](https://user-images.githubusercontent.com/110620369/220468115-c04895c1-6c57-466d-8e60-7f04a4acc510.png)

With verbose:
> ![example with verbose; prints the full trace](https://user-images.githubusercontent.com/110620369/220468299-890aca7d-67c4-4aee-b39b-a1c5d52b2a60.png)




### Standard checks

- **Unit tests**: unit tests added
- **Docs**: no docs needed
- **Backwards compatibility**: no issues


Patch:
diff --git a/pkg/cli/klothomain.go b/pkg/cli/klothomain.go
index 424568f3..21c37aa6 100644
--- a/pkg/cli/klothomain.go
+++ b/pkg/cli/klothomain.go
@@ -73,8 +73,10 @@ const defaultDisableLogo = false
 var hadWarnings = atomic.NewBool(false)
 var hadErrors = atomic.NewBool(false)
 
+const consoleEncoderName = "klotho-cli"
+
 func init() {
-	err := zap.RegisterEncoder("klotho-cli", func(zcfg zapcore.EncoderConfig) (zapcore.Encoder, error) {
+	err := zap.RegisterEncoder(consoleEncoderName, func(zcfg zapcore.EncoderConfig) (zapcore.Encoder, error) {
 		return logging.NewConsoleEncoder(cfg.verbose, hadWarnings, hadErrors), nil
 	})
 
@@ -145,7 +147,7 @@ func setupLogger(analyticsClient *analytics.Client) (*zap.Logger, error) {
 	} else {
 		zapCfg = zap.NewProductionConfig()
 	}
-	zapCfg.Encoding = "klotho-cli"
+	zapCfg.Encoding = consoleEncoderName
 	return zapCfg.Build(zap.WrapCore(func(core zapcore.Core) zapcore.Core {
 		trackingCore := analyticsClient.NewFieldListener(zapcore.WarnLevel)
 		return zapcore.NewTee(core, trackingCore)
diff --git a/pkg/logging/console.go b/pkg/logging/console.go
index ab02a518..ce5d758f 100644
--- a/pkg/logging/console.go
+++ b/pkg/logging/console.go
@@ -121,6 +121,7 @@ func (enc *ConsoleEncoder) EncodeEntry(ent zapcore.Entry, fieldList []zapcore.Fi
 		annotation  = enc.Annotation.a
 		nodeField   = enc.Node
 		postMessage = ""
+		errField    error
 
 		indentWriter = &IndentedWriter{Indentation: enc.levelPadding(), Writer: line}
 	)
@@ -147,7 +148,7 @@ func (enc *ConsoleEncoder) EncodeEntry(ent zapcore.Entry, fieldList []zapcore.Fi
 			postMessage = v.Message
 			continue
 		case error:
-			// hacky workaround to #195: just don't print errors, since they can be long strings of multi-line trace
+			errField = v
 			continue
 		}
 		if fieldCount > 0 {
@@ -267,7 +268,21 @@ func (enc *ConsoleEncoder) EncodeEntry(ent zapcore.Entry, fieldList []zapcore.Fi
 			line.AppendByte('\n')
 		}
 	}
-
+	if errField != nil {
+		indentWriter.Indentation += colour.Sprint("| ")
+		errFmt := "%v"
+		if enc.Verbose {
+			errFmt = "%+v"
+		}
+		errText := fmt.Sprintf("ERROR: "+errFmt, errField)
+		for _, errLine := range strings.Split(errText, "\n") {
+			fmt.Fprintf(&IndentedWriter{
+				Indentation: indentWriter.Indentation,
+				Writer:      line,
+				Colour:      colour,
+			}, "%s\n", errLine)
+		}
+	}
 	return line, nil
 }
 


Test patch:
diff --git a/pkg/logging/console_test.go b/pkg/logging/console_test.go
new file mode 100644
index 00000000..7713af3f
--- /dev/null
+++ b/pkg/logging/console_test.go
@@ -0,0 +1,163 @@
+package logging
+
+import (
+	"bytes"
+	"fmt"
+	"github.com/pkg/errors"
+	"github.com/stretchr/testify/assert"
+	"go.uber.org/atomic"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"strings"
+	"testing"
+)
+
+func TestEncodings(t *testing.T) {
+	cases := []struct {
+		name    string
+		given   logInput
+		expect  result
+		logFunc func(logger *zap.Logger, message string, fields ...zap.Field)
+	}{
+		{
+			name:  "no fields",
+			given: log("hello world"),
+			expect: result{
+				message:        "hello world\n",
+				verboseMessage: "  info hello world\n",
+			},
+		},
+		{
+			name:  "plain error field",
+			given: log("hello world", zap.Error(fmt.Errorf("my cool error"))),
+			expect: result{
+				message:        "hello world\n| ERROR: my cool error\n",
+				verboseMessage: "  info hello world\n      | ERROR: my cool error\n",
+			},
+		},
+		{
+			name:  "error field with stack",
+			given: log("hello world", zap.Error(errors.New("my cool error with stack trace"))),
+			expect: result{
+				message:        "hello world\n| ERROR: my cool error with stack trace\n",
+				verboseMessage: "  info hello world\n      | ERROR: my cool error with stack trace\n{{TRACE}}",
+			},
+		},
+		{
+			name:    "debug message",
+			given:   log("boom"),
+			logFunc: (*zap.Logger).Warn,
+			expect: result{
+				message:        "boom\n",
+				verboseMessage: "  warn boom\n",
+				warningsFound:  true,
+			},
+		},
+		{
+			name:    "error message",
+			given:   log("boom"),
+			logFunc: (*zap.Logger).Error,
+			expect: result{
+				message:        "boom\n",
+				verboseMessage: " error boom\n",
+				warningsFound:  true,
+				errorsFound:    true,
+			},
+		},
+		// note: don't test (*zap.Logger).Fatal, because it always calls os.Exit(1)
+	}
+	for _, tt := range cases {
+		t.Run(tt.name, func(t *testing.T) {
+			for _, verbose := range []bool{false, true} {
+				t.Run(fmt.Sprintf("verbose=%v", verbose), func(t *testing.T) {
+					assert := assert.New(t)
+
+					var hadWarnings, hadErrors atomic.Bool
+					encoder := NewConsoleEncoder(verbose, &hadWarnings, &hadErrors)
+
+					buf := &bytes.Buffer{}
+					logger := zap.New(
+						zapcore.NewCore(encoder, zapcore.AddSync(buf), zap.DebugLevel),
+						zap.AddCaller(),
+						zap.AddCallerSkip(1),
+					)
+
+					if tt.logFunc == nil {
+						tt.logFunc = (*zap.Logger).Info
+					}
+					tt.logFunc(logger, tt.given.message, tt.given.fields...)
+
+					var expectMessage string
+					if verbose {
+						expectMessage = tt.expect.verboseMessage
+					} else {
+						expectMessage = tt.expect.message
+					}
+
+					// for each field that's an Error with a stack trace, replace one instance of "{{TRACE}}" with
+					// that stack trace
+					for _, field := range tt.given.fields {
+						var indent string
+						if verbose {
+							indent = "      "
+						}
+						trace := getStackTrace(field, indent)
+						if trace != "" {
+							expectMessage = strings.Replace(expectMessage, "{{TRACE}}", trace, 1)
+						}
+					}
+
+					assert.Equal(expectMessage, buf.String())
+					assert.Equal(tt.expect.warningsFound, hadWarnings.Load())
+					assert.Equal(tt.expect.errorsFound, hadErrors.Load())
+				})
+			}
+		})
+	}
+}
+
+// getStackTrace gets the stack trace, but only if the field is an error that has a stack trace.
+// This makes for a less transparent test, but it's a necessary evil, since the stack trace is dynamic (depending even
+// on GOROOT, etc.)
+func getStackTrace(field zap.Field, indent string) string {
+	if field.Type != zapcore.ErrorType {
+		return ""
+	}
+
+	type stackTracer interface {
+		StackTrace() errors.StackTrace
+	}
+	trace, hasTrace := field.Interface.(stackTracer)
+	if !hasTrace {
+		return ""
+	}
+
+	var result string
+	for _, frame := range trace.StackTrace() {
+		for _, frameLine := range strings.Split(fmt.Sprintf("%+v", frame), "\n") {
+			result += fmt.Sprintf("%s| %+v\n", indent, frameLine)
+		}
+	}
+	return result
+}
+
+type (
+	logInput struct {
+		message string
+		fields  []zap.Field
+	}
+
+	result struct {
+		message        string
+		warningsFound  bool
+		errorsFound    bool
+		verboseMessage string
+	}
+)
+
+func log(message string, fields ...zap.Field) logInput {
+	return logInput{
+		message: message,
+		fields:  fields,
+	}
+}