Repository: hashicorp/go-hclog
Pull request #87 (2021-02-13 23:34:34)

Improve rendering of empty strings and multiline values
This change improves 2 things:

1. empty strings are render as `""` instead of the absence of a value. The absence is fairly confusing.
2. Values that contain newlines are broken out and render under the key that they are for with indentation. This makes it possible to use tools like `spew.Sdump` easily on values and get easy to read output.

Here is an example the multiline rendering:

```
2021-02-13T15:22:31.131-0800 [INFO]  debug event detected event:
  event=
  | (*randomStruct)(0xc000284390)({
  |  Count: (int) 1,
  |  Max: (int) 1000,
  |  File: (string) (len=7) "foo-bar"
  | })
  root="" num_buffers=10
  more=
  | ([]string) (len=40 cap=40) {
  |  (string) (len=22) "TERM_PROGRAM=iTerm.app",
  |  (string) (len=20) "TERM=screen-256color",
  |  (string) (len=24) "SHELL=/usr/local/bin/zsh",
  |  (string) (len=15) "NVIM_GO_DEBUG=1",
  |  (string) (len=26) "TERM_PROGRAM_VERSION=3.4.3",
  |  (string) (len=38) "ZSH_AUTOSUGGEST_HIGHLIGHT_STYLE=fg=242",
  |  (string) (len=8) "RPROMPT=",
  |  (string) (len=37) "__CF_USER_TEXT_ENCODING=0x1F6:0x0:0x0",
  |  (string) (len=11) "EDITOR=nvim",
  |  (string) (len=16) "LANG=en_US.UTF-8",
  |  (string) (len=18) "ITERM_PROFILE=Work",
  |  (string) (len=13) "XPC_FLAGS=0x0",
  |  (string) (len=13) "TMUX_PANE=%47",
  |  (string) (len=15) "RBENV_SHELL=zsh",
  |  (string) (len=18) "XPC_SERVICE_NAME=0",
  |  (string) (len=7) "SHLVL=2",
  |  (string) (len=14) "COLORFGBG=15;0",
  |  (string) (len=25) "LC_TERMINAL_VERSION=3.4.3",
  |  (string) (len=7) "LESS=-R",
  |  (string) (len=21) "GOPATH=/Users/evan/go",
  |  (string) (len=16) "PROMPT_EOL_MARK=",
  |  (string) (len=18) "LC_TERMINAL=iTerm2",
  |  (string) (len=19) "COLORTERM=truecolor"
  | }

```


Patch:
diff --git a/intlogger.go b/intlogger.go
index d186bbe..f8f6ebd 100644
--- a/intlogger.go
+++ b/intlogger.go
@@ -261,6 +261,9 @@ func (l *intLogger) logPlain(t time.Time, name string, level Level, msg string,
 			switch st := args[i+1].(type) {
 			case string:
 				val = st
+				if st == "" {
+					val = `""`
+				}
 			case int:
 				val = strconv.FormatInt(int64(st), 10)
 			case int64:
@@ -302,20 +305,32 @@ func (l *intLogger) logPlain(t time.Time, name string, level Level, msg string,
 				}
 			}
 
-			l.writer.WriteByte(' ')
+			var key string
+
 			switch st := args[i].(type) {
 			case string:
-				l.writer.WriteString(st)
+				key = st
 			default:
-				l.writer.WriteString(fmt.Sprintf("%s", st))
+				key = fmt.Sprintf("%s", st)
 			}
-			l.writer.WriteByte('=')
 
-			if !raw && strings.ContainsAny(val, " \t\n\r") {
+			if strings.Contains(val, "\n") {
+				l.writer.WriteString("\n  ")
+				l.writer.WriteString(key)
+				l.writer.WriteString("=\n")
+				writeIndent(l.writer, val, "  | ")
+				l.writer.WriteString("  ")
+			} else if !raw && strings.ContainsAny(val, " \t") {
+				l.writer.WriteByte(' ')
+				l.writer.WriteString(key)
+				l.writer.WriteByte('=')
 				l.writer.WriteByte('"')
 				l.writer.WriteString(val)
 				l.writer.WriteByte('"')
 			} else {
+				l.writer.WriteByte(' ')
+				l.writer.WriteString(key)
+				l.writer.WriteByte('=')
 				l.writer.WriteString(val)
 			}
 		}
@@ -329,6 +344,25 @@ func (l *intLogger) logPlain(t time.Time, name string, level Level, msg string,
 	}
 }
 
