helper/logging: Loosen the filtering heuristic even more

Now we'll consider any message that doesn't start with a digit as a
continuation. This is _definitely_ in loose, best-effort territory now
since a continuation line could very well start with a digit, but
ultimately this is still better than the totally broken behavior that
preceded it.

Just to make sure that none of these heuristics interfere with producing
complete, accurate logs for TRACE, we'll skip the LevelFilter altogether
in that case.

helper/logging/level.go

@@ -29,6 +29,14 @@ type LogLevel string
 //     line starts with at least one space in which case it is interpreted
 //     as a continuation of the previous line.
 //
+//   - If a log line starts with a non-whitespace character that isn't a digit
+//     then it's recognized as a degenerate continuation, because "real" log
+//     lines should start with a date/time and thus always have a leading
+//     digit. (This also cleans up after some situations where the assumptuion
+//     that messages arrive atomically aren't met, which is sadly sometimes
+//     true for longer messages that trip over some buffering behavior in
+//     panicwrap.)
+//
 // Because logging is a cross-cutting concern and not fully under the control
 // of Terraform itself, there will certainly be cases where the above
 // heuristics will fail. For example, it is likely that LevelFilter will
@@ -56,6 +64,7 @@ type LevelFilter struct {
 	Writer io.Writer
 
 	badLevels map[LogLevel]struct{}
+	show      bool
 	once      sync.Once
 }
 
@@ -93,22 +102,27 @@ func (f *LevelFilter) Check(line []byte) bool {
 // Behavior is undefined if any log line is split across multiple writes or
 // written without a trailing '\n' delimiter.
 func (f *LevelFilter) Write(p []byte) (n int, err error) {
-	show := true
 	for len(p) > 0 {
 		// Split at the first \n, inclusive
 		idx := bytes.IndexByte(p, '\n')
 		if idx == -1 {
-			// Invalid, undelimited write
+			// Invalid, undelimited write. We'll tolerate it assuming that
+			// our assumptions are being violated, but the results may be
+			// non-ideal.
+			idx = len(p) - 1
 			break
 		}
 		var l []byte
 		l, p = p[:idx+1], p[idx+1:]
-		// Lines starting with whitespace are continuations, so they inherit
+		// Lines starting with characters other than decimal digits (including
-		// the result of the check of the previous line.
+		// whitespace) are assumed to be continuations lines. This is an
-		if !(l[0] == ' ' || l[0] == '\t' || l[0] == '\n') {
+		// imprecise heuristic, but experimentally it seems to generate
-			show = f.Check(l)
+		// "good enough" results from Terraform Core's own logging. Its mileage
+		// may vary with output from other systems.
+		if l[0] >= '0' && l[0] <= '9' {
+			f.show = f.Check(l)
 		}
-		if show {
+		if f.show {
 			_, err = f.Writer.Write(l)
 			if err != nil {
 				// Technically it's not correct to say we've written the whole
@@ -141,4 +155,5 @@ func (f *LevelFilter) init() {
 		badLevels[level] = struct{}{}
 	}
 	f.badLevels = badLevels
+	f.show = true
 }

helper/logging/level_test.go

@@ -20,12 +20,12 @@ func TestLevelFilter(t *testing.T) {
 	}
 
 	logger := log.New(filter, "", 0)
-	logger.Print("[WARN] foo")
+	logger.Print("2019/01/01 00:00:00 [WARN] foo")
-	logger.Println("[ERROR] bar\n[DEBUG] buzz")
+	logger.Println("2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [DEBUG] buzz")
-	logger.Println("[DEBUG] baz\n  continuation\n[WARN] buzz\n  more\n[DEBUG] fizz")
+	logger.Println("2019/01/01 00:00:00 [DEBUG] baz\n  continuation\n2019/01/01 00:00:00 [WARN] buzz\n  more\n2019/01/01 00:00:00 [DEBUG] fizz")
 
 	result := buf.String()
-	expected := "[WARN] foo\n[ERROR] bar\n[WARN] buzz\n  more\n"
+	expected := "2019/01/01 00:00:00 [WARN] foo\n2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [WARN] buzz\n  more\n"
 	if result != expected {
 		t.Fatalf("wrong result\ngot:\n%s\nwant:\n%s", result, expected)
 	}

helper/logging/logging.go

@@ -37,14 +37,21 @@ func LogOutput() (logOutput io.Writer, err error) {
 		}
 	}
 
-	// This was the default since the beginning
+	if logLevel == "TRACE" {
+		// Just pass through logs directly then, without any level filtering at all.
+		return logOutput, nil
+	}
+
+	// Otherwise we'll use our level filter, which is a heuristic-based
+	// best effort thing that is not totally reliable but helps to reduce
+	// the volume of logs in some cases.
 	logOutput = &LevelFilter{
 		Levels:   ValidLevels,
 		MinLevel: LogLevel(logLevel),
 		Writer:   logOutput,
 	}
 
-	return
+	return logOutput, nil
 }
 
 // SetOutput checks for a log destination with LogOutput, and calls