+func writeIndent(w *writer, str string, indent string) {
+	for {
+		nl := strings.IndexByte(str, "\n"[0])
+		if nl == -1 {
+			if str != "" {
+				w.WriteString(indent)
+				w.WriteString(str)
+				w.WriteString("\n")
+			}
+			return
+		}
+
+		w.WriteString(indent)
+		w.WriteString(str[:nl])
+		w.WriteString("\n")
+		str = str[nl+1:]
+	}
+}
+
 func (l *intLogger) renderSlice(v reflect.Value) string {
 	var buf bytes.Buffer
 
@@ -345,22 +379,19 @@ func (l *intLogger) renderSlice(v reflect.Value) string {
 
 		switch sv.Kind() {
 		case reflect.String:
-			val = sv.String()
+			val = strconv.Quote(sv.String())
 		case reflect.Int, reflect.Int16, reflect.Int32, reflect.Int64:
 			val = strconv.FormatInt(sv.Int(), 10)
 		case reflect.Uint, reflect.Uint16, reflect.Uint32, reflect.Uint64:
 			val = strconv.FormatUint(sv.Uint(), 10)
 		default:
 			val = fmt.Sprintf("%v", sv.Interface())
+			if strings.ContainsAny(val, " \t\n\r") {
+				val = strconv.Quote(val)
+			}
 		}
 
-		if strings.ContainsAny(val, " \t\n\r") {
-			buf.WriteByte('"')
-			buf.WriteString(val)
-			buf.WriteByte('"')
-		} else {
-			buf.WriteString(val)
-		}
+		buf.WriteString(val)
 	}
 
 	buf.WriteRune(']')


Test patch:
diff --git a/interceptlogger_test.go b/interceptlogger_test.go
index 7b5a86d..f9d6412 100644
--- a/interceptlogger_test.go
+++ b/interceptlogger_test.go
@@ -234,7 +234,7 @@ func TestInterceptLogger(t *testing.T) {
 		output := buf.String()
 		dataIdx := strings.IndexByte(output, ' ')
 		rest := output[dataIdx+1:]
-		assert.Equal(t, "[DEBUG] with_test.sub_logger.http: test1: parent=logger path=/some/test/path args=[test, test]\n", rest)
+		assert.Equal(t, "[DEBUG] with_test.sub_logger.http: test1: parent=logger path=/some/test/path args=[\"test\", \"test\"]\n", rest)
 	})
 
 	t.Run("derived standard loggers send output to sinks", func(t *testing.T) {
diff --git a/logger_test.go b/logger_test.go
index 3b3f3bb..b1ef347 100644
--- a/logger_test.go
+++ b/logger_test.go
@@ -86,7 +86,7 @@ func TestLogger(t *testing.T) {
 		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=[testing, dev, 1, 5, \"[3 4]\"]\n", rest)
 	})
 
-	t.Run("renders values in slices with quotes if needed", func(t *testing.T) {
+	t.Run("renders values in slices with quotes", func(t *testing.T) {
 		var buf bytes.Buffer
 
 		logger := New(&LoggerOptions{
@@ -100,7 +100,29 @@ func TestLogger(t *testing.T) {
 		dataIdx := strings.IndexByte(str, ' ')
 		rest := str[dataIdx+1:]
 
-		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=[\"testing & qa\", dev]\n", rest)
+		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=[\"testing & qa\", \"dev\"]\n", rest)
+	})
+
+	t.Run("formats multiline values nicely", func(t *testing.T) {
+		var buf bytes.Buffer
+
+		logger := New(&LoggerOptions{
+			Name:   "test",
+			Output: &buf,
+		})
+
+		logger.Info("this is test", "who", "programmer", "why", "testing\nand other\npretty cool things")
+
+		str := buf.String()
+		dataIdx := strings.IndexByte(str, ' ')
+		rest := str[dataIdx+1:]
+
+		expected := `[INFO]  test: this is test: who=programmer
+  why=
+  | testing
+  | and other
+  | pretty cool things` + "\n  \n"
+		assert.Equal(t, expected, rest)
 	})
 
 	t.Run("outputs stack traces", func(t *testing.T) {
@@ -151,7 +173,7 @@ func TestLogger(t *testing.T) {
 		rest := str[dataIdx+1:]
 
 		// This test will break if you move this around, it's line dependent, just fyi
-		assert.Equal(t, "[INFO]  go-hclog/logger_test.go:147: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
+		assert.Equal(t, "[INFO]  go-hclog/logger_test.go:169: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
 	})
 
 	t.Run("prefixes the name", func(t *testing.T) {